chore(logging)_: switch to zap.Logger as central logger

Set zap.Logger as the  primary logger for status-go. All geth logs are
now proxied through zap.Logger.

closes: #6029
This commit is contained in:
Patryk Osmaczko 2024-11-04 09:09:28 +01:00 committed by osmaczko
parent d18dfeffca
commit c5c28cc568
19 changed files with 222 additions and 378 deletions

View File

@ -498,7 +498,7 @@ func (b *GethStatusBackend) setupLogSettings() error {
MaxBackups: b.config.LogMaxBackups, MaxBackups: b.config.LogMaxBackups,
CompressRotated: b.config.LogCompressRotated, CompressRotated: b.config.LogCompressRotated,
} }
if err := logutils.OverrideRootLogWithConfig(logSettings, false); err != nil { if err := logutils.OverrideRootLoggerWithConfig(logSettings); err != nil {
return err return err
} }
return nil return nil

View File

@ -73,8 +73,11 @@ func init() {
// nolint:gocyclo // nolint:gocyclo
func main() { func main() {
colors := terminal.IsTerminal(int(os.Stdin.Fd())) if err := logutils.OverrideRootLoggerWithConfig(logutils.LogSettings{
if err := logutils.OverrideRootLog(true, "ERROR", logutils.FileOptions{}, colors); err != nil { Enabled: true,
Level: "ERROR",
Colorized: terminal.IsTerminal(int(os.Stdin.Fd())),
}); err != nil {
stdlog.Fatalf("Error initializing logger: %v", err) stdlog.Fatalf("Error initializing logger: %v", err)
} }
@ -241,9 +244,9 @@ func setupLogging(config *params.NodeConfig) {
MaxSize: config.LogMaxSize, MaxSize: config.LogMaxSize,
MaxBackups: config.LogMaxBackups, MaxBackups: config.LogMaxBackups,
CompressRotated: config.LogCompressRotated, CompressRotated: config.LogCompressRotated,
Colorized: !(*logWithoutColors) && terminal.IsTerminal(int(os.Stdin.Fd())),
} }
colors := !(*logWithoutColors) && terminal.IsTerminal(int(os.Stdin.Fd())) if err := logutils.OverrideRootLoggerWithConfig(logSettings); err != nil {
if err := logutils.OverrideRootLogWithConfig(logSettings, colors); err != nil {
stdlog.Fatalf("Error initializing logger: %v", err) stdlog.Fatalf("Error initializing logger: %v", err)
} }
} }

View File

@ -82,8 +82,11 @@ func init() {
// nolint:gocyclo // nolint:gocyclo
func main() { func main() {
colors := terminal.IsTerminal(int(os.Stdin.Fd())) if err := logutils.OverrideRootLoggerWithConfig(logutils.LogSettings{
if err := logutils.OverrideRootLog(true, "ERROR", logutils.FileOptions{}, colors); err != nil { Enabled: true,
Level: "ERROR",
Colorized: terminal.IsTerminal(int(os.Stdin.Fd())),
}); err != nil {
stdlog.Fatalf("Error initializing logger: %v", err) stdlog.Fatalf("Error initializing logger: %v", err)
} }
@ -285,9 +288,9 @@ func setupLogging(config *params.NodeConfig) {
MaxSize: config.LogMaxSize, MaxSize: config.LogMaxSize,
MaxBackups: config.LogMaxBackups, MaxBackups: config.LogMaxBackups,
CompressRotated: config.LogCompressRotated, CompressRotated: config.LogCompressRotated,
Colorized: !(*logWithoutColors) && terminal.IsTerminal(int(os.Stdin.Fd())),
} }
colors := !(*logWithoutColors) && terminal.IsTerminal(int(os.Stdin.Fd())) if err := logutils.OverrideRootLoggerWithConfig(logSettings); err != nil {
if err := logutils.OverrideRootLogWithConfig(logSettings, colors); err != nil {
stdlog.Fatalf("Error initializing logger: %v", err) stdlog.Fatalf("Error initializing logger: %v", err)
} }
} }

View File

