Merge pull request #13641 from nicrowe00/logfile

Add log rotation based on log size

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"
+}