From 06c04af3659622f0dd43bdf86548a5e035b19f30 Mon Sep 17 00:00:00 2001 From: akrem-chabchoub Date: Fri, 23 Oct 2026 14:42:38 +0200 Subject: [PATCH 1/3] feat(logging): add log-caller flag to include caller information in log output --- cmd/bee/cmd/cmd.go | 14 +++- cmd/bee/cmd/cmd_test.go | 26 ++++++ cmd/bee/cmd/init.go | 14 +--- packaging/bee.yaml | 2 + packaging/docker/docker-compose.yml | 1 + packaging/docker/env | 2 + packaging/homebrew-amd64/bee.yaml | 2 + packaging/homebrew-arm64/bee.yaml | 2 + packaging/scoop/bee.yaml | 2 + pkg/log/formatter.go | 70 +++++++++++----- pkg/log/log.go | 4 +- pkg/log/logger.go | 8 +- pkg/log/logger_test.go | 126 +++++++++++++++++++++------- 13 files changed, 207 insertions(+), 66 deletions(-) diff --git a/cmd/bee/cmd/cmd.go b/cmd/bee/cmd/cmd.go index 0d4ee64ff12..a590d8ac615 100644 --- a/cmd/bee/cmd/cmd.go +++ b/cmd/bee/cmd/cmd.go @@ -48,6 +48,7 @@ const ( optionNameTracingSamplingRatio = "tracing-sampling-ratio" optionNameTracingServiceName = "tracing-service-name" optionNameVerbosity = "verbosity" + optionNameLogCaller = "log-caller" optionNamePaymentThreshold = "payment-threshold" optionNamePaymentTolerance = "payment-tolerance-percent" optionNamePaymentEarly = "payment-early-percent" @@ -345,6 +346,7 @@ func (c *command) setAllFlags(cmd *cobra.Command) { _ = cmd.Flags().MarkDeprecated(name, "no longer used after the OpenTelemetry migration; use the tracing-* options") } cmd.Flags().String(optionNameVerbosity, "info", "log verbosity level 0=silent, 1=error, 2=warn, 3=info, 4=debug, 5=trace") + cmd.Flags().Bool(optionNameLogCaller, false, "add caller file:line to log lines (development only)") cmd.Flags().String(optionWelcomeMessage, "", "send a welcome message string during handshakes") cmd.Flags().String(optionNamePaymentThreshold, "13500000", "threshold in BZZ where you expect to get paid from your peers") cmd.Flags().Int64(optionNamePaymentTolerance, 25, "excess debt above payment threshold in percentages where you disconnect from your peer") @@ -412,7 +414,11 @@ func (c *command) preRun(cmd *cobra.Command) error { func (c *command) initLogger(cmd *cobra.Command) error { v := strings.ToLower(c.config.GetString(optionNameVerbosity)) - logger, err := newLogger(cmd, v) + var opts []log.Option + if c.config.GetBool(optionNameLogCaller) { + opts = append(opts, log.WithCaller(log.CategoryAll)) + } + logger, err := newLogger(cmd, v, opts...) if err != nil { return fmt.Errorf("new logger: %w", err) } @@ -473,7 +479,7 @@ func (c *command) bindNestedConfig(cmd *cobra.Command, pairs []struct{ flat, dot } } -func newLogger(cmd *cobra.Command, verbosity string) (log.Logger, error) { +func newLogger(cmd *cobra.Command, verbosity string, opts ...log.Option) (log.Logger, error) { var ( sink = cmd.OutOrStdout() vLevel = log.VerbosityNone @@ -496,10 +502,10 @@ func newLogger(cmd *cobra.Command, verbosity string) (log.Logger, error) { return nil, fmt.Errorf("unknown verbosity level %q", verbosity) } - log.ModifyDefaults( + log.ModifyDefaults(append([]log.Option{ log.WithTimestamp(), log.WithLogMetrics(), - ) + }, opts...)...) return log.NewLogger( node.LoggerName, diff --git a/cmd/bee/cmd/cmd_test.go b/cmd/bee/cmd/cmd_test.go index e7a8cfdb11d..cab1701ff49 100644 --- a/cmd/bee/cmd/cmd_test.go +++ b/cmd/bee/cmd/cmd_test.go @@ -7,6 +7,7 @@ package cmd_test import ( "fmt" "os" + "path/filepath" "testing" "github.com/ethersphere/bee/v2/cmd/bee/cmd" @@ -39,3 +40,28 @@ func newCommand(t *testing.T, opts ...cmd.Option) (c *cmd.Command) { } return c } + +func TestLogCallerConfigAccepted(t *testing.T) { + t.Parallel() + + cfgFile := filepath.Join(t.TempDir(), "config.yaml") + if err := os.WriteFile(cfgFile, []byte("log-caller: true\n"), 0o644); err != nil { + t.Fatal(err) + } + + c := newCommand(t) + c.SetCfgFileForTest(cfgFile) + + for _, name := range []string{"start", "init"} { + sub := c.SubCommandForTest(name) + if sub == nil { + t.Fatalf("%s subcommand not found", name) + } + if err := c.CheckUnknownParamsForTest(sub); err != nil { + t.Fatalf("%s rejected log-caller: %v", name, err) + } + if sub.Flags().Lookup("log-caller") == nil { + t.Fatalf("%s is missing the log-caller flag", name) + } + } +} diff --git a/cmd/bee/cmd/init.go b/cmd/bee/cmd/init.go index 3df6b7aeb18..fb85baa919e 100644 --- a/cmd/bee/cmd/init.go +++ b/cmd/bee/cmd/init.go @@ -5,9 +5,6 @@ package cmd import ( - "fmt" - "strings" - "github.com/ethersphere/bee/v2/pkg/node" "github.com/spf13/cobra" ) @@ -21,18 +18,13 @@ func (c *command) initInitCmd() (err error) { return cmd.Help() } - v := strings.ToLower(c.config.GetString(optionNameVerbosity)) - logger, err := newLogger(cmd, v) - if err != nil { - return fmt.Errorf("new logger: %w", err) - } - _, err = c.configureSigner(cmd, logger) + _, err = c.configureSigner(cmd, c.logger) if err != nil { return err } dataDir := c.config.GetString(optionNameDataDir) - stateStore, _, err := node.InitStateStore(logger, dataDir, 1000) + stateStore, _, err := node.InitStateStore(c.logger, dataDir, 1000) if err != nil { return err } @@ -42,7 +34,7 @@ func (c *command) initInitCmd() (err error) { return nil }, PreRunE: func(cmd *cobra.Command, args []string) error { - return c.config.BindPFlags(cmd.Flags()) + return c.preRun(cmd) }, } diff --git a/packaging/bee.yaml b/packaging/bee.yaml index d3804d714c5..4c91efae60d 100644 --- a/packaging/bee.yaml +++ b/packaging/bee.yaml @@ -133,6 +133,8 @@ password-file: "/var/lib/bee/password" # transaction-debug-mode: false ## log verbosity level 0=silent, 1=error, 2=warn, 3=info, 4=debug, 5=trace # verbosity: info +## add caller file:line to log lines (development only) +# log-caller: false ## maximum node warmup duration; proceeds when stable or after this time # warmup-time: 5m0s ## send a welcome message string during handshakes diff --git a/packaging/docker/docker-compose.yml b/packaging/docker/docker-compose.yml index 16818215c7c..830c0316e02 100644 --- a/packaging/docker/docker-compose.yml +++ b/packaging/docker/docker-compose.yml @@ -32,6 +32,7 @@ services: - BEE_DB_WRITE_BUFFER_SIZE - BEE_FULL_NODE - BEE_GAS_LIMIT_FALLBACK + - BEE_LOG_CALLER - BEE_MAINNET - BEE_MINIMUM_GAS_TIP_CAP - BEE_MINIMUM_STORAGE_RADIUS diff --git a/packaging/docker/env b/packaging/docker/env index f33a62c0f15..87043ca4f39 100644 --- a/packaging/docker/env +++ b/packaging/docker/env @@ -139,6 +139,8 @@ # BEE_TRACING_SERVICE_NAME=bee ## log verbosity level 0=silent, 1=error, 2=warn, 3=info, 4=debug, 5=trace (default info) # BEE_VERBOSITY=info +## add caller file:line to log lines, development only (default false) +# BEE_LOG_CALLER=false ## maximum node warmup duration; proceeds when stable or after this time (default 5m) # BEE_WARMUP_TIME=5m ## send a welcome message string during handshakes (default empty) diff --git a/packaging/homebrew-amd64/bee.yaml b/packaging/homebrew-amd64/bee.yaml index 7ed90a8db09..f343dec9458 100644 --- a/packaging/homebrew-amd64/bee.yaml +++ b/packaging/homebrew-amd64/bee.yaml @@ -133,6 +133,8 @@ password-file: "/usr/local/var/lib/swarm-bee/password" # transaction-debug-mode: false ## log verbosity level 0=silent, 1=error, 2=warn, 3=info, 4=debug, 5=trace # verbosity: info +## add caller file:line to log lines (development only) +# log-caller: false ## maximum node warmup duration; proceeds when stable or after this time # warmup-time: 5m0s ## send a welcome message string during handshakes diff --git a/packaging/homebrew-arm64/bee.yaml b/packaging/homebrew-arm64/bee.yaml index da918441628..4bf3e8e117e 100644 --- a/packaging/homebrew-arm64/bee.yaml +++ b/packaging/homebrew-arm64/bee.yaml @@ -133,6 +133,8 @@ password-file: "/opt/homebrew/var/lib/swarm-bee/password" # transaction-debug-mode: false ## log verbosity level 0=silent, 1=error, 2=warn, 3=info, 4=debug, 5=trace # verbosity: info +## add caller file:line to log lines (development only) +# log-caller: false ## maximum node warmup duration; proceeds when stable or after this time # warmup-time: 5m0s ## send a welcome message string during handshakes diff --git a/packaging/scoop/bee.yaml b/packaging/scoop/bee.yaml index 3071bf6f490..2b5f6a94db0 100644 --- a/packaging/scoop/bee.yaml +++ b/packaging/scoop/bee.yaml @@ -133,6 +133,8 @@ password-file: "./password" # transaction-debug-mode: false ## log verbosity level 0=silent, 1=error, 2=warn, 3=info, 4=debug, 5=trace # verbosity: info +## add caller file:line to log lines (development only) +# log-caller: false ## maximum node warmup duration; proceeds when stable or after this time # warmup-time: 5m0s ## send a welcome message string during handshakes diff --git a/pkg/log/formatter.go b/pkg/log/formatter.go index da8f645c01c..47b57befeb3 100644 --- a/pkg/log/formatter.go +++ b/pkg/log/formatter.go @@ -10,11 +10,11 @@ import ( "bytes" "encoding" "fmt" - "path/filepath" "reflect" "runtime" "strconv" "strings" + "sync" ) // MessageCategory indicates which category or categories @@ -72,18 +72,33 @@ const ( maxLogDepthExceeded = `""` ) -// caller represents the original call site for a log line. The File and -// Line fields will always be provided, while the Func field is optional. +// callerPathPrefix is trimmed from caller paths to make them repository relative. +var callerPathPrefix = func() string { + const suffix = "pkg/log/formatter.go" + _, file, _, ok := runtime.Caller(0) + if !ok { + return "" + } + file = slashPath(file) + if !strings.HasSuffix(file, suffix) { + return "" + } + return strings.TrimSuffix(file, suffix) +}() + +// caller represents the original call site for a log line. type caller struct { - // File is the basename of the file for this call site. - File string `json:"file"` - // Line is the line number in the file for this call site. - Line int `json:"line"` - // Func is the function name for this call site, or empty if - // fmtOptions.logCallerFunc is not enabled. - Func string `json:"function,omitempty"` + // location is " file:line"; the leading space lets terminals detect + // the path with its line number when it follows the "caller"=" prefix. + location any + function any } +var unknownCaller = caller{location: " :0", function: ""} + +// callers caches call sites by program counter. +var callers sync.Map // map[uintptr]caller + // newFormatter constructs a formatter which // behavior is influenced by the given options. func newFormatter(opts fmtOptions) *formatter { @@ -373,17 +388,34 @@ func (f *formatter) prettyWithFlags(value any, flags uint32, depth int) string { // caller captures basic information about the caller (filename, line, function). func (f *formatter) caller() caller { - pc, file, line, ok := runtime.Caller(f.opts.callerDepth + 3) - if !ok { - return caller{"", 0, ""} + var pcs [1]uintptr + if runtime.Callers(f.opts.callerDepth+4, pcs[:]) == 0 { + return unknownCaller } - caller := caller{File: filepath.Base(file), Line: line} - if f.opts.logCallerFunc { - if fp := runtime.FuncForPC(pc); fp != nil { - caller.Func = fp.Name() - } + if c, ok := callers.Load(pcs[0]); ok { + return c.(caller) + } + frame, _ := runtime.CallersFrames(pcs[:]).Next() + if frame.File == "" { + return unknownCaller } - return caller + c := caller{ + location: " " + normalizeCallerFile(frame.File) + ":" + strconv.Itoa(frame.Line), + function: frame.Function, + } + callers.Store(pcs[0], c) + return c +} + +// slashPath rewrites Windows path separators so prefix checks work on every OS. +func slashPath(file string) string { + return strings.ReplaceAll(file, `\`, "/") +} + +// normalizeCallerFile turns a runtime file path into a repository-relative +// path with forward slashes, so Windows and Unix logs look the same. +func normalizeCallerFile(file string) string { + return strings.TrimPrefix(slashPath(file), callerPathPrefix) } // nonStringKey converts non-string value v to string. diff --git a/pkg/log/log.go b/pkg/log/log.go index 0efa22c6127..507a26138bc 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -215,7 +215,9 @@ func WithVerbosity(verbosity Level) Option { } // WithCaller tells the logger to add a "caller" key to some or all log lines. -// This has some overhead, so some users might not want it. +// The value is a repository-relative file:line string with a leading space so +// terminals can detect the path after the "caller"= prefix. This has some +// overhead, so some users might not want it. func WithCaller(category MessageCategory) Option { return func(opts *Options) { opts.fmtOptions.caller = category } } diff --git a/pkg/log/logger.go b/pkg/log/logger.go index f90d76ece47..0e23016e013 100644 --- a/pkg/log/logger.go +++ b/pkg/log/logger.go @@ -219,7 +219,7 @@ func (l *logger) setVerbosity(v Level) { // log logs the given msg and key-value pairs with the given level // and the given message category caller (if enabled) to the sink. func (l *logger) log(vl Level, mc MessageCategory, err error, msg string, keysAndValues ...any) error { - base := make([]any, 0, 14+len(keysAndValues)) + base := make([]any, 0, 16+len(keysAndValues)) if l.formatter.opts.logTimestamp { base = append(base, "time", time.Now().Format(l.formatter.opts.timestampLayout)) } @@ -228,7 +228,11 @@ func (l *logger) log(vl Level, mc MessageCategory, err error, msg string, keysAn base = append(base, "v", l.v) } if policy := l.formatter.opts.caller; policy == CategoryAll || policy == mc { - base = append(base, "caller", l.formatter.caller()) + c := l.formatter.caller() + base = append(base, "caller", c.location) + if l.formatter.opts.logCallerFunc { + base = append(base, "function", c.function) + } } base = append(base, "msg", msg) if vl == VerbosityError { diff --git a/pkg/log/logger_test.go b/pkg/log/logger_test.go index e3921b60a84..ac1bcc9117d 100644 --- a/pkg/log/logger_test.go +++ b/pkg/log/logger_test.go @@ -8,12 +8,14 @@ import ( "bytes" "errors" "fmt" - "path/filepath" "runtime" + "strings" "sync" "testing" ) +const callerFile = "pkg/log/logger_test.go" + // hook is a helper type for recording // if Hook.Fire method has been triggered. type hook bool @@ -343,8 +345,8 @@ func TestLoggerWithCaller(t *testing.T) { logger, bb := newLogger(WithCaller(CategoryAll)) logger.Build().Debug("msg") - _, file, line, _ := runtime.Caller(0) - want := fmt.Sprintf(`"level"="debug" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg"`, filepath.Base(file), line-1) + _, _, line, _ := runtime.Caller(0) + want := fmt.Sprintf(`"level"="debug" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, callerFile, line-1) have := string(bytes.TrimRight(bb.Bytes(), "\n")) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) @@ -353,8 +355,8 @@ func TestLoggerWithCaller(t *testing.T) { bb.Reset() logger.Build().Info("msg") - _, file, line, _ = runtime.Caller(0) - want = fmt.Sprintf(`"level"="info" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg"`, filepath.Base(file), line-1) + _, _, line, _ = runtime.Caller(0) + want = fmt.Sprintf(`"level"="info" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, callerFile, line-1) have = string(bytes.TrimRight(bb.Bytes(), "\n")) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) @@ -363,8 +365,8 @@ func TestLoggerWithCaller(t *testing.T) { bb.Reset() logger.Build().Warning("msg") - _, file, line, _ = runtime.Caller(0) - want = fmt.Sprintf(`"level"="warning" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg"`, filepath.Base(file), line-1) + _, _, line, _ = runtime.Caller(0) + want = fmt.Sprintf(`"level"="warning" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, callerFile, line-1) have = string(bytes.TrimRight(bb.Bytes(), "\n")) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) @@ -373,9 +375,9 @@ func TestLoggerWithCaller(t *testing.T) { bb.Reset() logger.Build().Error(errors.New("err"), "msg") - _, file, line, _ = runtime.Caller(0) + _, _, line, _ = runtime.Caller(0) have = string(bytes.TrimRight(bb.Bytes(), "\n")) - want = fmt.Sprintf(`"level"="error" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line-1) + want = fmt.Sprintf(`"level"="error" "logger"="root" "caller"=" %s:%d" "msg"="msg" "error"="err"`, callerFile, line-1) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -386,8 +388,8 @@ func TestLoggerWithCaller(t *testing.T) { logger, bb := newLogger(WithCaller(CategoryAll), WithCallerFunc()) logger.Build().Debug("msg") - _, file, line, _ := runtime.Caller(0) - want := fmt.Sprintf(`"level"="debug" "logger"="root" "caller"={"file":%q,"line":%d,"function":%q} "msg"="msg"`, filepath.Base(file), line-1, thisFunc) + _, _, line, _ := runtime.Caller(0) + want := fmt.Sprintf(`"level"="debug" "logger"="root" "caller"=" %s:%d" "function"=%q "msg"="msg"`, callerFile, line-1, thisFunc) have := string(bytes.TrimRight(bb.Bytes(), "\n")) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) @@ -396,8 +398,8 @@ func TestLoggerWithCaller(t *testing.T) { bb.Reset() logger.Build().Info("msg") - _, file, line, _ = runtime.Caller(0) - want = fmt.Sprintf(`"level"="info" "logger"="root" "caller"={"file":%q,"line":%d,"function":%q} "msg"="msg"`, filepath.Base(file), line-1, thisFunc) + _, _, line, _ = runtime.Caller(0) + want = fmt.Sprintf(`"level"="info" "logger"="root" "caller"=" %s:%d" "function"=%q "msg"="msg"`, callerFile, line-1, thisFunc) have = string(bytes.TrimRight(bb.Bytes(), "\n")) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) @@ -406,8 +408,8 @@ func TestLoggerWithCaller(t *testing.T) { bb.Reset() logger.Build().Warning("msg") - _, file, line, _ = runtime.Caller(0) - want = fmt.Sprintf(`"level"="warning" "logger"="root" "caller"={"file":%q,"line":%d,"function":%q} "msg"="msg"`, filepath.Base(file), line-1, thisFunc) + _, _, line, _ = runtime.Caller(0) + want = fmt.Sprintf(`"level"="warning" "logger"="root" "caller"=" %s:%d" "function"=%q "msg"="msg"`, callerFile, line-1, thisFunc) have = string(bytes.TrimRight(bb.Bytes(), "\n")) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) @@ -416,9 +418,9 @@ func TestLoggerWithCaller(t *testing.T) { bb.Reset() logger.Build().Error(errors.New("err"), "msg") - _, file, line, _ = runtime.Caller(0) + _, _, line, _ = runtime.Caller(0) have = string(bytes.TrimRight(bb.Bytes(), "\n")) - want = fmt.Sprintf(`"level"="error" "logger"="root" "caller"={"file":%q,"line":%d,"function":%q} "msg"="msg" "error"="err"`, filepath.Base(file), line-1, thisFunc) + want = fmt.Sprintf(`"level"="error" "logger"="root" "caller"=" %s:%d" "function"=%q "msg"="msg" "error"="err"`, callerFile, line-1, thisFunc) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -427,8 +429,8 @@ func TestLoggerWithCaller(t *testing.T) { logger, bb := newLogger(WithCaller(CategoryDebug)) logger.Build().Debug("msg") - _, file, line, _ := runtime.Caller(0) - want := fmt.Sprintf(`"level"="debug" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg"`, filepath.Base(file), line-1) + _, _, line, _ := runtime.Caller(0) + want := fmt.Sprintf(`"level"="debug" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, callerFile, line-1) have := string(bytes.TrimRight(bb.Bytes(), "\n")) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) @@ -474,9 +476,9 @@ func TestLoggerWithCaller(t *testing.T) { bb.Reset() logger.Build().Info("msg") - _, file, line, _ := runtime.Caller(0) + _, _, line, _ := runtime.Caller(0) have = string(bytes.TrimRight(bb.Bytes(), "\n")) - want = fmt.Sprintf(`"level"="info" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg"`, filepath.Base(file), line-1) + want = fmt.Sprintf(`"level"="info" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, callerFile, line-1) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -521,9 +523,9 @@ func TestLoggerWithCaller(t *testing.T) { bb.Reset() logger.Build().Warning("msg") - _, file, line, _ := runtime.Caller(0) + _, _, line, _ := runtime.Caller(0) have = string(bytes.TrimRight(bb.Bytes(), "\n")) - want = fmt.Sprintf(`"level"="warning" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg"`, filepath.Base(file), line-1) + want = fmt.Sprintf(`"level"="warning" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, callerFile, line-1) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -568,9 +570,9 @@ func TestLoggerWithCaller(t *testing.T) { bb.Reset() logger.Build().Error(errors.New("err"), "msg") - _, file, line, _ := runtime.Caller(0) + _, _, line, _ := runtime.Caller(0) have = string(bytes.TrimRight(bb.Bytes(), "\n")) - want = fmt.Sprintf(`"level"="error" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line-1) + want = fmt.Sprintf(`"level"="error" "logger"="root" "caller"=" %s:%d" "msg"="msg" "error"="err"`, callerFile, line-1) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -612,6 +614,27 @@ func TestLoggerWithCaller(t *testing.T) { t.Errorf("\nwant %q\nhave %q", want, have) } }) + t.Run("caller=CategoryAll, derived loggers", func(t *testing.T) { + logger, bb := newLogger(WithCaller(CategoryAll), WithVerbosity(VerbosityAll)) + + logger.WithName("pfx").WithValues("k", "v").Build().Info("msg") + _, _, line, _ := runtime.Caller(0) + want := fmt.Sprintf(`"level"="info" "logger"="root/pfx" "caller"=" %s:%d" "msg"="msg" "k"="v"`, callerFile, line-1) + have := string(bytes.TrimRight(bb.Bytes(), "\n")) + if have != want { + t.Errorf("\nwant %q\nhave %q", want, have) + } + + bb.Reset() + + logger.V(1).Build().Debug("msg") + _, _, line, _ = runtime.Caller(0) + want = fmt.Sprintf(`"level"="debug" "logger"="root" "v"=1 "caller"=" %s:%d" "msg"="msg"`, callerFile, line-1) + have = string(bytes.TrimRight(bb.Bytes(), "\n")) + if have != want { + t.Errorf("\nwant %q\nhave %q", want, have) + } + }) } func TestLoggerWithName(t *testing.T) { @@ -803,7 +826,7 @@ func TestLoggerWithCallDepth(t *testing.T) { logger.Build().Debug("msg") _, file, line, _ := runtime.Caller(1) have := string(bytes.TrimRight(bb.Bytes(), "\n")) - want := fmt.Sprintf(`"level"="debug" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg"`, filepath.Base(file), line) + want := fmt.Sprintf(`"level"="debug" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, file, line) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -813,7 +836,7 @@ func TestLoggerWithCallDepth(t *testing.T) { logger.Build().Info("msg") _, file, line, _ := runtime.Caller(1) have := string(bytes.TrimRight(bb.Bytes(), "\n")) - want := fmt.Sprintf(`"level"="info" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg"`, filepath.Base(file), line) + want := fmt.Sprintf(`"level"="info" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, file, line) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -823,7 +846,7 @@ func TestLoggerWithCallDepth(t *testing.T) { logger.Build().Warning("msg") _, file, line, _ := runtime.Caller(1) have := string(bytes.TrimRight(bb.Bytes(), "\n")) - want := fmt.Sprintf(`"level"="warning" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg"`, filepath.Base(file), line) + want := fmt.Sprintf(`"level"="warning" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, file, line) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -833,7 +856,7 @@ func TestLoggerWithCallDepth(t *testing.T) { logger.Build().Error(errors.New("err"), "msg") _, file, line, _ := runtime.Caller(1) have := string(bytes.TrimRight(bb.Bytes(), "\n")) - want := fmt.Sprintf(`"level"="error" "logger"="root" "caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line) + want := fmt.Sprintf(`"level"="error" "logger"="root" "caller"=" %s:%d" "msg"="msg" "error"="err"`, file, line) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -1050,3 +1073,48 @@ func TestLoggerVerbosity(t *testing.T) { } }) } + +func TestNormalizeCallerFile(t *testing.T) { + t.Parallel() + + if callerPathPrefix == "" { + t.Fatal("callerPathPrefix is empty") + } + if strings.Contains(callerPathPrefix, "\\") { + t.Fatalf("callerPathPrefix contains backslash: %q", callerPathPrefix) + } + + _, file, _, ok := runtime.Caller(0) + if !ok { + t.Fatal("runtime.Caller failed") + } + if have := normalizeCallerFile(file); have != callerFile { + t.Fatalf("current file: want %q, have %q", callerFile, have) + } + + win := strings.ReplaceAll(callerPathPrefix, "/", `\`) + strings.ReplaceAll(callerFile, "/", `\`) + if have := normalizeCallerFile(win); have != callerFile { + t.Fatalf("windows path: want %q, have %q", callerFile, have) + } +} + +func BenchmarkLoggerCaller(b *testing.B) { + for _, bc := range []struct { + name string + opts []Option + }{ + {name: "caller=CategoryNone"}, + {name: "caller=CategoryAll", opts: []Option{WithCaller(CategoryAll)}}, + {name: "caller=CategoryAll, logCallerFunc=true", opts: []Option{WithCaller(CategoryAll), WithCallerFunc()}}, + } { + b.Run(bc.name, func(b *testing.B) { + logger, bb := newLogger(bc.opts...) + l := logger.Build() + b.ReportAllocs() + for b.Loop() { + l.Info("msg", "k", "v") + bb.Reset() + } + }) + } +} From 06b19069bccd3ed148614ba076f4f2da7316fea8 Mon Sep 17 00:00:00 2001 From: akrem-chabchoub Date: Mon, 26 Oct 2026 09:53:40 +0100 Subject: [PATCH 2/3] refactor(logging): simplify caller information handling --- pkg/log/formatter.go | 28 +++++++++------------------- pkg/log/logger_test.go | 29 ++++------------------------- 2 files changed, 13 insertions(+), 44 deletions(-) diff --git a/pkg/log/formatter.go b/pkg/log/formatter.go index 47b57befeb3..90119ce2a28 100644 --- a/pkg/log/formatter.go +++ b/pkg/log/formatter.go @@ -14,7 +14,6 @@ import ( "runtime" "strconv" "strings" - "sync" ) // MessageCategory indicates which category or categories @@ -90,15 +89,12 @@ var callerPathPrefix = func() string { type caller struct { // location is " file:line"; the leading space lets terminals detect // the path with its line number when it follows the "caller"=" prefix. - location any - function any + location string + function string } var unknownCaller = caller{location: " :0", function: ""} -// callers caches call sites by program counter. -var callers sync.Map // map[uintptr]caller - // newFormatter constructs a formatter which // behavior is influenced by the given options. func newFormatter(opts fmtOptions) *formatter { @@ -388,22 +384,16 @@ func (f *formatter) prettyWithFlags(value any, flags uint32, depth int) string { // caller captures basic information about the caller (filename, line, function). func (f *formatter) caller() caller { - var pcs [1]uintptr - if runtime.Callers(f.opts.callerDepth+4, pcs[:]) == 0 { - return unknownCaller - } - if c, ok := callers.Load(pcs[0]); ok { - return c.(caller) - } - frame, _ := runtime.CallersFrames(pcs[:]).Next() - if frame.File == "" { + pc, file, line, ok := runtime.Caller(f.opts.callerDepth + 3) + if !ok { return unknownCaller } - c := caller{ - location: " " + normalizeCallerFile(frame.File) + ":" + strconv.Itoa(frame.Line), - function: frame.Function, + c := caller{location: " " + normalizeCallerFile(file) + ":" + strconv.Itoa(line)} + if f.opts.logCallerFunc { + if fp := runtime.FuncForPC(pc); fp != nil { + c.function = fp.Name() + } } - callers.Store(pcs[0], c) return c } diff --git a/pkg/log/logger_test.go b/pkg/log/logger_test.go index ac1bcc9117d..e2644a53fb8 100644 --- a/pkg/log/logger_test.go +++ b/pkg/log/logger_test.go @@ -826,7 +826,7 @@ func TestLoggerWithCallDepth(t *testing.T) { logger.Build().Debug("msg") _, file, line, _ := runtime.Caller(1) have := string(bytes.TrimRight(bb.Bytes(), "\n")) - want := fmt.Sprintf(`"level"="debug" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, file, line) + want := fmt.Sprintf(`"level"="debug" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, normalizeCallerFile(file), line) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -836,7 +836,7 @@ func TestLoggerWithCallDepth(t *testing.T) { logger.Build().Info("msg") _, file, line, _ := runtime.Caller(1) have := string(bytes.TrimRight(bb.Bytes(), "\n")) - want := fmt.Sprintf(`"level"="info" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, file, line) + want := fmt.Sprintf(`"level"="info" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, normalizeCallerFile(file), line) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -846,7 +846,7 @@ func TestLoggerWithCallDepth(t *testing.T) { logger.Build().Warning("msg") _, file, line, _ := runtime.Caller(1) have := string(bytes.TrimRight(bb.Bytes(), "\n")) - want := fmt.Sprintf(`"level"="warning" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, file, line) + want := fmt.Sprintf(`"level"="warning" "logger"="root" "caller"=" %s:%d" "msg"="msg"`, normalizeCallerFile(file), line) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -856,7 +856,7 @@ func TestLoggerWithCallDepth(t *testing.T) { logger.Build().Error(errors.New("err"), "msg") _, file, line, _ := runtime.Caller(1) have := string(bytes.TrimRight(bb.Bytes(), "\n")) - want := fmt.Sprintf(`"level"="error" "logger"="root" "caller"=" %s:%d" "msg"="msg" "error"="err"`, file, line) + want := fmt.Sprintf(`"level"="error" "logger"="root" "caller"=" %s:%d" "msg"="msg" "error"="err"`, normalizeCallerFile(file), line) if have != want { t.Errorf("\nwant %q\nhave %q", want, have) } @@ -1097,24 +1097,3 @@ func TestNormalizeCallerFile(t *testing.T) { t.Fatalf("windows path: want %q, have %q", callerFile, have) } } - -func BenchmarkLoggerCaller(b *testing.B) { - for _, bc := range []struct { - name string - opts []Option - }{ - {name: "caller=CategoryNone"}, - {name: "caller=CategoryAll", opts: []Option{WithCaller(CategoryAll)}}, - {name: "caller=CategoryAll, logCallerFunc=true", opts: []Option{WithCaller(CategoryAll), WithCallerFunc()}}, - } { - b.Run(bc.name, func(b *testing.B) { - logger, bb := newLogger(bc.opts...) - l := logger.Build() - b.ReportAllocs() - for b.Loop() { - l.Info("msg", "k", "v") - bb.Reset() - } - }) - } -} From 9f68cc996e251ffc3365feb199de8ffa11befe68 Mon Sep 17 00:00:00 2001 From: akrem-chabchoub Date: Mon, 26 Oct 2026 13:27:03 +0100 Subject: [PATCH 3/3] fix: revert logs --- cmd/bee/cmd/cmd_test.go | 26 -------------------------- pkg/log/log.go | 4 +--- 2 files changed, 1 insertion(+), 29 deletions(-) diff --git a/cmd/bee/cmd/cmd_test.go b/cmd/bee/cmd/cmd_test.go index cab1701ff49..e7a8cfdb11d 100644 --- a/cmd/bee/cmd/cmd_test.go +++ b/cmd/bee/cmd/cmd_test.go @@ -7,7 +7,6 @@ package cmd_test import ( "fmt" "os" - "path/filepath" "testing" "github.com/ethersphere/bee/v2/cmd/bee/cmd" @@ -40,28 +39,3 @@ func newCommand(t *testing.T, opts ...cmd.Option) (c *cmd.Command) { } return c } - -func TestLogCallerConfigAccepted(t *testing.T) { - t.Parallel() - - cfgFile := filepath.Join(t.TempDir(), "config.yaml") - if err := os.WriteFile(cfgFile, []byte("log-caller: true\n"), 0o644); err != nil { - t.Fatal(err) - } - - c := newCommand(t) - c.SetCfgFileForTest(cfgFile) - - for _, name := range []string{"start", "init"} { - sub := c.SubCommandForTest(name) - if sub == nil { - t.Fatalf("%s subcommand not found", name) - } - if err := c.CheckUnknownParamsForTest(sub); err != nil { - t.Fatalf("%s rejected log-caller: %v", name, err) - } - if sub.Flags().Lookup("log-caller") == nil { - t.Fatalf("%s is missing the log-caller flag", name) - } - } -} diff --git a/pkg/log/log.go b/pkg/log/log.go index 507a26138bc..0efa22c6127 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -215,9 +215,7 @@ func WithVerbosity(verbosity Level) Option { } // WithCaller tells the logger to add a "caller" key to some or all log lines. -// The value is a repository-relative file:line string with a leading space so -// terminals can detect the path after the "caller"= prefix. This has some -// overhead, so some users might not want it. +// This has some overhead, so some users might not want it. func WithCaller(category MessageCategory) Option { return func(opts *Options) { opts.fmtOptions.caller = category } }