chore_: use zap logger as request logger

iterates: status-im/status-desktop#16536
This commit is contained in:
Patryk Osmaczko 2024-10-24 23:46:23 +02:00 committed by osmaczko
parent 153c5dbdf4
commit 2c1b321e58
4 changed files with 69 additions and 47 deletions

View File

@ -1,6 +1,7 @@
package logutils package logutils
import ( import (
"go.uber.org/zap/zapcore"
"gopkg.in/natefinch/lumberjack.v2" "gopkg.in/natefinch/lumberjack.v2"
"github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/log"
@ -28,3 +29,13 @@ func FileHandlerWithRotation(opts FileOptions, format log.Format) log.Handler {
} }
return log.StreamHandler(logger, format) 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,
})
}

View File

@ -2,58 +2,49 @@ package requestlog
import ( import (
"errors" "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/logutils"
"github.com/status-im/status-go/protocol/zaputil"
) )
var ( var (
// requestLogger is the request logger object requestLogger *zap.Logger
requestLogger log.Logger
// isRequestLoggingEnabled controls whether request logging is enabled
isRequestLoggingEnabled atomic.Bool
) )
// 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 // IsRequestLoggingEnabled returns whether RPC logging is enabled
func IsRequestLoggingEnabled() bool { func IsRequestLoggingEnabled() bool {
return isRequestLoggingEnabled.Load() return requestLogger != nil
} }
// GetRequestLogger returns the RPC logger object // GetRequestLogger returns the RPC logger object
func GetRequestLogger() log.Logger { func GetRequestLogger() *zap.Logger {
return requestLogger return requestLogger
} }
func ConfigureAndEnableRequestLogging(file string) error { func ConfigureAndEnableRequestLogging(file string) error {
log.Info("initialising request logger", "log file", file) if len(file) == 0 {
requestLogger := NewRequestLogger() return errors.New("file is required")
if file == "" {
return errors.New("log file path is required")
} }
if IsRequestLoggingEnabled() {
return errors.New("request logging is already enabled")
}
fileOpts := logutils.FileOptions{ fileOpts := logutils.FileOptions{
Filename: file, Filename: file,
MaxBackups: 1, MaxBackups: 1,
} }
handler := logutils.FileHandlerWithRotation(fileOpts, log.LogfmtFormat())
filteredHandler := log.LvlFilterHandler(log.LvlDebug, handler) core := zapcore.NewCore(
requestLogger.SetHandler(filteredHandler) zaputil.NewConsoleHexEncoder(zap.NewDevelopmentEncoderConfig()),
EnableRequestLogging(true) zapcore.AddSync(logutils.ZapSyncerWithRotation(fileOpts)),
zap.DebugLevel,
)
requestLogger = zap.New(core).Named("RequestLogger")
return nil return nil
} }

View File

@ -65,7 +65,6 @@ func getShortFunctionName(fn any) string {
func call(fn any, params ...any) any { func call(fn any, params ...any) any {
defer func() { defer func() {
if r := recover(); r != nil { 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")) logutils.ZapLogger().Error("panic found in call", zap.Any("error", r), zap.Stack("stacktrace"))
panic(r) panic(r)
} }
@ -73,7 +72,8 @@ func call(fn any, params ...any) any {
var startTime time.Time var startTime time.Time
if requestlog.IsRequestLoggingEnabled() { requestLoggingEnabled := requestlog.IsRequestLoggingEnabled()
if requestLoggingEnabled {
startTime = time.Now() startTime = time.Now()
} }
@ -96,12 +96,18 @@ func call(fn any, params ...any) any {
resp = results[0].Interface() resp = results[0].Interface()
} }
if requestlog.IsRequestLoggingEnabled() { if requestLoggingEnabled {
duration := time.Since(startTime) duration := time.Since(startTime)
methodName := getShortFunctionName(fn) methodName := getShortFunctionName(fn)
paramsString := removeSensitiveInfo(fmt.Sprintf("%+v", params)) paramsString := removeSensitiveInfo(fmt.Sprintf("%+v", params))
respString := removeSensitiveInfo(fmt.Sprintf("%+v", resp)) 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 return resp

View File

@ -3,17 +3,18 @@ package statusgo
import ( import (
"encoding/json" "encoding/json"
"fmt" "fmt"
"os"
"strings" "strings"
"testing" "testing"
"github.com/ethereum/go-ethereum/log"
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
"github.com/status-im/status-go/logutils/requestlog" "github.com/status-im/status-go/logutils/requestlog"
"github.com/status-im/status-go/multiaccounts" "github.com/status-im/status-go/multiaccounts"
"github.com/status-im/status-go/multiaccounts/settings" "github.com/status-im/status-go/multiaccounts/settings"
"github.com/status-im/status-go/signal" "github.com/status-im/status-go/signal"
"github.com/ethereum/go-ethereum/log"
) )
func TestRemoveSensitiveInfo(t *testing.T) { func TestRemoveSensitiveInfo(t *testing.T) {
@ -60,17 +61,17 @@ func TestRemoveSensitiveInfo(t *testing.T) {
} }
func TestCall(t *testing.T) { func TestCall(t *testing.T) {
// Enable request logging // Create a temporary file for logging
requestlog.EnableRequestLogging(true) tempLogFile, err := os.CreateTemp(t.TempDir(), "TestCall*.log")
require.NoError(t, err)
// Create a mock logger to capture log output // Enable request logging
var logOutput string err = requestlog.ConfigureAndEnableRequestLogging(tempLogFile.Name())
mockLogger := log.New() require.NoError(t, err)
mockLogger.SetHandler(log.FuncHandler(func(r *log.Record) error {
logOutput += r.Msg + fmt.Sprintf("%s", r.Ctx...) // Logger must not be nil after enabling
return nil logger := requestlog.GetRequestLogger()
})) require.NotNil(t, logger)
requestlog.NewRequestLogger().SetHandler(mockLogger.GetHandler())
// Test case 1: Normal execution // Test case 1: Normal execution
testFunc := func(param string) string { testFunc := func(param string) string {
@ -86,6 +87,11 @@ func TestCall(t *testing.T) {
t.Errorf("Expected result %s, got %s", expectedResult, result) 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 // 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 {
@ -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 // Test case 2: Panic -> recovery -> re-panic
oldRootHandler := log.Root().GetHandler() oldRootHandler := log.Root().GetHandler()
defer log.Root().SetHandler(oldRootHandler) defer log.Root().SetHandler(oldRootHandler)
log.Root().SetHandler(mockLogger.GetHandler()) log.Root().SetHandler(mockLogger.GetHandler())
// Clear log output for next test // Clear log output for next test
logOutput = "" logOutput = ""
e := "test panic" e := "test panic"
panicFunc := func() { panicFunc := func() {
panic(e) panic(e)