diff options
| -rw-r--r-- | libpod/events.go | 5 | ||||
| -rw-r--r-- | libpod/events/config.go | 4 | ||||
| -rw-r--r-- | libpod/events/events.go | 21 | ||||
| -rw-r--r-- | libpod/events/logfile.go | 156 | ||||
| -rw-r--r-- | libpod/events/logfile_test.go | 140 | ||||
| -rw-r--r-- | test/system/090-events.bats | 65 |
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" +} |