From 6accea3755baf924d3b2c671e73d5d4b20b3a215 Mon Sep 17 00:00:00 2001 From: Ben Marx Date: Mon, 10 Aug 2026 16:00:03 -0700 Subject: [PATCH] solana/rpc: wait as long as a rate-limited endpoint asks MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The retry budget cannot rescue a rate-limited call, because it is shorter than the window that refused it. Backoff totals ~3s of jitter across four attempts (measured: [1.5s, 3.0s]); the provider fronting mainnet-beta enforces its limits over a rolling 10s window. So every attempt lands inside the window the first one was refused in, and four requests are spent to be told the same thing, aimed at an endpoint that is already shedding load. The number that fixes this is on the response, in Retry-After, and until now nothing here could reach it: solana-go discards the http.Response inside CallForInto and its error types carry a code and nothing else. So the transport records the header against the in-flight call, via an unexported context slot, and the retry loop takes it before waiting. The endpoint's own number then wins over our guess in both directions — a fixed 10s wait would stall a call the endpoint would have served again in 1s, and would still be short for a provider whose window is longer. The header is recorded on every response, not only on a 429. The refusals that motivated this arrived as HTTP 200 with the rate limit inside the JSON-RPC envelope, a shape no status-code check matches. It costs nothing: the retry loop reads the value only after an attempt failed retryably. Waits are spread upward only. Every client refused in the same window otherwise resumes together and re-spikes the endpoint as the window rolls, and arriving early is arriving refused, so the spread never subtracts. One call holds for at most 15s of endpoint-requested waiting, summed across its attempts. That clears the 10s window it is meant to outlast, and keeps the worst case at 4 attempts of 10s plus 15s, so 55s, still inside state-ingest's 60s tick — the caller that passes its root context straight down with no bound of its own. A call asked for longer stops instead of waiting a shorter time: a partial wait spends the wait and is refused anyway. It returns the rate limit itself, so the caller sees the cause rather than a deadline, and increments doublezero_solana_rpc_retry_after_exceeded_total, which is the series that says the allowance is sized wrong. Endpoints that send no Retry-After keep the existing jittered backoff untouched. Callers can tune or disable this with RetryOptions.MaxRetryAfter. defaultRequestTimeout's comment documented a ~43s worst case sized against that 60s tick, and the test asserting it hardcoded the 3s backoff total. Both now carry the allowance instead, because it is the term that bounds the wait. Verified end to end through the real constructor rather than the retry helper, since the value has to cross the transport boundary the helper cannot see: removing the one wiring line drops the observed wait from 1.1s to 2.8ms and both shapes of refusal fail. --- CHANGELOG.md | 1 + tools/solana/pkg/jsonrpc/metrics.go | 12 ++ tools/solana/pkg/jsonrpc/retry.go | 86 +++++++- tools/solana/pkg/jsonrpc/retry_test.go | 3 +- tools/solana/pkg/jsonrpc/retryafter.go | 90 ++++++++ tools/solana/pkg/jsonrpc/retryafter_test.go | 216 ++++++++++++++++++++ tools/solana/pkg/rpc/ratelimit.go | 12 ++ tools/solana/pkg/rpc/retry.go | 6 +- tools/solana/pkg/rpc/retry_test.go | 14 +- tools/solana/pkg/rpc/retryafter_test.go | 178 ++++++++++++++++ 10 files changed, 603 insertions(+), 15 deletions(-) create mode 100644 tools/solana/pkg/jsonrpc/retryafter.go create mode 100644 tools/solana/pkg/jsonrpc/retryafter_test.go create mode 100644 tools/solana/pkg/rpc/retryafter_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 9809b9ef41..4ff03dbf57 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,7 @@ All notable changes to this project will be documented in this file. - The Go telemetry SDK no longer reports a transaction the program rejected as a success. Finalization only means the cluster agreed on the transaction: a rejected instruction finalizes too, carrying the rejection in `err`, which the executor never read. It now returns a `*telemetry.ProgramError` holding the ledger's error and the program's log output, and leads the message with the program's own explanation so a caller that just prints the error still gets the reason. This is the check the serviceability executor already made. (malbeclabs/infra#1703, #4152) - A samples-account-full or missing-account rejection that reaches execution now returns the same `ErrSamplesAccountFull` / `ErrAccountNotFound` the equivalent preflight rejection does, via the new `ProgramError.CustomErrorCode()`. Preflight catches nearly all of these, but a write that simulated cleanly and then failed against the bank it landed on reported its code only through the finalized transaction, so a caller's account-full handling worked on one side of preflight and not the other. (malbeclabs/infra#1703, #4152) - Rate-limit headroom reported by a ledger RPC endpoint is now recorded per JSON-RPC method: new `doublezero_solana_rpc_ratelimit_method_limit` and `doublezero_solana_rpc_ratelimit_method_remaining` gauges, fed by a passive transport wrapper on every retrying client `tools/solana/pkg/rpc` builds. A 429 was previously opaque: solana-go keeps only a code on its error types (`*HTTPError` is `{Code int, err error}`, `*RPCError` is `{Code, Message, Data}`) and discards the `http.Response` inside `CallForInto`, so the `X-Ratelimit-*` headers naming the cap were gone before any caller saw the error — a lake indexer activity was rate-limited on `getTransaction` for 4.5 hours with no way to learn the number it was exceeding, and the endpoint returns no such headers on a 200 either. Limits are enforced per method, per source IP, over a rolling window, so the numbers are attributed to the method they apply to; a global request-rate graph does not show this. Costs nothing where unused: the request body is inspected only once a response header proves there is something to record, it is read through `GetBody` so the body the transport sends is untouched, and an endpoint reporting no headers produces no series. Two further signals make a refusal attributable to a hop: `doublezero_solana_rpc_ratelimited_total` labels each rate-limited response by the shape that carried it, since an HTTP 429 status is what an edge limiter returns while a limiter at or behind the origin commonly answers 200 with the refusal inside the JSON-RPC envelope — only the latter reaches a caller as an `*RPCError`, and no HTTP-level metric shows it; and `doublezero_solana_rpc_responses_total` counts responses by the serving node the endpoint names, which answers whether load is concentrated on one node given limits are enforced per source IP. Neither is recoverable after the fact, which is why the 4.5h rate limit could not be attributed to the edge or the ledger node. (malbeclabs/lake#753, #4161) + - A retrying ledger RPC client now waits as long as a rate-limited endpoint asks it to, instead of retrying inside the window that just refused it. The retry budget totals about 3 seconds of jittered backoff across four attempts, while the provider fronting mainnet-beta enforces its limits over a rolling 10-second window, so every attempt of a rate-limited call landed inside the window the first one was refused in — four requests spent to be told the same thing, aimed at an endpoint already shedding load. The number that fixes this is on the response, in `Retry-After`, and it could not be reached: solana-go discards the `http.Response` inside `CallForInto` and its error types carry only a code. The transport now records the header against the in-flight call and the retry loop takes it before waiting, so the endpoint's own number wins over our guess in both directions. Waits are spread upward only, because arriving before the window rolls is arriving refused. One call will hold for at most 15 seconds of endpoint-requested waiting, which clears the 10-second window and keeps the worst case at about 55 seconds against state-ingest's 60-second tick; a call asked for longer than that stops rather than waiting a shorter time, since a partial wait spends the wait and is refused anyway, and it returns the rate limit itself so the caller sees the cause. New counter `doublezero_solana_rpc_retry_after_exceeded_total` is the series that says the allowance is sized wrong. Endpoints that send no `Retry-After` keep the existing backoff untouched. Callers can tune or disable this with `jsonrpc.RetryOptions.MaxRetryAfter`. (malbeclabs/lake#753, #4161) - Collector - A failed internet-latency submission now retries from the first unwritten sample rather than restarting at the beginning of the flushed partition, and only the unwritten remainder is requeued — the same fix the device telemetry submitter got in #4145. A partition larger than one transaction is written in batches, so any failure part-way through left the earlier batches onchain while the retry and the next tick re-sent them, appending those samples a second time and skewing the latency they feed. Reachable today from an RPC timeout mid-partition; surfacing program rejections adds another way in. (malbeclabs/infra#1703, #4152) - Device Telemetry diff --git a/tools/solana/pkg/jsonrpc/metrics.go b/tools/solana/pkg/jsonrpc/metrics.go index 5dc9a4a372..c838e1a25d 100644 --- a/tools/solana/pkg/jsonrpc/metrics.go +++ b/tools/solana/pkg/jsonrpc/metrics.go @@ -34,4 +34,16 @@ var ( Name: "doublezero_solana_rpc_ratelimited_total", Help: "Rate-limited JSON-RPC responses, by method and the error shape that carried the limit (http_status or jsonrpc_error).", }, []string{"method", "carrier"}) + + // retryAfterExceededTotal counts calls that stopped retrying because the endpoint + // asked for a longer wait than one call is allowed to hold (MaxRetryAfter). + // + // This is the series that says the cap is set wrong. A rate limit that clears + // inside the cap never appears here; one that shows up steadily means the + // endpoint's window is longer than we sized for, and the fix is the cap or the + // caller's request rate, not another attempt. + retryAfterExceededTotal = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "doublezero_solana_rpc_retry_after_exceeded_total", + Help: "JSON-RPC calls that gave up because the endpoint's Retry-After exceeded the per-call allowance, by method.", + }, []string{"method"}) ) diff --git a/tools/solana/pkg/jsonrpc/retry.go b/tools/solana/pkg/jsonrpc/retry.go index 68295cab78..a2ebecce9d 100644 --- a/tools/solana/pkg/jsonrpc/retry.go +++ b/tools/solana/pkg/jsonrpc/retry.go @@ -20,6 +20,22 @@ const ( defaultBaseBackoff = 500 * time.Millisecond defaultMaxBackoff = 5 * time.Second + // defaultMaxRetryAfter caps the total time one call will spend waiting on + // endpoint-supplied Retry-After headers, summed across its attempts. + // + // It has to clear the window it is meant to outlast, or honoring the header + // changes nothing: our mainnet provider enforces limits over a rolling 10s + // window. It also has to keep the worst case inside what callers were sized + // for. defaultRequestTimeout in the rpc package documents ~43s worst case and + // names state-ingest's 60s tick as the constraint, because state-ingest passes + // its root context straight down with no call-site bound. 15s puts the worst + // case at 4 attempts of 10s plus 15s of waiting, so 55s, still inside that tick. + // + // A call whose remaining allowance cannot cover what the endpoint asked for + // stops retrying rather than waiting a shorter time. Sleeping less than the + // endpoint asked buys a refusal at the cost of the wait. + defaultMaxRetryAfter = 15 * time.Second + // batchLabel is the metric label for CallBatch, which carries a mix of methods. batchLabel = "batch" ) @@ -29,6 +45,11 @@ type RetryOptions struct { BaseBackoff time.Duration MaxBackoff time.Duration IsRetryableFunc func(error) bool + + // MaxRetryAfter caps the total wait one call will honor from endpoint-supplied + // Retry-After headers. Defaults to defaultMaxRetryAfter. A negative value turns + // the header off and leaves every wait to BaseBackoff. + MaxRetryAfter time.Duration } func WithRetry(inner solanarpc.JSONRPCClient, opt *RetryOptions) solanarpc.JSONRPCClient { @@ -47,6 +68,9 @@ func WithRetry(inner solanarpc.JSONRPCClient, opt *RetryOptions) solanarpc.JSONR if opt.IsRetryableFunc == nil { opt.IsRetryableFunc = isRetryableJSONRPC } + if opt.MaxRetryAfter == 0 { + opt.MaxRetryAfter = defaultMaxRetryAfter + } return &retryingJSONRPCClient{inner: inner, opt: *opt} } @@ -112,10 +136,26 @@ func doRetry(ctx context.Context, opt RetryOptions, label string, idempotent boo maxAttempts = 1 } + // The transport writes any Retry-After it sees into this slot, keyed on the + // context it hands down (see retryafter.go). The sink is per call, not per + // attempt, because take() clears it. + ctx, sink := withRetryAfterSink(ctx) + var lastErr error + var retryAfterSpent time.Duration for attempt := 1; attempt <= maxAttempts; attempt++ { if attempt > 1 { - if err := sleepBackoff(ctx, opt, attempt); err != nil { + wait, honored, ok := nextWait(opt, attempt, sink.take(), retryAfterSpent) + if !ok { + // The endpoint asked for longer than this call is allowed to wait. + // Retrying sooner than it asked is a refusal we have already paid + // for, so return the rate limit and let the caller's next poll + // arrive after the window instead. + retryAfterExceededTotal.WithLabelValues(label).Inc() + return lastErr + } + retryAfterSpent += honored + if err := sleepFor(ctx, wait); err != nil { // Keep the error that caused the retry. A caller whose deadline is // shorter than the retry budget would otherwise log only "context // deadline exceeded" and lose the 503 behind it — the one thing @@ -142,13 +182,39 @@ func doRetry(ctx context.Context, opt RetryOptions, label string, idempotent boo return lastErr } -// sleepBackoff waits before the given attempt, honoring ctx cancellation and -// deadlines. The wait is jittered over [d/2, d] so that the ~60 doublezerod hosts -// and dozen services reading the same ledger endpoint do not retry in lockstep and -// re-spike an endpoint that is already shedding load. Jitter keeps a floor at half -// the interval rather than reaching down to zero, so the total budget stays -// predictable against the caller's poll interval. -func sleepBackoff(ctx context.Context, opt RetryOptions, attempt int) error { +// nextWait decides how long to wait before the given attempt. +// +// retryAfter is what the endpoint asked for on the attempt that just failed, 0 if it +// asked for nothing. spent is what earlier attempts of this call already waited on +// its say-so. It returns the wait, how much of that wait counts against the +// Retry-After allowance, and whether to retry at all. +// +// An endpoint's own number always wins over our backoff, in both directions: it knows +// its window and we are guessing. The one thing we do not do is wait a shorter time +// than it asked — that spends the wait and still gets refused — so a request that +// does not fit the remaining allowance ends the call instead. +func nextWait(opt RetryOptions, attempt int, retryAfter, spent time.Duration) (wait, honored time.Duration, ok bool) { + if retryAfter > 0 && opt.MaxRetryAfter > 0 { + // Spread the resumption. Every client refused in the same window otherwise + // waits the same number of seconds and fires together, re-spiking an endpoint + // at the moment its window rolls. The spread is upward only, for the reason + // above: arriving early is arriving refused. + wait = retryAfter + rand.N(retryAfter/4+1) + if spent+wait > opt.MaxRetryAfter { + return 0, 0, false + } + return wait, wait, true + } + return jitteredBackoff(opt, attempt), 0, true +} + +// jitteredBackoff is the wait for an endpoint that named no number of its own. It +// grows linearly with the attempt and is jittered over [d/2, d] so that the ~60 +// doublezerod hosts and dozen services reading the same ledger endpoint do not retry +// in lockstep and re-spike an endpoint that is already shedding load. Jitter keeps a +// floor at half the interval rather than reaching down to zero, so the total budget +// stays predictable against the caller's poll interval. +func jitteredBackoff(opt RetryOptions, attempt int) time.Duration { d := opt.BaseBackoff * time.Duration(attempt-1) if d > opt.MaxBackoff { d = opt.MaxBackoff @@ -156,7 +222,11 @@ func sleepBackoff(ctx context.Context, opt RetryOptions, attempt int) error { if d > 0 { d = d/2 + rand.N(d/2+1) } + return d +} +// sleepFor waits, honoring ctx cancellation and deadlines. +func sleepFor(ctx context.Context, d time.Duration) error { t := time.NewTimer(d) defer t.Stop() select { diff --git a/tools/solana/pkg/jsonrpc/retry_test.go b/tools/solana/pkg/jsonrpc/retry_test.go index 4e513f5c6b..8f2848848d 100644 --- a/tools/solana/pkg/jsonrpc/retry_test.go +++ b/tools/solana/pkg/jsonrpc/retry_test.go @@ -328,7 +328,8 @@ func TestTools_Solana_JSONRPC_SleepBackoff_JitteredWithinBounds(t *testing.T) { var sawBelowCeiling bool for i := 0; i < 20; i++ { start := time.Now() - require.NoError(t, sleepBackoff(context.Background(), opt, 3)) // nominal 40ms, capped at 40ms + // nominal 40ms, capped at 40ms + require.NoError(t, sleepFor(context.Background(), jitteredBackoff(opt, 3))) elapsed := time.Since(start) require.GreaterOrEqual(t, elapsed, 20*time.Millisecond, "jitter must not drop below half the interval") if elapsed < 40*time.Millisecond { diff --git a/tools/solana/pkg/jsonrpc/retryafter.go b/tools/solana/pkg/jsonrpc/retryafter.go new file mode 100644 index 0000000000..17ac9c07a5 --- /dev/null +++ b/tools/solana/pkg/jsonrpc/retryafter.go @@ -0,0 +1,90 @@ +package jsonrpc + +import ( + "context" + "net/http" + "strconv" + "sync/atomic" + "time" +) + +// A rate-limited endpoint tells us how long to wait, and until now nothing in this +// stack could hear it. The retry budget is ~3s of jittered backoff across 4 attempts +// (see sleepBackoff), while the provider fronting our mainnet ledger enforces its +// limits over a rolling 10s window. Every attempt therefore lands inside the same +// window the first one was refused in, so a rate-limited call cannot be rescued by +// retrying — it burns four requests to be told the same thing, which is exactly the +// load the endpoint is trying to shed. +// +// The number that fixes this is on the response, in Retry-After. It cannot be read +// from the error: solana-go discards the http.Response inside CallForInto, and its +// error types carry a code and nothing else. So the transport records it against the +// in-flight call (see NoteRetryAfter) and the retry loop takes it before sleeping. +// +// Guessing instead of reading was the alternative, and it is worse in both +// directions: a fixed 10s wait stalls a call the endpoint would have served again in +// 1s, and it is still too short for a provider whose window is longer. + +// retryAfterKey addresses the per-call slot in a context. An unexported key type +// means no other package can collide with it or read the slot by accident. +type retryAfterKey struct{} + +// retryAfterSink holds the most recent Retry-After the transport saw for one call. +// Attempts run one at a time, but a single attempt can produce more than one round +// trip (a redirect, a retried h2 stream), so writes are atomic and the last one wins. +type retryAfterSink struct{ nanos atomic.Int64 } + +// take returns the recorded wait and clears the slot. Clearing matters: without it a +// Retry-After from attempt 2 would still be sitting there before attempt 3, and a +// refusal that carried no header would be paced by a stale number. +func (s *retryAfterSink) take() time.Duration { + return time.Duration(s.nanos.Swap(0)) +} + +// withRetryAfterSink returns a context carrying a fresh slot for the transport to +// write into, and the slot itself. +func withRetryAfterSink(ctx context.Context) (context.Context, *retryAfterSink) { + sink := &retryAfterSink{} + return context.WithValue(ctx, retryAfterKey{}, sink), sink +} + +// NoteRetryAfter records how long an endpoint asked the caller to wait before +// repeating the in-flight request. It is for HTTP transports wrapping a client built +// by this repo's rpc package; a context from anywhere else is ignored, so calling it +// is always safe. +// +// Only the retry loop reads this, and only after an attempt has failed with a +// retryable error. So a header on a successful response costs nothing, and there is +// no need to filter by status code here — which matters, because the refusals that +// caused this work arrived as HTTP 200 with the rate limit inside the JSON-RPC +// envelope, a shape no status-code check would have matched. +func NoteRetryAfter(ctx context.Context, d time.Duration) { + if d <= 0 { + return + } + if sink, ok := ctx.Value(retryAfterKey{}).(*retryAfterSink); ok { + sink.nanos.Store(int64(d)) + } +} + +// ParseRetryAfter reads a Retry-After header value as a duration, relative to now. +// RFC 9110 allows either delta-seconds or an HTTP-date, and providers send both. A +// value that is missing, unparseable, or already in the past yields 0, meaning "the +// endpoint said nothing" — the caller then keeps its own backoff. +func ParseRetryAfter(value string, now time.Time) time.Duration { + if value == "" { + return 0 + } + if secs, err := strconv.Atoi(value); err == nil { + if secs <= 0 { + return 0 + } + return time.Duration(secs) * time.Second + } + if when, err := http.ParseTime(value); err == nil { + if d := when.Sub(now); d > 0 { + return d + } + } + return 0 +} diff --git a/tools/solana/pkg/jsonrpc/retryafter_test.go b/tools/solana/pkg/jsonrpc/retryafter_test.go new file mode 100644 index 0000000000..5faee658d8 --- /dev/null +++ b/tools/solana/pkg/jsonrpc/retryafter_test.go @@ -0,0 +1,216 @@ +package jsonrpc + +import ( + "context" + "testing" + "time" + + "github.com/prometheus/client_golang/prometheus/testutil" + "github.com/stretchr/testify/require" +) + +func TestTools_Solana_JSONRPC_ParseRetryAfter(t *testing.T) { + t.Parallel() + + now := time.Date(2026, 8, 10, 12, 0, 0, 0, time.UTC) + for _, tc := range []struct { + name string + value string + want time.Duration + }{ + {"absent", "", 0}, + {"delta seconds", "10", 10 * time.Second}, + {"delta seconds, large", "120", 2 * time.Minute}, + // A zero or negative delta means "retry now", which is what our own backoff + // already does. Reporting 0 keeps the caller on its own schedule. + {"delta zero", "0", 0}, + {"delta negative", "-5", 0}, + {"http date ahead", "Mon, 10 Aug 2026 12:00:30 GMT", 30 * time.Second}, + // A date already past is stale, not an instruction to wait. + {"http date behind", "Mon, 10 Aug 2026 11:59:30 GMT", 0}, + {"garbage", "soon", 0}, + {"empty-ish", " ", 0}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + require.Equal(t, tc.want, ParseRetryAfter(tc.value, now)) + }) + } +} + +// TestTools_Solana_JSONRPC_NoteRetryAfter_IgnoresForeignContext: NoteRetryAfter is +// called from a transport that cannot know whether the client it serves was built by +// this package. A context without a sink must be a no-op, never a panic. +func TestTools_Solana_JSONRPC_NoteRetryAfter_IgnoresForeignContext(t *testing.T) { + t.Parallel() + + NoteRetryAfter(context.Background(), 5*time.Second) + + ctx, sink := withRetryAfterSink(context.Background()) + NoteRetryAfter(ctx, 0) + require.Zero(t, sink.take(), "a non-positive wait is not a wait") + + NoteRetryAfter(ctx, 7*time.Second) + require.Equal(t, 7*time.Second, sink.take()) + require.Zero(t, sink.take(), "take must clear the slot, or a stale wait paces the next attempt") +} + +// TestTools_Solana_JSONRPC_NextWait_PrefersTheEndpointsNumber is the whole point. +// The package backoff totals ~3s across four attempts while the provider fronting our +// mainnet ledger enforces its limits over a rolling 10s window, so every attempt of a +// rate-limited call lands inside the window that refused the first one. Only the +// endpoint knows its window, so its number has to win. +func TestTools_Solana_JSONRPC_NextWait_PrefersTheEndpointsNumber(t *testing.T) { + t.Parallel() + + opt := RetryOptions{BaseBackoff: 500 * time.Millisecond, MaxBackoff: 5 * time.Second, MaxRetryAfter: 15 * time.Second} + + // No header: our own jittered backoff, which for attempt 2 is [250ms, 500ms]. + wait, honored, ok := nextWait(opt, 2, 0, 0) + require.True(t, ok) + require.Zero(t, honored, "backoff we chose ourselves must not count against the allowance") + require.GreaterOrEqual(t, wait, 250*time.Millisecond) + require.LessOrEqual(t, wait, 500*time.Millisecond) + + // With a header the wait is the endpoint's number, spread upward only. Arriving + // before the window rolls is arriving refused, so the spread never subtracts. + var sawSpread bool + for range 40 { + wait, honored, ok = nextWait(opt, 2, 10*time.Second, 0) + require.True(t, ok) + require.GreaterOrEqual(t, wait, 10*time.Second, + "waiting less than the endpoint asked spends the wait and still gets refused") + require.LessOrEqual(t, wait, 12500*time.Millisecond) + require.Equal(t, wait, honored, "an honored wait counts fully against the allowance") + if wait > 10*time.Second { + sawSpread = true + } + } + require.True(t, sawSpread, + "every client refused in the same window would resume in lockstep and re-spike the endpoint") + + // A 10s wait beats a 500ms backoff by 20x, which is the entire fix. + quiet, _, _ := nextWait(opt, 2, 0, 0) + loud, _, _ := nextWait(opt, 2, 10*time.Second, 0) + require.Greater(t, loud, 10*quiet) +} + +// TestTools_Solana_JSONRPC_NextWait_StopsRatherThanWaitShort: the allowance bounds how +// long one call can be held, and a call that cannot afford what the endpoint asked for +// must end. Waiting a shorter time is the worst of both: it spends the wait and is +// refused anyway, because the window has not rolled. +func TestTools_Solana_JSONRPC_NextWait_StopsRatherThanWaitShort(t *testing.T) { + t.Parallel() + + opt := RetryOptions{BaseBackoff: 500 * time.Millisecond, MaxBackoff: 5 * time.Second, MaxRetryAfter: 15 * time.Second} + + // Asked for more than the whole allowance. + _, _, ok := nextWait(opt, 2, 30*time.Second, 0) + require.False(t, ok, "a wait longer than one call may hold must end the call, not be truncated") + + // Fits on its own, but not on top of what earlier attempts already waited. + _, _, ok = nextWait(opt, 3, 10*time.Second, 10*time.Second) + require.False(t, ok, "the allowance is per call, summed across attempts") + + // One 10s wait does fit, from a clean start. + wait, honored, ok := nextWait(opt, 2, 10*time.Second, 0) + require.True(t, ok) + require.Equal(t, wait, honored) + + // A negative allowance turns the header off, leaving the caller's own backoff. + off := opt + off.MaxRetryAfter = -1 + wait, honored, ok = nextWait(off, 2, 10*time.Second, 0) + require.True(t, ok) + require.Zero(t, honored) + require.LessOrEqual(t, wait, 500*time.Millisecond) +} + +// TestTools_Solana_JSONRPC_DoRetry_HonorsRetryAfterAndStopsWhenTooLong drives the loop +// rather than the helper, so it pins the two things the helper cannot: that the wait is +// actually taken, and that giving up returns the rate-limit error rather than a +// deadline or a nil. +func TestTools_Solana_JSONRPC_DoRetry_HonorsRetryAfterAndStopsWhenTooLong(t *testing.T) { + t.Parallel() + + rateLimited := &solanaRateLimit{} + + t.Run("waits the endpoints number, then succeeds", func(t *testing.T) { + t.Parallel() + + opt := RetryOptions{ + MaxAttempts: 4, BaseBackoff: time.Millisecond, MaxBackoff: time.Millisecond, + MaxRetryAfter: time.Second, IsRetryableFunc: func(error) bool { return true }, + } + var attempts int + start := time.Now() + err := doRetry(context.Background(), opt, "getTransaction", true, func(ctx context.Context) error { + attempts++ + if attempts == 1 { + NoteRetryAfter(ctx, 120*time.Millisecond) + return rateLimited + } + return nil + }) + elapsed := time.Since(start) + + require.NoError(t, err) + require.Equal(t, 2, attempts) + require.GreaterOrEqual(t, elapsed, 120*time.Millisecond, + "the endpoint's wait must be taken; a 1ms backoff would retry inside the same window") + }) + + t.Run("gives up and returns the rate limit", func(t *testing.T) { + t.Parallel() + + const method = "getSignaturesForAddress" + before := testutil.ToFloat64(retryAfterExceededTotal.WithLabelValues(method)) + + opt := RetryOptions{ + MaxAttempts: 4, BaseBackoff: time.Millisecond, MaxBackoff: time.Millisecond, + MaxRetryAfter: 50 * time.Millisecond, IsRetryableFunc: func(error) bool { return true }, + } + var attempts int + err := doRetry(context.Background(), opt, method, true, func(ctx context.Context) error { + attempts++ + NoteRetryAfter(ctx, 10*time.Second) + return rateLimited + }) + + require.ErrorIs(t, err, rateLimited, + "the caller must see the rate limit, not a truncated-wait failure or a nil") + require.Equal(t, 1, attempts, "no attempt may follow a wait we cannot afford") + require.Equal(t, before+1, testutil.ToFloat64(retryAfterExceededTotal.WithLabelValues(method)), + "giving up on the allowance is the series that says the cap is set wrong") + }) + + t.Run("no header leaves the existing backoff alone", func(t *testing.T) { + t.Parallel() + + opt := RetryOptions{ + MaxAttempts: 3, BaseBackoff: time.Millisecond, MaxBackoff: 2 * time.Millisecond, + MaxRetryAfter: time.Hour, IsRetryableFunc: func(error) bool { return true }, + } + var attempts int + start := time.Now() + err := doRetry(context.Background(), opt, "getSlot", true, func(ctx context.Context) error { + attempts++ + return rateLimited + }) + + require.ErrorIs(t, err, rateLimited) + require.Equal(t, 3, attempts, "all attempts must still be spent when no header is offered") + require.Less(t, time.Since(start), time.Second, + "an endpoint that names no number must not be waited on as if it had") + }) +} + +// solanaRateLimit stands in for a provider refusal. The shape does not matter here — +// these tests supply their own classifier — only that it is a distinct error value. +type solanaRateLimit struct{} + +func (*solanaRateLimit) Error() string { + return "Too many requests for a specific RPC call" +} + +var _ error = (*solanaRateLimit)(nil) diff --git a/tools/solana/pkg/rpc/ratelimit.go b/tools/solana/pkg/rpc/ratelimit.go index 4150cd4c1c..4251d73d0d 100644 --- a/tools/solana/pkg/rpc/ratelimit.go +++ b/tools/solana/pkg/rpc/ratelimit.go @@ -5,7 +5,9 @@ import ( "io" "net/http" "strconv" + "time" + "github.com/malbeclabs/doublezero/tools/solana/pkg/jsonrpc" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promauto" ) @@ -52,6 +54,7 @@ const ( headerMethodLimit = "X-Ratelimit-Method-Limit" headerMethodRemaining = "X-Ratelimit-Method-Remaining" headerRPCNode = "X-RPC-Node" + headerRetryAfter = "Retry-After" // maxObservedBody bounds how much of a request body is read to recover the // method name. JSON-RPC requests put "method" near the front, and this only @@ -76,6 +79,15 @@ func (o *rateLimitObserver) RoundTrip(req *http.Request) (*http.Response, error) } responsesTotal.WithLabelValues(node).Inc() + // Hand any Retry-After to the retry loop, which cannot see it otherwise: the + // response is discarded before the error reaches it (see jsonrpc.NoteRetryAfter). + // Recorded on every response rather than only on a 429, because the refusals that + // motivated this arrived as HTTP 200 with the rate limit inside the JSON-RPC + // envelope, and the retry loop only reads the value when an attempt failed. + if d := jsonrpc.ParseRetryAfter(resp.Header.Get(headerRetryAfter), time.Now()); d > 0 { + jsonrpc.NoteRetryAfter(req.Context(), d) + } + // Cheap exit first. Most endpoints report nothing, and this must not add // per-request work on the hot path when there is nothing to record — so the // request body is only inspected once a header proves it is worth it. diff --git a/tools/solana/pkg/rpc/retry.go b/tools/solana/pkg/rpc/retry.go index 011597888d..6a0d1686de 100644 --- a/tools/solana/pkg/rpc/retry.go +++ b/tools/solana/pkg/rpc/retry.go @@ -20,8 +20,10 @@ const ( // retry attempt. It must be short enough that an exhausted retry budget still // fits inside a caller's poll interval: retry multiplies a hang by MaxAttempts, // so a long per-attempt bound amplifies an endpoint stall instead of containing - // it. At the package retry defaults (4 attempts, ~3s of total jittered backoff) - // 10s puts the worst case at ~43s. + // it. At the package retry defaults (4 attempts, and up to 15s of waiting once a + // rate-limited endpoint's own Retry-After is honored) 10s puts the worst case at + // ~55s. Our own jittered backoff totals ~3s and applies only when the endpoint + // names no number, so the Retry-After allowance is what bounds the wait. // // 10s is chosen against the heaviest call we actually make, an unfiltered // getProgramAccounts over the serviceability program. Measured against mainnet diff --git a/tools/solana/pkg/rpc/retry_test.go b/tools/solana/pkg/rpc/retry_test.go index 275bbf7a4d..e1ece036c2 100644 --- a/tools/solana/pkg/rpc/retry_test.go +++ b/tools/solana/pkg/rpc/retry_test.go @@ -321,10 +321,16 @@ func TestNew_DefaultRequestTimeoutIsBounded(t *testing.T) { require.Equal(t, 10*time.Second, defaultRequestTimeout) - // Worst case for one logical call: every attempt burns the full timeout, plus - // the jittered backoff between them. - const maxAttempts = 4 - worstCase := maxAttempts*defaultRequestTimeout + 3*time.Second + // Worst case for one logical call: every attempt burns the full timeout, plus the + // waiting between them. Waiting is now bounded by the Retry-After allowance rather + // than by our own backoff, because an endpoint that names a number gets that number + // (jsonrpc.defaultMaxRetryAfter). Both are that package's constants, restated here + // the same way maxAttempts is. + const ( + maxAttempts = 4 + maxRetryAfter = 15 * time.Second + ) + worstCase := maxAttempts*defaultRequestTimeout + maxRetryAfter require.Less(t, worstCase, 60*time.Second, "an exhausted retry budget must fit inside state-ingest's 60s refresh tick") diff --git a/tools/solana/pkg/rpc/retryafter_test.go b/tools/solana/pkg/rpc/retryafter_test.go new file mode 100644 index 0000000000..3fc62ecc5f --- /dev/null +++ b/tools/solana/pkg/rpc/retryafter_test.go @@ -0,0 +1,178 @@ +package rpc + +import ( + "context" + "fmt" + "net/http" + "net/http/httptest" + "sync/atomic" + "testing" + "time" + + "github.com/malbeclabs/doublezero/tools/solana/pkg/jsonrpc" + "github.com/stretchr/testify/require" +) + +// refusalShape is how a provider delivers a rate limit. Both shapes are real: our +// mainnet ledger's sustained refusals arrived as HTTP 200 with the limit inside the +// JSON-RPC envelope, which no status-code check would have matched. +type refusalShape struct { + name string + write func(w http.ResponseWriter) +} + +var refusalShapes = []refusalShape{ + { + name: "http 429 status", + write: func(w http.ResponseWriter) { + http.Error(w, "Too many requests from your IP", http.StatusTooManyRequests) + }, + }, + { + name: "jsonrpc 429 inside a 200", + write: func(w http.ResponseWriter) { + w.Header().Set("Content-Type", "application/json") + fmt.Fprint(w, `{"jsonrpc":"2.0","id":1,"error":{"code":429,`+ + `"message":"Too many requests for a specific RPC call"}}`) + }, + }, +} + +// refusingServer refuses the first call with shape, then serves getVersion. It records +// how many requests arrived and always sets Retry-After, as our provider confirms it +// does on every refusal. +func refusingServer(t *testing.T, shape refusalShape, retryAfter string, calls *atomic.Int64) *httptest.Server { + t.Helper() + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if calls.Add(1) == 1 { + if retryAfter != "" { + w.Header().Set("Retry-After", retryAfter) + } + shape.write(w) + return + } + w.Header().Set("Content-Type", "application/json") + fmt.Fprint(w, `{"jsonrpc":"2.0","id":1,"result":{"solana-core":"2.0.0"}}`) + })) + t.Cleanup(srv.Close) + return srv +} + +// TestTools_Solana_RPC_RetryAfter_IsHonoredEndToEnd is the regression, and it has to +// run through the real constructor: the number is on the response, and solana-go +// discards the response before the error reaches the retry loop. Only the transport +// the constructor installs can carry it across that gap, so a unit test of the retry +// helper would pass with the wiring absent. +// +// The default backoff is ~500ms on the second attempt while the provider fronting our +// mainnet ledger enforces limits over a rolling 10s window. Retrying inside that +// window is a guaranteed second refusal — four attempts spent to be told the same +// thing, against an endpoint already shedding load. +func TestTools_Solana_RPC_RetryAfter_IsHonoredEndToEnd(t *testing.T) { + t.Parallel() + + for _, shape := range refusalShapes { + t.Run(shape.name, func(t *testing.T) { + t.Parallel() + + var calls atomic.Int64 + srv := refusingServer(t, shape, "1", &calls) + + client := New(srv.URL, Options{Retry: &jsonrpc.RetryOptions{ + MaxAttempts: 4, + BaseBackoff: time.Millisecond, + MaxBackoff: time.Millisecond, + MaxRetryAfter: 5 * time.Second, + }}) + defer client.Close() + + start := time.Now() + got, err := client.GetVersion(context.Background()) + elapsed := time.Since(start) + + require.NoError(t, err) + require.Equal(t, "2.0.0", got.SolanaCore) + require.EqualValues(t, 2, calls.Load()) + require.GreaterOrEqual(t, elapsed, time.Second, + "Retry-After: 1 must hold the retry for a second; the 1ms backoff configured "+ + "here would have retried inside the window that just refused us") + }) + } +} + +// TestTools_Solana_RPC_RetryAfter_OffKeepsTheOldBackoff is the other half of the +// regression. It proves the timing above comes from the header rather than from +// anything else in the stack: same server, same refusal, allowance turned off, and the +// retry lands immediately. +func TestTools_Solana_RPC_RetryAfter_OffKeepsTheOldBackoff(t *testing.T) { + t.Parallel() + + var calls atomic.Int64 + srv := refusingServer(t, refusalShapes[1], "1", &calls) + + client := New(srv.URL, Options{Retry: &jsonrpc.RetryOptions{ + MaxAttempts: 4, + BaseBackoff: time.Millisecond, + MaxBackoff: time.Millisecond, + MaxRetryAfter: -1, // off + }}) + defer client.Close() + + start := time.Now() + _, err := client.GetVersion(context.Background()) + elapsed := time.Since(start) + + require.NoError(t, err) + require.EqualValues(t, 2, calls.Load()) + require.Less(t, elapsed, time.Second, + "with the allowance off the wait must come from BaseBackoff alone") +} + +// TestTools_Solana_RPC_RetryAfter_TooLongEndsTheCall: an endpoint asking for longer +// than one call may be held gets no further attempts. Retrying sooner than it asked is +// a refusal already paid for, and the caller's own next poll arrives after the window +// anyway. The caller must see the rate limit, not a deadline. +func TestTools_Solana_RPC_RetryAfter_TooLongEndsTheCall(t *testing.T) { + t.Parallel() + + var calls atomic.Int64 + srv := refusingServer(t, refusalShapes[1], "600", &calls) + + client := New(srv.URL, Options{Retry: &jsonrpc.RetryOptions{ + MaxAttempts: 4, + BaseBackoff: time.Millisecond, + MaxBackoff: time.Millisecond, + MaxRetryAfter: 5 * time.Second, + }}) + defer client.Close() + + start := time.Now() + _, err := client.GetVersion(context.Background()) + elapsed := time.Since(start) + + require.Error(t, err) + require.ErrorContains(t, err, "429", "the rate limit itself must reach the caller") + require.EqualValues(t, 1, calls.Load(), "no attempt may follow a wait we cannot afford") + require.Less(t, elapsed, time.Second, "and it must not be held while deciding that") +} + +// TestTools_Solana_RPC_RetryAfter_AbsentHeaderStillRetries: most endpoints send no +// Retry-After, and the existing backoff has to keep working for them untouched. +func TestTools_Solana_RPC_RetryAfter_AbsentHeaderStillRetries(t *testing.T) { + t.Parallel() + + var calls atomic.Int64 + srv := refusingServer(t, refusalShapes[0], "", &calls) + + client := New(srv.URL, Options{Retry: &jsonrpc.RetryOptions{ + MaxAttempts: 4, + BaseBackoff: time.Millisecond, + MaxBackoff: time.Millisecond, + }}) + defer client.Close() + + got, err := client.GetVersion(context.Background()) + require.NoError(t, err) + require.Equal(t, "2.0.0", got.SolanaCore) + require.EqualValues(t, 2, calls.Load()) +}