fix(log): ensure func record is correct (#3501)

The "func" field in log output is incorrect in some cases and showing internal logging methods instead of the actual calling function. This is happening because the caller information is being captured statically (5 call frames) which can be different for different call patterns. Changes: * Move the caller capture to the event creation * Use deterministic skip (3 frames) for event creation * Add test cases to verify that the caller is captured correctly Note: tests needed to written outside convey to avoid call insertion Signed-off-by: Ravi Chamarthy <ravi@chamarthy.dev>
2026-06-17 21:17:58 +08:00 · 2025-10-31 17:01:35 -07:00
parent 195f50bac5
commit fdba14b9a3
3 changed files with 162 additions and 31 deletions
@@ -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)
 	})
@@ -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)
 }

@@ -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)
+	}
+}