Skip to content
Open
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
59 changes: 45 additions & 14 deletions pkg/ethrpc/service/log.go
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ import (
"github.com/ethereum/go-ethereum/core/types"
"go.uber.org/zap"

apperr "github.com/chainsafe/canton-middleware/pkg/app/errors"
"github.com/chainsafe/canton-middleware/pkg/ethrpc"
)

Expand All @@ -31,6 +32,32 @@ func NewLog(svc Service, logger *zap.Logger) Service {
return &logService{svc: svc, logger: logger}
}

// logErr emits a method's failure log line at a severity chosen by error kind,
// so routine client-side rejections don't masquerade as server failures. Wallets
// like MetaMask constantly probe the facade — polling stale imported tokens,
// calling unsupported methods, sending contract-creation-shaped calls — and
// every such probe surfaces here as a client-category error (bad request,
// not-supported, forbidden, …). Logging those at ERROR buries the genuine faults
// among noise.
//
// server/internal → Error (store, Canton, or other downstream failure)
// client error → Warn when warnOnClientErr, else Debug
//
// SendRawTransaction passes warnOnClientErr=true: a rejected transfer attempt
// (e.g. a non-whitelisted sender) is worth an operator's attention without being
// an Error, whereas read-path probes (Call) stay at Debug.
func (l *logService) logErr(failedMsg string, warnOnClientErr bool, err error, fields []zap.Field) {
fields = append(fields, zap.Error(err))
switch {
case apperr.IsInternalError(err):
l.logger.Error(failedMsg, fields...)
case warnOnClientErr:
l.logger.Warn(failedMsg, fields...)
default:
l.logger.Debug(failedMsg, fields...)
}
}
Comment on lines +49 to +59

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

Mutating a slice parameter in-place via append is a Go anti-pattern that can lead to subtle bugs if the caller's slice has extra capacity or is reused in the future. Additionally, adding a defensive nil check for err prevents potential issues if logErr is ever called with a nil error.

Using 3-index slicing (fields[:len(fields):len(fields)]) forces a copy of the slice when appending, ensuring the caller's underlying array is never mutated.

func (l *logService) logErr(failedMsg string, warnOnClientErr bool, err error, fields []zap.Field) {
	if err == nil {
		return
	}
	fields = append(fields[:len(fields):len(fields)], zap.Error(err))
	switch {
	case apperr.IsInternalError(err):
		l.logger.Error(failedMsg, fields...)
	case warnOnClientErr:
		l.logger.Warn(failedMsg, fields...)
	default:
		l.logger.Debug(failedMsg, fields...)
	}
}


