From 5461efc826952833fcdecca5d3daa3ee70423a31 Mon Sep 17 00:00:00 2001 From: Jeroen Wijenbergh Date: Fri, 1 Aug 2025 15:10:41 +0200 Subject: Client + Log: Implement a log rotater --- internal/config/config.go | 2 +- internal/log/log.go | 15 ++--- internal/log/rotate.go | 109 +++++++++++++++++++++++++++++++++ internal/log/rotate_test.go | 144 ++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 260 insertions(+), 10 deletions(-) create mode 100644 internal/log/rotate.go create mode 100644 internal/log/rotate_test.go (limited to 'internal') diff --git a/internal/config/config.go b/internal/config/config.go index e324ebb..4b939b2 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -8,7 +8,7 @@ import ( "os" "path" - "codeberg.org/eduVPN/eduvpn-common/internal/config/atomicfile" + "codeberg.org/eduVPN/eduvpn-common/internal/atomicfile" "codeberg.org/eduVPN/eduvpn-common/internal/config/v1" "codeberg.org/eduVPN/eduvpn-common/internal/config/v2" "codeberg.org/eduVPN/eduvpn-common/internal/discovery" diff --git a/internal/log/log.go b/internal/log/log.go index 53671b3..6a48ad7 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -14,25 +14,22 @@ import ( // This can be done as this function sets the logger as the default logger in slog // It returns the log file and the error // This log file should be closed at the end -func Init(lvl slog.Level, dir string) (*os.File, error) { +func Init(lvl slog.Level, dir string) (*FileRotater, error) { err := os.MkdirAll(dir, 0o700) if err != nil { return nil, err } name := path.Join(dir, "log") - f, err := os.OpenFile( - name, - os.O_RDWR|os.O_CREATE|os.O_APPEND, - 0o666, - ) + + fr, err := NewFileRotater(name) if err != nil { - return nil, fmt.Errorf("failed creating log: %w", err) + return nil, fmt.Errorf("failed creating log rotater: %w", err) } - multi := io.MultiWriter(os.Stdout, f) + multi := io.MultiWriter(os.Stdout, fr) handler := slog.NewTextHandler(multi, &slog.HandlerOptions{ Level: lvl, }) logger := slog.New(handler) slog.SetDefault(logger) - return f, nil + return fr, nil } diff --git a/internal/log/rotate.go b/internal/log/rotate.go new file mode 100644 index 0000000..fb93c3c --- /dev/null +++ b/internal/log/rotate.go @@ -0,0 +1,109 @@ +package log + +import ( + "io" + "os" + "sync" + + "codeberg.org/eduVPN/eduvpn-common/internal/atomicfile" +) + +var ( + // MaxSize is the maximum size in bytes from when to start trimming + MaxSize int64 = 1024 * 1024 + + // TrimSize denotes how much to trim from the beginning + TrimSize = MaxSize / 2 + + // TrimMsg is the message to display when it was trimmed + TrimMsg = "--- previous part was trimmed by eduvpn-common as the file was too big ---\n" +) + +// FileRotater is a file that is trimmed when a maximum size is reached +// This is for logging useful +type FileRotater struct { + filename string + file *os.File + mu sync.Mutex +} + +// NewFileRotater creates a new log file rotater +func NewFileRotater(filename string) (*FileRotater, error) { + fr := &FileRotater{ + filename: filename, + } + + err := fr.open() + if err != nil { + return nil, err + } + return fr, nil +} + +func (fr *FileRotater) open() error { + f, err := os.OpenFile(fr.filename, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0o666) + if err != nil { + return err + } + fr.file = f + return nil +} + +func (fr *FileRotater) trim() error { + fr.mu.Lock() + defer fr.mu.Unlock() + // We need to seek to the trim size to skip over that part as we discard it + _, err := fr.file.Seek(TrimSize, io.SeekStart) + if err != nil { + return err + } + + // get the part of the file that we want to keep + keep, err := io.ReadAll(fr.file) + if err != nil { + return err + } + + all := []byte(TrimMsg) + all = append(all, keep...) + err = atomicfile.WriteFile(fr.file.Name(), all, 0o666) + if err != nil { + return err + } + + // re-open the handle as the file was renamed + err = fr.file.Close() + if err != nil { + return err + } + err = fr.open() + if err != nil { + return err + } + return nil +} + +// Write implements io.Writer for the log rotater +func (fr *FileRotater) Write(p []byte) (n int, err error) { + fi, err := fr.file.Stat() + if err != nil { + return 0, err + } + + if fi.Size() >= MaxSize { + err = fr.trim() + if err != nil { + return 0, err + } + } + // we don't write atomically here as we want it to be as fast as possible + // and if we lose a part of one log statement it's not a big deal + return fr.file.Write(p) +} + +// Close closes the file in a safe way by locking and unlocking the mutex +func (fr *FileRotater) Close() error { + fr.mu.Lock() + defer fr.mu.Unlock() + return fr.file.Close() +} diff --git a/internal/log/rotate_test.go b/internal/log/rotate_test.go new file mode 100644 index 0000000..5381a49 --- /dev/null +++ b/internal/log/rotate_test.go @@ -0,0 +1,144 @@ +package log + +import ( + "io" + "os" + "path/filepath" + "strings" + "sync" + "testing" +) + +func createFileRotater(t *testing.T) (*FileRotater, func()) { + d, err := os.MkdirTemp("", "logtest") + if err != nil { + t.Fatalf("failed creating tmp dir: %v", err) + } + fn := filepath.Join(d, "test.log") + fr, err := NewFileRotater(fn) + if err != nil { + t.Fatalf("NewFileRotater error: %v", err) + } + if fr == nil { + t.Fatal("NewFileRotater returned nil") + } + return fr, func() { + err := os.RemoveAll(d) + if err != nil { + t.Errorf("failed removing file: %v", err) + } + } +} + +func TestNewFileRotater(t *testing.T) { + _, cleanup := createFileRotater(t) + cleanup() + + d, err := os.MkdirTemp("", "anotherlogtest") + if err != nil { + t.Fatalf("failed creating another tmp dir: %v", err) + } + nef := filepath.Join(d, "notexist", "test.log") + _, err = NewFileRotater(nef) + if err == nil { + t.Error("NewFileRotater returned no error with nonexistent dir") + } +} + +func TestWriteConcurrent(t *testing.T) { + fr, cleanup := createFileRotater(t) + defer cleanup() + MaxSize = 5 + var wg sync.WaitGroup + for range 5 { + wg.Add(1) + go func() { + _, err := fr.Write([]byte("test")) + defer wg.Done() + if err != nil { + t.Errorf("concurrent write returned an error: %v", err) + } + }() + } + wg.Wait() +} + +func TestWriteTrim(t *testing.T) { + fr, cleanup := createFileRotater(t) + defer cleanup() + writeNCheckSize := func(n int, size int64) { + buf := make([]byte, n) + + for i := 0; i < n; i++ { + buf[i] = 'x' + } + _, err := fr.Write(buf) + if err != nil { + t.Fatalf("failed writing: %v", err) + } + + fs, err := fr.file.Stat() + if err != nil { + t.Fatalf("failed getting size: %v", err) + } + + gsize := fs.Size() + + if gsize != size { + t.Fatalf("got: %v, want: %v, max size: %v", gsize, size, MaxSize) + } + } + + // we test by writing a start message and checking if it disappears after trimmign + // the max size we set to the length of the start message + 20 bytes + begS := "this is the start" + begB := []byte(begS) + startN := int64(len(begB)) + MaxSize = startN + 20 + TrimSize = MaxSize / 2 + + // no trim yet + _, err := fr.Write(begB) + if err != nil { + t.Fatalf("failed writing start message: %v", err) + } + + // write until the trimming size + writeNCheckSize(5, startN+5) + writeNCheckSize(15, MaxSize) + + // set the length we want to write + var n int64 = 11 + + // now the size should be the length of the trimmed message plus the remaining (non-trimmed part of the file) plus the length we want to write + + size := int64(len(TrimMsg)) + (MaxSize - TrimSize) + n + writeNCheckSize(11, size) + + // disable trimming by setting it to a high value + MaxSize = 9000 + TrimSize = 9000 + + // now the size should be the old size plus the write size + newN := 12 + writeNCheckSize(newN, size+int64(newN)) + + _, err = fr.file.Seek(0, io.SeekStart) + if err != nil { + t.Fatalf("failed going to beginning of file: %v", err) + } + + b, err := io.ReadAll(fr.file) + if err != nil { + t.Fatalf("failed reading file: %v", err) + } + + corpus := string(b) + if strings.Contains(corpus, begS) { + t.Fatalf("file still contains beginning message: %v", corpus) + } + + if !strings.Contains(corpus, TrimMsg) { + t.Fatalf("file does not contain trim message: %v", corpus) + } +} -- cgit v1.2.3