From b0c8514ed0b0356f8e1fcaad525a469649b5c187 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Wed, 30 Sep 2026 17:22:44 -0700 Subject: [PATCH 01/20] A rate-limited or failing token endpoint is a wait for the connector, not its end managerTokens handed the event feed the CLI's own error type, which the feed's seam does not recognise, so every token renewal failure that was not a transport failure was classed unrecoverable and ended the run: a 429 or a 5xx from the agent token endpoint stopped the connector. A retryable renewal failure that got an HTTP answer now reaches the SDK as a retryable *basecamp.Error, a 429 carrying its Retry-After, so the feed backs off and carries on. The CLI's error stays its cause and is still what is rendered. A refused credential is not retryable and is returned untouched, so it still ends the run as a disconnect. --- internal/auth/revoke.go | 20 ++ internal/commands/connect.go | 26 ++- internal/commands/connect_token_retry_test.go | 203 ++++++++++++++++++ 3 files changed, 248 insertions(+), 1 deletion(-) create mode 100644 internal/commands/connect_token_retry_test.go diff --git a/internal/auth/revoke.go b/internal/auth/revoke.go index 7525ad414..174c02ede 100644 --- a/internal/auth/revoke.go +++ b/internal/auth/revoke.go @@ -232,6 +232,9 @@ func statusFailure(msg string, resp *http.Response) error { e := output.ErrRateLimit(retryAfter) e.Message = msg e.HTTPStatus = resp.StatusCode + if retryAfter > 0 { + e.Cause = retryAfterError(retryAfter) + } return e case http.StatusInsufficientStorage: e := output.ErrAPI(resp.StatusCode, msg) @@ -244,6 +247,23 @@ func statusFailure(msg string, resp *http.Response) error { } } +// retryAfterError is a 429's Retry-After, in seconds, carried as the cause of +// the rate limit statusFailure builds: output.Error has no field for it, and +// a caller that reschedules the work itself needs the number, not the hint. +type retryAfterError int + +func (s retryAfterError) Error() string { return fmt.Sprintf("retry after %d seconds", int(s)) } + +// RetryAfter is the wait, in seconds, a rate-limited answer named, or zero +// when it named none. +func RetryAfter(err error) int { + var s retryAfterError + if errors.As(err, &s) { + return int(s) + } + return 0 +} + // discardGrant revokes a freshly minted credential the login refused to // store (a Verify failure). Without it the grant would stay live and // full-scope with no local record of it. The refusal is the error the diff --git a/internal/commands/connect.go b/internal/commands/connect.go index a094877b2..77ecc935b 100644 --- a/internal/commands/connect.go +++ b/internal/commands/connect.go @@ -1102,7 +1102,31 @@ func asDoctorChecks(in []setup.Check) []Check { type managerTokens struct{ mgr *auth.Manager } func (t *managerTokens) AccessToken(ctx context.Context) (string, error) { - return t.mgr.AccessToken(ctx) + token, err := t.mgr.AccessToken(ctx) + return token, retryableInSDKTerms(err) +} + +// retryableInSDKTerms hands the SDK a token renewal that can be retried — a +// rate limit, the token endpoint's own 5xx — in the SDK's error type. The +// event feed classifies a failure by that type alone and takes anything else +// as unrecoverable, so without it a brief rate limit on the agent's token +// would end the run. The CLI's error stays the cause, so its words are still +// the ones rendered. A failure that got no answer at all already reaches the +// feed as the transport failure it is, and one that cannot be retried — a +// refused credential first among them — is returned as it is. +func retryableInSDKTerms(err error) error { + var cliErr *output.Error + var sdkErr *basecamp.Error + if !errors.As(err, &cliErr) || !cliErr.Retryable || cliErr.HTTPStatus == 0 || errors.As(err, &sdkErr) { + return err + } + e := &basecamp.Error{Code: basecamp.CodeAPI, Message: err.Error(), HTTPStatus: cliErr.HTTPStatus, Retryable: true, Cause: err} + if cliErr.HTTPStatus == http.StatusTooManyRequests { + e.Code = basecamp.CodeRateLimit + // Through the SDK's constructor for its bound on the wait. + e.RetryAfter = basecamp.ErrRateLimit(auth.RetryAfter(err)).RetryAfter + } + return e } // connectSDKClient is the client setup reads through: no request hooks, no diff --git a/internal/commands/connect_token_retry_test.go b/internal/commands/connect_token_retry_test.go new file mode 100644 index 000000000..efad2436a --- /dev/null +++ b/internal/commands/connect_token_retry_test.go @@ -0,0 +1,203 @@ +package commands + +import ( + "errors" + "net/http" + "net/http/httptest" + "sync/atomic" + "testing" + "time" + + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp/eventfeed" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/basecamp/basecamp-cli/internal/auth" + "github.com/basecamp/basecamp-cli/internal/config" + "github.com/basecamp/basecamp-cli/internal/output" +) + +// tokenEndpointFeed is the connector's live feed over an Agent whose token +// has expired, against a server whose token endpoint answers with answer. +// Nothing but the token endpoint is ever reached: every feed request needs +// a token first. It reports how many mints the endpoint saw. +func tokenEndpointFeed(t *testing.T, answer func(http.ResponseWriter)) (*eventfeed.Live, func() int32) { + t.Helper() + t.Setenv("BASECAMP_NO_KEYRING", "1") + t.Setenv("BASECAMP_TOKEN", "") + t.Setenv("XDG_CONFIG_HOME", t.TempDir()) + + var mints atomic.Int32 + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path != "/oauth/tokens" { + t.Errorf("the feed reached %s without a token", r.URL.Path) + w.WriteHeader(http.StatusTeapot) + return + } + mints.Add(1) + answer(w) + })) + t.Cleanup(srv.Close) + + cfg := &config.Config{AccountID: "555", BaseURL: srv.URL, ActiveProfile: "agent", Sources: map[string]string{}} + mgr := auth.NewManager(cfg, srv.Client()) + store := auth.NewStore(config.GlobalConfigDir()) + mgr.SetStore(store) + require.NoError(t, store.Save("profile:agent", &auth.Credentials{ + AccessToken: "bc_at_expired", + OAuthType: "agent", + ClientID: "agent-client", + ClientSecret: "agent-secret", + TokenEndpoint: srv.URL + "/oauth/tokens", + ExpiresAt: time.Now().Add(-time.Minute).Unix(), + })) + + live, err := eventfeed.NewLive(&basecamp.Config{BaseURL: srv.URL}, &managerTokens{mgr: mgr}, "555", eventfeed.AccountLane, connectSDKOptions()...) + require.NoError(t, err) + return live, mints.Load +} + +func answerStatus(status int, header map[string]string, body string) func(http.ResponseWriter) { + return func(w http.ResponseWriter) { + for k, v := range header { + w.Header().Set(k, v) + } + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(status) + _, _ = w.Write([]byte(body)) + } +} + +// A token endpoint that rate-limits the Agent is a wait, not the end of the +// connector: the feed is told to back off for the Retry-After the endpoint +// named, on the mint lane and the poll lane alike. +func TestARateLimitedTokenRenewalThrottlesTheFeed(t *testing.T) { + live, mints := tokenEndpointFeed(t, answerStatus(http.StatusTooManyRequests, map[string]string{"Retry-After": "42"}, `{"error":"slow_down"}`)) + + _, err := live.Minter().MintStreamTicket(t.Context()) + var mintErr *eventfeed.MintError + require.ErrorAs(t, err, &mintErr) + assert.Equal(t, eventfeed.MintThrottled, mintErr.Kind, "%v", err) + assert.Equal(t, 42*time.Second, mintErr.RetryAfter) + + _, err = live.Polls().Poll(t.Context(), eventfeed.Cursor{Since: "now"}, eventfeed.Filters{}) + var pollErr *eventfeed.PollError + require.ErrorAs(t, err, &pollErr) + assert.Equal(t, eventfeed.PollThrottled, pollErr.Kind, "%v", err) + assert.Equal(t, 42*time.Second, pollErr.RetryAfter) + + assert.Equal(t, int32(2), mints()) +} + +// A rate limit that names no wait is still a wait: the feed's own backoff +// governs. +func TestARateLimitWithoutRetryAfterIsTransient(t *testing.T) { + live, _ := tokenEndpointFeed(t, answerStatus(http.StatusTooManyRequests, nil, "")) + + _, err := live.Minter().MintStreamTicket(t.Context()) + var mintErr *eventfeed.MintError + require.ErrorAs(t, err, &mintErr) + assert.Equal(t, eventfeed.MintTransient, mintErr.Kind, "%v", err) +} + +// The token endpoint's own trouble is retryable: the feed reconnects or +// re-polls after its backoff instead of ending the run. +func TestAServerFaultAtTheTokenEndpointIsTransient(t *testing.T) { + for _, status := range []int{http.StatusInternalServerError, http.StatusBadGateway, http.StatusServiceUnavailable} { + live, _ := tokenEndpointFeed(t, answerStatus(status, nil, `{"error":"invalid_client"}`)) + + _, err := live.Minter().MintStreamTicket(t.Context()) + var mintErr *eventfeed.MintError + require.ErrorAs(t, err, &mintErr, status) + assert.Equal(t, eventfeed.MintTransient, mintErr.Kind, "%d: %v", status, err) + + _, err = live.Polls().Poll(t.Context(), eventfeed.Cursor{Since: "now"}, eventfeed.Filters{}) + var pollErr *eventfeed.PollError + require.ErrorAs(t, err, &pollErr, status) + assert.Equal(t, eventfeed.PollTransient, pollErr.Kind, "%d: %v", status, err) + } +} + +// A token endpoint that does not answer at all is a transport failure the +// feed already rides out. +func TestAnUnreachableTokenEndpointIsTransient(t *testing.T) { + live, _ := tokenEndpointFeed(t, func(w http.ResponseWriter) { + hj, ok := w.(http.Hijacker) + require.True(t, ok) + conn, _, err := hj.Hijack() + require.NoError(t, err) + _ = conn.Close() + }) + + _, err := live.Minter().MintStreamTicket(t.Context()) + var mintErr *eventfeed.MintError + require.ErrorAs(t, err, &mintErr) + assert.Equal(t, eventfeed.MintTransient, mintErr.Kind, "%v", err) +} + +// The CLI's own words still reach whoever renders the failure: the SDK +// error the feed classifies wraps them, it does not replace them. +func TestAThrottledRenewalKeepsTheCLIsMessage(t *testing.T) { + live, _ := tokenEndpointFeed(t, answerStatus(http.StatusServiceUnavailable, nil, "")) + + _, err := live.Minter().MintStreamTicket(t.Context()) + e := output.AsError(err) + assert.Equal(t, "minting an agent token: the server answered HTTP 503", e.Message) + assert.True(t, e.Retryable) +} + +// A refusal of the Agent's credential stays the end of the run, and stays +// recognizable as the disconnect it is. +func TestARefusedTokenRenewalStillEndsTheFeed(t *testing.T) { + for name, answer := range map[string]func(http.ResponseWriter){ + "invalid_client": answerStatus(http.StatusBadRequest, nil, `{"error":"invalid_client"}`), + "bare 401": answerStatus(http.StatusUnauthorized, nil, ""), + } { + live, _ := tokenEndpointFeed(t, answer) + + _, err := live.Minter().MintStreamTicket(t.Context()) + var mintErr *eventfeed.MintError + require.ErrorAs(t, err, &mintErr, name) + assert.Equal(t, eventfeed.MintUnrecoverable, mintErr.Kind, "%s: %v", name, err) + assert.True(t, errors.Is(err, auth.ErrAgentCredentialRefused), name) + + _, err = live.Polls().Poll(t.Context(), eventfeed.Cursor{Since: "now"}, eventfeed.Filters{}) + var pollErr *eventfeed.PollError + require.ErrorAs(t, err, &pollErr, name) + assert.Equal(t, eventfeed.PollUnrecoverable, pollErr.Kind, "%s: %v", name, err) + assert.True(t, errors.Is(err, auth.ErrAgentCredentialRefused), name) + } +} + +// A wait too long to represent is bounded, never turned negative. +func TestAnAbsurdRetryAfterIsBounded(t *testing.T) { + live, _ := tokenEndpointFeed(t, answerStatus(http.StatusTooManyRequests, map[string]string{"Retry-After": "99999999999999"}, "")) + + _, err := live.Minter().MintStreamTicket(t.Context()) + var mintErr *eventfeed.MintError + require.ErrorAs(t, err, &mintErr) + assert.Equal(t, eventfeed.MintThrottled, mintErr.Kind, "%v", err) + assert.Positive(t, mintErr.RetryAfter) +} + +// A rate limit that carries no number — a hold the CLI keeps itself, say — +// is still retryable; a failure that is not retryable, got no answer, or is +// already the SDK's, passes through untouched. +func TestOnlyARetryableCLIFailureIsTranslated(t *testing.T) { + var sdkErr *basecamp.Error + held := retryableInSDKTerms(output.ErrRateLimit(30)) + require.ErrorAs(t, held, &sdkErr) + assert.True(t, sdkErr.Retryable) + assert.Equal(t, http.StatusTooManyRequests, sdkErr.HTTPStatus) + + for _, err := range []error{ + nil, + output.ErrNetwork(errors.New("connection reset")), + output.ErrAPI(http.StatusNotFound, "minting an agent token: the server answered HTTP 404"), + &basecamp.Error{Code: basecamp.CodeAPI, HTTPStatus: 503, Retryable: true}, + errors.New("the store could not be read"), + } { + assert.Equal(t, err, retryableInSDKTerms(err)) + } +} From 937d46e7db6e6fc7159d27ffa4ec024ab47175d5 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Wed, 30 Sep 2026 17:34:02 -0700 Subject: [PATCH 02/20] Read a token endpoint's Retry-After in its date form too A 429 whose Retry-After was an HTTP date, or a count too large for an int, carried no wait at all, so the feed retried on its own short backoff instead of the one the endpoint asked for. Both forms are now read, the date rounded up, an oversized count held at the bound. --- internal/auth/retry_after_test.go | 39 +++++++++++++++++++ internal/auth/revoke.go | 23 ++++++++++- internal/commands/connect_token_retry_test.go | 17 +++++++- 3 files changed, 76 insertions(+), 3 deletions(-) create mode 100644 internal/auth/retry_after_test.go diff --git a/internal/auth/retry_after_test.go b/internal/auth/retry_after_test.go new file mode 100644 index 000000000..0bd9c39d2 --- /dev/null +++ b/internal/auth/retry_after_test.go @@ -0,0 +1,39 @@ +package auth + +import ( + "net/http" + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +// A Retry-After is read in both of its forms, a date rounded up to the +// second, and a count too large to hold is held at the bound, never read as +// no wait at all. +func TestRetryAfterReadsBothForms(t *testing.T) { + now := time.Date(2026, 10, 1, 0, 0, 0, 0, time.UTC) + for value, want := range map[string]int{ + "42": 42, + " 42 ": 42, + "0": 0, + "99999999999999999999999": maxRetryAfterSeconds, + now.Add(90 * time.Second).Format(http.TimeFormat): 90, + now.Add(-time.Minute).Format(http.TimeFormat): 0, + "": 0, + "-5": 0, + "soon": 0, + } { + assert.Equal(t, want, retryAfterSeconds(value, now), "%q", value) + } +} + +// The wait a rate limit named travels with it, whichever form it came in. +func TestARateLimitCarriesItsWait(t *testing.T) { + for _, value := range []string{"90", time.Now().Add(90 * time.Second).UTC().Format(http.TimeFormat)} { + err := statusFailure("minting an agent token", &http.Response{StatusCode: http.StatusTooManyRequests, Header: http.Header{"Retry-After": {value}}}) + assert.InDelta(t, 90, RetryAfter(err), 1, value) + } + err := statusFailure("minting an agent token", &http.Response{StatusCode: http.StatusTooManyRequests, Header: http.Header{}}) + assert.Zero(t, RetryAfter(err)) +} diff --git a/internal/auth/revoke.go b/internal/auth/revoke.go index 174c02ede..c53f1b93b 100644 --- a/internal/auth/revoke.go +++ b/internal/auth/revoke.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "io" + "math" "net/http" "net/url" "strconv" @@ -228,7 +229,7 @@ func transportFailure(msg string, cause error) error { func statusFailure(msg string, resp *http.Response) error { switch resp.StatusCode { case http.StatusTooManyRequests: - retryAfter, _ := strconv.Atoi(strings.TrimSpace(resp.Header.Get("Retry-After"))) + retryAfter := retryAfterSeconds(resp.Header.Get("Retry-After"), time.Now()) e := output.ErrRateLimit(retryAfter) e.Message = msg e.HTTPStatus = resp.StatusCode @@ -254,6 +255,26 @@ type retryAfterError int func (s retryAfterError) Error() string { return fmt.Sprintf("retry after %d seconds", int(s)) } +// maxRetryAfterSeconds bounds a Retry-After to what an int holds on every +// platform; the SDK applies its own, tighter bound to whatever it is handed. +const maxRetryAfterSeconds = math.MaxInt32 + +// retryAfterSeconds is the wait a Retry-After header asks for, in either +// RFC 9110 form — a count of seconds or an HTTP date, rounded up — and zero +// when it asks for nothing this can read. A count too large to hold is held +// at the bound rather than read as no wait at all. +func retryAfterSeconds(value string, now time.Time) int { + value = strings.TrimSpace(value) + if seconds, err := strconv.ParseUint(value, 10, 64); err == nil || errors.Is(err, strconv.ErrRange) { + return int(min(seconds, maxRetryAfterSeconds)) + } + when, err := http.ParseTime(value) + if err != nil { + return 0 + } + return int(min(math.Ceil(max(when.Sub(now), 0).Seconds()), maxRetryAfterSeconds)) +} + // RetryAfter is the wait, in seconds, a rate-limited answer named, or zero // when it named none. func RetryAfter(err error) int { diff --git a/internal/commands/connect_token_retry_test.go b/internal/commands/connect_token_retry_test.go index efad2436a..01ba51508 100644 --- a/internal/commands/connect_token_retry_test.go +++ b/internal/commands/connect_token_retry_test.go @@ -19,7 +19,8 @@ import ( ) // tokenEndpointFeed is the connector's live feed over an Agent whose token -// has expired, against a server whose token endpoint answers with answer. +// has expired, against a server whose token endpoint responds through the +// answer callback. // Nothing but the token endpoint is ever reached: every feed request needs // a token first. It reports how many mints the endpoint saw. func tokenEndpointFeed(t *testing.T, answer func(http.ResponseWriter)) (*eventfeed.Live, func() int32) { @@ -90,6 +91,18 @@ func TestARateLimitedTokenRenewalThrottlesTheFeed(t *testing.T) { assert.Equal(t, int32(2), mints()) } +// A wait named as an HTTP date is honored as surely as one named in seconds. +func TestARateLimitUntilADateThrottlesTheFeed(t *testing.T) { + until := time.Now().Add(2 * time.Minute).UTC().Format(http.TimeFormat) + live, _ := tokenEndpointFeed(t, answerStatus(http.StatusTooManyRequests, map[string]string{"Retry-After": until}, "")) + + _, err := live.Minter().MintStreamTicket(t.Context()) + var mintErr *eventfeed.MintError + require.ErrorAs(t, err, &mintErr) + assert.Equal(t, eventfeed.MintThrottled, mintErr.Kind, "%v", err) + assert.InDelta(t, 2*time.Minute, mintErr.RetryAfter, float64(2*time.Second)) +} + // A rate limit that names no wait is still a wait: the feed's own backoff // governs. func TestARateLimitWithoutRetryAfterIsTransient(t *testing.T) { @@ -138,7 +151,7 @@ func TestAnUnreachableTokenEndpointIsTransient(t *testing.T) { // The CLI's own words still reach whoever renders the failure: the SDK // error the feed classifies wraps them, it does not replace them. -func TestAThrottledRenewalKeepsTheCLIsMessage(t *testing.T) { +func TestAFailedRenewalKeepsTheCLIsMessage(t *testing.T) { live, _ := tokenEndpointFeed(t, answerStatus(http.StatusServiceUnavailable, nil, "")) _, err := live.Minter().MintStreamTicket(t.Context()) From af071d02677cb7febf5e2de877a45d33b4e6a5ee Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Wed, 30 Sep 2026 17:40:18 -0700 Subject: [PATCH 03/20] Bound a parsed Retry-After where the conversion happens The bound was applied through min, which a reader of the conversion cannot see; it is now a comparison right before it. --- internal/auth/revoke.go | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/internal/auth/revoke.go b/internal/auth/revoke.go index c53f1b93b..1fb1ac299 100644 --- a/internal/auth/revoke.go +++ b/internal/auth/revoke.go @@ -266,13 +266,23 @@ const maxRetryAfterSeconds = math.MaxInt32 func retryAfterSeconds(value string, now time.Time) int { value = strings.TrimSpace(value) if seconds, err := strconv.ParseUint(value, 10, 64); err == nil || errors.Is(err, strconv.ErrRange) { - return int(min(seconds, maxRetryAfterSeconds)) + if seconds > maxRetryAfterSeconds { + return maxRetryAfterSeconds + } + return int(seconds) } when, err := http.ParseTime(value) if err != nil { return 0 } - return int(min(math.Ceil(max(when.Sub(now), 0).Seconds()), maxRetryAfterSeconds)) + seconds := math.Ceil(when.Sub(now).Seconds()) + switch { + case seconds <= 0: + return 0 + case seconds > maxRetryAfterSeconds: + return maxRetryAfterSeconds + } + return int(seconds) } // RetryAfter is the wait, in seconds, a rate-limited answer named, or zero From a2cd22f024378676b7ec18c9db85f13da825b74e Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Wed, 30 Sep 2026 17:46:46 -0700 Subject: [PATCH 04/20] Fail the unreachable-endpoint test from its handler safely require stops a goroutine it does not own; the handler now asserts and returns. --- internal/commands/connect_token_retry_test.go | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/internal/commands/connect_token_retry_test.go b/internal/commands/connect_token_retry_test.go index 01ba51508..43cabc96e 100644 --- a/internal/commands/connect_token_retry_test.go +++ b/internal/commands/connect_token_retry_test.go @@ -136,10 +136,15 @@ func TestAServerFaultAtTheTokenEndpointIsTransient(t *testing.T) { // feed already rides out. func TestAnUnreachableTokenEndpointIsTransient(t *testing.T) { live, _ := tokenEndpointFeed(t, func(w http.ResponseWriter) { + // The handler runs off the test goroutine, where only assert is safe. hj, ok := w.(http.Hijacker) - require.True(t, ok) + if !assert.True(t, ok) { + return + } conn, _, err := hj.Hijack() - require.NoError(t, err) + if !assert.NoError(t, err) { + return + } _ = conn.Close() }) From 67348a666c31a259fb0bce7e661458ab85a8bfa8 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Wed, 30 Sep 2026 18:07:02 -0700 Subject: [PATCH 05/20] A starting connector waits for its token instead of exiting The connector's first read of who it is needs a token, and a token renewal the endpoint rate-limited, failed with a 5xx, or never answered ended the start. Under systemd every such exit costs a start, and five in 300 seconds leave the unit failed for good: a sixty-second rate limit was enough. The start now gets its token before anything reads Basecamp, and a failure the running feed would wait out is waited out here too: for the Retry-After the endpoint named, or on the feed's backoff, logged once per wait, and tried again. A refused credential still ends the start at once as a disconnect, and a SIGTERM, an interrupt, or a canceled context ends the wait promptly. The feed and the start share one rule for what is retryable. --- internal/commands/connect.go | 29 ++- internal/commands/connect_run.go | 20 +- internal/commands/connect_start_wait.go | 99 ++++++++++ internal/commands/connect_start_wait_test.go | 196 +++++++++++++++++++ 4 files changed, 335 insertions(+), 9 deletions(-) create mode 100644 internal/commands/connect_start_wait.go create mode 100644 internal/commands/connect_start_wait_test.go diff --git a/internal/commands/connect.go b/internal/commands/connect.go index 77ecc935b..38993fcd0 100644 --- a/internal/commands/connect.go +++ b/internal/commands/connect.go @@ -4,12 +4,15 @@ import ( "context" "errors" "fmt" + "net" "net/http" + "net/url" "os" "path/filepath" "runtime" "strconv" "strings" + "time" "unicode" "github.com/spf13/cobra" @@ -1117,18 +1120,38 @@ func (t *managerTokens) AccessToken(ctx context.Context) (string, error) { func retryableInSDKTerms(err error) error { var cliErr *output.Error var sdkErr *basecamp.Error - if !errors.As(err, &cliErr) || !cliErr.Retryable || cliErr.HTTPStatus == 0 || errors.As(err, &sdkErr) { + asked, retryable := tokenRetry(err) + if !retryable || !errors.As(err, &cliErr) || cliErr.HTTPStatus == 0 || errors.As(err, &sdkErr) { return err } e := &basecamp.Error{Code: basecamp.CodeAPI, Message: err.Error(), HTTPStatus: cliErr.HTTPStatus, Retryable: true, Cause: err} if cliErr.HTTPStatus == http.StatusTooManyRequests { e.Code = basecamp.CodeRateLimit - // Through the SDK's constructor for its bound on the wait. - e.RetryAfter = basecamp.ErrRateLimit(auth.RetryAfter(err)).RetryAfter + e.RetryAfter = int(asked / time.Second) } return e } +// tokenRetry is the one rule for a failed token renewal, which the running +// feed (through retryableInSDKTerms) and a starting connector both go by: +// whether it can be retried, and the wait the endpoint named, zero when it +// named none. Retryable is the CLI's own verdict — a rate limit, a 5xx — or a +// request that got no answer at all, which the feed's SDK already rides out +// as a transport failure. The wait is passed through the SDK's constructor +// for its bound. +func tokenRetry(err error) (time.Duration, bool) { + var cliErr *output.Error + var urlErr *url.Error + var netErr net.Error + switch { + case errors.As(err, &cliErr) && cliErr.Retryable: + return time.Duration(basecamp.ErrRateLimit(auth.RetryAfter(err)).RetryAfter) * time.Second, true + case errors.As(err, &urlErr), errors.As(err, &netErr): + return 0, true + } + return 0, false +} + // connectSDKClient is the client setup reads through: no request hooks, no // debug logger and no cache. The hooks and logger print request URLs, and // the feed's URLs carry positions and tickets; -v on setup must not be a way diff --git a/internal/commands/connect_run.go b/internal/commands/connect_run.go index c2743cf32..41ce17cd8 100644 --- a/internal/commands/connect_run.go +++ b/internal/commands/connect_run.go @@ -13,7 +13,6 @@ import ( "strconv" "strings" "sync" - "syscall" "time" "github.com/spf13/cobra" @@ -170,7 +169,19 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { if err != nil { return output.ErrAuth("The stored credential could not be read: " + setup.ErrorText(err)) } + logger := slog.New(slog.NewTextHandler(cmd.ErrOrStderr(), nil)) tokens := &managerTokens{mgr: app.Auth} + // Every read below needs a token first. One the running feed would + // wait for is waited for here too, rather than ending the start. + startSignals, stopStartSignals := connector.NotifyShutdown() + err = awaitConnectToken(ctx, tokens, connectStartWait{Log: func(line string) { logger.Warn(line) }, Signals: startSignals}) + stopStartSignals() + if agentDisconnectedAtStart(kind, err) { + return errAgentDisconnected("", name) + } + if err != nil { + return err + } client := connectSDKClient(app, tokens) accountClient := client.ForAccount(account) me, err := (setup.SDKReader{Client: accountClient}).Me(ctx) @@ -215,7 +226,6 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { } defer func() { _ = ledger.Close() }() - logger := slog.New(slog.NewTextHandler(cmd.ErrOrStderr(), nil)) if f.hold { // Before intake starts: nothing this run admits may dispatch ahead of // the marker. @@ -352,10 +362,8 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { sig := received mu.Unlock() switch { - case sig == os.Interrupt || sig == syscall.SIGINT: - return output.ErrInterrupted("connector interrupted") - case sig == syscall.SIGTERM: - return output.ErrTerminated("connector terminated") + case sig != nil: + return connectStoppedBySignal(sig) case firstErr != nil: var err error refused := func() bool { return confirmAgentRefused(context.WithoutCancel(ctx), app, kind, name) } diff --git a/internal/commands/connect_start_wait.go b/internal/commands/connect_start_wait.go new file mode 100644 index 000000000..680a0814d --- /dev/null +++ b/internal/commands/connect_start_wait.go @@ -0,0 +1,99 @@ +package commands + +import ( + "context" + "fmt" + "math/rand/v2" + "os" + "syscall" + "time" + + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" + + "github.com/basecamp/basecamp-cli/internal/output" +) + +// The feed's own reconnect backoff (EVENT_FEED_BACKOFF_BASE and its cap), +// which a start waits on when the token endpoint names no wait of its own. +const ( + connectStartBackoffBase = time.Second + connectStartBackoffCap = 60 * time.Second +) + +// connectStartWait is how a starting connector waits for its token: where +// it says so, which signals end the wait, and how it sleeps — the default +// a timer that a signal or ctx cuts short. +type connectStartWait struct { + Log func(string) + Signals <-chan os.Signal + Sleep func(ctx context.Context, signals <-chan os.Signal, d time.Duration) error +} + +// awaitConnectToken holds a starting connector until the agent's token can +// be had. A failure the running feed would wait out — a rate limit, the +// token endpoint's own 5xx, no answer at all — is waited out here too, for +// the Retry-After it named or on the feed's backoff, and tried again; it +// never ends the start. A process that is alive and waiting does not use up +// a supervisor's start limit, which a process exiting on every rate limit +// does in seconds. Anything else, a refused credential first among them, +// is returned at once. So is a signal or a canceled ctx, mid-wait. +func awaitConnectToken(ctx context.Context, tokens basecamp.TokenProvider, w connectStartWait) error { + sleep := w.Sleep + if sleep == nil { + sleep = sleepUnlessStopped + } + for attempt := 1; ; attempt++ { + _, err := tokens.AccessToken(ctx) + if err == nil { + return nil + } + if ctx.Err() != nil { + return ctx.Err() + } + asked, ok := tokenRetry(err) + if !ok { + return err + } + wait := asked + if wait <= 0 { + wait = connectStartBackoff(attempt) + } + w.Log(fmt.Sprintf("connector: could not get the agent's token yet (%s); trying again in %s", output.AsError(err).Message, wait.Round(time.Second))) + if err := sleep(ctx, w.Signals, wait); err != nil { + return err + } + } +} + +// connectStartBackoff is the feed's full-jitter draw for the attempt'th +// consecutive failure: uniform in (0, min(base × 2^(attempt−1), cap)]. +func connectStartBackoff(attempt int) time.Duration { + envelope := connectStartBackoffCap + if attempt <= 6 { + envelope = min(connectStartBackoffBase<<(attempt-1), connectStartBackoffCap) + } + return time.Duration(rand.Int64N(int64(envelope))) + 1 //nolint:gosec // jitter spreads retries; nothing depends on it being unpredictable +} + +// sleepUnlessStopped waits d, or less when ctx ends or a shutdown signal +// arrives, and says which stopped it. +func sleepUnlessStopped(ctx context.Context, signals <-chan os.Signal, d time.Duration) error { + timer := time.NewTimer(d) + defer timer.Stop() + select { + case <-timer.C: + return nil + case <-ctx.Done(): + return ctx.Err() + case sig := <-signals: + return connectStoppedBySignal(sig) + } +} + +// connectStoppedBySignal is the error a connector stopped by sig exits with. +func connectStoppedBySignal(sig os.Signal) error { + if sig == syscall.SIGTERM { + return output.ErrTerminated("connector terminated") + } + return output.ErrInterrupted("connector interrupted") +} diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go new file mode 100644 index 000000000..68d35462c --- /dev/null +++ b/internal/commands/connect_start_wait_test.go @@ -0,0 +1,196 @@ +package commands + +import ( + "context" + "errors" + "net/http" + "net/http/httptest" + "os" + "sync" + "syscall" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/basecamp/basecamp-cli/internal/auth" + "github.com/basecamp/basecamp-cli/internal/config" + "github.com/basecamp/basecamp-cli/internal/connector/setup" + "github.com/basecamp/basecamp-cli/internal/output" +) + +const mintedToken = `{"access_token":"bc_at_minted","token_type":"bearer","expires_in":3600}` + +// startingAgent is an Agent whose token has expired, against a token +// endpoint that gives the answers in order, the last one from then on. +func startingAgent(t *testing.T, answers ...func(http.ResponseWriter)) (*managerTokens, func() int) { + t.Helper() + t.Setenv("BASECAMP_NO_KEYRING", "1") + t.Setenv("BASECAMP_TOKEN", "") + t.Setenv("XDG_CONFIG_HOME", t.TempDir()) + + var mu sync.Mutex + mints := 0 + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path != "/oauth/tokens" { + t.Errorf("the start reached %s", r.URL.Path) + w.WriteHeader(http.StatusTeapot) + return + } + mu.Lock() + answer := answers[min(mints, len(answers)-1)] + mints++ + mu.Unlock() + answer(w) + })) + t.Cleanup(srv.Close) + + cfg := &config.Config{AccountID: "555", BaseURL: srv.URL, ActiveProfile: "agent", Sources: map[string]string{}} + mgr := auth.NewManager(cfg, srv.Client()) + store := auth.NewStore(config.GlobalConfigDir()) + mgr.SetStore(store) + require.NoError(t, store.Save("profile:agent", &auth.Credentials{ + AccessToken: "bc_at_expired", + OAuthType: "agent", + ClientID: "agent-client", + ClientSecret: "agent-secret", + TokenEndpoint: srv.URL + "/oauth/tokens", + ExpiresAt: time.Now().Add(-time.Minute).Unix(), + })) + return &managerTokens{mgr: mgr}, func() int { mu.Lock(); defer mu.Unlock(); return mints } +} + +// startWaits records the waits a start takes, and the words it logs for +// each, without spending them. +type startWaits struct { + waits []time.Duration + lines []string +} + +func (w *startWaits) options() connectStartWait { + return connectStartWait{ + Log: func(line string) { w.lines = append(w.lines, line) }, + Sleep: func(_ context.Context, _ <-chan os.Signal, d time.Duration) error { + w.waits = append(w.waits, d) + return nil + }, + } +} + +// A connector started while the token endpoint rate-limits the agent waits +// for as long as it was asked, says so once, and comes up. +func TestAStartWaitsOutARateLimitAndComesUp(t *testing.T) { + tokens, mints := startingAgent(t, + answerStatus(http.StatusTooManyRequests, map[string]string{"Retry-After": "42"}, `{"error":"slow_down"}`), + answerStatus(http.StatusOK, nil, mintedToken)) + var w startWaits + + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options())) + assert.Equal(t, []time.Duration{42 * time.Second}, w.waits) + require.Len(t, w.lines, 1) + assert.Contains(t, w.lines[0], "42s") + assert.Equal(t, 2, mints()) + + token, err := tokens.AccessToken(t.Context()) + require.NoError(t, err) + assert.Equal(t, "bc_at_minted", token, "what the start waited for is the token the run uses") +} + +// The token endpoint's own trouble is waited out on the feed's backoff, +// however many times it repeats. +func TestAStartRidesOutServerFaults(t *testing.T) { + unavailable := answerStatus(http.StatusServiceUnavailable, nil, "") + tokens, mints := startingAgent(t, unavailable, unavailable, unavailable, answerStatus(http.StatusOK, nil, mintedToken)) + var w startWaits + + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options())) + require.Len(t, w.waits, 3) + for _, d := range w.waits { + assert.True(t, d > 0 && d <= time.Minute, "%s is within the feed's backoff", d) + } + assert.Len(t, w.lines, 3) + assert.Equal(t, 4, mints()) +} + +// A token endpoint that does not answer at all is waited out the same way. +func TestAStartRidesOutAnUnreachableTokenEndpoint(t *testing.T) { + dropped := func(w http.ResponseWriter) { + hj, ok := w.(http.Hijacker) + if !assert.True(t, ok) { + return + } + conn, _, err := hj.Hijack() + if !assert.NoError(t, err) { + return + } + _ = conn.Close() + } + tokens, _ := startingAgent(t, dropped, answerStatus(http.StatusOK, nil, mintedToken)) + var w startWaits + + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options())) + assert.Len(t, w.waits, 1) +} + +// A refused credential is not waited on: the start ends at once, as the +// disconnect it is. +func TestAStartEndsAtOnceOnARefusedCredential(t *testing.T) { + for name, answer := range map[string]func(http.ResponseWriter){ + "invalid_client": answerStatus(http.StatusBadRequest, nil, `{"error":"invalid_client"}`), + "invalid_grant": answerStatus(http.StatusBadRequest, nil, `{"error":"invalid_grant"}`), + "bare 401": answerStatus(http.StatusUnauthorized, nil, ""), + "bare 403": answerStatus(http.StatusForbidden, nil, ""), + } { + tokens, mints := startingAgent(t, answer) + var w startWaits + + err := awaitConnectToken(t.Context(), tokens, w.options()) + require.Error(t, err, name) + assert.True(t, errors.Is(err, auth.ErrAgentCredentialRefused), name) + assert.True(t, agentDisconnectedAtStart(setup.KindAgent, err), name) + assert.Empty(t, w.waits, name) + assert.Equal(t, 1, mints(), name) + } +} + +// A connector waiting to start stops promptly when it is told to: canceled, +// or sent SIGTERM or an interrupt, it does not sit out the wait. +func TestAStartStopsPromptlyWhileItWaits(t *testing.T) { + limited := answerStatus(http.StatusTooManyRequests, map[string]string{"Retry-After": "3600"}, "") + + t.Run("canceled", func(t *testing.T) { + tokens, _ := startingAgent(t, limited) + ctx, cancel := context.WithCancel(t.Context()) + time.AfterFunc(50*time.Millisecond, cancel) + start := time.Now() + err := awaitConnectToken(ctx, tokens, connectStartWait{Log: func(string) {}}) + assert.ErrorIs(t, err, context.Canceled) + assert.Less(t, time.Since(start), 5*time.Second) + }) + + for sig, want := range map[os.Signal]string{syscall.SIGTERM: output.CodeTerminated, os.Interrupt: output.CodeInterrupted} { + t.Run(sig.String(), func(t *testing.T) { + tokens, _ := startingAgent(t, limited) + signals := make(chan os.Signal, 1) + time.AfterFunc(50*time.Millisecond, func() { signals <- sig }) + start := time.Now() + err := awaitConnectToken(t.Context(), tokens, connectStartWait{Log: func(string) {}, Signals: signals}) + var e *output.Error + require.ErrorAs(t, err, &e) + assert.Equal(t, want, e.Code) + assert.Less(t, time.Since(start), 5*time.Second) + }) + } +} + +// The start's backoff is the feed's: a full-jitter draw under an envelope +// that doubles from a second and stops at a minute. +func TestTheStartBacksOffAsTheFeedDoes(t *testing.T) { + for attempt, envelope := range map[int]time.Duration{1: time.Second, 2: 2 * time.Second, 6: 32 * time.Second, 7: time.Minute, 1000: time.Minute} { + for range 100 { + d := connectStartBackoff(attempt) + assert.True(t, d > 0 && d <= envelope, "attempt %d drew %s", attempt, d) + } + } +} From d9d97027dabe6a2827ab2cdd4003bc67a5bc4d20 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Wed, 30 Sep 2026 18:35:36 -0700 Subject: [PATCH 06/20] A stop signal ends the start even with a token renewal in flight The start only listened for a signal while it slept, so one that came during a renewal waited out the renewal, and one that came as the renewal succeeded was dropped and the connector started anyway. The signal now cancels the renewal, and one that arrived by the time the renewal succeeded still stops the start. --- internal/commands/connect_run.go | 6 +++ internal/commands/connect_start_wait.go | 52 +++++++++++++++----- internal/commands/connect_start_wait_test.go | 37 +++++++++++++- 3 files changed, 82 insertions(+), 13 deletions(-) diff --git a/internal/commands/connect_run.go b/internal/commands/connect_run.go index 41ce17cd8..15024e620 100644 --- a/internal/commands/connect_run.go +++ b/internal/commands/connect_run.go @@ -176,6 +176,12 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { startSignals, stopStartSignals := connector.NotifyShutdown() err = awaitConnectToken(ctx, tokens, connectStartWait{Log: func(line string) { logger.Warn(line) }, Signals: startSignals}) stopStartSignals() + select { + case sig := <-startSignals: + // Delivered after the wait had finished, before the stop took. + return connectStoppedBySignal(sig) + default: + } if agentDisconnectedAtStart(kind, err) { return errAgentDisconnected("", name) } diff --git a/internal/commands/connect_start_wait.go b/internal/commands/connect_start_wait.go index 680a0814d..7b20408cd 100644 --- a/internal/commands/connect_start_wait.go +++ b/internal/commands/connect_start_wait.go @@ -21,12 +21,12 @@ const ( ) // connectStartWait is how a starting connector waits for its token: where -// it says so, which signals end the wait, and how it sleeps — the default -// a timer that a signal or ctx cuts short. +// it says so, which signals stop it, and how it sleeps — by default a timer +// that ctx cuts short. type connectStartWait struct { Log func(string) Signals <-chan os.Signal - Sleep func(ctx context.Context, signals <-chan os.Signal, d time.Duration) error + Sleep func(ctx context.Context, d time.Duration) error } // awaitConnectToken holds a starting connector until the agent's token can @@ -36,11 +36,42 @@ type connectStartWait struct { // never ends the start. A process that is alive and waiting does not use up // a supervisor's start limit, which a process exiting on every rate limit // does in seconds. Anything else, a refused credential first among them, -// is returned at once. So is a signal or a canceled ctx, mid-wait. -func awaitConnectToken(ctx context.Context, tokens basecamp.TokenProvider, w connectStartWait) error { +// is returned at once. +// +// A shutdown signal stops it whenever it arrives — mid-wait, or with a +// renewal in flight, which it cancels — and one that arrives as a renewal +// succeeds still wins: the connector was told to stop, and does not start. +func awaitConnectToken(parent context.Context, tokens basecamp.TokenProvider, w connectStartWait) error { + ctx, cancel := context.WithCancel(parent) + var stopped error + watched := make(chan struct{}) + go func() { + defer close(watched) + select { + case sig := <-w.Signals: + stopped = connectStoppedBySignal(sig) + cancel() + case <-ctx.Done(): + } + }() + err := awaitToken(ctx, tokens, w) + cancel() + <-watched + if stopped != nil { + return stopped + } + select { + case sig := <-w.Signals: + return connectStoppedBySignal(sig) + default: + return err + } +} + +func awaitToken(ctx context.Context, tokens basecamp.TokenProvider, w connectStartWait) error { sleep := w.Sleep if sleep == nil { - sleep = sleepUnlessStopped + sleep = sleepUnlessCanceled } for attempt := 1; ; attempt++ { _, err := tokens.AccessToken(ctx) @@ -59,7 +90,7 @@ func awaitConnectToken(ctx context.Context, tokens basecamp.TokenProvider, w con wait = connectStartBackoff(attempt) } w.Log(fmt.Sprintf("connector: could not get the agent's token yet (%s); trying again in %s", output.AsError(err).Message, wait.Round(time.Second))) - if err := sleep(ctx, w.Signals, wait); err != nil { + if err := sleep(ctx, wait); err != nil { return err } } @@ -75,9 +106,8 @@ func connectStartBackoff(attempt int) time.Duration { return time.Duration(rand.Int64N(int64(envelope))) + 1 //nolint:gosec // jitter spreads retries; nothing depends on it being unpredictable } -// sleepUnlessStopped waits d, or less when ctx ends or a shutdown signal -// arrives, and says which stopped it. -func sleepUnlessStopped(ctx context.Context, signals <-chan os.Signal, d time.Duration) error { +// sleepUnlessCanceled waits d, or less when ctx ends. +func sleepUnlessCanceled(ctx context.Context, d time.Duration) error { timer := time.NewTimer(d) defer timer.Stop() select { @@ -85,8 +115,6 @@ func sleepUnlessStopped(ctx context.Context, signals <-chan os.Signal, d time.Du return nil case <-ctx.Done(): return ctx.Err() - case sig := <-signals: - return connectStoppedBySignal(sig) } } diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index 68d35462c..9c817cf0f 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -71,7 +71,7 @@ type startWaits struct { func (w *startWaits) options() connectStartWait { return connectStartWait{ Log: func(line string) { w.lines = append(w.lines, line) }, - Sleep: func(_ context.Context, _ <-chan os.Signal, d time.Duration) error { + Sleep: func(_ context.Context, d time.Duration) error { w.waits = append(w.waits, d) return nil }, @@ -184,6 +184,41 @@ func TestAStartStopsPromptlyWhileItWaits(t *testing.T) { } } +// A stop that arrives while a renewal is in flight cancels it; one that +// arrives as the renewal succeeds still stops the start. +func TestAStopDuringARenewalStopsTheStart(t *testing.T) { + t.Run("hung renewal", func(t *testing.T) { + release := make(chan struct{}) + tokens, _ := startingAgent(t, func(w http.ResponseWriter) { + <-release + answerStatus(http.StatusOK, nil, mintedToken)(w) + }) + // After the server's own cleanup is registered, so it runs first: + // the server cannot close while its handler is held. + t.Cleanup(func() { close(release) }) + signals := make(chan os.Signal, 1) + time.AfterFunc(50*time.Millisecond, func() { signals <- syscall.SIGTERM }) + start := time.Now() + err := awaitConnectToken(t.Context(), tokens, connectStartWait{Log: func(string) {}, Signals: signals}) + var e *output.Error + require.ErrorAs(t, err, &e) + assert.Equal(t, output.CodeTerminated, e.Code) + assert.Less(t, time.Since(start), 5*time.Second) + }) + + t.Run("renewal succeeds", func(t *testing.T) { + signals := make(chan os.Signal, 1) + tokens, _ := startingAgent(t, func(w http.ResponseWriter) { + signals <- os.Interrupt + answerStatus(http.StatusOK, nil, mintedToken)(w) + }) + err := awaitConnectToken(t.Context(), tokens, connectStartWait{Log: func(string) {}, Signals: signals}) + var e *output.Error + require.ErrorAs(t, err, &e) + assert.Equal(t, output.CodeInterrupted, e.Code) + }) +} + // The start's backoff is the feed's: a full-jitter draw under an envelope // that doubles from a second and stops at a minute. func TestTheStartBacksOffAsTheFeedDoes(t *testing.T) { From e5976ff62be1702b37bba849e49b938210bbb919 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Wed, 30 Sep 2026 18:44:03 -0700 Subject: [PATCH 07/20] Retry only what a wait can change, and keep the start's error framing A token endpoint the egress policy refuses, or a URL the client cannot send, was treated as a request that got no answer and retried forever; only a transport failure on the way now is. An OAuth refresh's rate limit carries its Retry-After on the SDK error under the CLI's, and that wait is now the one taken. A start that cannot learn who it is again says so in the profile's terms, unless it was stopped or the agent was disconnected. --- internal/commands/connect.go | 41 +++++++++++--- internal/commands/connect_run.go | 29 ++++++---- internal/commands/connect_start_wait_test.go | 57 ++++++++++++++++++++ 3 files changed, 109 insertions(+), 18 deletions(-) diff --git a/internal/commands/connect.go b/internal/commands/connect.go index 38993fcd0..9c58557f7 100644 --- a/internal/commands/connect.go +++ b/internal/commands/connect.go @@ -4,6 +4,7 @@ import ( "context" "errors" "fmt" + "io" "net" "net/http" "net/url" @@ -15,6 +16,7 @@ import ( "time" "unicode" + surfguard "github.com/basecamp/surfguard/go" "github.com/spf13/cobra" "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" @@ -1135,23 +1137,46 @@ func retryableInSDKTerms(err error) error { // tokenRetry is the one rule for a failed token renewal, which the running // feed (through retryableInSDKTerms) and a starting connector both go by: // whether it can be retried, and the wait the endpoint named, zero when it -// named none. Retryable is the CLI's own verdict — a rate limit, a 5xx — or a -// request that got no answer at all, which the feed's SDK already rides out -// as a transport failure. The wait is passed through the SDK's constructor -// for its bound. +// named none. +// +// Retryable is the CLI's own verdict — a rate limit, a 5xx — or a request +// that got no answer: a connection refused, reset or dropped, a name that +// did not resolve, a timeout. A URL the egress policy refused, or one the +// client could not even send, is a verdict on the configuration that no +// wait changes. The wait is the agent mint's own, or that of the SDK error +// an OAuth refresh carries, through the SDK's constructor for its bound. func tokenRetry(err error) (time.Duration, bool) { + if errors.Is(err, surfguard.ErrBlocked) { + return 0, false + } + seconds := auth.RetryAfter(err) + var sdkErr *basecamp.Error + if errors.As(err, &sdkErr) { + seconds = max(seconds, sdkErr.RetryAfter) + } var cliErr *output.Error - var urlErr *url.Error - var netErr net.Error switch { case errors.As(err, &cliErr) && cliErr.Retryable: - return time.Duration(basecamp.ErrRateLimit(auth.RetryAfter(err)).RetryAfter) * time.Second, true - case errors.As(err, &urlErr), errors.As(err, &netErr): + return time.Duration(basecamp.ErrRateLimit(seconds).RetryAfter) * time.Second, true + case gotNoAnswer(err): return 0, true } return 0, false } +// gotNoAnswer reports a request that was sent, or tried to be, and got no +// response: the transport failed on the way, not the URL or the client. +func gotNoAnswer(err error) bool { + var urlErr *url.Error + if !errors.As(err, &urlErr) { + return false + } + var opErr *net.OpError + var dnsErr *net.DNSError + return urlErr.Timeout() || errors.Is(urlErr.Err, io.EOF) || errors.Is(urlErr.Err, io.ErrUnexpectedEOF) || + errors.As(urlErr.Err, &opErr) || errors.As(urlErr.Err, &dnsErr) +} + // connectSDKClient is the client setup reads through: no request hooks, no // debug logger and no cache. The hooks and logger print request URLs, and // the feed's URLs carry positions and tickets; -v on setup must not be a way diff --git a/internal/commands/connect_run.go b/internal/commands/connect_run.go index 15024e620..208e15aa8 100644 --- a/internal/commands/connect_run.go +++ b/internal/commands/connect_run.go @@ -182,22 +182,14 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { return connectStoppedBySignal(sig) default: } - if agentDisconnectedAtStart(kind, err) { - return errAgentDisconnected("", name) - } if err != nil { - return err + return connectStartFailure(kind, name, err) } client := connectSDKClient(app, tokens) accountClient := client.ForAccount(account) me, err := (setup.SDKReader{Client: accountClient}).Me(ctx) - if agentDisconnectedAtStart(kind, err) { - // Disconnected while the connector wasn't running: said the way a - // running connector says it, with no name, since reading it failed. - return errAgentDisconnected("", name) - } if err != nil { - return output.ErrAuth(fmt.Sprintf("Could not read who profile %q is: %s", name, setup.ErrorText(err))) + return connectStartFailure(kind, name, err) } if _, err := checkConnectIdentity(ctx, app, client, kind, creds.OAuthType, me, file.Agent.IdentityID); err != nil { return err @@ -400,6 +392,23 @@ func connectorStoppedBy(err error, agent, profile string, refused func() bool) ( return connector.ConnectionDisconnected, e.Message, e } +// connectStartFailure is what a start that could not learn who it is exits +// with. Stopped by a signal or a canceled context, it says so as it is. +// Disconnected while the connector wasn't running, it is said the way a +// running connector says it, with no name, since reading it failed. +// Anything else is a failure to read who the profile is. +func connectStartFailure(kind, profile string, err error) error { + var e *output.Error + switch { + case errors.Is(err, context.Canceled), errors.Is(err, context.DeadlineExceeded), + errors.As(err, &e) && (e.Code == output.CodeTerminated || e.Code == output.CodeInterrupted): + return err + case agentDisconnectedAtStart(kind, err): + return errAgentDisconnected("", profile) + } + return output.ErrAuth(fmt.Sprintf("Could not read who profile %q is: %s", profile, setup.ErrorText(err))) +} + // agentDisconnectedAtStart reports whether the connector's first read of who // it is failed because Basecamp refused an Agent's credential: a token // renewal it refused, or a token minted before the disconnect that it no diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index 9c817cf0f..d0e184120 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -3,14 +3,20 @@ package commands import ( "context" "errors" + "fmt" + "io" + "net" "net/http" "net/http/httptest" + "net/url" "os" "sync" "syscall" "testing" "time" + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" + surfguard "github.com/basecamp/surfguard/go" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -229,3 +235,54 @@ func TestTheStartBacksOffAsTheFeedDoes(t *testing.T) { } } } + +// What no wait can change is not retried: a URL the egress policy refused, +// or one the client could not send at all. A request that got no answer is. +func TestOnlyATransportFailureWithoutAnAnswerIsRetried(t *testing.T) { + wrap := func(err error) error { + return fmt.Errorf("minting an agent token: %w", &url.Error{Op: "Post", URL: "https://example.test/oauth/tokens", Err: err}) + } + for name, err := range map[string]error{ + "blocked by policy": wrap(&net.OpError{Op: "dial", Net: "tcp", Err: surfguard.ErrBlocked}), + "unsupported scheme": wrap(errors.New("unsupported protocol scheme \"ftp\"")), + } { + _, ok := tokenRetry(err) + assert.False(t, ok, name) + } + for name, err := range map[string]error{ + "refused": wrap(&net.OpError{Op: "dial", Net: "tcp", Err: syscall.ECONNREFUSED}), + "dropped": wrap(io.EOF), + "no name": wrap(&net.DNSError{Err: "no such host", Name: "example.test", IsNotFound: true}), + "cut off": wrap(io.ErrUnexpectedEOF), + } { + _, ok := tokenRetry(err) + assert.True(t, ok, name) + } +} + +// An OAuth refresh carries its rate limit as the SDK's error, under the +// CLI's: the wait it names is the one taken. +func TestARefreshRateLimitKeepsItsWait(t *testing.T) { + refused := &output.Error{Code: output.CodeRateLimit, Message: "token refresh failed: rate limited", HTTPStatus: 429, Retryable: true, + Cause: basecamp.ErrRateLimit(30)} + wait, ok := tokenRetry(refused) + assert.True(t, ok) + assert.Equal(t, 30*time.Second, wait) +} + +// A start that cannot learn who it is says so in the profile's terms, +// unless it was stopped or the agent was disconnected. +func TestAStartFailureKeepsItsFraming(t *testing.T) { + refused := output.ErrAuth("Minting an agent token was refused (invalid_client)") + refused.Cause = auth.ErrAgentCredentialRefused + terminated := output.ErrTerminated("connector terminated") + + assert.Same(t, terminated, connectStartFailure(setup.KindAgent, "agent", terminated)) + assert.ErrorIs(t, connectStartFailure(setup.KindAgent, "agent", context.Canceled), context.Canceled) + assert.Equal(t, errAgentDisconnected("", "agent"), connectStartFailure(setup.KindAgent, "agent", refused)) + + var e *output.Error + require.ErrorAs(t, connectStartFailure(setup.KindAgent, "agent", output.ErrAPI(404, "minting an agent token: the server answered HTTP 404")), &e) + assert.Equal(t, output.CodeAuth, e.Code) + assert.Equal(t, `Could not read who profile "agent" is: minting an agent token: the server answered HTTP 404`, e.Message) +} From 945f2c63dd8c11ca9f4eab6c9f28ef03d7be2e6c Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Wed, 30 Sep 2026 19:00:33 -0700 Subject: [PATCH 08/20] Never log a start's wait as none A full-jitter draw under half a second rounded to 0s, which read as an immediate retry while the connector did wait. --- internal/commands/connect_start_wait.go | 2 +- internal/commands/connect_start_wait_test.go | 3 +++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/internal/commands/connect_start_wait.go b/internal/commands/connect_start_wait.go index 7b20408cd..755cd48f5 100644 --- a/internal/commands/connect_start_wait.go +++ b/internal/commands/connect_start_wait.go @@ -89,7 +89,7 @@ func awaitToken(ctx context.Context, tokens basecamp.TokenProvider, w connectSta if wait <= 0 { wait = connectStartBackoff(attempt) } - w.Log(fmt.Sprintf("connector: could not get the agent's token yet (%s); trying again in %s", output.AsError(err).Message, wait.Round(time.Second))) + w.Log(fmt.Sprintf("connector: could not get the agent's token yet (%s); trying again in %s", output.AsError(err).Message, max(wait.Round(time.Second), time.Second))) if err := sleep(ctx, wait); err != nil { return err } diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index d0e184120..b624cb107 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -116,6 +116,9 @@ func TestAStartRidesOutServerFaults(t *testing.T) { assert.True(t, d > 0 && d <= time.Minute, "%s is within the feed's backoff", d) } assert.Len(t, w.lines, 3) + for _, line := range w.lines { + assert.NotContains(t, line, "in 0s", "a wait is never logged as none") + } assert.Equal(t, 4, mints()) } From d28ac0e2acfbd4d8410bee1ae95552048e61c67f Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Wed, 30 Sep 2026 19:09:08 -0700 Subject: [PATCH 09/20] A second signal ends a start whose renewal will not stop Saving a renewed credential does not stop for a canceled context, so a start could sit through a stop it had been sent. As for a running connector, a second signal now ends the process. --- internal/commands/connect_start_wait.go | 28 ++++++++++++++-- internal/commands/connect_start_wait_test.go | 35 ++++++++++++++++++++ 2 files changed, 60 insertions(+), 3 deletions(-) diff --git a/internal/commands/connect_start_wait.go b/internal/commands/connect_start_wait.go index 755cd48f5..2662d1d49 100644 --- a/internal/commands/connect_start_wait.go +++ b/internal/commands/connect_start_wait.go @@ -10,6 +10,7 @@ import ( "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" + "github.com/basecamp/basecamp-cli/internal/connector" "github.com/basecamp/basecamp-cli/internal/output" ) @@ -27,6 +28,17 @@ type connectStartWait struct { Log func(string) Signals <-chan os.Signal Sleep func(ctx context.Context, d time.Duration) error + // Exit ends the process on a second signal; os.Exit when nil. + Exit func(code int) +} + +func (w connectStartWait) forceStop(sig os.Signal) { + exit := w.Exit + if exit == nil { + exit = os.Exit + } + w.Log("connector: stopping now, before it has started; signal " + sig.String()) + exit(connector.ExitCodeForSignal(sig)) } // awaitConnectToken holds a starting connector until the agent's token can @@ -44,7 +56,7 @@ type connectStartWait struct { func awaitConnectToken(parent context.Context, tokens basecamp.TokenProvider, w connectStartWait) error { ctx, cancel := context.WithCancel(parent) var stopped error - watched := make(chan struct{}) + watched, done := make(chan struct{}), make(chan struct{}) go func() { defer close(watched) select { @@ -52,10 +64,20 @@ func awaitConnectToken(parent context.Context, tokens basecamp.TokenProvider, w stopped = connectStoppedBySignal(sig) cancel() case <-ctx.Done(): + return + } + // Saving a renewed credential does not stop for a canceled + // context. A second signal is someone who has waited long enough, + // and ends the process as it does for a running connector. + select { + case sig := <-w.Signals: + w.forceStop(sig) + case <-done: } }() err := awaitToken(ctx, tokens, w) cancel() + close(done) <-watched if stopped != nil { return stopped @@ -96,8 +118,8 @@ func awaitToken(ctx context.Context, tokens basecamp.TokenProvider, w connectSta } } -// connectStartBackoff is the feed's full-jitter draw for the attempt'th -// consecutive failure: uniform in (0, min(base × 2^(attempt−1), cap)]. +// connectStartBackoff is the feed's full-jitter draw for the nth +// consecutive failure, n being attempt: uniform in (0, min(base × 2^(attempt−1), cap)]. func connectStartBackoff(attempt int) time.Duration { envelope := connectStartBackoffCap if attempt <= 6 { diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index b624cb107..addc14dee 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -22,6 +22,7 @@ import ( "github.com/basecamp/basecamp-cli/internal/auth" "github.com/basecamp/basecamp-cli/internal/config" + "github.com/basecamp/basecamp-cli/internal/connector" "github.com/basecamp/basecamp-cli/internal/connector/setup" "github.com/basecamp/basecamp-cli/internal/output" ) @@ -289,3 +290,37 @@ func TestAStartFailureKeepsItsFraming(t *testing.T) { assert.Equal(t, output.CodeAuth, e.Code) assert.Equal(t, `Could not read who profile "agent" is: minting an agent token: the server answered HTTP 404`, e.Message) } + +// stuckTokens is a renewal that does not stop for its context, as saving a +// renewed credential does not. +type stuckTokens struct{ release chan struct{} } + +func (s stuckTokens) AccessToken(context.Context) (string, error) { + <-s.release + return "bc_at_minted", nil +} + +// A second signal ends a start whose renewal will not stop, as it ends a +// running connector. +func TestASecondSignalForcesAStuckStartToEnd(t *testing.T) { + tokens := stuckTokens{release: make(chan struct{})} + signals := make(chan os.Signal, 2) + exited := make(chan int, 1) + signals <- syscall.SIGTERM + signals <- syscall.SIGTERM + + result := make(chan error, 1) + go func() { + result <- awaitConnectToken(t.Context(), tokens, connectStartWait{Log: func(string) {}, Signals: signals, Exit: func(code int) { exited <- code }}) + }() + select { + case code := <-exited: + assert.Equal(t, connector.ExitCodeForSignal(syscall.SIGTERM), code) + case <-time.After(5 * time.Second): + t.Fatal("a second signal did not end the stuck start") + } + close(tokens.release) + var e *output.Error + require.ErrorAs(t, <-result, &e) + assert.Equal(t, output.CodeTerminated, e.Code) +} From 29f685c38e9ae48ebe1ff931176fcf355cea84df Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Wed, 30 Sep 2026 19:27:02 -0700 Subject: [PATCH 10/20] The feed and the start retry exactly the same token failures A response that arrived is classified by its status even when its body was cut off: a truncated 401 is still a refusal, a truncated 429 or 5xx still retryable, and only a 200 cut short is a network failure. A request that got no response at all - dropped, refused, unresolved, timed out, a TLS handshake or a proxy that failed - is a network failure and is retried, a misconfigured one included. A URL the egress policy refuses, or one the client cannot send, never is. The feed now reads through feedTokens, which hands it every failure already classified by tokenRetry, the rule the start waits by, instead of leaving the unrecognised ones to the SDK's own transport check; the two cannot drift apart. --- internal/auth/agent.go | 10 +- internal/commands/connect.go | 108 ++++++++++------ internal/commands/connect_run.go | 2 +- internal/commands/connect_start_wait_test.go | 116 ++++++++++++++++-- internal/commands/connect_token_retry_test.go | 59 ++++++--- 5 files changed, 232 insertions(+), 63 deletions(-) diff --git a/internal/auth/agent.go b/internal/auth/agent.go index e7dda7ffa..002f69014 100644 --- a/internal/auth/agent.go +++ b/internal/auth/agent.go @@ -358,7 +358,15 @@ func (m *Manager) mintAgentToken(ctx context.Context, mint *agentMint) (*oauth.T return nil, hold, err } if err != nil { - return nil, nil, wrapOAuthError("minting an agent token", err) + // A status that arrived is the verdict even when its body did not + // follow: a 401 is still a refusal, a 5xx still retryable. Only a + // 200 cut short has none — the token never arrived — and it is the + // transport failure it is. + if resp.StatusCode != http.StatusOK { + hold, err := m.agentMintRefusal(resp, nil, mint) + return nil, hold, err + } + return nil, nil, transportFailure("minting an agent token", err) } if int64(len(body)) > maxAgentTokenBytes { return nil, nil, output.ErrAPI(resp.StatusCode, diff --git a/internal/commands/connect.go b/internal/commands/connect.go index 9c58557f7..1d8e7a7dd 100644 --- a/internal/commands/connect.go +++ b/internal/commands/connect.go @@ -4,7 +4,6 @@ import ( "context" "errors" "fmt" - "io" "net" "net/http" "net/url" @@ -1106,47 +1105,80 @@ func asDoctorChecks(in []setup.Check) []Check { // managerTokens is a TokenProvider over an auth manager. type managerTokens struct{ mgr *auth.Manager } +// AccessToken hands a client a renewal failure it can retry in the SDK's +// own error type, so the SDK retries it as it would any 429 or 5xx; every +// other failure is the CLI's own, as it was. func (t *managerTokens) AccessToken(ctx context.Context) (string, error) { token, err := t.mgr.AccessToken(ctx) - return token, retryableInSDKTerms(err) + if e := tokenFailureInSDKTerms(err); e != nil && e.Retryable && e.HTTPStatus != 0 { + return token, e + } + return token, err } -// retryableInSDKTerms hands the SDK a token renewal that can be retried — a -// rate limit, the token endpoint's own 5xx — in the SDK's error type. The -// event feed classifies a failure by that type alone and takes anything else -// as unrecoverable, so without it a brief rate limit on the agent's token -// would end the run. The CLI's error stays the cause, so its words are still -// the ones rendered. A failure that got no answer at all already reaches the -// feed as the transport failure it is, and one that cannot be retried — a -// refused credential first among them — is returned as it is. -func retryableInSDKTerms(err error) error { - var cliErr *output.Error - var sdkErr *basecamp.Error +// feedTokens is the token provider the event feed reads through. The feed +// classifies a failure by the SDK's error type alone, and reads anything it +// does not recognize its own way, so every failure is handed over already +// classified by tokenRetry — the same rule a starting connector waits by, +// so the two cannot drift apart. +type feedTokens struct{ managerTokens } + +func (t *feedTokens) AccessToken(ctx context.Context) (string, error) { + token, err := t.mgr.AccessToken(ctx) + if e := tokenFailureInSDKTerms(err); e != nil { + return token, e + } + return token, err +} + +// tokenFailureInSDKTerms is a failed renewal as the SDK's error, classified +// by tokenRetry, or nil when there was no failure. A retryable one keeps +// its status — a 429 with the wait it named, a 5xx — or, with no status, is +// a network failure; the feed backs off and carries on either way. One that +// cannot be retried carries no status at all, so the feed ends on it rather +// than counting it toward its own authorization threshold; a refused +// credential is still recognizable down the chain as the disconnect it is. +// The CLI's error stays the cause, so its words are still the ones rendered. +func tokenFailureInSDKTerms(err error) *basecamp.Error { + if err == nil { + return nil + } asked, retryable := tokenRetry(err) - if !retryable || !errors.As(err, &cliErr) || cliErr.HTTPStatus == 0 || errors.As(err, &sdkErr) { - return err + e := &basecamp.Error{Code: basecamp.CodeAPI, Message: err.Error(), Retryable: retryable, Cause: err} + if !retryable { + return e + } + var cliErr *output.Error + if errors.As(err, &cliErr) { + e.HTTPStatus = cliErr.HTTPStatus } - e := &basecamp.Error{Code: basecamp.CodeAPI, Message: err.Error(), HTTPStatus: cliErr.HTTPStatus, Retryable: true, Cause: err} - if cliErr.HTTPStatus == http.StatusTooManyRequests { + switch e.HTTPStatus { + case http.StatusTooManyRequests: e.Code = basecamp.CodeRateLimit e.RetryAfter = int(asked / time.Second) + case 0: + e.Code = basecamp.CodeNetwork } return e } // tokenRetry is the one rule for a failed token renewal, which the running -// feed (through retryableInSDKTerms) and a starting connector both go by: -// whether it can be retried, and the wait the endpoint named, zero when it -// named none. +// feed (through feedTokens) and a starting connector both go by: whether it +// can be retried, and the wait the endpoint named, zero when it named none. // -// Retryable is the CLI's own verdict — a rate limit, a 5xx — or a request -// that got no answer: a connection refused, reset or dropped, a name that -// did not resolve, a timeout. A URL the egress policy refused, or one the -// client could not even send, is a verdict on the configuration that no -// wait changes. The wait is the agent mint's own, or that of the SDK error -// an OAuth refresh carries, through the SDK's constructor for its bound. +// A response that arrived is classified by its status, whatever became of +// its body: a 429 or a 5xx can be retried, a refusal cannot — the CLI's own +// verdict says which. A request that got no response — a connection +// refused, reset or dropped, a name that did not resolve, a timeout, a TLS +// handshake or a proxy that failed — is a network failure, and is retried +// too, a misconfigured one included: the process stays alive and says why, +// where exiting would only have a supervisor give up sooner, knowing less. +// Two things are never retried, because no wait changes them: a URL the +// egress policy refused, and one the client could not send at all. The +// wait is the agent mint's own, or that of the SDK error an OAuth refresh +// carries, through the SDK's constructor for its bound. func tokenRetry(err error) (time.Duration, bool) { - if errors.Is(err, surfguard.ErrBlocked) { + if errors.Is(err, surfguard.ErrBlocked) || cannotBeSent(err) { return 0, false } seconds := auth.RetryAfter(err) @@ -1158,23 +1190,29 @@ func tokenRetry(err error) (time.Duration, bool) { switch { case errors.As(err, &cliErr) && cliErr.Retryable: return time.Duration(basecamp.ErrRateLimit(seconds).RetryAfter) * time.Second, true - case gotNoAnswer(err): + case gotNoResponse(err): return 0, true } return 0, false } -// gotNoAnswer reports a request that was sent, or tried to be, and got no -// response: the transport failed on the way, not the URL or the client. -func gotNoAnswer(err error) bool { +// gotNoResponse reports a request that failed on the way, with no response +// to classify. +func gotNoResponse(err error) bool { + var urlErr *url.Error + var netErr net.Error + return errors.As(err, &urlErr) || errors.As(err, &netErr) +} + +// cannotBeSent reports a request whose URL the client cannot send: not an +// absolute http or https URL with a host. It never reached the network. +func cannotBeSent(err error) bool { var urlErr *url.Error if !errors.As(err, &urlErr) { return false } - var opErr *net.OpError - var dnsErr *net.DNSError - return urlErr.Timeout() || errors.Is(urlErr.Err, io.EOF) || errors.Is(urlErr.Err, io.ErrUnexpectedEOF) || - errors.As(urlErr.Err, &opErr) || errors.As(urlErr.Err, &dnsErr) + u, parseErr := url.Parse(urlErr.URL) + return parseErr != nil || (u.Scheme != "http" && u.Scheme != "https") || u.Host == "" } // connectSDKClient is the client setup reads through: no request hooks, no diff --git a/internal/commands/connect_run.go b/internal/commands/connect_run.go index 208e15aa8..1c03c0b27 100644 --- a/internal/commands/connect_run.go +++ b/internal/commands/connect_run.go @@ -245,7 +245,7 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { if err != nil { return err } - live, err := eventfeed.NewLive(&basecamp.Config{BaseURL: app.Config.BaseURL}, tokens, account, eventfeed.AccountLane, connectSDKOptions()...) + live, err := eventfeed.NewLive(&basecamp.Config{BaseURL: app.Config.BaseURL}, &feedTokens{*tokens}, account, eventfeed.AccountLane, connectSDKOptions()...) if err != nil { return err } diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index addc14dee..62d9c5687 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -2,6 +2,8 @@ package commands import ( "context" + "crypto/tls" + "crypto/x509" "errors" "fmt" "io" @@ -241,26 +243,118 @@ func TestTheStartBacksOffAsTheFeedDoes(t *testing.T) { } // What no wait can change is not retried: a URL the egress policy refused, -// or one the client could not send at all. A request that got no answer is. -func TestOnlyATransportFailureWithoutAnAnswerIsRetried(t *testing.T) { - wrap := func(err error) error { - return fmt.Errorf("minting an agent token: %w", &url.Error{Op: "Post", URL: "https://example.test/oauth/tokens", Err: err}) +// or one the client could not send at all. A request that got no response +// is, a misconfigured TLS or proxy included. +func TestOnlyARequestThatGotNoResponseIsRetried(t *testing.T) { + wrap := func(target string, err error) error { + return fmt.Errorf("minting an agent token: %w", &url.Error{Op: "Post", URL: target, Err: err}) } + const endpoint = "https://example.test/oauth/tokens" for name, err := range map[string]error{ - "blocked by policy": wrap(&net.OpError{Op: "dial", Net: "tcp", Err: surfguard.ErrBlocked}), - "unsupported scheme": wrap(errors.New("unsupported protocol scheme \"ftp\"")), + "blocked by policy": wrap(endpoint, &net.OpError{Op: "dial", Net: "tcp", Err: surfguard.ErrBlocked}), + "unsupported scheme": wrap("ftp://example.test/oauth/tokens", errors.New(`unsupported protocol scheme "ftp"`)), + "no host": wrap("https:///oauth/tokens", errors.New("http: no Host in request URL")), } { _, ok := tokenRetry(err) assert.False(t, ok, name) } for name, err := range map[string]error{ - "refused": wrap(&net.OpError{Op: "dial", Net: "tcp", Err: syscall.ECONNREFUSED}), - "dropped": wrap(io.EOF), - "no name": wrap(&net.DNSError{Err: "no such host", Name: "example.test", IsNotFound: true}), - "cut off": wrap(io.ErrUnexpectedEOF), + "refused": wrap(endpoint, &net.OpError{Op: "dial", Net: "tcp", Err: syscall.ECONNREFUSED}), + "dropped": wrap(endpoint, io.EOF), + "no name": wrap(endpoint, &net.DNSError{Err: "no such host", Name: "example.test", IsNotFound: true}), + "cut off": wrap(endpoint, io.ErrUnexpectedEOF), + "untrusted TLS": wrap(endpoint, &tls.CertificateVerificationError{Err: x509.UnknownAuthorityError{}}), + "proxy": wrap(endpoint, &net.OpError{Op: "proxyconnect", Net: "tcp", Err: syscall.ECONNREFUSED}), } { - _, ok := tokenRetry(err) + wait, ok := tokenRetry(err) assert.True(t, ok, name) + assert.Zero(t, wait, name) + } +} + +// A token endpoint whose certificate is not trusted got no response to +// classify, and the start keeps waiting — saying why each time — rather +// than exiting. +func TestAStartKeepsWaitingOnAnUntrustedCertificate(t *testing.T) { + t.Setenv("BASECAMP_NO_KEYRING", "1") + t.Setenv("BASECAMP_TOKEN", "") + t.Setenv("XDG_CONFIG_HOME", t.TempDir()) + srv := httptest.NewTLSServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + t.Error("a request got through an untrusted certificate") + })) + t.Cleanup(srv.Close) + + cfg := &config.Config{AccountID: "555", BaseURL: srv.URL, ActiveProfile: "agent", Sources: map[string]string{}} + mgr := auth.NewManager(cfg, &http.Client{}) + store := auth.NewStore(config.GlobalConfigDir()) + mgr.SetStore(store) + require.NoError(t, store.Save("profile:agent", &auth.Credentials{ + AccessToken: "bc_at_expired", OAuthType: "agent", ClientID: "agent-client", ClientSecret: "agent-secret", + TokenEndpoint: srv.URL + "/oauth/tokens", ExpiresAt: time.Now().Add(-time.Minute).Unix(), + })) + + ctx, cancel := context.WithCancel(t.Context()) + var lines []string + waits := 0 + err := awaitConnectToken(ctx, &managerTokens{mgr: mgr}, connectStartWait{ + Log: func(line string) { lines = append(lines, line) }, + Sleep: func(context.Context, time.Duration) error { + if waits++; waits == 2 { + cancel() + } + return nil + }, + }) + assert.ErrorIs(t, err, context.Canceled) + assert.Equal(t, 2, waits) + require.NotEmpty(t, lines) + assert.Contains(t, lines[0], "certificate") +} + +// truncatedAnswer sends status and headers promising more body than it +// sends, then drops the connection. +func truncatedAnswer(t *testing.T, status int) func(http.ResponseWriter) { + return func(w http.ResponseWriter) { + w.Header().Set("Content-Type", "application/json") + w.Header().Set("Content-Length", "500") + w.WriteHeader(status) + _, _ = w.Write([]byte(`{"error":`)) + hj, ok := w.(http.Hijacker) + if !assert.True(t, ok) { + return + } + conn, _, err := hj.Hijack() + if !assert.NoError(t, err) { + return + } + _ = conn.Close() + } +} + +// A response classifies by its status even when its body is cut off: a +// truncated 401 is still a refusal, and ends the start as a disconnect. +func TestATruncatedRefusalStillEndsTheStart(t *testing.T) { + tokens, mints := startingAgent(t, truncatedAnswer(t, http.StatusUnauthorized)) + var w startWaits + + err := awaitConnectToken(t.Context(), tokens, w.options()) + require.Error(t, err) + assert.ErrorIs(t, err, auth.ErrAgentCredentialRefused) + assert.Equal(t, errAgentDisconnected("", "agent"), connectStartFailure(setup.KindAgent, "agent", err)) + assert.Empty(t, w.waits) + assert.Equal(t, 1, mints()) +} + +// A truncated 503 is still the server's own trouble, and is waited out; a +// truncated 200 never delivered its token, and is waited out too. +func TestATruncatedServerFaultIsWaitedOut(t *testing.T) { + for _, status := range []int{http.StatusServiceUnavailable, http.StatusOK} { + tokens, mints := startingAgent(t, truncatedAnswer(t, status), answerStatus(http.StatusOK, nil, mintedToken)) + var w startWaits + + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options()), status) + assert.Len(t, w.waits, 1, status) + assert.Equal(t, 2, mints(), status) } } diff --git a/internal/commands/connect_token_retry_test.go b/internal/commands/connect_token_retry_test.go index 43cabc96e..db1680d16 100644 --- a/internal/commands/connect_token_retry_test.go +++ b/internal/commands/connect_token_retry_test.go @@ -2,8 +2,11 @@ package commands import ( "errors" + "fmt" + "io" "net/http" "net/http/httptest" + "net/url" "sync/atomic" "testing" "time" @@ -54,7 +57,7 @@ func tokenEndpointFeed(t *testing.T, answer func(http.ResponseWriter)) (*eventfe ExpiresAt: time.Now().Add(-time.Minute).Unix(), })) - live, err := eventfeed.NewLive(&basecamp.Config{BaseURL: srv.URL}, &managerTokens{mgr: mgr}, "555", eventfeed.AccountLane, connectSDKOptions()...) + live, err := eventfeed.NewLive(&basecamp.Config{BaseURL: srv.URL}, &feedTokens{managerTokens{mgr: mgr}}, "555", eventfeed.AccountLane, connectSDKOptions()...) require.NoError(t, err) return live, mints.Load } @@ -199,23 +202,49 @@ func TestAnAbsurdRetryAfterIsBounded(t *testing.T) { assert.Positive(t, mintErr.RetryAfter) } -// A rate limit that carries no number — a hold the CLI keeps itself, say — -// is still retryable; a failure that is not retryable, got no answer, or is -// already the SDK's, passes through untouched. -func TestOnlyARetryableCLIFailureIsTranslated(t *testing.T) { - var sdkErr *basecamp.Error - held := retryableInSDKTerms(output.ErrRateLimit(30)) - require.ErrorAs(t, held, &sdkErr) - assert.True(t, sdkErr.Retryable) - assert.Equal(t, http.StatusTooManyRequests, sdkErr.HTTPStatus) - +// Every failure reaches the feed already classified: a rate limit that +// carries no number — a hold the CLI keeps itself, say — and a request that +// got no response are retryable; anything else carries no status, so the +// feed ends on it rather than counting it as an authorization failure. +func TestTheFeedSeesEveryFailureClassified(t *testing.T) { + assert.Nil(t, tokenFailureInSDKTerms(nil)) + + held := tokenFailureInSDKTerms(output.ErrRateLimit(30)) + assert.True(t, held.Retryable) + assert.Equal(t, http.StatusTooManyRequests, held.HTTPStatus) + + network := tokenFailureInSDKTerms(fmt.Errorf("minting an agent token: %w", &url.Error{Op: "Post", URL: "https://example.test/oauth/tokens", Err: io.EOF})) + assert.True(t, network.Retryable) + assert.Equal(t, basecamp.CodeNetwork, network.Code) + assert.Zero(t, network.HTTPStatus) + + refused := output.ErrAuth("Minting an agent token was refused (HTTP 401)") + refused.HTTPStatus = http.StatusUnauthorized + refused.Cause = auth.ErrAgentCredentialRefused for _, err := range []error{ - nil, - output.ErrNetwork(errors.New("connection reset")), + refused, output.ErrAPI(http.StatusNotFound, "minting an agent token: the server answered HTTP 404"), - &basecamp.Error{Code: basecamp.CodeAPI, HTTPStatus: 503, Retryable: true}, errors.New("the store could not be read"), } { - assert.Equal(t, err, retryableInSDKTerms(err)) + e := tokenFailureInSDKTerms(err) + assert.False(t, e.Retryable, "%v", err) + assert.Zero(t, e.HTTPStatus, "%v", err) + assert.ErrorIs(t, e, err) } } + +// The feed goes by the same rule as the start: a truncated 401 ends it as a +// refusal, a truncated 503 is waited out. +func TestTheFeedClassifiesATruncatedResponseByItsStatus(t *testing.T) { + live, _ := tokenEndpointFeed(t, truncatedAnswer(t, http.StatusUnauthorized)) + _, err := live.Minter().MintStreamTicket(t.Context()) + var mintErr *eventfeed.MintError + require.ErrorAs(t, err, &mintErr) + assert.Equal(t, eventfeed.MintUnrecoverable, mintErr.Kind, "%v", err) + assert.ErrorIs(t, err, auth.ErrAgentCredentialRefused) + + live, _ = tokenEndpointFeed(t, truncatedAnswer(t, http.StatusServiceUnavailable)) + _, err = live.Minter().MintStreamTicket(t.Context()) + require.ErrorAs(t, err, &mintErr) + assert.Equal(t, eventfeed.MintTransient, mintErr.Kind, "%v", err) +} From 720db6e031141584c8affd5882c09b43c22d1c62 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Thu, 1 Oct 2026 02:28:24 -0700 Subject: [PATCH 11/20] A held rate limit carries its wait, read from the hold's deadline The error a stored rate-limit hold answers a mint with, and the one the 429 that set it returns, said how long to wait only in its hint. The feed and a starting connector, which reschedule the mint themselves, fell back to their own backoff and spent attempts the hold answered locally. The wait now travels as the error's cause, read from the stored deadline, so both wait it out exactly. --- internal/auth/agent_hold.go | 12 +++- internal/auth/auth.go | 6 ++ internal/commands/connect_start_wait_test.go | 56 ++++++++++++++++--- internal/commands/connect_token_retry_test.go | 19 ++++--- 4 files changed, 73 insertions(+), 20 deletions(-) diff --git a/internal/auth/agent_hold.go b/internal/auth/agent_hold.go index e24457c3d..3c26275ea 100644 --- a/internal/auth/agent_hold.go +++ b/internal/auth/agent_hold.go @@ -184,10 +184,16 @@ func holdWait(hold *MintHold, now time.Time) int { } // holdRateLimitError is the rate-limit error for a rate_limited hold, -// whether the 429 that set it or a later mint it held. +// whether the 429 that set it or a later mint it held. It carries the +// hold's wait, read from its deadline, for a caller that reschedules the +// mint itself (RetryAfter): one sent any sooner is answered by the hold. func holdRateLimitError(hold *MintHold, now time.Time, message string) *output.Error { - e := output.ErrRateLimit(holdWait(hold, now)) + wait := holdWait(hold, now) + e := output.ErrRateLimit(wait) e.Message = message + if wait > 0 { + e.Cause = retryAfterError(wait) + } return e } @@ -209,7 +215,7 @@ func (m *Manager) heldMint(creds *Credentials) error { switch hold.Kind { case mintHoldRateLimited: e := holdRateLimitError(hold, now, fmt.Sprintf("Minting an agent token is held until %s: the token endpoint rate-limited the last attempt (%s)", when, hold.Detail)) - e.Cause = errMintHeld + e.Cause = errors.Join(e.Cause, errMintHeld) return e case mintHoldRefused: msg := "Minting an agent token was refused (" + hold.Detail + ")" diff --git a/internal/auth/auth.go b/internal/auth/auth.go index 6967f975f..63d7933c5 100644 --- a/internal/auth/auth.go +++ b/internal/auth/auth.go @@ -1976,3 +1976,9 @@ func (m *Manager) GetStore() *Store { func (m *Manager) SetStore(s *Store) { m.store = s } + +// SetClock sets the time a remembered mint verdict is read and written +// against, for a caller that drives time itself; nil means time.Now. +func (m *Manager) SetClock(clock func() time.Time) { + m.clock = clock +} diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index 62d9c5687..b6dc2cd64 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -31,9 +31,16 @@ import ( const mintedToken = `{"access_token":"bc_at_minted","token_type":"bearer","expires_in":3600}` +// startTokens is a starting agent's tokens over a clock the test drives, +// so a wait spent in a fake sleep is time the mint hold sees pass. +type startTokens struct { + managerTokens + now *time.Time +} + // startingAgent is an Agent whose token has expired, against a token // endpoint that gives the answers in order, the last one from then on. -func startingAgent(t *testing.T, answers ...func(http.ResponseWriter)) (*managerTokens, func() int) { +func startingAgent(t *testing.T, answers ...func(http.ResponseWriter)) (*startTokens, func() int) { t.Helper() t.Setenv("BASECAMP_NO_KEYRING", "1") t.Setenv("BASECAMP_TOKEN", "") @@ -67,7 +74,11 @@ func startingAgent(t *testing.T, answers ...func(http.ResponseWriter)) (*manager TokenEndpoint: srv.URL + "/oauth/tokens", ExpiresAt: time.Now().Add(-time.Minute).Unix(), })) - return &managerTokens{mgr: mgr}, func() int { mu.Lock(); defer mu.Unlock(); return mints } + // On a whole second, as a hold's deadline is stored: a wait read back + // from it is then exactly the one the endpoint named. + now := time.Now().Truncate(time.Second) + mgr.SetClock(func() time.Time { return now }) + return &startTokens{managerTokens: managerTokens{mgr: mgr}, now: &now}, func() int { mu.Lock(); defer mu.Unlock(); return mints } } // startWaits records the waits a start takes, and the words it logs for @@ -77,11 +88,12 @@ type startWaits struct { lines []string } -func (w *startWaits) options() connectStartWait { +func (w *startWaits) options(tokens *startTokens) connectStartWait { return connectStartWait{ Log: func(line string) { w.lines = append(w.lines, line) }, Sleep: func(_ context.Context, d time.Duration) error { w.waits = append(w.waits, d) + *tokens.now = tokens.now.Add(d) return nil }, } @@ -95,7 +107,7 @@ func TestAStartWaitsOutARateLimitAndComesUp(t *testing.T) { answerStatus(http.StatusOK, nil, mintedToken)) var w startWaits - require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options())) + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options(tokens))) assert.Equal(t, []time.Duration{42 * time.Second}, w.waits) require.Len(t, w.lines, 1) assert.Contains(t, w.lines[0], "42s") @@ -113,7 +125,7 @@ func TestAStartRidesOutServerFaults(t *testing.T) { tokens, mints := startingAgent(t, unavailable, unavailable, unavailable, answerStatus(http.StatusOK, nil, mintedToken)) var w startWaits - require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options())) + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options(tokens))) require.Len(t, w.waits, 3) for _, d := range w.waits { assert.True(t, d > 0 && d <= time.Minute, "%s is within the feed's backoff", d) @@ -141,7 +153,7 @@ func TestAStartRidesOutAnUnreachableTokenEndpoint(t *testing.T) { tokens, _ := startingAgent(t, dropped, answerStatus(http.StatusOK, nil, mintedToken)) var w startWaits - require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options())) + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options(tokens))) assert.Len(t, w.waits, 1) } @@ -157,7 +169,7 @@ func TestAStartEndsAtOnceOnARefusedCredential(t *testing.T) { tokens, mints := startingAgent(t, answer) var w startWaits - err := awaitConnectToken(t.Context(), tokens, w.options()) + err := awaitConnectToken(t.Context(), tokens, w.options(tokens)) require.Error(t, err, name) assert.True(t, errors.Is(err, auth.ErrAgentCredentialRefused), name) assert.True(t, agentDisconnectedAtStart(setup.KindAgent, err), name) @@ -337,7 +349,7 @@ func TestATruncatedRefusalStillEndsTheStart(t *testing.T) { tokens, mints := startingAgent(t, truncatedAnswer(t, http.StatusUnauthorized)) var w startWaits - err := awaitConnectToken(t.Context(), tokens, w.options()) + err := awaitConnectToken(t.Context(), tokens, w.options(tokens)) require.Error(t, err) assert.ErrorIs(t, err, auth.ErrAgentCredentialRefused) assert.Equal(t, errAgentDisconnected("", "agent"), connectStartFailure(setup.KindAgent, "agent", err)) @@ -352,7 +364,7 @@ func TestATruncatedServerFaultIsWaitedOut(t *testing.T) { tokens, mints := startingAgent(t, truncatedAnswer(t, status), answerStatus(http.StatusOK, nil, mintedToken)) var w startWaits - require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options()), status) + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options(tokens)), status) assert.Len(t, w.waits, 1, status) assert.Equal(t, 2, mints(), status) } @@ -418,3 +430,29 @@ func TestASecondSignalForcesAStuckStartToEnd(t *testing.T) { require.ErrorAs(t, <-result, &e) assert.Equal(t, output.CodeTerminated, e.Code) } + +// A rate limit the CLI holds itself is waited out to its stored deadline, +// not on backoff: the hold answers locally until then, so any earlier +// attempt is spent for nothing. +func TestAStartWaitsOutAStoredRateLimitHold(t *testing.T) { + tokens, mints := startingAgent(t, answerStatus(http.StatusTooManyRequests, map[string]string{"Retry-After": "90"}, "")) + ctx, cancel := context.WithCancel(t.Context()) + var waits []time.Duration + err := awaitConnectToken(ctx, tokens, connectStartWait{ + Log: func(string) {}, + Sleep: func(_ context.Context, d time.Duration) error { + if waits = append(waits, d); len(waits) == 2 { + cancel() + } + // Short of the deadline: the hold, not the endpoint, answers next. + *tokens.now = tokens.now.Add(d / 2) + return nil + }, + }) + require.ErrorIs(t, err, context.Canceled) + require.Len(t, waits, 2) + assert.InDelta(t, 90*time.Second, waits[0], float64(2*time.Second), "waited %s, not the hold's deadline", waits[0]) + assert.InDelta(t, 45*time.Second, waits[1], float64(2*time.Second), "waited %s, not what is left of the hold", waits[1]) + assert.Equal(t, 1, mints(), "the second attempt was the stored hold's to answer") + +} diff --git a/internal/commands/connect_token_retry_test.go b/internal/commands/connect_token_retry_test.go index db1680d16..a6f5daa9f 100644 --- a/internal/commands/connect_token_retry_test.go +++ b/internal/commands/connect_token_retry_test.go @@ -75,7 +75,9 @@ func answerStatus(status int, header map[string]string, body string) func(http.R // A token endpoint that rate-limits the Agent is a wait, not the end of the // connector: the feed is told to back off for the Retry-After the endpoint -// named, on the mint lane and the poll lane alike. +// named, on the mint lane and the poll lane alike. The second is answered +// by the stored hold, which names what is left of the same wait — the +// deadline, rounded up to the second it is stored in. func TestARateLimitedTokenRenewalThrottlesTheFeed(t *testing.T) { live, mints := tokenEndpointFeed(t, answerStatus(http.StatusTooManyRequests, map[string]string{"Retry-After": "42"}, `{"error":"slow_down"}`)) @@ -83,15 +85,15 @@ func TestARateLimitedTokenRenewalThrottlesTheFeed(t *testing.T) { var mintErr *eventfeed.MintError require.ErrorAs(t, err, &mintErr) assert.Equal(t, eventfeed.MintThrottled, mintErr.Kind, "%v", err) - assert.Equal(t, 42*time.Second, mintErr.RetryAfter) + assert.InDelta(t, 42*time.Second, mintErr.RetryAfter, float64(time.Second)) _, err = live.Polls().Poll(t.Context(), eventfeed.Cursor{Since: "now"}, eventfeed.Filters{}) var pollErr *eventfeed.PollError require.ErrorAs(t, err, &pollErr) assert.Equal(t, eventfeed.PollThrottled, pollErr.Kind, "%v", err) - assert.Equal(t, 42*time.Second, pollErr.RetryAfter) + assert.InDelta(t, 42*time.Second, pollErr.RetryAfter, float64(time.Second)) - assert.Equal(t, int32(2), mints()) + assert.Equal(t, int32(1), mints(), "the poll's renewal was the stored hold's to answer") } // A wait named as an HTTP date is honored as surely as one named in seconds. @@ -106,15 +108,16 @@ func TestARateLimitUntilADateThrottlesTheFeed(t *testing.T) { assert.InDelta(t, 2*time.Minute, mintErr.RetryAfter, float64(2*time.Second)) } -// A rate limit that names no wait is still a wait: the feed's own backoff -// governs. -func TestARateLimitWithoutRetryAfterIsTransient(t *testing.T) { +// A rate limit that names no wait is held for the default, and the feed +// waits that out rather than backing off into the hold. +func TestARateLimitWithoutRetryAfterWaitsOutTheDefaultHold(t *testing.T) { live, _ := tokenEndpointFeed(t, answerStatus(http.StatusTooManyRequests, nil, "")) _, err := live.Minter().MintStreamTicket(t.Context()) var mintErr *eventfeed.MintError require.ErrorAs(t, err, &mintErr) - assert.Equal(t, eventfeed.MintTransient, mintErr.Kind, "%v", err) + assert.Equal(t, eventfeed.MintThrottled, mintErr.Kind, "%v", err) + assert.InDelta(t, time.Minute, mintErr.RetryAfter, float64(time.Second)) } // The token endpoint's own trouble is retryable: the feed reconnects or From 6a8f6d8f8108b3f31a5d6673d2d83c96b3942588 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Thu, 1 Oct 2026 02:28:40 -0700 Subject: [PATCH 12/20] Pin the held rate limit's wait in the hold's own test --- internal/auth/agent_hold_test.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/internal/auth/agent_hold_test.go b/internal/auth/agent_hold_test.go index f7b8fc950..cd9ac4147 100644 --- a/internal/auth/agent_hold_test.go +++ b/internal/auth/agent_hold_test.go @@ -155,6 +155,7 @@ func TestARateLimitIsHeldUntilItsRetryAfter(t *testing.T) { require.Error(t, err) assert.Equal(t, output.CodeRateLimit, output.AsError(err).Code) assert.NotContains(t, output.AsError(err).Message, "invalid_client", "a 429 is not a verdict on the client") + assert.Equal(t, 300, RetryAfter(err), "the wait is read from the hold's deadline") *now = now.Add(299 * time.Second) _, err = m.AccessToken(context.Background()) @@ -167,6 +168,8 @@ func TestARateLimitIsHeldUntilItsRetryAfter(t *testing.T) { assert.Contains(t, held.Message, "the server answered HTTP 429") assert.NotContains(t, held.Message, "invalid_client") assert.Contains(t, held.Hint, "1 seconds") + assert.Equal(t, 1, RetryAfter(err), "a held mint carries what is left of the hold") + assert.ErrorIs(t, err, errMintHeld) assert.NotContains(t, held.Hint, "--with-client-credentials", "a rate limit is not a refused secret") assert.False(t, errors.Is(err, ErrAgentCredentialRefused), "a rate limit is not a disconnect") From c85d2eb7e9e524efeac262cf33c20b18efe0e27e Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Thu, 1 Oct 2026 02:45:03 -0700 Subject: [PATCH 13/20] Classify an unreadable or oversized error response by its status A 5xx whose body was larger than any token response - a proxy's error page - still fell to a final "body exceeds" error and ended the connector. Any non-200 response whose body could not be read, or was too large to, is now classified by its status alone, as a 429's already was. And a start no longer mistakes a request's own timeout for the connector being stopped: only its own context ending, or a signal, is returned as it is. --- internal/auth/agent.go | 18 +++++------ internal/commands/connect_run.go | 11 ++++--- internal/commands/connect_start_wait_test.go | 33 +++++++++++++++++--- 3 files changed, 41 insertions(+), 21 deletions(-) diff --git a/internal/auth/agent.go b/internal/auth/agent.go index 002f69014..2e9c19024 100644 --- a/internal/auth/agent.go +++ b/internal/auth/agent.go @@ -351,21 +351,17 @@ func (m *Manager) mintAgentToken(ctx context.Context, mint *agentMint) (*oauth.T } body, err := io.ReadAll(io.LimitReader(resp.Body, maxAgentTokenBytes+1)) - if resp.StatusCode == http.StatusTooManyRequests && (err != nil || int64(len(body)) > maxAgentTokenBytes) { - // A 429's status and Retry-After are all its hold needs, and a - // body that could not be read must not cost the hold. + if resp.StatusCode != http.StatusOK && (err != nil || int64(len(body)) > maxAgentTokenBytes) { + // A status that arrived is the verdict even when its body could + // not be read, or was too large to: a 401 is still a refusal, a + // 429 still sets its hold from its status and Retry-After, a 5xx + // — a proxy's error page, say — is still retryable. hold, err := m.agentMintRefusal(resp, nil, mint) return nil, hold, err } if err != nil { - // A status that arrived is the verdict even when its body did not - // follow: a 401 is still a refusal, a 5xx still retryable. Only a - // 200 cut short has none — the token never arrived — and it is the - // transport failure it is. - if resp.StatusCode != http.StatusOK { - hold, err := m.agentMintRefusal(resp, nil, mint) - return nil, hold, err - } + // Only a 200 cut short has no verdict — the token never arrived — + // and it is the transport failure it is. return nil, nil, transportFailure("minting an agent token", err) } if int64(len(body)) > maxAgentTokenBytes { diff --git a/internal/commands/connect_run.go b/internal/commands/connect_run.go index 1c03c0b27..adef5451d 100644 --- a/internal/commands/connect_run.go +++ b/internal/commands/connect_run.go @@ -183,13 +183,13 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { default: } if err != nil { - return connectStartFailure(kind, name, err) + return connectStartFailure(ctx, kind, name, err) } client := connectSDKClient(app, tokens) accountClient := client.ForAccount(account) me, err := (setup.SDKReader{Client: accountClient}).Me(ctx) if err != nil { - return connectStartFailure(kind, name, err) + return connectStartFailure(ctx, kind, name, err) } if _, err := checkConnectIdentity(ctx, app, client, kind, creds.OAuthType, me, file.Agent.IdentityID); err != nil { return err @@ -393,14 +393,15 @@ func connectorStoppedBy(err error, agent, profile string, refused func() bool) ( } // connectStartFailure is what a start that could not learn who it is exits -// with. Stopped by a signal or a canceled context, it says so as it is. +// with. Stopped by a signal, or because ctx itself ended, it says so as it +// is; a request's own timeout is not the connector stopping. // Disconnected while the connector wasn't running, it is said the way a // running connector says it, with no name, since reading it failed. // Anything else is a failure to read who the profile is. -func connectStartFailure(kind, profile string, err error) error { +func connectStartFailure(ctx context.Context, kind, profile string, err error) error { var e *output.Error switch { - case errors.Is(err, context.Canceled), errors.Is(err, context.DeadlineExceeded), + case ctx.Err() != nil, errors.As(err, &e) && (e.Code == output.CodeTerminated || e.Code == output.CodeInterrupted): return err case agentDisconnectedAtStart(kind, err): diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index b6dc2cd64..24dafc3e1 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -12,6 +12,7 @@ import ( "net/http/httptest" "net/url" "os" + "strings" "sync" "syscall" "testing" @@ -352,7 +353,7 @@ func TestATruncatedRefusalStillEndsTheStart(t *testing.T) { err := awaitConnectToken(t.Context(), tokens, w.options(tokens)) require.Error(t, err) assert.ErrorIs(t, err, auth.ErrAgentCredentialRefused) - assert.Equal(t, errAgentDisconnected("", "agent"), connectStartFailure(setup.KindAgent, "agent", err)) + assert.Equal(t, errAgentDisconnected("", "agent"), connectStartFailure(t.Context(), setup.KindAgent, "agent", err)) assert.Empty(t, w.waits) assert.Equal(t, 1, mints()) } @@ -387,12 +388,22 @@ func TestAStartFailureKeepsItsFraming(t *testing.T) { refused.Cause = auth.ErrAgentCredentialRefused terminated := output.ErrTerminated("connector terminated") - assert.Same(t, terminated, connectStartFailure(setup.KindAgent, "agent", terminated)) - assert.ErrorIs(t, connectStartFailure(setup.KindAgent, "agent", context.Canceled), context.Canceled) - assert.Equal(t, errAgentDisconnected("", "agent"), connectStartFailure(setup.KindAgent, "agent", refused)) + canceled, cancel := context.WithCancel(t.Context()) + cancel() + assert.Same(t, terminated, connectStartFailure(t.Context(), setup.KindAgent, "agent", terminated)) + assert.ErrorIs(t, connectStartFailure(canceled, setup.KindAgent, "agent", context.Canceled), context.Canceled) + assert.Equal(t, errAgentDisconnected("", "agent"), connectStartFailure(t.Context(), setup.KindAgent, "agent", refused)) + + // A request's own timeout, while the connector is not stopping, is a + // failure to read who the profile is like any other. + timedOut := &basecamp.Error{Code: basecamp.CodeNetwork, Message: "request timed out", Retryable: true, Cause: context.DeadlineExceeded} + var framed *output.Error + require.ErrorAs(t, connectStartFailure(t.Context(), setup.KindAgent, "agent", timedOut), &framed) + assert.Equal(t, output.CodeAuth, framed.Code) + assert.Contains(t, framed.Message, `Could not read who profile "agent" is`) var e *output.Error - require.ErrorAs(t, connectStartFailure(setup.KindAgent, "agent", output.ErrAPI(404, "minting an agent token: the server answered HTTP 404")), &e) + require.ErrorAs(t, connectStartFailure(t.Context(), setup.KindAgent, "agent", output.ErrAPI(404, "minting an agent token: the server answered HTTP 404")), &e) assert.Equal(t, output.CodeAuth, e.Code) assert.Equal(t, `Could not read who profile "agent" is: minting an agent token: the server answered HTTP 404`, e.Message) } @@ -456,3 +467,15 @@ func TestAStartWaitsOutAStoredRateLimitHold(t *testing.T) { assert.Equal(t, 1, mints(), "the second attempt was the stored hold's to answer") } + +// A server fault whose body is larger than any token response — a proxy's +// error page, say — is still classified by its status, and waited out. +func TestAnOversizedServerFaultIsWaitedOut(t *testing.T) { + page := strings.Repeat("x", 2<<20) + tokens, mints := startingAgent(t, answerStatus(http.StatusServiceUnavailable, nil, page), answerStatus(http.StatusOK, nil, mintedToken)) + var w startWaits + + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options(tokens))) + assert.Len(t, w.waits, 1) + assert.Equal(t, 2, mints()) +} From fb43aeaf4f40d78b7d529e6013df64836dcc3740 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Thu, 1 Oct 2026 10:59:56 -0700 Subject: [PATCH 14/20] Tell the session a connector waiting for its token is not stopped A connector started while the token endpoint rate-limits the agent now waits instead of exiting, and says so. The skill reads that line for what it is, so the session leaves it running rather than reporting a failure or starting another. --- skills/basecamp-connect/SKILL.md | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/skills/basecamp-connect/SKILL.md b/skills/basecamp-connect/SKILL.md index 831b1aaa4..62c9caba4 100644 --- a/skills/basecamp-connect/SKILL.md +++ b/skills/basecamp-connect/SKILL.md @@ -261,7 +261,11 @@ basecamp connect -P '' It runs until stopped. Its folder doesn't matter: every subagent works in the repo you choose for it. Read the output once after a few seconds. You should see `connector: running` in its log. If it exited instead, explain the error -(see *When the connector stops*), and stop. +(see *When the connector stops*), and stop. If it says `could not get the +agent's token yet`, Basecamp's token endpoint is rate-limiting it or having +trouble: it waits as long as it says and tries again on its own. Tell the +person, leave it running, and arm the monitor as usual. Restarting it doesn't +help. Then arm a persistent monitor on that file with the Monitor tool (`persistent: true`), replaying from the start so nothing that arrived between From 767c8a94b978e018aa8f67220866230be6e18fb4 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Thu, 1 Oct 2026 11:24:22 -0700 Subject: [PATCH 15/20] A second connector is refused before it waits for a token The instance lock was taken after the identity read, so a second connector started while the token endpoint rate-limited the agent waited out the rate limit, alive and logging, before finding the first one running. The lock is now taken first, under the agent connect.json names, which VerifyAgent then holds the credential to. --- internal/commands/connect_run.go | 30 ++++++------ internal/commands/connect_setup_test.go | 13 ++++++ internal/commands/connect_start_wait_test.go | 48 ++++++++++++++++++++ 3 files changed, 78 insertions(+), 13 deletions(-) diff --git a/internal/commands/connect_run.go b/internal/commands/connect_run.go index adef5451d..89c1ec2b1 100644 --- a/internal/commands/connect_run.go +++ b/internal/commands/connect_run.go @@ -169,6 +169,23 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { if err != nil { return output.ErrAuth("The stored credential could not be read: " + setup.ErrorText(err)) } + // The lock first, under the agent connect.json names: a second + // connector for an agent already running says so now, not after + // waiting out a rate limit for a token it would never use. VerifyAgent + // below holds the credential to that same person. + stateDir, err := connectStateDir(file, f.shadow) + if err != nil { + return output.ErrUsage("The connector's state directory cannot be used: " + err.Error()) + } + lock, err := connector.AcquireInstanceLock(stateDir, account, file.Agent.PersonID, time.Now()) + if err != nil { + if errors.Is(err, connector.ErrAlreadyRunning) { + return &output.Error{Code: output.CodeLockUnavailable, Message: err.Error()} + } + return err + } + defer func() { _ = lock.Release() }() + logger := slog.New(slog.NewTextHandler(cmd.ErrOrStderr(), nil)) tokens := &managerTokens{mgr: app.Auth} // Every read below needs a token first. One the running feed would @@ -205,19 +222,6 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { } policy.Buckets = buckets - stateDir, err := connectStateDir(file, f.shadow) - if err != nil { - return output.ErrUsage("The connector's state directory cannot be used: " + err.Error()) - } - lock, err := connector.AcquireInstanceLock(stateDir, account, agentID, time.Now()) - if err != nil { - if errors.Is(err, connector.ErrAlreadyRunning) { - return &output.Error{Code: output.CodeLockUnavailable, Message: err.Error()} - } - return err - } - defer func() { _ = lock.Release() }() - ledger, err := connector.OpenLedger(filepath.Join(stateDir, connector.LedgerFile)) if err != nil { return err diff --git a/internal/commands/connect_setup_test.go b/internal/commands/connect_setup_test.go index e0381e724..298b9d7be 100644 --- a/internal/commands/connect_setup_test.go +++ b/internal/commands/connect_setup_test.go @@ -77,6 +77,10 @@ type connectSetupServer struct { // refuseSecret answers every mint with invalid_client, as Basecamp does // for an agent disconnected, or connected on another computer. refuseSecret bool + // rateLimitMints answers every mint with a 429 asking for an hour. + rateLimitMints bool + // mints counts the agent token mints. + mints int } func startConnectSetupServer(t *testing.T) *connectSetupServer { @@ -108,6 +112,15 @@ func startConnectSetupServer(t *testing.T) *connectSetupServer { writeJSON(w, map[string]any{"client_id": "agent-client", "client_secret": fakeConnectSecret, "account_id": "999", "scope": scope}) }) mux.HandleFunc("/oauth/tokens", func(w http.ResponseWriter, _ *http.Request) { + s.mu.Lock() + s.mints++ + rateLimited := s.rateLimitMints + s.mu.Unlock() + if rateLimited { + w.Header().Set("Retry-After", "3600") + w.WriteHeader(http.StatusTooManyRequests) + return + } if s.refuseSecret { w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusUnauthorized) diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index 24dafc3e1..528d60dca 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -1,6 +1,7 @@ package commands import ( + "bytes" "context" "crypto/tls" "crypto/x509" @@ -23,6 +24,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "github.com/basecamp/basecamp-cli/internal/appctx" "github.com/basecamp/basecamp-cli/internal/auth" "github.com/basecamp/basecamp-cli/internal/config" "github.com/basecamp/basecamp-cli/internal/connector" @@ -479,3 +481,49 @@ func TestAnOversizedServerFaultIsWaitedOut(t *testing.T) { assert.Len(t, w.waits, 1) assert.Equal(t, 2, mints()) } + +// A second connector for an agent that is already running says so at once, +// even while the token endpoint is rate-limiting it: the lock is checked +// before the start waits for a token, not after. +func TestASecondConnectorIsRefusedBeforeItWaitsForAToken(t *testing.T) { + f := newOperatorFixture(t) + dir, err := connectStateDir(f.file, false) + require.NoError(t, err) + lock, err := connector.AcquireInstanceLock(dir, f.file.AccountID, f.file.Agent.PersonID, time.Now()) + require.NoError(t, err) + t.Cleanup(func() { _ = lock.Release() }) + + app := newConnectSetupApp(t, f.s, "agent") + creds, err := app.Auth.GetStore().Load(app.Auth.CredentialKey()) + require.NoError(t, err) + creds.ExpiresAt = time.Now().Add(-time.Minute).Unix() + require.NoError(t, app.Auth.GetStore().Save(app.Auth.CredentialKey(), creds)) + f.s.mu.Lock() + f.s.rateLimitMints, f.s.mints = true, 0 + f.s.mu.Unlock() + + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + var buf bytes.Buffer + app.Output = output.New(output.Options{Format: output.FormatJSON, Writer: &buf}) + cmd := NewConnectCmd() + cmd.SetArgs(nil) + cmd.SetContext(appctx.WithApp(ctx, app)) + cmd.SetOut(&buf) + cmd.SetErr(&buf) + cmd.SilenceErrors, cmd.SilenceUsage = true, true + done := make(chan error, 1) + go func() { done <- cmd.Execute() }() + + select { + case err := <-done: + assert.Equal(t, output.CodeLockUnavailable, usageError(t, err).Code, buf.String()) + case <-time.After(10 * time.Second): + cancel() + <-done + t.Fatalf("a second connector waited for a token instead of refusing: %s", buf.String()) + } + f.s.mu.Lock() + defer f.s.mu.Unlock() + assert.Zero(t, f.s.mints, "nothing was minted for a connector that cannot run") +} From 0a035cf9f0859942fcec431822bf2b71105ee05d Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Thu, 1 Oct 2026 11:45:21 -0700 Subject: [PATCH 16/20] Wait what the server named or the backoff, and hold no lock while waiting The wait for a retryable token failure is now exactly the Retry-After the server named, on a 5xx as on a 429, or nothing, which leaves it to the backoff; it no longer passes through the SDK's rate-limit constructor to get there. A starting connector only looks at the instance lock before it waits for a token, and takes it once the credential is proven to be the agent connect.json names: a profile holding some other agent's credential no longer keeps that agent's real connector out while it waits. A second connector is still refused up front. A closed signal channel is not taken as a stop, and a start with no log set still waits instead of panicking. --- internal/auth/revoke.go | 8 +- internal/commands/connect.go | 10 +- internal/commands/connect_run.go | 48 +++++-- internal/commands/connect_start_wait.go | 31 +++-- internal/commands/connect_start_wait_test.go | 138 +++++++++++++++++++ 5 files changed, 210 insertions(+), 25 deletions(-) diff --git a/internal/auth/revoke.go b/internal/auth/revoke.go index 1fb1ac299..5c2c17903 100644 --- a/internal/auth/revoke.go +++ b/internal/auth/revoke.go @@ -225,7 +225,8 @@ func transportFailure(msg string, cause error) error { // statusFailure is a revocation request the server answered with something // other than 200, classified the way the SDK classifies any other response: // 429 is a rate limit (retryable, with its Retry-After), 507 an account -// limit (a verdict, not retryable), any other 5xx retryable, the rest final. +// limit (a verdict, not retryable), any other 5xx retryable (with its +// Retry-After, when it names one), the rest final. func statusFailure(msg string, resp *http.Response) error { switch resp.StatusCode { case http.StatusTooManyRequests: @@ -244,6 +245,11 @@ func statusFailure(msg string, resp *http.Response) error { default: e := output.ErrAPI(resp.StatusCode, msg) e.Retryable = resp.StatusCode >= 500 && resp.StatusCode < 600 + // A 503 may name its wait as surely as a 429; a retryable answer + // carries it the same way. + if retryAfter := retryAfterSeconds(resp.Header.Get("Retry-After"), time.Now()); e.Retryable && retryAfter > 0 { + e.Cause = retryAfterError(retryAfter) + } return e } } diff --git a/internal/commands/connect.go b/internal/commands/connect.go index 1d8e7a7dd..e6548eda3 100644 --- a/internal/commands/connect.go +++ b/internal/commands/connect.go @@ -1133,7 +1133,7 @@ func (t *feedTokens) AccessToken(ctx context.Context) (string, error) { // tokenFailureInSDKTerms is a failed renewal as the SDK's error, classified // by tokenRetry, or nil when there was no failure. A retryable one keeps -// its status — a 429 with the wait it named, a 5xx — or, with no status, is +// its status and any wait it named — a 429, a 5xx — or, with no status, is // a network failure; the feed backs off and carries on either way. One that // cannot be retried carries no status at all, so the feed ends on it rather // than counting it toward its own authorization threshold; a refused @@ -1152,10 +1152,10 @@ func tokenFailureInSDKTerms(err error) *basecamp.Error { if errors.As(err, &cliErr) { e.HTTPStatus = cliErr.HTTPStatus } + e.RetryAfter = int(asked / time.Second) switch e.HTTPStatus { case http.StatusTooManyRequests: e.Code = basecamp.CodeRateLimit - e.RetryAfter = int(asked / time.Second) case 0: e.Code = basecamp.CodeNetwork } @@ -1176,7 +1176,7 @@ func tokenFailureInSDKTerms(err error) *basecamp.Error { // Two things are never retried, because no wait changes them: a URL the // egress policy refused, and one the client could not send at all. The // wait is the agent mint's own, or that of the SDK error an OAuth refresh -// carries, through the SDK's constructor for its bound. +// carries; both are bounded where they are parsed. func tokenRetry(err error) (time.Duration, bool) { if errors.Is(err, surfguard.ErrBlocked) || cannotBeSent(err) { return 0, false @@ -1189,7 +1189,9 @@ func tokenRetry(err error) (time.Duration, bool) { var cliErr *output.Error switch { case errors.As(err, &cliErr) && cliErr.Retryable: - return time.Duration(basecamp.ErrRateLimit(seconds).RetryAfter) * time.Second, true + // Exactly what the server named, or nothing, which leaves it to + // the backoff: never a default wait from anywhere else. + return time.Duration(max(seconds, 0)) * time.Second, true case gotNoResponse(err): return 0, true } diff --git a/internal/commands/connect_run.go b/internal/commands/connect_run.go index 89c1ec2b1..a854eaf39 100644 --- a/internal/commands/connect_run.go +++ b/internal/commands/connect_run.go @@ -169,22 +169,19 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { if err != nil { return output.ErrAuth("The stored credential could not be read: " + setup.ErrorText(err)) } - // The lock first, under the agent connect.json names: a second - // connector for an agent already running says so now, not after - // waiting out a rate limit for a token it would never use. VerifyAgent - // below holds the credential to that same person. + // A look at the lock first, under the agent connect.json names: a + // second connector for an agent already running says so now, not after + // waiting out a rate limit for a token it would never use. Only a look: + // until the credential is proven to be that agent, holding its lock + // through the wait could keep the agent's real connector from starting. + // The lock is taken for the run once the identity is verified. stateDir, err := connectStateDir(file, f.shadow) if err != nil { return output.ErrUsage("The connector's state directory cannot be used: " + err.Error()) } - lock, err := connector.AcquireInstanceLock(stateDir, account, file.Agent.PersonID, time.Now()) - if err != nil { - if errors.Is(err, connector.ErrAlreadyRunning) { - return &output.Error{Code: output.CodeLockUnavailable, Message: err.Error()} - } + if err := connectLockFree(stateDir, account, file.Agent.PersonID); err != nil { return err } - defer func() { _ = lock.Release() }() logger := slog.New(slog.NewTextHandler(cmd.ErrOrStderr(), nil)) tokens := &managerTokens{mgr: app.Auth} @@ -194,9 +191,11 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { err = awaitConnectToken(ctx, tokens, connectStartWait{Log: func(line string) { logger.Warn(line) }, Signals: startSignals}) stopStartSignals() select { - case sig := <-startSignals: + case sig, ok := <-startSignals: // Delivered after the wait had finished, before the stop took. - return connectStoppedBySignal(sig) + if ok { + return connectStoppedBySignal(sig) + } default: } if err != nil { @@ -215,6 +214,11 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { return output.ErrAuth(err.Error()) } agentID := me.ID + lock, err := acquireConnectLock(stateDir, account, agentID) + if err != nil { + return err + } + defer func() { _ = lock.Release() }() policy, err := file.Policy(agentID) if err != nil { @@ -396,6 +400,26 @@ func connectorStoppedBy(err error, agent, profile string, refused func() bool) ( return connector.ConnectionDisconnected, e.Message, e } +// acquireConnectLock takes the connector's instance lock for the run, or +// says another connector for this agent already holds it. +func acquireConnectLock(stateDir, account string, agentID int64) (*connector.InstanceLock, error) { + lock, err := connector.AcquireInstanceLock(stateDir, account, agentID, time.Now()) + if errors.Is(err, connector.ErrAlreadyRunning) { + return nil, &output.Error{Code: output.CodeLockUnavailable, Message: err.Error()} + } + return lock, err +} + +// connectLockFree reports, by taking and at once releasing it, whether the +// instance lock is free: the start's look before it waits for a token. +func connectLockFree(stateDir, account string, agentID int64) error { + lock, err := acquireConnectLock(stateDir, account, agentID) + if err != nil { + return err + } + return lock.Release() +} + // connectStartFailure is what a start that could not learn who it is exits // with. Stopped by a signal, or because ctx itself ended, it says so as it // is; a request's own timeout is not the connector stopping. diff --git a/internal/commands/connect_start_wait.go b/internal/commands/connect_start_wait.go index 2662d1d49..9bee80564 100644 --- a/internal/commands/connect_start_wait.go +++ b/internal/commands/connect_start_wait.go @@ -25,6 +25,7 @@ const ( // it says so, which signals stop it, and how it sleeps — by default a timer // that ctx cuts short. type connectStartWait struct { + // Log says each wait, once; nothing is said when nil. Log func(string) Signals <-chan os.Signal Sleep func(ctx context.Context, d time.Duration) error @@ -37,10 +38,16 @@ func (w connectStartWait) forceStop(sig os.Signal) { if exit == nil { exit = os.Exit } - w.Log("connector: stopping now, before it has started; signal " + sig.String()) + w.log("connector: stopping now, before it has started; signal " + sig.String()) exit(connector.ExitCodeForSignal(sig)) } +func (w connectStartWait) log(line string) { + if w.Log != nil { + w.Log(line) + } +} + // awaitConnectToken holds a starting connector until the agent's token can // be had. A failure the running feed would wait out — a rate limit, the // token endpoint's own 5xx, no answer at all — is waited out here too, for @@ -59,8 +66,12 @@ func awaitConnectToken(parent context.Context, tokens basecamp.TokenProvider, w watched, done := make(chan struct{}), make(chan struct{}) go func() { defer close(watched) + // A closed channel delivers no stop, only the end of the watch. select { - case sig := <-w.Signals: + case sig, ok := <-w.Signals: + if !ok { + return + } stopped = connectStoppedBySignal(sig) cancel() case <-ctx.Done(): @@ -70,8 +81,10 @@ func awaitConnectToken(parent context.Context, tokens basecamp.TokenProvider, w // context. A second signal is someone who has waited long enough, // and ends the process as it does for a running connector. select { - case sig := <-w.Signals: - w.forceStop(sig) + case sig, ok := <-w.Signals: + if ok { + w.forceStop(sig) + } case <-done: } }() @@ -83,11 +96,13 @@ func awaitConnectToken(parent context.Context, tokens basecamp.TokenProvider, w return stopped } select { - case sig := <-w.Signals: - return connectStoppedBySignal(sig) + case sig, ok := <-w.Signals: + if ok { + return connectStoppedBySignal(sig) + } default: - return err } + return err } func awaitToken(ctx context.Context, tokens basecamp.TokenProvider, w connectStartWait) error { @@ -111,7 +126,7 @@ func awaitToken(ctx context.Context, tokens basecamp.TokenProvider, w connectSta if wait <= 0 { wait = connectStartBackoff(attempt) } - w.Log(fmt.Sprintf("connector: could not get the agent's token yet (%s); trying again in %s", output.AsError(err).Message, max(wait.Round(time.Second), time.Second))) + w.log(fmt.Sprintf("connector: could not get the agent's token yet (%s); trying again in %s", output.AsError(err).Message, max(wait.Round(time.Second), time.Second))) if err := sleep(ctx, wait); err != nil { return err } diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index 528d60dca..d97140951 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -20,6 +20,7 @@ import ( "time" "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp/eventfeed" surfguard "github.com/basecamp/surfguard/go" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -527,3 +528,140 @@ func TestASecondConnectorIsRefusedBeforeItWaitsForAToken(t *testing.T) { defer f.s.mu.Unlock() assert.Zero(t, f.s.mints, "nothing was minted for a connector that cannot run") } + +// A 503 that names its Retry-After is waited out for that long, by the +// start and the feed alike, not on backoff. +func TestAServerFaultsRetryAfterIsHonored(t *testing.T) { + unavailable := answerStatus(http.StatusServiceUnavailable, map[string]string{"Retry-After": "30"}, "") + tokens, _ := startingAgent(t, unavailable, answerStatus(http.StatusOK, nil, mintedToken)) + var w startWaits + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options(tokens))) + assert.Equal(t, []time.Duration{30 * time.Second}, w.waits) + + live, _ := tokenEndpointFeed(t, unavailable) + _, err := live.Minter().MintStreamTicket(t.Context()) + var mintErr *eventfeed.MintError + require.ErrorAs(t, err, &mintErr) + assert.Equal(t, eventfeed.MintThrottled, mintErr.Kind, "%v", err) + assert.Equal(t, 30*time.Second, mintErr.RetryAfter) +} + +// lockedBuffer is a buffer a running command writes while the test reads. +type lockedBuffer struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (b *lockedBuffer) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.Write(p) +} + +func (b *lockedBuffer) String() string { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.String() +} + +// A start waiting for its token does not hold the agent's lock: until the +// credential is proven to be that agent, the lock is only looked at, so a +// profile whose credential is some other agent's cannot keep the real +// connector out while it waits. +func TestAStartWaitingForItsTokenHoldsNoLock(t *testing.T) { + f := newOperatorFixture(t) + app := newConnectSetupApp(t, f.s, "agent") + creds, err := app.Auth.GetStore().Load(app.Auth.CredentialKey()) + require.NoError(t, err) + creds.ExpiresAt = time.Now().Add(-time.Minute).Unix() + require.NoError(t, app.Auth.GetStore().Save(app.Auth.CredentialKey(), creds)) + f.s.mu.Lock() + f.s.rateLimitMints = true + f.s.mu.Unlock() + + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + var out lockedBuffer + app.Output = output.New(output.Options{Format: output.FormatJSON, Writer: &out}) + cmd := NewConnectCmd() + cmd.SetArgs(nil) + cmd.SetContext(appctx.WithApp(ctx, app)) + cmd.SetOut(&out) + cmd.SetErr(&out) + cmd.SilenceErrors, cmd.SilenceUsage = true, true + done := make(chan error, 1) + go func() { done <- cmd.Execute() }() + + require.Eventually(t, func() bool { return strings.Contains(out.String(), "could not get the agent's token yet") }, + 10*time.Second, 20*time.Millisecond, "the start never waited: %s", out.String()) + dir, err := connectStateDir(f.file, false) + require.NoError(t, err) + lock, err := connector.AcquireInstanceLock(dir, f.file.AccountID, f.file.Agent.PersonID, time.Now()) + require.NoError(t, err, "a waiting start held the agent's lock") + require.NoError(t, lock.Release()) + + cancel() + select { + case <-done: + case <-time.After(10 * time.Second): + t.Fatal("the waiting start did not stop when canceled") + } +} + +// okTokens is a renewal that succeeds at once. +type okTokens struct{} + +func (okTokens) AccessToken(context.Context) (string, error) { return "bc_at_minted", nil } + +// A closed signal channel delivers nothing: it is not a stop. +func TestAClosedSignalChannelIsNotAStop(t *testing.T) { + signals := make(chan os.Signal) + close(signals) + assert.NoError(t, awaitConnectToken(t.Context(), okTokens{}, connectStartWait{Signals: signals})) +} + +// A wait with nowhere to say so still waits, and a forced stop still stops. +func TestAStartWithoutALogStillWaits(t *testing.T) { + unavailable := answerStatus(http.StatusServiceUnavailable, nil, "") + tokens, _ := startingAgent(t, unavailable, answerStatus(http.StatusOK, nil, mintedToken)) + w := startWaits{} + opts := w.options(tokens) + opts.Log = nil + require.NoError(t, awaitConnectToken(t.Context(), tokens, opts)) + assert.Len(t, w.waits, 1) + + exited := -1 + connectStartWait{Exit: func(code int) { exited = code }}.forceStop(syscall.SIGTERM) + assert.Equal(t, connector.ExitCodeForSignal(syscall.SIGTERM), exited) +} + +// The wait comes from the server or from the backoff, never from anywhere +// else: a 5xx that names none waits on the backoff, one that names one +// waits exactly that, and so does a 429. +func TestTheWaitIsWhatTheServerNamedOrNothing(t *testing.T) { + failure := func(status int) error { + if status == http.StatusTooManyRequests { + return output.ErrRateLimit(0) + } + e := output.ErrAPI(status, "minting an agent token") + e.Retryable = true + return e + } + wait, ok := tokenRetry(failure(http.StatusServiceUnavailable)) + assert.True(t, ok) + assert.Zero(t, wait, "a 5xx naming no wait leaves it to the backoff") + wait, ok = tokenRetry(failure(http.StatusTooManyRequests)) + assert.True(t, ok) + assert.Zero(t, wait, "a 429 naming no wait leaves it to the backoff") + + start := startWaitsFor(t, answerStatus(http.StatusBadGateway, map[string]string{"Retry-After": "17"}, "")) + assert.Equal(t, []time.Duration{17 * time.Second}, start) +} + +func startWaitsFor(t *testing.T, first func(http.ResponseWriter)) []time.Duration { + t.Helper() + tokens, _ := startingAgent(t, first, answerStatus(http.StatusOK, nil, mintedToken)) + var w startWaits + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options(tokens))) + return w.waits +} From cc2f30e4a6318b2700837c6724849425188090b0 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Thu, 1 Oct 2026 12:06:34 -0700 Subject: [PATCH 17/20] Every wait a server names is waited, never longer than one cap A 503 or a bot user's OAuth refresh could name a Retry-After of years, and the connector would wait it: a hang, not a wait. Every wait a server names, whatever the status or token path, now goes through one cap, auth.MaxServerWait, the bound #787 already puts on a mint hold, so a held rate limit and every other named wait agree. When the server asked for longer, the start and the feed say so once: what it asked for, and what is waited. --- internal/auth/agent_hold.go | 6 +++ internal/commands/connect.go | 44 ++++++++++++------ internal/commands/connect_run.go | 2 +- internal/commands/connect_start_wait.go | 12 ++++- internal/commands/connect_start_wait_test.go | 46 +++++++++++++++++++ internal/commands/connect_token_retry_test.go | 2 +- 6 files changed, 95 insertions(+), 17 deletions(-) diff --git a/internal/auth/agent_hold.go b/internal/auth/agent_hold.go index 3c26275ea..114945121 100644 --- a/internal/auth/agent_hold.go +++ b/internal/auth/agent_hold.go @@ -100,6 +100,12 @@ const defaultAgentRateLimitHold = 60 * time.Second // the safe direction to fail in. const maxAgentMintHold = time.Hour +// MaxServerWait is the longest any wait a server names is waited, whatever +// the status or the token path: the same bound as a mint hold, so a held +// rate limit and every other named wait agree. A connector that waited a +// server's word for years would be a hang, not a wait. +const MaxServerWait = maxAgentMintHold + // MintHold is the token endpoint's last refusal of an agent credential's // client, remembered so the next mint can answer it without asking again. // diff --git a/internal/commands/connect.go b/internal/commands/connect.go index e6548eda3..6c32403b2 100644 --- a/internal/commands/connect.go +++ b/internal/commands/connect.go @@ -1121,14 +1121,23 @@ func (t *managerTokens) AccessToken(ctx context.Context) (string, error) { // does not recognize its own way, so every failure is handed over already // classified by tokenRetry — the same rule a starting connector waits by, // so the two cannot drift apart. -type feedTokens struct{ managerTokens } +type feedTokens struct { + managerTokens + // log says a wait the server named past the cap, once per answer that + // named it; nothing is said when nil. + log func(string) +} func (t *feedTokens) AccessToken(ctx context.Context) (string, error) { token, err := t.mgr.AccessToken(ctx) - if e := tokenFailureInSDKTerms(err); e != nil { - return token, e + e := tokenFailureInSDKTerms(err) + if e == nil { + return token, err } - return token, err + if named, wait := serverNamedWait(err), time.Duration(e.RetryAfter)*time.Second; e.Retryable && named > wait && t.log != nil { + t.log(connectWaitLine(output.AsError(err).Message, named, wait)) + } + return token, e } // tokenFailureInSDKTerms is a failed renewal as the SDK's error, classified @@ -1175,29 +1184,36 @@ func tokenFailureInSDKTerms(err error) *basecamp.Error { // where exiting would only have a supervisor give up sooner, knowing less. // Two things are never retried, because no wait changes them: a URL the // egress policy refused, and one the client could not send at all. The -// wait is the agent mint's own, or that of the SDK error an OAuth refresh -// carries; both are bounded where they are parsed. +// wait is what the server named, never longer than auth.MaxServerWait. func tokenRetry(err error) (time.Duration, bool) { if errors.Is(err, surfguard.ErrBlocked) || cannotBeSent(err) { return 0, false } - seconds := auth.RetryAfter(err) - var sdkErr *basecamp.Error - if errors.As(err, &sdkErr) { - seconds = max(seconds, sdkErr.RetryAfter) - } var cliErr *output.Error switch { case errors.As(err, &cliErr) && cliErr.Retryable: - // Exactly what the server named, or nothing, which leaves it to - // the backoff: never a default wait from anywhere else. - return time.Duration(max(seconds, 0)) * time.Second, true + // Exactly what the server named, never longer than the one cap, + // or nothing, which leaves it to the backoff: never a default + // wait from anywhere else. + return min(serverNamedWait(err), auth.MaxServerWait), true case gotNoResponse(err): return 0, true } return 0, false } +// serverNamedWait is the wait the server named for err, as it named it: +// the agent mint's own, or that of the SDK error an OAuth refresh carries. +// Zero when it named none. +func serverNamedWait(err error) time.Duration { + seconds := auth.RetryAfter(err) + var sdkErr *basecamp.Error + if errors.As(err, &sdkErr) { + seconds = max(seconds, sdkErr.RetryAfter) + } + return time.Duration(max(seconds, 0)) * time.Second +} + // gotNoResponse reports a request that failed on the way, with no response // to classify. func gotNoResponse(err error) bool { diff --git a/internal/commands/connect_run.go b/internal/commands/connect_run.go index a854eaf39..5c59e7034 100644 --- a/internal/commands/connect_run.go +++ b/internal/commands/connect_run.go @@ -253,7 +253,7 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { if err != nil { return err } - live, err := eventfeed.NewLive(&basecamp.Config{BaseURL: app.Config.BaseURL}, &feedTokens{*tokens}, account, eventfeed.AccountLane, connectSDKOptions()...) + live, err := eventfeed.NewLive(&basecamp.Config{BaseURL: app.Config.BaseURL}, &feedTokens{managerTokens: *tokens, log: func(line string) { logger.Warn(line) }}, account, eventfeed.AccountLane, connectSDKOptions()...) if err != nil { return err } diff --git a/internal/commands/connect_start_wait.go b/internal/commands/connect_start_wait.go index 9bee80564..8389317ef 100644 --- a/internal/commands/connect_start_wait.go +++ b/internal/commands/connect_start_wait.go @@ -126,7 +126,7 @@ func awaitToken(ctx context.Context, tokens basecamp.TokenProvider, w connectSta if wait <= 0 { wait = connectStartBackoff(attempt) } - w.log(fmt.Sprintf("connector: could not get the agent's token yet (%s); trying again in %s", output.AsError(err).Message, max(wait.Round(time.Second), time.Second))) + w.log(connectWaitLine(output.AsError(err).Message, serverNamedWait(err), wait)) if err := sleep(ctx, wait); err != nil { return err } @@ -162,3 +162,13 @@ func connectStoppedBySignal(sig os.Signal) error { } return output.ErrInterrupted("connector interrupted") } + +// connectWaitLine says, once per wait, why the start is waiting and for how +// long, and when the server asked for longer than the cap, both. +func connectWaitLine(reason string, named, wait time.Duration) string { + line := fmt.Sprintf("connector: could not get the agent's token yet (%s); ", reason) + if named > wait { + return line + fmt.Sprintf("the server asked to wait %s, longer than the connector waits; waiting %s", named, wait) + } + return line + fmt.Sprintf("trying again in %s", max(wait.Round(time.Second), time.Second)) +} diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index d97140951..1ba310d1c 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -665,3 +665,49 @@ func startWaitsFor(t *testing.T, first func(http.ResponseWriter)) []time.Duratio require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options(tokens))) return w.waits } + +// A server can name any wait; the connector waits it, never longer than +// the one cap. A 503 asking for three years is waited out for the cap, and +// the log says both. +func TestAnAbsurdServerWaitIsCapped(t *testing.T) { + absurd := answerStatus(http.StatusServiceUnavailable, map[string]string{"Retry-After": "99999999"}, "") + tokens, _ := startingAgent(t, absurd, answerStatus(http.StatusOK, nil, mintedToken)) + var w startWaits + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options(tokens))) + assert.Equal(t, []time.Duration{auth.MaxServerWait}, w.waits) + require.Len(t, w.lines, 1) + assert.Contains(t, w.lines[0], "asked to wait 27777h46m39s") + assert.Contains(t, w.lines[0], "waiting "+auth.MaxServerWait.String()) + + // A bot user's OAuth refresh carries its wait on the SDK's error. + refresh := &output.Error{Code: output.CodeRateLimit, Message: "token refresh failed", HTTPStatus: 429, Retryable: true, + Cause: basecamp.ErrRateLimit(99999999)} + wait, ok := tokenRetry(refresh) + assert.True(t, ok) + assert.Equal(t, auth.MaxServerWait, wait) + + // The feed is handed the same cap. + live, _ := tokenEndpointFeed(t, absurd) + _, err := live.Minter().MintStreamTicket(t.Context()) + var mintErr *eventfeed.MintError + require.ErrorAs(t, err, &mintErr) + assert.Equal(t, eventfeed.MintThrottled, mintErr.Kind, "%v", err) + assert.Equal(t, auth.MaxServerWait, mintErr.RetryAfter) +} + +// The feed is told the cap too, and says once that the server asked for +// longer. +func TestTheFeedSaysWhenItCapsAWait(t *testing.T) { + absurd := answerStatus(http.StatusServiceUnavailable, map[string]string{"Retry-After": "99999999"}, "") + start, _ := startingAgent(t, absurd) + var lines []string + tokens := &feedTokens{managerTokens: start.managerTokens, log: func(line string) { lines = append(lines, line) }} + + _, err := tokens.AccessToken(t.Context()) + var sdkErr *basecamp.Error + require.ErrorAs(t, err, &sdkErr) + assert.Equal(t, auth.MaxServerWait, time.Duration(sdkErr.RetryAfter)*time.Second) + require.Len(t, lines, 1) + assert.Contains(t, lines[0], "asked to wait 27777h46m39s") + assert.Contains(t, lines[0], "waiting "+auth.MaxServerWait.String()) +} diff --git a/internal/commands/connect_token_retry_test.go b/internal/commands/connect_token_retry_test.go index a6f5daa9f..aa529f46a 100644 --- a/internal/commands/connect_token_retry_test.go +++ b/internal/commands/connect_token_retry_test.go @@ -57,7 +57,7 @@ func tokenEndpointFeed(t *testing.T, answer func(http.ResponseWriter)) (*eventfe ExpiresAt: time.Now().Add(-time.Minute).Unix(), })) - live, err := eventfeed.NewLive(&basecamp.Config{BaseURL: srv.URL}, &feedTokens{managerTokens{mgr: mgr}}, "555", eventfeed.AccountLane, connectSDKOptions()...) + live, err := eventfeed.NewLive(&basecamp.Config{BaseURL: srv.URL}, &feedTokens{managerTokens: managerTokens{mgr: mgr}}, "555", eventfeed.AccountLane, connectSDKOptions()...) require.NoError(t, err) return live, mints.Load } From a4438209e824998bb00c528175168721917afbf4 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Thu, 1 Oct 2026 12:24:16 -0700 Subject: [PATCH 18/20] One cap for every server-named wait, the one a hold is written under MaxServerWait was an hour, while #787 writes a rate-limit hold under the thirty-minute bound its Retry-After parser applies: an agent's 429 was capped at thirty minutes and every other named wait at an hour. The one cap is now that thirty minutes, and the hold is written under it by name. A 429 held for the cap keeps what the server asked for, so the start and the feed say both. --- internal/auth/agent.go | 8 +++++++- internal/auth/agent_hold.go | 12 ++++++------ internal/auth/revoke.go | 18 ++++++++++++++++++ internal/commands/connect.go | 2 +- internal/commands/connect_start_wait_test.go | 15 +++++++++++++++ 5 files changed, 47 insertions(+), 8 deletions(-) diff --git a/internal/auth/agent.go b/internal/auth/agent.go index 2e9c19024..78a6996d8 100644 --- a/internal/auth/agent.go +++ b/internal/auth/agent.go @@ -486,7 +486,13 @@ func (m *Manager) agentMintRefusal(resp *http.Response, body []byte, mint *agent now := m.now() hold := mintHoldFor(mint, resp, detail, code, false, now) if hold != nil && hold.Kind == mintHoldRateLimited { - return hold, holdRateLimitError(hold, now, "minting an agent token: "+detail) + e := holdRateLimitError(hold, now, "minting an agent token: "+detail) + if named := retryAfterSeconds(resp.Header.Get("Retry-After"), now); named > holdWait(hold, now) { + // Held for the cap; what the server asked for is kept too, + // so a caller can say both. + e.Cause = errors.Join(e.Cause, namedWaitError(named)) + } + return hold, e } return hold, statusFailure("minting an agent token: "+detail, resp) } diff --git a/internal/auth/agent_hold.go b/internal/auth/agent_hold.go index 114945121..dae04992d 100644 --- a/internal/auth/agent_hold.go +++ b/internal/auth/agent_hold.go @@ -101,10 +101,10 @@ const defaultAgentRateLimitHold = 60 * time.Second const maxAgentMintHold = time.Hour // MaxServerWait is the longest any wait a server names is waited, whatever -// the status or the token path: the same bound as a mint hold, so a held -// rate limit and every other named wait agree. A connector that waited a -// server's word for years would be a hang, not a wait. -const MaxServerWait = maxAgentMintHold +// the status or the token path: the bound a rate-limit hold is written +// under, so a held rate limit and every other named wait agree. A connector +// that waited a server's word for years would be a hang, not a wait. +const MaxServerWait = maxAgentConnectLifetime // MintHold is the token endpoint's last refusal of an agent credential's // client, remembered so the next mint can answer it without asking again. @@ -166,13 +166,13 @@ func mintHoldFor(mint *agentMint, resp *http.Response, detail, code string, refu } // rateLimitHold is how long a 429 holds the mint: its Retry-After, or -// defaultAgentRateLimitHold when it has none, never past maxAgentMintHold. +// defaultAgentRateLimitHold when it has none, never past MaxServerWait. func rateLimitHold(header http.Header, now time.Time) time.Duration { wait := retryAfter(header, now) if wait <= 0 { wait = defaultAgentRateLimitHold } - return min(wait, maxAgentMintHold) + return min(wait, MaxServerWait) } // ceilUnix is t in Unix seconds, rounded up: a deadline stored in whole diff --git a/internal/auth/revoke.go b/internal/auth/revoke.go index 5c2c17903..2c114cf6c 100644 --- a/internal/auth/revoke.go +++ b/internal/auth/revoke.go @@ -291,6 +291,24 @@ func retryAfterSeconds(value string, now time.Time) int { return int(seconds) } +// namedWaitError is the wait a server asked for, in seconds, when what is +// waited is less: a 429 held for the cap rather than for all it named. +type namedWaitError int + +func (s namedWaitError) Error() string { + return fmt.Sprintf("the server asked to wait %d seconds", int(s)) +} + +// NamedWait is the wait, in seconds, the server itself named for err: more +// than RetryAfter when the wait was capped, the same otherwise. +func NamedWait(err error) int { + var s namedWaitError + if errors.As(err, &s) { + return int(s) + } + return RetryAfter(err) +} + // RetryAfter is the wait, in seconds, a rate-limited answer named, or zero // when it named none. func RetryAfter(err error) int { diff --git a/internal/commands/connect.go b/internal/commands/connect.go index 6c32403b2..cf14d17f5 100644 --- a/internal/commands/connect.go +++ b/internal/commands/connect.go @@ -1206,7 +1206,7 @@ func tokenRetry(err error) (time.Duration, bool) { // the agent mint's own, or that of the SDK error an OAuth refresh carries. // Zero when it named none. func serverNamedWait(err error) time.Duration { - seconds := auth.RetryAfter(err) + seconds := auth.NamedWait(err) var sdkErr *basecamp.Error if errors.As(err, &sdkErr) { seconds = max(seconds, sdkErr.RetryAfter) diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index 1ba310d1c..1011d75fa 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -711,3 +711,18 @@ func TestTheFeedSaysWhenItCapsAWait(t *testing.T) { assert.Contains(t, lines[0], "asked to wait 27777h46m39s") assert.Contains(t, lines[0], "waiting "+auth.MaxServerWait.String()) } + +// An agent mint's 429 goes through the same cap as every other named wait, +// and the log says what the server asked for beyond it. +func TestAnAgentRateLimitBeyondTheCapIsCappedAndSaid(t *testing.T) { + tokens, mints := startingAgent(t, + answerStatus(http.StatusTooManyRequests, map[string]string{"Retry-After": "86400"}, ""), + answerStatus(http.StatusOK, nil, mintedToken)) + var w startWaits + require.NoError(t, awaitConnectToken(t.Context(), tokens, w.options(tokens))) + assert.Equal(t, []time.Duration{auth.MaxServerWait}, w.waits, "the hold and the start wait the one cap") + require.Len(t, w.lines, 1) + assert.Contains(t, w.lines[0], "asked to wait 24h0m0s") + assert.Contains(t, w.lines[0], "waiting "+auth.MaxServerWait.String()) + assert.Equal(t, 2, mints(), "the hold had ended when the start tried again") +} From 0921b567982b51ff8d9fddfea4690445e72ffd5c Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Thu, 1 Oct 2026 12:37:04 -0700 Subject: [PATCH 19/20] Read every Retry-After with one parser Two parsers read the header: the agent-connect one, which #787's hold used, read a count too large for an int as no header at all and held for the one-minute default, while the connector's saturated it to the cap. The hold was then shorter than the wait the connector reported, and another process could mint inside it. retryAfter now reads through retryAfterSeconds and applies its own ceiling, so there is one parser and the hold and the reported wait agree. --- internal/auth/agent_connect.go | 21 ++++----------------- internal/auth/agent_hold_test.go | 3 +++ 2 files changed, 7 insertions(+), 17 deletions(-) diff --git a/internal/auth/agent_connect.go b/internal/auth/agent_connect.go index faf460409..fafca6a99 100644 --- a/internal/auth/agent_connect.go +++ b/internal/auth/agent_connect.go @@ -8,7 +8,6 @@ import ( "io" "net/http" "net/url" - "strconv" "strings" "time" "unicode" @@ -766,23 +765,11 @@ func agentConnectBackoff(answer *agentConnectAnswer, interval time.Duration) tim // for nothing this can read. The date form is what a proxy in front of the // server is as likely to send as the server itself, and reading only the // seconds form would answer a mandated wait with the five-second step and -// earn the next refusal. +// earn the next refusal. It is read by retryAfterSeconds, the one parser +// every Retry-After goes through, so a count too large to hold is the cap +// here too, not a header nothing could read. func retryAfter(header http.Header, now time.Time) time.Duration { - value := strings.TrimSpace(header.Get("Retry-After")) - if value == "" { - return 0 - } - if seconds, err := strconv.Atoi(value); err == nil { - if seconds <= 0 { - return 0 - } - return reportedSeconds(seconds, maxAgentConnectLifetime) - } - when, err := http.ParseTime(value) - if err != nil { - return 0 - } - return min(max(when.Sub(now), 0), maxAgentConnectLifetime) + return min(time.Duration(retryAfterSeconds(header.Get("Retry-After"), now))*time.Second, maxAgentConnectLifetime) } // agentConnectExpired is the one ending that is nobody's fault: the code diff --git a/internal/auth/agent_hold_test.go b/internal/auth/agent_hold_test.go index cd9ac4147..a6968f88e 100644 --- a/internal/auth/agent_hold_test.go +++ b/internal/auth/agent_hold_test.go @@ -226,6 +226,9 @@ func TestARateLimitHoldIsBounded(t *testing.T) { }{ "no Retry-After": {func(time.Time) http.Header { return nil }, defaultAgentRateLimitHold}, "an absurd one": {retryAfter("86400"), maxAgentConnectLifetime}, + // Too large for an int: still the cap, never the one-minute default + // a header nothing could read gets. + "an overflowing one": {retryAfter("99999999999999999999999"), MaxServerWait}, "an HTTP-date": {func(now time.Time) http.Header { return http.Header{"Retry-After": {now.Add(10 * time.Minute).UTC().Format(http.TimeFormat)}} }, 10 * time.Minute}, From ecc90a7e6c2bd05b4ecf4ed8c478b00f35aff6b6 Mon Sep 17 00:00:00 2001 From: Jeremy Daer Date: Thu, 1 Oct 2026 12:49:39 -0700 Subject: [PATCH 20/20] Say a capped refresh wait as the server named it A bot user's refresh reaches the start wrapped in this package's SDK error, whose wait is already capped, and the start's log read only that outer error: it said the cap as if the server had asked for it. Every SDK error down the chain is read now, so the log says what was asked and what is waited. --- internal/commands/connect.go | 12 +++++++++--- internal/commands/connect_start_wait_test.go | 10 ++++++++++ 2 files changed, 19 insertions(+), 3 deletions(-) diff --git a/internal/commands/connect.go b/internal/commands/connect.go index cf14d17f5..3b8597511 100644 --- a/internal/commands/connect.go +++ b/internal/commands/connect.go @@ -1204,12 +1204,18 @@ func tokenRetry(err error) (time.Duration, bool) { // serverNamedWait is the wait the server named for err, as it named it: // the agent mint's own, or that of the SDK error an OAuth refresh carries. -// Zero when it named none. +// Every SDK error down the chain is read, not only the first, since the +// first may be this package's own capped wrapping of the one the server +// gave. Zero when it named none. func serverNamedWait(err error) time.Duration { seconds := auth.NamedWait(err) - var sdkErr *basecamp.Error - if errors.As(err, &sdkErr) { + for next := err; next != nil; { + var sdkErr *basecamp.Error + if !errors.As(next, &sdkErr) { + break + } seconds = max(seconds, sdkErr.RetryAfter) + next = sdkErr.Cause } return time.Duration(max(seconds, 0)) * time.Second } diff --git a/internal/commands/connect_start_wait_test.go b/internal/commands/connect_start_wait_test.go index 1011d75fa..901e4c2df 100644 --- a/internal/commands/connect_start_wait_test.go +++ b/internal/commands/connect_start_wait_test.go @@ -726,3 +726,13 @@ func TestAnAgentRateLimitBeyondTheCapIsCappedAndSaid(t *testing.T) { assert.Contains(t, w.lines[0], "waiting "+auth.MaxServerWait.String()) assert.Equal(t, 2, mints(), "the hold had ended when the start tried again") } + +// A refresh's wait, once wrapped for the SDK with the cap, still reads +// back as what the server named, so the start's log says both. +func TestACappedRefreshWaitStillSaysWhatWasNamed(t *testing.T) { + refresh := &output.Error{Code: output.CodeRateLimit, Message: "token refresh failed", HTTPStatus: 429, Retryable: true, + Cause: basecamp.ErrRateLimit(99999999)} + wrapped := tokenFailureInSDKTerms(refresh) + assert.Equal(t, auth.MaxServerWait, time.Duration(wrapped.RetryAfter)*time.Second) + assert.Equal(t, 99999999*time.Second, serverNamedWait(wrapped)) +}