From 2cac8bc36be6a7af8a908b02aa4120450d8534e5 Mon Sep 17 00:00:00 2001 From: Hamdi Allam Date: Thu, 7 Nov 2024 20:02:07 +0200 Subject: [PATCH] logging in the middleware --- op-txproxy/auth_handler.go | 12 ++++++++++-- op-txproxy/auth_handler_test.go | 23 ++++++++++++++++------- op-txproxy/conditional_txs.go | 1 - op-txproxy/txproxy.go | 2 +- 4 files changed, 27 insertions(+), 11 deletions(-) diff --git a/op-txproxy/auth_handler.go b/op-txproxy/auth_handler.go index 61188c2c..60902451 100644 --- a/op-txproxy/auth_handler.go +++ b/op-txproxy/auth_handler.go @@ -11,6 +11,7 @@ import ( "github.com/ethereum/go-ethereum/accounts" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/log" ) var ( @@ -25,6 +26,7 @@ var ( ) type authHandler struct { + log log.Logger headerKey string next http.Handler } @@ -37,9 +39,10 @@ type authHandler struct { // 3. Passed Validation: AuthContext is set with the authenticated caller // // note: only up to the default body limit (5MB) is read when constructing the text hash -func AuthMiddleware(headerKey string) func(next http.Handler) http.Handler { +func AuthMiddleware(log log.Logger, headerKey string) func(next http.Handler) http.Handler { + log = log.New("role", "auth") return func(next http.Handler) http.Handler { - return &authHandler{headerKey, next} + return &authHandler{log, headerKey, next} } } @@ -57,8 +60,11 @@ func (h *authHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { h.next.ServeHTTP(w, r) return } + + h.log.Debug("validating header", "header", authHeader) authElems := strings.Split(authHeader, ":") if len(authElems) != 2 { + h.log.Info("invalid auth header", "header", authHeader, "err", misformattedAuthErr) newCtx := context.WithValue(r.Context(), authContextKey{}, &AuthContext{common.Address{}, misformattedAuthErr}) h.next.ServeHTTP(w, r.WithContext(newCtx)) return @@ -88,12 +94,14 @@ func (h *authHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { caller, signature := common.HexToAddress(authElems[0]), common.FromHex(authElems[1]) sigPubKey, err := crypto.SigToPub(txtHash, signature) if sigPubKey == nil || err != nil { + h.log.Info("invalid auth header", "header", authHeader, "err", invalidSignatureErr) newCtx := context.WithValue(r.Context(), authContextKey{}, &AuthContext{common.Address{}, invalidSignatureErr}) h.next.ServeHTTP(w, r.WithContext(newCtx)) return } if caller != crypto.PubkeyToAddress(*sigPubKey) { + h.log.Info("invalid auth header", "header", authHeader, "err", mismatchedRecoveredSignerErr) newCtx := context.WithValue(r.Context(), authContextKey{}, &AuthContext{common.Address{}, mismatchedRecoveredSignerErr}) h.next.ServeHTTP(w, r.WithContext(newCtx)) return diff --git a/op-txproxy/auth_handler_test.go b/op-txproxy/auth_handler_test.go index 0b2bb4ef..04605ffa 100644 --- a/op-txproxy/auth_handler_test.go +++ b/op-txproxy/auth_handler_test.go @@ -12,10 +12,12 @@ import ( "testing" oprpc "github.com/ethereum-optimism/optimism/op-service/rpc" + "github.com/ethereum-optimism/optimism/op-service/testlog" "github.com/ethereum/go-ethereum/accounts" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/rpc" "github.com/stretchr/testify/require" @@ -23,7 +25,8 @@ import ( func TestAuthHandlerMissingAuth(t *testing.T) { var authContext *AuthContext - handler := authHandler{headerKey: "auth", next: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + log := testlog.Logger(t, log.LevelInfo) + handler := authHandler{log: log, headerKey: "auth", next: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { authContext = AuthFromContext(r.Context()) })} @@ -36,7 +39,8 @@ func TestAuthHandlerMissingAuth(t *testing.T) { func TestAuthHandlerBadHeader(t *testing.T) { var authContext *AuthContext - handler := authHandler{headerKey: "auth", next: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + log := testlog.Logger(t, log.LevelInfo) + handler := authHandler{log: log, headerKey: "auth", next: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { authContext = AuthFromContext(r.Context()) })} @@ -52,7 +56,8 @@ func TestAuthHandlerBadHeader(t *testing.T) { func TestAuthHandlerBadSignature(t *testing.T) { var authContext *AuthContext - handler := authHandler{headerKey: "auth", next: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + log := testlog.Logger(t, log.LevelInfo) + handler := authHandler{log: log, headerKey: "auth", next: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { authContext = AuthFromContext(r.Context()) })} @@ -68,7 +73,8 @@ func TestAuthHandlerBadSignature(t *testing.T) { func TestAuthHandlerMismatchedCaller(t *testing.T) { var authContext *AuthContext - handler := authHandler{headerKey: "auth", next: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + log := testlog.Logger(t, log.LevelInfo) + handler := authHandler{log: log, headerKey: "auth", next: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { authContext = AuthFromContext(r.Context()) })} @@ -93,7 +99,8 @@ func TestAuthHandlerSetContext(t *testing.T) { w.WriteHeader(http.StatusOK) }) - handler := authHandler{headerKey: DefaultAuthHeaderKey, next: ctxHandler} + log := testlog.Logger(t, log.LevelInfo) + handler := authHandler{log: log, headerKey: DefaultAuthHeaderKey, next: ctxHandler} rr := httptest.NewRecorder() body := bytes.NewBufferString("body") @@ -121,8 +128,9 @@ func (a *AuthAwareRPC) Run(ctx context.Context) error { } func TestAuthHandlerRpcMiddleware(t *testing.T) { + log := testlog.Logger(t, log.LevelInfo) apis := []rpc.API{{Namespace: "test", Service: &AuthAwareRPC{}}} - rpcServer := oprpc.NewServer("127.0.0.1", 0, "", oprpc.WithAPIs(apis), oprpc.WithMiddleware(AuthMiddleware("auth"))) + rpcServer := oprpc.NewServer("127.0.0.1", 0, "", oprpc.WithAPIs(apis), oprpc.WithMiddleware(AuthMiddleware(log, "auth"))) require.NoError(t, rpcServer.Start()) t.Cleanup(func() { _ = rpcServer.Stop() }) @@ -152,7 +160,8 @@ func TestAuthHandlerRequestBodyLimit(t *testing.T) { w.WriteHeader(http.StatusOK) }) - handler := authHandler{headerKey: "auth", next: bodyHandler} + log := testlog.Logger(t, log.LevelInfo) + handler := authHandler{log: log, headerKey: "auth", next: bodyHandler} // only up to limit is read when validating the request body authBody := strings.Repeat("*", defaultBodyLimit) diff --git a/op-txproxy/conditional_txs.go b/op-txproxy/conditional_txs.go index e78e31f5..6b211ae8 100644 --- a/op-txproxy/conditional_txs.go +++ b/op-txproxy/conditional_txs.go @@ -28,7 +28,6 @@ var ( failedValidationErr = &rpc.JsonError{Message: "failed conditional validation", Code: params.TransactionConditionalRejectedErrCode} maxCostExceededErr = &rpc.JsonError{Message: "max cost exceeded", Code: params.TransactionConditionalRejectedErrCode} missingAuthenticationErr = &rpc.JsonError{Message: "missing authentication", Code: params.TransactionConditionalRejectedErrCode} - invalidAuthenticationErr = &rpc.JsonError{Message: "invalid authentication", Code: params.TransactionConditionalRejectedErrCode} ) type ConditionalTxService struct { diff --git a/op-txproxy/txproxy.go b/op-txproxy/txproxy.go index a5543d78..098fb4d0 100644 --- a/op-txproxy/txproxy.go +++ b/op-txproxy/txproxy.go @@ -96,7 +96,7 @@ func (txp *TxProxy) initRPC(cfg *CLIConfig) error { rpcOpts := []oprpc.ServerOption{ oprpc.WithAPIs(apis), oprpc.WithLogger(txp.log), - oprpc.WithMiddleware(AuthMiddleware(DefaultAuthHeaderKey)), + oprpc.WithMiddleware(AuthMiddleware(txp.log, DefaultAuthHeaderKey)), } txp.log.Info("starting rpc server", "addr", rpcCfg.ListenAddr, "port", rpcCfg.ListenPort)