388 lines
12 KiB
Go
388 lines
12 KiB
Go
package logging
|
|
|
|
import (
|
|
"bytes"
|
|
"errors"
|
|
"fmt"
|
|
"io"
|
|
"os"
|
|
"path/filepath"
|
|
"strings"
|
|
"sync"
|
|
"sync/atomic"
|
|
"testing"
|
|
"time"
|
|
|
|
log "github.com/sirupsen/logrus"
|
|
)
|
|
|
|
func TestWeeklyLogRotationShiftsAndRetainsExactGenerations(t *testing.T) {
|
|
directory := t.TempDir()
|
|
path := filepath.Join(directory, "hardlink.log")
|
|
writeLogTestFile(t, path, "active")
|
|
for generation := 1; generation <= 14; generation++ {
|
|
writeLogTestFile(t, weeklyLogTestGeneration(path, generation), fmt.Sprintf("generation-%d", generation))
|
|
}
|
|
writeLogTestFile(t, weeklyLogTestGeneration(path, 19), "generation-19")
|
|
for name, contents := range map[string]string{
|
|
"hardlink.backup.14.log": "related-looking backup",
|
|
"another.14.log": "unrelated log",
|
|
"hardlink.14.log.bak": "different extension",
|
|
} {
|
|
writeLogTestFile(t, filepath.Join(directory, name), contents)
|
|
}
|
|
|
|
sunday := time.Date(2026, time.August, 9, 12, 0, 0, 0, time.UTC)
|
|
setLogTestModTime(t, path, sunday)
|
|
writer := newLogTestWriter(t, path, sunday, weeklyLogRuntime{})
|
|
writer.rotateIfNeeded(time.Date(2026, time.August, 10, 0, 0, 0, 0, time.UTC))
|
|
if err := writer.Close(); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
|
|
requireLogTestContents(t, path, "")
|
|
requireLogTestContents(t, weeklyLogTestGeneration(path, 1), "active")
|
|
requireLogTestContents(t, weeklyLogTestGeneration(path, 2), "generation-1")
|
|
requireLogTestContents(t, weeklyLogTestGeneration(path, 13), "generation-12")
|
|
for _, generation := range []int{14, 19} {
|
|
if _, err := os.Stat(weeklyLogTestGeneration(path, generation)); !errors.Is(err, os.ErrNotExist) {
|
|
t.Errorf("generation %d exists after rotation, want removed: %v", generation, err)
|
|
}
|
|
}
|
|
for name, contents := range map[string]string{
|
|
"hardlink.backup.14.log": "related-looking backup",
|
|
"another.14.log": "unrelated log",
|
|
"hardlink.14.log.bak": "different extension",
|
|
} {
|
|
requireLogTestContents(t, filepath.Join(directory, name), contents)
|
|
}
|
|
}
|
|
|
|
func TestWeeklyLogRotationOccursOncePerWeek(t *testing.T) {
|
|
directory := t.TempDir()
|
|
path := filepath.Join(directory, "hardlink.log")
|
|
writeLogTestFile(t, path, "week-zero\n")
|
|
sunday := time.Date(2026, time.January, 4, 18, 0, 0, 0, time.UTC)
|
|
setLogTestModTime(t, path, sunday)
|
|
writer := newLogTestWriter(t, path, sunday, weeklyLogRuntime{})
|
|
|
|
writer.rotateIfNeeded(time.Date(2026, time.January, 4, 23, 59, 59, 0, time.UTC))
|
|
if _, err := os.Stat(weeklyLogTestGeneration(path, 1)); !errors.Is(err, os.ErrNotExist) {
|
|
t.Fatalf("rotation before Monday: %v, want no generation", err)
|
|
}
|
|
writer.rotateIfNeeded(time.Date(2026, time.January, 5, 0, 0, 0, 0, time.UTC))
|
|
if _, err := writer.Write([]byte("week-one\n")); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
writer.rotateIfNeeded(time.Date(2026, time.January, 6, 12, 0, 0, 0, time.UTC))
|
|
if err := writer.Close(); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
|
|
requireLogTestContents(t, weeklyLogTestGeneration(path, 1), "week-zero\n")
|
|
requireLogTestContents(t, path, "week-one\n")
|
|
if _, err := os.Stat(weeklyLogTestGeneration(path, 2)); !errors.Is(err, os.ErrNotExist) {
|
|
t.Errorf("same-week rotation created generation 2: %v", err)
|
|
}
|
|
}
|
|
|
|
func TestWeeklyLogStartupRotatesOnceAfterSeveralMissedWeeks(t *testing.T) {
|
|
directory := t.TempDir()
|
|
path := filepath.Join(directory, "hardlink.log")
|
|
writeLogTestFile(t, path, "old active")
|
|
writeLogTestFile(t, weeklyLogTestGeneration(path, 1), "older history")
|
|
setLogTestModTime(t, path, time.Date(2026, time.January, 5, 12, 0, 0, 0, time.UTC))
|
|
|
|
now := time.Date(2026, time.February, 23, 9, 0, 0, 0, time.UTC)
|
|
writer := newLogTestWriter(t, path, now, weeklyLogRuntime{})
|
|
if err := writer.Close(); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
|
|
requireLogTestContents(t, weeklyLogTestGeneration(path, 1), "old active")
|
|
requireLogTestContents(t, weeklyLogTestGeneration(path, 2), "older history")
|
|
if _, err := os.Stat(weeklyLogTestGeneration(path, 3)); !errors.Is(err, os.ErrNotExist) {
|
|
t.Errorf("missed weeks created generation 3: %v", err)
|
|
}
|
|
}
|
|
|
|
func TestWeeklyLogSchedulerUsesLocalMondayBoundary(t *testing.T) {
|
|
location, err := time.LoadLocation("Europe/London")
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
directory := t.TempDir()
|
|
path := filepath.Join(directory, "hardlink.log")
|
|
writeLogTestFile(t, path, "sunday")
|
|
sunday := time.Date(2026, time.March, 29, 0, 0, 0, 0, location)
|
|
setLogTestModTime(t, path, sunday)
|
|
|
|
clock := &atomic.Pointer[time.Time]{}
|
|
clock.Store(&sunday)
|
|
created := make(chan *logTestTimer, 2)
|
|
rotated := make(chan struct{})
|
|
runtime := weeklyLogRuntime{
|
|
now: func() time.Time { return *clock.Load() },
|
|
newTimer: func(duration time.Duration) logRotationTimer {
|
|
timer := &logTestTimer{duration: duration, ch: make(chan time.Time, 1)}
|
|
created <- timer
|
|
return timer
|
|
},
|
|
rename: func(oldPath, newPath string) error {
|
|
err := os.Rename(oldPath, newPath)
|
|
if oldPath == path && err == nil {
|
|
close(rotated)
|
|
}
|
|
return err
|
|
},
|
|
}
|
|
writer, err := newWeeklyLogWriter(path, location, runtime)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
timer := <-created
|
|
if timer.duration != 23*time.Hour {
|
|
t.Fatalf("timer duration = %v, want 23h across DST boundary", timer.duration)
|
|
}
|
|
monday := time.Date(2026, time.March, 30, 0, 0, 0, 0, location)
|
|
clock.Store(&monday)
|
|
timer.ch <- monday
|
|
<-rotated
|
|
if err := writer.Close(); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
requireLogTestContents(t, weeklyLogTestGeneration(path, 1), "sunday")
|
|
}
|
|
|
|
func TestWeeklyLogConcurrentWritesRemainCompleteAcrossRotation(t *testing.T) {
|
|
directory := t.TempDir()
|
|
path := filepath.Join(directory, "hardlink.log")
|
|
sunday := time.Date(2026, time.August, 9, 12, 0, 0, 0, time.UTC)
|
|
writer := newLogTestWriter(t, path, sunday, weeklyLogRuntime{})
|
|
|
|
const goroutines = 8
|
|
const recordsPerGoroutine = 100
|
|
writeErrors := make(chan error, goroutines)
|
|
var writers sync.WaitGroup
|
|
writers.Add(goroutines)
|
|
for worker := 0; worker < goroutines; worker++ {
|
|
go func() {
|
|
defer writers.Done()
|
|
for record := 0; record < recordsPerGoroutine; record++ {
|
|
if _, err := writer.Write([]byte(fmt.Sprintf("%d:%d\n", worker, record))); err != nil {
|
|
writeErrors <- err
|
|
return
|
|
}
|
|
}
|
|
}()
|
|
}
|
|
writer.rotateIfNeeded(time.Date(2026, time.August, 10, 0, 0, 0, 0, time.UTC))
|
|
writers.Wait()
|
|
close(writeErrors)
|
|
for err := range writeErrors {
|
|
t.Errorf("weeklyLogWriter.Write() error = %v, want nil", err)
|
|
}
|
|
if err := writer.Close(); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
|
|
contents := readLogTestFile(t, weeklyLogTestGeneration(path, 1)) + readLogTestFile(t, path)
|
|
lines := strings.Split(strings.TrimSpace(contents), "\n")
|
|
if len(lines) != goroutines*recordsPerGoroutine {
|
|
t.Fatalf("record count = %d, want %d", len(lines), goroutines*recordsPerGoroutine)
|
|
}
|
|
seen := make(map[string]bool, len(lines))
|
|
for _, line := range lines {
|
|
if _, _, ok := strings.Cut(line, ":"); !ok {
|
|
t.Fatalf("record %q has no separator", line)
|
|
}
|
|
seen[line] = true
|
|
}
|
|
if len(seen) != goroutines*recordsPerGoroutine {
|
|
t.Errorf("unique record count = %d, want %d", len(seen), goroutines*recordsPerGoroutine)
|
|
}
|
|
}
|
|
|
|
func TestWeeklyLogCloseWaitsForRotationAndIsIdempotent(t *testing.T) {
|
|
directory := t.TempDir()
|
|
path := filepath.Join(directory, "hardlink.log")
|
|
writeLogTestFile(t, path, "active")
|
|
sunday := time.Date(2026, time.August, 9, 12, 0, 0, 0, time.UTC)
|
|
setLogTestModTime(t, path, sunday)
|
|
started := make(chan struct{})
|
|
release := make(chan struct{})
|
|
runtime := weeklyLogRuntime{rename: func(oldPath, newPath string) error {
|
|
if oldPath == path {
|
|
close(started)
|
|
<-release
|
|
}
|
|
return os.Rename(oldPath, newPath)
|
|
}}
|
|
writer := newLogTestWriter(t, path, sunday, runtime)
|
|
rotationDone := make(chan struct{})
|
|
go func() {
|
|
writer.rotateIfNeeded(time.Date(2026, time.August, 10, 0, 0, 0, 0, time.UTC))
|
|
close(rotationDone)
|
|
}()
|
|
<-started
|
|
|
|
closeDone := make(chan error, 1)
|
|
go func() { closeDone <- writer.Close() }()
|
|
select {
|
|
case err := <-closeDone:
|
|
t.Fatalf("weeklyLogWriter.Close() during rotation returned %v, want blocked", err)
|
|
case <-time.After(20 * time.Millisecond):
|
|
}
|
|
close(release)
|
|
<-rotationDone
|
|
if err := <-closeDone; err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if err := writer.Close(); err != nil {
|
|
t.Errorf("second weeklyLogWriter.Close() error = %v, want nil", err)
|
|
}
|
|
if _, err := writer.Write([]byte("after close")); !errors.Is(err, os.ErrClosed) {
|
|
t.Errorf("weeklyLogWriter.Write() after close error = %v, want os.ErrClosed", err)
|
|
}
|
|
}
|
|
|
|
func TestWeeklyLogRotationFailureIsNonRecursiveAndPreservesWrites(t *testing.T) {
|
|
directory := t.TempDir()
|
|
path := filepath.Join(directory, "hardlink.log")
|
|
writeLogTestFile(t, path, "before\n")
|
|
sunday := time.Date(2026, time.August, 9, 12, 0, 0, 0, time.UTC)
|
|
setLogTestModTime(t, path, sunday)
|
|
var diagnostics bytes.Buffer
|
|
runtime := weeklyLogRuntime{
|
|
rename: func(oldPath, newPath string) error {
|
|
if oldPath == path {
|
|
return errors.New("injected rename failure")
|
|
}
|
|
return os.Rename(oldPath, newPath)
|
|
},
|
|
diagnostic: &diagnostics,
|
|
}
|
|
writer := newLogTestWriter(t, path, sunday, runtime)
|
|
writer.rotateIfNeeded(time.Date(2026, time.August, 10, 0, 0, 0, 0, time.UTC))
|
|
if _, err := writer.Write([]byte("after\n")); err != nil {
|
|
t.Fatalf("weeklyLogWriter.Write() after failed rotation error = %v, want nil", err)
|
|
}
|
|
if err := writer.Close(); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
|
|
requireLogTestContents(t, path, "before\nafter\n")
|
|
if !strings.Contains(diagnostics.String(), "weekly_log_rotation_failed") || !strings.Contains(diagnostics.String(), "injected rename failure") {
|
|
t.Errorf("rotation diagnostic = %q, want action and injected error", diagnostics.String())
|
|
}
|
|
if strings.Contains(readLogTestFile(t, path), "weekly log rotation failed") {
|
|
t.Error("rotation diagnostic recursively entered active log")
|
|
}
|
|
}
|
|
|
|
func TestSetupLoggingKeepsFilenameAndJSONFormat(t *testing.T) {
|
|
logger := log.StandardLogger()
|
|
previousOutput := logger.Out
|
|
previousFormatter := logger.Formatter
|
|
previousLevel := logger.Level
|
|
t.Cleanup(func() {
|
|
logger.SetOutput(previousOutput)
|
|
logger.SetFormatter(previousFormatter)
|
|
logger.SetLevel(previousLevel)
|
|
})
|
|
|
|
directory := filepath.Join(t.TempDir(), "nested", "logs")
|
|
writer, err := SetupLogging(directory, "hardlink", "v-test")
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
log.WithField("probe", "value").Info("test record")
|
|
if err := writer.Close(); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
|
|
contents := readLogTestFile(t, filepath.Join(directory, "hardlink.log"))
|
|
for _, want := range []string{`"buildVersion":"v-test"`, `"msg":"Logging initialized"`, `"probe":"value"`, `"msg":"test record"`} {
|
|
if !strings.Contains(contents, want) {
|
|
t.Errorf("hardlink.log contents missing %q: %s", want, contents)
|
|
}
|
|
}
|
|
if _, err := os.Stat(filepath.Join(directory, "hardlink.1.log")); !errors.Is(err, os.ErrNotExist) {
|
|
t.Errorf("SetupLogging() created archive during current week: %v", err)
|
|
}
|
|
}
|
|
|
|
type logTestTimer struct {
|
|
duration time.Duration
|
|
ch chan time.Time
|
|
stopped atomic.Bool
|
|
}
|
|
|
|
func (t *logTestTimer) C() <-chan time.Time {
|
|
return t.ch
|
|
}
|
|
|
|
func (t *logTestTimer) Stop() bool {
|
|
return !t.stopped.Swap(true)
|
|
}
|
|
|
|
func newLogTestWriter(t *testing.T, path string, now time.Time, overrides weeklyLogRuntime) *weeklyLogWriter {
|
|
t.Helper()
|
|
runtime := defaultWeeklyLogRuntime()
|
|
runtime.now = func() time.Time { return now }
|
|
if overrides.now != nil {
|
|
runtime.now = overrides.now
|
|
}
|
|
if overrides.newTimer != nil {
|
|
runtime.newTimer = overrides.newTimer
|
|
}
|
|
if overrides.rename != nil {
|
|
runtime.rename = overrides.rename
|
|
}
|
|
if overrides.diagnostic != nil {
|
|
runtime.diagnostic = overrides.diagnostic
|
|
}
|
|
writer, err := newWeeklyLogWriter(path, now.Location(), runtime)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
return writer
|
|
}
|
|
|
|
func weeklyLogTestGeneration(path string, generation int) string {
|
|
extension := filepath.Ext(path)
|
|
return fmt.Sprintf("%s.%d%s", strings.TrimSuffix(path, extension), generation, extension)
|
|
}
|
|
|
|
func writeLogTestFile(t *testing.T, path, contents string) {
|
|
t.Helper()
|
|
if err := os.WriteFile(path, []byte(contents), 0o600); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
}
|
|
|
|
func setLogTestModTime(t *testing.T, path string, value time.Time) {
|
|
t.Helper()
|
|
if err := os.Chtimes(path, value, value); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
}
|
|
|
|
func readLogTestFile(t *testing.T, path string) string {
|
|
t.Helper()
|
|
contents, err := os.ReadFile(path)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
return string(contents)
|
|
}
|
|
|
|
func requireLogTestContents(t *testing.T, path, want string) {
|
|
t.Helper()
|
|
if got := readLogTestFile(t, path); got != want {
|
|
t.Errorf("%s contents = %q, want %q", filepath.Base(path), got, want)
|
|
}
|
|
}
|
|
|
|
var _ io.WriteCloser = (*weeklyLogWriter)(nil)
|