From 3da3afa5764bcec2d50b219446579b5770051f32 Mon Sep 17 00:00:00 2001 From: Niall Crowe Date: Fri, 25 Feb 2022 09:25:30 +0000 Subject: 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 Signed-off-by: Valentin Rothberg --- libpod/events.go | 5 +- libpod/events/config.go | 4 ++ libpod/events/events.go | 21 ++---- libpod/events/logfile.go | 156 ++++++++++++++++++++++++++++++++++++++++-- libpod/events/logfile_test.go | 140 +++++++++++++++++++++++++++++++++++++ 5 files changed, 306 insertions(+), 20 deletions(-) create mode 100644 libpod/events/logfile_test.go (limited to 'libpod') 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) +} -- cgit v1.2.3-54-g00ecf