From f09d6e0808747002d4aeea7b3cf152478ab41fd7 Mon Sep 17 00:00:00 2001 From: Revolution1 Date: Tue, 3 Dec 2024 19:27:37 +0800 Subject: [PATCH 1/6] fix: exclude context canccel error from forward error counting --- proxyd/backend.go | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/proxyd/backend.go b/proxyd/backend.go index 77d3326b..a1bae78d 100644 --- a/proxyd/backend.go +++ b/proxyd/backend.go @@ -381,6 +381,10 @@ func (b *Backend) Forward(ctx context.Context, reqs []*RPCReq, isBatch bool) ([] "method", metricLabelMethod, ) res, err := b.doForward(ctx, reqs, isBatch) + // if it's canceld, we don't want to count it as an error + if strings.Contains(err.Error(), "context canceled") { + return nil, err + } switch err { case nil: // do nothing case ErrBackendResponseTooLarge: @@ -583,6 +587,10 @@ func (b *Backend) doForward(ctx context.Context, rpcReqs []*RPCReq, isBatch bool start := time.Now() httpRes, err := b.client.DoLimited(httpReq) if err != nil { + // if it's canceld, we don't want to count it as an error + if strings.Contains(err.Error(), "context canceled") { + return nil, err + } b.intermittentErrorsSlidingWindow.Incr() RecordBackendNetworkErrorRateSlidingWindow(b, b.ErrorRate()) return nil, wrapErr(err, "error in backend request") @@ -1406,6 +1414,14 @@ func (bg *BackendGroup) ForwardRequestToBackendGroup( if len(rpcReqs) > 0 { res, err = back.Forward(ctx, rpcReqs, isBatch) + if strings.Contains(err.Error(), "context canceled") { + log.Info("context canceled", "req_id", GetReqID(ctx), "auth", GetAuthCtx(ctx)) + return &BackendGroupRPCResponse{ + RPCRes: nil, + ServedBy: "", + error: err, + } + } if errors.Is(err, ErrConsensusGetReceiptsCantBeBatched) || errors.Is(err, ErrConsensusGetReceiptsInvalidTarget) || From 076b7e9be12d973cd34a7e776426421259ddca15 Mon Sep 17 00:00:00 2001 From: Revolution1 Date: Tue, 3 Dec 2024 19:55:14 +0800 Subject: [PATCH 2/6] use errors.is --- proxyd/backend.go | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/proxyd/backend.go b/proxyd/backend.go index a1bae78d..0a2077c9 100644 --- a/proxyd/backend.go +++ b/proxyd/backend.go @@ -381,12 +381,10 @@ func (b *Backend) Forward(ctx context.Context, reqs []*RPCReq, isBatch bool) ([] "method", metricLabelMethod, ) res, err := b.doForward(ctx, reqs, isBatch) - // if it's canceld, we don't want to count it as an error - if strings.Contains(err.Error(), "context canceled") { - return nil, err - } switch err { case nil: // do nothing + case context.Canceled: + return nil, err case ErrBackendResponseTooLarge: log.Warn( "backend response too large", @@ -588,7 +586,7 @@ func (b *Backend) doForward(ctx context.Context, rpcReqs []*RPCReq, isBatch bool httpRes, err := b.client.DoLimited(httpReq) if err != nil { // if it's canceld, we don't want to count it as an error - if strings.Contains(err.Error(), "context canceled") { + if errors.Is(err, context.Canceled) { return nil, err } b.intermittentErrorsSlidingWindow.Incr() @@ -1414,7 +1412,7 @@ func (bg *BackendGroup) ForwardRequestToBackendGroup( if len(rpcReqs) > 0 { res, err = back.Forward(ctx, rpcReqs, isBatch) - if strings.Contains(err.Error(), "context canceled") { + if err != nil && errors.Is(err, context.Canceled) { log.Info("context canceled", "req_id", GetReqID(ctx), "auth", GetAuthCtx(ctx)) return &BackendGroupRPCResponse{ RPCRes: nil, From 5c3ed889e4f8b593a082da2995a1bd808c988e4f Mon Sep 17 00:00:00 2001 From: Revolution1 Date: Tue, 3 Dec 2024 20:29:45 +0800 Subject: [PATCH 3/6] add test --- proxyd/backend.go | 3 +++ proxyd/backend_test.go | 22 ++++++++++++++++++++++ 2 files changed, 25 insertions(+) diff --git a/proxyd/backend.go b/proxyd/backend.go index 0a2077c9..5ff902aa 100644 --- a/proxyd/backend.go +++ b/proxyd/backend.go @@ -1333,6 +1333,9 @@ type LimitedHTTPClient struct { func (c *LimitedHTTPClient) DoLimited(req *http.Request) (*http.Response, error) { if err := c.sem.Acquire(req.Context(), 1); err != nil { + if errors.Is(err, context.Canceled) { + return nil, err + } tooManyRequestErrorsTotal.WithLabelValues(c.backendName).Inc() return nil, wrapErr(err, "too many requests") } diff --git a/proxyd/backend_test.go b/proxyd/backend_test.go index 73ebebfe..c7d343f6 100644 --- a/proxyd/backend_test.go +++ b/proxyd/backend_test.go @@ -1,9 +1,12 @@ package proxyd import ( + "context" + "encoding/json" "testing" "github.com/stretchr/testify/assert" + "golang.org/x/sync/semaphore" ) func TestStripXFF(t *testing.T) { @@ -20,3 +23,22 @@ func TestStripXFF(t *testing.T) { assert.Equal(t, test.out, actual) } } + +func TestForwardContextCanceled(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + cancel() + sem := semaphore.NewWeighted(100) + backend := NewBackend( + "test", + "http://localhost:8545", + "ws://localhost:8545", + sem, + ) + _, err := backend.Forward(ctx, []*RPCReq{ + {JSONRPC: "2.0", Method: "eth_blockNumber", ID: json.RawMessage("1")}, + }, true) + assert.ErrorIs(t, context.Canceled, err) + assert.Equal(t, uint(1), backend.networkRequestsSlidingWindow.Count()) + assert.Equal(t, uint(0), backend.intermittentErrorsSlidingWindow.Count()) + assert.Zero(t, backend.ErrorRate()) +} From 47e99bfdec7dccfd4d81de6961f3a3ed65fbcc1c Mon Sep 17 00:00:00 2001 From: Revolution1 Date: Tue, 3 Dec 2024 20:48:07 +0800 Subject: [PATCH 4/6] up --- proxyd/backend.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/proxyd/backend.go b/proxyd/backend.go index 5ff902aa..dff49ac0 100644 --- a/proxyd/backend.go +++ b/proxyd/backend.go @@ -1415,7 +1415,7 @@ func (bg *BackendGroup) ForwardRequestToBackendGroup( if len(rpcReqs) > 0 { res, err = back.Forward(ctx, rpcReqs, isBatch) - if err != nil && errors.Is(err, context.Canceled) { + if errors.Is(err, context.Canceled) { log.Info("context canceled", "req_id", GetReqID(ctx), "auth", GetAuthCtx(ctx)) return &BackendGroupRPCResponse{ RPCRes: nil, From 92f1e20aa56a8998a050af3e19829c7a56e1be77 Mon Sep 17 00:00:00 2001 From: Revolution1 Date: Tue, 3 Dec 2024 21:02:47 +0800 Subject: [PATCH 5/6] adjust loglevel for canceled reqs --- proxyd/backend.go | 7 ++++++- proxyd/server.go | 7 ++++++- 2 files changed, 12 insertions(+), 2 deletions(-) diff --git a/proxyd/backend.go b/proxyd/backend.go index dff49ac0..c84be0a7 100644 --- a/proxyd/backend.go +++ b/proxyd/backend.go @@ -804,7 +804,12 @@ func (bg *BackendGroup) Forward(ctx context.Context, rpcReqs []*RPCReq, isBatch backendResp := <-ch if backendResp.error != nil { - log.Error("error serving requests", + logfn := log.Error + // If the context was canceled, downgrade the log level to debug. + if errors.Is(backendResp.error, context.Canceled) { + logfn = log.Debug + } + logfn("error serving requests", "req_id", GetReqID(ctx), "auth", GetAuthCtx(ctx), "err", backendResp.error, diff --git a/proxyd/server.go b/proxyd/server.go index 1b529b6d..5932838c 100644 --- a/proxyd/server.go +++ b/proxyd/server.go @@ -532,7 +532,12 @@ func (s *Server) handleBatchRPC(ctx context.Context, reqs []json.RawMessage, isL errors.Is(err, ErrConsensusGetReceiptsInvalidTarget) { return nil, false, "", err } - log.Error( + logfn := log.Error + // If the context was canceled, downgrade the log level to debug. + if errors.Is(err, context.Canceled) { + logfn = log.Debug + } + logfn( "error forwarding RPC batch", "batch_size", len(elems), "backend_group", group, From 858c4c5962ce6031ccf371e8f8153c232fec5d86 Mon Sep 17 00:00:00 2001 From: Revolution1 Date: Wed, 4 Dec 2024 18:20:45 +0800 Subject: [PATCH 6/6] test logging changes --- proxyd/backend_test.go | 23 +++++++++++++++++++---- 1 file changed, 19 insertions(+), 4 deletions(-) diff --git a/proxyd/backend_test.go b/proxyd/backend_test.go index c7d343f6..20429925 100644 --- a/proxyd/backend_test.go +++ b/proxyd/backend_test.go @@ -1,10 +1,13 @@ package proxyd import ( + "bytes" "context" "encoding/json" + "log/slog" "testing" + "github.com/ethereum/go-ethereum/log" "github.com/stretchr/testify/assert" "golang.org/x/sync/semaphore" ) @@ -25,6 +28,10 @@ func TestStripXFF(t *testing.T) { } func TestForwardContextCanceled(t *testing.T) { + buf := bytes.NewBuffer(nil) + log.SetDefault(log.NewLogger(slog.NewTextHandler(buf, &slog.HandlerOptions{ + Level: slog.LevelDebug.Level(), + }))) ctx, cancel := context.WithCancel(context.Background()) cancel() sem := semaphore.NewWeighted(100) @@ -34,11 +41,19 @@ func TestForwardContextCanceled(t *testing.T) { "ws://localhost:8545", sem, ) - _, err := backend.Forward(ctx, []*RPCReq{ + backendGroup := &BackendGroup{ + Name: "testgroup", + Backends: []*Backend{backend}, + routingStrategy: "fallback", + } + _, _, err := backendGroup.Forward(ctx, []*RPCReq{ {JSONRPC: "2.0", Method: "eth_blockNumber", ID: json.RawMessage("1")}, }, true) assert.ErrorIs(t, context.Canceled, err) - assert.Equal(t, uint(1), backend.networkRequestsSlidingWindow.Count()) - assert.Equal(t, uint(0), backend.intermittentErrorsSlidingWindow.Count()) - assert.Zero(t, backend.ErrorRate()) + assert.Equalf(t, uint(1), backend.networkRequestsSlidingWindow.Count(), "exact 1 network request should be counted") + assert.Equalf(t, uint(0), backend.intermittentErrorsSlidingWindow.Count(), "no intermittent errors should be counted") + assert.Zerof(t, backend.ErrorRate(), "error rate should be zero") + logs := buf.String() + assert.NotZero(t, logs) + assert.NotContainsf(t, logs, "level=ERROR", "context canceled error should not be logged as a ERROR") }