diff --git a/pkg/cli/server/config_reloader_test.go b/pkg/cli/server/config_reloader_test.go index 5de632e5..a9831f2c 100644 --- a/pkg/cli/server/config_reloader_test.go +++ b/pkg/cli/server/config_reloader_test.go @@ -494,11 +494,13 @@ func TestConfigReloader(t *testing.T) { // wait for config reload time.Sleep(5 * time.Second) + // Wait for the async trivy download to fail and log the error found, err := test.ReadLogFileAndSearchString(logFile.Name(), "failed to download trivy-db to destination dir", 30*time.Second) So(err, ShouldBeNil) So(found, ShouldBeTrue) + // Now read the file once and check all the expected log content data, err := os.ReadFile(logFile.Name()) So(err, ShouldBeNil) t.Logf("log file: %s", data) @@ -508,9 +510,12 @@ func TestConfigReloader(t *testing.T) { So(string(data), ShouldContainSubstring, "\"UpdateInterval\":18000000000000") So(string(data), ShouldContainSubstring, "\"Scrub\":null") So(string(data), ShouldContainSubstring, "\"DBRepository\":\"another/unreachable/trivy/url2\"") - // matching log message when it errors out, test that indeed the download will try the second url + + // Just verify the new URL appears in the logs to confirm config reload worked and ignore + // the order of json message formatting that can change independent of this functional + // test. found, err = test.ReadLogFileAndSearchString(logFile.Name(), - "\"dbRepository\":\"index.docker.io/another/unreachable/trivy/url2:2\",\"goroutine", 1*time.Minute) + "index.docker.io/another/unreachable/trivy/url2", 1*time.Minute) So(err, ShouldBeNil) So(found, ShouldBeTrue) }) diff --git a/pkg/log/log.go b/pkg/log/log.go index 25b6ad75..72af6e23 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -15,9 +15,10 @@ import ( ) const ( - defaultPerms = 0o0600 - messageKey = "message" - callerSkipFrameCount = 5 + defaultPerms = 0o0600 + messageKey = "message" + // Skip: runtime.Callers(0), newEvent(1), Info/Error/etc(2), actual caller(3). + callerSkipFrameCount = 3 ) // Logger extends slog's Logger with zerolog-compatible API. @@ -27,45 +28,72 @@ type Logger struct { // Event represents a log event, mimicking zerolog.Event. type Event struct { - logger *Logger - level slog.Level - attrs []slog.Attr - isPanic bool + logger *Logger + level slog.Level + attrs []slog.Attr + isPanic bool + caller string + function string +} + +// newEvent creates a new log event with caller information captured at the point of creation. +func (l Logger) newEvent(level slog.Level, isPanic bool) *Event { + var caller, function string + + // Get the program counter at the caller's location + pc := make([]uintptr, 1) + n := runtime.Callers(callerSkipFrameCount, pc) + + if n > 0 { + frames := runtime.CallersFrames(pc) + frame, _ := frames.Next() + caller = fmt.Sprintf("%s:%d", frame.File, frame.Line) + function = frame.Function + } + + return &Event{ + logger: &l, + level: level, + attrs: []slog.Attr{}, + isPanic: isPanic, + caller: caller, + function: function, + } } // Info returns an event for info level logging. func (l Logger) Info() *Event { - return &Event{logger: &l, level: slog.LevelInfo, attrs: []slog.Attr{}} + return l.newEvent(slog.LevelInfo, false) } // Debug returns an event for debug level logging. func (l Logger) Debug() *Event { - return &Event{logger: &l, level: slog.LevelDebug, attrs: []slog.Attr{}} + return l.newEvent(slog.LevelDebug, false) } // Error returns an event for error level logging. func (l Logger) Error() *Event { - return &Event{logger: &l, level: slog.LevelError, attrs: []slog.Attr{}} + return l.newEvent(slog.LevelError, false) } // Warn returns an event for warn level logging. func (l Logger) Warn() *Event { - return &Event{logger: &l, level: slog.LevelWarn, attrs: []slog.Attr{}} + return l.newEvent(slog.LevelWarn, false) } // Panic returns an event for panic level logging (maps to error + panic). func (l Logger) Panic() *Event { - return &Event{logger: &l, level: slog.LevelError, attrs: []slog.Attr{}, isPanic: true} + return l.newEvent(slog.LevelError, true) } // Fatal returns an event for fatal level logging (maps to error + panic). func (l Logger) Fatal() *Event { - return &Event{logger: &l, level: slog.LevelError, attrs: []slog.Attr{}, isPanic: true} + return l.newEvent(slog.LevelError, true) } // Err logs an error directly on the logger (convenience method). func (l Logger) Err(err error) *Event { - event := l.Error() + event := l.newEvent(slog.LevelError, false) if err != nil { event.attrs = append(event.attrs, slog.String("error", err.Error())) } @@ -75,7 +103,7 @@ func (l Logger) Err(err error) *Event { // With returns a logger with additional context. func (l Logger) With() *Event { - return &Event{logger: &l, level: slog.LevelInfo, attrs: []slog.Attr{}} + return l.newEvent(slog.LevelInfo, false) } // Logger returns the logger from an event (for method chaining). @@ -188,7 +216,20 @@ func NewTestLoggerPtr() *Logger { // Msgf logs the event with a formatted message. func (e *Event) Msgf(format string, args ...interface{}) { msg := fmt.Sprintf(format, args...) - e.logger.LogAttrs(nil, e.level, msg, e.attrs...) + + // Create a new slice to avoid modifying the original + attrs := make([]slog.Attr, len(e.attrs), len(e.attrs)+2) + copy(attrs, e.attrs) + + if e.caller != "" { + attrs = append(attrs, slog.String("caller", e.caller)) + } + + if e.function != "" { + attrs = append(attrs, slog.String("func", e.function)) + } + + e.logger.LogAttrs(nil, e.level, msg, attrs...) if e.isPanic { panic(msg) @@ -197,7 +238,20 @@ func (e *Event) Msgf(format string, args ...interface{}) { // Msg logs the event with a simple message. func (e *Event) Msg(msg string) { - e.logger.LogAttrs(nil, e.level, msg, e.attrs...) + // Add caller and function info to attributes if captured + // Create a new slice to avoid modifying the original + attrs := make([]slog.Attr, len(e.attrs), len(e.attrs)+2) + copy(attrs, e.attrs) + + if e.caller != "" { + attrs = append(attrs, slog.String("caller", e.caller)) + } + + if e.function != "" { + attrs = append(attrs, slog.String("func", e.function)) + } + + e.logger.LogAttrs(nil, e.level, msg, attrs...) if e.isPanic { panic(msg) @@ -330,18 +384,8 @@ func (h *CallerHandler) Enabled(ctx context.Context, level slog.Level) bool { } func (h *CallerHandler) Handle(ctx context.Context, record slog.Record) error { - // Add caller information - if pc, file, line, ok := runtime.Caller(callerSkipFrameCount); ok { // Adjust stack depth as needed - frame := runtime.CallersFrames([]uintptr{pc}) - f, _ := frame.Next() - - record.Add("caller", fmt.Sprintf("%s:%d", file, line)) - - if f.Function != "" { - record.Add("func", f.Function) - } - } - + // Caller information is now added directly in Event.Msg/Msgf methods + // This handler is kept for compatibility but no longer modifies the record return h.handler.Handle(ctx, record) } diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go index f9f23de0..ebcecb28 100644 --- a/pkg/log/log_test.go +++ b/pkg/log/log_test.go @@ -340,3 +340,85 @@ func TestNewAuditLogger(t *testing.T) { }, ShouldPanic) }) } + +func TestCallerFunction(t *testing.T) { + var buf bytes.Buffer + logger := log.NewLoggerWithWriter("debug", &buf) + + // Test case 1: Simple log without chaining + logger.Info().Msg("test message 1") + output1 := buf.String() + + if !strings.Contains(output1, "test message 1") { + t.Errorf("Expected output to contain 'test message 1', got: %s", output1) + } + + if !strings.Contains(output1, "TestCallerFunction") { + t.Errorf("Expected output to contain 'TestCallerFunction', got: %s", output1) + } + + if strings.Contains(output1, "(*Event).Str") { + t.Errorf("Expected output NOT to contain '(*Event).Str', got: %s", output1) + } + + // Reset buffer + buf.Reset() + + // Test case 2: Log with Str() chaining (this was the problematic case) + logger.Info().Str("module", "test").Msg("test message 2") + output2 := buf.String() + + if !strings.Contains(output2, "test message 2") { + t.Errorf("Expected output to contain 'test message 2', got: %s", output2) + } + + if !strings.Contains(output2, "module") { + t.Errorf("Expected output to contain 'module', got: %s", output2) + } + + if !strings.Contains(output2, "TestCallerFunction") { + t.Errorf("Expected output to contain 'TestCallerFunction', got: %s", output2) + } + + if strings.Contains(output2, "(*Event).Str") { + t.Errorf("Expected output NOT to contain '(*Event).Str', got: %s", output2) + } + + // Reset buffer + buf.Reset() + + // Test case 3: Log with multiple chainings + logger.Error().Str("module", "test").Str("error", "something").Msg("test error message") + output3 := buf.String() + + if !strings.Contains(output3, "test error message") { + t.Errorf("Expected output to contain 'test error message', got: %s", output3) + } + + if !strings.Contains(output3, "TestCallerFunction") { + t.Errorf("Expected output to contain 'TestCallerFunction', got: %s", output3) + } + + if strings.Contains(output3, "(*Event).Str") { + t.Errorf("Expected output NOT to contain '(*Event).Str', got: %s", output3) + } + + // Reset buffer + buf.Reset() + + // Test case 4: Debug with Int + logger.Debug().Int("count", 42).Msg("test debug message") + output4 := buf.String() + + if !strings.Contains(output4, "test debug message") { + t.Errorf("Expected output to contain 'test debug message', got: %s", output4) + } + + if !strings.Contains(output4, "TestCallerFunction") { + t.Errorf("Expected output to contain 'TestCallerFunction', got: %s", output4) + } + + if strings.Contains(output4, "(*Event).Int") { + t.Errorf("Expected output NOT to contain '(*Event).Int', got: %s", output4) + } +}