@ -24,9 +24,9 @@ func init() {
Enabled: true, Enabled: true,
MobileSystem: false, MobileSystem: false,
Level: "INFO", Level: "INFO",
Colorized: terminal.IsTerminal(int(os.Stdin.Fd())),
} }
colors := terminal.IsTerminal(int(os.Stdin.Fd())) if err := logutils.OverrideRootLoggerWithConfig(logSettings); err != nil {
if err := logutils.OverrideRootLogWithConfig(logSettings, colors); err != nil {
stdlog.Fatalf("failed to initialize log: %v", err) stdlog.Fatalf("failed to initialize log: %v", err)
} }
} }

View File

@ -32,7 +32,7 @@ func setupLogger(file string) *zap.Logger {
MaxBackups: 3, MaxBackups: 3,
CompressRotated: true, CompressRotated: true,
} }
if err := logutils.OverrideRootLogWithConfig(logSettings, false); err != nil { if err := logutils.OverrideRootLoggerWithConfig(logSettings); err != nil {
zap.S().Fatalf("Error initializing logger: %v", err) zap.S().Fatalf("Error initializing logger: %v", err)
} }
return logutils.ZapLogger() return logutils.ZapLogger()

View File

@ -100,8 +100,11 @@ func init() {
// nolint:gocyclo // nolint:gocyclo
func main() { func main() {
colors := terminal.IsTerminal(int(os.Stdin.Fd())) if err := logutils.OverrideRootLoggerWithConfig(logutils.LogSettings{
if err := logutils.OverrideRootLog(true, "ERROR", logutils.FileOptions{}, colors); err != nil { Enabled: true,
Level: "ERROR",
Colorized: terminal.IsTerminal(int(os.Stdin.Fd())),
}); err != nil {
stdlog.Fatalf("Error initializing logger: %v", err) stdlog.Fatalf("Error initializing logger: %v", err)
} }
@ -399,9 +402,9 @@ func setupLogging(config *params.NodeConfig) {
MaxSize: config.LogMaxSize, MaxSize: config.LogMaxSize,
MaxBackups: config.LogMaxBackups, MaxBackups: config.LogMaxBackups,
CompressRotated: config.LogCompressRotated, CompressRotated: config.LogCompressRotated,
Colorized: !(*logWithoutColors) && terminal.IsTerminal(int(os.Stdin.Fd())),
} }
colors := !(*logWithoutColors) && terminal.IsTerminal(int(os.Stdin.Fd())) if err := logutils.OverrideRootLoggerWithConfig(logSettings); err != nil {
if err := logutils.OverrideRootLogWithConfig(logSettings, colors); err != nil {
stdlog.Fatalf("Error initializing logger: %v", err) stdlog.Fatalf("Error initializing logger: %v", err)
} }
} }

View File

