From 2c1b321e58695b934bf76800c48321f65150343b Mon Sep 17 00:00:00 2001 From: Patryk Osmaczko Date: Thu, 24 Oct 2024 23:46:23 +0200 Subject: [PATCH] chore_: use zap logger as request logger iterates: status-im/status-desktop#16536 --- logutils/logrotation.go | 11 +++++++ logutils/requestlog/request_log.go | 53 +++++++++++++----------------- mobile/status_request_log.go | 14 +++++--- mobile/status_request_log_test.go | 38 ++++++++++++++------- 4 files changed, 69 insertions(+), 47 deletions(-) diff --git a/logutils/logrotation.go b/logutils/logrotation.go index 40963175f..27934b023 100644 --- a/logutils/logrotation.go +++ b/logutils/logrotation.go @@ -1,6 +1,7 @@ package logutils import ( + "go.uber.org/zap/zapcore" "gopkg.in/natefinch/lumberjack.v2" "github.com/ethereum/go-ethereum/log" @@ -28,3 +29,13 @@ func FileHandlerWithRotation(opts FileOptions, format log.Format) log.Handler { } return log.StreamHandler(logger, format) } + +// ZapSyncerWithRotation creates a zapcore.WriteSyncer with a configured rotation +func ZapSyncerWithRotation(opts FileOptions) zapcore.WriteSyncer { + return zapcore.AddSync(&lumberjack.Logger{ + Filename: opts.Filename, + MaxSize: opts.MaxSize, + MaxBackups: opts.MaxBackups, + Compress: opts.Compress, + }) +} diff --git a/logutils/requestlog/request_log.go b/logutils/requestlog/request_log.go index 0b48907c4..ea7cfcdf2 100644 --- a/logutils/requestlog/request_log.go +++ b/logutils/requestlog/request_log.go @@ -2,58 +2,49 @@ package requestlog import ( "errors" - "sync/atomic" - "github.com/ethereum/go-ethereum/log" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/status-im/status-go/logutils" + "github.com/status-im/status-go/protocol/zaputil" ) var ( - // requestLogger is the request logger object - requestLogger log.Logger - // isRequestLoggingEnabled controls whether request logging is enabled - isRequestLoggingEnabled atomic.Bool + requestLogger *zap.Logger ) -// NewRequestLogger creates a new request logger object -func NewRequestLogger(ctx ...interface{}) log.Logger { - requestLogger = log.New(ctx...) - return requestLogger -} - -// EnableRequestLogging enables or disables RPC logging -func EnableRequestLogging(enable bool) { - if enable { - isRequestLoggingEnabled.Store(true) - } else { - isRequestLoggingEnabled.Store(false) - } -} - // IsRequestLoggingEnabled returns whether RPC logging is enabled func IsRequestLoggingEnabled() bool { - return isRequestLoggingEnabled.Load() + return requestLogger != nil } // GetRequestLogger returns the RPC logger object -func GetRequestLogger() log.Logger { +func GetRequestLogger() *zap.Logger { return requestLogger } func ConfigureAndEnableRequestLogging(file string) error { - log.Info("initialising request logger", "log file", file) - requestLogger := NewRequestLogger() - if file == "" { - return errors.New("log file path is required") + if len(file) == 0 { + return errors.New("file is required") } + + if IsRequestLoggingEnabled() { + return errors.New("request logging is already enabled") + } + fileOpts := logutils.FileOptions{ Filename: file, MaxBackups: 1, } - handler := logutils.FileHandlerWithRotation(fileOpts, log.LogfmtFormat()) - filteredHandler := log.LvlFilterHandler(log.LvlDebug, handler) - requestLogger.SetHandler(filteredHandler) - EnableRequestLogging(true) + + core := zapcore.NewCore( + zaputil.NewConsoleHexEncoder(zap.NewDevelopmentEncoderConfig()), + zapcore.AddSync(logutils.ZapSyncerWithRotation(fileOpts)), + zap.DebugLevel, + ) + + requestLogger = zap.New(core).Named("RequestLogger") + return nil } diff --git a/mobile/status_request_log.go b/mobile/status_request_log.go index 8124120ce..b9b7e096d 100644 --- a/mobile/status_request_log.go +++ b/mobile/status_request_log.go @@ -65,7 +65,6 @@ func getShortFunctionName(fn any) string { func call(fn any, params ...any) any { defer func() { if r := recover(); r != nil { - // we're not sure if request logging is enabled here, so we log it use default logger logutils.ZapLogger().Error("panic found in call", zap.Any("error", r), zap.Stack("stacktrace")) panic(r) } @@ -73,7 +72,8 @@ func call(fn any, params ...any) any { var startTime time.Time - if requestlog.IsRequestLoggingEnabled() { + requestLoggingEnabled := requestlog.IsRequestLoggingEnabled() + if requestLoggingEnabled { startTime = time.Now() } @@ -96,12 +96,18 @@ func call(fn any, params ...any) any { resp = results[0].Interface() } - if requestlog.IsRequestLoggingEnabled() { + if requestLoggingEnabled { duration := time.Since(startTime) methodName := getShortFunctionName(fn) paramsString := removeSensitiveInfo(fmt.Sprintf("%+v", params)) respString := removeSensitiveInfo(fmt.Sprintf("%+v", resp)) - requestlog.GetRequestLogger().Debug(methodName, "params", paramsString, "resp", respString, "duration", duration) + + requestlog.GetRequestLogger().Debug("call", + zap.String("method", methodName), + zap.String("params", paramsString), + zap.String("resp", respString), + zap.Duration("duration", duration), + ) } return resp diff --git a/mobile/status_request_log_test.go b/mobile/status_request_log_test.go index a1835569e..2096f2d55 100644 --- a/mobile/status_request_log_test.go +++ b/mobile/status_request_log_test.go @@ -3,17 +3,18 @@ package statusgo import ( "encoding/json" "fmt" + "os" "strings" "testing" + "github.com/ethereum/go-ethereum/log" + "github.com/stretchr/testify/require" "github.com/status-im/status-go/logutils/requestlog" "github.com/status-im/status-go/multiaccounts" "github.com/status-im/status-go/multiaccounts/settings" "github.com/status-im/status-go/signal" - - "github.com/ethereum/go-ethereum/log" ) func TestRemoveSensitiveInfo(t *testing.T) { @@ -60,17 +61,17 @@ func TestRemoveSensitiveInfo(t *testing.T) { } func TestCall(t *testing.T) { - // Enable request logging - requestlog.EnableRequestLogging(true) + // Create a temporary file for logging + tempLogFile, err := os.CreateTemp(t.TempDir(), "TestCall*.log") + require.NoError(t, err) - // Create a mock logger to capture log output - var logOutput string - mockLogger := log.New() - mockLogger.SetHandler(log.FuncHandler(func(r *log.Record) error { - logOutput += r.Msg + fmt.Sprintf("%s", r.Ctx...) - return nil - })) - requestlog.NewRequestLogger().SetHandler(mockLogger.GetHandler()) + // Enable request logging + err = requestlog.ConfigureAndEnableRequestLogging(tempLogFile.Name()) + require.NoError(t, err) + + // Logger must not be nil after enabling + logger := requestlog.GetRequestLogger() + require.NotNil(t, logger) // Test case 1: Normal execution testFunc := func(param string) string { @@ -86,6 +87,11 @@ func TestCall(t *testing.T) { t.Errorf("Expected result %s, got %s", expectedResult, result) } + // Read the log file + logData, err := os.ReadFile(tempLogFile.Name()) + require.NoError(t, err) + logOutput := string(logData) + // Check if the log contains expected information expectedLogParts := []string{getShortFunctionName(testFunc), "params", testParam, "resp", expectedResult} for _, part := range expectedLogParts { @@ -94,12 +100,20 @@ func TestCall(t *testing.T) { } } + // 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 oldRootHandler := log.Root().GetHandler() defer log.Root().SetHandler(oldRootHandler) log.Root().SetHandler(mockLogger.GetHandler()) // Clear log output for next test logOutput = "" + e := "test panic" panicFunc := func() { panic(e)