diff --git a/internal/commands/files.go b/internal/commands/files.go index 4b117bb47..5d13b81b9 100644 --- a/internal/commands/files.go +++ b/internal/commands/files.go @@ -1504,8 +1504,7 @@ You can pass either an item ID or a Basecamp URL: // If all probes failed, check if first error was 404 or something else if result == nil && firstErr != nil { - sdkErr := basecamp.AsError(firstErr) - if sdkErr.Code != basecamp.CodeNotFound { + if sdkErr := basecamp.AsError(firstErr); sdkErr == nil || sdkErr.Code != basecamp.CodeNotFound { // Return actual error (auth, permission, network, etc.) return convertSDKError(firstErr) } @@ -2155,8 +2154,7 @@ You can pass either an item ID or a Basecamp URL: detectedType = "upload" } else { // All probes failed - check if first error was 404 or something else - sdkErr := basecamp.AsError(firstErr) - if sdkErr.Code != basecamp.CodeNotFound { + if sdkErr := basecamp.AsError(firstErr); sdkErr == nil || sdkErr.Code != basecamp.CodeNotFound { // Return actual error (auth, permission, network, etc.) return convertSDKError(firstErr) } diff --git a/internal/commands/projects.go b/internal/commands/projects.go index e696eaeef..70f4748bd 100644 --- a/internal/commands/projects.go +++ b/internal/commands/projects.go @@ -433,6 +433,11 @@ func convertSDKError(err error) error { return nil } + // A gate that queued and gave up says which limit, how long, and what to do + if gateErr := output.AsGateError(err); gateErr != nil { + return gateErr + } + // Handle resilience sentinel errors (use errors.Is for wrapped errors) if errors.Is(err, basecamp.ErrRateLimited) { return &output.Error{ diff --git a/internal/commands/projects_test.go b/internal/commands/projects_test.go index 557720f3f..d3a812f1a 100644 --- a/internal/commands/projects_test.go +++ b/internal/commands/projects_test.go @@ -2,13 +2,16 @@ package commands import ( "bytes" + "context" "encoding/json" "fmt" "io" "net/http" "net/http/httptest" + "os" "strings" "testing" + "time" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -20,6 +23,7 @@ import ( "github.com/basecamp/basecamp-cli/internal/config" "github.com/basecamp/basecamp-cli/internal/names" "github.com/basecamp/basecamp-cli/internal/output" + "github.com/basecamp/basecamp-cli/internal/resilience" ) type mockProjectUpdateTransport struct { @@ -190,3 +194,26 @@ func TestProjectsCreateErrorEnvelopeCarriesRetryable(t *testing.T) { }) } } + +// A gate that queued and gave up reaches the user with its own message and +// hint (which limit, how long it waited, what to do) rather than the generic +// sentinel wording, while keeping the rate-limit code and retryable flag. +func TestConvertSDKErrorCarriesTheGateMessageAndHint(t *testing.T) { + store := resilience.NewStore(t.TempDir()) + require.NoError(t, store.Update(func(state *resilience.State) error { + state.Bulkhead.ActivePIDs = []int{os.Getppid()} + return nil + })) + bh := resilience.NewBulkhead(store, resilience.BulkheadConfig{MaxConcurrent: 1}) + gateErr := bh.Wait(context.Background(), time.Now()) + require.Error(t, gateErr) + + err := convertSDKError(fmt.Errorf("listing projects: %w", gateErr)) + + var outErr *output.Error + require.ErrorAs(t, err, &outErr) + assert.Equal(t, basecamp.CodeRateLimit, outErr.Code) + assert.Equal(t, "Too many concurrent basecamp processes (limit 1); waited 0s", outErr.Message) + assert.Equal(t, "Re-run, or lower parallelism.", outErr.Hint) + assert.True(t, outErr.Retryable) +} diff --git a/internal/names/resolver.go b/internal/names/resolver.go index b8957c423..f58bc9017 100644 --- a/internal/names/resolver.go +++ b/internal/names/resolver.go @@ -689,6 +689,11 @@ func convertSDKError(err error) error { return nil } + // A gate that queued and gave up says which limit, how long, and what to do + if gateErr := output.AsGateError(err); gateErr != nil { + return gateErr + } + // Handle resilience sentinel errors (use errors.Is for wrapped errors) if errors.Is(err, basecamp.ErrRateLimited) { return &output.Error{ diff --git a/internal/output/errors.go b/internal/output/errors.go index 76c6676a0..d9ec24c57 100644 --- a/internal/output/errors.go +++ b/internal/output/errors.go @@ -7,6 +7,8 @@ import ( "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" clioutput "github.com/basecamp/cli/output" + + "github.com/basecamp/basecamp-cli/internal/resilience" ) // Error is a structured error with code, message, and optional hint. @@ -32,6 +34,9 @@ func ErrAmbiguous(resource string, matches []string) *Error { } func AsError(err error) *Error { + if gateErr := AsGateError(err); gateErr != nil { + return gateErr + } var sdkErr *basecamp.Error if errors.As(err, &sdkErr) { message := err.Error() @@ -53,6 +58,23 @@ func AsError(err error) *Error { return clioutput.AsError(err) } +// AsGateError converts a resilience gate rejection, which arrives through +// any SDK operation, into the rate-limit error the user sees: the gate's own +// message and hint (which limit, how long it waited, what to do), retryable. +// Nil when err is not a gate rejection. +func AsGateError(err error) *Error { + var gateErr *resilience.GateError + if !errors.As(err, &gateErr) { + return nil + } + return &Error{ + Code: CodeRateLimit, + Message: gateErr.Message, + Hint: gateErr.Hint, + Retryable: true, + } +} + // RequestID returns the SDK request ID carried by err, if present. func RequestID(err error) string { var sdkErr *basecamp.Error diff --git a/internal/output/gate_error_test.go b/internal/output/gate_error_test.go new file mode 100644 index 000000000..5a38ce29d --- /dev/null +++ b/internal/output/gate_error_test.go @@ -0,0 +1,34 @@ +package output + +import ( + "context" + "fmt" + "os" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/basecamp/basecamp-cli/internal/resilience" +) + +// A gate rejection reaches the user with its own message and hint through +// the central conversion too, so commands that return SDK errors directly +// render the same thing as those that call convertSDKError. +func TestAsErrorCarriesTheGateMessageAndHint(t *testing.T) { + store := resilience.NewStore(t.TempDir()) + require.NoError(t, store.Update(func(state *resilience.State) error { + state.Bulkhead.ActivePIDs = []int{os.Getppid()} + return nil + })) + gateErr := resilience.NewBulkhead(store, resilience.BulkheadConfig{MaxConcurrent: 1}).Wait(context.Background(), time.Now()) + require.Error(t, gateErr) + + err := AsError(fmt.Errorf("listing chat lines: %w", gateErr)) + + assert.Equal(t, CodeRateLimit, err.Code) + assert.Equal(t, "Too many concurrent basecamp processes (limit 1); waited 0s", err.Message) + assert.Equal(t, "Re-run, or lower parallelism.", err.Hint) + assert.True(t, err.Retryable) +} diff --git a/internal/resilience/bulkhead.go b/internal/resilience/bulkhead.go index 781f459ac..0ae3ce2f5 100644 --- a/internal/resilience/bulkhead.go +++ b/internal/resilience/bulkhead.go @@ -1,8 +1,12 @@ package resilience import ( + "context" + "fmt" "os" "time" + + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" ) // Bulkhead implements the bulkhead pattern with cross-process persistence. @@ -82,6 +86,44 @@ func (b *Bulkhead) Acquire() (bool, error) { return acquired, nil } +// slotPoll is the base interval between slot attempts while queued. A slot +// frees when another process finishes its operation, which is network-bound, +// so tens of milliseconds is fine-grained enough without hammering the lock. +const slotPoll = 25 * time.Millisecond + +// Wait acquires a slot, polling with jitter until deadline. It returns nil +// once the slot is held (Acquire fails open on a store error), a *GateError +// once the deadline has passed, or ctx.Err(). Cancellation and the deadline +// are checked before every attempt, so an expired or canceled gate reserves +// nothing, and cancellation outranks the deadline. +func (b *Bulkhead) Wait(ctx context.Context, deadline time.Time) error { + return b.waitSince(ctx, b.now(), deadline) +} + +// waitSince is Wait for a gate that started queueing at start, so the wait +// it reports covers the whole gate and not only the slot phase. +func (b *Bulkhead) waitSince(ctx context.Context, start, deadline time.Time) error { + for { + if err := ctx.Err(); err != nil { + return err + } + remaining := deadline.Sub(b.now()) + if remaining <= 0 { + return &GateError{ + Message: fmt.Sprintf("Too many concurrent basecamp processes (limit %d); waited %s", b.config.MaxConcurrent, b.now().Sub(start).Round(time.Second)), + Hint: "Re-run, or lower parallelism.", + sentinel: basecamp.ErrBulkheadFull, + } + } + if acquired, _ := b.Acquire(); acquired { //nolint:contextcheck // lock acquisition is context-independent by design + return nil + } + if err := pause(ctx, min(jittered(slotPoll), remaining)); err != nil { + return err + } + } +} + // Release releases the slot held by this process. func (b *Bulkhead) Release() error { return b.store.Update(func(state *State) error { diff --git a/internal/resilience/circuit_breaker.go b/internal/resilience/circuit_breaker.go index d904c4db9..65325f541 100644 --- a/internal/resilience/circuit_breaker.go +++ b/internal/resilience/circuit_breaker.go @@ -40,6 +40,15 @@ func (cb *CircuitBreaker) now() time.Time { return cb.nowFn() } +// Tripped reports whether the circuit is open with its timeout still running: +// the one state Allow rejects without writing anything. Read here so a gate +// can fail fast before queueing for a token it would only be refused with. +func (cb *CircuitBreaker) Tripped() bool { + state, err := cb.store.Load() + return err == nil && state.CircuitBreaker.IsOpen() && + cb.now().Sub(state.CircuitBreaker.OpenedAt) < cb.config.OpenTimeout +} + // Allow checks if a request should be allowed. // Returns true if the request can proceed, false if it should be rejected. // In half-open state, atomically reserves an attempt slot to prevent thundering herd. diff --git a/internal/resilience/config.go b/internal/resilience/config.go index 23db671b6..c9640598b 100644 --- a/internal/resilience/config.go +++ b/internal/resilience/config.go @@ -6,6 +6,13 @@ import ( // Config holds configuration for all resilience primitives. type Config struct { + // MaxWait bounds how long a gated operation queues for a rate-limiter + // token or a bulkhead slot before it is rejected. Parallel invocations + // of the CLI share one bucket and one slot table, so a burst that would + // otherwise fail fast waits its turn instead. + // Default: 10 seconds + MaxWait time.Duration + // CircuitBreaker configures the circuit breaker pattern. CircuitBreaker CircuitBreakerConfig @@ -67,6 +74,7 @@ type BulkheadConfig struct { // DefaultConfig returns a Config with sensible defaults for the Basecamp API. func DefaultConfig() *Config { return &Config{ + MaxWait: DefaultMaxWait, CircuitBreaker: CircuitBreakerConfig{ FailureThreshold: 5, SuccessThreshold: 2, diff --git a/internal/resilience/gate.go b/internal/resilience/gate.go new file mode 100644 index 000000000..c19e0cb4c --- /dev/null +++ b/internal/resilience/gate.go @@ -0,0 +1,60 @@ +package resilience + +import ( + "context" + "math/rand/v2" + "time" +) + +// DefaultMaxWait is how long OnOperationGate queues for a token or a slot +// before giving up. It is long enough to absorb a burst of parallel CLI +// invocations (10 workers draining a 50-token bucket refill at 10/s in well +// under a second) and short enough that a genuinely saturated machine still +// fails within one attention span. +const DefaultMaxWait = 10 * time.Second + +// GateError is a gate rejection that already waited its turn. It unwraps to +// the SDK sentinel (basecamp.ErrRateLimited or basecamp.ErrBulkheadFull) so +// existing errors.Is checks keep working, and carries the message and hint +// the CLI shows: which limit, how long it waited, and what to do. +type GateError struct { + Message string + Hint string + sentinel error +} + +func (e *GateError) Error() string { return e.Message } + +// Unwrap returns the SDK sentinel the rejection stands for. +func (e *GateError) Unwrap() error { return e.sentinel } + +// pause sleeps for d or until ctx is done, whichever comes first. +func pause(ctx context.Context, d time.Duration) error { + timer := time.NewTimer(d) + defer timer.Stop() + select { + case <-ctx.Done(): + return ctx.Err() + case <-timer.C: + return nil + } +} + +// jittered stretches d by up to half again so that processes which woke +// together do not retry in lockstep and starve each other at the lock. +func jittered(d time.Duration) time.Duration { + return d + jitter(d) +} + +// jitter is the random stretch jittered adds; a variable so tests can pin it. +var jitter = func(d time.Duration) time.Duration { + return rand.N(d/2 + 1) //nolint:gosec // jitter spreads retries; it guards nothing +} + +// ceilSeconds rounds d up to a whole second. +func ceilSeconds(d time.Duration) time.Duration { + if d%time.Second == 0 { + return d + } + return d.Truncate(time.Second) + time.Second +} diff --git a/internal/resilience/gate_test.go b/internal/resilience/gate_test.go new file mode 100644 index 000000000..43f24bf88 --- /dev/null +++ b/internal/resilience/gate_test.go @@ -0,0 +1,609 @@ +package resilience + +import ( + "bufio" + "bytes" + "context" + "errors" + "fmt" + "io" + "os" + "os/exec" + "strconv" + "strings" + "sync" + "testing" + "time" + + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" + "github.com/gofrs/flock" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// TestHelperProcess is the re-exec target for the multi-process tests below: +// each child is one CLI invocation against the shared store in BH_STATE_DIR. +// +// BH_MODE=ops runs BH_OPS gated operations, each held for BH_HOLD, and prints +// OK or REJECT per operation plus PEAK, the most live slot holders it saw +// while holding one. BH_MODE=linger churns BH_OPS acquire/release pairs, prints +// DONE, then stays alive until stdin closes so the parent can check that its +// releases were not lost while the process still counts as a live holder. +func TestHelperProcess(t *testing.T) { + if os.Getenv("BH_HELPER") != "1" { + return + } + store := NewStore(os.Getenv("BH_STATE_DIR")) + ops, _ := strconv.Atoi(os.Getenv("BH_OPS")) + hold, _ := time.ParseDuration(os.Getenv("BH_HOLD")) + cfg := DefaultConfig() + if tokens, err := strconv.ParseFloat(os.Getenv("BH_MAX_TOKENS"), 64); err == nil { + cfg.RateLimiter.MaxTokens = tokens + } + + switch os.Getenv("BH_MODE") { + case "ops": + hooks := NewGatingHooksFromConfig(store, cfg) + op := basecamp.OperationInfo{Service: "Projects", Operation: "List"} + peak := 0 + for range ops { + ctx, err := hooks.OnOperationGate(context.Background(), op) + if err != nil { + fmt.Printf("REJECT %v\n", err) + continue + } + if inUse, err := hooks.bulkhead.InUse(); err == nil { + peak = max(peak, inUse) + } + time.Sleep(hold) + hooks.OnOperationEnd(ctx, op, nil, hold) + fmt.Println("OK") + } + fmt.Printf("PEAK %d\n", peak) + case "linger": + bh := NewBulkhead(store, cfg.Bulkhead) + rl := NewRateLimiter(store, cfg.RateLimiter) + for range ops { + _, _ = rl.Allow() + _, _ = bh.Acquire() + _ = bh.Release() + } + fmt.Println("DONE") + _, _ = io.ReadAll(os.Stdin) + } + os.Exit(0) +} + +type helperEnv map[string]string + +func helperCommand(t *testing.T, env helperEnv) *exec.Cmd { + t.Helper() + cmd := exec.CommandContext(t.Context(), os.Args[0], "-test.run=^TestHelperProcess$") + cmd.Env = append(os.Environ(), "BH_HELPER=1") + for k, v := range env { + cmd.Env = append(cmd.Env, k+"="+v) + } + return cmd +} + +// runInvocation runs one child to completion and returns its report lines. +func runInvocation(t *testing.T, env helperEnv) []string { + t.Helper() + cmd := helperCommand(t, env) + var out bytes.Buffer + cmd.Stdout, cmd.Stderr = &out, &out + require.NoError(t, cmd.Run(), out.String()) + var lines []string + for _, l := range strings.Split(out.String(), "\n") { + if strings.HasPrefix(l, "OK") || strings.HasPrefix(l, "REJECT") || strings.HasPrefix(l, "PEAK") { + lines = append(lines, l) + } + } + return lines +} + +type invocationTally struct { + ok, rejected, peak int + rejections []string +} + +func tally(lines []string) invocationTally { + var tl invocationTally + for _, l := range lines { + switch { + case l == "OK": + tl.ok++ + case strings.HasPrefix(l, "REJECT"): + tl.rejected++ + tl.rejections = append(tl.rejections, l) + case strings.HasPrefix(l, "PEAK"): + n, _ := strconv.Atoi(strings.TrimPrefix(l, "PEAK ")) + tl.peak = max(tl.peak, n) + } + } + return tl +} + +// runWorkers runs `workers` goroutines that each perform `calls` sequential +// child invocations, the shape of a parallel smoke test, and tallies the lot. +func runWorkers(t *testing.T, workers, calls int, env helperEnv) invocationTally { + t.Helper() + var mu sync.Mutex + var all []string + var wg sync.WaitGroup + for range workers { + wg.Add(1) + go func() { + defer wg.Done() + for range calls { + lines := runInvocation(t, env) + mu.Lock() + all = append(all, lines...) + mu.Unlock() + } + }() + } + wg.Wait() + return tally(all) +} + +// The smoke-test shape: ten workers each making eight sequential calls +// through the production defaults. Before queueing, the shared 50-token +// bucket drained in the first half second and every later call failed with +// "rate limit exceeded" while the server had never answered 429. +func TestGateQueuesTenParallelWorkersThroughTheDefaults(t *testing.T) { + dir := t.TempDir() + start := time.Now() + tl := runWorkers(t, 10, 8, helperEnv{"BH_STATE_DIR": dir, "BH_MODE": "ops", "BH_OPS": "1", "BH_HOLD": "10ms"}) + + assert.Equal(t, 80, tl.ok, "every call succeeds: %v", tl.rejections) + assert.Zero(t, tl.rejected) + assert.LessOrEqual(t, tl.peak, 10, "never more than MaxConcurrent live holders") + assert.Less(t, time.Since(start), DefaultMaxWait) +} + +// Fifteen simultaneous invocations against ten slots: nobody fails, nobody +// sees more than ten holders, and the wall clock shows the overflow waited +// for a second round rather than being admitted alongside the first. +func TestGateQueuesOversubscribedInvocationsWithinTheSlotLimit(t *testing.T) { + dir := t.TempDir() + hold := 150 * time.Millisecond + start := time.Now() + tl := runWorkers(t, 15, 1, helperEnv{ + "BH_STATE_DIR": dir, "BH_MODE": "ops", "BH_OPS": "1", + "BH_HOLD": hold.String(), "BH_MAX_TOKENS": "100", + }) + elapsed := time.Since(start) + + assert.Equal(t, 15, tl.ok, "every invocation succeeds: %v", tl.rejections) + assert.LessOrEqual(t, tl.peak, 10, "never more than MaxConcurrent live holders") + assert.GreaterOrEqual(t, elapsed, 2*hold, "the overflow waited for a slot") + assert.Less(t, elapsed, DefaultMaxWait) + + state, err := NewStore(dir).Load() + require.NoError(t, err) + assert.Empty(t, state.Bulkhead.ActivePIDs, "every slot released") +} + +// A dozen processes churning the lock must not lose each other's releases: +// while every child is still alive (so a leaked PID would not be swept as +// dead) the slot table is empty. +func TestStoreLockContentionDoesNotLoseReleases(t *testing.T) { + dir := t.TempDir() + const children = 12 + type child struct { + cmd *exec.Cmd + stdin io.WriteCloser + } + kids := make([]child, 0, children) + done := make(chan error, children) + for range children { + cmd := helperCommand(t, helperEnv{"BH_STATE_DIR": dir, "BH_MODE": "linger", "BH_OPS": "40"}) + stdin, err := cmd.StdinPipe() + require.NoError(t, err) + stdout, err := cmd.StdoutPipe() + require.NoError(t, err) + require.NoError(t, cmd.Start()) + kids = append(kids, child{cmd, stdin}) + go func() { + scanner := bufio.NewScanner(stdout) + for scanner.Scan() { + if scanner.Text() == "DONE" { + done <- nil + return + } + } + done <- errors.New("child exited without DONE") + }() + } + for range children { + require.NoError(t, <-done) + } + + state, err := NewStore(dir).Load() + require.NoError(t, err) + assert.Empty(t, state.Bulkhead.ActivePIDs, "a live process still holds a slot it released") + + for _, k := range kids { + _ = k.stdin.Close() + _ = k.cmd.Wait() + } +} + +func TestRateLimiterWaitSleepsForARefill(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{MaxTokens: 1, RefillRate: 100, TokensPerRequest: 1}) + allowed, err := rl.Allow() + require.NoError(t, err) + require.True(t, allowed) + + start := time.Now() + require.NoError(t, rl.Wait(context.Background(), start.Add(time.Second))) + assert.GreaterOrEqual(t, time.Since(start), 5*time.Millisecond, "waited for the token to refill") +} + +func TestRateLimiterWaitGivesUpWhenTheRefillOutlastsTheDeadline(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{MaxTokens: 1, RefillRate: 10, TokensPerRequest: 1}) + _, _ = rl.Allow() + + err := rl.Wait(context.Background(), time.Now().Add(20*time.Millisecond)) + + var gateErr *GateError + require.ErrorAs(t, err, &gateErr) + assert.ErrorIs(t, err, basecamp.ErrRateLimited) + assert.Equal(t, "Too many requests (client limit 10/s); waited 0s", gateErr.Message) + assert.Equal(t, "Re-run, or lower parallelism.", gateErr.Hint) +} + +func TestRateLimiterWaitReportsTheEffectiveRequestRate(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{MaxTokens: 5, RefillRate: 10, TokensPerRequest: 5}) + _, _ = rl.Allow() + + err := rl.Wait(context.Background(), time.Now().Add(20*time.Millisecond)) + + var gateErr *GateError + require.ErrorAs(t, err, &gateErr) + assert.Equal(t, "Too many requests (client limit 2/s); waited 0s", gateErr.Message) +} + +// holdStoreLock takes the store's lock from a second file description and +// keeps it for d, the way a busy neighboring process would. +func holdStoreLock(t *testing.T, store *Store, d time.Duration) { + t.Helper() + require.NoError(t, os.MkdirAll(store.Dir(), 0o700)) + held := flock.New(store.lockPath()) + require.NoError(t, held.Lock()) + go func() { + time.Sleep(d) + _ = held.Unlock() + }() +} + +// An Update that meets a held lock waits for it within LockTimeout and lands +// on the state the holder left, where a budget shorter than the hold falls +// open and writes over it. The production budget is the wide one. +func TestStoreLockTimeoutCoversAHeldLock(t *testing.T) { + previous := LockTimeout + t.Cleanup(func() { LockTimeout = previous }) + const hold = 150 * time.Millisecond + + update := func(dir string) (waited time.Duration) { + store := NewStore(dir) + require.NoError(t, store.Save(&State{Bulkhead: BulkheadState{ActivePIDs: []int{os.Getppid()}}})) + holdStoreLock(t, store, hold) + start := time.Now() + require.NoError(t, store.Update(func(state *State) error { + state.Bulkhead.AddPID(os.Getpid()) + return nil + })) + return time.Since(start) + } + + LockTimeout = 2 * time.Second + assert.GreaterOrEqual(t, update(t.TempDir()), hold, "waited for the holder") + + LockTimeout = 20 * time.Millisecond + assert.Less(t, update(t.TempDir()), hold, "fell open before the holder released") +} + +func TestRateLimiterWaitOutlastsAShortRetryAfter(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) + require.NoError(t, rl.SetRetryAfterDuration(30*time.Millisecond)) + + start := time.Now() + require.NoError(t, rl.Wait(context.Background(), start.Add(time.Second))) + assert.GreaterOrEqual(t, time.Since(start), 30*time.Millisecond, "sent nothing before the block lifted") +} + +func TestRateLimiterWaitReportsALongRetryAfterImmediately(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) + require.NoError(t, rl.SetRetryAfterDuration(30*time.Second)) + + start := time.Now() + err := rl.Wait(context.Background(), start.Add(100*time.Millisecond)) + + var gateErr *GateError + require.ErrorAs(t, err, &gateErr) + assert.ErrorIs(t, err, basecamp.ErrRateLimited) + assert.Equal(t, "Rate limited by the server; retry after 30s", gateErr.Message) + assert.Equal(t, "Wait 30s, then re-run.", gateErr.Hint) + assert.Less(t, time.Since(start), 100*time.Millisecond, "did not burn the budget on a block it cannot outlast") +} + +// The jitter that spreads retries must not stretch a sleep to or past the +// budget: a block that lifts just inside the deadline is waited out and the +// token taken, not overshot or rejected at the wire. Pinned to the maximum +// jitter, which unchecked would overshoot by half. +func TestRateLimiterWaitNeverSleepsPastTheDeadline(t *testing.T) { + previous := jitter + jitter = func(d time.Duration) time.Duration { return d / 2 } + t.Cleanup(func() { jitter = previous }) + + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) + require.NoError(t, rl.SetRetryAfterDuration(200*time.Millisecond)) + + start := time.Now() + budget := 220 * time.Millisecond + require.NoError(t, rl.Wait(context.Background(), start.Add(budget))) + assert.Less(t, time.Since(start), budget+60*time.Millisecond) +} + +func TestRateLimiterWaitRoundsTheRetryAfterUp(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) + require.NoError(t, rl.SetRetryAfterDuration(40*time.Second+400*time.Millisecond)) + + err := rl.Wait(context.Background(), time.Now().Add(time.Second)) + + var gateErr *GateError + require.ErrorAs(t, err, &gateErr) + assert.Equal(t, "Rate limited by the server; retry after 41s", gateErr.Message) + assert.Equal(t, "Wait 41s, then re-run.", gateErr.Hint) +} + +func TestCeilSeconds(t *testing.T) { + assert.Equal(t, 41*time.Second, ceilSeconds(40*time.Second+time.Millisecond)) + assert.Equal(t, 40*time.Second, ceilSeconds(40*time.Second)) + assert.Equal(t, time.Second, ceilSeconds(time.Millisecond)) +} + +func TestRateLimiterWaitStopsWhenTheContextIsCancelled(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{}) + require.NoError(t, rl.SetRetryAfterDuration(5*time.Second)) + + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + defer cancel() + err := rl.Wait(ctx, time.Now().Add(time.Minute)) + assert.ErrorIs(t, err, context.DeadlineExceeded) +} + +// occupyBulkhead fills every slot with the test runner's PID: alive, and not +// ours, so Acquire cannot reuse it. +func occupyBulkhead(t *testing.T, store *Store, slots int) { + t.Helper() + require.NoError(t, store.Update(func(state *State) error { + for range slots { + state.Bulkhead.ActivePIDs = append(state.Bulkhead.ActivePIDs, os.Getppid()) + } + return nil + })) +} + +func TestBulkheadWaitQueuesUntilASlotFrees(t *testing.T) { + store := NewStore(t.TempDir()) + occupyBulkhead(t, store, 1) + bh := NewBulkhead(store, BulkheadConfig{MaxConcurrent: 1}) + + go func() { + time.Sleep(40 * time.Millisecond) + _ = store.Update(func(state *State) error { + state.Bulkhead.RemovePID(os.Getppid()) + return nil + }) + }() + + start := time.Now() + require.NoError(t, bh.Wait(context.Background(), start.Add(2*time.Second))) + assert.GreaterOrEqual(t, time.Since(start), 40*time.Millisecond) + + state, err := store.Load() + require.NoError(t, err) + assert.Equal(t, []int{os.Getpid()}, state.Bulkhead.ActivePIDs) +} + +func TestBulkheadWaitGivesUpWithTheLimitAndTheWait(t *testing.T) { + store := NewStore(t.TempDir()) + occupyBulkhead(t, store, 1) + bh := NewBulkhead(store, BulkheadConfig{MaxConcurrent: 1}) + + err := bh.Wait(context.Background(), time.Now().Add(60*time.Millisecond)) + + var gateErr *GateError + require.ErrorAs(t, err, &gateErr) + assert.ErrorIs(t, err, basecamp.ErrBulkheadFull) + assert.Equal(t, "Too many concurrent basecamp processes (limit 1); waited 0s", gateErr.Message) + assert.Equal(t, "Re-run, or lower parallelism.", gateErr.Hint) +} + +func TestGatingHooksGateSharesOneWaitBudgetAndLeaksNoSlot(t *testing.T) { + store := NewStore(t.TempDir()) + occupyBulkhead(t, store, 1) + cfg := DefaultConfig() + cfg.MaxWait = 60 * time.Millisecond + cfg.Bulkhead.MaxConcurrent = 1 + hooks := NewGatingHooksFromConfig(store, cfg) + + start := time.Now() + _, err := hooks.OnOperationGate(context.Background(), basecamp.OperationInfo{Service: "Todos", Operation: "Complete"}) + elapsed := time.Since(start) + + var gateErr *GateError + require.ErrorAs(t, err, &gateErr) + assert.ErrorIs(t, err, basecamp.ErrBulkheadFull) + assert.GreaterOrEqual(t, elapsed, cfg.MaxWait, "queued for the whole budget") + assert.Less(t, elapsed, time.Second) + + state, err := store.Load() + require.NoError(t, err) + assert.False(t, state.Bulkhead.HasPID(os.Getpid()), "a rejected gate holds no slot") +} + +func TestBulkheadWaitReturnsCancellationWithoutReservingASlot(t *testing.T) { + store := NewStore(t.TempDir()) + bh := NewBulkhead(store, BulkheadConfig{MaxConcurrent: 1}) + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + err := bh.Wait(ctx, time.Now().Add(time.Second)) + + assert.ErrorIs(t, err, context.Canceled) + state, loadErr := store.Load() + require.NoError(t, loadErr) + assert.Empty(t, state.Bulkhead.ActivePIDs) +} + +func TestRateLimiterWaitReturnsCancellationWithoutConsumingAToken(t *testing.T) { + rl := NewRateLimiter(NewStore(t.TempDir()), RateLimiterConfig{MaxTokens: 5, RefillRate: 0.001}) + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + err := rl.Wait(ctx, time.Now().Add(time.Second)) + + assert.ErrorIs(t, err, context.Canceled) + tokens, tokensErr := rl.Tokens() + require.NoError(t, tokensErr) + assert.Equal(t, float64(5), tokens) +} + +func TestCircuitBreakerTripped(t *testing.T) { + store := NewStore(t.TempDir()) + cb := NewCircuitBreaker(store, CircuitBreakerConfig{OpenTimeout: time.Minute}) + clock := newFakeClock() + cb.nowFn = clock.Now + assert.False(t, cb.Tripped(), "closed") + + require.NoError(t, store.Update(func(state *State) error { + state.CircuitBreaker.State = CircuitOpen + state.CircuitBreaker.OpenedAt = clock.Now() + return nil + })) + assert.True(t, cb.Tripped(), "open, timeout running") + + clock.Advance(2 * time.Minute) + assert.False(t, cb.Tripped(), "open, timeout expired: Allow decides") +} + +// With the circuit open, an invocation must not spend its queue budget +// waiting for a token it would only be refused with. +func TestGatingHooksFailsFastOnAnOpenCircuitBeforeQueueing(t *testing.T) { + store := NewStore(t.TempDir()) + require.NoError(t, store.Update(func(state *State) error { + state.CircuitBreaker.State = CircuitOpen + state.CircuitBreaker.OpenedAt = time.Now() + return nil + })) + cfg := DefaultConfig() + cfg.MaxWait = 2 * time.Second + cfg.RateLimiter = RateLimiterConfig{MaxTokens: 1, RefillRate: 2, TokensPerRequest: 1} + hooks := NewGatingHooksFromConfig(store, cfg) + allowed, err := hooks.rateLimiter.Allow() + require.NoError(t, err) + require.True(t, allowed, "bucket drained") + + start := time.Now() + _, err = hooks.OnOperationGate(context.Background(), basecamp.OperationInfo{Service: "Todos", Operation: "Complete"}) + + assert.ErrorIs(t, err, basecamp.ErrCircuitOpen) + assert.Less(t, time.Since(start), 100*time.Millisecond, "no queueing for a refill") + tokens, tokensErr := hooks.rateLimiter.Tokens() + require.NoError(t, tokensErr) + assert.Less(t, tokens, 1.0, "no token consumed") +} + +// An expired budget rejects before the attempt, so a slot or token that +// happens to be free at the deadline is not taken past it. +func TestWaitsRejectAnExpiredDeadlineWithoutReserving(t *testing.T) { + store := NewStore(t.TempDir()) + past := time.Now().Add(-time.Millisecond) + + bh := NewBulkhead(store, BulkheadConfig{MaxConcurrent: 1}) + assert.ErrorIs(t, bh.Wait(context.Background(), past), basecamp.ErrBulkheadFull) + state, err := store.Load() + require.NoError(t, err) + assert.Empty(t, state.Bulkhead.ActivePIDs, "free slot left untaken") + + rl := NewRateLimiter(store, RateLimiterConfig{MaxTokens: 5, RefillRate: 0.001}) + assert.ErrorIs(t, rl.Wait(context.Background(), past), basecamp.ErrRateLimited) + tokens, err := rl.Tokens() + require.NoError(t, err) + assert.Equal(t, float64(5), tokens, "no token consumed") +} + +func TestGatingHooksAnswersCancellationBeforeTheCircuit(t *testing.T) { + store := NewStore(t.TempDir()) + require.NoError(t, store.Update(func(state *State) error { + state.CircuitBreaker.State = CircuitOpen + state.CircuitBreaker.OpenedAt = time.Now() + return nil + })) + hooks := NewGatingHooksFromConfig(store, DefaultConfig()) + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + _, err := hooks.OnOperationGate(ctx, basecamp.OperationInfo{Service: "Todos", Operation: "Complete"}) + assert.ErrorIs(t, err, context.Canceled) +} + +// The bulkhead's give-up message counts the whole gate wait, not only the +// slot phase: a gate that spent its budget on the rate limiter and then met +// a full bulkhead reports the total. +func TestBulkheadWaitReportsTheWholeGateWait(t *testing.T) { + store := NewStore(t.TempDir()) + occupyBulkhead(t, store, 1) + bh := NewBulkhead(store, BulkheadConfig{MaxConcurrent: 1}) + start := time.Now().Add(-9 * time.Second) + + err := bh.waitSince(context.Background(), start, time.Now().Add(20*time.Millisecond)) + + var gateErr *GateError + require.ErrorAs(t, err, &gateErr) + assert.Equal(t, "Too many concurrent basecamp processes (limit 1); waited 9s", gateErr.Message) +} + +// slotHeldCancel is a context that reports cancellation from the moment this +// process holds a bulkhead slot: the narrow window between the slot phase +// succeeding and the circuit breaker reserving an attempt. +type slotHeldCancel struct { + context.Context + store *Store +} + +func (c slotHeldCancel) Err() error { + state, err := c.store.Load() + if err == nil && state.Bulkhead.HasPID(os.Getpid()) { + return context.Canceled + } + return nil +} + +func TestGatingHooksReleasesTheSlotWhenCancellationLandsBeforeTheCircuit(t *testing.T) { + store := NewStore(t.TempDir()) + require.NoError(t, store.Update(func(state *State) error { + state.CircuitBreaker.State = CircuitHalfOpen + return nil + })) + hooks := NewGatingHooksFromConfig(store, DefaultConfig()) + + _, err := hooks.OnOperationGate(slotHeldCancel{context.Background(), store}, basecamp.OperationInfo{Service: "Todos", Operation: "Complete"}) + + assert.ErrorIs(t, err, context.Canceled) + state, loadErr := store.Load() + require.NoError(t, loadErr) + assert.Empty(t, state.Bulkhead.ActivePIDs, "slot released") + assert.Zero(t, state.CircuitBreaker.HalfOpenAttempts, "no half-open attempt reserved") +} + +func TestGateErrorUnwrapsToTheSDKSentinel(t *testing.T) { + err := fmt.Errorf("listing projects: %w", &GateError{Message: "m", Hint: "h", sentinel: basecamp.ErrBulkheadFull}) + assert.ErrorIs(t, err, basecamp.ErrBulkheadFull) + assert.NotErrorIs(t, err, basecamp.ErrRateLimited) + assert.Equal(t, "listing projects: m", err.Error()) +} diff --git a/internal/resilience/hooks.go b/internal/resilience/hooks.go index 6f9c45041..05ef17fef 100644 --- a/internal/resilience/hooks.go +++ b/internal/resilience/hooks.go @@ -26,14 +26,17 @@ type GatingHooks struct { circuitBreaker *CircuitBreaker rateLimiter *RateLimiter bulkhead *Bulkhead + maxWait time.Duration } -// NewGatingHooks creates a new GatingHooks with the given primitives. +// NewGatingHooks creates a new GatingHooks with the given primitives and the +// default queueing bound. func NewGatingHooks(cb *CircuitBreaker, rl *RateLimiter, bh *Bulkhead) *GatingHooks { return &GatingHooks{ circuitBreaker: cb, rateLimiter: rl, bulkhead: bh, + maxWait: DefaultMaxWait, } } @@ -42,12 +45,19 @@ func NewGatingHooksFromConfig(store *Store, cfg *Config) *GatingHooks { cb := NewCircuitBreaker(store, cfg.CircuitBreaker) rl := NewRateLimiter(store, cfg.RateLimiter) bh := NewBulkhead(store, cfg.Bulkhead) - return NewGatingHooks(cb, rl, bh) + hooks := NewGatingHooks(cb, rl, bh) + if cfg.MaxWait > 0 { + hooks.maxWait = cfg.MaxWait + } + return hooks } // OnOperationGate is called before OnOperationStart. // It checks rate limiter, bulkhead, and circuit breaker before allowing -// the operation to proceed. +// the operation to proceed. The rate limiter and bulkhead queue rather than +// reject: parallel CLI invocations share both, and a burst that briefly +// exceeds a limit waits its turn within one maxWait budget shared by the +// two, failing with a *GateError only when the budget runs out. // // Gate order is important: rate limiter and bulkhead are checked BEFORE // circuit breaker because the circuit breaker reserves a half-open slot @@ -61,19 +71,40 @@ func NewGatingHooksFromConfig(store *Store, cfg *Config) *GatingHooks { // Returns a context that should be used for the operation and an error // if the operation should be rejected. func (h *GatingHooks) OnOperationGate(ctx context.Context, op basecamp.OperationInfo) (context.Context, error) { - // Check rate limiter first (no state reservation, safe to reject) + // A canceled caller is answered before anything is read or reserved. + if err := ctx.Err(); err != nil { + return ctx, err + } + + // An open circuit fails fast before any queueing: waiting for a token + // only to be refused by the breaker would defeat its purpose during an + // outage. Nothing is reserved here; the reserving check still runs last. + if h.circuitBreaker != nil && h.circuitBreaker.Tripped() { + return ctx, basecamp.ErrCircuitOpen + } + + start := time.Now() + deadline := start.Add(h.maxWait) + + // Rate limiter first: it queues for a refill and consumes a token on + // success, which is the only state it holds, so a later rejection wastes + // at most that token. if h.rateLimiter != nil { - allowed, _ := h.rateLimiter.Allow() // Fail open on error - if !allowed { - return ctx, basecamp.ErrRateLimited + if err := h.rateLimiter.waitSince(ctx, start, deadline); err != nil { + return ctx, err } } // Acquire bulkhead slot (PID-based, released in OnOperationEnd) if h.bulkhead != nil { - acquired, _ := h.bulkhead.Acquire() // Fail open on error - if !acquired { - return ctx, basecamp.ErrBulkheadFull + if err := h.bulkhead.waitSince(ctx, start, deadline); err != nil { + return ctx, err + } + // A cancellation that landed while the slot was being taken must not + // go on to reserve a half-open attempt. + if err := ctx.Err(); err != nil { + _ = h.bulkhead.Release() + return ctx, err } // Store marker in context so OnOperationEnd knows to release the slot ctx = context.WithValue(ctx, releaseKey{}, true) diff --git a/internal/resilience/rate_limiter.go b/internal/resilience/rate_limiter.go index 482dad17c..d525c3767 100644 --- a/internal/resilience/rate_limiter.go +++ b/internal/resilience/rate_limiter.go @@ -1,7 +1,11 @@ package resilience import ( + "context" + "fmt" "time" + + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" ) // RateLimiter implements the token bucket algorithm with cross-process persistence. @@ -61,15 +65,22 @@ func (rl *RateLimiter) refill(state *RateLimiterState, now time.Time) { // Returns true if the request can proceed, false if it should be rejected. // On success, consumes tokens from the bucket. func (rl *RateLimiter) Allow() (bool, error) { - var allowed bool + allowed, _, _ := rl.take() + return allowed, nil +} +// take is one non-blocking pass through the bucket. When the request is not +// allowed, wait is how long until it could be: the remainder of a Retry-After +// block (blocked is true) or the refill time for the missing tokens. A store +// error allows the request (fail open), as every primitive here does. +func (rl *RateLimiter) take() (allowed bool, wait time.Duration, blocked bool) { err := rl.store.Update(func(state *State) error { rlState := &state.RateLimiter now := rl.now() // Check Retry-After block if rlState.IsBlocked() { - allowed = false + allowed, blocked, wait = false, true, rlState.BlockedFor() return nil } @@ -79,7 +90,8 @@ func (rl *RateLimiter) Allow() (bool, error) { rlState.Tokens -= rl.config.TokensPerRequest allowed = true } else { - allowed = false + deficit := rl.config.TokensPerRequest - rlState.Tokens + allowed, wait = false, time.Duration(deficit/rl.config.RefillRate*float64(time.Second)) } state.UpdatedAt = now @@ -87,11 +99,76 @@ func (rl *RateLimiter) Allow() (bool, error) { }) if err != nil { - // On error, allow the request (fail open) - return true, nil //nolint:nilerr // Intentional fail-open: allow request when state cannot be updated + return true, 0, false } - return allowed, nil + return allowed, wait, blocked +} + +// minRefillWait floors the sleep between token attempts: a deficit of a few +// microseconds is not worth a wakeup, and under contention the refill is +// consumed by whichever process reaches the lock first anyway. +const minRefillWait = 5 * time.Millisecond + +// Wait consumes tokens for one request, sleeping for refills or for a +// Retry-After block to lift, until deadline. It returns nil when the request +// may proceed, a *GateError when the deadline would pass first, or ctx.Err(). +// A Retry-After block that outlasts the deadline is reported immediately +// rather than waited on, with the remaining time in the message. +// Cancellation and the deadline are checked before every attempt, so an +// expired or canceled gate consumes nothing, and cancellation outranks the +// deadline. +func (rl *RateLimiter) Wait(ctx context.Context, deadline time.Time) error { + return rl.waitSince(ctx, rl.now(), deadline) +} + +// waitSince is Wait for a gate that started queueing at start. +func (rl *RateLimiter) waitSince(ctx context.Context, start, deadline time.Time) error { + for { + if err := ctx.Err(); err != nil { + return err + } + remaining := deadline.Sub(rl.now()) + if remaining <= 0 { + return rl.gateError(false, 0, rl.now().Sub(start)) + } + allowed, wait, blocked := rl.take() //nolint:contextcheck // lock acquisition is context-independent by design + if allowed { + return nil + } + if wait > remaining { + return rl.gateError(blocked, wait, rl.now().Sub(start)) + } + // Jitter never pushes the sleep to the deadline: a wake there would be + // rejected unheard after having waited out the very refill or block + // it was waiting for. + sleep := jittered(max(wait, minRefillWait)) + if sleep > remaining { + sleep = wait + } + if err := pause(ctx, sleep); err != nil { + return err + } + } +} + +func (rl *RateLimiter) gateError(blocked bool, wait, waited time.Duration) *GateError { + if blocked { + // Rounded up: a "retry after 40s" that is really 40.4s would send the + // re-run into the tail of the block. + retryAfter := ceilSeconds(wait) + return &GateError{ + Message: fmt.Sprintf("Rate limited by the server; retry after %s", retryAfter), + Hint: fmt.Sprintf("Wait %s, then re-run.", retryAfter), + sentinel: basecamp.ErrRateLimited, + } + } + requestsPerSecond := rl.config.RefillRate / rl.config.TokensPerRequest + return &GateError{ + Message: fmt.Sprintf("Too many requests (client limit %g/s); waited %s", requestsPerSecond, waited.Round(time.Second)), + Hint: "Re-run, or lower parallelism.", + sentinel: basecamp.ErrRateLimited, + } } // SetRetryAfter sets a block until the given time due to a 429 response. diff --git a/internal/resilience/store.go b/internal/resilience/store.go index 6214eb68c..b06c1ba34 100644 --- a/internal/resilience/store.go +++ b/internal/resilience/store.go @@ -77,7 +77,15 @@ func (s *Store) lockPath() string { // LockTimeout is the maximum time to wait for acquiring the file lock. // If exceeded, operations proceed without locking (fail-open) to avoid CLI hangs. -const LockTimeout = 100 * time.Millisecond +// +// The lock is held only for one read-modify-write of a small JSON file, so +// a wait this long means the holder is wedged (NFS, a stopped process), not +// busy. The budget has to cover a queue of parallel invocations all polling +// the state file on a slow disk: a process that times out falls open and +// writes back a stale copy, which can resurrect a slot another live process +// had just released. TestStoreLockContentionDoesNotLoseReleases shows that +// loss once the budget is squeezed to a millisecond. +var LockTimeout = 2 * time.Second // fileLock represents an acquired file lock. type fileLock struct {