op-service: Log a warning when an RPC request has to be retried

op-program/host/host.go

@@ -224,7 +224,7 @@ func createRetryingRPC(ctx context.Context, logger log.Logger, url string) (clie
 	if err != nil {
 		return nil, err
 	}
-	return opclient.NewRetryingClient(rpc, maxRPCRetries), nil
+	return opclient.NewRetryingClient(logger, rpc, maxRPCRetries), nil
 }
 
 func routeHints(logger log.Logger, hHostRW io.ReadWriter, hinter preimage.HintHandler) chan error {

op-service/client/retry.go

@@ -5,6 +5,7 @@ import (
 	"time"
 
 	"github.com/ethereum/go-ethereum"
+	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/rpc"
 	"github.com/hashicorp/go-multierror"
 
@@ -19,6 +20,7 @@ var (
 
 // retryingClient wraps a [client.RPC] with a backoff strategy.
 type retryingClient struct {
+	log           log.Logger
 	c             client.RPC
 	retryAttempts int
 	strategy      backoff.Strategy
@@ -26,11 +28,12 @@ type retryingClient struct {
 
 // NewRetryingClient creates a new retrying client.
 // The backoff strategy is optional, if not provided, the default exponential backoff strategy is used.
-func NewRetryingClient(c client.RPC, retries int, strategy ...backoff.Strategy) *retryingClient {
+func NewRetryingClient(logger log.Logger, c client.RPC, retries int, strategy ...backoff.Strategy) *retryingClient {
 	if len(strategy) == 0 {
 		strategy = []backoff.Strategy{ExponentialBackoff}
 	}
 	return &retryingClient{
+		log:           logger,
 		c:             c,
 		retryAttempts: retries,
 		strategy:      strategy[0],
@@ -50,7 +53,11 @@ func (b *retryingClient) CallContext(ctx context.Context, result any, method str
 	return backoff.DoCtx(ctx, b.retryAttempts, b.strategy, func() error {
 		cCtx, cancel := context.WithTimeout(ctx, 10*time.Second)
 		defer cancel()
-		return b.c.CallContext(cCtx, result, method, args...)
+		err := b.c.CallContext(cCtx, result, method, args...)
+		if err != nil {
+			b.log.Warn("RPC request failed", "method", method, "err", err)
+		}
+		return err
 	})
 }
 
@@ -85,6 +92,7 @@ func (b *retryingClient) BatchCallContext(ctx context.Context, input []rpc.Batch
 		}
 		err := b.c.BatchCallContext(cCtx, batch)
 		if err != nil {
+			b.log.Warn("Batch request failed", "err", err)
 			// Whole call failed, retry all pending elems again
 			return err
 		}
@@ -107,6 +115,7 @@ func (b *retryingClient) BatchCallContext(ctx context.Context, input []rpc.Batch
 		}
 		if len(failed) > 0 {
 			pending = failed
+			b.log.Warn("Batch request returned errors", "err", combinedErr)
 			return combinedErr
 		}
 		return nil
@@ -118,6 +127,9 @@ func (b *retryingClient) EthSubscribe(ctx context.Context, channel any, args ...
 	err := backoff.DoCtx(ctx, b.retryAttempts, b.strategy, func() error {
 		var err error
 		sub, err = b.c.EthSubscribe(ctx, channel, args...)
+		if err != nil {
+			b.log.Warn("Subscription request failed", "err", err)
+		}
 		return err
 	})
 	return sub, err

op-service/client/retry_test.go

@@ -5,6 +5,8 @@ import (
 	"errors"
 	"testing"
 
+	"github.com/ethereum-optimism/optimism/op-node/testlog"
+	"github.com/ethereum/go-ethereum/log"
 	"github.com/stretchr/testify/mock"
 	"github.com/stretchr/testify/require"
 
@@ -66,18 +68,18 @@ var _ opclient.RPC = (*MockRPC)(nil)
 
 func TestClient_BackoffClient_Strategy(t *testing.T) {
 	mockRpc := &MockRPC{}
-	backoffClient := client.NewRetryingClient(mockRpc, 0)
+	backoffClient := client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 0)
 	require.Equal(t, backoffClient.BackoffStrategy(), client.ExponentialBackoff)
 
 	fixedStrategy := &backoff.FixedStrategy{}
-	backoffClient = client.NewRetryingClient(mockRpc, 0, fixedStrategy)
+	backoffClient = client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 0, fixedStrategy)
 	require.Equal(t, backoffClient.BackoffStrategy(), fixedStrategy)
 }
 
 func TestClient_BackoffClient_Close(t *testing.T) {
 	mockRpc := &MockRPC{}
 	mockRpc.On("Close").Return()
-	backoffClient := client.NewRetryingClient(mockRpc, 0)
+	backoffClient := client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 0)
 	backoffClient.Close()
 	require.True(t, mockRpc.AssertCalled(t, "Close"))
 }
@@ -85,7 +87,7 @@ func TestClient_BackoffClient_Close(t *testing.T) {
 func TestClient_BackoffClient_CallContext(t *testing.T) {
 	mockRpc := &MockRPC{}
 	mockRpc.ExpectCallContext(nil, nil, "foo", "bar")
-	backoffClient := client.NewRetryingClient(mockRpc, 1)
+	backoffClient := client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 1)
 	err := backoffClient.CallContext(context.Background(), nil, "foo", "bar")
 	require.NoError(t, err)
 	require.True(t, mockRpc.AssertCalled(t, "CallContext", mock.Anything, nil, "foo", []interface{}{"bar"}))
@@ -94,7 +96,7 @@ func TestClient_BackoffClient_CallContext(t *testing.T) {
 func TestClient_BackoffClient_CallContext_WithRetries(t *testing.T) {
 	mockRpc := &MockRPC{}
 	mockRpc.ExpectCallContext(errors.New("foo"), nil, "foo", "bar")
-	backoffClient := client.NewRetryingClient(mockRpc, 2, backoff.Fixed(0))
+	backoffClient := client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 2, backoff.Fixed(0))
 	err := backoffClient.CallContext(context.Background(), nil, "foo", "bar")
 	require.Error(t, err)
 	require.True(t, mockRpc.AssertNumberOfCalls(t, "CallContext", 2))
@@ -103,7 +105,7 @@ func TestClient_BackoffClient_CallContext_WithRetries(t *testing.T) {
 func TestClient_BackoffClient_BatchCallContext(t *testing.T) {
 	mockRpc := &MockRPC{}
 	mockRpc.ExpectBatchCallContext(nil, []rpc.BatchElem{})
-	backoffClient := client.NewRetryingClient(mockRpc, 1)
+	backoffClient := client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 1)
 	err := backoffClient.BatchCallContext(context.Background(), nil)
 	require.NoError(t, err)
 	require.True(t, mockRpc.AssertCalled(t, "BatchCallContext", mock.Anything, []rpc.BatchElem{}))
@@ -112,7 +114,7 @@ func TestClient_BackoffClient_BatchCallContext(t *testing.T) {
 func TestClient_BackoffClient_BatchCallContext_WithRetries(t *testing.T) {
 	mockRpc := &MockRPC{}
 	mockRpc.ExpectBatchCallContext(errors.New("foo"), []rpc.BatchElem{})
-	backoffClient := client.NewRetryingClient(mockRpc, 2, backoff.Fixed(0))
+	backoffClient := client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 2, backoff.Fixed(0))
 	err := backoffClient.BatchCallContext(context.Background(), nil)
 	require.Error(t, err)
 	require.True(t, mockRpc.AssertNumberOfCalls(t, "BatchCallContext", 2))
@@ -134,7 +136,7 @@ func TestClient_BackoffClient_BatchCallContext_WithPartialRetries(t *testing.T)
 		batch[0].Error = errors.New("boom again")
 		batch[1].Result = batch[1].Method
 	})
-	backoffClient := client.NewRetryingClient(mockRpc, 2, backoff.Fixed(0))
+	backoffClient := client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 2, backoff.Fixed(0))
 	err := backoffClient.BatchCallContext(context.Background(), batches)
 	require.Error(t, err)
 	require.True(t, mockRpc.AssertNumberOfCalls(t, "BatchCallContext", 2))
@@ -164,7 +166,7 @@ func TestClient_BackoffClient_BatchCallContext_WithPartialRetriesUntilSuccess(t
 	mockRpc.OnBatchCallContext(nil, []rpc.BatchElem{batches[1]}, func(batch []rpc.BatchElem) {
 		batch[0].Result = batch[0].Method
 	})
-	backoffClient := client.NewRetryingClient(mockRpc, 4, backoff.Fixed(0))
+	backoffClient := client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 4, backoff.Fixed(0))
 	err := backoffClient.BatchCallContext(context.Background(), batches)
 	require.NoError(t, err)
 	require.True(t, mockRpc.AssertNumberOfCalls(t, "BatchCallContext", 3))
@@ -178,7 +180,7 @@ func TestClient_BackoffClient_BatchCallContext_WithPartialRetriesUntilSuccess(t
 func TestClient_BackoffClient_EthSubscribe(t *testing.T) {
 	mockRpc := &MockRPC{}
 	mockRpc.ExpectEthSubscribe(ethereum.Subscription(nil), nil, nil, "foo", "bar")
-	backoffClient := client.NewRetryingClient(mockRpc, 1)
+	backoffClient := client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 1)
 	_, err := backoffClient.EthSubscribe(context.Background(), nil, "foo", "bar")
 	require.NoError(t, err)
 	require.True(t, mockRpc.AssertCalled(t, "EthSubscribe", mock.Anything, nil, []interface{}{"foo", "bar"}))
@@ -187,7 +189,7 @@ func TestClient_BackoffClient_EthSubscribe(t *testing.T) {
 func TestClient_BackoffClient_EthSubscribe_WithRetries(t *testing.T) {
 	mockRpc := &MockRPC{}
 	mockRpc.ExpectEthSubscribe(ethereum.Subscription(nil), errors.New("foo"), nil, "foo", "bar")
-	backoffClient := client.NewRetryingClient(mockRpc, 2, backoff.Fixed(0))
+	backoffClient := client.NewRetryingClient(testlog.Logger(t, log.LvlInfo), mockRpc, 2, backoff.Fixed(0))
 	_, err := backoffClient.EthSubscribe(context.Background(), nil, "foo", "bar")
 	require.Error(t, err)
 	require.True(t, mockRpc.AssertNumberOfCalls(t, "EthSubscribe", 2))