diff --git a/internal/auth/agent.go b/internal/auth/agent.go index e7dda7ffa..78a6996d8 100644 --- a/internal/auth/agent.go +++ b/internal/auth/agent.go @@ -351,14 +351,18 @@ 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 { - return nil, nil, wrapOAuthError("minting an agent token", 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 { return nil, nil, output.ErrAPI(resp.StatusCode, @@ -482,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_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.go b/internal/auth/agent_hold.go index e24457c3d..dae04992d 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 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. // @@ -160,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 @@ -184,10 +190,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 +221,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/agent_hold_test.go b/internal/auth/agent_hold_test.go index f7b8fc950..a6968f88e 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") @@ -223,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}, 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/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 7525ad414..2c114cf6c 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" @@ -224,14 +225,18 @@ 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: - 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 + if retryAfter > 0 { + e.Cause = retryAfterError(retryAfter) + } return e case http.StatusInsufficientStorage: e := output.ErrAPI(resp.StatusCode, msg) @@ -240,10 +245,80 @@ 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 } } +// 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)) } + +// 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) { + if seconds > maxRetryAfterSeconds { + return maxRetryAfterSeconds + } + return int(seconds) + } + when, err := http.ParseTime(value) + if err != nil { + return 0 + } + seconds := math.Ceil(when.Sub(now).Seconds()) + switch { + case seconds <= 0: + return 0 + case seconds > maxRetryAfterSeconds: + return maxRetryAfterSeconds + } + 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 { + 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..3b8597511 100644 --- a/internal/commands/connect.go +++ b/internal/commands/connect.go @@ -4,14 +4,18 @@ import ( "context" "errors" "fmt" + "net" "net/http" + "net/url" "os" "path/filepath" "runtime" "strconv" "strings" + "time" "unicode" + surfguard "github.com/basecamp/surfguard/go" "github.com/spf13/cobra" "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" @@ -1101,8 +1105,138 @@ 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) { - return t.mgr.AccessToken(ctx) + token, err := t.mgr.AccessToken(ctx) + if e := tokenFailureInSDKTerms(err); e != nil && e.Retryable && e.HTTPStatus != 0 { + return token, e + } + return token, err +} + +// 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 + // 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) + e := tokenFailureInSDKTerms(err) + if e == nil { + 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 +// by tokenRetry, or nil when there was no failure. A retryable one keeps +// 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 +// 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) + 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.RetryAfter = int(asked / time.Second) + switch e.HTTPStatus { + case http.StatusTooManyRequests: + e.Code = basecamp.CodeRateLimit + case 0: + e.Code = basecamp.CodeNetwork + } + return e +} + +// tokenRetry is the one rule for a failed token renewal, which the running +// 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. +// +// 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 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 + } + var cliErr *output.Error + switch { + case errors.As(err, &cliErr) && cliErr.Retryable: + // 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. +// 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) + 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 +} + +// 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 + } + 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 c2743cf32..5c59e7034 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,17 +169,43 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { if err != nil { return output.ErrAuth("The stored credential could not be read: " + setup.ErrorText(err)) } + // 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()) + } + if err := connectLockFree(stateDir, account, file.Agent.PersonID); err != nil { + return 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() + select { + case sig, ok := <-startSignals: + // Delivered after the wait had finished, before the stop took. + if ok { + return connectStoppedBySignal(sig) + } + default: + } + if err != nil { + return connectStartFailure(ctx, 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(ctx, kind, name, err) } if _, err := checkConnectIdentity(ctx, app, client, kind, creds.OAuthType, me, file.Agent.IdentityID); err != nil { return err @@ -189,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 { @@ -196,26 +226,12 @@ 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 } 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. @@ -237,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}, 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 } @@ -352,10 +368,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) } @@ -386,6 +400,44 @@ 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. +// 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(ctx context.Context, kind, profile string, err error) error { + var e *output.Error + switch { + case ctx.Err() != nil, + 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_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.go b/internal/commands/connect_start_wait.go new file mode 100644 index 000000000..8389317ef --- /dev/null +++ b/internal/commands/connect_start_wait.go @@ -0,0 +1,174 @@ +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/connector" + "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 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 + // 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)) +} + +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 +// 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. +// +// 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, 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, ok := <-w.Signals: + if !ok { + return + } + 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, ok := <-w.Signals: + if ok { + w.forceStop(sig) + } + case <-done: + } + }() + err := awaitToken(ctx, tokens, w) + cancel() + close(done) + <-watched + if stopped != nil { + return stopped + } + select { + case sig, ok := <-w.Signals: + if ok { + return connectStoppedBySignal(sig) + } + default: + } + return err +} + +func awaitToken(ctx context.Context, tokens basecamp.TokenProvider, w connectStartWait) error { + sleep := w.Sleep + if sleep == nil { + sleep = sleepUnlessCanceled + } + 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(connectWaitLine(output.AsError(err).Message, serverNamedWait(err), wait)) + if err := sleep(ctx, wait); err != nil { + return err + } + } +} + +// 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 { + 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 +} + +// 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 { + case <-timer.C: + return nil + case <-ctx.Done(): + return ctx.Err() + } +} + +// 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") +} + +// 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 new file mode 100644 index 000000000..901e4c2df --- /dev/null +++ b/internal/commands/connect_start_wait_test.go @@ -0,0 +1,738 @@ +package commands + +import ( + "bytes" + "context" + "crypto/tls" + "crypto/x509" + "errors" + "fmt" + "io" + "net" + "net/http" + "net/http/httptest" + "net/url" + "os" + "strings" + "sync" + "syscall" + "testing" + "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" + + "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" + "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}` + +// 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)) (*startTokens, 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(), + })) + // 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 +// each, without spending them. +type startWaits struct { + waits []time.Duration + lines []string +} + +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 + }, + } +} + +// 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(tokens))) + 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(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) + } + 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()) +} + +// 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(tokens))) + 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(tokens)) + 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) + }) + } +} + +// 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) { + 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) + } + } +} + +// 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 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(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(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}), + } { + 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(tokens)) + require.Error(t, err) + assert.ErrorIs(t, err, auth.ErrAgentCredentialRefused) + assert.Equal(t, errAgentDisconnected("", "agent"), connectStartFailure(t.Context(), 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(tokens)), status) + assert.Len(t, w.waits, 1, status) + assert.Equal(t, 2, mints(), status) + } +} + +// 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") + + 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(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) +} + +// 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) +} + +// 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") + +} + +// 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()) +} + +// 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") +} + +// 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 +} + +// 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()) +} + +// 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") +} + +// 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)) +} diff --git a/internal/commands/connect_token_retry_test.go b/internal/commands/connect_token_retry_test.go new file mode 100644 index 000000000..aa529f46a --- /dev/null +++ b/internal/commands/connect_token_retry_test.go @@ -0,0 +1,253 @@ +package commands + +import ( + "errors" + "fmt" + "io" + "net/http" + "net/http/httptest" + "net/url" + "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 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) { + 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}, &feedTokens{managerTokens: 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. 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"}`)) + + _, 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, 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.InDelta(t, 42*time.Second, pollErr.RetryAfter, float64(time.Second)) + + 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. +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 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.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 +// 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) { + // The handler runs off the test goroutine, where only assert is safe. + hj, ok := w.(http.Hijacker) + if !assert.True(t, ok) { + return + } + conn, _, err := hj.Hijack() + if !assert.NoError(t, err) { + return + } + _ = 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 TestAFailedRenewalKeepsTheCLIsMessage(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) +} + +// 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{ + refused, + output.ErrAPI(http.StatusNotFound, "minting an agent token: the server answered HTTP 404"), + errors.New("the store could not be read"), + } { + 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) +} 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