func (l *logService) ChainID(ctx context.Context) (chainID hexutil.Uint64) {
start := time.Now()
defer func() {
Expand All @@ -55,7 +82,7 @@ func (l *logService) BlockNumber(ctx context.Context) (n hexutil.Uint64, err err
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("BlockNumber failed", append(fields, zap.Error(err))...)
l.logErr("BlockNumber failed", false, err, fields)
return
}
l.logger.Info("BlockNumber completed", fields...)
Expand All @@ -73,7 +100,7 @@ func (l *logService) GasPrice(ctx context.Context) (price *hexutil.Big, err erro
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("GasPrice failed", append(fields, zap.Error(err))...)
l.logErr("GasPrice failed", false, err, fields)
return
}
l.logger.Info("GasPrice completed", fields...)
Expand All @@ -91,7 +118,7 @@ func (l *logService) MaxPriorityFeePerGas(ctx context.Context) (fee *hexutil.Big
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("MaxPriorityFeePerGas failed", append(fields, zap.Error(err))...)
l.logErr("MaxPriorityFeePerGas failed", false, err, fields)
return
}
l.logger.Info("MaxPriorityFeePerGas completed", fields...)
Expand All @@ -115,7 +142,7 @@ func (l *logService) EstimateGas(ctx context.Context, args *ethrpc.CallArgs) (ga
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("EstimateGas failed", append(fields, zap.Error(err))...)
l.logErr("EstimateGas failed", false, err, fields)
return
}
l.logger.Info("EstimateGas completed", fields...)
Expand All @@ -133,7 +160,7 @@ func (l *logService) GetBalance(ctx context.Context, address common.Address) (ba
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("GetBalance failed", append(fields, zap.Error(err))...)
l.logErr("GetBalance failed", false, err, fields)
return
}
l.logger.Info("GetBalance completed", fields...)
Expand All @@ -152,7 +179,7 @@ func (l *logService) GetTransactionCount(ctx context.Context, address common.Add
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("GetTransactionCount failed", append(fields, zap.Error(err))...)
l.logErr("GetTransactionCount failed", false, err, fields)
return
}
l.logger.Info("GetTransactionCount completed", fields...)
Expand All @@ -171,7 +198,7 @@ func (l *logService) GetCode(ctx context.Context, address common.Address) (code
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("GetCode failed", append(fields, zap.Error(err))...)
l.logErr("GetCode failed", false, err, fields)
return
}
l.logger.Info("GetCode completed", fields...)
Expand Down Expand Up @@ -204,7 +231,9 @@ func (l *logService) SendRawTransaction(ctx context.Context, data hexutil.Bytes)
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("SendRawTransaction failed", append(fields, zap.Error(err))...)
// warnOnClientErr: a rejected transfer (e.g. non-whitelisted sender)
// is operator-relevant but not a server fault, so it logs at Warn.
l.logErr("SendRawTransaction failed", true, err, fields)
return
}
l.logger.Info("SendRawTransaction completed", fields...)
Expand All @@ -224,7 +253,7 @@ func (l *logService) GetTransactionReceipt(ctx context.Context, hash common.Hash
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("GetTransactionReceipt failed", append(fields, zap.Error(err))...)
l.logErr("GetTransactionReceipt failed", false, err, fields)
return
}
l.logger.Info("GetTransactionReceipt completed", fields...)
Expand All @@ -243,7 +272,7 @@ func (l *logService) GetTransactionByHash(ctx context.Context, hash common.Hash)
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("GetTransactionByHash failed", append(fields, zap.Error(err))...)
l.logErr("GetTransactionByHash failed", false, err, fields)
return
}
l.logger.Info("GetTransactionByHash completed", fields...)
Expand All @@ -267,7 +296,9 @@ func (l *logService) Call(ctx context.Context, args *ethrpc.CallArgs) (result he
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("Call failed", append(fields, zap.Error(err))...)
// Read-path probe failures (unknown method, unsupported/stale token)
// are routine wallet behavior, not faults — keep them at Debug.
l.logErr("Call failed", false, err, fields)
return
}
l.logger.Info("Call completed", fields...)
Expand All @@ -286,7 +317,7 @@ func (l *logService) GetLogs(ctx context.Context, query ethrpc.FilterQuery) (log
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("GetLogs failed", append(fields, zap.Error(err))...)
l.logErr("GetLogs failed", false, err, fields)
return
}
l.logger.Info("GetLogs completed", fields...)
Expand Down Expand Up @@ -315,7 +346,7 @@ func (l *logService) GetBlockByNumber(
fields = append(fields, zap.String("block_hash", blockNr.BlockHash.Hex()))
}
if err != nil {
l.logger.Error("GetBlockByNumber failed", append(fields, zap.Error(err))...)
l.logErr("GetBlockByNumber failed", false, err, fields)
return
}
l.logger.Info("GetBlockByNumber completed", fields...)
Expand All @@ -339,7 +370,7 @@ func (l *logService) GetBlockByHash(
zap.Duration("duration", time.Since(start)),
}
if err != nil {
l.logger.Error("GetBlockByHash failed", append(fields, zap.Error(err))...)
l.logErr("GetBlockByHash failed", false, err, fields)
return
}
l.logger.Info("GetBlockByHash completed", fields...)
Expand Down
79 changes: 79 additions & 0 deletions pkg/ethrpc/service/log_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,79 @@
// SPDX-License-Identifier: Apache-2.0

package service_test

