log: fix wrong source file:line in JSON logs from release builds

JSON logs reported "source":"slog/logger.go:256" instead of the real
caller. getCaller skips logging-machinery frames by file path, but
release builds use -trimpath which rewrites the standard library slog
frame's path to "log/slog/logger.go" - matching neither the "/log/" nor
the "log.go" check, so it was reported as the source. Also skip frames
whose function belongs to the log/slog package, which is immune to
-trimpath.
This commit is contained in:
Nick Craig-Wood
2026-06-01 15:48:48 +01:00
parent d4397faa94
commit 5f5e2ef9cf
2 changed files with 43 additions and 2 deletions

View File

@@ -79,6 +79,19 @@ func mapLogLevelNames(groups []string, a slog.Attr) slog.Attr {
return a
}
// isLogFrame reports whether frame belongs to the logging machinery
// and so should be skipped when finding the real caller.
//
// rclone's own log packages are matched by file path, but the standard
// library log/slog package is matched by function name: under -trimpath
// its path is rewritten to "log/slog/logger.go", which neither file
// check catches.
func isLogFrame(frame runtime.Frame) bool {
file := frame.File
return strings.HasPrefix(frame.Function, "log/slog.") ||
strings.Contains(file, "/log/") || strings.HasSuffix(file, "log.go")
}
// get the file and line number of the caller skipping skip levels
func getCaller(skip int) string {
var pc [64]uintptr
@@ -92,10 +105,10 @@ func getCaller(skip int) string {
for more {
frame, more = frames.Next()
file := frame.File
if strings.Contains(file, "/log/") || strings.HasSuffix(file, "log.go") {
if isLogFrame(frame) {
continue
}
file := frame.File
line := frame.Line
// shorten file name

View File

@@ -7,6 +7,7 @@ import (
"io"
"os"
"regexp"
"runtime"
"strings"
"sync"
"testing"
@@ -71,6 +72,33 @@ func TestGetCaller(t *testing.T) {
// assert.Equal(t, "slog_test.go", match[1])
}
// Test isLogFrame skips logging-machinery frames, including the
// standard library log/slog frames whose path is trimmed by -trimpath.
func TestIsLogFrame(t *testing.T) {
tests := []struct {
name string
file string
fn string
want bool
}{
// rclone's own log packages
{"fsLog", "github.com/rclone/rclone/fs/log.go", "github.com/rclone/rclone/fs.Debugf", true},
{"fsLogSlog", "github.com/rclone/rclone/fs/log/slog.go", "github.com/rclone/rclone/fs/log.(*OutputHandler).Handle", true},
// standard library slog with -trimpath: path is "log/slog/logger.go"
{"slogTrimpath", "log/slog/logger.go", "log/slog.(*Logger).log", true},
// standard library slog without -trimpath: full path contains "/log/"
{"slogFullPath", "/usr/local/go/src/log/slog/logger.go", "log/slog.(*Logger).Log", true},
// a real caller must not be skipped
{"realCaller", "github.com/rclone/rclone/backend/drive/drive.go", "github.com/rclone/rclone/backend/drive.(*Fs).newObjectWithInfo", false},
}
for _, tc := range tests {
t.Run(tc.name, func(t *testing.T) {
got := isLogFrame(runtime.Frame{File: tc.file, Function: tc.fn})
assert.Equal(t, tc.want, got)
})
}
}
// Test formatStdLogHeader for various flag combinations.
func TestFormatStdLogHeader(t *testing.T) {
cases := []struct {