@ -53,6 +53,14 @@ func (core *Core) Enabled(lvl zapcore.Level) bool {
return core.level.Enabled(lvl) return core.level.Enabled(lvl)
} }
func (core *Core) Level() zapcore.Level {
return core.level.Level()
}
func (core *Core) SetLevel(lvl zapcore.Level) {
core.level.SetLevel(lvl)
}
func (core *Core) With(fields []zapcore.Field) zapcore.Core { func (core *Core) With(fields []zapcore.Field) zapcore.Core {
clonedEncoder := encoderWrapper{Encoder: core.getEncoder().Clone()} clonedEncoder := encoderWrapper{Encoder: core.getEncoder().Clone()}
for i := range fields { for i := range fields {

View File

@ -1,11 +1,15 @@
package logutils package logutils
import ( import (
"io"
"sync" "sync"
"time"
"go.uber.org/zap" "go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/log"
"github.com/status-im/status-go/protocol/zaputil"
) )
var ( var (
@ -13,15 +17,35 @@ var (
_initZapLogger sync.Once _initZapLogger sync.Once
) )
// ZapLogger creates a custom zap.Logger which will forward logs
// to status-go logger.
func ZapLogger() *zap.Logger { func ZapLogger() *zap.Logger {
_initZapLogger.Do(func() { _initZapLogger.Do(func() {
var err error _zapLogger = defaultLogger()
_zapLogger, err = NewZapLoggerWithAdapter(log.Root())
if err != nil { // forward geth logs to zap logger
panic(err) _gethLogger := _zapLogger.Named("geth")
} log.Root().SetHandler(gethAdapter(_gethLogger))
}) })
return _zapLogger return _zapLogger
} }
func defaultLogger() *zap.Logger {
core := NewCore(
defaultEncoder(),
zapcore.AddSync(io.Discard),
zap.NewAtomicLevelAt(zap.InfoLevel),
)
return zap.New(core, zap.AddCaller())
}
func defaultEncoder() zapcore.Encoder {
encoderConfig := zap.NewDevelopmentEncoderConfig()
encoderConfig.EncodeTime = utcTimeEncoder(encoderConfig.EncodeTime)
return zaputil.NewConsoleHexEncoder(encoderConfig)
}
func utcTimeEncoder(encoder zapcore.TimeEncoder) zapcore.TimeEncoder {
return func(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
encoder(t.UTC(), enc)
}
}

View File

@ -5,14 +5,16 @@ import (
"testing" "testing"
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
"go.uber.org/zap/zapcore"
"github.com/ethereum/go-ethereum/log"
) )
func TestPrintOrigins(t *testing.T) { func TestPrintOrigins(t *testing.T) {
buf := bytes.NewBuffer(nil) buffer := bytes.NewBuffer(nil)
handler := log.StreamHandler(buf, log.TerminalFormat(false))
require.NoError(t, enableRootLog("debug", handler)) logger := defaultLogger()
log.Debug("hello") logger.Core().(*Core).UpdateSyncer(zapcore.AddSync(buffer))
require.Contains(t, buf.String(), "logutils/logger_test.go:16")
logger.Info("hello")
require.Contains(t, buffer.String(), "logutils/logger_test.go:17")
} }

View File

@ -3,8 +3,6 @@ package logutils
import ( import (
"go.uber.org/zap/zapcore" "go.uber.org/zap/zapcore"
"gopkg.in/natefinch/lumberjack.v2" "gopkg.in/natefinch/lumberjack.v2"
"github.com/ethereum/go-ethereum/log"
) )
// FileOptions are all options supported by internal rotation module. // FileOptions are all options supported by internal rotation module.
@ -19,17 +17,6 @@ type FileOptions struct {
Compress bool Compress bool
} }
// FileHandlerWithRotation instantiates log.Handler with a configured rotation
func FileHandlerWithRotation(opts FileOptions, format log.Format) log.Handler {
logger := &lumberjack.Logger{
Filename: opts.Filename,
MaxSize: opts.MaxSize,
MaxBackups: opts.MaxBackups,
Compress: opts.Compress,
}
return log.StreamHandler(logger, format)
}
// ZapSyncerWithRotation creates a zapcore.WriteSyncer with a configured rotation // ZapSyncerWithRotation creates a zapcore.WriteSyncer with a configured rotation
func ZapSyncerWithRotation(opts FileOptions) zapcore.WriteSyncer { func ZapSyncerWithRotation(opts FileOptions) zapcore.WriteSyncer {
return zapcore.AddSync(&lumberjack.Logger{ return zapcore.AddSync(&lumberjack.Logger{

View File

@ -1,12 +1,12 @@
package logutils package logutils
import ( import (
"io"
"os" "os"
"strings"
logging "github.com/ipfs/go-log/v2" logging "github.com/ipfs/go-log/v2"
"github.com/ethereum/go-ethereum/log" "go.uber.org/zap/zapcore"
) )
type LogSettings struct { type LogSettings struct {
@ -17,84 +17,58 @@ type LogSettings struct {
MaxSize int `json:"MaxSize"` MaxSize int `json:"MaxSize"`
MaxBackups int `json:"MaxBackups"` MaxBackups int `json:"MaxBackups"`
CompressRotated bool `json:"CompressRotated"` CompressRotated bool `json:"CompressRotated"`
Colorized bool `json:"Colorized"` // FIXME: doesn't take effect
} }
// OverrideWithStdLogger overwrites ethereum's root logger with a logger from golang std lib. func OverrideRootLoggerWithConfig(settings LogSettings) error {
func OverrideWithStdLogger(logLevel string) error { return overrideCoreWithConfig(ZapLogger().Core().(*Core), settings)
return enableRootLog(logLevel, NewStdHandler(log.TerminalFormat(false)))
} }
// OverrideRootLogWithConfig derives all configuration from params.NodeConfig and configures logger using it. func overrideCoreWithConfig(core *Core, settings LogSettings) error {
func OverrideRootLogWithConfig(settings LogSettings, colors bool) error {
if !settings.Enabled { if !settings.Enabled {
core.UpdateSyncer(zapcore.AddSync(io.Discard))
return nil return nil
} }
if settings.Level == "" {
settings.Level = "info"
}
level, err := lvlFromString(settings.Level)
if err != nil {
return err
}
core.SetLevel(level)
if settings.MobileSystem { if settings.MobileSystem {
return OverrideWithStdLogger(settings.Level) core.UpdateSyncer(zapcore.Lock(os.Stdout))
}
return OverrideRootLog(settings.Enabled, settings.Level, FileOptions{
Filename: settings.File,
MaxSize: settings.MaxSize,
MaxBackups: settings.MaxBackups,
Compress: settings.CompressRotated,
}, colors)
}
// OverrideRootLog overrides root logger with file handler, if defined,
// and log level (defaults to INFO).
func OverrideRootLog(enabled bool, levelStr string, fileOpts FileOptions, terminal bool) error {
if !enabled {
disableRootLog()
return nil return nil
} }
if os.Getenv("CI") == "true" {
terminal = false if settings.File != "" {
} if settings.MaxBackups == 0 {
var (
handler log.Handler
)
if fileOpts.Filename != "" {
if fileOpts.MaxBackups == 0 {
// Setting MaxBackups to 0 causes all log files to be kept. Even setting MaxAge to > 0 doesn't fix it // Setting MaxBackups to 0 causes all log files to be kept. Even setting MaxAge to > 0 doesn't fix it
// Docs: https://pkg.go.dev/gopkg.in/natefinch/lumberjack.v2@v2.0.0#readme-cleaning-up-old-log-files // Docs: https://pkg.go.dev/gopkg.in/natefinch/lumberjack.v2@v2.0.0#readme-cleaning-up-old-log-files
fileOpts.MaxBackups = 1 settings.MaxBackups = 1
} }
handler = FileHandlerWithRotation(fileOpts, log.TerminalFormat(terminal)) core.UpdateSyncer(ZapSyncerWithRotation(FileOptions{
Filename: settings.File,
MaxSize: settings.MaxSize,
MaxBackups: settings.MaxBackups,
Compress: settings.CompressRotated,
}))
} else { } else {
handler = log.StreamHandler(os.Stderr, log.TerminalFormat(terminal)) core.UpdateSyncer(zapcore.Lock(os.Stderr))
} }
return enableRootLog(levelStr, handler) // FIXME: remove go-libp2p logging altogether
}
func disableRootLog() {
log.Root().SetHandler(log.DiscardHandler())
}
func enableRootLog(levelStr string, handler log.Handler) error {
if levelStr == "" {
levelStr = "INFO"
}
levelStr = strings.ToLower(levelStr)
level, err := log.LvlFromString(levelStr)
if err != nil {
return err
}
filteredHandler := log.LvlFilterHandler(level, handler)
log.Root().SetHandler(filteredHandler)
log.PrintOrigins(true)
// go-libp2p logger // go-libp2p logger
lvl, err := logging.LevelFromString(levelStr) {
if err != nil { lvl, err := logging.LevelFromString(settings.Level)
return err if err != nil {
return err
}
logging.SetAllLoggers(lvl)
} }
logging.SetAllLoggers(lvl)
return nil return nil
} }

77
logutils/override_test.go Normal file
View File

@ -0,0 +1,77 @@
package logutils
import (
"io"
"testing"
"github.com/stretchr/testify/require"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)
func TestOverrideCoreWithConfig(t *testing.T) {
tests := []struct {
name string
settings LogSettings
expectError bool
}{
{
name: "disabled logging",
settings: LogSettings{
Enabled: false,
},
expectError: false,
},
{
name: "invalid log level",
settings: LogSettings{
Enabled: true,
Level: "invalid",
},
expectError: true,
},
{
name: "valid log level",
settings: LogSettings{
Enabled: true,
Level: "info",
},
expectError: false,
},
{
name: "mobile system logging",
settings: LogSettings{
Enabled: true,
MobileSystem: true,
},
expectError: false,
},
{
name: "file logging with rotation",
settings: LogSettings{
Enabled: true,
File: "test.log",
MaxSize: 10,
MaxBackups: 0,
CompressRotated: true,
},
expectError: false,
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
core := NewCore(
defaultEncoder(),
zapcore.AddSync(io.Discard),
zap.NewAtomicLevelAt(zap.InfoLevel),
)
err := overrideCoreWithConfig(core, tt.settings)
if tt.expectError {
require.Error(t, err)
} else {
require.NoError(t, err)
}
})
}
}

View File

@ -1,17 +0,0 @@
package logutils
import (
stdlog "log"
"github.com/ethereum/go-ethereum/log"
)
// NewStdHandler returns handler that uses logger from golang std lib.
func NewStdHandler(fmtr log.Format) log.Handler {
return log.FuncHandler(func(r *log.Record) error {
line := fmtr.Format(r)
// 8 is a number of frames that will be skipped when log is printed.
// this is needed to show the file (with line number) where call to a logger was made
return stdlog.Output(8, string(line))
})
}

View File

@ -1,147 +0,0 @@
package logutils
import (
"fmt"
"math"
"time"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/ethereum/go-ethereum/log"
"github.com/status-im/status-go/protocol/zaputil"
)
type gethLoggerCore struct {
zapcore.LevelEnabler
fields []zapcore.Field
logger log.Logger
}
func (c gethLoggerCore) With(fields []zapcore.Field) zapcore.Core {
clone := c.clone()
clone.fields = append(clone.fields, fields...)
return clone
}
func (c gethLoggerCore) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
if c.Enabled(ent.Level) {
return ce.AddCore(ent, c)
}
return ce
}
func (c gethLoggerCore) Write(ent zapcore.Entry, fields []zapcore.Field) error {
fields = append(c.fields[:], fields...)
var args []interface{}
for _, f := range fields {
switch f.Type {
case zapcore.ArrayMarshalerType,
zapcore.ObjectMarshalerType,
zapcore.BinaryType,
zapcore.ByteStringType,
zapcore.Complex128Type,
zapcore.ReflectType,
zapcore.StringerType,
zapcore.ErrorType:
args = append(args, f.Key, f.Interface)
case zapcore.BoolType:
args = append(args, f.Key, f.Integer == 1)
case zapcore.DurationType:
args = append(args, f.Key, time.Duration(f.Integer))
case zapcore.Float64Type:
args = append(args, f.Key, math.Float64frombits(uint64(f.Integer)))
case zapcore.Float32Type:
args = append(args, f.Key, math.Float32frombits(uint32(f.Integer)))
case zapcore.Int64Type,
zapcore.Int32Type,
zapcore.Int16Type,
zapcore.Int8Type,
zapcore.Uint64Type,
zapcore.Uint32Type,
zapcore.Uint16Type,
zapcore.Uint8Type:
args = append(args, f.Key, f.Integer)
case zapcore.UintptrType:
args = append(args, f.Key, uintptr(f.Integer))
case zapcore.StringType:
args = append(args, f.Key, f.String)
case zapcore.TimeType:
if f.Interface != nil {
args = append(args, f.Key, time.Unix(0, f.Integer).In(f.Interface.(*time.Location)))
} else {
// Fall back to UTC if location is nil.
args = append(args, f.Key, time.Unix(0, f.Integer))
}
case zapcore.NamespaceType:
args = append(args, "namespace", f.Key)
case zapcore.SkipType:
break
default:
panic(fmt.Sprintf("unknown field type: %v", f))
}
}
// 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.Output(ent.Message, log.LvlDebug, callDepth, args...)
case zapcore.InfoLevel:
c.logger.Output(ent.Message, log.LvlInfo, callDepth, args...)
case zapcore.WarnLevel:
c.logger.Output(ent.Message, log.LvlWarn, callDepth, args...)
case zapcore.ErrorLevel:
c.logger.Output(ent.Message, log.LvlError, callDepth, args...)
case zapcore.DPanicLevel, zapcore.PanicLevel, zapcore.FatalLevel:
c.logger.Output(ent.Message, log.LvlCrit, callDepth, args...)
}
return nil
}
func (gethLoggerCore) Sync() error {
return nil
}
func (c *gethLoggerCore) clone() *gethLoggerCore {
return &gethLoggerCore{
LevelEnabler: c.LevelEnabler,
fields: c.fields,
logger: c.logger,
}
}
// NewZapAdapter returns a new zapcore.Core interface which forwards logs to log.Logger.
func NewZapAdapter(logger log.Logger, enab zapcore.LevelEnabler) zapcore.Core {
return &gethLoggerCore{
LevelEnabler: enab,
logger: logger,
}
}
// NewZapLoggerWithAdapter returns a logger forwarding all logs with level info and above.
func NewZapLoggerWithAdapter(logger log.Logger) (*zap.Logger, error) {
if err := zaputil.RegisterJSONHexEncoder(); err != nil {
panic(err)
}
cfg := zap.Config{
Level: zap.NewAtomicLevelAt(zapcore.DebugLevel),
Development: false,
Sampling: nil,
Encoding: "json-hex",
EncoderConfig: zap.NewProductionEncoderConfig(),
OutputPaths: []string{"stderr"},
ErrorOutputPaths: []string{"stderr"},
}
adapter := zap.WrapCore(
func(zapcore.Core) zapcore.Core {
return NewZapAdapter(logger, cfg.Level)
},
)
log.PrintOrigins(true)
return cfg.Build(adapter)
}

View File

@ -1,72 +0,0 @@
package logutils
import (
"bytes"
"errors"
"testing"
"github.com/stretchr/testify/require"
"go.uber.org/zap"
"github.com/ethereum/go-ethereum/log"
)
func TestNewZapAdapter(t *testing.T) {
buf := bytes.NewBuffer(nil)
logger := log.New()
handler := log.StreamHandler(buf, log.LogfmtFormat())
logger.SetHandler(handler)
cfg := zap.NewDevelopmentConfig()
adapter := NewZapAdapter(logger, cfg.Level)
zapLogger := zap.New(adapter)
buf.Reset()
zapLogger.
With(zap.Error(errors.New("some error"))).
Error("some message with error level")
require.Contains(t, buf.String(), `lvl=eror msg="some message with error level" error="some error`)
buf.Reset()
zapLogger.
With(zap.Int("counter", 100)).
Info("some message with param", zap.String("another-field", "another-value"))
require.Contains(t, buf.String(), `lvl=info msg="some message with param" counter=100 another-field=another-value`)
buf.Reset()
zapLogger.
With(zap.Namespace("some-namespace")).
With(zap.String("site", "SomeSite")).
Info("some message with param")
require.Contains(t, buf.String(), `lvl=info msg="some message with param" namespace=some-namespace site=SomeSite`)
}
func TestNewZapLoggerWithAdapter(t *testing.T) {
buf := bytes.NewBuffer(nil)
logger := log.New()
handler := log.StreamHandler(buf, log.LogfmtFormat())
logger.SetHandler(handler)
zapLogger, err := NewZapLoggerWithAdapter(logger)
require.NoError(t, err)
buf.Reset()
zapLogger.
With(zap.Error(errors.New("some error"))).
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`)
}

View File

@ -9,8 +9,6 @@ import (
"time" "time"
"go.uber.org/zap" "go.uber.org/zap"
"github.com/status-im/status-go/logutils"
) )
var sensitiveKeys = []string{ var sensitiveKeys = []string{
@ -62,17 +60,17 @@ func getShortFunctionName(fn any) string {
// 3. Uses reflection to Call the given function // 3. Uses reflection to Call the given function
// 4. If request logging is enabled, logs method name, parameters, response, and execution duration // 4. If request logging is enabled, logs method name, parameters, response, and execution duration
// 5. Removes sensitive information before logging // 5. Removes sensitive information before logging
func Call(logger *zap.Logger, fn any, params ...any) any { func Call(logger, requestLogger *zap.Logger, fn any, params ...any) any {
defer func() { defer func() {
if r := recover(); r != nil { if r := recover(); r != nil {
logutils.ZapLogger().Error("panic found in call", zap.Any("error", r), zap.Stack("stacktrace")) logger.Error("panic found in call", zap.Any("error", r), zap.Stack("stacktrace"))
panic(r) panic(r)
} }
}() }()
var startTime time.Time var startTime time.Time
requestLoggingEnabled := logger != nil requestLoggingEnabled := requestLogger != nil
if requestLoggingEnabled { if requestLoggingEnabled {
startTime = time.Now() startTime = time.Now()
} }
@ -102,7 +100,7 @@ func Call(logger *zap.Logger, fn any, params ...any) any {
paramsString := removeSensitiveInfo(fmt.Sprintf("%+v", params)) paramsString := removeSensitiveInfo(fmt.Sprintf("%+v", params))
respString := removeSensitiveInfo(fmt.Sprintf("%+v", resp)) respString := removeSensitiveInfo(fmt.Sprintf("%+v", resp))
logger.Debug("call", requestLogger.Debug("call",
zap.String("method", methodName), zap.String("method", methodName),
zap.String("params", paramsString), zap.String("params", paramsString),
zap.String("resp", respString), zap.String("resp", respString),
@ -113,8 +111,8 @@ func Call(logger *zap.Logger, fn any, params ...any) any {
return resp return resp
} }
func CallWithResponse(logger *zap.Logger, fn any, params ...any) string { func CallWithResponse(logger, requestLogger *zap.Logger, fn any, params ...any) string {
resp := Call(logger, fn, params...) resp := Call(logger, requestLogger, fn, params...)
if resp == nil { if resp == nil {
return "" return ""
} }

View File

@ -1,12 +1,13 @@
package callog package callog
import ( import (
"fmt" "bytes"
"os" "os"
"strings" "strings"
"testing" "testing"
"github.com/ethereum/go-ethereum/log" "go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
@ -57,14 +58,22 @@ func TestRemoveSensitiveInfo(t *testing.T) {
} }
func TestCall(t *testing.T) { func TestCall(t *testing.T) {
// Create a temporary file for logging // Create default logger
buffer := bytes.NewBuffer(nil)
logger := zap.New(zapcore.NewCore(
zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()),
zapcore.AddSync(buffer),
zap.DebugLevel,
))
// Create a temporary file for request logging
tempLogFile, err := os.CreateTemp(t.TempDir(), "TestCall*.log") tempLogFile, err := os.CreateTemp(t.TempDir(), "TestCall*.log")
require.NoError(t, err) require.NoError(t, err)
// Enable request logging // Enable request logging
logger, err := requestlog.CreateRequestLogger(tempLogFile.Name()) requestLogger, err := requestlog.CreateRequestLogger(tempLogFile.Name())
require.NoError(t, err) require.NoError(t, err)
require.NotNil(t, logger) require.NotNil(t, requestLogger)
// Test case 1: Normal execution // Test case 1: Normal execution
testFunc := func(param string) string { testFunc := func(param string) string {
@ -73,7 +82,7 @@ func TestCall(t *testing.T) {
testParam := "test input" testParam := "test input"
expectedResult := "test result: test input" expectedResult := "test result: test input"
result := CallWithResponse(logger, testFunc, testParam) result := CallWithResponse(logger, requestLogger, testFunc, testParam)
// Check the result // Check the result
if result != expectedResult { if result != expectedResult {
@ -83,29 +92,18 @@ func TestCall(t *testing.T) {
// Read the log file // Read the log file
logData, err := os.ReadFile(tempLogFile.Name()) logData, err := os.ReadFile(tempLogFile.Name())
require.NoError(t, err) require.NoError(t, err)
logOutput := string(logData) requestLogOutput := string(logData)
// Check if the log contains expected information // Check if the log contains expected information
expectedLogParts := []string{getShortFunctionName(testFunc), "params", testParam, "resp", expectedResult} expectedLogParts := []string{getShortFunctionName(testFunc), "params", testParam, "resp", expectedResult}
for _, part := range expectedLogParts { for _, part := range expectedLogParts {
if !strings.Contains(logOutput, part) { if !strings.Contains(requestLogOutput, part) {
t.Errorf("Log output doesn't contain expected part: %s", part) t.Errorf("Log output doesn't contain expected part: %s", part)
} }
} }
// Create a mock logger to capture log output
mockLogger := log.New()
mockLogger.SetHandler(log.FuncHandler(func(r *log.Record) error {
logOutput += r.Msg + fmt.Sprintf("%s", r.Ctx...)
return nil
}))
// Test case 2: Panic -> recovery -> re-panic // Test case 2: Panic -> recovery -> re-panic
oldRootHandler := log.Root().GetHandler() require.Empty(t, buffer.String())
defer log.Root().SetHandler(oldRootHandler)
log.Root().SetHandler(mockLogger.GetHandler())
// Clear log output for next test
logOutput = ""
e := "test panic" e := "test panic"
panicFunc := func() { panicFunc := func() {
@ -113,17 +111,17 @@ func TestCall(t *testing.T) {
} }
require.PanicsWithValue(t, e, func() { require.PanicsWithValue(t, e, func() {
Call(logger, panicFunc) Call(logger, requestLogger, panicFunc)
}) })
// Check if the panic was logged // Check if the panic was logged
if !strings.Contains(logOutput, "panic found in call") { if !strings.Contains(buffer.String(), "panic found in call") {
t.Errorf("Log output doesn't contain panic information") t.Errorf("Log output doesn't contain panic information")
} }
if !strings.Contains(logOutput, e) { if !strings.Contains(buffer.String(), e) {
t.Errorf("Log output doesn't contain panic message") t.Errorf("Log output doesn't contain panic message")
} }
if !strings.Contains(logOutput, "stacktrace") { if !strings.Contains(buffer.String(), "stacktrace") {
t.Errorf("Log output doesn't contain stacktrace") t.Errorf("Log output doesn't contain stacktrace")
} }
} }

View File

@ -53,11 +53,11 @@ import (
) )
func call(fn any, params ...any) any { func call(fn any, params ...any) any {
return callog.Call(requestlog.GetRequestLogger(), fn, params...) return callog.Call(logutils.ZapLogger(), requestlog.GetRequestLogger(), fn, params...)
} }
func callWithResponse(fn any, params ...any) string { func callWithResponse(fn any, params ...any) string {
return callog.CallWithResponse(requestlog.GetRequestLogger(), fn, params...) return callog.CallWithResponse(logutils.ZapLogger(), requestlog.GetRequestLogger(), fn, params...)
} }
type InitializeApplicationResponse struct { type InitializeApplicationResponse struct {
@ -2159,7 +2159,7 @@ func InitLogging(logSettingsJSON string) string {
return makeJSONResponse(err) return makeJSONResponse(err)
} }
if err = logutils.OverrideRootLogWithConfig(logSettings.LogSettings, false); err == nil { if err = logutils.OverrideRootLoggerWithConfig(logSettings.LogSettings); err == nil {
logutils.ZapLogger().Info("logging initialised", zap.String("logSettings", logSettingsJSON)) logutils.ZapLogger().Info("logging initialised", zap.String("logSettings", logSettingsJSON))
} }

View File

@ -67,8 +67,11 @@ func Init() {
flag.Parse() flag.Parse()
// set up logger // set up logger
loggerEnabled := *logLevel != "" err = logutils.OverrideRootLoggerWithConfig(logutils.LogSettings{
if err := logutils.OverrideRootLog(loggerEnabled, *logLevel, logutils.FileOptions{}, true); err != nil { Enabled: *logLevel != "",
Level: *logLevel,
})
if err != nil {
panic(err) panic(err)
} }