From 83016d70d4a506b66be35267b9f40c33e2cceae9 Mon Sep 17 00:00:00 2001 From: piekstra Date: Tue, 3 Nov 2026 09:00:13 -0500 Subject: [PATCH 1/2] fix(review): survive transient GitHub server errors cr made one attempt at every GitHub request, so a single 5xx anywhere in a run failed it before anything was reviewed. Reads now retry 5xx, 429 and connection failures with jittered backoff and honor Retry-After. Writes are not retried by the client, because a write can land and still return 5xx; the outbox re-reads the PR for the write's marker and resends only if it is absent. Failed runs now print a Status line on stdout as well as the error on stderr and a non-zero exit code. Twapp-Session: 59d912f3-982f-402e-8bd8-3e31269a28b0 --- docs/architecture.md | 8 + docs/development.md | 5 + docs/review-lifecycle.md | 10 + internal/app/progress.go | 48 +- internal/app/runtime.go | 37 +- internal/app/runtime_selection.go | 4 +- internal/app/runtime_test.go | 78 +++ internal/cmd/noleak/github_transient_test.go | 249 +++++++++ internal/cmd/noleak/noleak_test.go | 10 + internal/cmd/reviewcmd/reviewcmd.go | 33 +- internal/cmd/reviewcmd/reviewcmd_test.go | 72 +++ internal/gateio/gateio.go | 28 +- internal/gitexec/client.go | 88 ++- internal/gitexec/client_test.go | 123 ++++ internal/gitprovider/errors.go | 35 ++ internal/gitprovider/errors_test.go | 24 + internal/gitprovider/github/app_auth.go | 26 +- internal/gitprovider/github/client.go | 3 + internal/gitprovider/github/client_test.go | 4 + internal/gitprovider/github/graphql_reads.go | 2 + internal/gitprovider/github/http.go | 42 +- internal/gitprovider/github/rest.go | 16 +- internal/gitprovider/github/retry.go | 278 ++++++++++ internal/gitprovider/github/retry_test.go | 523 ++++++++++++++++++ .../testdata/review_threads_bot_author.json | 43 ++ internal/outbox/outbox.go | 20 + internal/outbox/write_retry.go | 185 +++++++ internal/outbox/write_retry_test.go | 487 ++++++++++++++++ internal/progress/progress.go | 16 + internal/progress/progress_test.go | 21 + internal/reviewrun/reviewrun.go | 11 +- internal/threadrespond/threadrespond.go | 15 +- internal/view/review.go | 2 +- internal/workbench/workbench.go | 24 +- internal/workbench/workbench_test.go | 23 + 35 files changed, 2523 insertions(+), 70 deletions(-) create mode 100644 internal/cmd/noleak/github_transient_test.go create mode 100644 internal/gitprovider/github/retry.go create mode 100644 internal/gitprovider/github/retry_test.go create mode 100644 internal/gitprovider/github/testdata/review_threads_bot_author.json create mode 100644 internal/outbox/write_retry.go create mode 100644 internal/outbox/write_retry_test.go diff --git a/docs/architecture.md b/docs/architecture.md index 7091e923..0eefb9c2 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -102,6 +102,14 @@ This keeps markers, retries, reconciliation, idempotency, and resume behavior in one place. New commands such as `cr respond` should produce planned thread actions and let the reviewplan/ledger/outbox flow perform provider writes. +The GitHub client retries only reads, in one place: `retrySafeOperation` in +`internal/gitprovider/github/retry.go` lists what may be re-sent, and everything +else, including any operation added later, gets one attempt. A write can land at +GitHub and still return 5xx, so a blind retry would post twice. Writes are retried +by the outbox, which waits for GitHub's 10-second processing limit to pass, re-reads +the PR, and sends again only when the action's marker is absent. If that read fails, +the write stays pending rather than being sent unverified. + Accepting a repository invitation is the one exception. It changes the posting identity's account, not a pull request, so it has no marker, no run, and nothing to reconcile, and accepting an invitation that is already gone fails diff --git a/docs/development.md b/docs/development.md index 2d8ec88c..f1149292 100644 --- a/docs/development.md +++ b/docs/development.md @@ -78,6 +78,11 @@ Review progress includes instant catalog-resolution, final selection, and per-reviewer assignment records. These expose IDs, winning provenance, selection reasoning, and assigned paths without logging prompt bodies. +Retries during a review are `event=info` records with `op="retry_read"`, +`op="retry_post"` or `op="retry_fetch"`. They carry `attempt`, `max_attempts`, +`delay_ms` where a wait is scheduled, and the cause in `error`; `retry_post` adds the +recovery `phase` (`waiting`, `reconciled`, `resending` or `abandoned`). + Current command coverage is `benchmark run`, `benchmark select`, `benchmark compare`, `data prune`, `data purge`, `config clear`, `me`, and `sessions delete`. diff --git a/docs/review-lifecycle.md b/docs/review-lifecycle.md index 45f74241..06963cbe 100644 --- a/docs/review-lifecycle.md +++ b/docs/review-lifecycle.md @@ -110,6 +110,16 @@ not reached the PR. - Outbox reconciliation checks markers before every dispatch, so a process crash after a provider write but before the local update does not duplicate the reply or final review. +- GitHub reads and `git fetch` retry 5xx, 429 and connection failures with + jittered backoff and honor `Retry-After`. A 404 fails immediately. +- A write that fails retryably during the final outbox is checked against the PR + after a settle wait, marked posted if its marker is there, and otherwise resent, + up to three sends. Once one action uses up its sends, later actions in that run + get one send each, so an outage cannot multiply the wait. Whatever is left stays + pending, the run exits 5, and the next `cr review` reconciles it. Duplicates remain + possible only if GitHub applies a write after the settle wait and the marker check. +- A run that fails renders `Status: error` and the cause on stdout, or the same + record as JSON, as well as the error on stderr and a non-zero exit code. - Thread replies are ordered before resolutions, and a resolution is not sent until its reply is posted or reconciled. - Completed summary markers on the PR outrank stale local fallback state. diff --git a/internal/app/progress.go b/internal/app/progress.go index fdf2e5f2..54e3cdf2 100644 --- a/internal/app/progress.go +++ b/internal/app/progress.go @@ -1,6 +1,14 @@ package app -import "github.com/open-cli-collective/codereview-cli/internal/progress" +import ( + "strconv" + "time" + + "github.com/open-cli-collective/codereview-cli/internal/gitexec" + githubprovider "github.com/open-cli-collective/codereview-cli/internal/gitprovider/github" + "github.com/open-cli-collective/codereview-cli/internal/outbox" + "github.com/open-cli-collective/codereview-cli/internal/progress" +) func endProgressSpan(span *progress.Span, err error) error { if span != nil { @@ -8,3 +16,41 @@ func endProgressSpan(span *progress.Span, err error) error { } return err } + +// githubRetryProgress reports each retried GitHub read, so a slow run shows why. +func githubRetryProgress(logger *progress.Logger, command string) func(githubprovider.RetryEvent) { + return func(event githubprovider.RetryEvent) { + logger.InfoReason(command, "retry_read", string(event.Op), event.Reason, + progress.Field{Key: "attempt", Value: strconv.Itoa(event.Attempt)}, + progress.Field{Key: "max_attempts", Value: strconv.Itoa(event.MaxAttempts)}, + progress.Field{Key: "delay_ms", Value: strconv.FormatInt(event.Delay.Milliseconds(), 10)}, + ) + } +} + +// gitFetchRetryProgress reports each retried git fetch. +func gitFetchRetryProgress(logger *progress.Logger, command string) func(gitexec.RetryEvent) { + return func(event gitexec.RetryEvent) { + logger.InfoReason(command, "retry_fetch", "workbench", event.Reason, + progress.Field{Key: "attempt", Value: strconv.Itoa(event.Attempt)}, + progress.Field{Key: "max_attempts", Value: strconv.Itoa(event.MaxAttempts)}, + progress.Field{Key: "delay_ms", Value: strconv.FormatInt(event.Delay.Milliseconds(), 10)}, + ) + } +} + +// writeRetryProgress reports each step of recovering a failed GitHub write. +func writeRetryProgress(logger *progress.Logger, command string) func(outbox.WriteRetryEvent) { + return func(event outbox.WriteRetryEvent) { + fields := []progress.Field{ + {Key: "phase", Value: string(event.Phase)}, + {Key: "action", Value: event.ActionID}, + {Key: "attempt", Value: strconv.Itoa(event.Attempt)}, + {Key: "max_attempts", Value: strconv.Itoa(event.MaxAttempts)}, + } + if event.Delay > time.Duration(0) { + fields = append(fields, progress.Field{Key: "delay_ms", Value: strconv.FormatInt(event.Delay.Milliseconds(), 10)}) + } + logger.InfoReason(command, "retry_post", string(event.Kind), event.Reason, fields...) + } +} diff --git a/internal/app/runtime.go b/internal/app/runtime.go index bbf73b8d..08c3dc9f 100644 --- a/internal/app/runtime.go +++ b/internal/app/runtime.go @@ -119,6 +119,22 @@ type Dependencies struct { CheckAgentSources func(context.Context, []string, io.Writer) } +// gitCommandFactory returns the injected factory, or the production one reporting +// fetch retries to onRetry. +func (d Dependencies) gitCommandFactory(onRetry func(gitexec.RetryEvent)) func(string, gitexec.TokenSource, string) (func(context.Context, string, ...string) ([]byte, error), error) { + if d.NewGitCommand != nil { + return d.NewGitCommand + } + return func(host string, tokens gitexec.TokenSource, username string) (func(context.Context, string, ...string) ([]byte, error), error) { + client, err := gitexec.NewWithUsername(host, tokens, username) + if err != nil { + return nil, err + } + client.OnRetry = onRetry + return client.Run, nil + } +} + func (d Dependencies) withDefaults() Dependencies { if d.NewGitProvider == nil { d.NewGitProvider = gitproviders.New @@ -126,15 +142,6 @@ func (d Dependencies) withDefaults() Dependencies { if d.ResolvePostingIdentity == nil { d.ResolvePostingIdentity = resolvePostingIdentity } - if d.NewGitCommand == nil { - d.NewGitCommand = func(host string, tokens gitexec.TokenSource, username string) (func(context.Context, string, ...string) ([]byte, error), error) { - client, err := gitexec.NewWithUsername(host, tokens, username) - if err != nil { - return nil, err - } - return client.Run, nil - } - } if d.ResolveRepoRoot == nil { d.ResolveRepoRoot = appruntime.ResolveRepoRoot } @@ -175,12 +182,12 @@ func Open(ctx context.Context, req OpenRequest) (Runtime, error) { cleanup() return Runtime{}, err } - repoProvider, repoCredential, err := deps.NewGitProvider(profile.Git, repoProviderStore, gitProviderOptions(profile, profile.Git, req.PRRef)) + repoProvider, repoCredential, err := deps.NewGitProvider(profile.Git, repoProviderStore, gitProviderOptions(profile, profile.Git, req.PRRef, githubRetryProgress(req.Progress, command))) if err != nil { cleanup() return Runtime{}, err } - gitCommand, err := deps.NewGitCommand(profile.Git.Host, repositoryTokenSource(repoProvider, repoCredential), gitproviders.GitBasicAuthUsername(profile.Git.ProviderKind())) + gitCommand, err := deps.gitCommandFactory(gitFetchRetryProgress(req.Progress, command))(profile.Git.Host, repositoryTokenSource(repoProvider, repoCredential), gitproviders.GitBasicAuthUsername(profile.Git.ProviderKind())) if err != nil { cleanup() return Runtime{}, err @@ -192,7 +199,7 @@ func Open(ctx context.Context, req OpenRequest) (Runtime, error) { cleanup() return Runtime{}, err } - postingProvider, credential, err := deps.NewGitProvider(postingGit, postingProviderStore, gitProviderOptions(profile, postingGit, req.PRRef)) + postingProvider, credential, err := deps.NewGitProvider(postingGit, postingProviderStore, gitProviderOptions(profile, postingGit, req.PRRef, githubRetryProgress(req.Progress, command))) if err != nil { cleanup() return Runtime{}, err @@ -374,11 +381,12 @@ func normalizeRuntimeProfile(profile config.Profile) config.Profile { }).Profiles["runtime"] } -func gitProviderOptions(profile config.Profile, git config.GitConfig, ref gitprovider.PRRef) gitproviders.Options { +func gitProviderOptions(profile config.Profile, git config.GitConfig, ref gitprovider.PRRef, onRetry func(githubprovider.RetryEvent)) gitproviders.Options { opts := gitproviders.Options{} if git.ProviderKind() != config.GitProviderGitHub { return opts } + opts.GitHub.Retry.OnRetry = onRetry if installationID := config.PinnedGitHubAppInstallationIDForGit(profile, git); installationID != "" { opts.GitHub.InstallationID = installationID return opts @@ -409,6 +417,7 @@ func runtimeLayout() (statepaths.Layout, error) { func buildReviewRunner(ledgerStore *ledger.Store, repoProvider gitprovider.GitProvider, postingProvider gitprovider.GitProvider, adapter llm.Adapter, profile config.Profile, limiter outbox.Limiter, layout statepaths.Layout, warnings io.Writer, logger *progress.Logger, dispatcher *hookDispatcher, req OpenRequest, command string, gitCommand func(context.Context, string, ...string) ([]byte, error), resolveRepoRoot func(context.Context) (string, error)) reviewRunner { taskProgress := newPipelineTaskProgress(logger, command, dispatcher) liveProvider := runtimeProvider{read: repoProvider, write: postingProvider} + writeRetry := outbox.DefaultWriteRetry(writeRetryProgress(logger, command)) pipelineOpts := pipeline.Options{ Provider: repoProvider, Adapter: adapter, @@ -450,6 +459,7 @@ func buildReviewRunner(ledgerStore *ledger.Store, repoProvider gitprovider.GitPr Provider: liveProvider, Planner: withProgressPlanner(logger, dispatcher, livePlanner{opts: pipelineOpts}), Limiter: limiter, + WriteRetry: writeRetry, Layout: layout, StaleHeartbeatThreshold: 10 * time.Minute, Warnings: warnings, @@ -464,6 +474,7 @@ func buildReviewRunner(ledgerStore *ledger.Store, repoProvider gitprovider.GitPr Provider: liveProvider, Adapter: adapter, Limiter: limiter, + WriteRetry: writeRetry, Layout: layout, TaskProgress: taskProgress, NewActionID: pipelineOpts.NewActionID, diff --git a/internal/app/runtime_selection.go b/internal/app/runtime_selection.go index a3344711..65dbb1f8 100644 --- a/internal/app/runtime_selection.go +++ b/internal/app/runtime_selection.go @@ -34,12 +34,12 @@ func OpenSelection(ctx context.Context, req SelectionOpenRequest) (SelectionRunt } // Selection-only paths read with the profile git credential while keeping // PR-scoped GitHub App installation lookup aligned with review runs. - provider, credential, err := deps.NewGitProvider(profile.Git, gitStore, gitProviderOptions(profile, profile.Git, req.PRRef)) + provider, credential, err := deps.NewGitProvider(profile.Git, gitStore, gitProviderOptions(profile, profile.Git, req.PRRef, nil)) if err != nil { cleanup() return SelectionRuntime{}, err } - gitCommand, err := deps.NewGitCommand(profile.Git.Host, repositoryTokenSource(provider, credential), gitproviders.GitBasicAuthUsername(profile.Git.ProviderKind())) + gitCommand, err := deps.gitCommandFactory(nil)(profile.Git.Host, repositoryTokenSource(provider, credential), gitproviders.GitBasicAuthUsername(profile.Git.ProviderKind())) if err != nil { cleanup() return SelectionRuntime{}, err diff --git a/internal/app/runtime_test.go b/internal/app/runtime_test.go index 76d70df3..fcae3bac 100644 --- a/internal/app/runtime_test.go +++ b/internal/app/runtime_test.go @@ -33,6 +33,7 @@ import ( "github.com/open-cli-collective/codereview-cli/internal/modelcatalog" "github.com/open-cli-collective/codereview-cli/internal/outbox" "github.com/open-cli-collective/codereview-cli/internal/pipeline" + "github.com/open-cli-collective/codereview-cli/internal/progress" "github.com/open-cli-collective/codereview-cli/internal/reporoot" "github.com/open-cli-collective/codereview-cli/internal/review" "github.com/open-cli-collective/codereview-cli/internal/reviewplan" @@ -1430,3 +1431,80 @@ func pipelineRequest(ref gitprovider.PRRef, pr gitprovider.PR, profile config.Pr PostingIdentity: identity, } } + +func TestOpenReportsGitHubRetriesThroughProgressAndEnablesWriteRecovery(t *testing.T) { + provider := &gitprovider.Fake{} + identity := gitprovider.Identity{Login: "review-bot", ID: "bot-id"} + var captured []gitproviders.Options + deps := testDependencies(t, + func(_ config.GitConfig, _ credentials.Reader, opts gitproviders.Options) (gitprovider.GitProvider, gitprovider.Credential, error) { + captured = append(captured, opts) + return provider, gitprovider.Credential{Type: "pat", Token: "token"}, nil + }, + func(context.Context, gitprovider.GitProvider, gitprovider.Credential, credentials.Reader, config.Profile) (gitprovider.Identity, error) { + return identity, nil + }, + func(config.LLMConfig, credentials.Reader) (llm.Adapter, error) { + return &llm.FakeAdapter{}, nil + }, + ) + cfg := testConfig() + var out bytes.Buffer + runtime, err := Open(context.Background(), OpenRequest{ + Config: cfg, + Profile: cfg.Profiles["home"], + ProfileName: "home", + Command: "review", + Progress: progress.New(&out, false, nil), + PRRef: gitprovider.PRRef{Host: "github.com", Owner: "o", Repo: "r", Number: 1}, + Dependencies: deps, + }) + if err != nil { + t.Fatalf("Open: %v", err) + } + defer runtime.Cleanup() + + if len(captured) != 2 { + t.Fatalf("providers built = %d, want read and posting", len(captured)) + } + for i, opts := range captured { + if opts.GitHub.Retry.OnRetry == nil { + t.Fatalf("provider %d has no retry observer", i) + } + } + captured[0].GitHub.Retry.OnRetry(githubprovider.RetryEvent{Op: gitprovider.OperationGetPR, Attempt: 2, MaxAttempts: 6, Delay: 3 * time.Second, Reason: "github: status 502"}) + line := out.String() + for _, want := range []string{`event=info`, `command="review"`, `op="retry_read"`, `target="GetPR"`, `attempt="2"`, `max_attempts="6"`, `delay_ms="3000"`, `error="github: status 502"`} { + if !strings.Contains(line, want) { + t.Fatalf("progress = %q, want %q", line, want) + } + } + + runner, ok := runtime.Runner.(reviewRunner) + if !ok { + t.Fatalf("runner = %T", runtime.Runner) + } + if runner.live.WriteRetry == nil || runner.respond.WriteRetry == nil { + t.Fatalf("write recovery live = %v respond = %v, want both enabled", runner.live.WriteRetry, runner.respond.WriteRetry) + } + out.Reset() + runner.live.WriteRetry.OnEvent(outbox.WriteRetryEvent{Phase: outbox.WriteRetryWaiting, ActionID: "action-1", Kind: ledger.PlannedActionSubmitReview, Attempt: 1, MaxAttempts: 3, Delay: 12 * time.Second, Reason: "github: status 504"}) + for _, want := range []string{`op="retry_post"`, `target="submit_review"`, `phase="waiting"`, `action="action-1"`, `delay_ms="12000"`, `error="github: status 504"`} { + if !strings.Contains(out.String(), want) { + t.Fatalf("progress = %q, want %q", out.String(), want) + } + } +} + +func TestGitFetchRetryProgress(t *testing.T) { + var out bytes.Buffer + gitFetchRetryProgress(progress.New(&out, false, nil), "review")(gitexec.RetryEvent{Attempt: 1, MaxAttempts: 4, Delay: time.Second, Reason: "git fetch https://x/y: returned error: 502"}) + for _, want := range []string{`op="retry_fetch"`, `attempt="1"`, `delay_ms="1000"`, `[path]`, `returned error: 502`} { + if !strings.Contains(out.String(), want) { + t.Fatalf("progress = %q, want %q", out.String(), want) + } + } + if strings.Contains(out.String(), "https://x/y") { + t.Fatalf("progress = %q, want the path redacted", out.String()) + } +} diff --git a/internal/cmd/noleak/github_transient_test.go b/internal/cmd/noleak/github_transient_test.go new file mode 100644 index 00000000..d966bea8 --- /dev/null +++ b/internal/cmd/noleak/github_transient_test.go @@ -0,0 +1,249 @@ +package noleak + +import ( + "encoding/json" + "fmt" + "io" + "net/http" + "strings" + "sync" + "sync/atomic" + "testing" + + "github.com/open-cli-collective/codereview-cli/internal/cmd/exitcode" +) + +// These drive the real `cr review` command tree and the real GitHub client +// against the fake server, with the retry waits injected away. + +func newTransientHarness(t *testing.T) *auditHarness { + t.Helper() + h := newAuditHarness(t) + t.Chdir(t.TempDir()) + seedConfiguredCredentials(t, h) + return h +} + +func (h *auditHarness) reviewsPath() string { + return fmt.Sprintf("/repos/%s/%s/pulls/%d/reviews", h.prRef.Owner, h.prRef.Repo, h.prRef.Number) +} + +func TestLiveReviewSurvivesFailureOfEveryGitHubReadOnce(t *testing.T) { + h := newTransientHarness(t) + var mu sync.Mutex + failed := map[string]bool{} + statuses := []int{500, 502, 503, 504} + h.githubFault = func(w http.ResponseWriter, r *http.Request) bool { + mu.Lock() + defer mu.Unlock() + key := r.Method + " " + r.URL.String() + " " + r.Header.Get("Accept") + if r.Method != http.MethodGet || failed[key] { + return false + } + failed[key] = true + w.WriteHeader(statuses[len(failed)%len(statuses)]) + return true + } + + stdout, stderr, err := h.run([]string{"review", h.prURL}) + if err != nil { + t.Fatalf("review: %v\nstdout = %s\nstderr = %s", err, stdout, stderr) + } + if len(failed) < 3 { + t.Fatalf("faulted reads = %v, want the run to have crossed several", failed) + } + if !strings.Contains(stdout, "Posts: posted=") || strings.Contains(stdout, "Status: error") { + t.Fatalf("stdout = %q, want a completed review", stdout) + } + if h.llmCalls.Load() == 0 { + t.Fatal("review never reached the model") + } +} + +func TestLiveReviewFailsClearlyWhenGitHubStaysDown(t *testing.T) { + for _, tt := range []struct { + name string + extra []string + check func(t *testing.T, stdout string) + }{ + {name: "text", check: func(t *testing.T, stdout string) { + t.Helper() + for _, want := range []string{"Status: error\n", "Exit code: 5\n", "status 502", "gave up after 6 attempts"} { + if !strings.Contains(stdout, want) { + t.Fatalf("stdout = %q, want %q", stdout, want) + } + } + }}, + {name: "json", extra: []string{"--json"}, check: func(t *testing.T, stdout string) { + t.Helper() + var rendered struct { + Status string `json:"status"` + Message string `json:"message"` + } + if err := json.Unmarshal([]byte(stdout), &rendered); err != nil { + t.Fatalf("stdout %q: %v", stdout, err) + } + if rendered.Status != "error" || !strings.Contains(rendered.Message, "gave up after 6 attempts") { + t.Fatalf("rendered = %#v", rendered) + } + }}, + } { + t.Run(tt.name, func(t *testing.T) { + h := newTransientHarness(t) + var prReads atomic.Int32 + pullPath := fmt.Sprintf("/repos/%s/%s/pulls/%d", h.prRef.Owner, h.prRef.Repo, h.prRef.Number) + h.githubFault = func(w http.ResponseWriter, r *http.Request) bool { + if r.URL.EscapedPath() != pullPath { + return false + } + prReads.Add(1) + w.WriteHeader(http.StatusBadGateway) + return true + } + + stdout, stderr, err := h.run(append([]string{"review", h.prURL}, tt.extra...)) + if err == nil { + t.Fatalf("review error = nil; stdout = %s", stdout) + } + if code := exitcode.FromError(err); code != exitcode.UpstreamError { + t.Fatalf("exit = %d, want %d: %v", code, exitcode.UpstreamError, err) + } + if !strings.Contains(err.Error(), "gave up after 6 attempts") { + t.Fatalf("error = %q, want the attempts named", err) + } + if prReads.Load() != 6 { + t.Fatalf("PR reads = %d, want 6", prReads.Load()) + } + if !strings.Contains(stderr, `op="execute_live"`) || !strings.Contains(stderr, "status=error") { + t.Fatalf("stderr = %q, want the failing progress record", stderr) + } + if h.llmCalls.Load() != 0 { + t.Fatalf("LLM calls = %d, want none", h.llmCalls.Load()) + } + tt.check(t, stdout) + h.assertNoLeaks(t, "stdout", []byte(stdout)) + h.assertNoLeaks(t, "stderr", []byte(stderr)) + h.assertNoLeaks(t, "returned error", []byte(err.Error())) + }) + } +} + +// reviewHost makes POST /reviews stateful: a kept body appears in later GETs. +type reviewHost struct { + mu sync.Mutex + posts int + kept []string +} + +func (host *reviewHost) fault(h *auditHarness, onPost func(attempt int) (keep bool, status int)) func(http.ResponseWriter, *http.Request) bool { + return func(w http.ResponseWriter, r *http.Request) bool { + if r.URL.EscapedPath() != h.reviewsPath() { + return false + } + host.mu.Lock() + defer host.mu.Unlock() + switch r.Method { + case http.MethodPost: + host.posts++ + var payload struct { + Body string `json:"body"` + } + raw, err := io.ReadAll(r.Body) + if err == nil { + err = json.Unmarshal(raw, &payload) + } + if err != nil { + h.t.Errorf("decode review: %v", err) + } + keep, status := onPost(host.posts) + if keep { + host.kept = append(host.kept, payload.Body) + } + w.WriteHeader(status) + if status < 300 { + _, _ = w.Write([]byte(`{"id":301}`)) + } + default: + reviews := make([]map[string]any, 0, len(host.kept)) + for i, body := range host.kept { + reviews = append(reviews, map[string]any{ + "id": 301 + i, + "body": body, + "state": "COMMENTED", + "commit_id": h.headSHA, + "user": map[string]any{"login": "reviewer-user", "id": 1002}, + "submitted_at": h.now.Format("2006-01-02T15:04:05Z"), + }) + } + writeHTTPJSON(h.t, w, reviews) + } + return true + } +} + +func TestLiveReviewThatLandedAndReturned502IsNotPostedTwice(t *testing.T) { + h := newTransientHarness(t) + host := &reviewHost{} + h.githubFault = host.fault(h, func(int) (bool, int) { return true, http.StatusBadGateway }) + + stdout, stderr, err := h.run([]string{"review", h.prURL}) + if err != nil { + t.Fatalf("review: %v\nstdout = %s\nstderr = %s", err, stdout, stderr) + } + if host.posts != 1 || len(host.kept) != 1 { + t.Fatalf("review POSTs = %d, kept = %d, want exactly one of each", host.posts, len(host.kept)) + } + if !strings.Contains(stdout, "pending=0") || !strings.Contains(stdout, "failed_terminal=0") { + t.Fatalf("stdout = %q, want nothing left pending", stdout) + } +} + +func TestLiveReviewThatDidNotLandIsResent(t *testing.T) { + h := newTransientHarness(t) + host := &reviewHost{} + h.githubFault = host.fault(h, func(attempt int) (bool, int) { + if attempt == 1 { + return false, http.StatusBadGateway + } + return true, http.StatusOK + }) + + stdout, stderr, err := h.run([]string{"review", h.prURL}) + if err != nil { + t.Fatalf("review: %v\nstdout = %s\nstderr = %s", err, stdout, stderr) + } + if host.posts != 2 || len(host.kept) != 1 { + t.Fatalf("review POSTs = %d, kept = %d, want two sends and one kept", host.posts, len(host.kept)) + } +} + +func TestLiveReviewFailedMarkerCheckStopsWithNonZeroExitAndNoSecondPost(t *testing.T) { + h := newTransientHarness(t) + host := &reviewHost{} + reviewFault := host.fault(h, func(int) (bool, int) { return true, http.StatusBadGateway }) + h.githubFault = func(w http.ResponseWriter, r *http.Request) bool { + host.mu.Lock() + posted := host.posts > 0 + host.mu.Unlock() + // Reads after the failed write cannot confirm anything. + if posted && r.Method == http.MethodGet && r.URL.EscapedPath() == h.reviewsPath() { + w.WriteHeader(http.StatusServiceUnavailable) + return true + } + return reviewFault(w, r) + } + + stdout, stderr, err := h.run([]string{"review", h.prURL}) + if err == nil { + t.Fatalf("review error = nil; stdout = %s", stdout) + } + if code := exitcode.FromError(err); code != exitcode.UpstreamError { + t.Fatalf("exit = %d, want upstream: %v", code, err) + } + if host.posts != 1 { + t.Fatalf("review POSTs = %d, want 1", host.posts) + } + if !strings.Contains(stdout, "post(s) still pending") || !strings.Contains(stdout, "run cr review again") { + t.Fatalf("stdout = %q\nstderr = %q, want the pending cause and next step", stdout, stderr) + } +} diff --git a/internal/cmd/noleak/noleak_test.go b/internal/cmd/noleak/noleak_test.go index 95f21918..bfdf57b0 100644 --- a/internal/cmd/noleak/noleak_test.go +++ b/internal/cmd/noleak/noleak_test.go @@ -45,6 +45,7 @@ import ( "github.com/open-cli-collective/codereview-cli/internal/identity" "github.com/open-cli-collective/codereview-cli/internal/ledger" "github.com/open-cli-collective/codereview-cli/internal/llmadapters" + "github.com/open-cli-collective/codereview-cli/internal/outbox" "github.com/open-cli-collective/codereview-cli/internal/pipeline" "github.com/open-cli-collective/codereview-cli/internal/reviewrun" "github.com/open-cli-collective/codereview-cli/internal/statepaths" @@ -337,6 +338,8 @@ type auditHarness struct { workbenchRepoDir string now time.Time llmCalls atomic.Int32 + // githubFault, when set, answers a GitHub request instead of the fixture. + githubFault func(http.ResponseWriter, *http.Request) bool gitSecret string reviewerSecret string @@ -869,6 +872,7 @@ func (h *auditHarness) reviewRuntimeFactory(ctx context.Context, runtimeOpts app Provider: liveProvider, Planner: livePlanner{opts: pipelineOpts}, Limiter: noLeakLimiter{}, + WriteRetry: &outbox.WriteRetry{Sleep: noRetryWait}, Layout: h.layout, Now: func() time.Time { return h.now }, StaleHeartbeatThreshold: 10 * time.Minute, @@ -897,6 +901,7 @@ func (h *auditHarness) newGitHubProvider(git config.GitConfig, store credentials BaseURL: h.githubURL, GraphQLURL: h.graphQLURL, InstallationLookup: lookup, + Retry: githubprovider.RetryPolicy{Sleep: noRetryWait}, } if lookup == nil { opts.InstallationID = h.githubAppInstallationIDSecret @@ -904,6 +909,8 @@ func (h *auditHarness) newGitHubProvider(git config.GitConfig, store credentials return githubprovider.NewFromGitConfig(git, store, opts) } +func noRetryWait(context.Context, time.Duration) error { return nil } + func gitConfigForReviewerAuth(profile config.Profile) config.GitConfig { if profile.ReviewerCredentials == nil { return profile.Git @@ -983,6 +990,9 @@ func (h *auditHarness) openLedger(t *testing.T) *ledger.Store { } func (h *auditHarness) handleGitHub(w http.ResponseWriter, r *http.Request) { + if h.githubFault != nil && h.githubFault(w, r) { + return + } if r.URL.EscapedPath() == "/graphql" { h.handleGitHubGraphQL(w, r) return diff --git a/internal/cmd/reviewcmd/reviewcmd.go b/internal/cmd/reviewcmd/reviewcmd.go index 8a68895d..4f51ad68 100644 --- a/internal/cmd/reviewcmd/reviewcmd.go +++ b/internal/cmd/reviewcmd/reviewcmd.go @@ -347,7 +347,11 @@ func runReview(ctx context.Context, cmd *cobra.Command, opts *root.Options, fact runtimeSpan := logger.Start("review", "build_runtime", "runtime") runtime, err := factory(ctx, runtimeReq) if err != nil { - return runtimeSpan.End(cmdruntime.MapRunError(err)) + mapped := runtimeSpan.End(cmdruntime.MapRunError(err)) + if !flags.dryRun { + renderLiveFailure(opts, flags, reviewrun.Result{}, mapped) + } + return mapped } _ = runtimeSpan.End(nil) if runtime.Cleanup != nil { @@ -475,11 +479,16 @@ func runLive(ctx context.Context, logger *progress.Logger, opts *root.Options, f execSpan := logger.Start("review", "execute_live", "pr") result, err := runner.Live(ctx, req, reviewrun.Flags{Rerun: flags.rerun, RetryPosts: flags.retryPosts}) if err != nil { - return execSpan.End(cmdruntime.MapRunError(err)) + mapped := execSpan.End(cmdruntime.MapRunError(err)) + renderLiveFailure(opts, flags, result, mapped) + return mapped } _ = execSpan.End(nil) renderSpan := logger.Start("review", "render_result", "stdout") rendered := newReviewLive(result) + if result.ExitCode != exitcode.Success && rendered.Message == "" { + rendered.Message = liveResultError(result).Error() + } err = view.Render(opts.Stdout, flags.jsonOutput, rendered, func(w io.Writer) error { return view.RenderReviewLiveText(w, rendered) }) @@ -496,6 +505,23 @@ func runLive(ctx context.Context, logger *progress.Logger, opts *root.Options, f return nil } +// liveFailureStatus matches the status a gate error already renders with. +const liveFailureStatus = "error" + +// renderLiveFailure gives a failed run the same stdout record as a finished one. +// Without it a consumer reading stdout, for `Status:` or for JSON, sees nothing at +// all when the run fails before producing a result. The error also reaches stderr +// and the exit code through the normal return path. +func renderLiveFailure(opts *root.Options, flags commandFlags, result reviewrun.Result, err error) { + rendered := newReviewLive(result) + rendered.Status = liveFailureStatus + rendered.Message = err.Error() + rendered.Outbox.ExitCode = exitcode.FromError(err) + _ = view.Render(opts.Stdout, flags.jsonOutput, rendered, func(w io.Writer) error { + return view.RenderReviewLiveText(w, rendered) + }) +} + func newReviewLive(result reviewrun.Result) view.ReviewLive { outcome := result.Outbox.Outcome.String() if outcome == "" && result.Run.Outcome != nil { @@ -552,6 +578,9 @@ func liveResultError(result reviewrun.Result) error { if strings.TrimSpace(result.Message) != "" { return errors.New(result.Message) } + if result.Outbox.Pending > 0 && result.Outbox.PendingError != "" { + return fmt.Errorf("live review incomplete: %d post(s) still pending: %s; run cr review again to reconcile and post them", result.Outbox.Pending, result.Outbox.PendingError) + } if result.Outbox.Outcome != "" { return fmt.Errorf("live review completed with outcome %s", result.Outbox.Outcome) } diff --git a/internal/cmd/reviewcmd/reviewcmd_test.go b/internal/cmd/reviewcmd/reviewcmd_test.go index 878a1cc0..52752387 100644 --- a/internal/cmd/reviewcmd/reviewcmd_test.go +++ b/internal/cmd/reviewcmd/reviewcmd_test.go @@ -1158,6 +1158,78 @@ func TestReviewLiveCallsRunnerAndRendersText(t *testing.T) { } } +func TestReviewLiveFailureRendersStatusOnStdoutAndExitsUpstream(t *testing.T) { + failure := gitprovider.WrapError(gitprovider.ErrRetryable, gitprovider.OperationGetPR, errors.New("github: status 502 (gave up after 6 attempts)")) + tests := []struct { + name string + factory func(*fakeRunner) RuntimeFactory + }{ + {name: "runner failure", factory: fakeFactory}, + {name: "runtime failure", factory: func(*fakeRunner) RuntimeFactory { + return func(context.Context, app.OpenRequest) (app.Runtime, error) { return app.Runtime{}, failure } + }}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + cmd, out, _ := newTestCommandWithStderr(t, testConfig(), tt.factory(&fakeRunner{liveErr: failure}), true) + err := root.Execute(cmd, []string{"review", "https://github.com/open-cli-collective/codereview-cli/pull/29"}) + if exitcode.FromError(err) != exitcode.UpstreamError { + t.Fatalf("exit = %d for %v, want upstream", exitcode.FromError(err), err) + } + for _, want := range []string{"Status: error\n", "Exit code: 5\n", "gave up after 6 attempts"} { + if !strings.Contains(out.String(), want) { + t.Fatalf("stdout = %q, want %q", out.String(), want) + } + } + if strings.Contains(out.String(), "Run: ") { + t.Fatalf("stdout = %q, want no empty run line", out.String()) + } + + cmd, out, _ = newTestCommandWithStderr(t, testConfig(), tt.factory(&fakeRunner{liveErr: failure}), true) + err = root.Execute(cmd, []string{"review", "https://github.com/open-cli-collective/codereview-cli/pull/29", "--json"}) + if exitcode.FromError(err) != exitcode.UpstreamError { + t.Fatalf("json exit = %d for %v, want upstream", exitcode.FromError(err), err) + } + var rendered map[string]any + if decodeErr := json.Unmarshal(out.Bytes(), &rendered); decodeErr != nil { + t.Fatalf("decode %q: %v", out.String(), decodeErr) + } + assertJSONPath(t, rendered, "status", "error") + assertJSONPath(t, rendered, "message", failure.Error()) + assertJSONPath(t, rendered, "outbox", "exit_code", float64(exitcode.UpstreamError)) + }) + } +} + +func TestReviewDryRunFailureLeavesStdoutEmpty(t *testing.T) { + failure := gitprovider.WrapError(gitprovider.ErrRetryable, gitprovider.OperationGetPR, errors.New("github: status 502")) + cmd, out, _ := newTestCommandWithStderr(t, testConfig(), fakeFactory(&fakeRunner{err: failure}), true) + err := root.Execute(cmd, []string{"review", "https://github.com/open-cli-collective/codereview-cli/pull/29", "--dry-run"}) + if exitcode.FromError(err) != exitcode.UpstreamError { + t.Fatalf("exit = %d for %v, want upstream", exitcode.FromError(err), err) + } + if out.Len() != 0 { + t.Fatalf("stdout = %q, want empty", out.String()) + } +} + +func TestReviewLiveIncompletePostsNameTheCause(t *testing.T) { + result := testLiveResult(false) + result.ExitCode = exitcode.UpstreamError + result.Outbox = outbox.Result{Outcome: ledger.OutcomeIncomplete, ExitCode: exitcode.UpstreamError, Pending: 2, PendingError: "SubmitReview: github: status 502"} + cmd, out, _ := newTestCommandWithStderr(t, testConfig(), fakeFactory(&fakeRunner{liveResult: result}), true) + + err := root.Execute(cmd, []string{"review", "https://github.com/open-cli-collective/codereview-cli/pull/29"}) + if exitcode.FromError(err) != exitcode.UpstreamError { + t.Fatalf("exit = %d for %v, want upstream", exitcode.FromError(err), err) + } + for _, text := range []string{err.Error(), out.String()} { + if !strings.Contains(text, "2 post(s) still pending") || !strings.Contains(text, "status 502") || !strings.Contains(text, "run cr review again") { + t.Fatalf("text = %q, want pending count, cause and next step", text) + } + } +} + func TestReviewLivePassesReviewerModelAndEffortOverrides(t *testing.T) { runner := &fakeRunner{liveResult: testLiveResult(false)} cmd, _ := newTestCommand(t, testConfig(), fakeFactory(runner)) diff --git a/internal/gateio/gateio.go b/internal/gateio/gateio.go index fe096181..6acc432c 100644 --- a/internal/gateio/gateio.go +++ b/internal/gateio/gateio.go @@ -65,6 +65,7 @@ type Options struct { Store Store Provider outbox.LiveProvider Limiter outbox.Limiter + WriteRetry *outbox.WriteRetry Layout statepaths.Layout Acquire AcquireFunc Now func() time.Time @@ -565,10 +566,11 @@ func executeRepair(ctx context.Context, opts Options, req Request, decision gate return repairExecution{}, err } postResult, err := outbox.Post(ctx, outbox.Options{ - Store: opts.Store, - Provider: opts.Provider, - Limiter: opts.Limiter, - Now: opts.Now, + Store: opts.Store, + Provider: opts.Provider, + Limiter: opts.Limiter, + Now: opts.Now, + WriteRetry: opts.WriteRetry, }, outbox.Request{ Run: run, PRRef: req.PRRef, @@ -603,10 +605,11 @@ func executeApprovalOverride(ctx context.Context, opts Options, req Request) (ap return approvalOverrideExecution{}, err } postResult, err := outbox.Post(ctx, outbox.Options{ - Store: opts.Store, - Provider: opts.Provider, - Limiter: opts.Limiter, - Now: opts.Now, + Store: opts.Store, + Provider: opts.Provider, + Limiter: opts.Limiter, + Now: opts.Now, + WriteRetry: opts.WriteRetry, }, outbox.Request{ Run: run, PRRef: req.PRRef, @@ -647,10 +650,11 @@ func executeRetryPosts(ctx context.Context, opts Options, req Request, run ledge return retryExecution{}, err } postResult, err := outbox.Post(ctx, outbox.Options{ - Store: opts.Store, - Provider: opts.Provider, - Limiter: opts.Limiter, - Now: opts.Now, + Store: opts.Store, + Provider: opts.Provider, + Limiter: opts.Limiter, + Now: opts.Now, + WriteRetry: opts.WriteRetry, }, outbox.Request{ Run: run, PRRef: req.PRRef, diff --git a/internal/gitexec/client.go b/internal/gitexec/client.go index 673d6d55..93654761 100644 --- a/internal/gitexec/client.go +++ b/internal/gitexec/client.go @@ -4,10 +4,16 @@ package gitexec import ( "context" "encoding/base64" + "errors" "fmt" + "math/rand/v2" "net/url" "os/exec" + "regexp" "strings" + "time" + + "github.com/open-cli-collective/codereview-cli/internal/gitprovider" ) // TokenSource supplies the current repository access token. @@ -24,11 +30,33 @@ func (f TokenSourceFunc) AccessToken(ctx context.Context) (string, error) { retu // defaultBasicAuthUsername is the GitHub HTTPS transport convention. const defaultBasicAuthUsername = "x-access-token" +const ( + fetchMaxAttempts = 4 + fetchBaseDelay = 2 * time.Second +) + +// transientFetchOutput matches the messages git and curl print, under the LC_ALL=C +// this client forces, for a failure another attempt can fix. A fetch the host +// refuses for good, such as an unadvertised SHA, matches none of them. +var transientFetchOutput = regexp.MustCompile(`(?i)returned error: (429|5\d\d)|rpc failed|connection reset|recv failure|failed to connect|could not resolve host|timed out|empty reply from server|early eof|unexpected disconnect|remote end hung up|tls connection|ssl_read|gnutls_|http/2 stream`) + +// RetryEvent describes one scheduled retry of a git fetch. +type RetryEvent struct { + Attempt int // the attempt that just failed, starting at 1 + MaxAttempts int + Delay time.Duration + Reason string +} + // Client runs Git with host-scoped HTTPS authentication. type Client struct { host string tokens TokenSource username string + // OnRetry observes each scheduled fetch retry. + OnRetry func(RetryEvent) + // sleep waits between fetch attempts. Tests replace it to avoid real waits. + sleep func(context.Context, time.Duration) error } // New constructs an authenticated Git client using the GitHub HTTPS username @@ -52,11 +80,65 @@ func NewWithUsername(host string, tokens TokenSource, username string) (*Client, if username == "" || strings.Contains(username, ":") { return nil, fmt.Errorf("gitexec: valid basic auth username is required") } - return &Client{host: host, tokens: tokens, username: username}, nil + return &Client{host: host, tokens: tokens, username: username, sleep: sleepContext}, nil } -// Run executes Git in dir, or the current directory when dir is empty. +func sleepContext(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 + } +} + +// Run executes Git in dir, or the current directory when dir is empty. A fetch +// only reads, so one that fails transiently is repeated within a small bound. func (c *Client) Run(ctx context.Context, dir string, args ...string) ([]byte, error) { + if len(args) == 0 || args[0] != "fetch" { + return c.runOnce(ctx, dir, args...) + } + for attempt := 1; ; attempt++ { + output, err := c.runOnce(ctx, dir, args...) + if err == nil || ctx.Err() != nil || !transientFetchFailure(err) { + return output, err + } + if attempt >= fetchMaxAttempts { + return nil, gitprovider.WrapError(gitprovider.ErrRetryable, "", fmt.Errorf("%w (gave up after %d attempts)", err, attempt)) + } + backoff := fetchBaseDelay << (attempt - 1) + delay := backoff/2 + rand.N(backoff/2+1) // #nosec G404 -- backoff spacing, not a secret. + if c.OnRetry != nil { + c.OnRetry(RetryEvent{Attempt: attempt, MaxAttempts: fetchMaxAttempts, Delay: delay, Reason: err.Error()}) + } + if sleepErr := c.sleep(ctx, delay); sleepErr != nil { + if errors.Is(sleepErr, context.Canceled) { + return nil, context.Canceled + } + return nil, gitprovider.WrapError(gitprovider.ErrRetryable, "", err) + } + } +} + +// commandError keeps git's own output apart from its arguments, which carry +// PR-controlled ref names that must not decide whether a failure is transient. +type commandError struct { + args []string + detail string +} + +func (e *commandError) Error() string { + return fmt.Sprintf("git %s: %s", strings.Join(e.args, " "), e.detail) +} + +func transientFetchFailure(err error) bool { + var failure *commandError + return errors.As(err, &failure) && transientFetchOutput.MatchString(failure.detail) +} + +func (c *Client) runOnce(ctx context.Context, dir string, args ...string) ([]byte, error) { header := "" token := "" if requiresAuthentication(c.host, args) { @@ -93,7 +175,7 @@ func (c *Client) Run(ctx context.Context, dir string, args ...string) ([]byte, e if header != "" { detail = strings.ReplaceAll(detail, header, "[REDACTED]") } - return nil, fmt.Errorf("git %s: %s", strings.Join(args, " "), detail) + return nil, &commandError{args: args, detail: detail} } func requiresAuthentication(host string, args []string) bool { diff --git a/internal/gitexec/client_test.go b/internal/gitexec/client_test.go index 58851bf2..a6d848ca 100644 --- a/internal/gitexec/client_test.go +++ b/internal/gitexec/client_test.go @@ -8,8 +8,12 @@ import ( "errors" "os" "path/filepath" + "strconv" "strings" "testing" + "time" + + "github.com/open-cli-collective/codereview-cli/internal/gitprovider" ) type rotatingTokens struct { @@ -143,3 +147,122 @@ func TestClientRedactsTokenFromGitError(t *testing.T) { t.Fatalf("Run error leaked token: %v", err) } } + +// fakeGit installs a git that prints the output of each attempt in turn and +// fails, then succeeds once they run out. It counts its invocations in a file. +func fakeGit(t *testing.T, outputs ...string) (count func() int) { + t.Helper() + dir := t.TempDir() + counter := filepath.Join(dir, "count") + script := "#!/bin/sh\necho x >> '" + counter + "'\nn=$(wc -l < '" + counter + "' | tr -d ' ')\ncase \"$n\" in\n" + for i, output := range outputs { + script += strconv.Itoa(i+1) + ") echo '" + output + "' >&2; exit 128 ;;\n" + } + script += "esac\nexit 0\n" + path := filepath.Join(dir, "git") + if err := os.WriteFile(path, []byte(script), 0o600); err != nil { + t.Fatal(err) + } + if err := os.Chmod(path, 0o700); err != nil { // #nosec G302 -- executable test fixture. + t.Fatal(err) + } + t.Setenv("PATH", dir+string(os.PathListSeparator)+os.Getenv("PATH")) + return func() int { + data, err := os.ReadFile(counter) // #nosec G304 -- test-owned temp file. + if err != nil { + return 0 + } + return strings.Count(string(data), "x") + } +} + +func newRetryTestClient(t *testing.T, delays *[]time.Duration, events *[]RetryEvent) *Client { + t.Helper() + client, err := New("github.com", TokenSourceFunc(func(context.Context) (string, error) { return "token", nil })) + if err != nil { + t.Fatal(err) + } + client.sleep = func(_ context.Context, d time.Duration) error { + *delays = append(*delays, d) + return nil + } + client.OnRetry = func(event RetryEvent) { *events = append(*events, event) } + return client +} + +const testFetchURL = "https://github.com/o/r.git" + +func TestFetchRetriesTransientServerError(t *testing.T) { + count := fakeGit(t, "fatal: unable to access '"+testFetchURL+"/': The requested URL returned error: 502") + var delays []time.Duration + var events []RetryEvent + + if _, err := newRetryTestClient(t, &delays, &events).Run(context.Background(), "", "fetch", "--no-tags", testFetchURL, "abc"); err != nil { + t.Fatalf("Run: %v", err) + } + if count() != 2 || len(delays) != 1 || len(events) != 1 || events[0].Attempt != 1 { + t.Fatalf("runs = %d delays = %v events = %#v, want one retry", count(), delays, events) + } + if delays[0] < time.Second || delays[0] > 2*time.Second { + t.Fatalf("delay = %s, want within the first backoff", delays[0]) + } +} + +func TestFetchGivesUpAsRetryableUpstreamFailure(t *testing.T) { + const failure = "error: RPC failed; curl 56 Recv failure: Connection reset by peer" + count := fakeGit(t, failure, failure, failure, failure, failure) + var delays []time.Duration + var events []RetryEvent + + _, err := newRetryTestClient(t, &delays, &events).Run(context.Background(), "", "fetch", "--no-tags", testFetchURL, "abc") + if !errors.Is(err, gitprovider.ErrRetryable) || !strings.Contains(err.Error(), "gave up after 4 attempts") { + t.Fatalf("error = %v, want retryable failure naming the attempts", err) + } + if count() != fetchMaxAttempts || len(delays) != fetchMaxAttempts-1 { + t.Fatalf("runs = %d delays = %v", count(), delays) + } +} + +func TestPermanentFetchFailureAndOtherCommandsAreNotRetried(t *testing.T) { + tests := []struct { + name string + output string + args []string + }{ + {name: "unadvertised sha", output: "fatal: remote error: upload-pack: not our ref abc", args: []string{"fetch", "--no-tags", testFetchURL, "abc"}}, + {name: "missing repository", output: "fatal: unable to access: The requested URL returned error: 404", args: []string{"fetch", "--no-tags", testFetchURL, "abc"}}, + {name: "transient words only in a ref name", output: "fatal: couldn't find remote ref", args: []string{"fetch", "--no-tags", testFetchURL, "refs/heads/gnutls_fix"}}, + {name: "not a fetch", output: "fatal: The requested URL returned error: 502", args: []string{"rev-parse", "HEAD"}}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + count := fakeGit(t, tt.output, tt.output) + var delays []time.Duration + var events []RetryEvent + + _, err := newRetryTestClient(t, &delays, &events).Run(context.Background(), "", tt.args...) + if err == nil || errors.Is(err, gitprovider.ErrRetryable) { + t.Fatalf("error = %v, want a plain failure", err) + } + if count() != 1 || len(delays) != 0 { + t.Fatalf("runs = %d delays = %v, want one run and no wait", count(), delays) + } + }) + } +} + +func TestFetchRetryStopsWhenContextIsCanceled(t *testing.T) { + const failure = "fatal: The requested URL returned error: 503" + count := fakeGit(t, failure, failure) + var delays []time.Duration + var events []RetryEvent + client := newRetryTestClient(t, &delays, &events) + client.sleep = func(context.Context, time.Duration) error { return context.Canceled } + + if _, err := client.Run(context.Background(), "", "fetch", "--no-tags", testFetchURL, "abc"); !errors.Is(err, context.Canceled) { + t.Fatalf("error = %v, want context.Canceled", err) + } + if count() != 1 { + t.Fatalf("runs = %d, want 1", count()) + } +} diff --git a/internal/gitprovider/errors.go b/internal/gitprovider/errors.go index dc18128c..cb339555 100644 --- a/internal/gitprovider/errors.go +++ b/internal/gitprovider/errors.go @@ -3,6 +3,7 @@ package gitprovider import ( "errors" "fmt" + "time" ) // Typed provider errors. Concrete adapters map host-specific failures into @@ -81,3 +82,37 @@ func WrapError(kind error, op Operation, err error) error { } return &ProviderError{Op: op, Kind: kind, Err: err} } + +// RetryAfterError carries the wait a host asked for through the error chain, so +// whichever layer retries can honor it without knowing HTTP headers. +type RetryAfterError struct { + After time.Duration + Err error +} + +func (e *RetryAfterError) Error() string { + if e == nil { + return "" + } + if e.Err == nil { + return "gitprovider: retry after " + e.After.String() + } + return e.Err.Error() +} + +// Unwrap exposes the classified provider error. +func (e *RetryAfterError) Unwrap() error { + if e == nil { + return nil + } + return e.Err +} + +// RetryAfterHint reports the wait the host requested, if err carries one. +func RetryAfterHint(err error) (time.Duration, bool) { + var hinted *RetryAfterError + if errors.As(err, &hinted) && hinted != nil { + return hinted.After, true + } + return 0, false +} diff --git a/internal/gitprovider/errors_test.go b/internal/gitprovider/errors_test.go index 9ff675e5..10af3922 100644 --- a/internal/gitprovider/errors_test.go +++ b/internal/gitprovider/errors_test.go @@ -2,7 +2,9 @@ package gitprovider import ( "errors" + "fmt" "testing" + "time" ) func TestProviderErrorMatchesKindAndCause(t *testing.T) { @@ -51,3 +53,25 @@ func TestProviderErrorZeroValueDoesNotPanic(t *testing.T) { t.Fatal("ProviderError with op Error() = empty string, want non-empty") } } + +func TestRetryAfterErrorKeepsClassificationAndHint(t *testing.T) { + inner := WrapError(ErrRetryable, OperationGetPR, errors.New("github: status 429")) + wrapped := fmt.Errorf("outer: %w", &RetryAfterError{After: 7 * time.Second, Err: inner}) + + if !errors.Is(wrapped, ErrRetryable) { + t.Fatalf("errors.Is(ErrRetryable) = false for %v", wrapped) + } + var providerErr *ProviderError + if !errors.As(wrapped, &providerErr) || providerErr.Op != OperationGetPR { + t.Fatalf("errors.As(ProviderError) = %#v", providerErr) + } + if hint, ok := RetryAfterHint(wrapped); !ok || hint != 7*time.Second { + t.Fatalf("RetryAfterHint = %s, %t", hint, ok) + } + if wrapped.Error() != "outer: "+inner.Error() { + t.Fatalf("Error() = %q", wrapped) + } + if _, ok := RetryAfterHint(inner); ok { + t.Fatal("RetryAfterHint found a hint on an unhinted error") + } +} diff --git a/internal/gitprovider/github/app_auth.go b/internal/gitprovider/github/app_auth.go index d29056df..a660d7c7 100644 --- a/internal/gitprovider/github/app_auth.go +++ b/internal/gitprovider/github/app_auth.go @@ -43,6 +43,7 @@ type githubAppAuth struct { tokenValue string expiresAt time.Time identity gitprovider.Identity + retry retrier } type githubAppInstallation struct { @@ -92,6 +93,7 @@ func newGitHubAppFromConfig(ctx context.Context, profile string, store credentia if !canResolveInstallation(installationID, opts.InstallationLookup) { return nil, gitprovider.Credential{}, gitprovider.WrapError(gitprovider.ErrAuth, "", fmt.Errorf("github app installation discovery requires repository context; pin an installation id or run against a repository")) } + retry := newRetrier(opts.Retry, now) auth := &githubAppAuth{ issuer: issuer, privateKey: privateKey, @@ -100,6 +102,7 @@ func newGitHubAppFromConfig(ctx context.Context, profile string, store credentia httpClient: httpClient, baseURL: baseURL, now: now, + retry: retry, } token, identity, err := auth.refresh(ctx, "") if err != nil { @@ -112,6 +115,7 @@ func newGitHubAppFromConfig(ctx context.Context, profile string, store credentia baseURL: baseURL, graphQLURL: graphQLURL, appAuth: auth, + retry: retry, } credential := gitprovider.Credential{ Type: credentialTypeGitHubApp, @@ -230,22 +234,28 @@ func mapCreateInstallationTokenError(op gitprovider.Operation, installationID st } func (a *githubAppAuth) doAppREST(ctx context.Context, op gitprovider.Operation, method, endpoint, jwt string, in any, out any) error { - var body *bytes.Reader + var payload []byte if in != nil { - payload, err := json.Marshal(in) + var err error + payload, err = json.Marshal(in) if err != nil { return err } - body = bytes.NewReader(payload) - } else { - body = bytes.NewReader(nil) } - req, err := http.NewRequestWithContext(ctx, method, endpoint, body) + // Installation lookups are reads and minting a token changes nothing a user + // can see, so these repeat even when op names the write that needed a token. + return a.retry.repeat(ctx, op, func() error { + return a.appRESTAttempt(ctx, op, method, endpoint, jwt, payload, in != nil, out) + }) +} + +func (a *githubAppAuth) appRESTAttempt(ctx context.Context, op gitprovider.Operation, method, endpoint, jwt string, payload []byte, hasBody bool, out any) error { + req, err := http.NewRequestWithContext(ctx, method, endpoint, bytes.NewReader(payload)) if err != nil { return err } setHeaders(req, jwt, acceptJSON) - if in != nil { + if hasBody { req.Header.Set("Content-Type", "application/json") } resp, err := a.httpClient.Do(req) @@ -258,7 +268,7 @@ func (a *githubAppAuth) doAppREST(ctx context.Context, op gitprovider.Operation, return gitprovider.WrapError(gitprovider.ErrRetryable, op, readErr) } if resp.StatusCode < 200 || resp.StatusCode > 299 { - return mapHTTPStatus(op, resp.StatusCode, responseBody) + return a.retry.responseError(op, resp.StatusCode, resp.Header, responseBody, mapHTTPStatus) } if out != nil { if err := json.Unmarshal(responseBody, out); err != nil { diff --git a/internal/gitprovider/github/client.go b/internal/gitprovider/github/client.go index 4fe0419c..4c37914d 100644 --- a/internal/gitprovider/github/client.go +++ b/internal/gitprovider/github/client.go @@ -48,6 +48,7 @@ type Options struct { AppID string InstallationID string InstallationLookup *InstallationLookup + Retry RetryPolicy } // Client is a GitHub read adapter. CR-10 adds write methods and full @@ -59,6 +60,7 @@ type Client struct { baseURL *url.URL graphQLURL *url.URL appAuth *githubAppAuth + retry retrier } // NewFromGitConfig builds a GitHub client and credential from config plus a token store. @@ -148,6 +150,7 @@ func New(opts Options) (*Client, error) { httpClient: httpClient, baseURL: baseURL, graphQLURL: graphQLURL, + retry: newRetrier(opts.Retry, opts.Now), }, nil } diff --git a/internal/gitprovider/github/client_test.go b/internal/gitprovider/github/client_test.go index 5bf29f15..9e843c52 100644 --- a/internal/gitprovider/github/client_test.go +++ b/internal/gitprovider/github/client_test.go @@ -9,6 +9,7 @@ import ( "net/http/httptest" "strings" "testing" + "time" "github.com/open-cli-collective/codereview-cli/internal/config" "github.com/open-cli-collective/codereview-cli/internal/credentials" @@ -407,6 +408,9 @@ func mustClient(t *testing.T, opts Options) *Client { if opts.Host == "" { opts.Host = defaultHost } + if opts.Retry.Sleep == nil { + opts.Retry.Sleep = func(context.Context, time.Duration) error { return nil } + } client, err := New(opts) if err != nil { t.Fatalf("New: %v", err) diff --git a/internal/gitprovider/github/graphql_reads.go b/internal/gitprovider/github/graphql_reads.go index 86ea79c6..3bad6813 100644 --- a/internal/gitprovider/github/graphql_reads.go +++ b/internal/gitprovider/github/graphql_reads.go @@ -51,6 +51,7 @@ query($owner: String!, $repo: String!, $number: Int!, $threadAfter: String) { databaseId body author { + __typename login ... on User { id: databaseId @@ -88,6 +89,7 @@ query($threadID: ID!, $commentAfter: String) { databaseId body author { + __typename login ... on User { id: databaseId diff --git a/internal/gitprovider/github/http.go b/internal/gitprovider/github/http.go index 878be122..1f6d2284 100644 --- a/internal/gitprovider/github/http.go +++ b/internal/gitprovider/github/http.go @@ -31,6 +31,20 @@ func (c *Client) doREST(ctx context.Context, op gitprovider.Operation, method, e } func (c *Client) doRESTWithToken(ctx context.Context, op gitprovider.Operation, method, endpoint, token, accept string, out any) ([]byte, http.Header, error) { + var body []byte + var header http.Header + err := c.retry.do(ctx, op, func() error { + var attemptErr error + body, header, attemptErr = c.restAttempt(ctx, op, method, endpoint, token, accept, out) + return attemptErr + }) + if err != nil { + return nil, header, err + } + return body, header, nil +} + +func (c *Client) restAttempt(ctx context.Context, op gitprovider.Operation, method, endpoint, token, accept string, out any) ([]byte, http.Header, error) { req, err := http.NewRequestWithContext(ctx, method, endpoint, nil) if err != nil { return nil, nil, err @@ -46,7 +60,7 @@ func (c *Client) doRESTWithToken(ctx context.Context, op gitprovider.Operation, return nil, nil, gitprovider.WrapError(gitprovider.ErrRetryable, op, readErr) } if resp.StatusCode < 200 || resp.StatusCode > 299 { - return nil, resp.Header, mapHTTPStatus(op, resp.StatusCode, body) + return nil, resp.Header, c.retry.responseError(op, resp.StatusCode, resp.Header, body, mapHTTPStatus) } if out != nil { if err := json.Unmarshal(body, out); err != nil { @@ -61,11 +75,17 @@ func (c *Client) doRESTJSON(ctx context.Context, op gitprovider.Operation, metho if err != nil { return err } - req, err := http.NewRequestWithContext(ctx, method, endpoint, bytes.NewReader(payload)) + token, err := c.bearerToken(ctx, op) if err != nil { return err } - token, err := c.bearerToken(ctx, op) + return c.retry.do(ctx, op, func() error { + return c.restJSONAttempt(ctx, op, method, endpoint, token, payload, out) + }) +} + +func (c *Client) restJSONAttempt(ctx context.Context, op gitprovider.Operation, method, endpoint, token string, payload []byte, out any) error { + req, err := http.NewRequestWithContext(ctx, method, endpoint, bytes.NewReader(payload)) if err != nil { return err } @@ -81,7 +101,7 @@ func (c *Client) doRESTJSON(ctx context.Context, op gitprovider.Operation, metho return gitprovider.WrapError(gitprovider.ErrRetryable, op, readErr) } if resp.StatusCode < 200 || resp.StatusCode > 299 { - return mapWriteHTTPStatus(op, resp.StatusCode, body) + return c.retry.responseError(op, resp.StatusCode, resp.Header, body, mapWriteHTTPStatus) } if out != nil { if err := json.Unmarshal(body, out); err != nil { @@ -118,11 +138,17 @@ func (c *Client) doGraphQLWithErrorMapper(ctx context.Context, op gitprovider.Op if err != nil { return err } - req, err := http.NewRequestWithContext(ctx, http.MethodPost, c.graphQLURL.String(), bytes.NewReader(payload)) + token, err := c.bearerToken(ctx, op) if err != nil { return err } - token, err := c.bearerToken(ctx, op) + return c.retry.do(ctx, op, func() error { + return c.graphQLAttempt(ctx, op, token, payload, out, mapErrors) + }) +} + +func (c *Client) graphQLAttempt(ctx context.Context, op gitprovider.Operation, token string, payload []byte, out any, mapErrors func(gitprovider.Operation, []graphQLError) error) error { + req, err := http.NewRequestWithContext(ctx, http.MethodPost, c.graphQLURL.String(), bytes.NewReader(payload)) if err != nil { return err } @@ -138,7 +164,7 @@ func (c *Client) doGraphQLWithErrorMapper(ctx context.Context, op gitprovider.Op return gitprovider.WrapError(gitprovider.ErrRetryable, op, readErr) } if resp.StatusCode < 200 || resp.StatusCode > 299 { - return mapHTTPStatus(op, resp.StatusCode, body) + return c.retry.responseError(op, resp.StatusCode, resp.Header, body, mapHTTPStatus) } var envelope graphQLResponse @@ -146,7 +172,7 @@ func (c *Client) doGraphQLWithErrorMapper(ctx context.Context, op gitprovider.Op return fmt.Errorf("%w: decode GraphQL response: %w", ErrValidation, err) } if len(envelope.Errors) > 0 { - return mapErrors(op, envelope.Errors) + return c.retry.withRetryHint(mapErrors(op, envelope.Errors), resp.Header) } if out == nil { return nil diff --git a/internal/gitprovider/github/rest.go b/internal/gitprovider/github/rest.go index 89e649a5..926b8d32 100644 --- a/internal/gitprovider/github/rest.go +++ b/internal/gitprovider/github/rest.go @@ -13,9 +13,10 @@ import ( ) type userResponse struct { - Login string `json:"login"` - ID int64 `json:"id"` - Name string `json:"name"` + Login string `json:"login"` + ID int64 `json:"id"` + Name string `json:"name"` + Typename string `json:"__typename"` } type repoResponse struct { @@ -313,8 +314,15 @@ func (c *Client) ListIssueComments(ctx context.Context, ref gitprovider.PRRef) ( } func identityFromUser(user userResponse) gitprovider.Identity { + login := user.Login + // GraphQL names an app "slug" where REST and the posting identity say + // "slug[bot]". Outbox reconciliation matches authors by this login, so the + // two must agree or an app's own posted marker goes unrecognized. + if user.Typename == "Bot" && login != "" && !strings.HasSuffix(login, "[bot]") { + login += "[bot]" + } return gitprovider.Identity{ - Login: user.Login, + Login: login, ID: stringIDFromInt(user.ID), DisplayName: user.Name, } diff --git a/internal/gitprovider/github/retry.go b/internal/gitprovider/github/retry.go new file mode 100644 index 00000000..58f23fa0 --- /dev/null +++ b/internal/gitprovider/github/retry.go @@ -0,0 +1,278 @@ +package github + +import ( + "context" + "crypto/tls" + "encoding/json" + "errors" + "fmt" + "math/rand/v2" + "net/http" + "strconv" + "strings" + "time" + + "github.com/open-cli-collective/codereview-cli/internal/gitprovider" +) + +const ( + defaultRetryMaxAttempts = 6 + defaultRetryBaseDelay = time.Second + defaultRetryMaxDelay = 16 * time.Second + // defaultRetryMaxWait is the longest host-requested wait worth sitting + // through. A primary rate limit can ask for most of an hour; that fails now + // with the reason instead of parking the run. + defaultRetryMaxWait = 2 * time.Minute + // defaultRetryMaxElapsed bounds one call across attempts, because each + // attempt can itself spend defaultHTTPTimeout on an abandoned connection. + defaultRetryMaxElapsed = 5 * time.Minute + // defaultRateLimitWait is GitHub's documented minimum wait when a rate-limit + // response names no wait of its own. + defaultRateLimitWait = time.Minute +) + +// RetryEvent describes one scheduled retry of a read. +type RetryEvent struct { + Op gitprovider.Operation + Attempt int // the attempt that just failed, starting at 1 + MaxAttempts int + Delay time.Duration + Reason string +} + +// RetryPolicy bounds retries of idempotent GitHub requests. Zero fields take +// the defaults; MaxAttempts of 1 disables retrying. +type RetryPolicy struct { + MaxAttempts int + BaseDelay time.Duration + MaxDelay time.Duration + MaxWait time.Duration + MaxElapsed time.Duration + // Sleep waits for d or until ctx ends. Tests inject it to avoid real waits. + Sleep func(ctx context.Context, d time.Duration) error + // Jitter maps a backoff to the delay actually used. + Jitter func(time.Duration) time.Duration + // OnRetry observes each scheduled retry. + OnRetry func(RetryEvent) +} + +type retrier struct { + policy RetryPolicy + now func() time.Time +} + +func newRetrier(policy RetryPolicy, now func() time.Time) retrier { + if policy.MaxAttempts <= 0 { + policy.MaxAttempts = defaultRetryMaxAttempts + } + if policy.BaseDelay <= 0 { + policy.BaseDelay = defaultRetryBaseDelay + } + if policy.MaxDelay <= 0 { + policy.MaxDelay = defaultRetryMaxDelay + } + if policy.MaxWait <= 0 { + policy.MaxWait = defaultRetryMaxWait + } + if policy.MaxElapsed <= 0 { + policy.MaxElapsed = defaultRetryMaxElapsed + } + if policy.Sleep == nil { + policy.Sleep = sleepContext + } + if policy.Jitter == nil { + policy.Jitter = equalJitter + } + if now == nil { + now = time.Now + } + return retrier{policy: policy, now: now} +} + +func sleepContext(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 + } +} + +func equalJitter(d time.Duration) time.Duration { + half := d / 2 + if half <= 0 { + return d + } + return half + rand.N(half+1) // #nosec G404 -- backoff spacing, not a secret. +} + +// retrySafeOperation lists what may be re-sent blindly. Anything else — writes +// and any operation added later — gets one attempt, because a write can land at +// GitHub and still return 5xx. Review writes are retried by internal/outbox, +// which re-reads the PR for its action marker before sending again. +func retrySafeOperation(op gitprovider.Operation) bool { + switch op { + case gitprovider.OperationWhoAmI, + gitprovider.OperationReviewAuthority, + gitprovider.OperationGetPR, + gitprovider.OperationGetDiff, + gitprovider.OperationGetDiffBetweenRefs, + gitprovider.OperationGetFileAtRef, + gitprovider.OperationListTreeAtRef, + gitprovider.OperationListInlineThreads, + gitprovider.OperationListReviews, + gitprovider.OperationListIssueComments, + gitprovider.OperationListRepositoryInvitations: + return true + case gitprovider.OperationPostInlineComment, + gitprovider.OperationReplyToThread, + gitprovider.OperationResolveThread, + gitprovider.OperationPostIssueComment, + gitprovider.OperationSubmitReview, + gitprovider.OperationAcceptRepositoryInvitation: + return false + default: + return false + } +} + +// do runs attempt under the policy when op is safe to repeat. +func (r retrier) do(ctx context.Context, op gitprovider.Operation, attempt func() error) error { + if !retrySafeOperation(op) { + return attempt() + } + return r.repeat(ctx, op, attempt) +} + +// repeat runs attempt until it stops failing retryably or the policy runs out. +func (r retrier) repeat(ctx context.Context, op gitprovider.Operation, attempt func() error) error { + started := r.now() + for tries := 1; ; tries++ { + err := attempt() + if err == nil || !errors.Is(err, gitprovider.ErrRetryable) || isPermanentTransportError(err) || ctx.Err() != nil { + return err + } + if tries >= r.policy.MaxAttempts { + return fmt.Errorf("%w (gave up after %d attempts)", err, tries) + } + delay := r.delay(tries, err) + if hint, ok := gitprovider.RetryAfterHint(err); ok && hint > r.policy.MaxWait { + return fmt.Errorf("%w (not retrying: GitHub asked to wait %s)", err, hint.Round(time.Second)) + } + if r.now().Sub(started)+delay > r.policy.MaxElapsed { + return fmt.Errorf("%w (gave up after %d attempts over %s)", err, tries, r.now().Sub(started).Round(time.Second)) + } + if deadline, ok := ctx.Deadline(); ok && r.now().Add(delay).After(deadline) { + return err + } + if r.policy.OnRetry != nil { + r.policy.OnRetry(RetryEvent{Op: op, Attempt: tries, MaxAttempts: r.policy.MaxAttempts, Delay: delay, Reason: retryReason(err)}) + } + if sleepErr := r.policy.Sleep(ctx, delay); sleepErr != nil { + if errors.Is(sleepErr, context.Canceled) { + return context.Canceled + } + return err + } + } +} + +func (r retrier) delay(tries int, err error) time.Duration { + backoff := r.policy.BaseDelay << (tries - 1) + if backoff > r.policy.MaxDelay || backoff <= 0 { + backoff = r.policy.MaxDelay + } + delay := r.policy.Jitter(backoff) + if hint, ok := gitprovider.RetryAfterHint(err); ok && hint > delay { + return hint + } + return delay +} + +// isPermanentTransportError spots transport failures another attempt cannot +// fix. They keep their ErrRetryable classification for exit codes. +func isPermanentTransportError(err error) bool { + var certErr *tls.CertificateVerificationError + return errors.As(err, &certErr) +} + +func retryReason(err error) string { + var providerErr *gitprovider.ProviderError + if errors.As(err, &providerErr) && providerErr.Err != nil { + return providerErr.Err.Error() + } + return err.Error() +} + +// responseError classifies a non-2xx response, attaching any requested wait. +func (r retrier) responseError(op gitprovider.Operation, status int, header http.Header, body []byte, classify func(gitprovider.Operation, int, []byte) error) error { + if !isRateLimitResponse(status, header, body) { + return r.withRetryHint(classify(op, status, body), header) + } + err := gitprovider.WrapError(gitprovider.ErrRetryable, op, fmt.Errorf("github: status %d (rate limited)", status)) + hint, ok := requestedWait(header, r.now()) + if !ok { + hint = defaultRateLimitWait + } + return &gitprovider.RetryAfterError{After: hint, Err: err} +} + +// withRetryHint attaches the wait from header to a retryable err. +func (r retrier) withRetryHint(err error, header http.Header) error { + if !errors.Is(err, gitprovider.ErrRetryable) { + return err + } + if hint, ok := requestedWait(header, r.now()); ok { + return &gitprovider.RetryAfterError{After: hint, Err: err} + } + return err +} + +// isRateLimitResponse recognizes a rate limit GitHub reports as 403 rather than +// 429. mapHTTPStatus would call that a permission failure, and the outbox would +// then record a terminal auth failure for a request that only needed waiting. +func isRateLimitResponse(status int, header http.Header, body []byte) bool { + if status == http.StatusTooManyRequests { + return true + } + if status != http.StatusForbidden { + return false + } + if strings.TrimSpace(header.Get("Retry-After")) != "" || strings.TrimSpace(header.Get("X-RateLimit-Remaining")) == "0" { + return true + } + var payload struct { + Message string `json:"message"` + } + if err := json.Unmarshal(body, &payload); err != nil { + return false + } + return strings.Contains(strings.ToLower(payload.Message), "rate limit") +} + +// requestedWait reads GitHub's documented order: Retry-After first, then +// X-RateLimit-Reset once the quota is exhausted. +func requestedWait(header http.Header, now time.Time) (time.Duration, bool) { + if value := strings.TrimSpace(header.Get("Retry-After")); value != "" { + if seconds, err := strconv.Atoi(value); err == nil { + if seconds < 0 { + return 0, false + } + return time.Duration(seconds) * time.Second, true + } + if at, err := http.ParseTime(value); err == nil { + return max(at.Sub(now), 0), true + } + return 0, false + } + if strings.TrimSpace(header.Get("X-RateLimit-Remaining")) != "0" { + return 0, false + } + reset, err := strconv.ParseInt(strings.TrimSpace(header.Get("X-RateLimit-Reset")), 10, 64) + if err != nil { + return 0, false + } + return max(time.Unix(reset, 0).Sub(now), 0), true +} diff --git a/internal/gitprovider/github/retry_test.go b/internal/gitprovider/github/retry_test.go new file mode 100644 index 00000000..8bfdd32d --- /dev/null +++ b/internal/gitprovider/github/retry_test.go @@ -0,0 +1,523 @@ +package github + +import ( + "context" + "crypto/tls" + "errors" + "net/http" + "net/http/httptest" + "os" + "strconv" + "strings" + "sync/atomic" + "testing" + "time" + + "github.com/open-cli-collective/codereview-cli/internal/gitprovider" + "github.com/open-cli-collective/codereview-cli/internal/review" +) + +// retryRecorder injects the wait and records what the policy asked for. +type retryRecorder struct { + delays []time.Duration + events []RetryEvent +} + +func (r *retryRecorder) policy() RetryPolicy { + return RetryPolicy{ + Sleep: func(_ context.Context, d time.Duration) error { + r.delays = append(r.delays, d) + return nil + }, + Jitter: func(d time.Duration) time.Duration { return d }, + OnRetry: func(event RetryEvent) { r.events = append(r.events, event) }, + } +} + +func retryClient(t *testing.T, serverURL string, policy RetryPolicy) *Client { + t.Helper() + return mustClient(t, Options{Token: "token", BaseURL: serverURL, GraphQLURL: serverURL + "/graphql", Retry: policy}) +} + +func patCredential() gitprovider.Credential { + return gitprovider.Credential{Type: credentialTypePAT, Token: "token"} +} + +// failingThenOK answers with the given statuses in turn, then with okBody. +func failingThenOK(calls *atomic.Int32, okBody string, statuses ...int) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + n := int(calls.Add(1)) + if n <= len(statuses) { + w.WriteHeader(statuses[n-1]) + return + } + _, _ = w.Write([]byte(okBody)) + }) +} + +func TestReadRetriesServerErrorsThenSucceeds(t *testing.T) { + for _, status := range []int{500, 502, 503, 504} { + t.Run(http.StatusText(status), func(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(failingThenOK(&calls, `{"login":"octocat","id":1}`, status)) + defer server.Close() + recorder := &retryRecorder{} + + identity, err := retryClient(t, server.URL, recorder.policy()).WhoAmI(context.Background(), patCredential()) + if err != nil { + t.Fatalf("WhoAmI: %v", err) + } + if identity.Login != "octocat" || calls.Load() != 2 { + t.Fatalf("identity = %#v after %d calls, want octocat after 2", identity, calls.Load()) + } + if len(recorder.events) != 1 { + t.Fatalf("events = %#v, want one", recorder.events) + } + event := recorder.events[0] + if event.Op != gitprovider.OperationWhoAmI || event.Attempt != 1 || event.MaxAttempts != defaultRetryMaxAttempts || event.Delay != defaultRetryBaseDelay || !strings.Contains(event.Reason, "status") { + t.Fatalf("event = %#v", event) + } + }) + } +} + +func TestReadRetriesConnectionReset(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + if calls.Add(1) == 1 { + conn, _, err := w.(http.Hijacker).Hijack() + if err != nil { + t.Errorf("Hijack: %v", err) + return + } + if tcp, ok := conn.(interface{ SetLinger(int) error }); ok { + _ = tcp.SetLinger(0) // Close with RST rather than FIN. + } + _ = conn.Close() + return + } + _, _ = w.Write([]byte(`{"login":"octocat","id":1}`)) + })) + defer server.Close() + + if _, err := retryClient(t, server.URL, (&retryRecorder{}).policy()).WhoAmI(context.Background(), patCredential()); err != nil { + t.Fatalf("WhoAmI: %v", err) + } + if calls.Load() != 2 { + t.Fatalf("calls = %d, want 2", calls.Load()) + } +} + +func TestGraphQLReadRetriesServerErrorAndRetryableEnvelope(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _ = readGraphQLRequestAtEndpoint(t, r) + switch calls.Add(1) { + case 1: + w.WriteHeader(http.StatusBadGateway) + case 2: + writeJSON(t, w, map[string]any{"errors": []graphQLError{{Type: "INTERNAL", Message: "server failed"}}}) + default: + _, _ = w.Write([]byte(`{"data":{"repository":{"pullRequest":{"reviewThreads":{"pageInfo":{"hasNextPage":false},"nodes":[]}}}}}`)) + } + })) + defer server.Close() + + threads, err := retryClient(t, server.URL, (&retryRecorder{}).policy()).ListInlineThreads(context.Background(), testPRRef()) + if err != nil { + t.Fatalf("ListInlineThreads: %v", err) + } + if len(threads) != 0 || calls.Load() != 3 { + t.Fatalf("threads = %#v after %d calls, want none after 3", threads, calls.Load()) + } +} + +func TestReadGivesUpAfterBoundedBackoffWithClearError(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + calls.Add(1) + w.WriteHeader(http.StatusBadGateway) + })) + defer server.Close() + recorder := &retryRecorder{} + + _, err := retryClient(t, server.URL, recorder.policy()).GetPR(context.Background(), testPRRef()) + if !errors.Is(err, gitprovider.ErrRetryable) { + t.Fatalf("error = %v, want ErrRetryable", err) + } + for _, want := range []string{"GetPR", "status 502", "gave up after 6 attempts"} { + if !strings.Contains(err.Error(), want) { + t.Fatalf("error = %q, want %q", err, want) + } + } + if calls.Load() != defaultRetryMaxAttempts { + t.Fatalf("calls = %d, want %d", calls.Load(), defaultRetryMaxAttempts) + } + want := []time.Duration{time.Second, 2 * time.Second, 4 * time.Second, 8 * time.Second, 16 * time.Second} + if len(recorder.delays) != len(want) { + t.Fatalf("delays = %v, want %v", recorder.delays, want) + } + for i := range want { + if recorder.delays[i] != want[i] { + t.Fatalf("delays = %v, want %v", recorder.delays, want) + } + } +} + +func TestDefaultJitterStaysWithinBackoff(t *testing.T) { + for range 200 { + if got := equalJitter(8 * time.Second); got < 4*time.Second || got > 8*time.Second { + t.Fatalf("equalJitter = %s, want 4s to 8s", got) + } + } +} + +func TestRetryStopsAtElapsedBudget(t *testing.T) { + now := time.Date(2026, 11, 3, 12, 0, 0, 0, time.UTC) + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + calls.Add(1) + w.Header().Set("Retry-After", "100") + w.WriteHeader(http.StatusServiceUnavailable) + })) + defer server.Close() + client := mustClient(t, Options{ + Token: "token", BaseURL: server.URL, GraphQLURL: server.URL + "/graphql", + Now: func() time.Time { return now }, + Retry: RetryPolicy{ + MaxElapsed: 3 * time.Minute, + Jitter: func(d time.Duration) time.Duration { return d }, + Sleep: func(_ context.Context, d time.Duration) error { + now = now.Add(d) + return nil + }, + }, + }) + + _, err := client.GetPR(context.Background(), testPRRef()) + if !errors.Is(err, gitprovider.ErrRetryable) || !strings.Contains(err.Error(), "gave up after 2 attempts over 1m40s") { + t.Fatalf("error = %v, want elapsed-budget failure", err) + } + if calls.Load() != 2 { + t.Fatalf("calls = %d, want 2", calls.Load()) + } +} + +func TestRetryHonorsRetryAfter(t *testing.T) { + now := time.Date(2026, 11, 3, 12, 0, 0, 0, time.UTC) + tests := []struct { + name string + status int + header map[string]string + body string + wantDelay time.Duration + }{ + {name: "503 seconds", status: 503, header: map[string]string{"Retry-After": "7"}, wantDelay: 7 * time.Second}, + {name: "503 http date", status: 503, header: map[string]string{"Retry-After": now.Add(9 * time.Second).UTC().Format(http.TimeFormat)}, wantDelay: 9 * time.Second}, + {name: "shorter than backoff keeps backoff", status: 503, header: map[string]string{"Retry-After": "0"}, wantDelay: time.Second}, + {name: "unparseable falls back to backoff", status: 503, header: map[string]string{"Retry-After": "soon"}, wantDelay: time.Second}, + {name: "429 retry after", status: 429, header: map[string]string{"Retry-After": "30"}, wantDelay: 30 * time.Second}, + {name: "secondary limit as 403 retry after", status: 403, header: map[string]string{"Retry-After": "45"}, wantDelay: 45 * time.Second}, + {name: "secondary limit as 403 message only", status: 403, body: `{"message":"You have exceeded a secondary rate limit."}`, wantDelay: time.Minute}, + {name: "429 no headers", status: 429, wantDelay: time.Minute}, + {name: "exhausted quota reset", status: 403, header: map[string]string{"X-RateLimit-Remaining": "0", "X-RateLimit-Reset": strconv.FormatInt(now.Add(20*time.Second).Unix(), 10)}, wantDelay: 20 * time.Second}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + if calls.Add(1) == 1 { + for key, value := range tt.header { + w.Header().Set(key, value) + } + w.WriteHeader(tt.status) + _, _ = w.Write([]byte(tt.body)) + return + } + _, _ = w.Write([]byte(`{"login":"octocat","id":1}`)) + })) + defer server.Close() + recorder := &retryRecorder{} + client := mustClient(t, Options{Token: "token", BaseURL: server.URL, GraphQLURL: server.URL + "/graphql", Now: func() time.Time { return now }, Retry: recorder.policy()}) + + if _, err := client.WhoAmI(context.Background(), patCredential()); err != nil { + t.Fatalf("WhoAmI: %v", err) + } + if len(recorder.delays) != 1 || recorder.delays[0] != tt.wantDelay { + t.Fatalf("delays = %v, want [%s]", recorder.delays, tt.wantDelay) + } + }) + } +} + +func TestRetryRefusesWaitBeyondLimit(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + calls.Add(1) + w.Header().Set("Retry-After", "1800") + w.WriteHeader(http.StatusForbidden) + })) + defer server.Close() + recorder := &retryRecorder{} + + _, err := retryClient(t, server.URL, recorder.policy()).GetPR(context.Background(), testPRRef()) + if !errors.Is(err, gitprovider.ErrRetryable) || errors.Is(err, gitprovider.ErrPermission) { + t.Fatalf("error = %v, want rate limit as ErrRetryable", err) + } + if !strings.Contains(err.Error(), "GitHub asked to wait 30m0s") { + t.Fatalf("error = %q, want the requested wait", err) + } + if calls.Load() != 1 || len(recorder.delays) != 0 { + t.Fatalf("calls = %d delays = %v, want one call and no wait", calls.Load(), recorder.delays) + } +} + +func TestNonTransientFailuresAreNotRetried(t *testing.T) { + tests := []struct { + name string + status int + body string + want error + }{ + {name: "404 fails fast", status: 404, want: gitprovider.ErrNotFound}, + {name: "401", status: 401, want: gitprovider.ErrAuth}, + {name: "403 without rate limit signal", status: 403, body: `{"message":"Resource not accessible"}`, want: gitprovider.ErrPermission}, + {name: "409", status: 409, want: gitprovider.ErrConflict}, + {name: "422", status: 422, want: ErrValidation}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + calls.Add(1) + w.WriteHeader(tt.status) + _, _ = w.Write([]byte(tt.body)) + })) + defer server.Close() + recorder := &retryRecorder{} + + _, err := retryClient(t, server.URL, recorder.policy()).GetDiff(context.Background(), testPRRef()) + if !errors.Is(err, tt.want) { + t.Fatalf("error = %v, want %v", err, tt.want) + } + if calls.Load() != 1 || len(recorder.delays) != 0 { + t.Fatalf("calls = %d delays = %v, want one call and no wait", calls.Load(), recorder.delays) + } + }) + } +} + +func TestWritesAreNotRetriedByTheClient(t *testing.T) { + ref := testPRRef() + sha := "head-sha" + tests := []struct { + name string + write func(*Client) error + }{ + {name: "inline comment", write: func(c *Client) error { + _, err := c.PostInlineComment(context.Background(), ref, gitprovider.InlineComment{CommitSHA: sha, Body: "body", Path: "a.go", Side: review.DiffSideRight, Line: 1, SubjectType: review.AnchorKindLine}) + return err + }}, + {name: "issue comment", write: func(c *Client) error { + _, err := c.PostIssueComment(context.Background(), ref, "body") + return err + }}, + {name: "review", write: func(c *Client) error { + _, err := c.SubmitReview(context.Background(), ref, gitprovider.ReviewRequest{CommitSHA: sha, Event: review.ReviewEventComment, Body: "body"}) + return err + }}, + {name: "thread reply", write: func(c *Client) error { + _, err := c.ReplyToThread(context.Background(), ref, "thread-1", "body") + return err + }}, + {name: "resolve thread", write: func(c *Client) error { + return c.ResolveThread(context.Background(), ref, "thread-1") + }}, + {name: "accept invitation", write: func(c *Client) error { + return c.AcceptRepositoryInvitation(context.Background(), "7") + }}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + calls.Add(1) + w.WriteHeader(http.StatusBadGateway) + })) + defer server.Close() + recorder := &retryRecorder{} + + err := tt.write(retryClient(t, server.URL, recorder.policy())) + if !errors.Is(err, gitprovider.ErrRetryable) { + t.Fatalf("error = %v, want ErrRetryable", err) + } + if calls.Load() != 1 || len(recorder.delays) != 0 { + t.Fatalf("calls = %d delays = %v, want one send and no wait", calls.Load(), recorder.delays) + } + }) + } +} + +// Fails closed: a new write must be added here deliberately, never inherit retry. +func TestRetrySafeOperationClassifiesEveryOperation(t *testing.T) { + want := map[gitprovider.Operation]bool{ + gitprovider.OperationWhoAmI: true, + gitprovider.OperationReviewAuthority: true, + gitprovider.OperationGetPR: true, + gitprovider.OperationGetDiff: true, + gitprovider.OperationGetDiffBetweenRefs: true, + gitprovider.OperationGetFileAtRef: true, + gitprovider.OperationListTreeAtRef: true, + gitprovider.OperationListInlineThreads: true, + gitprovider.OperationListReviews: true, + gitprovider.OperationListIssueComments: true, + gitprovider.OperationListRepositoryInvitations: true, + gitprovider.OperationPostInlineComment: false, + gitprovider.OperationReplyToThread: false, + gitprovider.OperationResolveThread: false, + gitprovider.OperationPostIssueComment: false, + gitprovider.OperationSubmitReview: false, + gitprovider.OperationAcceptRepositoryInvitation: false, + gitprovider.Operation("SomethingNew"): false, + } + for op, safe := range want { + if got := retrySafeOperation(op); got != safe { + t.Errorf("retrySafeOperation(%s) = %t, want %t", op, got, safe) + } + } +} + +func TestRetryStopsWhenContextIsCanceledDuringWait(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + calls.Add(1) + w.WriteHeader(http.StatusBadGateway) + })) + defer server.Close() + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + client := retryClient(t, server.URL, RetryPolicy{Sleep: func(ctx context.Context, _ time.Duration) error { + cancel() + return ctx.Err() + }}) + + if _, err := client.GetPR(ctx, testPRRef()); !errors.Is(err, context.Canceled) { + t.Fatalf("error = %v, want context.Canceled", err) + } + if calls.Load() != 1 { + t.Fatalf("calls = %d, want 1", calls.Load()) + } +} + +func TestRetryNeverWaitsPastContextDeadline(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + calls.Add(1) + w.Header().Set("Retry-After", "60") + w.WriteHeader(http.StatusServiceUnavailable) + })) + defer server.Close() + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + recorder := &retryRecorder{} + + _, err := retryClient(t, server.URL, recorder.policy()).GetPR(ctx, testPRRef()) + if !errors.Is(err, gitprovider.ErrRetryable) { + t.Fatalf("error = %v, want ErrRetryable", err) + } + if calls.Load() != 1 || len(recorder.delays) != 0 { + t.Fatalf("calls = %d delays = %v, want one call and no wait", calls.Load(), recorder.delays) + } +} + +func TestCertificateFailureIsNotRetried(t *testing.T) { + var calls atomic.Int32 + recorder := &retryRecorder{} + client := mustClient(t, Options{ + Token: "token", BaseURL: "https://example.invalid/", GraphQLURL: "https://example.invalid/graphql", + Retry: recorder.policy(), + HTTPClient: &http.Client{Transport: roundTripFunc(func(*http.Request) (*http.Response, error) { + calls.Add(1) + return nil, &tls.CertificateVerificationError{Err: errors.New("unknown authority")} + })}, + }) + + if _, err := client.GetPR(context.Background(), testPRRef()); !errors.Is(err, gitprovider.ErrRetryable) { + t.Fatalf("error = %v, want ErrRetryable classification", err) + } + if calls.Load() != 1 { + t.Fatalf("calls = %d, want 1", calls.Load()) + } +} + +func TestAppTokenMintRetriesEvenForAWrite(t *testing.T) { + now := time.Date(2026, 11, 3, 12, 0, 0, 0, time.UTC) + _, privateKeyPEM := testPrivateKey(t) + var mints, reviews atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + switch r.URL.Path { + case "/app/installations/42": + writeJSON(t, w, map[string]any{"id": 42, "app_id": 12345, "app_slug": "cr-reviewer"}) + case "/app/installations/42/access_tokens": + // The first mint is the client's construction; the second is the + // refresh a write triggers after the token has expired. + if mints.Add(1) == 2 { + w.WriteHeader(http.StatusBadGateway) + return + } + writeJSON(t, w, map[string]any{"token": "installation-token", "expires_at": now.Add(time.Hour).Format(time.RFC3339)}) + default: + reviews.Add(1) + w.WriteHeader(http.StatusBadGateway) + } + })) + defer server.Close() + recorder := &retryRecorder{} + + client, _, err := NewFromGitConfig(githubAppGitConfig("codereview/app"), githubAppStore(t, "app", "12345", privateKeyPEM), Options{ + BaseURL: server.URL, GraphQLURL: server.URL + "/graphql", + Now: func() time.Time { return now }, + InstallationID: "42", + Retry: recorder.policy(), + }) + if err != nil { + t.Fatalf("NewFromGitConfig: %v", err) + } + now = now.Add(2 * time.Hour) + + _, err = client.PostIssueComment(context.Background(), gitprovider.PRRef{Host: "github.com", Owner: "o", Repo: "r", Number: 1}, "body") + if !errors.Is(err, gitprovider.ErrRetryable) { + t.Fatalf("error = %v, want the write's own 502", err) + } + if mints.Load() != 3 { + t.Fatalf("token mints = %d, want initial + failed + retried", mints.Load()) + } + if reviews.Load() != 1 { + t.Fatalf("comment sends = %d, want 1", reviews.Load()) + } +} + +func TestThreadCommentBotAuthorMatchesPostingIdentity(t *testing.T) { + payload, err := os.ReadFile("testdata/review_threads_bot_author.json") + if err != nil { + t.Fatalf("ReadFile: %v", err) + } + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _ = readGraphQLRequestAtEndpoint(t, r) + _, _ = w.Write(payload) + })) + defer server.Close() + + threads, err := retryClient(t, server.URL, RetryPolicy{}).ListInlineThreads(context.Background(), testPRRef()) + if err != nil { + t.Fatalf("ListInlineThreads: %v", err) + } + comments := threads[0].Comments + posting := gitprovider.Identity{Login: "cr-reviewer[bot]", DisplayName: "cr-reviewer"} + if !comments[0].Author.Same(posting) { + t.Fatalf("app author = %#v, want it to match the posting identity", comments[0].Author) + } + if comments[1].Author.Same(posting) { + t.Fatalf("person author = %#v, must not match the app identity", comments[1].Author) + } +} diff --git a/internal/gitprovider/github/testdata/review_threads_bot_author.json b/internal/gitprovider/github/testdata/review_threads_bot_author.json new file mode 100644 index 00000000..5d4fed85 --- /dev/null +++ b/internal/gitprovider/github/testdata/review_threads_bot_author.json @@ -0,0 +1,43 @@ +{ + "data": { + "repository": { + "pullRequest": { + "reviewThreads": { + "pageInfo": {"hasNextPage": false}, + "nodes": [ + { + "id": "thread-1", + "isResolved": false, + "path": "a.go", + "line": 1, + "diffSide": "RIGHT", + "comments": { + "pageInfo": {"hasNextPage": false}, + "nodes": [ + { + "id": "app", + "databaseId": 1, + "body": "from app", + "author": {"__typename": "Bot", "login": "cr-reviewer"}, + "commit": {"oid": "head"}, + "path": "a.go", + "line": 1 + }, + { + "id": "person", + "databaseId": 2, + "body": "from person", + "author": {"__typename": "User", "login": "cr-reviewer", "id": 9}, + "commit": {"oid": "head"}, + "path": "a.go", + "line": 1 + } + ] + } + } + ] + } + } + } + } +} diff --git a/internal/outbox/outbox.go b/internal/outbox/outbox.go index 04a4505c..39c74957 100644 --- a/internal/outbox/outbox.go +++ b/internal/outbox/outbox.go @@ -61,6 +61,9 @@ type Options struct { Provider Provider Limiter Limiter Now func() time.Time + // WriteRetry enables in-run recovery of retryable write failures in Post. + // Nil leaves a failed write pending after one attempt. + WriteRetry *WriteRetry } // Request identifies the run and PR being posted. @@ -80,6 +83,8 @@ type Result struct { Pending int FailedTerminal int Aborted bool + // PendingError is the failure recorded on the first action still pending. + PendingError string } // InlineCommentPayload is an alias for the canonical inline comment payload. @@ -141,6 +146,7 @@ func Post(ctx context.Context, opts Options, req Request) (Result, error) { return Result{ExitCode: exitUpstream}, err } + writeRetriesSpent := false for i := range actions { if actions[i].Status != ledger.PlannedActionPending { continue @@ -209,6 +215,17 @@ func Post(ctx context.Context, opts Options, req Request) (Result, error) { } upstreamID, err := dispatch(ctx, opts.Provider, req.PRRef, plan) + if err != nil && opts.WriteRetry != nil && !writeRetriesSpent { + recovery, recoverErr := recoverWrite(ctx, opts, req, actions, i, plan, err) + if recoverErr != nil { + if isContextError(recoverErr) { + return summarize(actions, ledger.OutcomeIncomplete, exitUpstream, false), recoverErr + } + return Result{ExitCode: exitFailed}, recoverErr + } + upstreamID, err = recovery.upstreamID, recovery.err + writeRetriesSpent = errors.Is(err, gitprovider.ErrRetryable) + } if err == nil { now := opts.Now().UTC() actions[i].Status = ledger.PlannedActionPosted @@ -969,6 +986,9 @@ func summarize(actions []ledger.PlannedAction, outcome ledger.Outcome, exitCode result.Posted++ case ledger.PlannedActionPending: result.Pending++ + if result.PendingError == "" && action.Error != nil { + result.PendingError = *action.Error + } case ledger.PlannedActionFailedTerminal: result.FailedTerminal++ case ledger.PlannedActionSuperseded, ledger.PlannedActionPlannedOnly: diff --git a/internal/outbox/write_retry.go b/internal/outbox/write_retry.go new file mode 100644 index 00000000..e83350ac --- /dev/null +++ b/internal/outbox/write_retry.go @@ -0,0 +1,185 @@ +package outbox + +import ( + "context" + "errors" + "math/rand/v2" + "time" + + "github.com/open-cli-collective/codereview-cli/internal/gitprovider" + "github.com/open-cli-collective/codereview-cli/internal/ledger" +) + +const ( + defaultWriteMaxAttempts = 3 + // defaultWriteSettle spaces a resend from the failure. GitHub stops + // processing an API request after 10 seconds, so a write that returned 5xx or + // timed out has finished one way or the other before the marker check runs. + defaultWriteSettle = 12 * time.Second + // defaultWriteMaxWait matches the GitHub client's longest honored wait. + defaultWriteMaxWait = 2 * time.Minute +) + +// WriteRetry bounds in-run recovery of a write that failed retryably. A write +// can land at the host and still report failure, so nothing is resent until a +// fresh read of the PR shows the write's action marker is absent. +type WriteRetry struct { + // MaxAttempts counts sends of one action, including the first. + MaxAttempts int + // Settle is the wait before the first marker check; later checks wait + // proportionally longer. + Settle time.Duration + // MaxWait is the longest host-requested wait worth sitting through. + MaxWait time.Duration + // Sleep waits for d or until ctx ends. Tests inject it to avoid real waits. + Sleep func(ctx context.Context, d time.Duration) error + // Jitter maps a delay to the delay actually used. + Jitter func(time.Duration) time.Duration + // OnEvent observes each recovery step. + OnEvent func(WriteRetryEvent) +} + +// WriteRetryPhase names one step of write recovery. +type WriteRetryPhase string + +const ( + // WriteRetryWaiting means a write failed and the marker check is scheduled. + WriteRetryWaiting WriteRetryPhase = "waiting" + // WriteRetryReconciled means the failed write had landed; nothing is resent. + WriteRetryReconciled WriteRetryPhase = "reconciled" + // WriteRetryResending means the marker is absent and the write is resent. + WriteRetryResending WriteRetryPhase = "resending" + // WriteRetryAbandoned means recovery stopped with the action left pending. + WriteRetryAbandoned WriteRetryPhase = "abandoned" +) + +// WriteRetryEvent describes one recovery step for one action. +type WriteRetryEvent struct { + Phase WriteRetryPhase + ActionID string + Kind ledger.PlannedActionKind + Attempt int // sends so far + MaxAttempts int + Delay time.Duration + Reason string +} + +// DefaultWriteRetry is the production recovery policy. +func DefaultWriteRetry(onEvent func(WriteRetryEvent)) *WriteRetry { + return &WriteRetry{OnEvent: onEvent} +} + +func (w WriteRetry) normalized() WriteRetry { + if w.MaxAttempts <= 0 { + w.MaxAttempts = defaultWriteMaxAttempts + } + if w.Settle <= 0 { + w.Settle = defaultWriteSettle + } + if w.MaxWait <= 0 { + w.MaxWait = defaultWriteMaxWait + } + if w.Sleep == nil { + w.Sleep = sleepContext + } + if w.Jitter == nil { + w.Jitter = addJitter + } + return w +} + +func sleepContext(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 + } +} + +// addJitter only lengthens the delay, so the settle time stays a lower bound. +func addJitter(d time.Duration) time.Duration { + spread := d / 4 + if spread <= 0 { + return d + } + return d + rand.N(spread) // #nosec G404 -- backoff spacing, not a secret. +} + +type writeRecovery struct { + upstreamID string + err error +} + +// recoverWrite handles a failed dispatch of actions[i]. It returns the write's +// final result; a nil recovery.err means the action can be recorded as posted +// with recovery.upstreamID. The returned error is for failures of recovery +// itself: the ledger, or ctx ending during a wait. +func recoverWrite(ctx context.Context, opts Options, req Request, actions []ledger.PlannedAction, i int, plan actionPlan, sendErr error) (writeRecovery, error) { + policy := opts.WriteRetry.normalized() + action := &actions[i] + emit := func(phase WriteRetryPhase, attempt int, delay time.Duration, reason string) { + if policy.OnEvent != nil { + policy.OnEvent(WriteRetryEvent{Phase: phase, ActionID: action.ActionID, Kind: action.Kind, Attempt: attempt, MaxAttempts: policy.MaxAttempts, Delay: delay, Reason: reason}) + } + } + err := sendErr + for attempt := 1; attempt < policy.MaxAttempts && errors.Is(err, gitprovider.ErrRetryable); attempt++ { + if ctx.Err() != nil { + break + } + delay := policy.Jitter(policy.Settle * time.Duration(attempt)) + if hint, ok := gitprovider.RetryAfterHint(err); ok { + if hint > policy.MaxWait { + emit(WriteRetryAbandoned, attempt, 0, "host asked to wait "+hint.Round(time.Second).String()) + return writeRecovery{err: err}, nil + } + delay = max(delay, hint) + } + if updateErr := recordPendingError(ctx, opts.Store, action, err); updateErr != nil { + return writeRecovery{}, updateErr + } + emit(WriteRetryWaiting, attempt, delay, err.Error()) + if sleepErr := policy.Sleep(ctx, delay); sleepErr != nil { + return writeRecovery{}, sleepErr + } + + state, readErr := readHostState(ctx, opts.Provider, req.PRRef) + if readErr != nil { + emit(WriteRetryAbandoned, attempt, 0, "could not check whether the write landed: "+readErr.Error()) + return writeRecovery{err: err}, nil + } + match, matchErr := reconcileAction(req, opts.Provider.Capabilities(), actions, *action, state) + if matchErr != nil { + emit(WriteRetryAbandoned, attempt, 0, "could not check whether the write landed: "+matchErr.Error()) + return writeRecovery{err: err}, nil + } + if match.ok { + emit(WriteRetryReconciled, attempt, 0, "") + return writeRecovery{upstreamID: match.upstreamID}, nil + } + + if waitErr := opts.Limiter.Wait(ctx, req.PRRef.Host); waitErr != nil { + if isContextError(waitErr) { + return writeRecovery{}, waitErr + } + emit(WriteRetryAbandoned, attempt, 0, waitErr.Error()) + return writeRecovery{err: err}, nil + } + now := opts.Now().UTC() + action.Attempts++ + action.AttemptedAt = &now + if updateErr := opts.Store.UpdatePlannedAction(ctx, *action); updateErr != nil { + return writeRecovery{}, updateErr + } + emit(WriteRetryResending, attempt+1, 0, "") + var upstreamID string + upstreamID, err = dispatch(ctx, opts.Provider, req.PRRef, plan) + if err == nil { + return writeRecovery{upstreamID: upstreamID}, nil + } + } + return writeRecovery{err: err}, nil +} diff --git a/internal/outbox/write_retry_test.go b/internal/outbox/write_retry_test.go new file mode 100644 index 00000000..5db5671b --- /dev/null +++ b/internal/outbox/write_retry_test.go @@ -0,0 +1,487 @@ +package outbox + +import ( + "context" + "errors" + "fmt" + "slices" + "strings" + "testing" + "time" + + "github.com/open-cli-collective/codereview-cli/internal/gitprovider" + "github.com/open-cli-collective/codereview-cli/internal/ledger" + "github.com/open-cli-collective/codereview-cli/internal/review" +) + +// sendScript says what one write attempt does at the host. +type sendScript struct { + land bool // the host keeps the write + err error // what the client reports +} + +// simHost is a host whose writes become visible to later reads, so reconciliation +// can be exercised against a write that landed but reported failure. +type simHost struct { + identity gitprovider.Identity + caps gitprovider.ProviderCaps + script map[string][]sendScript // by write kind + sends map[string]int + comments []gitprovider.IssueComment + reviews []gitprovider.Review + thread gitprovider.InlineThread + reads int + readErrs []error // consumed by each host-state read after the first +} + +func newSimHost(script map[string][]sendScript) *simHost { + return &simHost{ + identity: botIdentity(), + script: script, + sends: map[string]int{}, + thread: gitprovider.InlineThread{ID: "thread-1", Path: "main.go", Side: review.DiffSideRight, Line: 12, SubjectType: review.AnchorKindLine}, + } +} + +func (h *simHost) send(kind string) sendScript { + h.sends[kind]++ + steps := h.script[kind] + if h.sends[kind] <= len(steps) { + return steps[h.sends[kind]-1] + } + return sendScript{land: true} +} + +func (h *simHost) nextID(kind string) string { return fmt.Sprintf("%s-%d", kind, h.sends[kind]) } + +func (h *simHost) ListInlineThreads(context.Context, gitprovider.PRRef) ([]gitprovider.InlineThread, error) { + h.reads++ + if h.reads > 1 && len(h.readErrs) > 0 { + err := h.readErrs[0] + h.readErrs = h.readErrs[1:] + if err != nil { + return nil, err + } + } + return []gitprovider.InlineThread{h.thread}, nil +} + +func (h *simHost) ListReviews(context.Context, gitprovider.PRRef) ([]gitprovider.Review, error) { + return slices.Clone(h.reviews), nil +} + +func (h *simHost) ListIssueComments(context.Context, gitprovider.PRRef) ([]gitprovider.IssueComment, error) { + return slices.Clone(h.comments), nil +} + +func (h *simHost) PostInlineComment(context.Context, gitprovider.PRRef, gitprovider.InlineComment) (gitprovider.CommentID, error) { + return "", errors.New("simHost: inline comments are bundled") +} + +func (h *simHost) ReplyToThread(_ context.Context, _ gitprovider.PRRef, _ gitprovider.ThreadID, body string) (gitprovider.CommentID, error) { + step := h.send("reply") + id := gitprovider.CommentID(h.nextID("reply")) + if step.land { + h.thread.Comments = append(h.thread.Comments, gitprovider.ThreadComment{ID: id, ThreadID: h.thread.ID, Author: h.identity, Body: body}) + } + if step.err != nil { + return "", step.err + } + return id, nil +} + +func (h *simHost) ResolveThread(context.Context, gitprovider.PRRef, gitprovider.ThreadID) error { + step := h.send("resolve") + if step.land { + h.thread.Resolved = true + } + return step.err +} + +func (h *simHost) PostIssueComment(_ context.Context, _ gitprovider.PRRef, body string) (gitprovider.CommentID, error) { + step := h.send("rollup") + id := gitprovider.CommentID(h.nextID("rollup")) + if step.land { + h.comments = append(h.comments, gitprovider.IssueComment{ID: id, Author: h.identity, Body: body}) + } + if step.err != nil { + return "", step.err + } + return id, nil +} + +func (h *simHost) SubmitReview(_ context.Context, _ gitprovider.PRRef, request gitprovider.ReviewRequest) (gitprovider.ReviewID, error) { + step := h.send("review") + id := gitprovider.ReviewID(h.nextID("review")) + if step.land { + h.reviews = append(h.reviews, gitprovider.Review{ID: id, Author: h.identity, Body: request.Body}) + for _, comment := range request.Comments { + h.thread.Comments = append(h.thread.Comments, gitprovider.ThreadComment{ID: gitprovider.CommentID(id), ThreadID: h.thread.ID, Author: h.identity, Body: comment.Body}) + } + } + if step.err != nil { + return "", step.err + } + return id, nil +} + +func (h *simHost) Capabilities() gitprovider.ProviderCaps { return h.caps } + +func retryableWriteError(op gitprovider.Operation) error { + return gitprovider.WrapError(gitprovider.ErrRetryable, op, errors.New("github: status 502")) +} + +type writeRetryRecorder struct { + delays []time.Duration + events []WriteRetryEvent +} + +func (r *writeRetryRecorder) policy() *WriteRetry { + return &WriteRetry{ + Jitter: func(d time.Duration) time.Duration { return d }, + Sleep: func(_ context.Context, d time.Duration) error { + r.delays = append(r.delays, d) + return nil + }, + OnEvent: func(event WriteRetryEvent) { r.events = append(r.events, event) }, + } +} + +func (r *writeRetryRecorder) phases() []WriteRetryPhase { + phases := make([]WriteRetryPhase, 0, len(r.events)) + for _, event := range r.events { + phases = append(phases, event.Phase) + } + return phases +} + +func writeRetryKinds() []struct { + name string + send string + action func(runID string) ledger.PlannedAction + count func(*simHost) int +} { + return []struct { + name string + send string + action func(runID string) ledger.PlannedAction + count func(*simHost) int + }{ + { + name: "rollup comment", + send: "rollup", + action: func(runID string) ledger.PlannedAction { + return plannedAction(runID, "action-1", ledger.PlannedActionRollupComment, true, "", RollupCommentPayload{Body: "rollup"}) + }, + count: func(h *simHost) int { return len(h.comments) }, + }, + { + name: "submit review", + send: "review", + action: func(runID string) ledger.PlannedAction { + return plannedAction(runID, "action-1", ledger.PlannedActionSubmitReview, true, "", SubmitReviewPayload{Body: "review", Event: review.ReviewEventComment}) + }, + count: func(h *simHost) int { return len(h.reviews) }, + }, + { + name: "thread reply", + send: "reply", + action: func(runID string) ledger.PlannedAction { + return plannedAction(runID, "action-1", ledger.PlannedActionThreadReply, true, "thread-1", ThreadReplyPayload{Body: "reply"}) + }, + count: func(h *simHost) int { return len(h.thread.Comments) }, + }, + } +} + +func TestWriteThatLandedAndReturned5xxIsNeverSentTwice(t *testing.T) { + for _, tt := range writeRetryKinds() { + t.Run(tt.name, func(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{tt.send: {{land: true, err: retryableWriteError(gitprovider.OperationSubmitReview)}}}) + insertAction(t, store, tt.action(run.RunID)) + recorder := &writeRetryRecorder{} + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: recorder.policy()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends[tt.send] != 1 || tt.count(host) != 1 { + t.Fatalf("sends = %d, on host = %d, want one of each", host.sends[tt.send], tt.count(host)) + } + if result.ExitCode != exitOK || result.Posted != 1 || result.Pending != 0 { + t.Fatalf("result = %#v, want posted", result) + } + action := actionByID(t, store, run.RunID, "action-1") + if action.Status != ledger.PlannedActionPosted || action.Attempts != 1 || action.Error != nil || action.UpstreamID == nil || *action.UpstreamID == "" { + t.Fatalf("action = %#v, want posted from the marker match", action) + } + if !slices.Equal(recorder.phases(), []WriteRetryPhase{WriteRetryWaiting, WriteRetryReconciled}) { + t.Fatalf("phases = %v", recorder.phases()) + } + }) + } +} + +func TestWriteThatDidNotLandIsResentOnceMarkerIsAbsent(t *testing.T) { + for _, tt := range writeRetryKinds() { + t.Run(tt.name, func(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{tt.send: {{land: false, err: retryableWriteError(gitprovider.OperationSubmitReview)}}}) + insertAction(t, store, tt.action(run.RunID)) + recorder := &writeRetryRecorder{} + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: recorder.policy()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends[tt.send] != 2 || tt.count(host) != 1 { + t.Fatalf("sends = %d, on host = %d, want two sends and one on the host", host.sends[tt.send], tt.count(host)) + } + if result.ExitCode != exitOK || result.Posted != 1 { + t.Fatalf("result = %#v, want posted", result) + } + action := actionByID(t, store, run.RunID, "action-1") + if action.Status != ledger.PlannedActionPosted || action.Attempts != 2 || action.Error != nil { + t.Fatalf("action = %#v, want posted after two attempts", action) + } + if !slices.Equal(recorder.phases(), []WriteRetryPhase{WriteRetryWaiting, WriteRetryResending}) { + t.Fatalf("phases = %v", recorder.phases()) + } + if host.reads != 2 { + t.Fatalf("host-state reads = %d, want the opening read and one before the resend", host.reads) + } + }) + } +} + +func TestResentWriteThatLandsOnSecondFailureIsNotSentAThirdTime(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + failure := retryableWriteError(gitprovider.OperationSubmitReview) + host := newSimHost(map[string][]sendScript{"review": {{land: false, err: failure}, {land: true, err: failure}}}) + insertAction(t, store, plannedAction(run.RunID, "action-1", ledger.PlannedActionSubmitReview, true, "", SubmitReviewPayload{Body: "review", Event: review.ReviewEventComment})) + recorder := &writeRetryRecorder{} + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: recorder.policy()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends["review"] != 2 || len(host.reviews) != 1 || result.ExitCode != exitOK { + t.Fatalf("sends = %d reviews = %d result = %#v, want two sends, one review, success", host.sends["review"], len(host.reviews), result) + } + if want := []time.Duration{defaultWriteSettle, 2 * defaultWriteSettle}; !slices.Equal(recorder.delays, want) { + t.Fatalf("delays = %v, want %v", recorder.delays, want) + } +} + +func TestFailedMarkerCheckNeverResends(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{"review": {{land: false, err: retryableWriteError(gitprovider.OperationSubmitReview)}}}) + host.readErrs = []error{retryableWriteError(gitprovider.OperationListInlineThreads)} + insertAction(t, store, plannedAction(run.RunID, "action-1", ledger.PlannedActionSubmitReview, true, "", SubmitReviewPayload{Body: "review", Event: review.ReviewEventComment})) + recorder := &writeRetryRecorder{} + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: recorder.policy()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends["review"] != 1 { + t.Fatalf("sends = %d, want 1: a write must not be resent unverified", host.sends["review"]) + } + if result.ExitCode != exitUpstream || result.Pending != 1 || result.Outcome != ledger.OutcomeIncomplete || !strings.Contains(result.PendingError, "status 502") { + t.Fatalf("result = %#v, want incomplete with the cause", result) + } + if got := recorder.phases(); !slices.Equal(got, []WriteRetryPhase{WriteRetryWaiting, WriteRetryAbandoned}) { + t.Fatalf("phases = %v", got) + } +} + +func TestExhaustedRetriesStayPendingAndTheNextRunReconciles(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + failure := retryableWriteError(gitprovider.OperationPostIssueComment) + // The last send lands although it reports failure, so only the later run can learn of it. + host := newSimHost(map[string][]sendScript{"rollup": {{err: failure}, {err: failure}, {land: true, err: failure}}}) + insertAction(t, store, plannedAction(run.RunID, "action-1", ledger.PlannedActionRollupComment, true, "", RollupCommentPayload{Body: "rollup"})) + recorder := &writeRetryRecorder{} + opts := Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: recorder.policy()} + + result, err := Post(context.Background(), opts, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends["rollup"] != defaultWriteMaxAttempts || result.ExitCode != exitUpstream || result.Outcome != ledger.OutcomeIncomplete || result.Pending != 1 { + t.Fatalf("sends = %d result = %#v, want %d sends and incomplete", host.sends["rollup"], result, defaultWriteMaxAttempts) + } + action := actionByID(t, store, run.RunID, "action-1") + if action.Status != ledger.PlannedActionPending || action.Attempts != defaultWriteMaxAttempts || action.Error == nil { + t.Fatalf("action = %#v, want pending with the error", action) + } + + result, err = Post(context.Background(), opts, testRequest(run)) + if err != nil { + t.Fatalf("second Post: %v", err) + } + if host.sends["rollup"] != defaultWriteMaxAttempts || len(host.comments) != 1 || result.ExitCode != exitOK { + t.Fatalf("sends = %d comments = %d result = %#v, want no new send and success", host.sends["rollup"], len(host.comments), result) + } +} + +func TestBundledInlineCommentsFollowAReconciledReview(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{"review": {{land: true, err: retryableWriteError(gitprovider.OperationSubmitReview)}}}) + host.caps = gitprovider.ProviderCaps{BundleInlineOnSubmit: true} + insertAction(t, store, plannedAction(run.RunID, "inline-1", ledger.PlannedActionInlineComment, true, "", InlineCommentPayload{Body: "inline", Path: "main.go", Side: review.DiffSideRight, Line: 12, SubjectType: review.AnchorKindLine})) + insertAction(t, store, plannedAction(run.RunID, "submit-1", ledger.PlannedActionSubmitReview, true, "", SubmitReviewPayload{Body: "review", Event: review.ReviewEventComment})) + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: (&writeRetryRecorder{}).policy()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends["review"] != 1 || result.ExitCode != exitOK || result.Posted != 2 { + t.Fatalf("sends = %d result = %#v, want one send and both actions posted", host.sends["review"], result) + } + inline := actionByID(t, store, run.RunID, "inline-1") + if inline.Status != ledger.PlannedActionPosted || inline.UpstreamID == nil || *inline.UpstreamID != "review-1" { + t.Fatalf("inline = %#v, want posted with the review", inline) + } +} + +func TestResolveThreadRetriesAreSafeWithoutReply(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{"resolve": {{land: true, err: retryableWriteError(gitprovider.OperationResolveThread)}}}) + insertAction(t, store, plannedAction(run.RunID, "resolve-1", ledger.PlannedActionResolveThread, true, "thread-1", ResolveThreadPayload{})) + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: (&writeRetryRecorder{}).policy()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if result.ExitCode != exitOK || !host.thread.Resolved { + t.Fatalf("result = %#v resolved = %t, want resolved", result, host.thread.Resolved) + } +} + +func TestRetryAfterExtendsTheSettleWaitAndLongWaitsAreAbandoned(t *testing.T) { + hinted := func(after time.Duration) error { + return &gitprovider.RetryAfterError{After: after, Err: retryableWriteError(gitprovider.OperationPostIssueComment)} + } + t.Run("honored", func(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{"rollup": {{err: hinted(90 * time.Second)}}}) + insertAction(t, store, plannedAction(run.RunID, "action-1", ledger.PlannedActionRollupComment, true, "", RollupCommentPayload{Body: "rollup"})) + recorder := &writeRetryRecorder{} + + if _, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: recorder.policy()}, testRequest(run)); err != nil { + t.Fatalf("Post: %v", err) + } + if !slices.Equal(recorder.delays, []time.Duration{90 * time.Second}) { + t.Fatalf("delays = %v, want the requested 90s", recorder.delays) + } + }) + t.Run("too long", func(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{"rollup": {{err: hinted(30 * time.Minute)}}}) + insertAction(t, store, plannedAction(run.RunID, "action-1", ledger.PlannedActionRollupComment, true, "", RollupCommentPayload{Body: "rollup"})) + recorder := &writeRetryRecorder{} + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: recorder.policy()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends["rollup"] != 1 || len(recorder.delays) != 0 || result.ExitCode != exitUpstream { + t.Fatalf("sends = %d delays = %v result = %#v, want one send, no wait, incomplete", host.sends["rollup"], recorder.delays, result) + } + }) +} + +func TestNonRetryableFailureAfterResendGoesThroughNormalHandling(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{"rollup": { + {err: retryableWriteError(gitprovider.OperationPostIssueComment)}, + {err: gitprovider.WrapError(gitprovider.ErrPermission, gitprovider.OperationPostIssueComment, errors.New("github: status 403"))}, + }}) + insertAction(t, store, plannedAction(run.RunID, "action-1", ledger.PlannedActionRollupComment, true, "", RollupCommentPayload{Body: "rollup"})) + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: (&writeRetryRecorder{}).policy()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends["rollup"] != 2 || result.ExitCode != exitAuth || result.FailedTerminal != 1 { + t.Fatalf("sends = %d result = %#v, want terminal auth failure", host.sends["rollup"], result) + } +} + +func TestSpentRetriesLeaveLaterActionsWithOneAttempt(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + failure := retryableWriteError(gitprovider.OperationReplyToThread) + host := newSimHost(map[string][]sendScript{ + "reply": {{err: failure}, {err: failure}, {err: failure}}, + "rollup": {{err: failure}}, + }) + insertAction(t, store, plannedAction(run.RunID, "reply-1", ledger.PlannedActionThreadReply, true, "thread-1", ThreadReplyPayload{Body: "reply"})) + insertAction(t, store, plannedAction(run.RunID, "rollup-1", ledger.PlannedActionRollupComment, true, "", RollupCommentPayload{Body: "rollup"})) + recorder := &writeRetryRecorder{} + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: recorder.policy()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends["reply"] != defaultWriteMaxAttempts || host.sends["rollup"] != 1 { + t.Fatalf("sends = %v, want the outage to stop retrying after one action", host.sends) + } + if result.ExitCode != exitUpstream || result.Pending != 2 { + t.Fatalf("result = %#v, want both pending", result) + } +} + +func TestCancelDuringWriteRetryWaitLeavesActionPending(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{"rollup": {{err: retryableWriteError(gitprovider.OperationPostIssueComment)}}}) + insertAction(t, store, plannedAction(run.RunID, "action-1", ledger.PlannedActionRollupComment, true, "", RollupCommentPayload{Body: "rollup"})) + policy := &WriteRetry{Sleep: func(context.Context, time.Duration) error { return context.Canceled }} + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: policy}, testRequest(run)) + if !errors.Is(err, context.Canceled) { + t.Fatalf("error = %v, want context.Canceled", err) + } + if result.ExitCode != exitUpstream || host.sends["rollup"] != 1 { + t.Fatalf("result = %#v sends = %d, want upstream exit and no resend", result, host.sends["rollup"]) + } + if action := actionByID(t, store, run.RunID, "action-1"); action.Status != ledger.PlannedActionPending { + t.Fatalf("action = %#v, want pending", action) + } +} + +func TestPostWithoutWriteRetrySendsOnce(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{"rollup": {{err: retryableWriteError(gitprovider.OperationPostIssueComment)}}}) + insertAction(t, store, plannedAction(run.RunID, "action-1", ledger.PlannedActionRollupComment, true, "", RollupCommentPayload{Body: "rollup"})) + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends["rollup"] != 1 || result.ExitCode != exitUpstream { + t.Fatalf("sends = %d result = %#v", host.sends["rollup"], result) + } +} + +func TestDefaultWriteJitterNeverShortensTheSettleWait(t *testing.T) { + for range 200 { + if got := addJitter(defaultWriteSettle); got < defaultWriteSettle || got >= defaultWriteSettle+defaultWriteSettle/4 { + t.Fatalf("addJitter = %s", got) + } + } +} diff --git a/internal/progress/progress.go b/internal/progress/progress.go index f6d1fa0d..c15da1e5 100644 --- a/internal/progress/progress.go +++ b/internal/progress/progress.go @@ -83,6 +83,22 @@ func (l *Logger) InfoFields(command, op, target string, fields ...Field) { }) } +// InfoReason writes an instantaneous record that explains itself with a failure +// message, redacted the same way an error line's summary is. +func (l *Logger) InfoReason(command, op, target, reason string, fields ...Field) { + line := progressLine{ + event: "info", + command: command, + op: op, + target: target, + fields: cloneFields(fields), + } + if reason != "" { + line.errSummary = sanitizeErrorSummary(reason) + } + l.writeLine(line) +} + // End writes a finish or error line and returns err. It is a no-op for disabled // loggers or a span that has already ended. func (s *Span) End(err error) error { diff --git a/internal/progress/progress_test.go b/internal/progress/progress_test.go index 5577c2af..bfbb3f6c 100644 --- a/internal/progress/progress_test.go +++ b/internal/progress/progress_test.go @@ -144,3 +144,24 @@ func (c *fixedClock) Now() time.Time { c.times = c.times[1:] return t } + +func TestLoggerInfoReasonRedactsPathsAndHonorsDisabled(t *testing.T) { + var out bytes.Buffer + logger := New(&out, false, nil) + logger.InfoReason("review", "retry_read", "GetPR", `Get "https://github.example/repos/secret": connection reset`, Field{Key: "attempt", Value: "1"}) + line := out.String() + for _, want := range []string{"event=info", `op="retry_read"`, `target="GetPR"`, `attempt="1"`, `error="Get [path] connection reset"`} { + if !strings.Contains(line, want) { + t.Fatalf("line = %q, want %q", line, want) + } + } + if strings.Contains(line, "secret") { + t.Fatalf("line = %q leaked the path", line) + } + + out.Reset() + New(&out, true, nil).InfoReason("review", "retry_read", "GetPR", "boom") + if out.Len() != 0 { + t.Fatalf("disabled logger wrote %q", out.String()) + } +} diff --git a/internal/reviewrun/reviewrun.go b/internal/reviewrun/reviewrun.go index 9026e97a..062ac138 100644 --- a/internal/reviewrun/reviewrun.go +++ b/internal/reviewrun/reviewrun.go @@ -57,6 +57,7 @@ type Options struct { Provider outbox.LiveProvider Planner Planner Limiter outbox.Limiter + WriteRetry *outbox.WriteRetry Layout statepaths.Layout Acquire gateio.AcquireFunc Now func() time.Time @@ -223,6 +224,7 @@ func evaluateGate(ctx context.Context, opts Options, req Request, pr gitprovider Store: opts.Store, Provider: opts.Provider, Limiter: opts.Limiter, + WriteRetry: opts.WriteRetry, Layout: opts.Layout, Acquire: opts.Acquire, Now: opts.Now, @@ -299,10 +301,11 @@ func continueRun(ctx context.Context, opts Options, req Request, result Result) } postResult, err := outbox.Post(ctx, outbox.Options{ - Store: opts.Store, - Provider: opts.Provider, - Limiter: opts.Limiter, - Now: opts.Now, + Store: opts.Store, + Provider: opts.Provider, + Limiter: opts.Limiter, + Now: opts.Now, + WriteRetry: opts.WriteRetry, }, outbox.Request{ Run: result.Run, PRRef: req.Pipeline.PRRef, diff --git a/internal/threadrespond/threadrespond.go b/internal/threadrespond/threadrespond.go index 135b7428..2cdf13c3 100644 --- a/internal/threadrespond/threadrespond.go +++ b/internal/threadrespond/threadrespond.go @@ -66,8 +66,10 @@ type Options struct { Provider outbox.LiveProvider Adapter llm.Adapter Limiter outbox.Limiter - Layout statepaths.Layout - Acquire AcquireFunc + // WriteRetry enables in-run recovery of retryable posting failures. + WriteRetry *outbox.WriteRetry + Layout statepaths.Layout + Acquire AcquireFunc // AcquireShared takes the shared data-root active-runs lock held for the // run's duration. Defaults to runlock.AcquireShared. AcquireShared AcquireFunc @@ -335,10 +337,11 @@ func completeAndRefresh(ctx context.Context, store Store, result Result, message func postAndRefresh(ctx context.Context, opts Options, req Request, result Result, desiredOutcome ledger.Outcome) (Result, error) { run := result.Run postResult, err := outbox.Post(ctx, outbox.Options{ - Store: opts.Store, - Provider: opts.Provider, - Limiter: opts.Limiter, - Now: opts.now, + Store: opts.Store, + Provider: opts.Provider, + Limiter: opts.Limiter, + Now: opts.now, + WriteRetry: opts.WriteRetry, }, outbox.Request{ Run: run, PRRef: req.PRRef, diff --git a/internal/view/review.go b/internal/view/review.go index 7a862cbb..f93369c8 100644 --- a/internal/view/review.go +++ b/internal/view/review.go @@ -456,7 +456,7 @@ func RenderReviewDryRunJSON(w io.Writer, result ReviewDryRun) error { // RenderReviewLiveText writes a human-readable live review summary. func RenderReviewLiveText(w io.Writer, result ReviewLive) error { - if err := writeKV(w, "Run", result.Run.RunID); err != nil { + if err := writeOptionalKV(w, "Run", result.Run.RunID); err != nil { return err } if err := writeKV(w, "Status", result.Status); err != nil { diff --git a/internal/workbench/workbench.go b/internal/workbench/workbench.go index 47a17b12..39c47df3 100644 --- a/internal/workbench/workbench.go +++ b/internal/workbench/workbench.go @@ -310,15 +310,26 @@ func ensureCommit(ctx context.Context, deps Deps, repoDir string, branch gitprov if commitPresent(ctx, deps, repoDir, branch.SHA) { return nil } - if _, err := deps.gitCommand(ctx, repoDir, "fetch", "--no-tags", remoteURL, branch.SHA); err == nil && commitPresent(ctx, deps, repoDir, branch.SHA) { + _, fetchErr := deps.gitCommand(ctx, repoDir, "fetch", "--no-tags", remoteURL, branch.SHA) + if fetchErr == nil && commitPresent(ctx, deps, repoDir, branch.SHA) { return nil } - if ref != "" { - if _, err := deps.gitCommand(ctx, repoDir, "fetch", "--no-tags", remoteURL, ref); err == nil && commitPresent(ctx, deps, repoDir, branch.SHA) { + if ref != "" && !errors.Is(fetchErr, gitprovider.ErrRetryable) { + _, fetchErr = deps.gitCommand(ctx, repoDir, "fetch", "--no-tags", remoteURL, ref) + if fetchErr == nil && commitPresent(ctx, deps, repoDir, branch.SHA) { return nil } } - return fmt.Errorf("pipeline: fetch commit %s for %s/%s from %q", prref.ShortSHA(branch.SHA), branch.Owner, branch.Repo, remoteURL) + return fetchFailure(fmt.Sprintf("pipeline: fetch commit %s for %s/%s from %q", prref.ShortSHA(branch.SHA), branch.Owner, branch.Repo, remoteURL), fetchErr) +} + +// fetchFailure keeps a transient cause in the chain, so the run exits as an +// upstream failure and says what the host returned. +func fetchFailure(message string, err error) error { + if errors.Is(err, gitprovider.ErrRetryable) { + return fmt.Errorf("%s: %w", message, err) + } + return errors.New(message) } func ensurePullRequestHead(ctx context.Context, deps Deps, repoDir string, number int, headRefNamespace string, head gitprovider.PRBranchRef, remoteURL string) error { @@ -326,10 +337,11 @@ func ensurePullRequestHead(ctx context.Context, deps Deps, repoDir string, numbe if err != nil { return err } - if _, err := deps.gitCommand(ctx, repoDir, "fetch", "--no-tags", remoteURL, ref); err == nil && commitPresent(ctx, deps, repoDir, head.SHA) { + _, fetchErr := deps.gitCommand(ctx, repoDir, "fetch", "--no-tags", remoteURL, ref) + if fetchErr == nil && commitPresent(ctx, deps, repoDir, head.SHA) { return nil } - return fmt.Errorf("pipeline: fetch PR head commit %s from %q ref %q", prref.ShortSHA(head.SHA), remoteURL, ref) + return fetchFailure(fmt.Sprintf("pipeline: fetch PR head commit %s from %q ref %q", prref.ShortSHA(head.SHA), remoteURL, ref), fetchErr) } func pullHeadRef(namespace string, number int) (string, error) { diff --git a/internal/workbench/workbench_test.go b/internal/workbench/workbench_test.go index 5478286f..ec41ec51 100644 --- a/internal/workbench/workbench_test.go +++ b/internal/workbench/workbench_test.go @@ -170,6 +170,29 @@ func TestPrepareRejectsUnsafeFetchRef(t *testing.T) { } } +func TestPrepareKeepsTransientFetchFailureInTheChain(t *testing.T) { + fixture := newForkWorkbenchFixture(t) + var fetches int + gitRunner := func(ctx context.Context, dir string, args ...string) ([]byte, error) { + if len(args) > 0 && args[0] == "fetch" { + fetches++ + return nil, gitprovider.WrapError(gitprovider.ErrRetryable, "", errors.New("git fetch: The requested URL returned error: 502 (gave up after 4 attempts)")) + } + cmd := exec.CommandContext(ctx, "git", args...) // #nosec G204 -- tests invoke git with fixed command names and structured arguments. + cmd.Env = gittest.Env() + cmd.Dir = dir + return cmd.CombinedOutput() + } + + err := Prepare(context.Background(), Deps{GitCommand: gitRunner}, Request{PRRef: fixture.pr.Ref, ReviewPR: fixture.pr, ChangedFiles: []string{"main.go"}, Artifacts: runartifact.FromDir(t.TempDir())}) + if !errors.Is(err, gitprovider.ErrRetryable) || !strings.Contains(err.Error(), "returned error: 502") { + t.Fatalf("Prepare error = %v, want the transient cause", err) + } + if fetches != 1 { + t.Fatalf("fetches = %d, want the fallback ref skipped once the host is failing", fetches) + } +} + func TestPrepareRefreshesExistingArtifactRoot(t *testing.T) { ctx := context.Background() fixture := newWorkbenchGitFixture(t) From c4245c9f7663aa5851867a1d4865a6bdb2b83855 Mon Sep 17 00:00:00 2001 From: piekstra Date: Tue, 3 Nov 2026 09:11:27 -0500 Subject: [PATCH 2/2] fix(review): take the write settle wait from the provider and harden retries Declare the settle wait through ProviderCaps.WriteSettle. GitHub documents a 10-second processing limit, so it declares 12 seconds. GitLab documents none, so a failed GitLab write gets one send and stays pending for the next run. Sign a fresh GitHub App JWT for each attempt, because retries can outlast one JWT's lifetime. Strip the fetch arguments from git's output before matching it, so a ref name cannot decide that a failure is transient. Add tests for rate-limited writes through the real client and for every outbox.Post path naming WriteRetry. Twapp-Session: 59d912f3-982f-402e-8bd8-3e31269a28b0 --- docs/architecture.md | 4 +- docs/review-lifecycle.md | 2 + .../architecture/outbox_write_retry_test.go | 101 ++++++++++++++ internal/cmd/noleak/noleak_test.go | 1 + internal/gitexec/client.go | 14 +- internal/gitexec/client_test.go | 2 +- internal/gitprovider/github/app_auth.go | 25 ++-- internal/gitprovider/github/client.go | 4 + internal/gitprovider/github/client_test.go | 3 + internal/gitprovider/github/retry_test.go | 125 ++++++++++++++++++ internal/gitprovider/gitlab/client_test.go | 3 + internal/gitprovider/types.go | 5 + internal/outbox/outbox.go | 7 +- internal/outbox/write_retry.go | 18 +-- internal/outbox/write_retry_test.go | 26 +++- 15 files changed, 304 insertions(+), 36 deletions(-) create mode 100644 internal/architecture/outbox_write_retry_test.go diff --git a/docs/architecture.md b/docs/architecture.md index 0eefb9c2..9fd5a353 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -108,7 +108,9 @@ else, including any operation added later, gets one attempt. A write can land at GitHub and still return 5xx, so a blind retry would post twice. Writes are retried by the outbox, which waits for GitHub's 10-second processing limit to pass, re-reads the PR, and sends again only when the action's marker is absent. If that read fails, -the write stays pending rather than being sent unverified. +the write stays pending rather than being sent unverified. The wait comes from the +provider's `ProviderCaps.WriteSettle`. A provider that declares none, as GitLab does +because nothing bounds its proxy and application timeouts, gets no resend in the run. Accepting a repository invitation is the one exception. It changes the posting identity's account, not a pull request, so it has no marker, no run, and diff --git a/docs/review-lifecycle.md b/docs/review-lifecycle.md index 06963cbe..61b965d5 100644 --- a/docs/review-lifecycle.md +++ b/docs/review-lifecycle.md @@ -118,6 +118,8 @@ not reached the PR. get one send each, so an outage cannot multiply the wait. Whatever is left stays pending, the run exits 5, and the next `cr review` reconciles it. Duplicates remain possible only if GitHub applies a write after the settle wait and the marker check. + GitLab declares no processing limit, so a GitLab write that fails retryably gets one + send and stays pending for the next `cr review` to reconcile. - A run that fails renders `Status: error` and the cause on stdout, or the same record as JSON, as well as the error on stderr and a non-zero exit code. - Thread replies are ordered before resolutions, and a resolution is not sent diff --git a/internal/architecture/outbox_write_retry_test.go b/internal/architecture/outbox_write_retry_test.go new file mode 100644 index 00000000..51765534 --- /dev/null +++ b/internal/architecture/outbox_write_retry_test.go @@ -0,0 +1,101 @@ +package architecture_test + +import ( + "go/ast" + "go/parser" + "go/token" + "io/fs" + "path/filepath" + "strings" + "testing" +) + +// A write path that omits WriteRetry compiles and silently loses in-run recovery, +// so every outbox.Post and every options literal that feeds one must name the field. +func TestOutboxPostPathsCarryWriteRetry(t *testing.T) { + repoRoot := repoRootFromTest(t) + feedsPost := map[string]bool{"reviewrun": true, "gateio": true, "threadrespond": true} + postCalls := 0 + + fset := token.NewFileSet() + err := filepath.WalkDir(filepath.Join(repoRoot, "internal"), func(path string, entry fs.DirEntry, walkErr error) error { + if walkErr != nil { + return walkErr + } + if entry.IsDir() || filepath.Ext(path) != ".go" || strings.HasSuffix(path, "_test.go") { + return nil + } + parsed, err := parser.ParseFile(fset, path, nil, 0) + if err != nil { + return err + } + ast.Inspect(parsed, func(node ast.Node) bool { + switch n := node.(type) { + case *ast.CallExpr: + if selectorIs(n.Fun, "outbox", "Post") { + postCalls++ + literal, ok := postOptionsLiteral(n) + if !ok { + t.Errorf("%s: outbox.Post options must be a literal so WriteRetry can be checked", fset.Position(n.Pos())) + } else if !namesField(literal, "WriteRetry") { + t.Errorf("%s: outbox.Post options omit WriteRetry", fset.Position(n.Pos())) + } + } + case *ast.CompositeLit: + if pkg, ok := optionsPackage(n.Type); ok && feedsPost[pkg] && !namesField(n, "WriteRetry") { + t.Errorf("%s: %s.Options omits WriteRetry", fset.Position(n.Pos()), pkg) + } + } + return true + }) + return nil + }) + if err != nil { + t.Fatalf("WalkDir(%s): %v", repoRoot, err) + } + if postCalls == 0 { + t.Fatal("found no outbox.Post calls, so this test checked nothing") + } +} + +func selectorIs(expr ast.Expr, pkg, name string) bool { + selector, ok := expr.(*ast.SelectorExpr) + if !ok || selector.Sel.Name != name { + return false + } + ident, ok := selector.X.(*ast.Ident) + return ok && ident.Name == pkg +} + +func postOptionsLiteral(call *ast.CallExpr) (*ast.CompositeLit, bool) { + if len(call.Args) < 2 { + return nil, false + } + literal, ok := call.Args[1].(*ast.CompositeLit) + return literal, ok +} + +func optionsPackage(expr ast.Expr) (string, bool) { + selector, ok := expr.(*ast.SelectorExpr) + if !ok || selector.Sel.Name != "Options" { + return "", false + } + ident, ok := selector.X.(*ast.Ident) + if !ok { + return "", false + } + return ident.Name, true +} + +func namesField(literal *ast.CompositeLit, field string) bool { + for _, element := range literal.Elts { + keyValue, ok := element.(*ast.KeyValueExpr) + if !ok { + continue + } + if key, ok := keyValue.Key.(*ast.Ident); ok && key.Name == field { + return true + } + } + return false +} diff --git a/internal/cmd/noleak/noleak_test.go b/internal/cmd/noleak/noleak_test.go index bfdf57b0..97e37b25 100644 --- a/internal/cmd/noleak/noleak_test.go +++ b/internal/cmd/noleak/noleak_test.go @@ -699,6 +699,7 @@ func (p noLeakRuntimeProvider) Capabilities() gitprovider.ProviderCaps { NativeFileLevelComments: readCaps.NativeFileLevelComments || writeCaps.NativeFileLevelComments, ThreadResolution: readCaps.ThreadResolution || writeCaps.ThreadResolution, BundleInlineOnSubmit: readCaps.BundleInlineOnSubmit || writeCaps.BundleInlineOnSubmit, + WriteSettle: writeCaps.WriteSettle, } } diff --git a/internal/gitexec/client.go b/internal/gitexec/client.go index 93654761..52e8b884 100644 --- a/internal/gitexec/client.go +++ b/internal/gitexec/client.go @@ -122,8 +122,7 @@ func (c *Client) Run(ctx context.Context, dir string, args ...string) ([]byte, e } } -// commandError keeps git's own output apart from its arguments, which carry -// PR-controlled ref names that must not decide whether a failure is transient. +// commandError keeps what is needed to judge a failure by git's own words. type commandError struct { args []string detail string @@ -135,7 +134,16 @@ func (e *commandError) Error() string { func transientFetchFailure(err error) bool { var failure *commandError - return errors.As(err, &failure) && transientFetchOutput.MatchString(failure.detail) + if !errors.As(err, &failure) { + return false + } + // Git echoes the requested ref into its output, and ref names are controlled + // by the PR, so they must not decide whether a failure is transient. + detail := failure.detail + for _, arg := range failure.args[1:] { + detail = strings.ReplaceAll(detail, arg, "") + } + return transientFetchOutput.MatchString(detail) } func (c *Client) runOnce(ctx context.Context, dir string, args ...string) ([]byte, error) { diff --git a/internal/gitexec/client_test.go b/internal/gitexec/client_test.go index a6d848ca..f10bce58 100644 --- a/internal/gitexec/client_test.go +++ b/internal/gitexec/client_test.go @@ -231,7 +231,7 @@ func TestPermanentFetchFailureAndOtherCommandsAreNotRetried(t *testing.T) { }{ {name: "unadvertised sha", output: "fatal: remote error: upload-pack: not our ref abc", args: []string{"fetch", "--no-tags", testFetchURL, "abc"}}, {name: "missing repository", output: "fatal: unable to access: The requested URL returned error: 404", args: []string{"fetch", "--no-tags", testFetchURL, "abc"}}, - {name: "transient words only in a ref name", output: "fatal: couldn't find remote ref", args: []string{"fetch", "--no-tags", testFetchURL, "refs/heads/gnutls_fix"}}, + {name: "transient words only in a ref name", output: "fatal: couldn\x27t find remote ref refs/heads/gnutls_fix", args: []string{"fetch", "--no-tags", testFetchURL, "refs/heads/gnutls_fix"}}, {name: "not a fetch", output: "fatal: The requested URL returned error: 502", args: []string{"rev-parse", "HEAD"}}, } for _, tt := range tests { diff --git a/internal/gitprovider/github/app_auth.go b/internal/gitprovider/github/app_auth.go index a660d7c7..b5381f4f 100644 --- a/internal/gitprovider/github/app_auth.go +++ b/internal/gitprovider/github/app_auth.go @@ -147,15 +147,11 @@ func (a *githubAppAuth) refresh(ctx context.Context, op gitprovider.Operation) ( } func (a *githubAppAuth) refreshLocked(ctx context.Context, op gitprovider.Operation) (string, gitprovider.Identity, error) { - jwt, err := a.jwt() - if err != nil { - return "", gitprovider.Identity{}, gitprovider.WrapError(gitprovider.ErrAuth, op, err) - } - installation, err := a.resolveInstallation(ctx, op, jwt) + installation, err := a.resolveInstallation(ctx, op) if err != nil { return "", gitprovider.Identity{}, err } - token, expiresAt, err := a.createInstallationToken(ctx, op, jwt, installation.ID) + token, expiresAt, err := a.createInstallationToken(ctx, op, installation.ID) if err != nil { return "", gitprovider.Identity{}, err } @@ -167,27 +163,27 @@ func (a *githubAppAuth) refreshLocked(ctx context.Context, op gitprovider.Operat return token, identity, nil } -func (a *githubAppAuth) resolveInstallation(ctx context.Context, op gitprovider.Operation, jwt string) (githubAppInstallation, error) { +func (a *githubAppAuth) resolveInstallation(ctx context.Context, op gitprovider.Operation) (githubAppInstallation, error) { if strings.TrimSpace(a.installationID) != "" { endpoint := restURL(a.baseURL, "app", "installations", a.installationID) var installation githubAppInstallation - if err := a.doAppREST(ctx, op, http.MethodGet, endpoint, jwt, nil, &installation); err != nil { + if err := a.doAppREST(ctx, op, http.MethodGet, endpoint, nil, &installation); err != nil { return githubAppInstallation{}, mapPinnedInstallationLookupError(op, a.installationID, err) } return installation, nil } endpoint := restURL(a.baseURL, "repos", a.lookup.Owner, a.lookup.Repo, "installation") var installation githubAppInstallation - if err := a.doAppREST(ctx, op, http.MethodGet, endpoint, jwt, nil, &installation); err != nil { + if err := a.doAppREST(ctx, op, http.MethodGet, endpoint, nil, &installation); err != nil { return githubAppInstallation{}, mapRepositoryInstallationLookupError(op, a.lookup.Owner, a.lookup.Repo, err) } return installation, nil } -func (a *githubAppAuth) createInstallationToken(ctx context.Context, op gitprovider.Operation, jwt string, installationID int64) (string, time.Time, error) { +func (a *githubAppAuth) createInstallationToken(ctx context.Context, op gitprovider.Operation, installationID int64) (string, time.Time, error) { endpoint := restURL(a.baseURL, "app", "installations", strconv.FormatInt(installationID, 10), "access_tokens") var response installationTokenResponse - if err := a.doAppREST(ctx, op, http.MethodPost, endpoint, jwt, map[string]any{}, &response); err != nil { + if err := a.doAppREST(ctx, op, http.MethodPost, endpoint, map[string]any{}, &response); err != nil { return "", time.Time{}, mapCreateInstallationTokenError(op, strconv.FormatInt(installationID, 10), err) } if strings.TrimSpace(response.Token) == "" { @@ -233,7 +229,7 @@ func mapCreateInstallationTokenError(op gitprovider.Operation, installationID st } } -func (a *githubAppAuth) doAppREST(ctx context.Context, op gitprovider.Operation, method, endpoint, jwt string, in any, out any) error { +func (a *githubAppAuth) doAppREST(ctx context.Context, op gitprovider.Operation, method, endpoint string, in any, out any) error { var payload []byte if in != nil { var err error @@ -244,7 +240,12 @@ func (a *githubAppAuth) doAppREST(ctx context.Context, op gitprovider.Operation, } // Installation lookups are reads and minting a token changes nothing a user // can see, so these repeat even when op names the write that needed a token. + // Each attempt signs its own JWT, because retries can outlast one JWT's lifetime. return a.retry.repeat(ctx, op, func() error { + jwt, err := a.jwt() + if err != nil { + return gitprovider.WrapError(gitprovider.ErrAuth, op, err) + } return a.appRESTAttempt(ctx, op, method, endpoint, jwt, payload, in != nil, out) }) } diff --git a/internal/gitprovider/github/client.go b/internal/gitprovider/github/client.go index 4c37914d..99649fdc 100644 --- a/internal/gitprovider/github/client.go +++ b/internal/gitprovider/github/client.go @@ -28,6 +28,9 @@ const ( gitHubAppRefreshSkew = 5 * time.Minute gitHubAppJWTBackdate = 60 * time.Second gitHubAppJWTLifetime = 9 * time.Minute + // writeSettle exceeds the 10 seconds after which GitHub documents that it + // terminates API request processing. + writeSettle = 12 * time.Second ) var ( @@ -182,6 +185,7 @@ func (c *Client) Capabilities() gitprovider.ProviderCaps { NativeFileLevelComments: false, ThreadResolution: true, BundleInlineOnSubmit: true, + WriteSettle: writeSettle, } } diff --git a/internal/gitprovider/github/client_test.go b/internal/gitprovider/github/client_test.go index 9e843c52..7de6a1e5 100644 --- a/internal/gitprovider/github/client_test.go +++ b/internal/gitprovider/github/client_test.go @@ -30,6 +30,9 @@ func TestCapabilities(t *testing.T) { if caps.NativeFileLevelComments || !caps.ThreadResolution || !caps.BundleInlineOnSubmit { t.Fatalf("Capabilities() = %#v, want bundled review comments with thread resolution and no native file comments", caps) } + if caps.WriteSettle <= 10*time.Second { + t.Fatalf("WriteSettle = %v, want longer than GitHub's 10-second processing limit", caps.WriteSettle) + } } func TestDefaultHTTPClientIsBounded(t *testing.T) { diff --git a/internal/gitprovider/github/retry_test.go b/internal/gitprovider/github/retry_test.go index 8bfdd32d..de9c44b0 100644 --- a/internal/gitprovider/github/retry_test.go +++ b/internal/gitprovider/github/retry_test.go @@ -3,6 +3,8 @@ package github import ( "context" "crypto/tls" + "encoding/base64" + "encoding/json" "errors" "net/http" "net/http/httptest" @@ -358,6 +360,64 @@ func TestWritesAreNotRetriedByTheClient(t *testing.T) { } } +func TestRateLimitedWriteStaysRetryableWithItsWait(t *testing.T) { + ref := testPRRef() + writes := []struct { + name string + write func(*Client) error + }{ + {name: "review", write: func(c *Client) error { + _, err := c.SubmitReview(context.Background(), ref, gitprovider.ReviewRequest{CommitSHA: "head-sha", Event: review.ReviewEventComment, Body: "body"}) + return err + }}, + {name: "issue comment", write: func(c *Client) error { + _, err := c.PostIssueComment(context.Background(), ref, "body") + return err + }}, + {name: "inline comment", write: func(c *Client) error { + _, err := c.PostInlineComment(context.Background(), ref, gitprovider.InlineComment{CommitSHA: "head-sha", Body: "body", Path: "a.go", Side: review.DiffSideRight, Line: 1, SubjectType: review.AnchorKindLine}) + return err + }}, + } + responses := []struct { + name string + retryAfter string + body string + wantWait time.Duration + }{ + {name: "retry-after", retryAfter: "30", body: `{"message":"forbidden"}`, wantWait: 30 * time.Second}, + {name: "secondary limit message without headers", body: `{"message":"You have exceeded a secondary rate limit."}`, wantWait: defaultRateLimitWait}, + } + for _, tt := range writes { + for _, response := range responses { + t.Run(tt.name+"/"+response.name, func(t *testing.T) { + var calls atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + calls.Add(1) + if response.retryAfter != "" { + w.Header().Set("Retry-After", response.retryAfter) + } + w.WriteHeader(http.StatusForbidden) + _, _ = w.Write([]byte(response.body)) + })) + defer server.Close() + recorder := &retryRecorder{} + + err := tt.write(retryClient(t, server.URL, recorder.policy())) + if !errors.Is(err, gitprovider.ErrRetryable) || errors.Is(err, gitprovider.ErrPermission) { + t.Fatalf("error = %v, want ErrRetryable and not ErrPermission", err) + } + if wait, ok := gitprovider.RetryAfterHint(err); !ok || wait != response.wantWait { + t.Fatalf("RetryAfterHint = %v, %v, want %v", wait, ok, response.wantWait) + } + if calls.Load() != 1 || len(recorder.delays) != 0 { + t.Fatalf("calls = %d delays = %v, want one send and no wait", calls.Load(), recorder.delays) + } + }) + } + } +} + // Fails closed: a new write must be added here deliberately, never inherit retry. func TestRetrySafeOperationClassifiesEveryOperation(t *testing.T) { want := map[gitprovider.Operation]bool{ @@ -497,6 +557,71 @@ func TestAppTokenMintRetriesEvenForAWrite(t *testing.T) { } } +func TestAppTokenRetriesOutlastingOneJWTStillAuthenticate(t *testing.T) { + var clockSeconds atomic.Int64 + clockSeconds.Store(time.Date(2026, 11, 3, 12, 0, 0, 0, time.UTC).Unix()) + now := func() time.Time { return time.Unix(clockSeconds.Load(), 0).UTC() } + _, privateKeyPEM := testPrivateKey(t) + var failuresLeft atomic.Int32 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if jwtExpiry(t, r).Before(now()) { + w.WriteHeader(http.StatusUnauthorized) + return + } + if failuresLeft.Add(-1) >= 0 { + w.WriteHeader(http.StatusServiceUnavailable) + return + } + if r.URL.Path == "/app/installations/42" { + writeJSON(t, w, map[string]any{"id": 42, "app_id": 12345, "app_slug": "cr-reviewer"}) + return + } + writeJSON(t, w, map[string]any{"token": "installation-token", "expires_at": now().Add(time.Hour).Format(time.RFC3339)}) + })) + defer server.Close() + // Each failed attempt costs more than half a JWT's lifetime. + failuresLeft.Store(2) + policy := RetryPolicy{ + MaxAttempts: 3, + MaxElapsed: 24 * time.Hour, + Sleep: func(context.Context, time.Duration) error { + clockSeconds.Add(int64((gitHubAppJWTLifetime * 2 / 3).Seconds())) + return nil + }, + } + + if _, _, err := NewFromGitConfig(githubAppGitConfig("codereview/app"), githubAppStore(t, "app", "12345", privateKeyPEM), Options{ + BaseURL: server.URL, GraphQLURL: server.URL + "/graphql", + Now: now, + InstallationID: "42", + Retry: policy, + }); err != nil { + t.Fatalf("NewFromGitConfig: %v", err) + } +} + +func jwtExpiry(t *testing.T, r *http.Request) time.Time { + t.Helper() + parts := strings.Split(strings.TrimPrefix(r.Header.Get("Authorization"), "Bearer "), ".") + if len(parts) != 3 { + t.Errorf("Authorization is not a JWT: %d parts", len(parts)) + return time.Time{} + } + payload, err := base64.RawURLEncoding.DecodeString(parts[1]) + if err != nil { + t.Errorf("decode JWT payload: %v", err) + return time.Time{} + } + var claims struct { + Exp int64 `json:"exp"` + } + if err := json.Unmarshal(payload, &claims); err != nil { + t.Errorf("parse JWT payload: %v", err) + return time.Time{} + } + return time.Unix(claims.Exp, 0) +} + func TestThreadCommentBotAuthorMatchesPostingIdentity(t *testing.T) { payload, err := os.ReadFile("testdata/review_threads_bot_author.json") if err != nil { diff --git a/internal/gitprovider/gitlab/client_test.go b/internal/gitprovider/gitlab/client_test.go index 408c834c..ecdc58fa 100644 --- a/internal/gitprovider/gitlab/client_test.go +++ b/internal/gitprovider/gitlab/client_test.go @@ -32,6 +32,9 @@ func TestCapabilities(t *testing.T) { if !caps.ReviewSummaryAsComment { t.Fatalf("Capabilities() = %#v, want review summaries as comments", caps) } + if caps.WriteSettle != 0 { + t.Fatalf("WriteSettle = %v, want none: GitLab documents no processing limit", caps.WriteSettle) + } if caps.HeadRefNamespace != "merge-requests" { t.Fatalf("HeadRefNamespace = %q, want merge-requests", caps.HeadRefNamespace) } diff --git a/internal/gitprovider/types.go b/internal/gitprovider/types.go index cd4fad6a..bfe03153 100644 --- a/internal/gitprovider/types.go +++ b/internal/gitprovider/types.go @@ -130,6 +130,11 @@ type ProviderCaps struct { // pull-request head commits (refs///head). Empty // means the GitHub "pull" namespace. HeadRefNamespace string + // WriteSettle is how long after a failed write the host has stopped + // processing it, so that a read can say whether the write landed. Zero means + // the host documents no such bound: a failed write is left for the next run + // to reconcile rather than resent in this one. + WriteSettle time.Duration } // PullHeadRefNamespace is the default virtual ref namespace for pull-request diff --git a/internal/outbox/outbox.go b/internal/outbox/outbox.go index 39c74957..b994646b 100644 --- a/internal/outbox/outbox.go +++ b/internal/outbox/outbox.go @@ -61,8 +61,9 @@ type Options struct { Provider Provider Limiter Limiter Now func() time.Time - // WriteRetry enables in-run recovery of retryable write failures in Post. - // Nil leaves a failed write pending after one attempt. + // WriteRetry enables in-run recovery of retryable write failures in Post, for + // providers that declare ProviderCaps.WriteSettle. Otherwise a failed write + // stays pending after one attempt. WriteRetry *WriteRetry } @@ -215,7 +216,7 @@ func Post(ctx context.Context, opts Options, req Request) (Result, error) { } upstreamID, err := dispatch(ctx, opts.Provider, req.PRRef, plan) - if err != nil && opts.WriteRetry != nil && !writeRetriesSpent { + if err != nil && opts.WriteRetry != nil && !writeRetriesSpent && opts.Provider.Capabilities().WriteSettle > 0 { recovery, recoverErr := recoverWrite(ctx, opts, req, actions, i, plan, err) if recoverErr != nil { if isContextError(recoverErr) { diff --git a/internal/outbox/write_retry.go b/internal/outbox/write_retry.go index e83350ac..9fd9ab44 100644 --- a/internal/outbox/write_retry.go +++ b/internal/outbox/write_retry.go @@ -12,23 +12,17 @@ import ( const ( defaultWriteMaxAttempts = 3 - // defaultWriteSettle spaces a resend from the failure. GitHub stops - // processing an API request after 10 seconds, so a write that returned 5xx or - // timed out has finished one way or the other before the marker check runs. - defaultWriteSettle = 12 * time.Second // defaultWriteMaxWait matches the GitHub client's longest honored wait. defaultWriteMaxWait = 2 * time.Minute ) // WriteRetry bounds in-run recovery of a write that failed retryably. A write -// can land at the host and still report failure, so nothing is resent until a -// fresh read of the PR shows the write's action marker is absent. +// can land at the host and still report failure, so nothing is resent until the +// provider's ProviderCaps.WriteSettle has passed and a fresh read of the PR shows +// the write's action marker is absent. Later checks wait proportionally longer. type WriteRetry struct { // MaxAttempts counts sends of one action, including the first. MaxAttempts int - // Settle is the wait before the first marker check; later checks wait - // proportionally longer. - Settle time.Duration // MaxWait is the longest host-requested wait worth sitting through. MaxWait time.Duration // Sleep waits for d or until ctx ends. Tests inject it to avoid real waits. @@ -73,9 +67,6 @@ func (w WriteRetry) normalized() WriteRetry { if w.MaxAttempts <= 0 { w.MaxAttempts = defaultWriteMaxAttempts } - if w.Settle <= 0 { - w.Settle = defaultWriteSettle - } if w.MaxWait <= 0 { w.MaxWait = defaultWriteMaxWait } @@ -119,6 +110,7 @@ type writeRecovery struct { // itself: the ledger, or ctx ending during a wait. func recoverWrite(ctx context.Context, opts Options, req Request, actions []ledger.PlannedAction, i int, plan actionPlan, sendErr error) (writeRecovery, error) { policy := opts.WriteRetry.normalized() + settle := opts.Provider.Capabilities().WriteSettle action := &actions[i] emit := func(phase WriteRetryPhase, attempt int, delay time.Duration, reason string) { if policy.OnEvent != nil { @@ -130,7 +122,7 @@ func recoverWrite(ctx context.Context, opts Options, req Request, actions []ledg if ctx.Err() != nil { break } - delay := policy.Jitter(policy.Settle * time.Duration(attempt)) + delay := policy.Jitter(settle * time.Duration(attempt)) if hint, ok := gitprovider.RetryAfterHint(err); ok { if hint > policy.MaxWait { emit(WriteRetryAbandoned, attempt, 0, "host asked to wait "+hint.Round(time.Second).String()) diff --git a/internal/outbox/write_retry_test.go b/internal/outbox/write_retry_test.go index 5db5671b..bef11f8a 100644 --- a/internal/outbox/write_retry_test.go +++ b/internal/outbox/write_retry_test.go @@ -14,6 +14,8 @@ import ( "github.com/open-cli-collective/codereview-cli/internal/review" ) +const testWriteSettle = 12 * time.Second + // sendScript says what one write attempt does at the host. type sendScript struct { land bool // the host keeps the write @@ -37,6 +39,7 @@ type simHost struct { func newSimHost(script map[string][]sendScript) *simHost { return &simHost{ identity: botIdentity(), + caps: gitprovider.ProviderCaps{WriteSettle: testWriteSettle}, script: script, sends: map[string]int{}, thread: gitprovider.InlineThread{ID: "thread-1", Path: "main.go", Side: review.DiffSideRight, Line: 12, SubjectType: review.AnchorKindLine}, @@ -272,7 +275,7 @@ func TestResentWriteThatLandsOnSecondFailureIsNotSentAThirdTime(t *testing.T) { if host.sends["review"] != 2 || len(host.reviews) != 1 || result.ExitCode != exitOK { t.Fatalf("sends = %d reviews = %d result = %#v, want two sends, one review, success", host.sends["review"], len(host.reviews), result) } - if want := []time.Duration{defaultWriteSettle, 2 * defaultWriteSettle}; !slices.Equal(recorder.delays, want) { + if want := []time.Duration{testWriteSettle, 2 * testWriteSettle}; !slices.Equal(recorder.delays, want) { t.Fatalf("delays = %v, want %v", recorder.delays, want) } } @@ -335,7 +338,7 @@ func TestBundledInlineCommentsFollowAReconciledReview(t *testing.T) { store := openStore(t) run := allocateRun(t, store, ledger.PostModeLive) host := newSimHost(map[string][]sendScript{"review": {{land: true, err: retryableWriteError(gitprovider.OperationSubmitReview)}}}) - host.caps = gitprovider.ProviderCaps{BundleInlineOnSubmit: true} + host.caps.BundleInlineOnSubmit = true insertAction(t, store, plannedAction(run.RunID, "inline-1", ledger.PlannedActionInlineComment, true, "", InlineCommentPayload{Body: "inline", Path: "main.go", Side: review.DiffSideRight, Line: 12, SubjectType: review.AnchorKindLine})) insertAction(t, store, plannedAction(run.RunID, "submit-1", ledger.PlannedActionSubmitReview, true, "", SubmitReviewPayload{Body: "review", Event: review.ReviewEventComment})) @@ -478,9 +481,26 @@ func TestPostWithoutWriteRetrySendsOnce(t *testing.T) { } } +func TestProviderWithoutWriteSettleIsNotResentInRun(t *testing.T) { + store := openStore(t) + run := allocateRun(t, store, ledger.PostModeLive) + host := newSimHost(map[string][]sendScript{"rollup": {{err: retryableWriteError(gitprovider.OperationPostIssueComment)}}}) + host.caps.WriteSettle = 0 + insertAction(t, store, plannedAction(run.RunID, "action-1", ledger.PlannedActionRollupComment, true, "", RollupCommentPayload{Body: "rollup"})) + recorder := &writeRetryRecorder{} + + result, err := Post(context.Background(), Options{Store: store, Provider: host, Limiter: noopLimiter{}, Now: fixedClock(), WriteRetry: recorder.policy()}, testRequest(run)) + if err != nil { + t.Fatalf("Post: %v", err) + } + if host.sends["rollup"] != 1 || len(recorder.delays) != 0 || result.ExitCode != exitUpstream || result.Pending != 1 { + t.Fatalf("sends = %d delays = %v result = %#v, want one send left pending", host.sends["rollup"], recorder.delays, result) + } +} + func TestDefaultWriteJitterNeverShortensTheSettleWait(t *testing.T) { for range 200 { - if got := addJitter(defaultWriteSettle); got < defaultWriteSettle || got >= defaultWriteSettle+defaultWriteSettle/4 { + if got := addJitter(testWriteSettle); got < testWriteSettle || got >= testWriteSettle+testWriteSettle/4 { t.Fatalf("addJitter = %s", got) } }