From f5872b536282179f931a5521ade79c9d97cf9d84 Mon Sep 17 00:00:00 2001 From: Tor Colvin Date: Mon, 5 Oct 2026 12:13:45 -0400 Subject: [PATCH 1/4] CBG-5405: fix race when InitLogging replaces memory loggers InitLogging copied the memory loggers' buffers without a lock, which raced with any goroutine that was still logging to them. NewFileLogger now takes the logger it replaces. For a memory logger, it calls SetOutput to wait for in-flight writes and forward later writes to the new logger, then copies the buffer. Log writes take no new lock. Tests that call InitializeMemoryLoggers and then InitLogging can run under the race detector again, so remove the !race build tag from audit_test.go and cluster_compat_audit_test.go. The audit RestTester now disables log collation for every logger, because FlushLogBuffers waits on a collation WaitGroup while background goroutines log. Co-Authored-By: Claude Opus 5.5 (1M context) --- base/logger_audit.go | 8 ++++++-- base/logger_file.go | 28 ++++++++++++++++++++++------ base/logging_config.go | 20 +++++++------------- rest/audit_test.go | 14 +++++++++++--- rest/cluster_compat_audit_test.go | 2 -- 5 files changed, 46 insertions(+), 26 deletions(-) diff --git a/base/logger_audit.go b/base/logger_audit.go index bcf5c00413..c606a3e6f7 100644 --- a/base/logger_audit.go +++ b/base/logger_audit.go @@ -187,7 +187,7 @@ func (l *AuditLogger) getAuditLoggerConfig() *AuditLoggerConfig { } // NewAuditLogger returns a new AuditLogger from a config. -func NewAuditLogger(ctx context.Context, config *AuditLoggerConfig, logFilePath string, minAge int, buffer *strings.Builder, globalFields map[string]any) (*AuditLogger, error) { +func NewAuditLogger(ctx context.Context, config *AuditLoggerConfig, logFilePath string, minAge int, prev *AuditLogger, globalFields map[string]any) (*AuditLogger, error) { if config == nil { config = &AuditLoggerConfig{} } @@ -203,7 +203,11 @@ func NewAuditLogger(ctx context.Context, config *AuditLoggerConfig, logFilePath config.CollationBufferSize = new(defaultFileLoggerCollateBufferSize) } - fl, err := NewFileLogger(ctx, &config.FileLoggerConfig, LevelNone, auditLogName, logFilePath, minAge, nil, buffer) + var prevFileLogger *FileLogger + if prev != nil { + prevFileLogger = &prev.FileLogger + } + fl, err := NewFileLogger(ctx, &config.FileLoggerConfig, LevelNone, auditLogName, logFilePath, minAge, nil, prevFileLogger) if err != nil { return nil, err } diff --git a/base/logger_file.go b/base/logger_file.go index 0069228487..a8ecba46db 100644 --- a/base/logger_file.go +++ b/base/logger_file.go @@ -88,8 +88,9 @@ type logRotationConfig struct { compress *bool `json:"-"` // Compress rotated logs, not exposed to users } -// NewFileLogger returns a new FileLogger from a config. -func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel, name string, logFilePath string, minAge int, defaultMaxAgeOverride *int, buffer *strings.Builder) (*FileLogger, error) { +// NewFileLogger returns a new FileLogger from a config. If prev is not nil, its buffered log lines are copied into the +// new logger, which is about to replace it. +func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel, name string, logFilePath string, minAge int, defaultMaxAgeOverride *int, prev *FileLogger) (*FileLogger, error) { if config == nil { config = &FileLoggerConfig{} } @@ -116,10 +117,6 @@ func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel } logger.Enabled.Set(*config.Enabled) - if buffer != nil { - logger.buffer = *buffer - } - // Only create the collateBuffer channel and worker if required. if *config.CollationBufferSize > 1 { logger.collateBuffer = make(chan string, *config.CollationBufferSize) @@ -130,9 +127,28 @@ func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel go logCollationWorker(logger.closed, logger.collateBuffer, logger.flushChan, logger.collateBufferWg, logger.logger, *config.CollationBufferSize, fileLoggerCollateFlushTimeout) } + if prev != nil { + if prev.output == &prev.buffer { + // SetOutput waits for in-flight writes to the memory logger, and later writes from goroutines that still hold + // prev are sent straight to the new logger. + prev.logger.SetOutput(loggerForwarder{logger}) + } + logger.buffer.WriteString(prev.buffer.String()) + } + return logger, nil } +// loggerForwarder is an io.Writer that writes each log line to a FileLogger. +type loggerForwarder struct { + logger *FileLogger +} + +func (f loggerForwarder) Write(p []byte) (int, error) { + f.logger.conditionalPrint(strings.TrimSuffix(string(p), "\n")) + return len(p), nil +} + func (l *FileLogger) FlushBufferToLog() { // Need to clear hanging new line to avoid empty line logString := strings.TrimSuffix(l.buffer.String(), "\n") diff --git a/base/logging_config.go b/base/logging_config.go index b577853493..6d3e88a7b4 100644 --- a/base/logging_config.go +++ b/base/logging_config.go @@ -16,7 +16,6 @@ import ( "log" "os" "path/filepath" - "strings" "time" "github.com/pkg/errors" @@ -92,49 +91,44 @@ func InitLogging(ctx context.Context, logFilePath string, ConsolefCtx(ctx, LevelInfo, KeyNone, "Logging: Audit to %v", auditLogFilePath) } - rawErrorlogger, err := NewFileLogger(ctx, error, LevelError, LevelError.String(), logFilePath, errorMinAge, nil, &errorLogger.Load().buffer) + rawErrorlogger, err := NewFileLogger(ctx, error, LevelError, LevelError.String(), logFilePath, errorMinAge, nil, errorLogger.Load()) if err != nil { return err } errorLogger.Store(rawErrorlogger) - rawWarnLogger, err := NewFileLogger(ctx, warn, LevelWarn, LevelWarn.String(), logFilePath, warnMinAge, nil, &warnLogger.Load().buffer) + rawWarnLogger, err := NewFileLogger(ctx, warn, LevelWarn, LevelWarn.String(), logFilePath, warnMinAge, nil, warnLogger.Load()) if err != nil { return err } warnLogger.Store(rawWarnLogger) - rawInfoLogger, err := NewFileLogger(ctx, info, LevelInfo, LevelInfo.String(), logFilePath, infoMinAge, nil, &infoLogger.Load().buffer) + rawInfoLogger, err := NewFileLogger(ctx, info, LevelInfo, LevelInfo.String(), logFilePath, infoMinAge, nil, infoLogger.Load()) if err != nil { return err } infoLogger.Store(rawInfoLogger) - rawDebugLogger, err := NewFileLogger(ctx, debug, LevelDebug, LevelDebug.String(), logFilePath, debugMinAge, nil, &debugLogger.Load().buffer) + rawDebugLogger, err := NewFileLogger(ctx, debug, LevelDebug, LevelDebug.String(), logFilePath, debugMinAge, nil, debugLogger.Load()) if err != nil { return err } debugLogger.Store(rawDebugLogger) - rawTraceLogger, err := NewFileLogger(ctx, trace, LevelTrace, LevelTrace.String(), logFilePath, traceMinAge, nil, &traceLogger.Load().buffer) + rawTraceLogger, err := NewFileLogger(ctx, trace, LevelTrace, LevelTrace.String(), logFilePath, traceMinAge, nil, traceLogger.Load()) if err != nil { return err } traceLogger.Store(rawTraceLogger) // Since there is no level checking in the stats logging, use LevelNone for the level. - rawStatsLogger, err := NewFileLogger(ctx, stats, LevelNone, "stats", logFilePath, statsMinAge, new(statsDefaultMaxAgeOverride), &statsLogger.Load().buffer) + rawStatsLogger, err := NewFileLogger(ctx, stats, LevelNone, "stats", logFilePath, statsMinAge, new(statsDefaultMaxAgeOverride), statsLogger.Load()) if err != nil { return err } statsLogger.Store(rawStatsLogger) - var auditLoggerBuffer *strings.Builder - prevAuditLogger := auditLogger.Load() - if prevAuditLogger != nil { - auditLoggerBuffer = &prevAuditLogger.buffer - } - rawAuditLogger, err := NewAuditLogger(ctx, audit, auditLogFilePath, auditMinAge, auditLoggerBuffer, auditLogGlobalFields) + rawAuditLogger, err := NewAuditLogger(ctx, audit, auditLogFilePath, auditMinAge, auditLogger.Load(), auditLogGlobalFields) if err != nil { return err } diff --git a/rest/audit_test.go b/rest/audit_test.go index b7b0642848..64a170d9a5 100644 --- a/rest/audit_test.go +++ b/rest/audit_test.go @@ -6,8 +6,6 @@ // software will be governed by the Apache License, Version 2.0, included in // the file licenses/APL2.txt. -//go:build !race - package rest import ( @@ -1627,9 +1625,16 @@ func createAuditLoggingRestTester(t *testing.T) *RestTester { }, Console: &base.ConsoleLoggerConfig{ FileLoggerConfig: base.FileLoggerConfig{ - Enabled: new(true), + Enabled: new(true), + CollationBufferSize: new(0), // avoid data race in collation with FlushLogBuffers test code }, }, + Error: &base.FileLoggerConfig{ + CollationBufferSize: new(0), // avoid data race in collation with FlushLogBuffers test code + }, + Warn: &base.FileLoggerConfig{ + CollationBufferSize: new(0), // avoid data race in collation with FlushLogBuffers test code + }, Info: &base.FileLoggerConfig{ Enabled: new(false), CollationBufferSize: new(0), // avoid data race in collation with FlushLogBuffers test code @@ -1642,6 +1647,9 @@ func createAuditLoggingRestTester(t *testing.T) *RestTester { Enabled: new(false), CollationBufferSize: new(0), // avoid data race in collation with FlushLogBuffers test code }, + Stats: &base.FileLoggerConfig{ + CollationBufferSize: new(0), // avoid data race in collation with FlushLogBuffers test code + }, } require.NoError(t, config.SetupAndValidateLogging(base.TestCtx(t))) }, diff --git a/rest/cluster_compat_audit_test.go b/rest/cluster_compat_audit_test.go index 377569155a..c451a26bbd 100644 --- a/rest/cluster_compat_audit_test.go +++ b/rest/cluster_compat_audit_test.go @@ -6,8 +6,6 @@ // software will be governed by the Apache License, Version 2.0, included in // the file licenses/APL2.txt. -//go:build !race - package rest import ( From 5e54118724f76fba130ca814ea84a5fe1a784ed0 Mon Sep 17 00:00:00 2001 From: Tor Colvin Date: Mon, 5 Oct 2026 20:07:30 -0400 Subject: [PATCH 2/4] CBG-5405: test log forwarding when a memory logger is replaced Co-Authored-By: Claude Opus 5.5 (1M context) --- base/logger_file_test.go | 46 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 46 insertions(+) diff --git a/base/logger_file_test.go b/base/logger_file_test.go index 349db209d8..14fe88d9ae 100644 --- a/base/logger_file_test.go +++ b/base/logger_file_test.go @@ -11,11 +11,13 @@ licenses/APL2.txt. package base import ( + "bytes" "fmt" "io" "log" "os" "path/filepath" + "strings" "testing" "github.com/couchbase/sync_gateway/testing/assert" @@ -276,3 +278,47 @@ func getDirFiles(t *testing.T, dir string) []string { } return fileNames } + +func TestNewFileLoggerReplacesMemoryLogger(t *testing.T) { + testCases := []struct { + name string + enabled bool + collationSize int + expected []string + }{ + {name: "uncollated", enabled: true, collationSize: 0, expected: []string{"buffered", "forwarded"}}, + {name: "collated", enabled: true, collationSize: 10, expected: []string{"buffered", "forwarded"}}, + {name: "disabled", enabled: false, collationSize: 0, expected: nil}, + } + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + prev := NewMemoryLogger(LevelInfo) + prev.log("buffered") + + var output bytes.Buffer + config := &FileLoggerConfig{ + Enabled: new(tc.enabled), + CollationBufferSize: new(tc.collationSize), + Output: &output, + } + logger, err := NewFileLogger(TestCtx(t), config, LevelInfo, "test", "", 0, nil, prev) + require.NoError(t, err) + defer func() { assert.NoError(t, logger.Close()) }() + + // a goroutine that loaded the global logger before it was replaced still writes to prev + prev.log("forwarded") + logger.FlushBufferToLog() + + if logger.collateBuffer != nil { + flushLogMutex.Lock() + defer flushLogMutex.Unlock() + logger.collateBufferWg.Wait() + flushLogBuffersWaitGroup.Add(1) + logger.flushChan <- struct{}{} + flushLogBuffersWaitGroup.Wait() + } + // forwarded lines go straight to output, so they can precede the buffered lines + assert.ElementsMatch(t, tc.expected, strings.Fields(output.String())) + }) + } +} From 4d0fbf54c8e23a38881fc029da50de8fc1f45686 Mon Sep 17 00:00:00 2001 From: Tor Colvin Date: Wed, 7 Oct 2026 09:36:47 -0400 Subject: [PATCH 3/4] move the swap logic out of constructors --- base/logger_audit.go | 8 ++------ base/logger_audit_test.go | 4 ++-- base/logger_file.go | 23 +++++++++++++---------- base/logger_file_test.go | 9 +++++++-- base/logging_config.go | 26 +++++++++++++------------- base/logging_test.go | 2 +- 6 files changed, 38 insertions(+), 34 deletions(-) diff --git a/base/logger_audit.go b/base/logger_audit.go index c606a3e6f7..4070d84e80 100644 --- a/base/logger_audit.go +++ b/base/logger_audit.go @@ -187,7 +187,7 @@ func (l *AuditLogger) getAuditLoggerConfig() *AuditLoggerConfig { } // NewAuditLogger returns a new AuditLogger from a config. -func NewAuditLogger(ctx context.Context, config *AuditLoggerConfig, logFilePath string, minAge int, prev *AuditLogger, globalFields map[string]any) (*AuditLogger, error) { +func NewAuditLogger(ctx context.Context, config *AuditLoggerConfig, logFilePath string, minAge int, globalFields map[string]any) (*AuditLogger, error) { if config == nil { config = &AuditLoggerConfig{} } @@ -203,11 +203,7 @@ func NewAuditLogger(ctx context.Context, config *AuditLoggerConfig, logFilePath config.CollationBufferSize = new(defaultFileLoggerCollateBufferSize) } - var prevFileLogger *FileLogger - if prev != nil { - prevFileLogger = &prev.FileLogger - } - fl, err := NewFileLogger(ctx, &config.FileLoggerConfig, LevelNone, auditLogName, logFilePath, minAge, nil, prevFileLogger) + fl, err := NewFileLogger(ctx, &config.FileLoggerConfig, LevelNone, auditLogName, logFilePath, minAge, nil) if err != nil { return nil, err } diff --git a/base/logger_audit_test.go b/base/logger_audit_test.go index ac394be913..3d957e2324 100644 --- a/base/logger_audit_test.go +++ b/base/logger_audit_test.go @@ -137,7 +137,7 @@ func TestAuditLoggerGlobalFields(t *testing.T) { if testCase.contextFields != nil { ctx = AuditLogCtx(ctx, testCase.contextFields) } - logger, err := NewAuditLogger(ctx, &AuditLoggerConfig{FileLoggerConfig: FileLoggerConfig{Enabled: new(true)}}, tmpdir, 0, nil, testCase.globalFields) + logger, err := NewAuditLogger(ctx, &AuditLoggerConfig{FileLoggerConfig: FileLoggerConfig{Enabled: new(true)}}, tmpdir, 0, testCase.globalFields) require.NoError(t, err) auditLogger.Store(logger) @@ -298,7 +298,7 @@ func BenchmarkAuditFieldwork(b *testing.B) { Output: buf, CollationBufferSize: new(0), }, - }, b.TempDir(), auditMinAge, nil, map[string]any{"foo": "bar", "buzz": 1234}) + }, b.TempDir(), auditMinAge, map[string]any{"foo": "bar", "buzz": 1234}) require.NoError(b, err) auditLogger.Store(al) diff --git a/base/logger_file.go b/base/logger_file.go index a8ecba46db..df2e3c03e4 100644 --- a/base/logger_file.go +++ b/base/logger_file.go @@ -21,6 +21,7 @@ import ( "runtime/debug" "strings" "sync" + "sync/atomic" "time" "github.com/pkg/errors" @@ -88,9 +89,8 @@ type logRotationConfig struct { compress *bool `json:"-"` // Compress rotated logs, not exposed to users } -// NewFileLogger returns a new FileLogger from a config. If prev is not nil, its buffered log lines are copied into the -// new logger, which is about to replace it. -func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel, name string, logFilePath string, minAge int, defaultMaxAgeOverride *int, prev *FileLogger) (*FileLogger, error) { +// NewFileLogger returns a new FileLogger from a config. +func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel, name string, logFilePath string, minAge int, defaultMaxAgeOverride *int) (*FileLogger, error) { if config == nil { config = &FileLoggerConfig{} } @@ -127,16 +127,19 @@ func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel go logCollationWorker(logger.closed, logger.collateBuffer, logger.flushChan, logger.collateBufferWg, logger.logger, *config.CollationBufferSize, fileLoggerCollateFlushTimeout) } - if prev != nil { + return logger, nil +} + +// swapFileLogger stores next in ptr, and moves buffered and later writes from the old memory logger to next. +func swapFileLogger(ptr *atomic.Pointer[FileLogger], next *FileLogger) { + if prev := ptr.Load(); prev != nil { if prev.output == &prev.buffer { - // SetOutput waits for in-flight writes to the memory logger, and later writes from goroutines that still hold - // prev are sent straight to the new logger. - prev.logger.SetOutput(loggerForwarder{logger}) + // SetOutput waits for in-flight writes to prev, so the buffer is stable once it returns. + prev.logger.SetOutput(loggerForwarder{next}) } - logger.buffer.WriteString(prev.buffer.String()) + next.buffer.WriteString(prev.buffer.String()) } - - return logger, nil + ptr.Store(next) } // loggerForwarder is an io.Writer that writes each log line to a FileLogger. diff --git a/base/logger_file_test.go b/base/logger_file_test.go index 14fe88d9ae..50419eb598 100644 --- a/base/logger_file_test.go +++ b/base/logger_file_test.go @@ -18,6 +18,7 @@ import ( "os" "path/filepath" "strings" + "sync/atomic" "testing" "github.com/couchbase/sync_gateway/testing/assert" @@ -279,7 +280,7 @@ func getDirFiles(t *testing.T, dir string) []string { return fileNames } -func TestNewFileLoggerReplacesMemoryLogger(t *testing.T) { +func TestSwapFileLoggerReplacesMemoryLogger(t *testing.T) { testCases := []struct { name string enabled bool @@ -294,6 +295,8 @@ func TestNewFileLoggerReplacesMemoryLogger(t *testing.T) { t.Run(tc.name, func(t *testing.T) { prev := NewMemoryLogger(LevelInfo) prev.log("buffered") + var ptr atomic.Pointer[FileLogger] + ptr.Store(prev) var output bytes.Buffer config := &FileLoggerConfig{ @@ -301,9 +304,11 @@ func TestNewFileLoggerReplacesMemoryLogger(t *testing.T) { CollationBufferSize: new(tc.collationSize), Output: &output, } - logger, err := NewFileLogger(TestCtx(t), config, LevelInfo, "test", "", 0, nil, prev) + logger, err := NewFileLogger(TestCtx(t), config, LevelInfo, "test", "", 0, nil) require.NoError(t, err) defer func() { assert.NoError(t, logger.Close()) }() + swapFileLogger(&ptr, logger) + require.Same(t, logger, ptr.Load()) // a goroutine that loaded the global logger before it was replaced still writes to prev prev.log("forwarded") diff --git a/base/logging_config.go b/base/logging_config.go index 6d3e88a7b4..d50cbd1eaa 100644 --- a/base/logging_config.go +++ b/base/logging_config.go @@ -91,44 +91,44 @@ func InitLogging(ctx context.Context, logFilePath string, ConsolefCtx(ctx, LevelInfo, KeyNone, "Logging: Audit to %v", auditLogFilePath) } - rawErrorlogger, err := NewFileLogger(ctx, error, LevelError, LevelError.String(), logFilePath, errorMinAge, nil, errorLogger.Load()) + rawErrorlogger, err := NewFileLogger(ctx, error, LevelError, LevelError.String(), logFilePath, errorMinAge, nil) if err != nil { return err } - errorLogger.Store(rawErrorlogger) + swapFileLogger(&errorLogger, rawErrorlogger) - rawWarnLogger, err := NewFileLogger(ctx, warn, LevelWarn, LevelWarn.String(), logFilePath, warnMinAge, nil, warnLogger.Load()) + rawWarnLogger, err := NewFileLogger(ctx, warn, LevelWarn, LevelWarn.String(), logFilePath, warnMinAge, nil) if err != nil { return err } - warnLogger.Store(rawWarnLogger) + swapFileLogger(&warnLogger, rawWarnLogger) - rawInfoLogger, err := NewFileLogger(ctx, info, LevelInfo, LevelInfo.String(), logFilePath, infoMinAge, nil, infoLogger.Load()) + rawInfoLogger, err := NewFileLogger(ctx, info, LevelInfo, LevelInfo.String(), logFilePath, infoMinAge, nil) if err != nil { return err } - infoLogger.Store(rawInfoLogger) + swapFileLogger(&infoLogger, rawInfoLogger) - rawDebugLogger, err := NewFileLogger(ctx, debug, LevelDebug, LevelDebug.String(), logFilePath, debugMinAge, nil, debugLogger.Load()) + rawDebugLogger, err := NewFileLogger(ctx, debug, LevelDebug, LevelDebug.String(), logFilePath, debugMinAge, nil) if err != nil { return err } - debugLogger.Store(rawDebugLogger) + swapFileLogger(&debugLogger, rawDebugLogger) - rawTraceLogger, err := NewFileLogger(ctx, trace, LevelTrace, LevelTrace.String(), logFilePath, traceMinAge, nil, traceLogger.Load()) + rawTraceLogger, err := NewFileLogger(ctx, trace, LevelTrace, LevelTrace.String(), logFilePath, traceMinAge, nil) if err != nil { return err } - traceLogger.Store(rawTraceLogger) + swapFileLogger(&traceLogger, rawTraceLogger) // Since there is no level checking in the stats logging, use LevelNone for the level. - rawStatsLogger, err := NewFileLogger(ctx, stats, LevelNone, "stats", logFilePath, statsMinAge, new(statsDefaultMaxAgeOverride), statsLogger.Load()) + rawStatsLogger, err := NewFileLogger(ctx, stats, LevelNone, "stats", logFilePath, statsMinAge, new(statsDefaultMaxAgeOverride)) if err != nil { return err } - statsLogger.Store(rawStatsLogger) + swapFileLogger(&statsLogger, rawStatsLogger) - rawAuditLogger, err := NewAuditLogger(ctx, audit, auditLogFilePath, auditMinAge, auditLogger.Load(), auditLogGlobalFields) + rawAuditLogger, err := NewAuditLogger(ctx, audit, auditLogFilePath, auditMinAge, auditLogGlobalFields) if err != nil { return err } diff --git a/base/logging_test.go b/base/logging_test.go index f430c8cea8..32be9f75b8 100644 --- a/base/logging_test.go +++ b/base/logging_test.go @@ -78,7 +78,7 @@ func TestLogRotationInterval(t *testing.T) { t.Logf("countBefore: %d", countBefore) ctx := TestCtx(t) - fl, err := NewFileLogger(ctx, config, LevelTrace, "test", logPath, 0, nil, nil) + fl, err := NewFileLogger(ctx, config, LevelTrace, "test", logPath, 0, nil) require.NoError(t, err) defer func() { assert.NoError(t, fl.Close()) From e9746a0c52ae295d4a571779ddba5ad0ab81251d Mon Sep 17 00:00:00 2001 From: Tor Colvin Date: Wed, 7 Oct 2026 12:18:24 -0400 Subject: [PATCH 4/4] allow swapping audit logger --- base/logger_audit_test.go | 33 +++++++++++++++++++++++++++++++++ base/logger_file.go | 15 ++++++++++++--- base/logger_file_test.go | 2 +- base/logging_config.go | 14 +++++++------- 4 files changed, 53 insertions(+), 11 deletions(-) diff --git a/base/logger_audit_test.go b/base/logger_audit_test.go index 3d957e2324..a73b9298a1 100644 --- a/base/logger_audit_test.go +++ b/base/logger_audit_test.go @@ -9,10 +9,14 @@ package base import ( + "bytes" "context" "encoding/json" "io" + "log" "maps" + "strings" + "sync/atomic" "testing" "github.com/couchbase/sync_gateway/testing/assert" @@ -355,3 +359,32 @@ func Test_expandFieldsAdditionalDataReadOnly(t *testing.T) { // additionalData should not be modified assert.Len(t, additionalData, 1) } + +func TestSwapAuditLoggerReplacesMemoryLogger(t *testing.T) { + prev := &AuditLogger{FileLogger: FileLogger{Enabled: AtomicBool{1}, closed: make(chan struct{})}} + prev.output = &prev.buffer + prev.logger = log.New(&prev.buffer, "", 0) + prev.log("buffered") + var ptr atomic.Pointer[AuditLogger] + ptr.Store(prev) + + var output bytes.Buffer + logger, err := NewAuditLogger(TestCtx(t), &AuditLoggerConfig{ + FileLoggerConfig: FileLoggerConfig{ + Enabled: new(true), + CollationBufferSize: new(0), + Output: &output, + }, + }, t.TempDir(), auditMinAge, nil) + require.NoError(t, err) + defer func() { assert.NoError(t, logger.Close()) }() + swapLogger(&ptr, logger) + require.Same(t, logger, ptr.Load()) + + // a goroutine that loaded the global logger before it was replaced still writes to prev + prev.log("forwarded") + logger.FlushBufferToLog() + + // forwarded lines go straight to output, so they can precede the buffered lines + assert.ElementsMatch(t, []string{"buffered", "forwarded"}, strings.Fields(output.String())) +} diff --git a/base/logger_file.go b/base/logger_file.go index df2e3c03e4..b6fe44b664 100644 --- a/base/logger_file.go +++ b/base/logger_file.go @@ -130,9 +130,13 @@ func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel return logger, nil } -// swapFileLogger stores next in ptr, and moves buffered and later writes from the old memory logger to next. -func swapFileLogger(ptr *atomic.Pointer[FileLogger], next *FileLogger) { - if prev := ptr.Load(); prev != nil { +// swapLogger stores next in ptr, and moves buffered and later writes from the old memory logger to next. +func swapLogger[T any, P interface { + *T + fileLogger() *FileLogger +}](ptr *atomic.Pointer[T], next P) { + if prev := P(ptr.Load()); prev != nil { + prev, next := prev.fileLogger(), next.fileLogger() if prev.output == &prev.buffer { // SetOutput waits for in-flight writes to prev, so the buffer is stable once it returns. prev.logger.SetOutput(loggerForwarder{next}) @@ -142,6 +146,11 @@ func swapFileLogger(ptr *atomic.Pointer[FileLogger], next *FileLogger) { ptr.Store(next) } +// fileLogger returns l. Loggers that embed FileLogger use it to give swapLogger their FileLogger. +func (l *FileLogger) fileLogger() *FileLogger { + return l +} + // loggerForwarder is an io.Writer that writes each log line to a FileLogger. type loggerForwarder struct { logger *FileLogger diff --git a/base/logger_file_test.go b/base/logger_file_test.go index 50419eb598..2d3e5b716e 100644 --- a/base/logger_file_test.go +++ b/base/logger_file_test.go @@ -307,7 +307,7 @@ func TestSwapFileLoggerReplacesMemoryLogger(t *testing.T) { logger, err := NewFileLogger(TestCtx(t), config, LevelInfo, "test", "", 0, nil) require.NoError(t, err) defer func() { assert.NoError(t, logger.Close()) }() - swapFileLogger(&ptr, logger) + swapLogger(&ptr, logger) require.Same(t, logger, ptr.Load()) // a goroutine that loaded the global logger before it was replaced still writes to prev diff --git a/base/logging_config.go b/base/logging_config.go index d50cbd1eaa..0c7a594d48 100644 --- a/base/logging_config.go +++ b/base/logging_config.go @@ -95,44 +95,44 @@ func InitLogging(ctx context.Context, logFilePath string, if err != nil { return err } - swapFileLogger(&errorLogger, rawErrorlogger) + swapLogger(&errorLogger, rawErrorlogger) rawWarnLogger, err := NewFileLogger(ctx, warn, LevelWarn, LevelWarn.String(), logFilePath, warnMinAge, nil) if err != nil { return err } - swapFileLogger(&warnLogger, rawWarnLogger) + swapLogger(&warnLogger, rawWarnLogger) rawInfoLogger, err := NewFileLogger(ctx, info, LevelInfo, LevelInfo.String(), logFilePath, infoMinAge, nil) if err != nil { return err } - swapFileLogger(&infoLogger, rawInfoLogger) + swapLogger(&infoLogger, rawInfoLogger) rawDebugLogger, err := NewFileLogger(ctx, debug, LevelDebug, LevelDebug.String(), logFilePath, debugMinAge, nil) if err != nil { return err } - swapFileLogger(&debugLogger, rawDebugLogger) + swapLogger(&debugLogger, rawDebugLogger) rawTraceLogger, err := NewFileLogger(ctx, trace, LevelTrace, LevelTrace.String(), logFilePath, traceMinAge, nil) if err != nil { return err } - swapFileLogger(&traceLogger, rawTraceLogger) + swapLogger(&traceLogger, rawTraceLogger) // Since there is no level checking in the stats logging, use LevelNone for the level. rawStatsLogger, err := NewFileLogger(ctx, stats, LevelNone, "stats", logFilePath, statsMinAge, new(statsDefaultMaxAgeOverride)) if err != nil { return err } - swapFileLogger(&statsLogger, rawStatsLogger) + swapLogger(&statsLogger, rawStatsLogger) rawAuditLogger, err := NewAuditLogger(ctx, audit, auditLogFilePath, auditMinAge, auditLogGlobalFields) if err != nil { return err } - auditLogger.Store(rawAuditLogger) + swapLogger(&auditLogger, rawAuditLogger) // Pick up any console log level/key changes for the external loggers too updateExternalLoggers()