From bdbbd3b0b320873746d60a2bcaac5e1ccad5994e Mon Sep 17 00:00:00 2001 From: Jorge Manrubia Date: Fri, 18 Sep 2026 18:54:26 +0200 Subject: [PATCH 1/3] A budget spent on the server's block no longer blames the client limit MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When a gated operation runs out of its wait budget, the rejection told the user "Too many requests (client limit 10/s); waited 10s" whatever it had actually been waiting on. The branch that reports a spent budget passed blocked=false unconditionally, so a server Retry-After that the gate slept out until the deadline passed came back named as our own token bucket, with "Re-run, or lower parallelism." underneath it. That is wrong advice, not just an imprecise one. Parallelism is the knob for the client limit; a Retry-After is the server asking everybody to wait, and turning workers down does nothing about it. This is exactly why the CI failure in "Check the clamp, not the clock, in the deadline test" read "client limit 10/s" when the test had blocked on a server Retry-After — the wording was left alone there because it is a call, not a refactor. The rejection now names the limit that held the gate. A budget spent on a server block says so and stops there: Rate limited by the server; waited 10s Re-run. and a budget spent on our own bucket is unchanged. Which one is true is read from the store at the point the error is produced: a Retry-After whose end falls after this gate started queueing covered the wait, whether it is still in force or lifted while being slept out. The block that lifted is the common case — sleeping it out to within a wakeup of the deadline is how the budget usually goes — so a check for a block still in force would miss the failure this came from. A Retry-After that expired before the gate started takes no blame. The block that outlasts the budget outright is untouched: it is still reported immediately as "Rate limited by the server; retry after 30s", which already named the right limit and carries a number worth acting on. Two of the three new tests are red without the fix, both server ones. The client-limit test passes either way by construction — that behaviour is unchanged and was already correct — and it is there so the fix cannot reach past the case it is for. --- internal/resilience/gate_test.go | 56 +++++++++++++++++++++++++++++ internal/resilience/rate_limiter.go | 40 +++++++++++++++++++-- 2 files changed, 94 insertions(+), 2 deletions(-) diff --git a/internal/resilience/gate_test.go b/internal/resilience/gate_test.go index 0ad0b4905..d83bd3a46 100644 --- a/internal/resilience/gate_test.go +++ b/internal/resilience/gate_test.go @@ -367,6 +367,62 @@ func TestRateLimiterWaitRoundsTheRetryAfterUp(t *testing.T) { assert.Equal(t, "Wait 41s, then re-run.", gateErr.Hint) } +// spentBudget runs a gate whose budget is already gone — the state +// waitSince reaches when a sleep for a refill or for a block wakes past the +// deadline — and returns the rejection. The ten seconds it reports as waited +// are the gate's, not the test's: nothing here sleeps. +func spentBudget(t *testing.T, rl *RateLimiter) *GateError { + t.Helper() + err := rl.waitSince(context.Background(), time.Now().Add(-10*time.Second), time.Now().Add(-time.Millisecond)) + + var gateErr *GateError + require.ErrorAs(t, err, &gateErr) + assert.ErrorIs(t, err, basecamp.ErrRateLimited) + return gateErr +} + +// A budget spent on the server's block says so. Blaming the client limit +// here reads as "lower your parallelism", which is advice about a knob that +// had nothing to do with a wait the server asked of everybody. +func TestRateLimiterBudgetSpentOnTheServersBlockNamesTheServer(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) + require.NoError(t, rl.SetRetryAfterDuration(30*time.Second)) + + gateErr := spentBudget(t, rl) + + assert.Equal(t, "Rate limited by the server; waited 10s", gateErr.Message) + assert.Equal(t, "Re-run.", gateErr.Hint) +} + +// The block that spent the budget is usually gone by the time the gate gives +// up — sleeping it out to within a wakeup of the deadline is how the budget +// went. It is still the wait the server asked for, and still not ours. +func TestRateLimiterBudgetSpentOnABlockThatLiftedNamesTheServer(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) + require.NoError(t, rl.SetRetryAfter(time.Now().Add(-5*time.Millisecond))) + + gateErr := spentBudget(t, rl) + + assert.Equal(t, "Rate limited by the server; waited 10s", gateErr.Message) + assert.Equal(t, "Re-run.", gateErr.Hint) +} + +// A budget spent on our own bucket is the client limit, and a Retry-After +// that expired before this gate ever started queueing does not take the +// blame for it. +func TestRateLimiterBudgetSpentOnOurOwnBucketNamesTheClientLimit(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) + + gateErr := spentBudget(t, rl) + assert.Equal(t, "Too many requests (client limit 10/s); waited 10s", gateErr.Message) + assert.Equal(t, "Re-run, or lower parallelism.", gateErr.Hint) + + require.NoError(t, rl.SetRetryAfter(time.Now().Add(-30*time.Second))) + stale := spentBudget(t, rl) + assert.Equal(t, "Too many requests (client limit 10/s); waited 10s", stale.Message) + assert.Equal(t, "Re-run, or lower parallelism.", stale.Hint) +} + func TestCeilSeconds(t *testing.T) { assert.Equal(t, 41*time.Second, ceilSeconds(40*time.Second+time.Millisecond)) assert.Equal(t, 40*time.Second, ceilSeconds(40*time.Second)) diff --git a/internal/resilience/rate_limiter.go b/internal/resilience/rate_limiter.go index 58aa4debd..03e1add45 100644 --- a/internal/resilience/rate_limiter.go +++ b/internal/resilience/rate_limiter.go @@ -128,7 +128,9 @@ func sleepWithin(wait, remaining time.Duration) time.Duration { // Retry-After block to lift, until deadline. It returns nil when the request // may proceed, a *GateError when the deadline would pass first, or ctx.Err(). // A Retry-After block that outlasts the deadline is reported immediately -// rather than waited on, with the remaining time in the message. +// rather than waited on, with the remaining time in the message, and a +// budget spent queueing names the limit that held the gate: the server's +// block, or our own bucket. // Cancellation and the deadline are checked before every attempt, so an // expired or canceled gate consumes nothing, and cancellation outranks the // deadline. @@ -144,7 +146,7 @@ func (rl *RateLimiter) waitSince(ctx context.Context, start, deadline time.Time) } remaining := deadline.Sub(rl.now()) if remaining <= 0 { - return rl.gateError(false, 0, rl.now().Sub(start)) + return rl.budgetError(start) //nolint:contextcheck // lock acquisition is context-independent by design } allowed, wait, blocked := rl.take() //nolint:contextcheck // lock acquisition is context-independent by design if allowed { @@ -170,6 +172,40 @@ func (rl *RateLimiter) gateError(blocked bool, wait, waited time.Duration) *Gate sentinel: basecamp.ErrRateLimited, } } + return rl.clientLimitError(waited) +} + +// budgetError is the rejection for a gate whose budget ran out while it was +// still queueing, which is where the wait it was spent on has to be named +// rather than assumed. A server Retry-After that covered the wait is the +// server's doing and nobody's parallelism; anything else is our own bucket. +func (rl *RateLimiter) budgetError(start time.Time) *GateError { + waited := rl.now().Sub(start) + if !rl.blockedSince(start) { + return rl.clientLimitError(waited) + } + return &GateError{ + Message: fmt.Sprintf("Rate limited by the server; waited %s", waited.Round(time.Second)), + Hint: "Re-run.", + sentinel: basecamp.ErrRateLimited, + } +} + +// blockedSince reports whether a server Retry-After covered a wait that began +// at start: one still in force, or one slept out that lifted before the +// budget ran out. A store error reads as no block, since the client limit is +// the only wait we know we imposed. +func (rl *RateLimiter) blockedSince(start time.Time) bool { + state, err := rl.store.Load() + if err != nil { + return false + } + return state.RateLimiter.RetryAfterUntil.After(start) +} + +// clientLimitError is the rejection for a wait our own token bucket imposed, +// reported as the request rate the bucket allows. +func (rl *RateLimiter) clientLimitError(waited time.Duration) *GateError { requestsPerSecond := rl.config.RefillRate / rl.config.TokensPerRequest return &GateError{ Message: fmt.Sprintf("Too many requests (client limit %g/s); waited %s", requestsPerSecond, waited.Round(time.Second)), From 5ee378782644188e0fc300d8ade67f5477fcb56b Mon Sep 17 00:00:00 2001 From: Jorge Manrubia Date: Fri, 18 Sep 2026 19:06:28 +0200 Subject: [PATCH 2/3] Observe which limit held the gate, do not read it back from the store The first pass named the limit by loading the store at the moment the error was produced and asking whether the Retry-After it held ended after this gate started queueing. That is a reconstruction, and the store is shared, so it can be wrong in the direction this card is about, only mirrored: another invocation's 429 lands while this gate sleeps for a refill of its own, and a client-side timeout is handed the server's name. A block that expired between the gate's start and its first take does the same. The reader is then told to sit and wait when they should lower parallelism. It also put a locking read on the path after the budget is spent. Store.Load takes the file lock with LockTimeout, 2s, so a contended store could stretch a 10s gate to 12s to choose a message. take already distinguishes the two: blocked is true only for a Retry-After still in force. waitSince now keeps that answer for the sleep it is in, and a spent budget reports the cause of the sleep that reached the deadline. No second read, no reconstruction, and the extra lock wait goes with it. The tests are red on both halves. The server one fails 10 of 10 against main, where a budget spent on a block reports the client limit. The client one fails 10 of 10 against the store-reading first pass, where an expired Retry-After in the shared store takes the blame for a wait the bucket imposed; it passes against main, since main never gets that wrong. Neither test times a sleep. A gate reaches a spent budget only by sleeping to the deadline, so both set the deadline to the instant the thing being waited for ends -- the block lifting, the token refilling -- and pin the jitter to zero. The sleep is then exactly that wait, and a timer that never fires early wakes past the deadline by construction. 20 of 20 each, and 5 of 5 under -race. --- internal/resilience/gate_test.go | 80 ++++++++++++++++------------- internal/resilience/rate_limiter.go | 37 ++++++------- 2 files changed, 62 insertions(+), 55 deletions(-) diff --git a/internal/resilience/gate_test.go b/internal/resilience/gate_test.go index d83bd3a46..486381c8d 100644 --- a/internal/resilience/gate_test.go +++ b/internal/resilience/gate_test.go @@ -367,60 +367,70 @@ func TestRateLimiterWaitRoundsTheRetryAfterUp(t *testing.T) { assert.Equal(t, "Wait 41s, then re-run.", gateErr.Hint) } -// spentBudget runs a gate whose budget is already gone — the state -// waitSince reaches when a sleep for a refill or for a block wakes past the -// deadline — and returns the rejection. The ten seconds it reports as waited -// are the gate's, not the test's: nothing here sleeps. -func spentBudget(t *testing.T, rl *RateLimiter) *GateError { +// noJitter pins the retry spread to zero, so a sleep for a wait is exactly +// that wait and the gate wakes the moment the thing it waited for is done — +// and, a hair later, past a deadline set to that same moment. A timer never +// fires early, so the budget below is spent by construction and not by +// hoping a sleep overshoots. +func noJitter(t *testing.T) { t.Helper() - err := rl.waitSince(context.Background(), time.Now().Add(-10*time.Second), time.Now().Add(-time.Millisecond)) - - var gateErr *GateError - require.ErrorAs(t, err, &gateErr) - assert.ErrorIs(t, err, basecamp.ErrRateLimited) - return gateErr + previous := jitter + jitter = func(time.Duration) time.Duration { return 0 } + t.Cleanup(func() { jitter = previous }) } // A budget spent on the server's block says so. Blaming the client limit // here reads as "lower your parallelism", which is advice about a knob that // had nothing to do with a wait the server asked of everybody. func TestRateLimiterBudgetSpentOnTheServersBlockNamesTheServer(t *testing.T) { + noJitter(t) rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) - require.NoError(t, rl.SetRetryAfterDuration(30*time.Second)) + until := time.Now().Add(20 * time.Millisecond) + require.NoError(t, rl.SetRetryAfter(until)) - gateErr := spentBudget(t, rl) + // The gate sleeps the block out and wakes past a deadline that ends with + // it: the shape the CI failure in #763 had, and the only way a spent + // budget is ever reached on a block. + err := rl.waitSince(context.Background(), time.Now().Add(-10*time.Second), until) + var gateErr *GateError + require.ErrorAs(t, err, &gateErr) + assert.ErrorIs(t, err, basecamp.ErrRateLimited) assert.Equal(t, "Rate limited by the server; waited 10s", gateErr.Message) assert.Equal(t, "Re-run.", gateErr.Hint) } -// The block that spent the budget is usually gone by the time the gate gives -// up — sleeping it out to within a wakeup of the deadline is how the budget -// went. It is still the wait the server asked for, and still not ours. -func TestRateLimiterBudgetSpentOnABlockThatLiftedNamesTheServer(t *testing.T) { - rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) - require.NoError(t, rl.SetRetryAfter(time.Now().Add(-5*time.Millisecond))) - - gateErr := spentBudget(t, rl) - - assert.Equal(t, "Rate limited by the server; waited 10s", gateErr.Message) - assert.Equal(t, "Re-run.", gateErr.Hint) -} +// The store is shared, so the Retry-After it holds when a gate gives up is +// not proof that this gate waited on one: a block can expire before the gate +// ever looks, and another invocation's 429 can land while it sleeps for a +// refill of its own. A wait our bucket imposed keeps its own name, and the +// advice that goes with it. +func TestRateLimiterBudgetSpentOnOurOwnRefillNamesTheClientLimit(t *testing.T) { + noJitter(t) + store := NewStore(t.TempDir()) + rl := NewRateLimiter(store, RateLimiterConfig{MaxTokens: 1, RefillRate: 10, TokensPerRequest: 1}) + require.NoError(t, rl.SetRetryAfter(time.Now().Add(-500*time.Millisecond))) + allowed, err := rl.Allow() + require.NoError(t, err) + require.True(t, allowed, "the block had lifted, so the token was there to take") -// A budget spent on our own bucket is the client limit, and a Retry-After -// that expired before this gate ever started queueing does not take the -// blame for it. -func TestRateLimiterBudgetSpentOnOurOwnBucketNamesTheClientLimit(t *testing.T) { - rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) + // The deadline ends with the refill this gate is actually waiting for. + state, err := store.Load() + require.NoError(t, err) + refilled := state.RateLimiter.LastRefillAt.Add(100 * time.Millisecond) + err = rl.waitSince(context.Background(), time.Now().Add(-10*time.Second), refilled) - gateErr := spentBudget(t, rl) + var gateErr *GateError + require.ErrorAs(t, err, &gateErr) + assert.ErrorIs(t, err, basecamp.ErrRateLimited) assert.Equal(t, "Too many requests (client limit 10/s); waited 10s", gateErr.Message) assert.Equal(t, "Re-run, or lower parallelism.", gateErr.Hint) - require.NoError(t, rl.SetRetryAfter(time.Now().Add(-30*time.Second))) - stale := spentBudget(t, rl) - assert.Equal(t, "Too many requests (client limit 10/s); waited 10s", stale.Message) - assert.Equal(t, "Re-run, or lower parallelism.", stale.Hint) + state, err = store.Load() + require.NoError(t, err) + assert.True(t, state.RateLimiter.RetryAfterUntil.Before(time.Now()), + "the store still holds the expired block, which is what a gate reading it back would find") + assert.False(t, state.RateLimiter.RetryAfterUntil.IsZero(), "and there is one to find") } func TestCeilSeconds(t *testing.T) { diff --git a/internal/resilience/rate_limiter.go b/internal/resilience/rate_limiter.go index 03e1add45..4005d96ec 100644 --- a/internal/resilience/rate_limiter.go +++ b/internal/resilience/rate_limiter.go @@ -138,15 +138,18 @@ func (rl *RateLimiter) Wait(ctx context.Context, deadline time.Time) error { return rl.waitSince(ctx, rl.now(), deadline) } -// waitSince is Wait for a gate that started queueing at start. +// waitSince is Wait for a gate that started queueing at start. It carries +// the cause of the sleep it is in, so that a budget which runs out can name +// what it was spent on. func (rl *RateLimiter) waitSince(ctx context.Context, start, deadline time.Time) error { + sleptOnServerBlock := false for { if err := ctx.Err(); err != nil { return err } remaining := deadline.Sub(rl.now()) if remaining <= 0 { - return rl.budgetError(start) //nolint:contextcheck // lock acquisition is context-independent by design + return rl.budgetError(sleptOnServerBlock, rl.now().Sub(start)) } allowed, wait, blocked := rl.take() //nolint:contextcheck // lock acquisition is context-independent by design if allowed { @@ -155,6 +158,7 @@ func (rl *RateLimiter) waitSince(ctx context.Context, start, deadline time.Time) if wait > remaining { return rl.gateError(blocked, wait, rl.now().Sub(start)) } + sleptOnServerBlock = blocked if err := pause(ctx, sleepWithin(wait, remaining)); err != nil { return err } @@ -176,12 +180,17 @@ func (rl *RateLimiter) gateError(blocked bool, wait, waited time.Duration) *Gate } // budgetError is the rejection for a gate whose budget ran out while it was -// still queueing, which is where the wait it was spent on has to be named -// rather than assumed. A server Retry-After that covered the wait is the -// server's doing and nobody's parallelism; anything else is our own bucket. -func (rl *RateLimiter) budgetError(start time.Time) *GateError { - waited := rl.now().Sub(start) - if !rl.blockedSince(start) { +// still sleeping, and sleptOnServerBlock is what that last sleep was for, as +// take saw it. A server Retry-After is the server's doing and nobody's +// parallelism; anything else is our own bucket. +// +// The cause is carried out of the sleep rather than read back from the store +// here, because the store is shared and by now says something else: another +// invocation's 429 can land while this gate sleeps for a refill of its own, +// and a block this gate never waited on can expire between the two. Either +// one would hand a client-side timeout the server's name. +func (rl *RateLimiter) budgetError(sleptOnServerBlock bool, waited time.Duration) *GateError { + if !sleptOnServerBlock { return rl.clientLimitError(waited) } return &GateError{ @@ -191,18 +200,6 @@ func (rl *RateLimiter) budgetError(start time.Time) *GateError { } } -// blockedSince reports whether a server Retry-After covered a wait that began -// at start: one still in force, or one slept out that lifted before the -// budget ran out. A store error reads as no block, since the client limit is -// the only wait we know we imposed. -func (rl *RateLimiter) blockedSince(start time.Time) bool { - state, err := rl.store.Load() - if err != nil { - return false - } - return state.RateLimiter.RetryAfterUntil.After(start) -} - // clientLimitError is the rejection for a wait our own token bucket imposed, // reported as the request rate the bucket allows. func (rl *RateLimiter) clientLimitError(waited time.Duration) *GateError { From 2333fde9220d3401f27ea564b1e6a1afa2a48089 Mon Sep 17 00:00:00 2001 From: Jorge Manrubia Date: Fri, 18 Sep 2026 19:20:09 +0200 Subject: [PATCH 3/3] Decide when the gate's deadline passes instead of racing it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Both new tests raced the clock they were testing. The server one set a Retry-After 20ms out and made that the deadline, with two store writes between the deadline being set and the take that had to observe the block: on a loaded runner the budget is gone before take ever looks, the gate never records a server block, and the test reports the client limit — the very defect it exists to catch, passing itself off as the fix failing. The client one had the same shape with a 100ms window, and both computed the reported wait from a real elapsed time that a slow enough machine rounds up a second. This is the 20ms margin from #763 again, the thing this whole card came out of. A gate reaches a spent budget by waking past its deadline, and no real timer can be asked for that. So the tests no longer ask: the limiter reads a clock it is given, pause is a variable beside jitter, and the test's pause does not sleep — it advances the held clock by the sleep it was handed plus a millisecond of lateness. The deadline boundary is now something the test states. Both run in 0.00s and there is no wall clock left in either. The seam buys the other half too. The interloping 429 that the client test needs — another invocation blocking the shared store while this gate sleeps for a refill of its own — is now written inside the pause, so the order is the test's rather than a goroutine's. That is the case the suppressed review comment named, and it is the one the wall-clock version could not reach at all. take reads the Retry-After against the transaction's own now while it is there, rather than against a second clock reading inside the state, which is what the refill beside it already did. Red again, and on more than before. The server case fails 10 of 10 with main's spent-budget branch restored. The client case fails 10 of 10 with the store-reading first pass restored, on the mid-sleep 429 specifically. 50 of 50 and 3 of 3 under -race with both in place. --- internal/resilience/gate.go | 6 +- internal/resilience/gate_test.go | 107 +++++++++++++++++++--------- internal/resilience/rate_limiter.go | 14 ++-- 3 files changed, 88 insertions(+), 39 deletions(-) diff --git a/internal/resilience/gate.go b/internal/resilience/gate.go index c19e0cb4c..bf1473ee2 100644 --- a/internal/resilience/gate.go +++ b/internal/resilience/gate.go @@ -28,8 +28,10 @@ func (e *GateError) Error() string { return e.Message } // Unwrap returns the SDK sentinel the rejection stands for. func (e *GateError) Unwrap() error { return e.sentinel } -// pause sleeps for d or until ctx is done, whichever comes first. -func pause(ctx context.Context, d time.Duration) error { +// pause sleeps for d or until ctx is done, whichever comes first. A +// variable, like jitter, so that a test can wake a gate on its own terms +// rather than waiting on a real timer and hoping about the wake-up. +var pause = func(ctx context.Context, d time.Duration) error { timer := time.NewTimer(d) defer timer.Stop() select { diff --git a/internal/resilience/gate_test.go b/internal/resilience/gate_test.go index 486381c8d..69a3ff1a3 100644 --- a/internal/resilience/gate_test.go +++ b/internal/resilience/gate_test.go @@ -367,70 +367,111 @@ func TestRateLimiterWaitRoundsTheRetryAfterUp(t *testing.T) { assert.Equal(t, "Wait 41s, then re-run.", gateErr.Hint) } -// noJitter pins the retry spread to zero, so a sleep for a wait is exactly -// that wait and the gate wakes the moment the thing it waited for is done — -// and, a hair later, past a deadline set to that same moment. A timer never -// fires early, so the budget below is spent by construction and not by -// hoping a sleep overshoots. -func noJitter(t *testing.T) { +// heldClock is a clock a test moves, and the gate's own sleeps move it: +// pause does not wait, it advances the clock by the sleep it was asked for +// plus the lateness every real wake-up has. A gate only ever reaches a spent +// budget by waking past its deadline, and that is the one thing a test +// cannot ask a real timer for — the 20ms margin measured on an idle box and +// spent by the scheduler on a loaded one is the defect this card came from. +// Here the overshoot is a fact of the test. +type heldClock struct { + mu sync.Mutex + t time.Time +} + +// holdClock freezes time and hands every sleep the given lateness. The +// jitter goes to zero with it, so a sleep for a wait is exactly that wait. +func holdClock(t *testing.T, lateness time.Duration) *heldClock { t.Helper() - previous := jitter + clock := &heldClock{t: time.Now()} + + previousJitter, previousPause := jitter, pause jitter = func(time.Duration) time.Duration { return 0 } - t.Cleanup(func() { jitter = previous }) + pause = func(ctx context.Context, d time.Duration) error { + if err := ctx.Err(); err != nil { + return err + } + clock.advance(d + lateness) + return nil + } + t.Cleanup(func() { jitter, pause = previousJitter, previousPause }) + + return clock +} + +func (c *heldClock) Now() time.Time { + c.mu.Lock() + defer c.mu.Unlock() + return c.t +} + +func (c *heldClock) advance(d time.Duration) { + c.mu.Lock() + defer c.mu.Unlock() + c.t = c.t.Add(d) } // A budget spent on the server's block says so. Blaming the client limit // here reads as "lower your parallelism", which is advice about a knob that // had nothing to do with a wait the server asked of everybody. +// +// The gate sleeps a 10s block out against a 10s budget and wakes a +// millisecond late, which is the shape the CI failure in #763 had and the +// only way a spent budget is ever reached on a block. func TestRateLimiterBudgetSpentOnTheServersBlockNamesTheServer(t *testing.T) { - noJitter(t) + clock := holdClock(t, time.Millisecond) rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) - until := time.Now().Add(20 * time.Millisecond) - require.NoError(t, rl.SetRetryAfter(until)) + rl.clock = clock.Now + start := clock.Now() + require.NoError(t, rl.SetRetryAfter(start.Add(DefaultMaxWait))) - // The gate sleeps the block out and wakes past a deadline that ends with - // it: the shape the CI failure in #763 had, and the only way a spent - // budget is ever reached on a block. - err := rl.waitSince(context.Background(), time.Now().Add(-10*time.Second), until) + err := rl.waitSince(context.Background(), start, start.Add(DefaultMaxWait)) var gateErr *GateError require.ErrorAs(t, err, &gateErr) assert.ErrorIs(t, err, basecamp.ErrRateLimited) assert.Equal(t, "Rate limited by the server; waited 10s", gateErr.Message) assert.Equal(t, "Re-run.", gateErr.Hint) + assert.Equal(t, start.Add(DefaultMaxWait+time.Millisecond), clock.Now(), "slept the block out and woke late") } // The store is shared, so the Retry-After it holds when a gate gives up is -// not proof that this gate waited on one: a block can expire before the gate -// ever looks, and another invocation's 429 can land while it sleeps for a -// refill of its own. A wait our bucket imposed keeps its own name, and the -// advice that goes with it. +// no evidence that this gate waited on one. Here another invocation's 429 +// lands while this gate sleeps for a refill of its own — the write happens +// inside the sleep, so the order is the test's and not the scheduler's — and +// the wait our own bucket imposed keeps its own name, and the advice that +// goes with it. func TestRateLimiterBudgetSpentOnOurOwnRefillNamesTheClientLimit(t *testing.T) { - noJitter(t) + clock := holdClock(t, time.Millisecond) store := NewStore(t.TempDir()) - rl := NewRateLimiter(store, RateLimiterConfig{MaxTokens: 1, RefillRate: 10, TokensPerRequest: 1}) - require.NoError(t, rl.SetRetryAfter(time.Now().Add(-500*time.Millisecond))) + rl := NewRateLimiter(store, RateLimiterConfig{MaxTokens: 1, RefillRate: 1, TokensPerRequest: 1}) + rl.clock = clock.Now + start := clock.Now() + allowed, err := rl.Allow() require.NoError(t, err) - require.True(t, allowed, "the block had lifted, so the token was there to take") + require.True(t, allowed, "the bucket's one token") - // The deadline ends with the refill this gate is actually waiting for. - state, err := store.Load() - require.NoError(t, err) - refilled := state.RateLimiter.LastRefillAt.Add(100 * time.Millisecond) - err = rl.waitSince(context.Background(), time.Now().Add(-10*time.Second), refilled) + sleep := pause + pause = func(ctx context.Context, d time.Duration) error { + //nolint:contextcheck // lock acquisition is context-independent by design + require.NoError(t, rl.SetRetryAfterDuration(30*time.Second), "someone else's 429, mid-sleep") + return sleep(ctx, d) + } + + // The budget ends with the refill of the token this gate is waiting for. + err = rl.waitSince(context.Background(), start, start.Add(time.Second)) var gateErr *GateError require.ErrorAs(t, err, &gateErr) assert.ErrorIs(t, err, basecamp.ErrRateLimited) - assert.Equal(t, "Too many requests (client limit 10/s); waited 10s", gateErr.Message) + assert.Equal(t, "Too many requests (client limit 1/s); waited 1s", gateErr.Message) assert.Equal(t, "Re-run, or lower parallelism.", gateErr.Hint) - state, err = store.Load() + state, err := store.Load() require.NoError(t, err) - assert.True(t, state.RateLimiter.RetryAfterUntil.Before(time.Now()), - "the store still holds the expired block, which is what a gate reading it back would find") - assert.False(t, state.RateLimiter.RetryAfterUntil.IsZero(), "and there is one to find") + require.True(t, state.RateLimiter.RetryAfterUntil.After(start), + "the block really did land, and a gate reading the store back would have called this the server's") } func TestCeilSeconds(t *testing.T) { diff --git a/internal/resilience/rate_limiter.go b/internal/resilience/rate_limiter.go index 4005d96ec..08286be01 100644 --- a/internal/resilience/rate_limiter.go +++ b/internal/resilience/rate_limiter.go @@ -12,6 +12,9 @@ import ( type RateLimiter struct { config RateLimiterConfig store *Store + // clock is the time the limiter reads. A field so that a test can put + // the deadline boundary where it wants it instead of racing a real one. + clock func() time.Time } // NewRateLimiter creates a new rate limiter with the given config. @@ -30,12 +33,13 @@ func NewRateLimiter(store *Store, config RateLimiterConfig) *RateLimiter { return &RateLimiter{ config: config, store: store, + clock: time.Now, } } // now returns the current time. func (rl *RateLimiter) now() time.Time { - return time.Now() + return rl.clock() } // refill adds tokens based on elapsed time since last refill. @@ -78,9 +82,11 @@ func (rl *RateLimiter) take() (allowed bool, wait time.Duration, blocked bool) { rlState := &state.RateLimiter now := rl.now() - // Check Retry-After block - if rlState.IsBlocked() { - allowed, blocked, wait = false, true, rlState.BlockedFor() + // Check Retry-After block, against the transaction's own now the + // way the refill below is, and not against a second reading of the + // clock inside the state. + if blockEnds := rlState.RetryAfterUntil; blockEnds.After(now) { + allowed, blocked, wait = false, true, blockEnds.Sub(now) return nil }