TraceLog changes (#1822)

* TraceLog rpc requests

Co-authored-by: rian <rian@physics.ox.ac.uk>
Co-authored-by: Paweł Nowosielski <pawel@nethermind.io>
Co-authored-by: Rian Hughes <rian.hughes@physics.ox.ac.uk>

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
 }
 

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
 		}

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)

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

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