import (
"context"
"errors"
"testing"

"github.com/ethereum/go-ethereum/common"
"github.com/ethereum/go-ethereum/common/hexutil"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/mock"
"github.com/stretchr/testify/require"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"go.uber.org/zap/zaptest/observer"

apperr "github.com/chainsafe/canton-middleware/pkg/app/errors"
"github.com/chainsafe/canton-middleware/pkg/ethrpc/service"
"github.com/chainsafe/canton-middleware/pkg/ethrpc/service/mocks"
)

// observedLog wraps a mock Service with the logging decorator, capturing every
// emitted entry so a test can assert the severity chosen for a given error.
func observedLog(t *testing.T) (*mocks.Service, service.Service, *observer.ObservedLogs) {
t.Helper()
core, logs := observer.New(zapcore.DebugLevel)
svc := mocks.NewService(t)
return svc, service.NewLog(svc, zap.New(core)), logs
}

// TestLogService_Severity locks in that client-side rejections are logged below
// ERROR — read-path probes at Debug, transfer attempts at Warn — while genuine
// server faults stay at ERROR. This keeps routine wallet probing from drowning
// real failures in the logs.
func TestLogService_Severity(t *testing.T) {
t.Run("Call client error is Debug, not Error", func(t *testing.T) {
svc, logSvc, logs := observedLog(t)
svc.EXPECT().Call(mock.Anything, mock.Anything).
Return(nil, apperr.BadRequestError(nil, "unknown method")).Once()

_, err := logSvc.Call(context.Background(), nil)
require.Error(t, err)

entries := logs.FilterMessage("Call failed").All()
require.Len(t, entries, 1)
assert.Equal(t, zapcore.DebugLevel, entries[0].Level)
})

t.Run("SendRawTransaction client error is Warn and carries the detail", func(t *testing.T) {
svc, logSvc, logs := observedLog(t)
svc.EXPECT().SendRawTransaction(mock.Anything, mock.Anything).
Return(common.Hash{}, apperr.ForbiddenError(
errors.New("sender not whitelisted: 0xabc"), "sender not whitelisted: 0xabc")).Once()

_, err := logSvc.SendRawTransaction(context.Background(), hexutil.Bytes{0x01})
require.Error(t, err)

entries := logs.FilterMessage("SendRawTransaction failed").All()
require.Len(t, entries, 1)
assert.Equal(t, zapcore.WarnLevel, entries[0].Level)
// The rejected address must reach the log, not just the generic message.
assert.Contains(t, entries[0].ContextMap()["error"], "sender not whitelisted: 0xabc")
})

t.Run("server fault stays at Error", func(t *testing.T) {
svc, logSvc, logs := observedLog(t)
svc.EXPECT().SendRawTransaction(mock.Anything, mock.Anything).
Return(common.Hash{}, apperr.DependencyError(errors.New("db down"), "insert mempool entry")).Once()

_, err := logSvc.SendRawTransaction(context.Background(), hexutil.Bytes{0x01})
require.Error(t, err)

entries := logs.FilterMessage("SendRawTransaction failed").All()
require.Len(t, entries, 1)
assert.Equal(t, zapcore.ErrorLevel, entries[0].Level)
})
}
7 changes: 6 additions & 1 deletion pkg/ethrpc/service/service.go
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ package service

import (
"context"
"errors"
"fmt"
"math/big"
"strings"
Expand Down Expand Up @@ -220,7 +221,11 @@ func (s *ethService) checkWhitelist(ctx context.Context, from common.Address) er
return apperr.DependencyError(err, "whitelist check")
}
if !whitelisted {
return apperr.ForbiddenError(nil, fmt.Sprintf("sender not whitelisted: %s", addr))
// Pass the detail as the wrapped error too: ServiceError.Error() returns
// the wrapped err, so without this the log line shows only the generic
// "request forbidden" and drops which address was rejected.
msg := fmt.Sprintf("sender not whitelisted: %s", addr)
return apperr.ForbiddenError(errors.New(msg), msg)
}
return nil
}
Expand Down
Loading