From 99a167cda53cb9bebf17d9e639c666c60e915d8d Mon Sep 17 00:00:00 2001 From: mattthew Date: Tue, 27 Oct 2026 12:23:35 -0400 Subject: [PATCH] fix(core): stop log rotation from overwriting backups in the same millisecond LogWriter names rotated backups with a millisecond timestamp. When two rotations land in the same millisecond, os.Rename replaces the earlier backup and compress() truncates its .gz, so a full file of log lines is lost. This is what makes TestLogWriterWithCompression flaky on fast CI disks. backupName now bumps the stamp until neither the plain nor the .gz name exists. processOldLogFiles also failed to parse the timestamp of compressed backups, so .gz files never aged out past MaxAge. Strip the .gz suffix before parsing. The LogWriter tests now wait on a WaitGroup instead of sleeping 10s, stop calling require from goroutines, and pass expected/actual in the right order. Co-Authored-By: Claude Opus 5.5 --- x/log_writer.go | 23 +++++++++++++++++++---- x/log_writer_test.go | 43 +++++++++++++++++++++++++++++++++++-------- 2 files changed, 54 insertions(+), 12 deletions(-) diff --git a/x/log_writer.go b/x/log_writer.go index 01402fd1810..43ef60d2141 100644 --- a/x/log_writer.go +++ b/x/log_writer.go @@ -307,10 +307,25 @@ func (l *LogWriter) open() error { } func backupName(name string) string { + return nextBackupName(name, time.Now().UTC()) +} + +// nextBackupName returns the backup path for name stamped with ts. backupTimeFormat only has millisecond resolution, +// so two rotations can land on the same stamp; renaming onto an existing backup (or compressing over its .gz) would +// silently drop the older one. On a collision the stamp is pushed forward until neither form exists, which keeps the +// name parseable by processOldLogFiles and the backups ordered. +func nextBackupName(name string, ts time.Time) string { dir := filepath.Dir(name) prefix, ext := prefixAndExt(name) - timestamp := time.Now().UTC().Format(backupTimeFormat) - return filepath.Join(dir, fmt.Sprintf("%s-%s%s", prefix, timestamp, ext)) + for { + candidate := filepath.Join(dir, fmt.Sprintf("%s-%s%s", prefix, ts.Format(backupTimeFormat), ext)) + _, errPlain := os.Lstat(candidate) + _, errGz := os.Lstat(candidate + ".gz") + if errPlain != nil && errGz != nil { + return candidate + } + ts = ts.Add(time.Millisecond) + } } func compress(src string) error { @@ -424,8 +439,8 @@ func processOldLogFiles(fp string, maxAge int64) ([]string, []string, error) { continue } - _, e := prefixAndExt(fp) - tsString := f.Name()[len(defPrefix) : len(f.Name())-len(e)] + name := strings.TrimSuffix(f.Name(), ".gz") + tsString := name[len(defPrefix) : len(name)-len(defExt)] ts, err := time.Parse(backupTimeFormat, tsString) if err != nil { continue diff --git a/x/log_writer_test.go b/x/log_writer_test.go index ab3768ef082..d12f953a5a0 100644 --- a/x/log_writer_test.go +++ b/x/log_writer_test.go @@ -16,9 +16,11 @@ import ( "os" "path/filepath" "strings" + "sync" "testing" "time" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -73,7 +75,6 @@ func TestLogWriterWithEncryption(t *testing.T) { require.Equal(t, n, len(msg)+20, "write length is not equal") } - time.Sleep(time.Second * 10) require.NoError(t, lw.Close()) file, err := os.Open(path) require.NoError(t, err) @@ -120,23 +121,26 @@ func writeToLogWriterAndVerify(t *testing.T, lw *LogWriter, path string) { msg := []byte("abcd") msg = bytes.Repeat(msg, 256) msg[1023] = '\n' + var wg sync.WaitGroup for range 10 { - go func() { + wg.Go(func() { for range 1000 { n, err := lw.Write(msg) - require.NoError(t, err) - require.Equal(t, n, len(msg), "write length is not equal") + assert.NoError(t, err) + assert.Equal(t, len(msg), n, "write length is not equal") } - }() + }) } - time.Sleep(time.Second * 10) + wg.Wait() require.NoError(t, lw.Close()) files, err := os.ReadDir("./log_test") require.NoError(t, err) lineCount := 0 for _, f := range files { - file, _ := os.Open(filepath.Join(filepath.Dir(path), f.Name())) + file, err := os.Open(filepath.Join(filepath.Dir(path), f.Name())) + require.NoError(t, err) + defer file.Close() var fileScanner *bufio.Scanner if strings.HasSuffix(file.Name(), ".gz") { @@ -154,5 +158,28 @@ func writeToLogWriterAndVerify(t *testing.T, lw *LogWriter, path string) { } } - require.Equal(t, lineCount, 10000) + require.Equal(t, 10000, lineCount) +} + +func TestNextBackupName(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "audit.log") + ts := time.Date(2026, 10, 27, 9, 40, 12, 682_000_000, time.UTC) + + first := nextBackupName(path, ts) + require.Equal(t, filepath.Join(dir, "audit-2026-10-27T09-40-12.682.log"), first) + + // A backup already rotated within the same millisecond must not be overwritten. + require.NoError(t, os.WriteFile(first, nil, 0600)) + second := nextBackupName(path, ts) + require.Equal(t, filepath.Join(dir, "audit-2026-10-27T09-40-12.683.log"), second) + + // Nor may one that has already been compressed, since compress() truncates the .gz. + require.NoError(t, os.WriteFile(second+".gz", nil, 0600)) + require.Equal(t, filepath.Join(dir, "audit-2026-10-27T09-40-12.684.log"), nextBackupName(path, ts)) + + // Bumped names, plain or compressed, must stay parseable so they still age out. + toRemove, toKeep, err := processOldLogFiles(path, 1) + require.NoError(t, err) + require.Len(t, append(toRemove, toKeep...), 2) }