Add log rotation based on log size

Add new functions to logfile.go for rotating and truncating
the events log file once the log file and its contents
exceed the maximum size limit while keeping 50% of the
log file's content

Also add tests to verify log rotation and truncation

Signed-off-by: Niall Crowe <nicrowe@redhat.com>
Signed-off-by: Valentin Rothberg <vrothberg@redhat.com>

6 files changed, 371 insertions, 20 deletions

diff --git a/libpod/events.go b/libpod/events.go
index d6595180a..3908536a1 100644
--- a/libpod/events.go
+++ b/libpod/events.go
@@ -13,8 +13,9 @@ import (
 // newEventer returns an eventer that can be used to read/write events
 func (r *Runtime) newEventer() (events.Eventer, error) {
 	options := events.EventerOptions{
-		EventerType: r.config.Engine.EventsLogger,
-		LogFilePath: r.config.Engine.EventsLogFilePath,
+		EventerType:    r.config.Engine.EventsLogger,
+		LogFilePath:    r.config.Engine.EventsLogFilePath,
+		LogFileMaxSize: r.config.Engine.EventsLogFileMaxSize,
 	}
 	return events.NewEventer(options)
 }
diff --git a/libpod/events/config.go b/libpod/events/config.go
index 188d15578..35680a275 100644
--- a/libpod/events/config.go
+++ b/libpod/events/config.go
@@ -60,6 +60,8 @@ type EventerOptions struct {
 	// LogFilePath is the path to where the log file should reside if using
 	// the file logger
 	LogFilePath string
+	// LogFileMaxSize is the default limit used for rotating the log file
+	LogFileMaxSize uint64
 }
 
 // Eventer is the interface for journald or file event logging
@@ -171,6 +173,8 @@ const (
 	Restart Status = "restart"
 	// Restore ...
 	Restore Status = "restore"
+	// Rotate indicates that the log file was rotated
+	Rotate Status = "log-rotation"
 	// Save ...
 	Save Status = "save"
 	// Start ...
diff --git a/libpod/events/events.go b/libpod/events/events.go
index 2cdd2ab67..1745095fb 100644
--- a/libpod/events/events.go
+++ b/libpod/events/events.go
@@ -3,11 +3,9 @@ package events
 import (
 	"encoding/json"
 	"fmt"
-	"os"
 	"time"
 
 	"github.com/containers/storage/pkg/stringid"
-	"github.com/nxadm/tail"
 	"github.com/pkg/errors"
 )
 
@@ -87,7 +85,11 @@ func (e *Event) ToHumanReadable(truncate bool) string {
 	case Image:
 		humanFormat = fmt.Sprintf("%s %s %s %s %s", e.Time, e.Type, e.Status, id, e.Name)
 	case System:
-		humanFormat = fmt.Sprintf("%s %s %s", e.Time, e.Type, e.Status)
+		if e.Name != "" {
+			humanFormat = fmt.Sprintf("%s %s %s %s", e.Time, e.Type, e.Status, e.Name)
+		} else {
+			humanFormat = fmt.Sprintf("%s %s %s", e.Time, e.Type, e.Status)
+		}
 	case Volume:
 		humanFormat = fmt.Sprintf("%s %s %s %s", e.Time, e.Type, e.Status, e.Name)
 	}
@@ -196,6 +198,8 @@ func StringToStatus(name string) (Status, error) {
 		return Restart, nil
 	case Restore.String():
 		return Restore, nil
+	case Rotate.String():
+		return Rotate, nil
 	case Save.String():
 		return Save, nil
 	case Start.String():
@@ -215,14 +219,3 @@ func StringToStatus(name string) (Status, error) {
 	}
 	return "", errors.Errorf("unknown event status %q", name)
 }
-
-func (e EventLogFile) getTail(options ReadOptions) (*tail.Tail, error) {
-	reopen := true
-	seek := tail.SeekInfo{Offset: 0, Whence: os.SEEK_END}
-	if options.FromStart || !options.Stream {
-		seek.Whence = 0
-		reopen = false
-	}
-	stream := options.Stream
-	return tail.TailFile(e.options.LogFilePath, tail.Config{ReOpen: reopen, Follow: stream, Location: &seek, Logger: tail.DiscardingLogger, Poll: true})
-}
diff --git a/libpod/events/logfile.go b/libpod/events/logfile.go
index 76173cde9..5091f3723 100644
--- a/libpod/events/logfile.go
+++ b/libpod/events/logfile.go
@@ -1,15 +1,24 @@
+//go:build linux
+// +build linux
+
 package events
 
 import (
+	"bufio"
 	"context"
 	"fmt"
+	"io"
+	"io/ioutil"
 	"os"
+	"path"
 	"time"
 
 	"github.com/containers/podman/v4/pkg/util"
 	"github.com/containers/storage/pkg/lockfile"
+	"github.com/nxadm/tail"
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
+	"golang.org/x/sys/unix"
 )
 
 // EventLogFile is the structure for event writing to a logfile. It contains the eventer
@@ -27,21 +36,55 @@ func (e EventLogFile) Write(ee Event) error {
 	}
 	lock.Lock()
 	defer lock.Unlock()
-	f, err := os.OpenFile(e.options.LogFilePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0700)
+
+	eventJSONString, err := ee.ToJSONString()
 	if err != nil {
 		return err
 	}
-	defer f.Close()
-	eventJSONString, err := ee.ToJSONString()
+
+	rotated, err := rotateLog(e.options.LogFilePath, eventJSONString, e.options.LogFileMaxSize)
+	if err != nil {
+		return fmt.Errorf("rotating log file: %w", err)
+	}
+
+	if rotated {
+		rEvent := NewEvent(Rotate)
+		rEvent.Type = System
+		rEvent.Name = e.options.LogFilePath
+		rotateJSONString, err := rEvent.ToJSONString()
+		if err != nil {
+			return err
+		}
+		if err := e.writeString(rotateJSONString); err != nil {
+			return err
+		}
+	}
+
+	return e.writeString(eventJSONString)
+}
+
+func (e EventLogFile) writeString(s string) error {
+	f, err := os.OpenFile(e.options.LogFilePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0700)
 	if err != nil {
 		return err
 	}
-	if _, err := f.WriteString(fmt.Sprintf("%s\n", eventJSONString)); err != nil {
+	if _, err := f.WriteString(s + "\n"); err != nil {
 		return err
 	}
 	return nil
 }
 
+func (e EventLogFile) getTail(options ReadOptions) (*tail.Tail, error) {
+	reopen := true
+	seek := tail.SeekInfo{Offset: 0, Whence: os.SEEK_END}
+	if options.FromStart || !options.Stream {
+		seek.Whence = 0
+		reopen = false
+	}
+	stream := options.Stream
+	return tail.TailFile(e.options.LogFilePath, tail.Config{ReOpen: reopen, Follow: stream, Location: &seek, Logger: tail.DiscardingLogger, Poll: true})
+}
+
 // Reads from the log file
 func (e EventLogFile) Read(ctx context.Context, options ReadOptions) error {
 	defer close(options.EventChannel)
@@ -107,3 +150,108 @@ func (e EventLogFile) Read(ctx context.Context, options ReadOptions) error {
 func (e EventLogFile) String() string {
 	return LogFile.String()
 }
+
+// Rotates the log file if the log file size and content exceeds limit
+func rotateLog(logfile string, content string, limit uint64) (bool, error) {
+	if limit == 0 {
+		return false, nil
+	}
+	file, err := os.Stat(logfile)
+	if err != nil {
+		return false, err
+	}
+	var filesize = uint64(file.Size())
+	var contentsize = uint64(len([]rune(content)))
+	if filesize+contentsize < limit {
+		return false, nil
+	}
+
+	if err := truncate(logfile); err != nil {
+		return false, err
+	}
+	return true, nil
+}
+
+// Truncates the log file and saves 50% of content to new log file
+func truncate(filePath string) error {
+	orig, err := os.Open(filePath)
+	if err != nil {
+		return err
+	}
+	defer orig.Close()
+
+	origFinfo, err := orig.Stat()
+	if err != nil {
+		return err
+	}
+
+	size := origFinfo.Size()
+	threshold := size / 2
+
+	tmp, err := ioutil.TempFile(path.Dir(filePath), "")
+	if err != nil {
+		// Retry in /tmp in case creating a tmp file in the same
+		// directory has failed.
+		tmp, err = ioutil.TempFile("", "")
+		if err != nil {
+			return err
+		}
+	}
+	defer tmp.Close()
+
+	// Jump directly to the threshold, drop the first line and copy the remainder
+	if _, err := orig.Seek(threshold, 0); err != nil {
+		return err
+	}
+	reader := bufio.NewReader(orig)
+	if _, err := reader.ReadString('\n'); err != nil {
+		if !errors.Is(err, io.EOF) {
+			return err
+		}
+	}
+	if _, err := reader.WriteTo(tmp); err != nil {
+		return fmt.Errorf("writing truncated contents: %w", err)
+	}
+
+	if err := renameLog(tmp.Name(), filePath); err != nil {
+		return fmt.Errorf("writing back %s to %s: %w", tmp.Name(), filePath, err)
+	}
+
+	return nil
+}
+
+// Renames from, to
+func renameLog(from, to string) error {
+	err := os.Rename(from, to)
+	if err == nil {
+		return nil
+	}
+
+	if !errors.Is(err, unix.EXDEV) {
+		return err
+	}
+
+	// Files are not on the same partition, so we need to copy them the
+	// hard way.
+	fFrom, err := os.Open(from)
+	if err != nil {
+		return err
+	}
+	defer fFrom.Close()
+
+	fTo, err := os.Create(to)
+	if err != nil {
+		return err
+	}
+	defer fTo.Close()
+
+	if _, err := io.Copy(fTo, fFrom); err != nil {
+		return fmt.Errorf("writing back from temporary file: %w", err)
+	}
+
+	if err := os.Remove(from); err != nil {
+		return fmt.Errorf("removing temporary file: %w", err)
+	}
+
+	return nil
+}
diff --git a/libpod/events/logfile_test.go b/libpod/events/logfile_test.go
new file mode 100644
index 000000000..302533c12
--- /dev/null
+++ b/libpod/events/logfile_test.go
@@ -0,0 +1,140 @@
+package events
+
+import (
+	"io/ioutil"
+	"os"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+)
+
+func TestRotateLog(t *testing.T) {
+	tests := []struct {
+		// If sizeInitial + sizeContent >= sizeLimit, then rotate
+		sizeInitial uint64
+		sizeContent uint64
+		sizeLimit   uint64
+		mustRotate  bool
+	}{
+		// No rotation
+		{0, 0, 1, false},
+		{1, 1, 0, false},
+		{10, 10, 30, false},
+		{1000, 500, 1600, false},
+		// Rotation
+		{10, 10, 20, true},
+		{30, 0, 29, true},
+		{200, 50, 150, true},
+		{1000, 600, 1500, true},
+	}
+
+	for _, test := range tests {
+		tmp, err := ioutil.TempFile("", "log-rotation-")
+		require.NoError(t, err)
+		defer os.Remove(tmp.Name())
+		defer tmp.Close()
+
+		// Create dummy file and content.
+		initialContent := make([]byte, test.sizeInitial)
+		logContent := make([]byte, test.sizeContent)
+
+		// Write content to the file.
+		_, err = tmp.Write(initialContent)
+		require.NoError(t, err)
+
+		// Now rotate
+		fInfoBeforeRotate, err := tmp.Stat()
+		require.NoError(t, err)
+		isRotated, err := rotateLog(tmp.Name(), string(logContent), test.sizeLimit)
+		require.NoError(t, err)
+
+		fInfoAfterRotate, err := os.Stat(tmp.Name())
+		// Test if rotation was successful
+		if test.mustRotate {
+			// File has been renamed
+			require.True(t, isRotated)
+			require.NoError(t, err, "log file has been renamed")
+			require.NotEqual(t, fInfoBeforeRotate.Size(), fInfoAfterRotate.Size())
+		} else {
+			// File has not been renamed
+			require.False(t, isRotated)
+			require.NoError(t, err, "log file has not been renamed")
+			require.Equal(t, fInfoBeforeRotate.Size(), fInfoAfterRotate.Size())
+		}
+	}
+}
+
+func TestTruncationOutput(t *testing.T) {
+	contentBefore := `0
+1
+2
+3
+4
+5
+6
+7
+8
+9
+10
+`
+	contentAfter := `6
+7
+8
+9
+10
+`
+	// Create dummy file
+	tmp, err := ioutil.TempFile("", "log-rotation")
+	require.NoError(t, err)
+	defer os.Remove(tmp.Name())
+	defer tmp.Close()
+
+	// Write content before truncation to dummy file
+	_, err = tmp.WriteString(contentBefore)
+	require.NoError(t, err)
+
+	// Truncate the file
+	beforeTruncation, err := ioutil.ReadFile(tmp.Name())
+	require.NoError(t, err)
+	err = truncate(tmp.Name())
+	require.NoError(t, err)
+	afterTruncation, err := ioutil.ReadFile(tmp.Name())
+	require.NoError(t, err)
+
+	// Test if rotation was successful
+	require.NoError(t, err, "Log content has changed")
+	require.NotEqual(t, beforeTruncation, afterTruncation)
+	require.Equal(t, string(afterTruncation), contentAfter)
+}
+
+func TestRenameLog(t *testing.T) {
+	fileContent := `0
+1
+2
+3
+4
+5
+`
+	// Create two dummy files
+	source, err := ioutil.TempFile("", "removing")
+	require.NoError(t, err)
+	target, err := ioutil.TempFile("", "renaming")
+	require.NoError(t, err)
+
+	// Write to source dummy file
+	_, err = source.WriteString(fileContent)
+	require.NoError(t, err)
+
+	// Rename the files
+	beforeRename, err := ioutil.ReadFile(source.Name())
+	require.NoError(t, err)
+	err = renameLog(source.Name(), target.Name())
+	require.NoError(t, err)
+	afterRename, err := ioutil.ReadFile(target.Name())
+	require.NoError(t, err)
+
+	// Test if renaming was successful
+	require.Error(t, os.Remove(source.Name()))
+	require.NoError(t, os.Remove(target.Name()))
+	require.Equal(t, beforeRename, afterRename)
+}
diff --git a/test/system/090-events.bats b/test/system/090-events.bats
index a0b0380a2..cac0a177c 100644
--- a/test/system/090-events.bats
+++ b/test/system/090-events.bats
@@ -129,3 +129,68 @@ EOF
     run cat $events_file
     is "$output" ".*\"Name\":\"$IMAGE" "test"
 }
+
+function _populate_events_file() {
+    # Create 100 duplicate entries to populate the events log file.
+    local events_file=$1
+    truncate --size=0 $events_file
+    for i in {0..99}; do
+    printf '{"Name":"busybox","Status":"pull","Time":"2022-04-06T11:26:42.7236679%02d+02:00","Type":"image","Attributes":null}\n' $i >> $events_file
+    done
+}
+
+@test "events log-file rotation" {
+    skip_if_remote "setting CONTAINERS_CONF logger options does not affect remote client"
+
+    # Make sure that the events log file is (not) rotated depending on the
+    # settings in containers.conf.
+
+    # Config without a limit
+    eventsFile=$PODMAN_TMPDIR/events.txt
+    _populate_events_file $eventsFile
+    containersConf=$PODMAN_TMPDIR/containers.conf
+    cat >$containersConf <<EOF
+[engine]
+events_logger="file"
+events_logfile_path="$eventsFile"
+EOF
+
+    # Create events *without* a limit and make sure that it has not been
+    # rotated/truncated.
+    contentBefore=$(head -n100 $eventsFile)
+    CONTAINERS_CONF=$containersConf run_podman run --rm $IMAGE true
+    contentAfter=$(head -n100 $eventsFile)
+    is "$contentBefore" "$contentAfter" "events file has not been rotated"
+
+    # Repopulate events file
+    rm $eventsFile
+    _populate_events_file $eventsFile
+
+    # Config with a limit
+    rm $containersConf
+    cat >$containersConf <<EOF
+[engine]
+events_logger="file"
+events_logfile_path="$eventsFile"
+# The limit of 4750 is the *exact* half of the inital events file.
+events_logfile_max_size=4750
+EOF
+
+    # Create events *with* a limit and make sure that it has been
+    # rotated/truncated.  Once rotated, the events file should only contain the
+    # second half of its previous events plus the new ones.
+    expectedContentAfterTruncation=$PODMAN_TMPDIR/truncated.txt
+
+    run_podman create $IMAGE
+    CONTAINERS_CONF=$containersConf run_podman rm $output
+    tail -n52 $eventsFile >> $expectedContentAfterTruncation
+
+    # Make sure the events file looks as expected.
+    is "$(cat $eventsFile)" "$(cat $expectedContentAfterTruncation)" "events file has been rotated"
+
+    # Make sure that `podman events` can read the file, and that it returns the
+    # same amount of events.  We checked the contents before.
+    CONTAINERS_CONF=$containersConf run_podman events --stream=false --since="2022-03-06T11:26:42.723667984+02:00"
+    is "$(wc -l <$eventsFile)" "$(wc -l <<<$output)" "all events are returned"
+    is "${lines[-2]}" ".* log-rotation $eventsFile"
+}