From d9b1ea46590a0508008e2ab417b6893eed9bd69e Mon Sep 17 00:00:00 2001 From: Ray Ozzie Date: Sat, 31 Oct 2026 20:46:59 -0400 Subject: [PATCH 1/2] Handle Notehub rate limits with bounded automatic retries --- README.md | 10 +- lib/config-http.go | 10 +- lib/config-retry.go | 176 +++++++++++++++++ lib/config-retry_test.go | 407 +++++++++++++++++++++++++++++++++++++++ notehub/api.go | 8 +- notehub/api_test.go | 50 ++++- notehub/main.go | 8 + notehub/main_test.go | 86 +++++++++ notehub/req.go | 62 +++++- notehub/req_test.go | 78 ++++++++ 10 files changed, 888 insertions(+), 7 deletions(-) create mode 100644 lib/config-retry.go create mode 100644 lib/config-retry_test.go create mode 100644 notehub/main_test.go diff --git a/README.md b/README.md index 48acc70..35679fa 100644 --- a/README.md +++ b/README.md @@ -198,9 +198,17 @@ The response body goes to stdout and diagnostics to stderr. JSON responses need successful responses may be empty. Check the exit code before treating a request as successful. After an uncertain write result, inspect the resource before retrying. +Rate limiting is handled for you. The hub allows a number of API requests a minute for +each billing account, and when it answers `429 Too Many Requests`, every command waits +for one request's share of that allowance to come back, as the hub's `X-RateLimit` +headers describe it, or as long as a `Retry-After` header asks, and sends the request +again, up to six times within a one-minute retry budget. If the next wait would exceed +that budget, or all retries are refused, the final 429 reaches you with any limit details +from the hub. + `--include` adds the HTTP status and headers. `--pretty` formats JSON but buffers the response; omit it for streaming responses. `--verbose` writes request details and -response status to stderr. +response status to stderr, and reports each wait for the hub's rate limiting. ### Large collections and modification cursors diff --git a/lib/config-http.go b/lib/config-http.go index fa6671e..96c8109 100644 --- a/lib/config-http.go +++ b/lib/config-http.go @@ -12,8 +12,9 @@ import ( ) // ConfigDoAuthenticated is the common request path for Notehub operations. -// It renews expiring credentials before sending and retries a 401 once when a -// refresh succeeds and the request body can be replayed. +// It renews expiring credentials before sending, retries a 401 once when a +// refresh succeeds and the request body can be replayed, and when the hub +// answers 429 Too Many Requests waits and sends again, as config-retry.go says. func ConfigDoAuthenticated(client *http.Client, req *http.Request) (*http.Response, error) { config, err := GetConfig() if err != nil { @@ -23,7 +24,7 @@ func ConfigDoAuthenticated(client *http.Client, req *http.Request) (*http.Respon } func (config *ConfigSettings) doAuthenticated(client *http.Client, req *http.Request, hub string) (*http.Response, error) { - return notehub.DoAuthenticatedRequest(client, req, func(ctx context.Context, rejectedToken string) (string, error) { + provider := func(ctx context.Context, rejectedToken string) (string, error) { if _, err := config.RefreshCredentialsForHub(ctx, hub, rejectedToken); err != nil { return "", err } @@ -32,6 +33,9 @@ func (config *ConfigSettings) doAuthenticated(client *http.Client, req *http.Req return "", fmt.Errorf("not logged in to %s: set %s, or run 'notehub login'", hub, ConfigTokenEnvVar) } return credentials.Token, nil + } + return doRetryingRateLimited(req, func(req *http.Request) (*http.Response, error) { + return notehub.DoAuthenticatedRequest(client, req, provider) }) } diff --git a/lib/config-retry.go b/lib/config-retry.go new file mode 100644 index 0000000..e7b8680 --- /dev/null +++ b/lib/config-retry.go @@ -0,0 +1,176 @@ +// Copyright 2026 Blues Inc. All rights reserved. +// Use of this source code is governed by licenses granted by the copyright holder. + +// The hub answers 429 Too Many Requests when an account sends too much too fast: its +// API allows a number of requests a minute for each billing account, and the refusal +// says so in X-RateLimit-Limit and X-RateLimit-Period, with X-RateLimit-Reset saying +// how long until the whole allowance is back. That isn't handed to the user straight +// away. The request is held back and sent again: for as long as a Retry-After header +// asks when the hub gives one, or else for one request's share of the allowance to come +// back, or when the hub says neither for a delay that doubles each time, in each case +// with some randomness so that clients limited together don't all return together. Only +// when the hub keeps refusing for a minute or so, or asks for a longer wait than that, +// does the 429 reach the caller. + +package lib + +import ( + "context" + "io" + "math/rand/v2" + "net/http" + "strconv" + "strings" + "time" +) + +const ( + // rateLimitRetries is how many times a rate-limited request is sent again + rateLimitRetries = 6 + // rateLimitFirstDelay is the first wait when the hub doesn't say how long; each wait + // after it is twice the one before, up to rateLimitMaxDelay + rateLimitFirstDelay = time.Second + // rateLimitMaxDelay is the longest wait before one retry, whether the hub asked for + // it or not: a hub asking for longer isn't retried, and its answer is returned + rateLimitMaxDelay = 60 * time.Second + // rateLimitRetryBudget includes requests and waits; no retry is scheduled beyond it. + // Requests already in progress and successful streaming responses are not cut short. + rateLimitRetryBudget = time.Minute +) + +// ConfigRateLimitNotify, when set, is told how long each wait is and which retry follows +// it, so that a verbose CLI can say what is happening; by default nothing is said +var ConfigRateLimitNotify func(wait time.Duration, retry int, retries int) + +// rateLimitSleep waits, or stops early when the request is cancelled; a test replaces it +var rateLimitSleep = func(ctx context.Context, wait time.Duration) error { + timer := time.NewTimer(wait) + defer timer.Stop() + select { + case <-timer.C: + return nil + case <-ctx.Done(): + return ctx.Err() + } +} + +// doRetryingRateLimited sends a request with send, and when the hub answers 429 Too Many +// Requests waits and sends it again, as long as its body can be sent again, until the hub +// answers otherwise or the retries or time budget run out. The response returned is the +// caller's to close. +func doRetryingRateLimited(req *http.Request, send func(*http.Request) (*http.Response, error)) (*http.Response, error) { + started := time.Now() + for retry := 1; ; retry++ { + rsp, err := send(req) + if err != nil || rsp.StatusCode != http.StatusTooManyRequests || retry > rateLimitRetries { + return rsp, err + } + wait, willing := rateLimitWait(rsp.Header, retry) + // Preserve the refusal rather than shortening a delay the hub requires. + if !willing || wait > rateLimitRetryBudget-time.Since(started) { + return rsp, nil + } + again, replayable := requestAgain(req) + if !replayable { + return rsp, nil + } + // The refusal's body isn't wanted; reading what little there is lets the + // connection be used again + io.Copy(io.Discard, io.LimitReader(rsp.Body, 64*1024)) + rsp.Body.Close() + if ConfigRateLimitNotify != nil { + ConfigRateLimitNotify(wait, retry, rateLimitRetries) + } + if err := rateLimitSleep(req.Context(), wait); err != nil { + if again.Body != nil { + again.Body.Close() + } + return nil, err + } + req = again + } +} + +// rateLimitWait is how long to wait before the given retry, the first being 1: what a +// Retry-After header asks; or else one request's share of the allowance the hub's +// X-RateLimit headers describe, and up to a quarter again in case others are waiting for +// it too; or when the hub says neither an increasing delay with some randomness. A wait +// longer than rateLimitMaxDelay isn't made. +func rateLimitWait(header http.Header, retry int) (wait time.Duration, willing bool) { + if asked, given := retryAfter(header, time.Now()); given { + if asked > rateLimitMaxDelay { + return 0, false + } + if asked > 0 { + return asked, true + } + } + if share, given := rateLimitShare(header); given { + if share > rateLimitMaxDelay { + return 0, false + } + return min(share+rand.N(share/4+1), rateLimitMaxDelay), true + } + delay := rateLimitFirstDelay << (retry - 1) + if delay > rateLimitMaxDelay || delay <= 0 { + delay = rateLimitMaxDelay + } + // Somewhere between half the delay and the whole of it + return delay/2 + rand.N(delay/2), true +} + +// retryAfter reads a Retry-After header, which gives a number of seconds or an HTTP date, +// as a wait from now; a header that is missing or can't be read gives none +func retryAfter(header http.Header, now time.Time) (wait time.Duration, given bool) { + value := strings.TrimSpace(header.Get("Retry-After")) + if value == "" { + return 0, false + } + if seconds, err := strconv.Atoi(value); err == nil { + return time.Duration(seconds) * time.Second, true + } + if at, err := http.ParseTime(value); err == nil { + return at.Sub(now), true + } + return 0, false +} + +// rateLimitShare is how long one request's share of the hub's allowance takes to come +// back, from the X-RateLimit-Limit and X-RateLimit-Period headers of a refusal: the hub +// admits that many requests in that period, so one more is admitted that fraction of the +// period after the last was. Without those, X-RateLimit-Reset, how long until the whole +// allowance is back, is a wait that surely suffices. The hub writes the durations as Go +// does, such as 1m0s. +func rateLimitShare(header http.Header) (share time.Duration, given bool) { + limit, limitErr := strconv.Atoi(strings.TrimSpace(header.Get("X-RateLimit-Limit"))) + period, periodErr := time.ParseDuration(strings.TrimSpace(header.Get("X-RateLimit-Period"))) + if limitErr == nil && periodErr == nil && limit > 0 && period > 0 { + if share = period / time.Duration(limit); share > 0 { + return share, true + } + } + if reset, err := time.ParseDuration(strings.TrimSpace(header.Get("X-RateLimit-Reset"))); err == nil && reset > 0 { + return reset, true + } + return 0, false +} + +// requestAgain is the request to send again: the same request with its body, which the +// first sending consumed, read afresh. That can be done when the body is empty or the +// request knows how to read it again, as http.NewRequest arranges for a request built +// from bytes or a string, which every request the CLI builds is. +func requestAgain(req *http.Request) (again *http.Request, replayable bool) { + again = req.Clone(req.Context()) + if req.Body == nil || req.Body == http.NoBody { + return again, true + } + if req.GetBody == nil { + return nil, false + } + body, err := req.GetBody() + if err != nil { + return nil, false + } + again.Body = body + return again, true +} diff --git a/lib/config-retry_test.go b/lib/config-retry_test.go new file mode 100644 index 0000000..c8e4531 --- /dev/null +++ b/lib/config-retry_test.go @@ -0,0 +1,407 @@ +package lib + +import ( + "context" + "errors" + "io" + "net/http" + "strconv" + "strings" + "testing" + "testing/synctest" + "time" +) + +// rateLimitTestSleeps replaces the wait between retries with a record of each one +func rateLimitTestSleeps(t *testing.T) *[]time.Duration { + t.Helper() + original := rateLimitSleep + t.Cleanup(func() { rateLimitSleep = original }) + sleeps := &[]time.Duration{} + rateLimitSleep = func(ctx context.Context, wait time.Duration) error { + *sleeps = append(*sleeps, wait) + return ctx.Err() + } + return sleeps +} + +// rateLimitTestTransport answers each request with the next status given, repeating the +// last, and records the body sent each time +func rateLimitTestTransport(t *testing.T, header http.Header, statuses ...int) (calls *int, bodies *[]string) { + t.Helper() + original := http.DefaultTransport + t.Cleanup(func() { http.DefaultTransport = original }) + calls, bodies = new(int), &[]string{} + http.DefaultTransport = refreshTransport(func(req *http.Request) (*http.Response, error) { + if req.URL.Path == "/oauth2/token" { + return &http.Response{StatusCode: 200, Body: io.NopCloser(strings.NewReader(`{"access_token":"renewed","refresh_token":"rotated","expires_in":3600}`))}, nil + } + if req.Header.Get("Authorization") == "" { + t.Error("a retried request lost its credentials") + } + body := "" + if req.Body != nil { + contents, _ := io.ReadAll(req.Body) + body = string(contents) + } + *bodies = append(*bodies, body) + status := statuses[min(*calls, len(statuses)-1)] + *calls++ + rsp := &http.Response{StatusCode: status, Header: http.Header{}, Body: io.NopCloser(strings.NewReader(`{"err":"status ` + strconv.Itoa(status) + `"}`))} + if status == http.StatusTooManyRequests { + rsp.Header = header.Clone() + } + return rsp, nil + }) + return calls, bodies +} + +// A rate-limited request is sent again with the same body, after waits that double +// each time, until the hub accepts it; the body of the refusal is never seen +func TestRateLimitedRequestIsRetried(t *testing.T) { + settings := refreshTestConfig(t, time.Now().Add(time.Hour)) + sleeps := rateLimitTestSleeps(t) + calls, bodies := rateLimitTestTransport(t, nil, 429, 429, 429, 200) + req, _ := http.NewRequest("POST", "https://"+settings.Hub+"/req", strings.NewReader(`{"req":"test"}`)) + rsp, err := settings.doAuthenticated(http.DefaultClient, req, settings.Hub) + if err != nil { + t.Fatal(err) + } + defer rsp.Body.Close() + if rsp.StatusCode != 200 || *calls != 4 { + t.Fatalf("status=%d calls=%d", rsp.StatusCode, *calls) + } + for i, body := range *bodies { + if body != `{"req":"test"}` { + t.Errorf("request %d sent body %q", i+1, body) + } + } + if len(*sleeps) != 3 { + t.Fatalf("sleeps=%v", *sleeps) + } + for i, wait := range *sleeps { + full := rateLimitFirstDelay << i + if wait < full/2 || wait > full { + t.Errorf("wait %d was %s, not between %s and %s", i+1, wait, full/2, full) + } + } +} + +// A request with no body is retried too +func TestRateLimitedRequestWithoutBodyIsRetried(t *testing.T) { + settings := refreshTestConfig(t, time.Now().Add(time.Hour)) + rateLimitTestSleeps(t) + calls, _ := rateLimitTestTransport(t, nil, 429, 200) + req, _ := http.NewRequest("GET", "https://"+settings.Hub+"/v1/projects", nil) + rsp, err := settings.doAuthenticated(http.DefaultClient, req, settings.Hub) + if err != nil { + t.Fatal(err) + } + rsp.Body.Close() + if rsp.StatusCode != 200 || *calls != 2 { + t.Fatalf("status=%d calls=%d", rsp.StatusCode, *calls) + } +} + +// The hub's headers say how long to wait: a Retry-After exactly, or one request's share +// of the allowance that X-RateLimit-Limit and X-RateLimit-Period describe, with up to a +// quarter again, or the X-RateLimit-Reset until the whole allowance is back; and the delay +// when the hub says nothing readable +func TestRateLimitedRequestHonorsHeaders(t *testing.T) { + hubHeaders := headerOf("X-RateLimit-Limit", "7", "X-RateLimit-Period", "1m0s", "X-RateLimit-Reset", "48.571428571s", "X-RateLimit-Remaining", "0") + share := time.Minute / 7 + for _, test := range []struct { + name string + header func() http.Header + least time.Duration + most time.Duration + }{ + {"Retry-After seconds", func() http.Header { return http.Header{"Retry-After": {"3"}} }, 3 * time.Second, 3 * time.Second}, + {"Retry-After date", func() http.Header { + return http.Header{"Retry-After": {time.Now().Add(5 * time.Second).UTC().Format(http.TimeFormat)}} + }, 3 * time.Second, 5 * time.Second}, + {"Retry-After zero falls back to the delay", func() http.Header { return http.Header{"Retry-After": {"0"}} }, rateLimitFirstDelay / 2, rateLimitFirstDelay}, + {"Retry-After unreadable falls back to the delay", func() http.Header { return http.Header{"Retry-After": {"soon"}} }, rateLimitFirstDelay / 2, rateLimitFirstDelay}, + {"the hub's X-RateLimit headers", func() http.Header { return hubHeaders.Clone() }, share, share + share/4}, + {"X-RateLimit-Reset alone", func() http.Header { return headerOf("X-RateLimit-Reset", "12.5s") }, 12500 * time.Millisecond, 12500*time.Millisecond + 12500*time.Millisecond/4}, + {"Retry-After over X-RateLimit", func() http.Header { h := hubHeaders.Clone(); h.Set("Retry-After", "3"); return h }, 3 * time.Second, 3 * time.Second}, + {"unreadable X-RateLimit falls back to the delay", func() http.Header { + return headerOf("X-RateLimit-Limit", "many", "X-RateLimit-Period", "a while", "X-RateLimit-Reset", "soon") + }, rateLimitFirstDelay / 2, rateLimitFirstDelay}, + } { + t.Run(test.name, func(t *testing.T) { + settings := refreshTestConfig(t, time.Now().Add(time.Hour)) + sleeps := rateLimitTestSleeps(t) + calls, _ := rateLimitTestTransport(t, test.header(), 429, 200) + req, _ := http.NewRequest("GET", "https://"+settings.Hub+"/v1/projects", nil) + rsp, err := settings.doAuthenticated(http.DefaultClient, req, settings.Hub) + if err != nil { + t.Fatal(err) + } + rsp.Body.Close() + if *calls != 2 || len(*sleeps) != 1 { + t.Fatalf("calls=%d sleeps=%v", *calls, *sleeps) + } + if wait := (*sleeps)[0]; wait < test.least || wait > test.most { + t.Fatalf("waited %s, not between %s and %s", wait, test.least, test.most) + } + }) + } +} + +// A hub that asks for a longer wait than the CLI is willing to make isn't retried, and +// its answer is returned for the caller to explain +func TestRateLimitedRequestWaitTooLong(t *testing.T) { + for _, test := range []struct { + name string + header http.Header + }{ + {"Retry-After", http.Header{"Retry-After": {"600"}}}, + {"X-RateLimit-Reset", headerOf("X-RateLimit-Reset", "5m0s")}, + {"X-RateLimit share", headerOf("X-RateLimit-Limit", "1", "X-RateLimit-Period", "2m0s")}, + } { + t.Run(test.name, func(t *testing.T) { + settings := refreshTestConfig(t, time.Now().Add(time.Hour)) + sleeps := rateLimitTestSleeps(t) + calls, _ := rateLimitTestTransport(t, test.header, 429, 200) + req, _ := http.NewRequest("GET", "https://"+settings.Hub+"/v1/projects", nil) + rsp, err := settings.doAuthenticated(http.DefaultClient, req, settings.Hub) + if err != nil { + t.Fatal(err) + } + defer rsp.Body.Close() + if rsp.StatusCode != 429 || *calls != 1 || len(*sleeps) != 0 { + t.Fatalf("status=%d calls=%d sleeps=%v", rsp.StatusCode, *calls, *sleeps) + } + }) + } +} + +// The retry budget includes time spent sending requests and waiting. A delay that +// won't fit is never shortened, and the final refusal is left intact for the caller. +func TestRateLimitedRequestRetryBudget(t *testing.T) { + for _, test := range []struct { + name string + header http.Header + requestTime time.Duration + finalStatus int + wantCalls int + wantElapsed time.Duration + wantWait time.Duration + }{ + {"repeated minute waits", headerOf("Retry-After", "60"), 0, 429, 2, time.Minute, time.Minute}, + {"do not shorten Retry-After", headerOf("Retry-After", "40"), 0, 429, 2, 40 * time.Second, 40 * time.Second}, + {"request time counts", headerOf("Retry-After", "25"), 10 * time.Second, 429, 2, 45 * time.Second, 25 * time.Second}, + {"request exhausts budget", headerOf("Retry-After", "1"), time.Minute, 429, 1, time.Minute, 0}, + {"X-RateLimit waits", headerOf("X-RateLimit-Limit", "1", "X-RateLimit-Period", "1m"), 0, 429, 2, time.Minute, time.Minute}, + {"successful retry", headerOf("Retry-After", "10"), time.Second, 200, 2, 12 * time.Second, 10 * time.Second}, + } { + t.Run(test.name, func(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + settings := refreshTestConfig(t, time.Now().Add(time.Hour)) + originalNotify := ConfigRateLimitNotify + t.Cleanup(func() { ConfigRateLimitNotify = originalNotify }) + var waits []time.Duration + ConfigRateLimitNotify = func(wait time.Duration, _, _ int) { waits = append(waits, wait) } + calls := 0 + client := &http.Client{Transport: refreshTransport(func(req *http.Request) (*http.Response, error) { + calls++ + time.Sleep(test.requestTime) + status := http.StatusTooManyRequests + if calls > 1 { + status = test.finalStatus + } + return &http.Response{StatusCode: status, Header: test.header.Clone(), Body: io.NopCloser(strings.NewReader("response body"))}, nil + })} + req, _ := http.NewRequest("GET", "https://"+settings.Hub+"/v1/projects", nil) + started := time.Now() + rsp, err := settings.doAuthenticated(client, req, settings.Hub) + if err != nil { + t.Fatal(err) + } + defer rsp.Body.Close() + if elapsed := time.Since(started); elapsed != test.wantElapsed || calls != test.wantCalls || rsp.StatusCode != test.finalStatus { + t.Fatalf("elapsed=%s calls=%d status=%d, want %s/%d/%d", elapsed, calls, rsp.StatusCode, test.wantElapsed, test.wantCalls, test.finalStatus) + } + wantWaits := 0 + if test.wantWait > 0 { + wantWaits = 1 + } + if len(waits) != wantWaits || (wantWaits == 1 && waits[0] != test.wantWait) { + t.Fatalf("waits=%v, want %d waits of %s", waits, wantWaits, test.wantWait) + } + if body, err := io.ReadAll(rsp.Body); err != nil || string(body) != "response body" { + t.Fatalf("final body=%q err=%v", body, err) + } + }) + }) + } +} + +// When the hub keeps refusing, the retries run out and the last refusal is returned +// whole, so the caller can read what the hub said +func TestRateLimitedRequestGivesUp(t *testing.T) { + settings := refreshTestConfig(t, time.Now().Add(time.Hour)) + sleeps := rateLimitTestSleeps(t) + calls, _ := rateLimitTestTransport(t, nil, 429) + req, _ := http.NewRequest("POST", "https://"+settings.Hub+"/req", strings.NewReader(`{"req":"test"}`)) + rsp, err := settings.doAuthenticated(http.DefaultClient, req, settings.Hub) + if err != nil { + t.Fatal(err) + } + defer rsp.Body.Close() + body, _ := io.ReadAll(rsp.Body) + if rsp.StatusCode != 429 || *calls != 1+rateLimitRetries || len(*sleeps) != rateLimitRetries || string(body) != `{"err":"status 429"}` { + t.Fatalf("status=%d calls=%d sleeps=%d body=%q", rsp.StatusCode, *calls, len(*sleeps), body) + } + if last := (*sleeps)[len(*sleeps)-1]; last > rateLimitMaxDelay { + t.Fatalf("waited %s, longer than %s", last, rateLimitMaxDelay) + } +} + +// A body that can't be read again isn't sent again +func TestRateLimitedRequestUnreplayableBody(t *testing.T) { + settings := refreshTestConfig(t, time.Now().Add(time.Hour)) + sleeps := rateLimitTestSleeps(t) + calls, _ := rateLimitTestTransport(t, nil, 429, 200) + req, _ := http.NewRequest("POST", "https://"+settings.Hub+"/req", struct{ io.Reader }{strings.NewReader(`{"req":"test"}`)}) + if req.GetBody != nil { + t.Fatal("the test needs a body that can't be read again") + } + rsp, err := settings.doAuthenticated(http.DefaultClient, req, settings.Hub) + if err != nil { + t.Fatal(err) + } + defer rsp.Body.Close() + if rsp.StatusCode != 429 || *calls != 1 || len(*sleeps) != 0 { + t.Fatalf("status=%d calls=%d sleeps=%v", rsp.StatusCode, *calls, *sleeps) + } +} + +// Rate limiting and credential renewal work together: a retried request that is then +// refused as unauthorized is renewed and sent once more, with its body +func TestRateLimitedThenUnauthorizedRequest(t *testing.T) { + settings := refreshTestConfig(t, time.Now().Add(time.Hour)) + rateLimitTestSleeps(t) + calls, bodies := rateLimitTestTransport(t, nil, 429, 401, 200) + req, _ := http.NewRequest("POST", "https://"+settings.Hub+"/req", strings.NewReader(`{"req":"test"}`)) + rsp, err := settings.doAuthenticated(http.DefaultClient, req, settings.Hub) + if err != nil { + t.Fatal(err) + } + rsp.Body.Close() + if rsp.StatusCode != 200 || *calls != 3 || len(*bodies) != 3 { + t.Fatalf("status=%d calls=%d bodies=%v", rsp.StatusCode, *calls, *bodies) + } + for i, body := range *bodies { + if body != `{"req":"test"}` { + t.Errorf("request %d sent body %q", i+1, body) + } + } +} + +// Each wait is reported when something is listening +func TestRateLimitedRequestNotifies(t *testing.T) { + settings := refreshTestConfig(t, time.Now().Add(time.Hour)) + sleeps := rateLimitTestSleeps(t) + rateLimitTestTransport(t, http.Header{"Retry-After": {"2"}}, 429, 429, 200) + original := ConfigRateLimitNotify + t.Cleanup(func() { ConfigRateLimitNotify = original }) + var told []string + ConfigRateLimitNotify = func(wait time.Duration, retry int, retries int) { + told = append(told, wait.String()+" "+strconv.Itoa(retry)+"/"+strconv.Itoa(retries)) + } + req, _ := http.NewRequest("GET", "https://"+settings.Hub+"/v1/projects", nil) + rsp, err := settings.doAuthenticated(http.DefaultClient, req, settings.Hub) + if err != nil { + t.Fatal(err) + } + rsp.Body.Close() + want := []string{"2s 1/" + strconv.Itoa(rateLimitRetries), "2s 2/" + strconv.Itoa(rateLimitRetries)} + if len(*sleeps) != 2 || strings.Join(told, ",") != strings.Join(want, ",") { + t.Fatalf("told=%v sleeps=%v", told, *sleeps) + } +} + +// A cancelled request stops waiting +func TestRateLimitedRequestCancelled(t *testing.T) { + settings := refreshTestConfig(t, time.Now().Add(time.Hour)) + calls, _ := rateLimitTestTransport(t, nil, 429, 200) + ctx, cancel := context.WithCancel(context.Background()) + cancel() + req, _ := http.NewRequestWithContext(ctx, "GET", "https://"+settings.Hub+"/v1/projects", nil) + rsp, err := settings.doAuthenticated(http.DefaultClient, req, settings.Hub) + if rsp != nil { + rsp.Body.Close() + } + if !errors.Is(err, context.Canceled) || *calls != 1 { + t.Fatalf("calls=%d err=%v", *calls, err) + } +} + +// The waits are read from Retry-After as the HTTP spec writes it, and otherwise grow +func TestRateLimitWait(t *testing.T) { + now := time.Now() + for _, test := range []struct { + value string + wait time.Duration + given bool + }{ + {"", 0, false}, + {"soon", 0, false}, + {"0", 0, true}, + {"-1", -time.Second, true}, + {"7", 7 * time.Second, true}, + {" 7 ", 7 * time.Second, true}, + {now.Add(90 * time.Second).UTC().Format(http.TimeFormat), 90 * time.Second, true}, + } { + wait, given := retryAfter(http.Header{"Retry-After": {test.value}}, now) + if given != test.given || (given && (wait < test.wait-time.Second || wait > test.wait)) { + t.Errorf("Retry-After %q: wait=%s given=%v", test.value, wait, given) + } + } + for retry := 1; retry <= rateLimitRetries+5; retry++ { + wait, willing := rateLimitWait(http.Header{}, retry) + full := min(rateLimitFirstDelay<<(retry-1), rateLimitMaxDelay) + if !willing || wait < full/2 || wait > full { + t.Errorf("retry %d: wait=%s willing=%v, expected between %s and %s", retry, wait, willing, full/2, full) + } + } + if _, willing := rateLimitWait(http.Header{"Retry-After": {"61"}}, 1); willing { + t.Error("willing to wait longer than the most allowed") + } + if wait, willing := rateLimitWait(http.Header{"Retry-After": {"60"}}, 1); !willing || wait != 60*time.Second { + t.Errorf("the most allowed: wait=%s willing=%v", wait, willing) + } + for _, test := range []struct { + limit, period, reset string + share time.Duration + given bool + }{ + {"7", "1m0s", "48.5s", time.Minute / 7, true}, + {"1000", "1m0s", "", 60 * time.Millisecond, true}, + {"", "", "48.5s", 48500 * time.Millisecond, true}, + {"7", "", "48.5s", 48500 * time.Millisecond, true}, + {"many", "1m0s", "soon", 0, false}, + {"0", "1m0s", "", 0, false}, + {"7", "0s", "", 0, false}, + {"7", "-1m0s", "-5s", 0, false}, + {"", "", "", 0, false}, + } { + header := headerOf("X-RateLimit-Limit", test.limit, "X-RateLimit-Period", test.period, "X-RateLimit-Reset", test.reset) + if share, given := rateLimitShare(header); given != test.given || share != test.share { + t.Errorf("X-RateLimit %q/%q/%q: share=%s given=%v", test.limit, test.period, test.reset, share, given) + } + } +} + +// headerOf builds a header from key and value pairs as a response's arrives, with the keys +// in canonical form: the hub's spellings, such as X-RateLimit-Limit, aren't, and a map +// literal written with them isn't found by Get +func headerOf(pairs ...string) http.Header { + header := http.Header{} + for i := 0; i+1 < len(pairs); i += 2 { + header.Set(pairs[i], pairs[i+1]) + } + return header +} diff --git a/notehub/api.go b/notehub/api.go index 04a1fb2..3a70bb7 100644 --- a/notehub/api.go +++ b/notehub/api.go @@ -559,7 +559,8 @@ func apiWrite(out io.Writer, rsp *apiResponse) { } // apiFailure is the error for a response whose status says the request failed, with the -// reason the hub gave in its JSON body, if any +// reason the hub gave in its JSON body, if any. A 429 that is still being answered after +// the shared request path's retries has no body, so its headers explain the limit. func apiFailure(rsp *apiResponse) error { if rsp.StatusCode < 400 { return nil @@ -574,6 +575,11 @@ func apiFailure(rsp *apiResponse) error { } } } + if reason == "" && rsp.StatusCode == http.StatusTooManyRequests { + if detail := rateLimitDetail(rsp.Header); detail != "" { + reason = ": " + detail + } + } return fmt.Errorf("HTTP %s%s", rsp.Status, reason) } diff --git a/notehub/api_test.go b/notehub/api_test.go index 850d3bc..8c99d9b 100644 --- a/notehub/api_test.go +++ b/notehub/api_test.go @@ -401,7 +401,7 @@ func TestApiPaginateStops(t *testing.T) { }{ {name: "empty terminal page", bodies: []string{`{"events":[],"next_cursor":"0","has_more":false}`}}, {name: "cursor cycle", bodies: []string{`{"next_cursor":"1.2","has_more":true}`, `{"next_cursor":"1.3","has_more":true}`, `{"next_cursor":"1.2","has_more":true}`}, want: "repeated a modification cursor"}, - {name: "HTTP error on next page", bodies: []string{`{"next_cursor":"1.2","has_more":true}`, `{"err":"rate limit"}`}, status: http.StatusTooManyRequests, want: "HTTP 429 Too Many Requests: rate limit"}, + {name: "HTTP error on next page", bodies: []string{`{"next_cursor":"1.2","has_more":true}`, `{"err":"not yours"}`}, status: http.StatusForbidden, want: "HTTP 403 Forbidden: not yours"}, } { t.Run(test.name, func(t *testing.T) { apiTestReset(t) @@ -430,6 +430,54 @@ func TestApiPaginateStops(t *testing.T) { } } +// A request the hub rate-limits is quietly sent again, so the user sees the answer that +// follows and never the 429. The hub's refusal has no body, only X-RateLimit headers, +// which say how long one request's share of the allowance takes to come back: here, with +// a short period, a few milliseconds, so the real wait is made. +func TestApiRetriesRateLimiting(t *testing.T) { + apiTestReset(t) + calls := 0 + newApiTestServer(t, func(w http.ResponseWriter, r *http.Request) { + calls++ + if calls <= 2 { + w.Header().Set("X-RateLimit-Limit", "7") + w.Header().Set("X-RateLimit-Period", "70ms") + w.Header().Set("X-RateLimit-Reset", "60ms") + w.Header().Set("X-RateLimit-Remaining", "0") + w.WriteHeader(http.StatusTooManyRequests) + return + } + io.WriteString(w, `{"projects":[]}`) + }) + out, err := apiTestRun(t, []string{"/v1/projects"}, "") + if err != nil || calls != 3 || out != `{"projects":[]}`+"\n" { + t.Fatalf("calls=%d out=%q err=%v", calls, out, err) + } +} + +// A hub that keeps refusing after every retry is reported with what its headers say about +// the limit, since the refusal itself has no body; a reason in a body is kept over that +func TestApiRateLimitExhausted(t *testing.T) { + apiTestReset(t) + calls := 0 + newApiTestServer(t, func(w http.ResponseWriter, r *http.Request) { + calls++ + w.Header().Set("X-RateLimit-Limit", "7") + w.Header().Set("X-RateLimit-Period", "70ms") + w.Header().Set("X-RateLimit-Reset", "60ms") + w.WriteHeader(http.StatusTooManyRequests) + }) + out, err := apiTestRun(t, []string{"/v1/projects"}, "") + want := "HTTP 429 Too Many Requests: the hub allows 7 requests every 70ms for your account, whole again in under a second" + if err == nil || err.Error() != want || calls != 7 || out != "" { + t.Fatalf("calls=%d out=%q err=%v", calls, out, err) + } + withBody := &apiResponse{Status: "429 Too Many Requests", StatusCode: 429, Header: headerOf("X-RateLimit-Limit", "7", "X-RateLimit-Period", "1m0s"), Body: []byte(`{"err":"slow down"}`)} + if err := apiFailure(withBody); err == nil || err.Error() != "HTTP 429 Too Many Requests: slow down" { + t.Fatalf("with a body: err=%v", err) + } +} + func TestApiPaginateRejectsConflictingRequests(t *testing.T) { apiTestReset(t) flagApiPaginate = true diff --git a/notehub/main.go b/notehub/main.go index 43ef773..7cc258c 100644 --- a/notehub/main.go +++ b/notehub/main.go @@ -75,6 +75,14 @@ func main() { fail(err) } + // Check verbosity when reporting: modes also parse switches after positional + // arguments, so --verbose may still change after this callback is installed. + lib.ConfigRateLimitNotify = func(wait time.Duration, retry int, retries int) { + if flagVerbose { + fmt.Fprintf(os.Stderr, "the hub is limiting requests: waiting %s, then retry %d of %d\n", wait.Round(100*time.Millisecond), retry, retries) + } + } + // Run the mode, unless the login command has already reported what went wrong if err = mode.Run(config); err != nil { if agentSignIn && errors.Is(err, errAgentReported) { diff --git a/notehub/main_test.go b/notehub/main_test.go new file mode 100644 index 0000000..e89f287 --- /dev/null +++ b/notehub/main_test.go @@ -0,0 +1,86 @@ +// Copyright 2026 Blues Inc. All rights reserved. +// Use of this source code is governed by licenses granted by the copyright holder. + +package main + +import ( + "bytes" + "context" + "flag" + "io" + "net/http" + "os" + "os/exec" + "slices" + "strings" + "testing" + "time" + + "github.com/blues/note-cli/lib" +) + +// Run main in a subprocess because it exits. The transport stays local while the +// real startup, argument parsing, retry handling, and diagnostic output are exercised. +func TestMainRateLimitLogging(t *testing.T) { + if os.Getenv("NOTEHUB_TEST_RATE_LIMIT_MAIN") == "1" { + separator := slices.Index(os.Args, "--") + if separator < 0 { + t.Fatal("missing CLI arguments") + } + os.Args = append([]string{cliName}, os.Args[separator+1:]...) + flag.CommandLine = flag.NewFlagSet(cliName, flag.ContinueOnError) + calls := 0 + http.DefaultTransport = authStatusTransport(func(req *http.Request) (*http.Response, error) { + calls++ + if calls == 1 { + return &http.Response{ + StatusCode: http.StatusTooManyRequests, Status: "429 Too Many Requests", + Header: headerOf("X-RateLimit-Limit", "1", "X-RateLimit-Period", "1ms"), Body: http.NoBody, + }, nil + } + return &http.Response{ + StatusCode: http.StatusOK, Status: "200 OK", Header: http.Header{}, + Body: io.NopCloser(strings.NewReader(`{"projects":[]}`)), + }, nil + }) + main() + return + } + for _, test := range []struct { + name string + args []string + verbose bool + }{ + {"before path", []string{"api", "--verbose", "GET", "/v1/projects"}, true}, + {"after path", []string{"api", "GET", "/v1/projects", "--verbose"}, true}, + {"disabled after path", []string{"api", "--verbose", "GET", "/v1/projects", "--verbose=false"}, false}, + {"quiet by default", []string{"api", "GET", "/v1/projects"}, false}, + } { + t.Run(test.name, func(t *testing.T) { + ctx, cancel := context.WithTimeout(t.Context(), 10*time.Second) + defer cancel() + args := append([]string{"-test.run=^TestMainRateLimitLogging$", "--"}, test.args...) + cmd := exec.CommandContext(ctx, os.Args[0], args...) + dir := t.TempDir() + cmd.Env = append(os.Environ(), "NOTEHUB_TEST_RATE_LIMIT_MAIN=1", "XDG_CONFIG_HOME="+dir, "APPDATA="+dir, lib.ConfigTokenEnvVar+"=api_key_test") + var stdout, stderr bytes.Buffer + cmd.Stdout, cmd.Stderr = &stdout, &stderr + if err := cmd.Run(); err != nil { + t.Fatalf("CLI failed: %v\n%s", err, &stderr) + } + if stdout.String() != "{\"projects\":[]}\n" { + t.Fatalf("stdout=%q", &stdout) + } + wantMessages := 0 + if test.verbose { + wantMessages = 1 + } + if got := strings.Count(stderr.String(), "then retry 1 of 6"); got != wantMessages { + t.Fatalf("verbose=%v, retry messages=%d, stderr=%q", test.verbose, got, &stderr) + } + if !test.verbose && stderr.Len() != 0 { + t.Fatalf("unexpected diagnostics: %q", &stderr) + } + }) + } +} diff --git a/notehub/req.go b/notehub/req.go index 295a406..998b6c9 100644 --- a/notehub/req.go +++ b/notehub/req.go @@ -11,7 +11,9 @@ import ( "net/http" "net/url" "os" + "strconv" "strings" + "time" "github.com/blues/note-cli/lib" "github.com/blues/note-go/note" @@ -52,9 +54,60 @@ func hubTransactionRequest(request notehub.HubRequest, verbose bool) (rsp notehu return } -// All Notehub data requests use the shared OAuth request handling. +// All Notehub data requests use the shared OAuth request handling, which also waits out +// the hub's rate limiting and sends again before a 429 is ever seen here. var authenticatedDo = lib.ConfigDoAuthenticated +// rateLimitedError is the error for a 429 the hub kept answering after every retry, saying +// what the refusal's headers say about the limit +func rateLimitedError(hub string, header http.Header) error { + if detail := rateLimitDetail(header); detail != "" { + return fmt.Errorf("%s is limiting requests: %s", hub, detail) + } + return fmt.Errorf("%s is limiting requests right now - wait a minute and try again", hub) +} + +// rateLimitDetail says what the X-RateLimit headers of the hub's refusal say about the +// limit it applies, as "the hub allows 7 requests a minute for your account, whole again +// in 49s", or "" when the refusal says nothing readable. The hub writes the durations +// as Go does, such as 1m0s. +func rateLimitDetail(header http.Header) string { + allows := "" + limit, limitErr := strconv.Atoi(strings.TrimSpace(header.Get("X-RateLimit-Limit"))) + period, periodErr := time.ParseDuration(strings.TrimSpace(header.Get("X-RateLimit-Period"))) + if limitErr == nil && periodErr == nil && limit > 0 && period > 0 { + allows = fmt.Sprintf("the hub allows %d requests %s for your account", limit, rateLimitPeriodText(period)) + } + reset, resetErr := time.ParseDuration(strings.TrimSpace(header.Get("X-RateLimit-Reset"))) + if resetErr != nil || reset <= 0 { + return allows + } + when := reset.Round(time.Second).String() + if reset < time.Second { + when = "under a second" + } + if allows == "" { + return "the hub's allowance for your account is whole again in " + when + } + return allows + ", whole again in " + when +} + +// rateLimitPeriodText is a period as "a minute", "every 5 minutes", "an hour", and so on +func rateLimitPeriodText(period time.Duration) string { + for _, unit := range []struct { + length time.Duration + one, many string + }{{time.Hour, "an hour", "hours"}, {time.Minute, "a minute", "minutes"}, {time.Second, "a second", "seconds"}} { + if period%unit.length == 0 { + if n := period / unit.length; n == 1 { + return unit.one + } + return fmt.Sprintf("every %d %s", period/unit.length, unit.many) + } + } + return "every " + period.String() +} + // Process a V0 HTTPS request and unmarshal into an object func reqHubV0(verbose bool, hub string, request []byte, requestFile string, filetype string, filetags string, filenotes string, overwrite bool, dropNonJSON bool, outq chan string, object interface{}) (err error) { var response []byte @@ -140,6 +193,9 @@ func reqHubV0JSON(verbose bool, hub string, request []byte, requestFile string, if httpRsp.StatusCode == http.StatusUnauthorized { return nil, authUnauthorizedError(hub) } + if httpRsp.StatusCode == http.StatusTooManyRequests { + return nil, rateLimitedError(hub, httpRsp.Header) + } // Note that we must do this with no timeout specified on // the httpClient, else monitor mode would time out. @@ -248,6 +304,10 @@ func reqHubV1JSON(verbose bool, hub string, verb string, url string, body []byte err = authUnauthorizedError(hub) return } + if httpRsp.StatusCode == http.StatusTooManyRequests { + err = rateLimitedError(hub, httpRsp.Header) + return + } if verbose { fmt.Printf("STATUS %d\n", httpRsp.StatusCode) diff --git a/notehub/req_test.go b/notehub/req_test.go index b94b6cb..a6a8685 100644 --- a/notehub/req_test.go +++ b/notehub/req_test.go @@ -59,3 +59,81 @@ func TestRequestPathsUseSharedAuthentication(t *testing.T) { }) } } + +// The shared request path waits out rate limiting and sends again, so a 429 reaches the +// legacy paths only once the retries have run out, and is then explained from the headers +// the hub puts on its bodiless refusal rather than read as an answer +func TestLegacyRequestsExplainRateLimiting(t *testing.T) { + apiTestReset(t) + original := authenticatedDo + t.Cleanup(func() { authenticatedDo = original }) + header := headerOf("X-RateLimit-Limit", "7", "X-RateLimit-Period", "1m0s", "X-RateLimit-Reset", "48.2s", "X-RateLimit-Remaining", "0") + authenticatedDo = func(client *http.Client, req *http.Request) (*http.Response, error) { + return &http.Response{StatusCode: http.StatusTooManyRequests, Status: "429 Too Many Requests", Header: header.Clone(), Body: http.NoBody}, nil + } + for _, tc := range []struct { + name string + run func() error + }{ + {"legacy V0", func() error { + _, err := reqHubV0JSON(false, "api.notefile.net", []byte(`{"req":"hub.app.get"}`), "", "", "", "", false, false, nil) + return err + }}, + {"legacy V1", func() error { + var rsp map[string]any + return reqHubV1(false, "api.notefile.net", "GET", "/v1/projects", nil, &rsp) + }}, + } { + t.Run(tc.name, func(t *testing.T) { + err := tc.run() + want := "api.notefile.net is limiting requests: the hub allows 7 requests a minute for your account, whole again in 48s" + if err == nil || err.Error() != want { + t.Fatalf("err=%v", err) + } + }) + } + authenticatedDo = func(client *http.Client, req *http.Request) (*http.Response, error) { + return &http.Response{StatusCode: http.StatusTooManyRequests, Status: "429 Too Many Requests", Header: http.Header{}, Body: http.NoBody}, nil + } + if _, err := reqHubV1JSON(false, "api.notefile.net", "GET", "/v1/projects", nil); err == nil || !strings.Contains(err.Error(), "api.notefile.net is limiting requests right now") { + t.Fatalf("without headers: err=%v", err) + } +} + +// The hub's refusal headers are read into words, in every form the hub might write them +func TestRateLimitDetail(t *testing.T) { + for _, test := range []struct { + limit, period, reset string + want string + }{ + {"7", "1m0s", "48.2s", "the hub allows 7 requests a minute for your account, whole again in 48s"}, + {"7", "1m0s", "48.5s", "the hub allows 7 requests a minute for your account, whole again in 49s"}, + {"7", "1m0s", "", "the hub allows 7 requests a minute for your account"}, + {"", "", "48.2s", "the hub's allowance for your account is whole again in 48s"}, + {"7", "1m0s", "300ms", "the hub allows 7 requests a minute for your account, whole again in under a second"}, + {"100", "5m0s", "", "the hub allows 100 requests every 5 minutes for your account"}, + {"1000", "1h0m0s", "", "the hub allows 1000 requests an hour for your account"}, + {"10", "1s", "", "the hub allows 10 requests a second for your account"}, + {"10", "30s", "", "the hub allows 10 requests every 30 seconds for your account"}, + {"10", "1m30s", "", "the hub allows 10 requests every 90 seconds for your account"}, + {"10", "1.5s", "", "the hub allows 10 requests every 1.5s for your account"}, + {"many", "1m0s", "soon", ""}, + {"", "", "", ""}, + } { + header := headerOf("X-RateLimit-Limit", test.limit, "X-RateLimit-Period", test.period, "X-RateLimit-Reset", test.reset) + if got := rateLimitDetail(header); got != test.want { + t.Errorf("X-RateLimit %q/%q/%q: %q, want %q", test.limit, test.period, test.reset, got, test.want) + } + } +} + +// headerOf builds a header from key and value pairs as a response's arrives, with the keys +// in canonical form: the hub's spellings, such as X-RateLimit-Limit, aren't, and a map +// literal written with them isn't found by Get +func headerOf(pairs ...string) http.Header { + header := http.Header{} + for i := 0; i+1 < len(pairs); i += 2 { + header.Set(pairs[i], pairs[i+1]) + } + return header +} From 68ecd95b6d19080f70a10585c3a5bb59e857709f Mon Sep 17 00:00:00 2001 From: Ray Ozzie Date: Tue, 3 Nov 2026 16:50:32 -0500 Subject: [PATCH 2/2] Simplify rate-limit retries to Retry-After with one-second fallback --- README.md | 11 ++-- lib/config-retry.go | 75 +++------------------------ lib/config-retry_test.go | 107 +++++++++------------------------------ notehub/api_test.go | 10 ++-- notehub/main_test.go | 2 +- 5 files changed, 40 insertions(+), 165 deletions(-) diff --git a/README.md b/README.md index 35679fa..15937bc 100644 --- a/README.md +++ b/README.md @@ -198,12 +198,11 @@ The response body goes to stdout and diagnostics to stderr. JSON responses need successful responses may be empty. Check the exit code before treating a request as successful. After an uncertain write result, inspect the resource before retrying. -Rate limiting is handled for you. The hub allows a number of API requests a minute for -each billing account, and when it answers `429 Too Many Requests`, every command waits -for one request's share of that allowance to come back, as the hub's `X-RateLimit` -headers describe it, or as long as a `Retry-After` header asks, and sends the request -again, up to six times within a one-minute retry budget. If the next wait would exceed -that budget, or all retries are refused, the final 429 reaches you with any limit details +Rate limiting is handled for you. When the hub answers `429 Too Many Requests`, every +command waits as long as `Retry-After` asks before sending the request again. A missing, +invalid, zero, or past `Retry-After` falls back to a one-second wait. Requests are retried +up to six times within a one-minute retry budget. If the next wait would exceed that +budget, or all retries are refused, the final 429 reaches you with any limit details from the hub. `--include` adds the HTTP status and headers. `--pretty` formats JSON but buffers the diff --git a/lib/config-retry.go b/lib/config-retry.go index e7b8680..e45ddcd 100644 --- a/lib/config-retry.go +++ b/lib/config-retry.go @@ -1,23 +1,15 @@ // Copyright 2026 Blues Inc. All rights reserved. // Use of this source code is governed by licenses granted by the copyright holder. -// The hub answers 429 Too Many Requests when an account sends too much too fast: its -// API allows a number of requests a minute for each billing account, and the refusal -// says so in X-RateLimit-Limit and X-RateLimit-Period, with X-RateLimit-Reset saying -// how long until the whole allowance is back. That isn't handed to the user straight -// away. The request is held back and sent again: for as long as a Retry-After header -// asks when the hub gives one, or else for one request's share of the allowance to come -// back, or when the hub says neither for a delay that doubles each time, in each case -// with some randomness so that clients limited together don't all return together. Only -// when the hub keeps refusing for a minute or so, or asks for a longer wait than that, -// does the 429 reach the caller. +// When the hub answers 429 Too Many Requests, wait as long as Retry-After asks, +// or one second if it gives no usable positive delay, and send the request again. +// Retries are bounded by a count and a time budget; the final refusal reaches the caller. package lib import ( "context" "io" - "math/rand/v2" "net/http" "strconv" "strings" @@ -27,12 +19,6 @@ import ( const ( // rateLimitRetries is how many times a rate-limited request is sent again rateLimitRetries = 6 - // rateLimitFirstDelay is the first wait when the hub doesn't say how long; each wait - // after it is twice the one before, up to rateLimitMaxDelay - rateLimitFirstDelay = time.Second - // rateLimitMaxDelay is the longest wait before one retry, whether the hub asked for - // it or not: a hub asking for longer isn't retried, and its answer is returned - rateLimitMaxDelay = 60 * time.Second // rateLimitRetryBudget includes requests and waits; no retry is scheduled beyond it. // Requests already in progress and successful streaming responses are not cut short. rateLimitRetryBudget = time.Minute @@ -65,9 +51,12 @@ func doRetryingRateLimited(req *http.Request, send func(*http.Request) (*http.Re if err != nil || rsp.StatusCode != http.StatusTooManyRequests || retry > rateLimitRetries { return rsp, err } - wait, willing := rateLimitWait(rsp.Header, retry) + wait, _ := retryAfter(rsp.Header, time.Now()) + if wait <= 0 { + wait = time.Second + } // Preserve the refusal rather than shortening a delay the hub requires. - if !willing || wait > rateLimitRetryBudget-time.Since(started) { + if wait > rateLimitRetryBudget-time.Since(started) { return rsp, nil } again, replayable := requestAgain(req) @@ -91,34 +80,6 @@ func doRetryingRateLimited(req *http.Request, send func(*http.Request) (*http.Re } } -// rateLimitWait is how long to wait before the given retry, the first being 1: what a -// Retry-After header asks; or else one request's share of the allowance the hub's -// X-RateLimit headers describe, and up to a quarter again in case others are waiting for -// it too; or when the hub says neither an increasing delay with some randomness. A wait -// longer than rateLimitMaxDelay isn't made. -func rateLimitWait(header http.Header, retry int) (wait time.Duration, willing bool) { - if asked, given := retryAfter(header, time.Now()); given { - if asked > rateLimitMaxDelay { - return 0, false - } - if asked > 0 { - return asked, true - } - } - if share, given := rateLimitShare(header); given { - if share > rateLimitMaxDelay { - return 0, false - } - return min(share+rand.N(share/4+1), rateLimitMaxDelay), true - } - delay := rateLimitFirstDelay << (retry - 1) - if delay > rateLimitMaxDelay || delay <= 0 { - delay = rateLimitMaxDelay - } - // Somewhere between half the delay and the whole of it - return delay/2 + rand.N(delay/2), true -} - // retryAfter reads a Retry-After header, which gives a number of seconds or an HTTP date, // as a wait from now; a header that is missing or can't be read gives none func retryAfter(header http.Header, now time.Time) (wait time.Duration, given bool) { @@ -135,26 +96,6 @@ func retryAfter(header http.Header, now time.Time) (wait time.Duration, given bo return 0, false } -// rateLimitShare is how long one request's share of the hub's allowance takes to come -// back, from the X-RateLimit-Limit and X-RateLimit-Period headers of a refusal: the hub -// admits that many requests in that period, so one more is admitted that fraction of the -// period after the last was. Without those, X-RateLimit-Reset, how long until the whole -// allowance is back, is a wait that surely suffices. The hub writes the durations as Go -// does, such as 1m0s. -func rateLimitShare(header http.Header) (share time.Duration, given bool) { - limit, limitErr := strconv.Atoi(strings.TrimSpace(header.Get("X-RateLimit-Limit"))) - period, periodErr := time.ParseDuration(strings.TrimSpace(header.Get("X-RateLimit-Period"))) - if limitErr == nil && periodErr == nil && limit > 0 && period > 0 { - if share = period / time.Duration(limit); share > 0 { - return share, true - } - } - if reset, err := time.ParseDuration(strings.TrimSpace(header.Get("X-RateLimit-Reset"))); err == nil && reset > 0 { - return reset, true - } - return 0, false -} - // requestAgain is the request to send again: the same request with its body, which the // first sending consumed, read afresh. That can be done when the body is empty or the // request knows how to read it again, as http.NewRequest arranges for a request built diff --git a/lib/config-retry_test.go b/lib/config-retry_test.go index c8e4531..bc7ce1f 100644 --- a/lib/config-retry_test.go +++ b/lib/config-retry_test.go @@ -56,8 +56,8 @@ func rateLimitTestTransport(t *testing.T, header http.Header, statuses ...int) ( return calls, bodies } -// A rate-limited request is sent again with the same body, after waits that double -// each time, until the hub accepts it; the body of the refusal is never seen +// A rate-limited request is sent again with the same body, after one-second waits +// when Retry-After is absent, until the hub accepts it; the refusal body is never seen func TestRateLimitedRequestIsRetried(t *testing.T) { settings := refreshTestConfig(t, time.Now().Add(time.Hour)) sleeps := rateLimitTestSleeps(t) @@ -80,9 +80,8 @@ func TestRateLimitedRequestIsRetried(t *testing.T) { t.Fatalf("sleeps=%v", *sleeps) } for i, wait := range *sleeps { - full := rateLimitFirstDelay << i - if wait < full/2 || wait > full { - t.Errorf("wait %d was %s, not between %s and %s", i+1, wait, full/2, full) + if wait != time.Second { + t.Errorf("wait %d was %s, want 1s", i+1, wait) } } } @@ -103,13 +102,9 @@ func TestRateLimitedRequestWithoutBodyIsRetried(t *testing.T) { } } -// The hub's headers say how long to wait: a Retry-After exactly, or one request's share -// of the allowance that X-RateLimit-Limit and X-RateLimit-Period describe, with up to a -// quarter again, or the X-RateLimit-Reset until the whole allowance is back; and the delay -// when the hub says nothing readable +// Only Retry-After controls the wait; without a usable positive delay, wait one second. func TestRateLimitedRequestHonorsHeaders(t *testing.T) { - hubHeaders := headerOf("X-RateLimit-Limit", "7", "X-RateLimit-Period", "1m0s", "X-RateLimit-Reset", "48.571428571s", "X-RateLimit-Remaining", "0") - share := time.Minute / 7 + hubHeaders := headerOf("X-RateLimit-Limit", "1", "X-RateLimit-Period", "2m0s", "X-RateLimit-Reset", "5m0s", "X-RateLimit-Remaining", "0") for _, test := range []struct { name string header func() http.Header @@ -120,14 +115,16 @@ func TestRateLimitedRequestHonorsHeaders(t *testing.T) { {"Retry-After date", func() http.Header { return http.Header{"Retry-After": {time.Now().Add(5 * time.Second).UTC().Format(http.TimeFormat)}} }, 3 * time.Second, 5 * time.Second}, - {"Retry-After zero falls back to the delay", func() http.Header { return http.Header{"Retry-After": {"0"}} }, rateLimitFirstDelay / 2, rateLimitFirstDelay}, - {"Retry-After unreadable falls back to the delay", func() http.Header { return http.Header{"Retry-After": {"soon"}} }, rateLimitFirstDelay / 2, rateLimitFirstDelay}, - {"the hub's X-RateLimit headers", func() http.Header { return hubHeaders.Clone() }, share, share + share/4}, - {"X-RateLimit-Reset alone", func() http.Header { return headerOf("X-RateLimit-Reset", "12.5s") }, 12500 * time.Millisecond, 12500*time.Millisecond + 12500*time.Millisecond/4}, + {"Retry-After missing", func() http.Header { return nil }, time.Second, time.Second}, + {"Retry-After zero", func() http.Header { return http.Header{"Retry-After": {"0"}} }, time.Second, time.Second}, + {"Retry-After negative", func() http.Header { return http.Header{"Retry-After": {"-1"}} }, time.Second, time.Second}, + {"Retry-After unreadable", func() http.Header { return http.Header{"Retry-After": {"soon"}} }, time.Second, time.Second}, + {"Retry-After past date", func() http.Header { + return http.Header{"Retry-After": {time.Now().Add(-time.Minute).UTC().Format(http.TimeFormat)}} + }, time.Second, time.Second}, + {"X-RateLimit ignored", func() http.Header { return hubHeaders.Clone() }, time.Second, time.Second}, {"Retry-After over X-RateLimit", func() http.Header { h := hubHeaders.Clone(); h.Set("Retry-After", "3"); return h }, 3 * time.Second, 3 * time.Second}, - {"unreadable X-RateLimit falls back to the delay", func() http.Header { - return headerOf("X-RateLimit-Limit", "many", "X-RateLimit-Period", "a while", "X-RateLimit-Reset", "soon") - }, rateLimitFirstDelay / 2, rateLimitFirstDelay}, + {"Retry-After zero ignores X-RateLimit", func() http.Header { h := hubHeaders.Clone(); h.Set("Retry-After", "0"); return h }, time.Second, time.Second}, } { t.Run(test.name, func(t *testing.T) { settings := refreshTestConfig(t, time.Now().Add(time.Hour)) @@ -149,34 +146,6 @@ func TestRateLimitedRequestHonorsHeaders(t *testing.T) { } } -// A hub that asks for a longer wait than the CLI is willing to make isn't retried, and -// its answer is returned for the caller to explain -func TestRateLimitedRequestWaitTooLong(t *testing.T) { - for _, test := range []struct { - name string - header http.Header - }{ - {"Retry-After", http.Header{"Retry-After": {"600"}}}, - {"X-RateLimit-Reset", headerOf("X-RateLimit-Reset", "5m0s")}, - {"X-RateLimit share", headerOf("X-RateLimit-Limit", "1", "X-RateLimit-Period", "2m0s")}, - } { - t.Run(test.name, func(t *testing.T) { - settings := refreshTestConfig(t, time.Now().Add(time.Hour)) - sleeps := rateLimitTestSleeps(t) - calls, _ := rateLimitTestTransport(t, test.header, 429, 200) - req, _ := http.NewRequest("GET", "https://"+settings.Hub+"/v1/projects", nil) - rsp, err := settings.doAuthenticated(http.DefaultClient, req, settings.Hub) - if err != nil { - t.Fatal(err) - } - defer rsp.Body.Close() - if rsp.StatusCode != 429 || *calls != 1 || len(*sleeps) != 0 { - t.Fatalf("status=%d calls=%d sleeps=%v", rsp.StatusCode, *calls, *sleeps) - } - }) - } -} - // The retry budget includes time spent sending requests and waiting. A delay that // won't fit is never shortened, and the final refusal is left intact for the caller. func TestRateLimitedRequestRetryBudget(t *testing.T) { @@ -189,11 +158,12 @@ func TestRateLimitedRequestRetryBudget(t *testing.T) { wantElapsed time.Duration wantWait time.Duration }{ + {"wait exceeds budget", headerOf("Retry-After", "600"), 0, 429, 1, 0, 0}, {"repeated minute waits", headerOf("Retry-After", "60"), 0, 429, 2, time.Minute, time.Minute}, {"do not shorten Retry-After", headerOf("Retry-After", "40"), 0, 429, 2, 40 * time.Second, 40 * time.Second}, {"request time counts", headerOf("Retry-After", "25"), 10 * time.Second, 429, 2, 45 * time.Second, 25 * time.Second}, {"request exhausts budget", headerOf("Retry-After", "1"), time.Minute, 429, 1, time.Minute, 0}, - {"X-RateLimit waits", headerOf("X-RateLimit-Limit", "1", "X-RateLimit-Period", "1m"), 0, 429, 2, time.Minute, time.Minute}, + {"fallback exceeds remaining budget", nil, time.Minute - 500*time.Millisecond, 429, 1, time.Minute - 500*time.Millisecond, 0}, {"successful retry", headerOf("Retry-After", "10"), time.Second, 200, 2, 12 * time.Second, 10 * time.Second}, } { t.Run(test.name, func(t *testing.T) { @@ -254,8 +224,10 @@ func TestRateLimitedRequestGivesUp(t *testing.T) { if rsp.StatusCode != 429 || *calls != 1+rateLimitRetries || len(*sleeps) != rateLimitRetries || string(body) != `{"err":"status 429"}` { t.Fatalf("status=%d calls=%d sleeps=%d body=%q", rsp.StatusCode, *calls, len(*sleeps), body) } - if last := (*sleeps)[len(*sleeps)-1]; last > rateLimitMaxDelay { - t.Fatalf("waited %s, longer than %s", last, rateLimitMaxDelay) + for _, wait := range *sleeps { + if wait != time.Second { + t.Fatalf("waited %s, want 1s", wait) + } } } @@ -339,8 +311,8 @@ func TestRateLimitedRequestCancelled(t *testing.T) { } } -// The waits are read from Retry-After as the HTTP spec writes it, and otherwise grow -func TestRateLimitWait(t *testing.T) { +// Retry-After accepts either seconds or an HTTP date. +func TestRetryAfter(t *testing.T) { now := time.Now() for _, test := range []struct { value string @@ -360,39 +332,6 @@ func TestRateLimitWait(t *testing.T) { t.Errorf("Retry-After %q: wait=%s given=%v", test.value, wait, given) } } - for retry := 1; retry <= rateLimitRetries+5; retry++ { - wait, willing := rateLimitWait(http.Header{}, retry) - full := min(rateLimitFirstDelay<<(retry-1), rateLimitMaxDelay) - if !willing || wait < full/2 || wait > full { - t.Errorf("retry %d: wait=%s willing=%v, expected between %s and %s", retry, wait, willing, full/2, full) - } - } - if _, willing := rateLimitWait(http.Header{"Retry-After": {"61"}}, 1); willing { - t.Error("willing to wait longer than the most allowed") - } - if wait, willing := rateLimitWait(http.Header{"Retry-After": {"60"}}, 1); !willing || wait != 60*time.Second { - t.Errorf("the most allowed: wait=%s willing=%v", wait, willing) - } - for _, test := range []struct { - limit, period, reset string - share time.Duration - given bool - }{ - {"7", "1m0s", "48.5s", time.Minute / 7, true}, - {"1000", "1m0s", "", 60 * time.Millisecond, true}, - {"", "", "48.5s", 48500 * time.Millisecond, true}, - {"7", "", "48.5s", 48500 * time.Millisecond, true}, - {"many", "1m0s", "soon", 0, false}, - {"0", "1m0s", "", 0, false}, - {"7", "0s", "", 0, false}, - {"7", "-1m0s", "-5s", 0, false}, - {"", "", "", 0, false}, - } { - header := headerOf("X-RateLimit-Limit", test.limit, "X-RateLimit-Period", test.period, "X-RateLimit-Reset", test.reset) - if share, given := rateLimitShare(header); given != test.given || share != test.share { - t.Errorf("X-RateLimit %q/%q/%q: share=%s given=%v", test.limit, test.period, test.reset, share, given) - } - } } // headerOf builds a header from key and value pairs as a response's arrives, with the keys diff --git a/notehub/api_test.go b/notehub/api_test.go index 8c99d9b..af2784d 100644 --- a/notehub/api_test.go +++ b/notehub/api_test.go @@ -431,19 +431,15 @@ func TestApiPaginateStops(t *testing.T) { } // A request the hub rate-limits is quietly sent again, so the user sees the answer that -// follows and never the 429. The hub's refusal has no body, only X-RateLimit headers, -// which say how long one request's share of the allowance takes to come back: here, with -// a short period, a few milliseconds, so the real wait is made. +// follows and never the 429. The hub's refusal has no body, only Retry-After, +// and the real wait is made. func TestApiRetriesRateLimiting(t *testing.T) { apiTestReset(t) calls := 0 newApiTestServer(t, func(w http.ResponseWriter, r *http.Request) { calls++ if calls <= 2 { - w.Header().Set("X-RateLimit-Limit", "7") - w.Header().Set("X-RateLimit-Period", "70ms") - w.Header().Set("X-RateLimit-Reset", "60ms") - w.Header().Set("X-RateLimit-Remaining", "0") + w.Header().Set("Retry-After", "1") w.WriteHeader(http.StatusTooManyRequests) return } diff --git a/notehub/main_test.go b/notehub/main_test.go index e89f287..38fdc97 100644 --- a/notehub/main_test.go +++ b/notehub/main_test.go @@ -35,7 +35,7 @@ func TestMainRateLimitLogging(t *testing.T) { if calls == 1 { return &http.Response{ StatusCode: http.StatusTooManyRequests, Status: "429 Too Many Requests", - Header: headerOf("X-RateLimit-Limit", "1", "X-RateLimit-Period", "1ms"), Body: http.NoBody, + Header: http.Header{"Retry-After": {"1"}}, Body: http.NoBody, }, nil } return &http.Response{