From 3283b79ef8eae76c374eab6c5c3b7e3b76a43726 Mon Sep 17 00:00:00 2001 From: KananGiovanni <141927408+KananGiovanni@users.noreply.github.com> Date: Thu, 16 May 2024 21:10:18 +0900 Subject: [PATCH] TraceLog changes (#1822) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * TraceLog rpc requests Co-authored-by: rian Co-authored-by: Paweł Nowosielski Co-authored-by: Rian Hughes --- jsonrpc/server.go | 6 ++++++ p2p/sync.go | 3 ++- upgrader/upgrader_test.go | 5 +++++ utils/log.go | 38 +++++++++++++++++++++++++++++++++----- utils/log_test.go | 1 + 5 files changed, 47 insertions(+), 6 deletions(-) diff --git a/jsonrpc/server.go b/jsonrpc/server.go index 1a2339b156..b75aeae6d0 100644 --- a/jsonrpc/server.go +++ b/jsonrpc/server.go @@ -397,7 +397,9 @@ func isNil(i any) bool { } func (s *Server) handleRequest(ctx context.Context, req *Request) (*response, error) { + s.log.Tracew("Received request", "req", req) if err := req.isSane(); err != nil { + s.log.Tracew("Request sanity check failed", "err", err) return nil, err } @@ -409,6 +411,7 @@ func (s *Server) handleRequest(ctx context.Context, req *Request) (*response, er calledMethod, found := s.methods[req.Method] if !found { res.Error = Err(MethodNotFound, nil) + s.log.Tracew("Method not found in request", "method", req.Method) return res, nil } @@ -417,6 +420,7 @@ func (s *Server) handleRequest(ctx context.Context, req *Request) (*response, er args, err := s.buildArguments(ctx, req.Params, calledMethod) if err != nil { res.Error = Err(InvalidParams, err.Error()) + s.log.Tracew("Error building arguments for RPC call", "err", err) return res, nil } defer func() { @@ -425,6 +429,7 @@ func (s *Server) handleRequest(ctx context.Context, req *Request) (*response, er tuple := reflect.ValueOf(calledMethod.Handler).Call(args) if res.ID == nil { // notification + s.log.Tracew("Notification received, no response expected") return nil, nil } @@ -439,6 +444,7 @@ func (s *Server) handleRequest(ctx context.Context, req *Request) (*response, er return res, nil } res.Result = tuple[0].Interface() + return res, nil } diff --git a/p2p/sync.go b/p2p/sync.go index 635673891d..53ceaeff55 100644 --- a/p2p/sync.go +++ b/p2p/sync.go @@ -195,7 +195,8 @@ func (s *syncService) logError(msg string, err error) { if !errors.Is(err, context.Canceled) { var log utils.SimpleLogger if v, ok := s.log.(*utils.ZapLogger); ok { - log = v.WithOptions(zap.AddCallerSkip(1)) + enhancedLogger := v.SugaredLogger.Desugar().WithOptions(zap.AddCallerSkip(1)).Sugar() + log = &utils.ZapLogger{SugaredLogger: enhancedLogger} } else { log = s.log } diff --git a/upgrader/upgrader_test.go b/upgrader/upgrader_test.go index 4b26342d77..213eed0b5e 100644 --- a/upgrader/upgrader_test.go +++ b/upgrader/upgrader_test.go @@ -19,6 +19,7 @@ type upgradeLogger struct { infoMsg string warnMsg string errorMsg string + traceMsg string } func (l *upgradeLogger) Debugw(msg string, keysAndValues ...any) {} @@ -35,6 +36,10 @@ func (l *upgradeLogger) Errorw(msg string, keysAndValues ...any) { l.errorMsg = msg } +func (l *upgradeLogger) Tracew(msg string, keysAndValues ...any) { + l.traceMsg = msg +} + func newVersion(t *testing.T, v string) semver.Version { version, err := semver.StrictNewVersion(v) require.NoError(t, err) diff --git a/utils/log.go b/utils/log.go index f9f4b837c8..7a6d93e614 100644 --- a/utils/log.go +++ b/utils/log.go @@ -12,8 +12,8 @@ import ( ) var ErrUnknownLogLevel = fmt.Errorf( - "unknown log level (known: %s, %s, %s, %s)", - DEBUG, INFO, WARN, ERROR, + "unknown log level (known: %s, %s, %s, %s, %s)", + DEBUG, INFO, WARN, ERROR, TRACE, ) type LogLevel int @@ -30,6 +30,7 @@ const ( INFO WARN ERROR + TRACE ) func (l LogLevel) String() string { @@ -42,6 +43,8 @@ func (l LogLevel) String() string { return "warn" case ERROR: return "error" + case TRACE: + return "trace" default: // Should not happen. panic(ErrUnknownLogLevel) @@ -62,6 +65,8 @@ func (l *LogLevel) Set(s string) error { *l = WARN case "ERROR", "error": *l = ERROR + case "TRACE", "trace": + *l = TRACE default: return ErrUnknownLogLevel } @@ -90,12 +95,27 @@ type SimpleLogger interface { Infow(msg string, keysAndValues ...any) Warnw(msg string, keysAndValues ...any) Errorw(msg string, keysAndValues ...any) + Tracew(msg string, keysAndValues ...any) } type ZapLogger struct { *zap.SugaredLogger } +const ( + traceLevel = zapcore.Level(-2) +) + +func (l *ZapLogger) IsTraceEnabled() bool { + return l.Desugar().Core().Enabled(traceLevel) +} + +func (l *ZapLogger) Tracew(msg string, keysAndValues ...interface{}) { + if l.IsTraceEnabled() { + l.Debugw("[TRACE] "+msg, keysAndValues...) // Hack: we use Debug for traces + } +} + var _ Logger = (*ZapLogger)(nil) func NewNopZapLogger() *ZapLogger { @@ -113,9 +133,17 @@ func NewZapLogger(logLevel LogLevel, colour bool) (*ZapLogger, error) { config.EncoderConfig.EncodeTime = func(t time.Time, enc zapcore.PrimitiveArrayEncoder) { enc.AppendString(t.Local().Format("15:04:05.000 02/01/2006 -07:00")) } - level, err := zapcore.ParseLevel(logLevel.String()) - if err != nil { - return nil, err + + var level zapcore.Level + var err error + levelStr := logLevel.String() + if logLevel == TRACE { + level = traceLevel + } else { + level, err = zapcore.ParseLevel(levelStr) + if err != nil { + return nil, err + } } config.Level.SetLevel(level) log, err := config.Build() diff --git a/utils/log_test.go b/utils/log_test.go index a3f782a1db..5f77b2735d 100644 --- a/utils/log_test.go +++ b/utils/log_test.go @@ -15,6 +15,7 @@ var levelStrings = map[utils.LogLevel]string{ utils.INFO: "info", utils.WARN: "warn", utils.ERROR: "error", + utils.TRACE: "trace", } func TestLogLevelString(t *testing.T) {