diff --git a/README.md b/README.md index 48acc70..15937bc 100644 --- a/README.md +++ b/README.md @@ -198,9 +198,16 @@ 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. 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 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..e45ddcd --- /dev/null +++ b/lib/config-retry.go @@ -0,0 +1,117 @@ +// Copyright 2026 Blues Inc. All rights reserved. +// Use of this source code is governed by licenses granted by the copyright holder. + +// 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" + "net/http" + "strconv" + "strings" + "time" +) + +const ( + // rateLimitRetries is how many times a rate-limited request is sent again + rateLimitRetries = 6 + // 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, _ := retryAfter(rsp.Header, time.Now()) + if wait <= 0 { + wait = time.Second + } + // Preserve the refusal rather than shortening a delay the hub requires. + if 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 + } +} + +// 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 +} + +// 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..bc7ce1f --- /dev/null +++ b/lib/config-retry_test.go @@ -0,0 +1,346 @@ +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 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) + 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 { + if wait != time.Second { + t.Errorf("wait %d was %s, want 1s", i+1, wait) + } + } +} + +// 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) + } +} + +// Only Retry-After controls the wait; without a usable positive delay, wait one second. +func TestRateLimitedRequestHonorsHeaders(t *testing.T) { + 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 + 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 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}, + {"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)) + 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) + } + }) + } +} + +// 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 + }{ + {"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}, + {"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) { + 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) + } + for _, wait := range *sleeps { + if wait != time.Second { + t.Fatalf("waited %s, want 1s", wait) + } + } +} + +// 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) + } +} + +// Retry-After accepts either seconds or an HTTP date. +func TestRetryAfter(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) + } + } +} + +// 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..af2784d 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,50 @@ 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 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("Retry-After", "1") + 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..38fdc97 --- /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: http.Header{"Retry-After": {"1"}}, 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 +}