feat(logging): add log-caller flag to include caller information in l…

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,

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)
 		},
 	}
 

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

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

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)

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

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

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

pkg/log/formatter.go

@@ -10,7 +10,6 @@ import (
 	"bytes"
 	"encoding"
 	"fmt"
-	"path/filepath"
 	"reflect"
 	"runtime"
 	"strconv"
@@ -72,18 +71,30 @@ const (
 	maxLogDepthExceeded = `"<max-log-depth-exceeded>"`
 )
 
-// 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 string
+	function string
 }
 
+var unknownCaller = caller{location: " <unknown>:0", function: "<unknown>"}
+
 // newFormatter constructs a formatter which
 // behavior is influenced by the given options.
 func newFormatter(opts fmtOptions) *formatter {
@@ -375,15 +386,26 @@ func (f *formatter) prettyWithFlags(value any, flags uint32, depth int) string {
 func (f *formatter) caller() caller {
 	pc, file, line, ok := runtime.Caller(f.opts.callerDepth + 3)
 	if !ok {
-		return caller{"<unknown>", 0, ""}
+		return unknownCaller
 	}
-	caller := caller{File: filepath.Base(file), Line: line}
+	c := caller{location: " " + normalizeCallerFile(file) + ":" + strconv.Itoa(line)}
 	if f.opts.logCallerFunc {
 		if fp := runtime.FuncForPC(pc); fp != nil {
-			caller.Func = fp.Name()
+			c.function = fp.Name()
 		}
 	}
-	return caller
+	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.

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 {