Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

chore_: use zap logger as request logger #5991

Merged
merged 1 commit into from
Oct 29, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 11 additions & 0 deletions logutils/logrotation.go
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
package logutils

import (
"go.uber.org/zap/zapcore"
"gopkg.in/natefinch/lumberjack.v2"

"github.com/ethereum/go-ethereum/log"
Expand Down Expand Up @@ -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,
})
}
53 changes: 22 additions & 31 deletions logutils/requestlog/request_log.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,58 +2,49 @@

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")

Check warning on line 29 in logutils/requestlog/request_log.go

View check run for this annotation

Codecov / codecov/patch

logutils/requestlog/request_log.go#L29

Added line #L29 was not covered by tests
}

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
}
14 changes: 10 additions & 4 deletions mobile/status_request_log.go
Original file line number Diff line number Diff line change
Expand Up @@ -65,15 +65,15 @@ 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)
}
}()

var startTime time.Time

if requestlog.IsRequestLoggingEnabled() {
requestLoggingEnabled := requestlog.IsRequestLoggingEnabled()
if requestLoggingEnabled {
startTime = time.Now()
}

Expand All @@ -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)
osmaczko marked this conversation as resolved.
Show resolved Hide resolved

requestlog.GetRequestLogger().Debug("call",
zap.String("method", methodName),
zap.String("params", paramsString),
zap.String("resp", respString),
zap.Duration("duration", duration),
)
}

return resp
Expand Down
36 changes: 25 additions & 11 deletions mobile/status_request_log_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -60,17 +61,17 @@ func TestRemoveSensitiveInfo(t *testing.T) {
}

func TestCall(t *testing.T) {
// Create a temporary file for logging
tempLogFile, err := os.CreateTemp(t.TempDir(), "TestCall*.log")
require.NoError(t, err)

// Enable request logging
requestlog.EnableRequestLogging(true)
err = requestlog.ConfigureAndEnableRequestLogging(tempLogFile.Name())
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())
// Logger must not be nil after enabling
logger := requestlog.GetRequestLogger()
require.NotNil(t, logger)

// Test case 1: Normal execution
testFunc := func(param string) string {
Expand All @@ -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 {
Expand All @@ -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)
Expand Down