diff --git a/base/logger.go b/base/logger.go index 0294cea774..6d5734dbec 100644 --- a/base/logger.go +++ b/base/logger.go @@ -13,6 +13,7 @@ package base import ( "log" "math" + "slices" "strings" "sync" "time" @@ -21,27 +22,34 @@ import ( var flushLogBuffersWaitGroup sync.WaitGroup var flushLogMutex sync.Mutex +// getFileLoggers returns a slice of all non-nil file loggers. +func getFileLoggers() []*FileLogger { + loggers := []*FileLogger{ + traceLogger.Load(), + debugLogger.Load(), + infoLogger.Load(), + warnLogger.Load(), + errorLogger.Load(), + statsLogger.Load(), + } + rawAuditLogger := auditLogger.Load() + if rawAuditLogger != nil { + loggers = append(loggers, &rawAuditLogger.FileLogger) + } + rawConsoleLogger := consoleLogger.Load() + if rawConsoleLogger != nil { + loggers = append(loggers, &rawConsoleLogger.FileLogger) + } + return slices.DeleteFunc(loggers, func(l *FileLogger) bool { return l == nil }) +} + // FlushLogBuffers will cause all log collation buffers to be flushed to the output before returning. func FlushLogBuffers() { flushLogMutex.Lock() defer flushLogMutex.Unlock() - loggers := []*FileLogger{ - traceLogger, - debugLogger, - infoLogger, - warnLogger, - errorLogger, - statsLogger, - &consoleLogger.FileLogger, - } - - if auditLogger != nil { - loggers = append(loggers, &auditLogger.FileLogger) - } - - for _, logger := range loggers { - if logger != nil && cap(logger.collateBuffer) > 1 { + for _, logger := range getFileLoggers() { + if cap(logger.collateBuffer) > 1 { logger.collateBufferWg.Wait() flushLogBuffersWaitGroup.Add(1) logger.flushChan <- struct{}{} diff --git a/base/logger_audit.go b/base/logger_audit.go index 3b638beaa7..c2cd2e6907 100644 --- a/base/logger_audit.go +++ b/base/logger_audit.go @@ -119,20 +119,25 @@ func (f AuditFields) merge(ctx context.Context, overwrites AuditFields) AuditFie func Audit(ctx context.Context, id AuditID, additionalData AuditFields) { var fields AuditFields + logger := auditLogger.Load() if IsDevMode() { // NOTE: This check is expensive and indicates a dev-time mistake that needs addressing. // Don't bother in production code, but also delay expandFields until we know we will log. - fields = expandFields(id, ctx, auditLogger.globalFields, additionalData) + var globalFields AuditFields + if logger != nil { + globalFields = logger.globalFields + } + fields = expandFields(id, ctx, globalFields, additionalData) id.MustValidateFields(fields) } - if !auditLogger.shouldLog(id, ctx) { + if !logger.shouldLog(id, ctx) { return } // delayed expansion until after enabled checks in non-dev mode if fields == nil { - fields = expandFields(id, ctx, auditLogger.globalFields, additionalData) + fields = expandFields(id, ctx, logger.globalFields, additionalData) } fieldsJSON, err := jsoniter.MarshalToString(fields) @@ -141,12 +146,16 @@ func Audit(ctx context.Context, id AuditID, additionalData AuditFields) { return } - auditLogger.logf(fieldsJSON) + logger.logf(fieldsJSON) } // IsAuditEnabled checks if auditing is enabled for the SG node func IsAuditEnabled() bool { - return auditLogger.FileLogger.shouldLog(LevelNone) + logger := auditLogger.Load() + if logger == nil { + return false + } + return logger.FileLogger.shouldLog(LevelNone) } // AuditLogger is a file logger with audit-specific behaviour. @@ -164,10 +173,9 @@ func (l *AuditLogger) getAuditLoggerConfig() *AuditLoggerConfig { if l != nil { // Copy config struct to avoid mutating running config c = l.config + c.FileLoggerConfig = *l.getFileLoggerConfig() } - c.FileLoggerConfig = *l.getFileLoggerConfig() - return &c } @@ -229,7 +237,9 @@ func NewAuditLogger(ctx context.Context, config *AuditLoggerConfig, logFilePath } func (al *AuditLogger) shouldLog(id AuditID, ctx context.Context) bool { - if !auditLogger.FileLogger.shouldLog(LevelNone) { + if al == nil { + return false + } else if !al.FileLogger.shouldLog(LevelNone) { return false } diff --git a/base/logger_audit_test.go b/base/logger_audit_test.go index 63ea331175..d1ec98a9f3 100644 --- a/base/logger_audit_test.go +++ b/base/logger_audit_test.go @@ -136,9 +136,11 @@ func TestAuditLoggerGlobalFields(t *testing.T) { if testCase.contextFields != nil { ctx = AuditLogCtx(ctx, testCase.contextFields) } - var err error - auditLogger, err = NewAuditLogger(ctx, &AuditLoggerConfig{FileLoggerConfig: FileLoggerConfig{Enabled: BoolPtr(true)}}, tmpdir, 0, nil, testCase.globalFields) + logger, err := NewAuditLogger(ctx, &AuditLoggerConfig{FileLoggerConfig: FileLoggerConfig{Enabled: BoolPtr(true)}}, tmpdir, 0, nil, testCase.globalFields) require.NoError(t, err) + defer assert.NoError(t, logger.Close()) + auditLogger.Store(logger) + startWarnCount := SyncGatewayStats.GlobalStats.ResourceUtilizationStats().WarnCount.Value() output := AuditLogContents(t, func(tb testing.TB) { // Test basic audit event @@ -296,7 +298,7 @@ func BenchmarkAuditFieldwork(b *testing.B) { }, }, b.TempDir(), auditMinage, nil, map[string]any{"foo": "bar", "buzz": 1234}) require.NoError(b, err) - auditLogger = al + auditLogger.Store(al) ctx := TestCtx(b) ctx = DatabaseLogCtx(ctx, "db", nil) diff --git a/base/logger_external.go b/base/logger_external.go index 1130ee917d..9a355f2baa 100644 --- a/base/logger_external.go +++ b/base/logger_external.go @@ -47,7 +47,8 @@ func initExternalLoggers() { func updateExternalLoggers() { // use context.Background() since this is called from init or to reset test logging - if consoleLogger != nil && consoleLogger.shouldLog(context.Background(), LevelDebug, KeyWalrus) { + logger := consoleLogger.Load() + if logger.shouldLog(context.Background(), LevelDebug, KeyWalrus) { rosmar.SetLogLevel(rosmar.LevelDebug) } else { rosmar.SetLogLevel(rosmar.LevelInfo) @@ -170,10 +171,11 @@ func (CBGoUtilsLogger) SetLevel(l logging.Level) { // CBGoUtilsLogger.Level returns a compatible go-couchbase/golog Log Level for // the given logging config LogLevel func (CBGoUtilsLogger) Level() logging.Level { - if consoleLogger == nil || consoleLogger.LogLevel == nil { + logger := consoleLogger.Load() + if logger == nil || logger.LogLevel == nil { return logging.INFO } - switch *consoleLogger.LogLevel { + switch *logger.LogLevel { case LevelTrace: return logging.TRACE case LevelDebug: diff --git a/base/logger_file.go b/base/logger_file.go index 68fe89834d..ae25c3fed2 100644 --- a/base/logger_file.go +++ b/base/logger_file.go @@ -192,6 +192,13 @@ func (l *FileLogger) logf(format string, args ...interface{}) { } } +// conditionalPrintf will log the message if the log level is enabled. +func (l *FileLogger) conditionalPrintf(logLevel LogLevel, format string, args ...interface{}) { + if l.shouldLog(logLevel) { + l.logf(format, args...) + } +} + // shouldLog returns true if we can log. func (l *FileLogger) shouldLog(logLevel LogLevel) bool { return l != nil && l.logger != nil && diff --git a/base/logging.go b/base/logging.go index 3bfef17a47..111e4f1b9e 100644 --- a/base/logging.go +++ b/base/logging.go @@ -17,6 +17,7 @@ import ( "os" "runtime" "strings" + "sync/atomic" "testing" "time" @@ -85,10 +86,10 @@ func lastComponent(path string) string { // ************************************************************************* var ( - consoleLogger *ConsoleLogger - traceLogger, debugLogger, infoLogger, warnLogger, errorLogger, statsLogger *FileLogger + consoleLogger atomic.Pointer[ConsoleLogger] + traceLogger, debugLogger, infoLogger, warnLogger, errorLogger, statsLogger atomic.Pointer[FileLogger] - auditLogger = &AuditLogger{} + auditLogger atomic.Pointer[AuditLogger] // envColorCapable evaluated only once to prevent unnecessary // overhead of checking os.Getenv on each colorEnabled() invocation @@ -96,26 +97,24 @@ var ( ) // RotateLogfiles rotates all active log files. -func RotateLogfiles(ctx context.Context) map[*FileLogger]error { +func RotateLogfiles(ctx context.Context) { InfofCtx(ctx, KeyAll, "Rotating log files...") - loggers := map[*FileLogger]error{ - traceLogger: nil, - debugLogger: nil, - infoLogger: nil, - warnLogger: nil, - errorLogger: nil, - statsLogger: nil, - } - - for logger := range loggers { - loggers[logger] = logger.Rotate() + for _, logger := range getFileLoggers() { + err := logger.Rotate() + if err != nil { + WarnfCtx(ctx, "Error rotating %v: %v", logger, err) + } } - - return loggers } func init() { + initializeLoggers(context.Background()) +} + +// initializeLoggers should be called once per program in init. This is also called to reset logging in a test context. +func initializeLoggers(ctx context.Context) { + nilAllNonConsoleLoggers() // We'll initilise a default consoleLogger so we can still log stuff before/during parsing logging configs. // This maintains consistent formatting (timestamps, levels, etc) in the output, // and allows a single set of logging functions to be used, rather than fmt.Printf() @@ -124,7 +123,7 @@ func init() { // initializing a logging config, and when running under a test scenario. initialCollationBufferSize := 0 - consoleLogger = mustInitConsoleLogger(context.Background(), &ConsoleLoggerConfig{LogKeys: []string{logKeyNames[KeyHTTP]}, FileLoggerConfig: FileLoggerConfig{Enabled: BoolPtr(true), CollationBufferSize: &initialCollationBufferSize}}) + consoleLogger.Store(mustInitConsoleLogger(context.Background(), &ConsoleLoggerConfig{LogKeys: []string{logKeyNames[KeyHTTP]}, FileLoggerConfig: FileLoggerConfig{Enabled: BoolPtr(true), CollationBufferSize: &initialCollationBufferSize}})) initExternalLoggers() } @@ -133,7 +132,7 @@ type logFn func(ctx context.Context, format string, args ...any) // PanicfCtx logs the given formatted string and args to the error log level and given log key and then panics. func PanicfCtx(ctx context.Context, format string, args ...any) { // Fall back to stdlib's log.Panicf if SG loggers aren't set up. - if errorLogger == nil { + if errorLogger.Load() == nil { log.Panicf(format, args...) } // ensure the log message always reaches console @@ -145,7 +144,7 @@ func PanicfCtx(ctx context.Context, format string, args ...any) { // FatalfCtx logs the given formatted string and args to the error log level and given log key and then exits. func FatalfCtx(ctx context.Context, format string, args ...any) { // Fall back to stdlib's log.Panicf if SG loggers aren't set up. - if errorLogger == nil { + if errorLogger.Load() == nil { log.Fatalf(format, args...) } // ensure the log message always reaches console @@ -187,9 +186,8 @@ func LogLevelCtx(ctx context.Context, logLevel LogLevel, logKey LogKey, format s // RecordStats writes the given stats JSON content to a stats log file, if enabled. // The content passed in is expected to be a JSON dictionary. func RecordStats(statsJson string) { - if statsLogger != nil { - statsLogger.logf(statsJson) - } + // if statsLogger is nil, logf will no-op + statsLogger.Load().logf(statsJson) } // logTo is the "core" logging function. All other logging functions (like Debugf(), WarnfCtx(), etc.) end up here. @@ -206,12 +204,12 @@ func logTo(ctx context.Context, logLevel LogLevel, logKey LogKey, format string, SyncGatewayStats.GlobalStats.ResourceUtilizationStats().WarnCount.Add(1) } - shouldLogConsole := consoleLogger.shouldLog(ctx, logLevel, logKey) - shouldLogError := errorLogger.shouldLog(logLevel) - shouldLogWarn := warnLogger.shouldLog(logLevel) - shouldLogInfo := infoLogger.shouldLog(logLevel) - shouldLogDebug := debugLogger.shouldLog(logLevel) - shouldLogTrace := traceLogger.shouldLog(logLevel) + shouldLogConsole := consoleLogger.Load().shouldLog(ctx, logLevel, logKey) + shouldLogError := errorLogger.Load().shouldLog(logLevel) + shouldLogWarn := warnLogger.Load().shouldLog(logLevel) + shouldLogInfo := infoLogger.Load().shouldLog(logLevel) + shouldLogDebug := debugLogger.Load().shouldLog(logLevel) + shouldLogTrace := traceLogger.Load().shouldLog(logLevel) // exit before string formatting if no loggers need to log if !(shouldLogConsole || shouldLogError || shouldLogWarn || shouldLogInfo || shouldLogDebug || shouldLogTrace) { @@ -235,22 +233,22 @@ func logTo(ctx context.Context, logLevel LogLevel, logKey LogKey, format string, // If either global console or db console wants to log, allow it if shouldLogConsole { - consoleLogger.logf(color(format, logLevel), args...) + consoleLogger.Load().logf(color(format, logLevel), args...) } if shouldLogError { - errorLogger.logf(format, args...) + errorLogger.Load().logf(format, args...) } if shouldLogWarn { - warnLogger.logf(format, args...) + warnLogger.Load().logf(format, args...) } if shouldLogInfo { - infoLogger.logf(format, args...) + infoLogger.Load().logf(format, args...) } if shouldLogDebug { - debugLogger.logf(format, args...) + debugLogger.Load().logf(format, args...) } if shouldLogTrace { - traceLogger.logf(format, args...) + traceLogger.Load().logf(format, args...) } } @@ -261,8 +259,9 @@ var consoleFOutput io.Writer = os.Stderr func ConsolefCtx(ctx context.Context, logLevel LogLevel, logKey LogKey, format string, args ...any) { logTo(ctx, logLevel, logKey, format, args...) + logger := consoleLogger.Load() // If the above logTo didn't already log to stderr, do it directly here - if !consoleLogger.isStderr || !consoleLogger.shouldLog(ctx, logLevel, logKey) { + if !logger.isStderr || !logger.shouldLog(ctx, logLevel, logKey) { format = color(addPrefixes(format, ctx, logLevel, logKey), logLevel) _, _ = fmt.Fprintf(consoleFOutput, format+"\n", args...) } @@ -277,21 +276,11 @@ func LogSyncGatewayVersion(ctx context.Context) { // Log the startup indicator to ALL log files too. msg = addPrefixes(msg, ctx, LevelNone, KeyNone) - if errorLogger.shouldLog(LevelNone) { - errorLogger.logger.Printf(msg) - } - if warnLogger.shouldLog(LevelNone) { - warnLogger.logger.Printf(msg) - } - if infoLogger.shouldLog(LevelNone) { - infoLogger.logger.Printf(msg) - } - if debugLogger.shouldLog(LevelNone) { - debugLogger.logger.Printf(msg) - } - if traceLogger.shouldLog(LevelNone) { - traceLogger.logger.Printf(msg) - } + errorLogger.Load().conditionalPrintf(LevelNone, msg) + warnLogger.Load().conditionalPrintf(LevelNone, msg) + infoLogger.Load().conditionalPrintf(LevelNone, msg) + debugLogger.Load().conditionalPrintf(LevelNone, msg) + traceLogger.Load().conditionalPrintf(LevelNone, msg) } // addPrefixes will modify the format string to add timestamps, log level, and other common prefixes. @@ -358,35 +347,35 @@ func color(str string, logLevel LogLevel) string { // colorEnabled returns true if the console logger has color enabled, // and the environment supports ANSI color escape sequences. func colorEnabled() bool { - return consoleLogger.ColorEnabled && envColorCapable + return consoleLogger.Load().ColorEnabled && envColorCapable } // ConsoleLogLevel returns the console log level. func ConsoleLogLevel() *LogLevel { - return consoleLogger.LogLevel + return consoleLogger.Load().LogLevel } // ConsoleLogKey returns the console log key. func ConsoleLogKey() *LogKeyMask { - return consoleLogger.LogKeyMask + return consoleLogger.Load().LogKeyMask } // LogInfoEnabled returns true if either the console should log at info level, // or if the infoLogger is enabled. func LogInfoEnabled(ctx context.Context, logKey LogKey) bool { - return consoleLogger.shouldLog(ctx, LevelInfo, logKey) || infoLogger.shouldLog(LevelInfo) + return consoleLogger.Load().shouldLog(ctx, LevelInfo, logKey) || infoLogger.Load().shouldLog(LevelInfo) } // LogDebugEnabled returns true if either the console should log at debug level, // or if the debugLogger is enabled. func LogDebugEnabled(ctx context.Context, logKey LogKey) bool { - return consoleLogger.shouldLog(ctx, LevelDebug, logKey) || debugLogger.shouldLog(LevelDebug) + return consoleLogger.Load().shouldLog(ctx, LevelDebug, logKey) || debugLogger.Load().shouldLog(LevelDebug) } // LogTraceEnabled returns true if either the console should log at trace level, // or if the traceLogger is enabled. func LogTraceEnabled(ctx context.Context, logKey LogKey) bool { - return consoleLogger.shouldLog(ctx, LevelTrace, logKey) || traceLogger.shouldLog(LevelTrace) + return consoleLogger.Load().shouldLog(ctx, LevelTrace, logKey) || traceLogger.Load().shouldLog(LevelTrace) } func LogLevelEnabled(ctx context.Context, level LogLevel, logKey LogKey) bool { @@ -406,14 +395,14 @@ func AssertLogContains(t *testing.T, s string, f func()) { // Temporarily override logger output b := &bytes.Buffer{} mw := io.MultiWriter(b, os.Stderr) - consoleLogger.logger.SetOutput(mw) - defer func() { consoleLogger.logger.SetOutput(os.Stderr) }() - + consoleLogger.Load().logger.SetOutput(mw) // Call the given function f() FlushLogBuffers() - consoleLogger.FlushBufferToLog() + consoleLogger.Load().FlushBufferToLog() + // do not reset output in defer, since we are accessing b.String() after + consoleLogger.Load().logger.SetOutput(os.Stderr) assert.Contains(t, b.String(), s) } @@ -423,16 +412,14 @@ func AuditLogContents(t testing.TB, f func(t testing.TB)) []byte { b := &bytes.Buffer{} mw := io.MultiWriter(b, os.Stderr) - FlushLogBuffers() - auditLogger.FlushBufferToLog() - - auditLogger.logger.SetOutput(mw) - defer func() { auditLogger.logger.SetOutput(os.Stderr) }() + auditLogger.Load().logger.SetOutput(mw) // Call the given function f(t) FlushLogBuffers() - auditLogger.FlushBufferToLog() + auditLogger.Load().FlushBufferToLog() + // do not reset output in defer, since we are accessing b.bytes() + auditLogger.Load().logger.SetOutput(os.Stderr) return b.Bytes() } diff --git a/base/logging_config.go b/base/logging_config.go index 947997a2c0..5b43ce5534 100644 --- a/base/logging_config.go +++ b/base/logging_config.go @@ -16,6 +16,7 @@ import ( "log" "os" "path/filepath" + "strings" "time" "github.com/pkg/errors" @@ -62,26 +63,18 @@ func InitLogging(ctx context.Context, logFilePath string, error, warn, info, debug, trace, stats *FileLoggerConfig, audit *AuditLoggerConfig, auditLogGlobalFields map[string]any) (err error) { - consoleLogger, err = NewConsoleLogger(ctx, true, console) + rawConsoleLogger, err := NewConsoleLogger(ctx, true, console) if err != nil { return err } + consoleLogger.Store(rawConsoleLogger) // If there's nowhere to specified put log files, we'll log an error, but continue anyway. if logFilePath == "" { ConsolefCtx(ctx, LevelInfo, KeyNone, "Logging: Files disabled") // Explicitly log this error to console ConsolefCtx(ctx, LevelError, KeyNone, ErrUnsetLogFilePath.Error()) - - // nil out other loggers - errorLogger = nil - warnLogger = nil - infoLogger = nil - debugLogger = nil - traceLogger = nil - statsLogger = nil - auditLogger = &AuditLogger{} - + nilAllNonConsoleLoggers() return nil } @@ -101,41 +94,54 @@ func InitLogging(ctx context.Context, logFilePath string, } ConsolefCtx(ctx, LevelInfo, KeyNone, "Logging: Audit to %v", auditLogFilePath) } - errorLogger, err = NewFileLogger(ctx, error, LevelError, LevelError.String(), logFilePath, errorMinAge, &errorLogger.buffer) + + rawErrorlogger, err := NewFileLogger(ctx, error, LevelError, LevelError.String(), logFilePath, errorMinAge, &errorLogger.Load().buffer) if err != nil { return err } + errorLogger.Store(rawErrorlogger) - warnLogger, err = NewFileLogger(ctx, warn, LevelWarn, LevelWarn.String(), logFilePath, warnMinAge, &warnLogger.buffer) + rawWarnLogger, err := NewFileLogger(ctx, warn, LevelWarn, LevelWarn.String(), logFilePath, warnMinAge, &warnLogger.Load().buffer) if err != nil { return err } + warnLogger.Store(rawWarnLogger) - infoLogger, err = NewFileLogger(ctx, info, LevelInfo, LevelInfo.String(), logFilePath, infoMinAge, &infoLogger.buffer) + rawInfoLogger, err := NewFileLogger(ctx, info, LevelInfo, LevelInfo.String(), logFilePath, infoMinAge, &infoLogger.Load().buffer) if err != nil { return err } + infoLogger.Store(rawInfoLogger) - debugLogger, err = NewFileLogger(ctx, debug, LevelDebug, LevelDebug.String(), logFilePath, debugMinAge, &debugLogger.buffer) + rawDebugLogger, err := NewFileLogger(ctx, debug, LevelDebug, LevelDebug.String(), logFilePath, debugMinAge, &debugLogger.Load().buffer) if err != nil { return err } + debugLogger.Store(rawDebugLogger) - traceLogger, err = NewFileLogger(ctx, trace, LevelTrace, LevelTrace.String(), logFilePath, traceMinAge, &traceLogger.buffer) + rawTraceLogger, err := NewFileLogger(ctx, trace, LevelTrace, LevelTrace.String(), logFilePath, traceMinAge, &traceLogger.Load().buffer) if err != nil { return err } + traceLogger.Store(rawTraceLogger) // Since there is no level checking in the stats logging, use LevelNone for the level. - statsLogger, err = NewFileLogger(ctx, stats, LevelNone, "stats", logFilePath, statsMinage, &statsLogger.buffer) + rawStatsLogger, err := NewFileLogger(ctx, stats, LevelNone, "stats", logFilePath, statsMinage, &statsLogger.Load().buffer) if err != nil { return err } + statsLogger.Store(rawStatsLogger) - auditLogger, err = NewAuditLogger(ctx, audit, auditLogFilePath, auditMinage, &auditLogger.buffer, auditLogGlobalFields) + var auditLoggerBuffer *strings.Builder + prevAuditLogger := auditLogger.Load() + if prevAuditLogger != nil { + auditLoggerBuffer = &prevAuditLogger.buffer + } + rawAuditLogger, err := NewAuditLogger(ctx, audit, auditLogFilePath, auditMinage, auditLoggerBuffer, auditLogGlobalFields) if err != nil { return err } + auditLogger.Store(rawAuditLogger) // Initialize external loggers too initExternalLoggers() @@ -158,106 +164,105 @@ func NewMemoryLogger(level LogLevel) *FileLogger { // InitializeMemoryLoggers will set the global loggers to a in-memory logging buffer, to be flushed to configured outputs at a later time. func InitializeMemoryLoggers() { - errorLogger = NewMemoryLogger(LevelError) - warnLogger = NewMemoryLogger(LevelWarn) - infoLogger = NewMemoryLogger(LevelInfo) - debugLogger = NewMemoryLogger(LevelDebug) - traceLogger = NewMemoryLogger(LevelTrace) - statsLogger = NewMemoryLogger(LevelNone) + errorLogger.Store(NewMemoryLogger(LevelError)) + warnLogger.Store(NewMemoryLogger(LevelWarn)) + infoLogger.Store(NewMemoryLogger(LevelInfo)) + debugLogger.Store(NewMemoryLogger(LevelDebug)) + traceLogger.Store(NewMemoryLogger(LevelTrace)) + statsLogger.Store(NewMemoryLogger(LevelNone)) } func FlushLoggerBuffers() { - if errorLogger != nil { - errorLogger.FlushBufferToLog() - } - if warnLogger != nil { - warnLogger.FlushBufferToLog() - } - if infoLogger != nil { - infoLogger.FlushBufferToLog() - } - if debugLogger != nil { - debugLogger.FlushBufferToLog() - } - if traceLogger != nil { - traceLogger.FlushBufferToLog() - } - if statsLogger != nil { - statsLogger.FlushBufferToLog() + for _, logger := range getFileLoggers() { + logger.FlushBufferToLog() } } func EnableErrorLogger(enabled bool) { - if errorLogger != nil { - errorLogger.Enabled.Set(enabled) + logger := errorLogger.Load() + if logger == nil { + return } + logger.Enabled.Set(enabled) } func EnableWarnLogger(enabled bool) { - if warnLogger != nil { - warnLogger.Enabled.Set(enabled) + logger := warnLogger.Load() + if logger == nil { + return } + logger.Enabled.Set(enabled) } func EnableInfoLogger(enabled bool) { - if infoLogger != nil { - infoLogger.Enabled.Set(enabled) + logger := infoLogger.Load() + if logger == nil { + return } + logger.Enabled.Set(enabled) } func EnableDebugLogger(enabled bool) { - if debugLogger != nil { - debugLogger.Enabled.Set(enabled) + logger := debugLogger.Load() + if logger == nil { + return } + logger.Enabled.Set(enabled) } func EnableTraceLogger(enabled bool) { - if traceLogger != nil { - traceLogger.Enabled.Set(enabled) + logger := traceLogger.Load() + if logger == nil { + return } + logger.Enabled.Set(enabled) } func EnableStatsLogger(enabled bool) { - if statsLogger != nil { - statsLogger.Enabled.Set(enabled) + logger := statsLogger.Load() + if logger == nil { + return } + logger.Enabled.Set(enabled) } func EnableAuditLogger(ctx context.Context, enabled bool) { - if auditLogger != nil { - if !enabled { - Audit(ctx, AuditIDAuditDisabled, AuditFields{AuditFieldAuditScope: "global"}) - } - auditLogger.Enabled.Set(enabled) - if enabled { - Audit(ctx, AuditIDAuditEnabled, AuditFields{AuditFieldAuditScope: "global"}) - } + logger := auditLogger.Load() + if logger == nil { + return + } + if !enabled { + Audit(ctx, AuditIDAuditDisabled, AuditFields{AuditFieldAuditScope: "global"}) + } + logger.Enabled.Set(enabled) + if enabled { + Audit(ctx, AuditIDAuditEnabled, AuditFields{AuditFieldAuditScope: "global"}) } } // === Used by tests only === func ErrorLoggerIsEnabled() bool { - return errorLogger.Enabled.IsTrue() + return errorLogger.Load().Enabled.IsTrue() } func WarnLoggerIsEnabled() bool { - return warnLogger.Enabled.IsTrue() + return warnLogger.Load().Enabled.IsTrue() } func InfoLoggerIsEnabled() bool { - return infoLogger.Enabled.IsTrue() + return infoLogger.Load().Enabled.IsTrue() } func DebugLoggerIsEnabled() bool { - return debugLogger.Enabled.IsTrue() + return debugLogger.Load().Enabled.IsTrue() } func TraceLoggerIsEnabled() bool { - return traceLogger.Enabled.IsTrue() + return traceLogger.Load().Enabled.IsTrue() } func StatsLoggerIsEnabled() bool { - return statsLogger.Enabled.IsTrue() + return statsLogger.Load().Enabled.IsTrue() } type LoggingConfig struct { @@ -285,14 +290,14 @@ func BuildLoggingConfigFromLoggers(originalConfig LoggingConfig) *LoggingConfig LogFilePath: originalConfig.LogFilePath, } - config.Console = consoleLogger.getConsoleLoggerConfig() - config.Error = errorLogger.getFileLoggerConfig() - config.Warn = warnLogger.getFileLoggerConfig() - config.Info = infoLogger.getFileLoggerConfig() - config.Debug = debugLogger.getFileLoggerConfig() - config.Trace = traceLogger.getFileLoggerConfig() - config.Stats = statsLogger.getFileLoggerConfig() - config.Audit = auditLogger.getAuditLoggerConfig() + config.Console = consoleLogger.Load().getConsoleLoggerConfig() + config.Error = errorLogger.Load().getFileLoggerConfig() + config.Warn = warnLogger.Load().getFileLoggerConfig() + config.Info = infoLogger.Load().getFileLoggerConfig() + config.Debug = debugLogger.Load().getFileLoggerConfig() + config.Trace = traceLogger.Load().getFileLoggerConfig() + config.Stats = statsLogger.Load().getFileLoggerConfig() + config.Audit = auditLogger.Load().getAuditLoggerConfig() return &config } @@ -348,3 +353,14 @@ func validateLogFileOutput(logFileOutput string) error { return file.Close() } + +// nilAllNonConsoleLoggers will nil out all loggers except the console logger. +func nilAllNonConsoleLoggers() { + errorLogger.Store(nil) + warnLogger.Store(nil) + infoLogger.Store(nil) + debugLogger.Store(nil) + traceLogger.Store(nil) + statsLogger.Store(nil) + auditLogger.Store(nil) +} diff --git a/base/logging_context_test.go b/base/logging_context_test.go index 2cfb48f2de..0e8691b3ac 100644 --- a/base/logging_context_test.go +++ b/base/logging_context_test.go @@ -26,13 +26,14 @@ func requireLogIs(t testing.TB, s string, f func()) { timestampLength := len(time.Now().Format(ISO8601Format) + " ") + logger := consoleLogger.Load() // Temporarily override logger output for the given function call - originalColor := consoleLogger.ColorEnabled - consoleLogger.ColorEnabled = false - consoleLogger.logger.SetOutput(&b) + originalColor := logger.ColorEnabled + logger.ColorEnabled = false + logger.logger.SetOutput(&b) defer func() { - consoleLogger.ColorEnabled = originalColor - consoleLogger.logger.SetOutput(os.Stderr) + logger.ColorEnabled = originalColor + logger.logger.SetOutput(os.Stderr) }() f() diff --git a/base/logging_test.go b/base/logging_test.go index 04fdfe4da5..752ea0539a 100644 --- a/base/logging_test.go +++ b/base/logging_test.go @@ -174,10 +174,10 @@ func BenchmarkLogRotation(b *testing.B) { } func TestLogColor(t *testing.T) { - origColor := consoleLogger.ColorEnabled - defer func() { consoleLogger.ColorEnabled = origColor }() + origColor := consoleLogger.Load().ColorEnabled + defer func() { consoleLogger.Load().ColorEnabled = origColor }() - consoleLogger.ColorEnabled = true + consoleLogger.Load().ColorEnabled = true if colorEnabled() { assert.Equal(t, "\x1b[0;36mFormat\x1b[0m", color("Format", LevelDebug)) assert.Equal(t, "\x1b[1;34mFormat\x1b[0m", color("Format", LevelInfo)) @@ -187,7 +187,7 @@ func TestLogColor(t *testing.T) { assert.Equal(t, "\x1b[0mFormat\x1b[0m", color("Format", LevelNone)) } - consoleLogger.ColorEnabled = false + consoleLogger.Load().ColorEnabled = false assert.Equal(t, "Format", color("Format", LevelDebug)) assert.Equal(t, "Format", color("Format", LevelInfo)) assert.Equal(t, "Format", color("Format", LevelWarn)) @@ -202,7 +202,7 @@ func BenchmarkLogColorEnabled(b *testing.B) { } b.Run("enabled", func(b *testing.B) { - consoleLogger.ColorEnabled = true + consoleLogger.Load().ColorEnabled = true require.NoError(b, os.Setenv("TERM", "xterm-256color")) b.ResetTimer() @@ -212,7 +212,7 @@ func BenchmarkLogColorEnabled(b *testing.B) { }) b.Run("disabled console color", func(b *testing.B) { - consoleLogger.ColorEnabled = false + consoleLogger.Load().ColorEnabled = false require.NoError(b, os.Setenv("TERM", "xterm-256color")) b.ResetTimer() @@ -222,7 +222,7 @@ func BenchmarkLogColorEnabled(b *testing.B) { }) b.Run("disabled term color", func(b *testing.B) { - consoleLogger.ColorEnabled = true + consoleLogger.Load().ColorEnabled = true require.NoError(b, os.Setenv("TERM", "dumb")) b.ResetTimer() @@ -259,12 +259,12 @@ func TestLogSyncGatewayVersion(t *testing.T) { for i := LevelNone; i < levelCount; i++ { t.Run(i.String(), func(t *testing.T) { - consoleLogger.LogLevel.Set(i) + consoleLogger.Load().LogLevel.Set(i) out := CaptureConsolefLogOutput(func() { LogSyncGatewayVersion(TestCtx(t)) }) assert.Contains(t, out, LongVersionString) }) } - consoleLogger.LogLevel.Set(LevelInfo) + consoleLogger.Load().LogLevel.Set(LevelInfo) } func CaptureConsolefLogOutput(f func()) string { diff --git a/base/main_test_bucket_pool.go b/base/main_test_bucket_pool.go index 102d183d5b..a80cbc615f 100644 --- a/base/main_test_bucket_pool.go +++ b/base/main_test_bucket_pool.go @@ -716,7 +716,7 @@ func TestBucketPoolMain(ctx context.Context, m *testing.M, bucketReadierFunc TBP options TestBucketPoolOptions) { // can't use defer because of os.Exit teardownFuncs := make([]func(), 0) - teardownFuncs = append(teardownFuncs, SetUpGlobalTestLogging(ctx, m)) + teardownFuncs = append(teardownFuncs, SetUpGlobalTestLogging(ctx)) teardownFuncs = append(teardownFuncs, SetUpGlobalTestProfiling(m)) teardownFuncs = append(teardownFuncs, SetUpGlobalTestMemoryWatermark(m, options.MemWatermarkThresholdMB)) diff --git a/base/util_test.go b/base/util_test.go index 0b9478b269..7d8544682f 100644 --- a/base/util_test.go +++ b/base/util_test.go @@ -638,28 +638,28 @@ func TestSetTestLogging(t *testing.T) { } // Check default state of logging is as expected. - require.Equal(t, LevelInfo, *consoleLogger.LogLevel) - require.Equal(t, *logKeyMask(KeyHTTP), *consoleLogger.LogKeyMask) + require.Equal(t, LevelInfo, *consoleLogger.Load().LogLevel) + require.Equal(t, *logKeyMask(KeyHTTP), *consoleLogger.Load().LogKeyMask) cleanup := setTestLogging(LevelDebug, "", KeyDCP, KeySync) - assert.Equal(t, LevelDebug, *consoleLogger.LogLevel) - assert.Equal(t, *logKeyMask(KeyDCP, KeySync), *consoleLogger.LogKeyMask) + assert.Equal(t, LevelDebug, *consoleLogger.Load().LogLevel) + assert.Equal(t, *logKeyMask(KeyDCP, KeySync), *consoleLogger.Load().LogKeyMask) cleanup() - assert.Equal(t, LevelInfo, *consoleLogger.LogLevel) - require.Equal(t, *logKeyMask(KeyHTTP), *consoleLogger.LogKeyMask) + assert.Equal(t, LevelInfo, *consoleLogger.Load().LogLevel) + require.Equal(t, *logKeyMask(KeyHTTP), *consoleLogger.Load().LogKeyMask) cleanup = setTestLogging(LevelNone, "", KeyNone) - assert.Equal(t, LevelNone, *consoleLogger.LogLevel) - assert.Equal(t, *logKeyMask(KeyNone), *consoleLogger.LogKeyMask) + assert.Equal(t, LevelNone, *consoleLogger.Load().LogLevel) + assert.Equal(t, *logKeyMask(KeyNone), *consoleLogger.Load().LogKeyMask) cleanup() - assert.Equal(t, LevelInfo, *consoleLogger.LogLevel) - require.Equal(t, *logKeyMask(KeyHTTP), *consoleLogger.LogKeyMask) + assert.Equal(t, LevelInfo, *consoleLogger.Load().LogLevel) + require.Equal(t, *logKeyMask(KeyHTTP), *consoleLogger.Load().LogKeyMask) cleanup = setTestLogging(LevelDebug, "", KeyDCP, KeySync) - assert.Equal(t, LevelDebug, *consoleLogger.LogLevel) - assert.Equal(t, *logKeyMask(KeyDCP, KeySync), *consoleLogger.LogKeyMask) + assert.Equal(t, LevelDebug, *consoleLogger.Load().LogLevel) + assert.Equal(t, *logKeyMask(KeyDCP, KeySync), *consoleLogger.Load().LogKeyMask) // Now we should panic because we forgot to call teardown! assert.Panics(t, func() { diff --git a/base/util_testing.go b/base/util_testing.go index c824984183..1c0390d0b5 100644 --- a/base/util_testing.go +++ b/base/util_testing.go @@ -568,7 +568,7 @@ var GlobalTestLoggingSet = AtomicBool{} // SetUpGlobalTestLogging sets a global log level at runtime by using the SG_TEST_LOG_LEVEL environment variable. // This global level overrides any tests that specify their own test log level with SetUpTestLogging. -func SetUpGlobalTestLogging(ctx context.Context, m *testing.M) (teardownFn func()) { +func SetUpGlobalTestLogging(ctx context.Context) (teardownFn func()) { if logLevel := os.Getenv(TestEnvGlobalLogLevel); logLevel != "" { var l LogLevel err := l.UnmarshalText([]byte(logLevel)) @@ -598,49 +598,16 @@ func SetUpTestLogging(tb testing.TB, logLevel LogLevel, logKeys ...LogKey) { tb.Cleanup(cleanup) } -// ResetGlobalTestLogging will ensure that the loggers are replaced at the endof the the test. This is only safe to call with go:build !race since swapping the global loggers can trigger a race condition from background processes of the test harness. +// ResetGlobalTestLogging will ensure that the loggers are replaced at the end of the the test. func ResetGlobalTestLogging(t testing.TB) { - oldErrorLogger := errorLogger - oldWarnLogger := warnLogger - oldInfoLogger := infoLogger - oldDebugLogger := debugLogger - oldTraceLogger := traceLogger - oldStatsLogger := statsLogger - oldAuditLogger := auditLogger - oldConsoleLogger := consoleLogger t.Cleanup(func() { - if errorLogger != nil { - assert.NoError(t, errorLogger.Close()) + for _, logger := range getFileLoggers() { + assert.NoError(t, logger.Close()) } - errorLogger = oldErrorLogger - if warnLogger != nil { - assert.NoError(t, warnLogger.Close()) - } - warnLogger = oldWarnLogger - if infoLogger != nil { - assert.NoError(t, infoLogger.Close()) - } - infoLogger = oldInfoLogger - if debugLogger != nil { - assert.NoError(t, debugLogger.Close()) - } - debugLogger = oldDebugLogger - if traceLogger != nil { - assert.NoError(t, traceLogger.Close()) - } - traceLogger = oldTraceLogger - if statsLogger != nil { - assert.NoError(t, statsLogger.Close()) - } - statsLogger = oldStatsLogger - if auditLogger != nil { - assert.NoError(t, auditLogger.Close()) - } - auditLogger = oldAuditLogger - if consoleLogger != nil { - assert.NoError(t, consoleLogger.Close()) - } - consoleLogger = oldConsoleLogger + ctx := TestCtx(t) + initializeLoggers(ctx) + SetUpGlobalTestLogging(ctx) + }) } @@ -658,13 +625,14 @@ func SetUpBenchmarkLogging(tb testing.TB, logLevel LogLevel, logKeys ...LogKey) teardownFnOrig := setTestLogging(logLevel, "", logKeys...) // discard all logging output for benchmarking (but still execute logging as normal) - consoleLogger.logger.SetOutput(io.Discard) + consoleLogger.Load().logger.SetOutput(io.Discard) tb.Cleanup(func() { + logger := consoleLogger.Load() // revert back to original output - if consoleLogger != nil && consoleLogger.output != nil { - consoleLogger.logger.SetOutput(consoleLogger.output) + if logger != nil && logger.output != nil { + logger.logger.SetOutput(logger.output) } else { - consoleLogger.logger.SetOutput(os.Stderr) + logger.logger.SetOutput(os.Stderr) } teardownFnOrig() }) @@ -680,23 +648,27 @@ func setTestLogging(logLevel LogLevel, caller string, logKeys ...LogKey) (teardo } } + logger := consoleLogger.Load() initialLogLevel := LevelInfo initialLogKey := logKeyMask(KeyHTTP) // Check that a previous invocation has not forgotten to call teardownFn - if *consoleLogger.LogLevel != initialLogLevel || - *consoleLogger.LogKeyMask != *initialLogKey { - panic("Logging is in an unexpected state! Did a previous test forget to call the teardownFn of SetUpTestLogging?") + if *logger.LogLevel != initialLogLevel || + *logger.LogKeyMask != *initialLogKey { + panic(fmt.Sprintf("Logging is in an unexpected state! Did a previous test forget to call the teardownFn of SetUpTestLogging?, LogLevel=%s, expected=%s; LogKeyMask=%s, expected=%s", logger.LogLevel, initialLogLevel, logger.LogKeyMask, initialLogKey)) } - - consoleLogger.LogLevel.Set(logLevel) - consoleLogger.LogKeyMask.Set(logKeyMask(logKeys...)) + if errorLogger.Load() != nil { + panic("Logging is in an expected state, an earlier test possibly needed to call ResetGlobalTestLogging") + } + logger.LogLevel.Set(logLevel) + logger.LogKeyMask.Set(logKeyMask(logKeys...)) updateExternalLoggers() return func() { + logger := consoleLogger.Load() // Return logging to a default state - consoleLogger.LogLevel.Set(initialLogLevel) - consoleLogger.LogKeyMask.Set(initialLogKey) + logger.LogLevel.Set(initialLogLevel) + logger.LogKeyMask.Set(initialLogKey) updateExternalLoggers() if caller != "" { InfofCtx(context.Background(), KeyAll, "%v: Reset logging", caller) diff --git a/channels/main_test.go b/channels/main_test.go index f3877481b9..1ed04b08e0 100644 --- a/channels/main_test.go +++ b/channels/main_test.go @@ -22,7 +22,7 @@ func TestMain(m *testing.M) { ctx := context.Background() // start of test process // can't use defer because of os.Exit teardownFuncs := make([]func(), 0) - teardownFuncs = append(teardownFuncs, base.SetUpGlobalTestLogging(ctx, m)) + teardownFuncs = append(teardownFuncs, base.SetUpGlobalTestLogging(ctx)) teardownFuncs = append(teardownFuncs, base.SetUpGlobalTestProfiling(m)) teardownFuncs = append(teardownFuncs, base.SetUpGlobalTestMemoryWatermark(m, 128)) diff --git a/rest/adminapitest/admin_api_test.go b/rest/adminapitest/admin_api_test.go index f8984379af..63fffe8339 100644 --- a/rest/adminapitest/admin_api_test.go +++ b/rest/adminapitest/admin_api_test.go @@ -163,6 +163,7 @@ func TestNoPanicInvalidUpdate(t *testing.T) { } func TestLoggingKeys(t *testing.T) { + base.ResetGlobalTestLogging(t) if base.GlobalTestLoggingSet.IsTrue() { t.Skip("Test does not work when a global test log level is set") } @@ -2924,6 +2925,7 @@ func TestConfigEndpoint(t *testing.T) { for _, testCase := range testCases { t.Run(testCase.Name, func(t *testing.T) { + base.ResetGlobalTestLogging(t) base.SetUpTestLogging(t, base.LevelInfo, base.KeyAll) base.InitializeMemoryLoggers() @@ -3025,6 +3027,7 @@ func TestInitialStartupConfig(t *testing.T) { } func TestIncludeRuntimeStartupConfig(t *testing.T) { + base.ResetGlobalTestLogging(t) base.SetUpTestLogging(t, base.LevelInfo, base.KeyAll) base.InitializeMemoryLoggers() @@ -3275,6 +3278,7 @@ func TestNotExistentDBRequest(t *testing.T) { } func TestConfigsIncludeDefaults(t *testing.T) { + base.ResetGlobalTestLogging(t) base.RequireNumTestBuckets(t, 2) base.SetUpTestLogging(t, base.LevelInfo, base.KeyHTTP) diff --git a/rest/audit_test.go b/rest/audit_test.go index f97cb11a50..b75b9aa180 100644 --- a/rest/audit_test.go +++ b/rest/audit_test.go @@ -13,8 +13,10 @@ package rest import ( "bytes" "encoding/base64" + "encoding/json" "fmt" "net/http" + "os" "strings" "testing" @@ -60,15 +62,8 @@ func TestAuditLoggingFields(t *testing.T) { config.Unsupported.AuditInfoProvider = &AuditInfoProviderConfig{ RequestInfoHeaderName: base.StringPtr(requestInfoHeaderName), } - config.Logging = base.LoggingConfig{ - LogFilePath: tempdir, - Audit: &base.AuditLoggerConfig{ - FileLoggerConfig: base.FileLoggerConfig{ - Enabled: base.BoolPtr(true), - }, - EnabledEvents: base.AllGlobalAuditeventIDs, // enable everything for testing - }, - } + config.Logging = getAuditLoggingTestConfig(tempdir) + config.Logging.Audit.EnabledEvents = base.AllGlobalAuditeventIDs require.NoError(t, config.SetupAndValidateLogging(base.TestCtx(t))) }, }) @@ -537,42 +532,7 @@ func jsonLines(t testing.TB, data []byte) []map[string]any { } func TestAuditDatabaseUpdate(t *testing.T) { - // get tempdir before resetting global loggers, since the logger cleanup needs to happen before deletion - tempdir := t.TempDir() - base.ResetGlobalTestLogging(t) - base.InitializeMemoryLoggers() - rt := NewRestTester(t, &RestTesterConfig{ - PersistentConfig: true, - MutateStartupConfig: func(config *StartupConfig) { - config.Logging = base.LoggingConfig{ - LogFilePath: tempdir, - Audit: &base.AuditLoggerConfig{ - FileLoggerConfig: base.FileLoggerConfig{ - Enabled: base.BoolPtr(true), - CollationBufferSize: base.IntPtr(0), // avoid data race in collation with FlushLogBuffers test code - }, - }, - Console: &base.ConsoleLoggerConfig{ - FileLoggerConfig: base.FileLoggerConfig{ - Enabled: base.BoolPtr(true), - }, - }, - Info: &base.FileLoggerConfig{ - Enabled: base.BoolPtr(false), - CollationBufferSize: base.IntPtr(0), // avoid data race in collation with FlushLogBuffers test code - }, - Debug: &base.FileLoggerConfig{ - Enabled: base.BoolPtr(false), - CollationBufferSize: base.IntPtr(0), // avoid data race in collation with FlushLogBuffers test code - }, - Trace: &base.FileLoggerConfig{ - Enabled: base.BoolPtr(false), - CollationBufferSize: base.IntPtr(0), // avoid data race in collation with FlushLogBuffers test code - }, - } - require.NoError(t, config.SetupAndValidateLogging(base.TestCtx(t))) - }, - }) + rt := createAuditLoggingRestTester(t) defer rt.Close() // initialize RestTester @@ -740,14 +700,7 @@ func TestEffectiveUserID(t *testing.T) { PersistentConfig: true, MutateStartupConfig: func(config *StartupConfig) { config.Unsupported.EffectiveUserHeaderName = base.StringPtr("user_header") - config.Logging = base.LoggingConfig{ - LogFilePath: tempdir, - Audit: &base.AuditLoggerConfig{ - FileLoggerConfig: base.FileLoggerConfig{ - Enabled: base.BoolPtr(true), - }, - }, - } + config.Logging = getAuditLoggingTestConfig(tempdir) require.NoError(t, config.SetupAndValidateLogging(base.TestCtx(t))) }, }) @@ -1568,6 +1521,82 @@ func TestAuditBlipCRUD(t *testing.T) { }) } +// TestAuditLoggingGlobals modifies all the global loggers +func TestAuditLoggingGlobals(t *testing.T) { + globalFields := map[string]any{ + "global": "field", + "global2": "field2", + } + + globalEnvVarName := "SG_TEST_GLOBAL_AUDIT_LOGGING" + + testCases := []struct { + name string + globalAuditEvents *string + startupErrorMsg string + }{ + { + name: "no global fields", + }, + { + name: "with global fields", + globalAuditEvents: base.StringPtr(string(base.MustJSONMarshal(t, globalFields))), + }, + { + name: "invalid json", + globalAuditEvents: base.StringPtr(`notjson`), + startupErrorMsg: "Unable to unmarshal", + }, + { + name: "empty env var", + globalAuditEvents: base.StringPtr(""), + startupErrorMsg: "Unable to unmarshal", + }, + } + for _, testCase := range testCases { + t.Run(testCase.name, func(t *testing.T) { + base.ResetGlobalTestLogging(t) + base.InitializeMemoryLoggers() + ctx := base.TestCtx(t) + if testCase.globalAuditEvents != nil { + require.NoError(t, os.Setenv(globalEnvVarName, *testCase.globalAuditEvents)) + defer func() { + require.NoError(t, os.Unsetenv(globalEnvVarName)) + }() + } else { + require.NoError(t, os.Unsetenv(globalEnvVarName)) + } + startupConfig := DefaultStartupConfig("") + startupConfig.Logging = getAuditLoggingTestConfig(t.TempDir()) + if testCase.globalAuditEvents != nil { + startupConfig.Unsupported.AuditInfoProvider = &AuditInfoProviderConfig{ + GlobalInfoEnvVarName: base.StringPtr(globalEnvVarName), + } + } + err := startupConfig.SetupAndValidateLogging(ctx) + if testCase.startupErrorMsg != "" { + require.ErrorContains(t, err, testCase.startupErrorMsg) + return + } + require.NoError(t, err) + output := base.AuditLogContents(t, func(tb testing.TB) { + base.Audit(ctx, base.AuditIDPublicUserAuthenticated, map[string]any{base.AuditFieldAuthMethod: "basic"}) + }) + var event map[string]any + require.NoError(t, json.Unmarshal(output, &event)) + require.Contains(t, event, base.AuditFieldAuthMethod) + for k, v := range globalFields { + if testCase.globalAuditEvents != nil { + require.Equal(t, v, event[k]) + } else { + require.NotContains(t, event, k) + } + } + }) + } + +} + // TestDatabaseAuditChanges verifies that the expect events are raised when the audit configuration is changed. // Note: test cases are run sequentially, and depend on ordering, as events are only raised for changes in state func TestDatabaseAuditChanges(t *testing.T) { @@ -1735,3 +1764,33 @@ func TestDatabaseAuditChanges(t *testing.T) { }) } } + +// getAuditLoggingTestConfig returns a logging config with audit enabled and other loggers configured without collation to avoid CBG-4129 +func getAuditLoggingTestConfig(tempdir string) base.LoggingConfig { + return base.LoggingConfig{ + LogFilePath: tempdir, + Audit: &base.AuditLoggerConfig{ + FileLoggerConfig: base.FileLoggerConfig{ + Enabled: base.BoolPtr(true), + CollationBufferSize: base.IntPtr(0), // avoid data race in collation with FlushLogBuffers test code CBG-4129 + }, + }, + Console: &base.ConsoleLoggerConfig{ + FileLoggerConfig: base.FileLoggerConfig{ + Enabled: base.BoolPtr(true), + }, + }, + Info: &base.FileLoggerConfig{ + Enabled: base.BoolPtr(false), + CollationBufferSize: base.IntPtr(0), // avoid data race in collation with FlushLogBuffers test code CBG-4129 + }, + Debug: &base.FileLoggerConfig{ + Enabled: base.BoolPtr(false), + CollationBufferSize: base.IntPtr(0), // avoid data race in collation with FlushLogBuffers test code CBG-4129 + }, + Trace: &base.FileLoggerConfig{ + Enabled: base.BoolPtr(false), + CollationBufferSize: base.IntPtr(0), // avoid data race in collation with FlushLogBuffers test code CBG-4129 + }, + } +} diff --git a/rest/changestest/changes_api_no_race_test.go b/rest/changestest/logging_test.go similarity index 73% rename from rest/changestest/changes_api_no_race_test.go rename to rest/changestest/logging_test.go index 9e8763fcdb..8292c39441 100644 --- a/rest/changestest/changes_api_no_race_test.go +++ b/rest/changestest/logging_test.go @@ -1,12 +1,10 @@ -// Copyright 2012-Present Couchbase, Inc. +// Copyright 2024-Present Couchbase, Inc. // -// Use of this software is governed by the Business Source License included -// in the file licenses/BSL-Couchbase.txt. As of the Change Date specified -// in that file, in accordance with the Business Source License, use of this -// software will be governed by the Apache License, Version 2.0, included in -// the file licenses/APL2.txt. - -//go:build !race +// Use of this software is governed by the Business Source License included +// in the file licenses/BSL-Couchbase.txt. As of the Change Date specified +// in that file, in accordance with the Business Source License, use of this +// software will be governed by the Apache License, Version 2.0, included in +// the file licenses/APL2.txt. package changestest @@ -20,7 +18,6 @@ import ( "github.com/stretchr/testify/require" ) -// AssertLogContains can hit the race detector due to swapping the global loggers // TestDocChangedLogging exercises some of the logging in DocChanged func TestDocChangedLogging(t *testing.T) { base.SetUpTestLogging(t, base.LevelDebug, base.KeyHTTP, base.KeyCache, base.KeyChanges) diff --git a/rest/config.go b/rest/config.go index 0f87c1d34d..032a6f929e 100644 --- a/rest/config.go +++ b/rest/config.go @@ -2242,11 +2242,7 @@ func PersistentConfigKey30(ctx context.Context, groupID string) string { } func HandleSighup(ctx context.Context) { - for logger, err := range base.RotateLogfiles(ctx) { - if err != nil { - base.WarnfCtx(ctx, "Error rotating %v: %v", logger, err) - } - } + base.RotateLogfiles(ctx) } // RegisterSignalHandler invokes functions based on the given signals: diff --git a/rest/config_no_race_test.go b/rest/config_no_race_test.go deleted file mode 100644 index bba8e8d4b4..0000000000 --- a/rest/config_no_race_test.go +++ /dev/null @@ -1,124 +0,0 @@ -// Copyright 2024-Present Couchbase, Inc. -// -// Use of this software is governed by the Business Source License included -// in the file licenses/BSL-Couchbase.txt. As of the Change Date specified -// in that file, in accordance with the Business Source License, use of this -// software will be governed by the Apache License, Version 2.0, included in -// the file licenses/APL2.txt. - -//go:build !race - -package rest - -import ( - "encoding/json" - "os" - "testing" - - "github.com/couchbase/sync_gateway/auth" - "github.com/couchbase/sync_gateway/base" - - "github.com/stretchr/testify/require" -) - -// AssertLogContains can hit the race detector due to swapping the global loggers - -func TestBadCORSValuesConfig(t *testing.T) { - rt := NewRestTester(t, &RestTesterConfig{PersistentConfig: true}) - defer rt.Close() - - // expect database to be created with bad CORS values, but do log a warning - dbConfig := rt.NewDbConfig() - dbConfig.CORS = &auth.CORSConfig{ - Origin: []string{"http://example.com", "1http://example.com"}, - } - base.AssertLogContains(t, "cors.origin contains values", func() { - rt.CreateDatabase("db", dbConfig) - }) -} - -// TestAuditLoggingGlobals modifies all the global loggers -func TestAuditLoggingGlobals(t *testing.T) { - if !base.UnitTestUrlIsWalrus() { - t.Skip("This test can panic with gocb logging CBG-4076") - } - globalFields := map[string]any{ - "global": "field", - "global2": "field2", - } - - globalEnvVarName := "SG_TEST_GLOBAL_AUDIT_LOGGING" - - testCases := []struct { - name string - globalAuditEvents *string - startupErrorMsg string - }{ - { - name: "no global fields", - }, - { - name: "with global fields", - globalAuditEvents: base.StringPtr(string(base.MustJSONMarshal(t, globalFields))), - }, - { - name: "invalid json", - globalAuditEvents: base.StringPtr(`notjson`), - startupErrorMsg: "Unable to unmarshal", - }, - { - name: "empty env var", - globalAuditEvents: base.StringPtr(""), - startupErrorMsg: "Unable to unmarshal", - }, - } - for _, testCase := range testCases { - t.Run(testCase.name, func(t *testing.T) { - base.ResetGlobalTestLogging(t) - base.InitializeMemoryLoggers() - ctx := base.TestCtx(t) - if testCase.globalAuditEvents != nil { - require.NoError(t, os.Setenv(globalEnvVarName, *testCase.globalAuditEvents)) - defer func() { - require.NoError(t, os.Unsetenv(globalEnvVarName)) - }() - } else { - require.NoError(t, os.Unsetenv(globalEnvVarName)) - } - startupConfig := DefaultStartupConfig("") - startupConfig.Logging = base.LoggingConfig{ - LogFilePath: t.TempDir(), - Audit: &base.AuditLoggerConfig{ - FileLoggerConfig: base.FileLoggerConfig{ - Enabled: base.BoolPtr(true), - }, - }, - } - if testCase.globalAuditEvents != nil { - startupConfig.Unsupported.AuditInfoProvider = &AuditInfoProviderConfig{ - GlobalInfoEnvVarName: base.StringPtr(globalEnvVarName), - } - } - err := startupConfig.SetupAndValidateLogging(ctx) - if testCase.startupErrorMsg != "" { - require.ErrorContains(t, err, testCase.startupErrorMsg) - return - } - require.NoError(t, err) - output := base.AuditLogContents(t, func(tb testing.TB) { - base.Audit(ctx, base.AuditIDPublicUserAuthenticated, map[string]any{base.AuditFieldAuthMethod: "basic"}) - }) - var event map[string]any - require.NoError(t, json.Unmarshal(output, &event)) - require.Contains(t, event, base.AuditFieldAuthMethod) - for k, v := range globalFields { - if testCase.globalAuditEvents != nil { - require.Equal(t, v, event[k]) - } else { - require.NotContains(t, event, k) - } - } - }) - } - -} diff --git a/rest/config_test.go b/rest/config_test.go index 990274705b..346b416421 100644 --- a/rest/config_test.go +++ b/rest/config_test.go @@ -1425,6 +1425,7 @@ func deleteTempFile(t *testing.T, file *os.File) { } func TestDefaultLogging(t *testing.T) { + base.ResetGlobalTestLogging(t) base.SetUpTestLogging(t, base.LevelInfo, base.KeyAll) config := DefaultStartupConfig("") assert.Equal(t, base.RedactPartial, config.Logging.RedactionLevel) diff --git a/rest/cors_test.go b/rest/cors_test.go index 23fad1acfc..1cf0a19ec0 100644 --- a/rest/cors_test.go +++ b/rest/cors_test.go @@ -539,3 +539,17 @@ func requireBlipHandshakeMatchingHost(rt *RestTester) { _, err := createBlipTesterWithSpec(rt.TB(), spec, rt) require.NoError(rt.TB(), err) } + +func TestBadCORSValuesConfig(t *testing.T) { + rt := NewRestTester(t, &RestTesterConfig{PersistentConfig: true}) + defer rt.Close() + + // expect database to be created with bad CORS values, but do log a warning + dbConfig := rt.NewDbConfig() + dbConfig.CORS = &auth.CORSConfig{ + Origin: []string{"http://example.com", "1http://example.com"}, + } + base.AssertLogContains(t, "cors.origin contains values", func() { + rt.CreateDatabase("db", dbConfig) + }) +} diff --git a/rest/importtest/import_no_race_test.go b/rest/importtest/import_logging_test.go similarity index 95% rename from rest/importtest/import_no_race_test.go rename to rest/importtest/import_logging_test.go index bcf4fec244..4e3decef09 100644 --- a/rest/importtest/import_no_race_test.go +++ b/rest/importtest/import_logging_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 importtest import ( @@ -20,8 +18,6 @@ import ( "github.com/stretchr/testify/assert" ) -// AssertLogContains can hit the race detector due to swapping the global loggers - func TestImportFilterLogging(t *testing.T) { const errorMessage = `ImportFilterError` importFilter := `function (doc) { console.error("` + errorMessage + `"); return doc.type == "mobile"; }` diff --git a/rest/handler_no_race_test.go b/rest/logging_test.go similarity index 96% rename from rest/handler_no_race_test.go rename to rest/logging_test.go index 83934b379c..86557cc989 100644 --- a/rest/handler_no_race_test.go +++ b/rest/logging_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 ( @@ -18,7 +16,6 @@ import ( "github.com/couchbase/sync_gateway/base" ) -// AssertLogContains can hit the race detector due to swapping the global loggers func TestHTTPLoggingRedaction(t *testing.T) { base.SetUpTestLogging(t, base.LevelInfo, base.KeyHTTP) diff --git a/rest/replicatortest/replicator_test.go b/rest/replicatortest/replicator_test.go index b4a57e17fa..c460f75a0a 100644 --- a/rest/replicatortest/replicator_test.go +++ b/rest/replicatortest/replicator_test.go @@ -7908,9 +7908,6 @@ func TestGroupIDReplications(t *testing.T) { if !base.IsEnterpriseEdition() { t.Skip("Requires EE to use GroupID") } - if base.UnitTestUrlIsWalrus() { - t.Skip("CBG-3713 temporarily skip until -race condition is worked out") - } base.RequireNumTestBuckets(t, 2) base.SetUpTestLogging(t, base.LevelInfo, base.KeyAll)