print origins for log (#4277)

VERSION

@@ -1 +1 @@
-0.171.10
+0.171.11

go.mod

@@ -2,7 +2,7 @@ module github.com/status-im/status-go
 
 go 1.19
 
-replace github.com/ethereum/go-ethereum v1.10.26 => github.com/status-im/go-ethereum v1.10.25-status.9
+replace github.com/ethereum/go-ethereum v1.10.26 => github.com/status-im/go-ethereum v1.10.25-status.11
 
 replace github.com/docker/docker => github.com/docker/engine v1.4.2-0.20190717161051-705d9623b7c1
 

go.sum

@@ -1982,8 +1982,8 @@ github.com/spf13/viper v1.4.0/go.mod h1:PTJ7Z/lr49W6bUbkmS1V3by4uWynFiR9p7+dSq/y
 github.com/spf13/viper v1.7.0/go.mod h1:8WkrPz2fc9jxqZNCJI/76HCieCp4Q8HaLFoCha5qpdg=
 github.com/status-im/doubleratchet v3.0.0+incompatible h1:aJ1ejcSERpSzmWZBgtfYtiU2nF0Q8ZkGyuEPYETXkCY=
 github.com/status-im/doubleratchet v3.0.0+incompatible/go.mod h1:1sqR0+yhiM/bd+wrdX79AOt2csZuJOni0nUDzKNuqOU=
-github.com/status-im/go-ethereum v1.10.25-status.9 h1:NDuRs5TC4JjqPcYE8/sUtspdA+OwV1JRy3bbRLdIcL0=
-github.com/status-im/go-ethereum v1.10.25-status.9/go.mod h1:Dt4K5JYMhJRdtXJwBEyGZLZn9iz/chSOZyjVmt5ZhwQ=
+github.com/status-im/go-ethereum v1.10.25-status.11 h1:casDsgnrkXzyO9SQVyFsT+63XuInyFXzfEHRW/9eEVY=
+github.com/status-im/go-ethereum v1.10.25-status.11/go.mod h1:Dt4K5JYMhJRdtXJwBEyGZLZn9iz/chSOZyjVmt5ZhwQ=
 github.com/status-im/go-multiaddr-ethv4 v1.2.5 h1:pN+ey6wYKbvNNu5/xq9+VL0N8Yq0pZUTbZp0URg+Yn4=
 github.com/status-im/go-multiaddr-ethv4 v1.2.5/go.mod h1:Fhe/18yWU5QwlAYiOO3Bb1BLe0bn5YobcNBHsjRr4kk=
 github.com/status-im/go-sqlcipher/v4 v4.5.4-status.2 h1:Oi9JTAI2DZEe5UKlpUcvKBCCSn3ULsLIrix7jPnEoPE=

logutils/logger.go

@@ -8,11 +8,6 @@ import (
 	"github.com/ethereum/go-ethereum/log"
 )
 
-// Logger returns the main logger instance used by status-go.
-func Logger() log.Logger {
-	return log.Root()
-}
-
 var (
 	_zapLogger     *zap.Logger
 	_initZapLogger sync.Once
@@ -23,7 +18,7 @@ var (
 func ZapLogger() *zap.Logger {
 	_initZapLogger.Do(func() {
 		var err error
-		_zapLogger, err = NewZapLoggerWithAdapter(Logger())
+		_zapLogger, err = NewZapLoggerWithAdapter(log.Root())
 		if err != nil {
 			panic(err)
 		}

logutils/logger_test.go

@@ -0,0 +1,18 @@
+package logutils
+
+import (
+	"bytes"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+
+	"github.com/ethereum/go-ethereum/log"
+)
+
+func TestPrintOrigins(t *testing.T) {
+	buf := bytes.NewBuffer(nil)
+	handler := log.StreamHandler(buf, log.TerminalFormat(false))
+	require.NoError(t, enableRootLog("debug", handler))
+	log.Debug("hello")
+	require.Contains(t, buf.String(), "logutils/logger_test.go:16")
+}

logutils/override.go

@@ -21,7 +21,7 @@ type LogSettings struct {
 
 // OverrideWithStdLogger overwrites ethereum's root logger with a logger from golang std lib.
 func OverrideWithStdLogger(logLevel string) error {
-	return enableRootLog(logLevel, NewStdHandler(log.LogfmtFormat()))
+	return enableRootLog(logLevel, NewStdHandler(log.TerminalFormat(false)))
 }
 
 // OverrideRootLogWithConfig derives all configuration from params.NodeConfig and configures logger using it.
@@ -60,7 +60,7 @@ func OverrideRootLog(enabled bool, levelStr string, fileOpts FileOptions, termin
 			// Docs: https://pkg.go.dev/gopkg.in/natefinch/lumberjack.v2@v2.0.0#readme-cleaning-up-old-log-files
 			fileOpts.MaxBackups = 1
 		}
-		handler = FileHandlerWithRotation(fileOpts, log.LogfmtFormat())
+		handler = FileHandlerWithRotation(fileOpts, log.TerminalFormat(terminal))
 	} else {
 		handler = log.StreamHandler(os.Stderr, log.TerminalFormat(terminal))
 	}
@@ -86,6 +86,7 @@ func enableRootLog(levelStr string, handler log.Handler) error {
 
 	filteredHandler := log.LvlFilterHandler(level, handler)
 	log.Root().SetHandler(filteredHandler)
+	log.PrintOrigins(true)
 
 	// go-libp2p logger
 	lvl, err := logging.LevelFromString(levelStr)

logutils/zap_adapter.go

@@ -84,17 +84,20 @@ func (c gethLoggerCore) Write(ent zapcore.Entry, fields []zapcore.Field) error {
 		}
 	}
 
+	// set callDepth to 3 for `Output` to skip the calls to zap.Logger
+	// and get the correct caller in the log
+	callDepth := 3
 	switch ent.Level {
 	case zapcore.DebugLevel:
-		c.logger.Debug(ent.Message, args...)
+		c.logger.Output(ent.Message, log.LvlDebug, callDepth, args...)
 	case zapcore.InfoLevel:
-		c.logger.Info(ent.Message, args...)
+		c.logger.Output(ent.Message, log.LvlInfo, callDepth, args...)
 	case zapcore.WarnLevel:
-		c.logger.Warn(ent.Message, args...)
+		c.logger.Output(ent.Message, log.LvlWarn, callDepth, args...)
 	case zapcore.ErrorLevel:
-		c.logger.Error(ent.Message, args...)
+		c.logger.Output(ent.Message, log.LvlError, callDepth, args...)
 	case zapcore.DPanicLevel, zapcore.PanicLevel, zapcore.FatalLevel:
-		c.logger.Crit(ent.Message, args...)
+		c.logger.Output(ent.Message, log.LvlCrit, callDepth, args...)
 	}
 
 	return nil
@@ -144,5 +147,6 @@ func NewZapLoggerWithAdapter(logger log.Logger) (*zap.Logger, error) {
 			return NewZapAdapter(logger, cfg.Level)
 		},
 	)
+	log.PrintOrigins(true)
 	return cfg.Build(adapter)
 }

logutils/zap_adapter_test.go

@@ -57,3 +57,16 @@ func TestNewZapLoggerWithAdapter(t *testing.T) {
 		Error("some message with error level")
 	require.Contains(t, buf.String(), `lvl=eror msg="some message with error level" error="some error`)
 }
+
+func TestZapLoggerTerminalFormat(t *testing.T) {
+	buf := bytes.NewBuffer(nil)
+	logger := log.New()
+	handler := log.StreamHandler(buf, log.TerminalFormat(false))
+	logger.SetHandler(handler)
+
+	zapLogger, err := NewZapLoggerWithAdapter(logger)
+	require.NoError(t, err)
+
+	zapLogger.Info("some message with error level")
+	require.Contains(t, buf.String(), `logutils/zap_adapter_test.go:70`)
+}

vendor/github.com/ethereum/go-ethereum/log/logger.go

@@ -123,6 +123,8 @@ type Logger interface {
 	Warn(msg string, ctx ...interface{})
 	Error(msg string, ctx ...interface{})
 	Crit(msg string, ctx ...interface{})
+
+	Output(msg string, lvl Lvl, callDepth int, ctx ...interface{})
 }
 
 type logger struct {
@@ -130,6 +132,15 @@ type logger struct {
 	h   *swapHandler
 }
 
+// Output is a convenient alias for write, allowing for the modification of
+// the callDepth (number of stack frames to skip).
+// callDepth influences the reported line number of the log message.
+// A callDepth of zero reports the immediate caller of Output.
+// Non-zero callDepth skips as many stack frames.
+func (l *logger) Output(msg string, lvl Lvl, callDepth int, ctx ...interface{}) {
+	l.write(msg, lvl, ctx, callDepth+skipLevel)
+}
+
 func (l *logger) write(msg string, lvl Lvl, ctx []interface{}, skip int) {
 	l.h.Log(&Record{
 		Time: time.Now(),

vendor/modules.txt

@@ -208,7 +208,7 @@ github.com/edsrzf/mmap-go
 ## explicit; go 1.14
 github.com/elastic/gosigar
 github.com/elastic/gosigar/sys/windows
-# github.com/ethereum/go-ethereum v1.10.26 => github.com/status-im/go-ethereum v1.10.25-status.9
+# github.com/ethereum/go-ethereum v1.10.26 => github.com/status-im/go-ethereum v1.10.25-status.11
 ## explicit; go 1.17
 github.com/ethereum/go-ethereum
 github.com/ethereum/go-ethereum/accounts