From 51a1a9940f0bc4646003c6144ea8ae0c3fd9a5f1 Mon Sep 17 00:00:00 2001 From: frank Date: Thu, 9 Nov 2023 14:35:59 +0800 Subject: [PATCH] print origins for log (#4277) --- VERSION | 2 +- go.mod | 2 +- go.sum | 4 ++-- logutils/logger.go | 7 +------ logutils/logger_test.go | 18 ++++++++++++++++++ logutils/override.go | 5 +++-- logutils/zap_adapter.go | 14 +++++++++----- logutils/zap_adapter_test.go | 13 +++++++++++++ .../ethereum/go-ethereum/log/logger.go | 11 +++++++++++ vendor/modules.txt | 2 +- 10 files changed, 60 insertions(+), 18 deletions(-) create mode 100644 logutils/logger_test.go diff --git a/VERSION b/VERSION index 05477b880..2a20cc3a4 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -0.171.10 +0.171.11 diff --git a/go.mod b/go.mod index b6b5f500f..377771acf 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 69ff26f2f..cd7e0f1d3 100644 --- a/go.sum +++ b/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= diff --git a/logutils/logger.go b/logutils/logger.go index 377c6413b..9ed84e058 100644 --- a/logutils/logger.go +++ b/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) } diff --git a/logutils/logger_test.go b/logutils/logger_test.go new file mode 100644 index 000000000..a76256c40 --- /dev/null +++ b/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") +} diff --git a/logutils/override.go b/logutils/override.go index 0fb992b97..771f95694 100644 --- a/logutils/override.go +++ b/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) diff --git a/logutils/zap_adapter.go b/logutils/zap_adapter.go index 96babcb3b..e650d6015 100644 --- a/logutils/zap_adapter.go +++ b/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) } diff --git a/logutils/zap_adapter_test.go b/logutils/zap_adapter_test.go index 755046f82..6dc138bef 100644 --- a/logutils/zap_adapter_test.go +++ b/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`) +} diff --git a/vendor/github.com/ethereum/go-ethereum/log/logger.go b/vendor/github.com/ethereum/go-ethereum/log/logger.go index 276d6969e..16fa0a84b 100644 --- a/vendor/github.com/ethereum/go-ethereum/log/logger.go +++ b/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(), diff --git a/vendor/modules.txt b/vendor/modules.txt index bc83aa8d0..b4cb8a019 100644 --- a/vendor/modules.txt +++ b/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