fix: retry transient report-read failures during scan polling (sable-l10k) - #220
Merged
Conversation
…l10k) A paying customer's GitHub Actions run died on: ::error::Rafter scan poll failed: HTTP 500 — Failed to fetch report from storage: Object not found A report is not durable the instant a scan flips to completed, so a poll can hit a 5xx on a scan that is perfectly readable seconds later. Every poll path treated any non-2xx as fatal and exited immediately — while the transport-error branch three lines above already retried. That asymmetry was the bug: a curl-level failure was survivable, an HTTP-level one was not. Reproduced in a real GitHub Actions run against a mock backend that injects one transient 500 into an otherwise healthy poll sequence; the run died on a scan that completed on the very next poll. All three surfaces now share one contract (documented in CLI_SPEC.md): - 5xx / 408 / 404 mid-poll and transport errors are transient. Retried up to 5 consecutive times with 2s/4s/8s/16s backoff; the counter resets on any successful poll. - Other 4xx (401/403/429) are not retried. A 404 on the FIRST poll is still a genuinely missing scan, exit 2. - On giving up, the message names the scan id, the `rafter get <id>` retry, and the dashboard. Storage-layer wording survives as supporting detail rather than as the whole explanation. The Python loop was additionally calling .json() on the 500 body, reading no status, falling out of the loop and writing the error payload out as if it were results — a silent wrong answer rather than a loud failure. Also here, from the security review of this diff: - Strip newlines and cap length on server-controlled `.error` before it reaches `::error::`/`::warning::`. A body containing a newline could forge workflow commands (`::add-mask::`, `::stop-commands::`). Same class as the pre-existing sinks; this diff widened it from 2 to 6. - Add --connect-timeout/--max-time to curl and an axios timeout, so a hung server cannot stall inside a request that the retry loop only checks between attempts. - Source the action's `status` output from the poll step when the results step never runs, so the new `unreadable` status reaches consumers instead of an empty string. Coverage: 8 vitest + 9 pytest cases pinning both halves of the contract, plus two end-to-end CI jobs that drive the composite action against a localhost mock backend — no API key, no credit spend.
Leaving vitest's fake timers installed past the end of the test body hangs the afterEach hook on Node 18 — the cross-platform matrix caught it on both ubuntu and macos. Matches the in-test restore the existing scan-remote tests already use; the afterEach restore stays as a fallback for failed assertions.
An independent reviewer was asked to argue against merging #220. It found a regression I introduced, a contract my own spec text got wrong, and a test suite that did not test the mechanism it existed to protect. All real. REGRESSION I INTRODUCED — a failed results fetch reported `completed`. Sourcing the action's `status` output from `steps.results.outputs.status || steps.poll.outputs.status` meant that when the results fetch exhausted its retries, the empty results output fell back to the poll step's `completed`. A consumer gating on `status == 'completed'` saw a clean scan, and the artifact upload published the error body as rafter-results.json. Exactly the silent-wrong-answer class this PR set out to remove. Both give-up paths in fetch_results now record `status=unreadable`, and the artifact upload is gated on the results step rather than the poll step. THE TESTS DID NOT TEST THE BACKOFF. Setting BASE_BACKOFF_MS to 0 left all 8 vitest cases green, and the Python fixture patched out time.sleep entirely, making the schedule unobservable by construction. Backoff IS the fix — retrying five times inside a millisecond gives an eventually-consistent store no time to converge. Both suites now pin the exact sequence (10s poll, then 2/4/8/16), and both verify the consecutive counter resets on a successful poll. THE ACTION VIOLATED THE CONTRACT THIS PR WROTE. CLI_SPEC said transport errors were retried on the same budget as 5xx; in the action they retried on a flat 10s and never touched the counter, so an unreachable backend burned the whole timeout and then reported "scan did not complete within N minutes" — a timeout message for a DNS failure. They now share the budget and exit with status=unreachable. The spec is also corrected where the action genuinely cannot match the CLI: it has no first-poll concept, so every 404 there is lag (bounded by the 5-failure budget, not the full timeout). UNBOUNDED CLI LOOP. The consecutive counter was constructed per call, and resets on success, so a backend alternating 200/500 forever never exhausted it — and the CLI has no wall-clock deadline. Added a total budget (20 per invocation) that does not reset, keeping the useful reset-on-success semantics without the hole. THE REMEDY WE RECOMMEND WAS THE ONE PATH NOT FIXED. The give-up message says "retry with rafter get <id>", which re-enters at the first poll — which had no retry, so it died on the raw storage jargon we had just stopped printing. Worse for 404: the loop retried it five times, then recommended a command that reports "not found" with a different exit code. The first poll now retries transient 5xx while still treating 404 as fatal. PARITY BREAKS (this repo requires strict Node/Python parity): - Python accepted only 200; Node accepts any 2xx. On a 202 they returned opposite outcomes — Python exit 1, Node exit 0 with an empty payload. - Node wrote the retry notice into the ora spinner, which renders nothing on a non-TTY. The diagnostic was invisible in CI, the one place it matters. It goes to stderr now, matching Python. - Node retried ANY error lacking a `.response`, including TypeErrors thrown from our own code. Narrowed to genuine HTTP-layer errors. - Python raised PollGaveUpError for non-transient statuses too, conflating "tried five times" with "did not try". Split out PollFatalError. - Neither runtime truncated server error text; both now cap it like the action does. ALSO: sanitized the three remaining unsanitized `.error`/response echo sites in action.yml, guarded TIMEOUT_MINUTES before bash arithmetic evaluates it, and restored the remaining-budget denominator the poll log line had lost. COVERAGE for the two things a "simplification" would silently break: a CI job injecting a mid-poll 404, a CI job failing the results fetch specifically, and six new assertions in the action.yml drift detector (404 in the transient set, transport errors counted, give-up message actionable, both unreadable writes, artifact gating, exponential backoff). Each was mutation-tested to confirm it fails when the property is removed. CHANGELOG documents the two behavior changes this ships: timeout-minutes is now a real wall-clock deadline rather than a poll count, and Python's non-transient mid-poll failures now exit 1 instead of 0.
…sable-l10k)
A verification pass over the previous fix commit found a defect in code that
commit introduced, plus three places where a fix was thinner than it looked.
THE BLOCKER — I added a truncate() helper that assumed the server's error
field is a string. A backend answering {"error": {"message": "..."}} on a 500
made it call .split() on a dict (Python: AttributeError, uncaught, straight to
a traceback) and .replace() on an object (Node: "s.replace is not a function",
and crucially NO retry — 2 calls, not 5). So the one shape of error body most
likely to appear on a real 500 turned a retryable failure into an immediate
hard failure with a nonsense message, inside the very code meant to make
transient failures survivable. Both runtimes now coerce before truncating.
THE TOTAL-CAP TEST DID NOT TEST THE TOTAL CAP. Deleting the total clause from
FailureBudget.exhausted left all 14 Node tests green: the mock queue drained,
axios returned undefined, and the resulting TypeError was converted by the
loop's own catch into the exact exit code the test asserted. The test now uses
an endless flapping mock with a hard ceiling, so a missing cap fails loudly
and immediately rather than passing on an unrelated crash. Verified by
mutation both ways. (Python's equivalent was already genuine.)
THE RECOMMENDED REMEDY STILL DID NOT RETRY. The last commit made the first
poll retry, but `rafter get <id>` WITHOUT --interactive takes a different path
entirely — a single un-retried request in both runtimes. So the command the
give-up message recommends was still defeated by the failure that produced the
message. It now shares the same retry budget.
THE MESSAGE LIED ABOUT ITS OWN ATTEMPT COUNT. Both runtimes hardcoded "after 5
attempts" while exhaustion can equally come from the total budget of 20 — a
flapping backend produced "after 5 attempts" following 20 failures over four
minutes. It now reports the real count. Relatedly, the CLI blamed the report
("could not read the report … retry with rafter get") even when nothing ever
reached the server; it now distinguishes unreachable-API from unreadable-report,
which the action already did.
ALSO:
- Narrowed isTransientPollError: Node's own TypeError [ERR_INVALID_CHAR]
carries .code, so an API key read from a file with a trailing newline was
retried five times and reported as a flaky backend. Dropped .code; real
axios timeouts still retry via .request/.isAxiosError.
- Validate the server-supplied scan_id before it reaches $GITHUB_OUTPUT. A
newline there forges step outputs, including status=completed. The CHANGELOG
claimed sanitization was complete "at every site" when this one was open;
the claim is now true rather than trimmed.
- Three more drift assertions (sanitization present, TIMEOUT_MINUTES guarded,
scan_id validated) — the first of which was itself broken on first write and
only caught by mutation-testing it.
- Tests for the nested-error crash, the truncation cap, the real attempt
count, and the unreachable-API message, in both runtimes.
This was referenced Sep 1, 2026
Rome-1
added a commit
that referenced
this pull request
Sep 1, 2026
…10k (#221) The assignment was to explain why 8 of 17 checks skipped on PR #220. The skip pattern is real, but it is not why the bug reached a customer. Testing that claim rather than assuming it is what turned up the rest. WOULD ANY EXISTING CHECK HAVE CAUGHT IT, IF IT HAD RUN? No. Checked out main at 0996492 (the buggy tree) and ran the entire suite against it: 2065 passed, and the only failures were three files that fail for environmental reasons here and are unrelated to polling. tests/scan-remote.test.ts and test_scan_remote.py both cover the poll loop — with the HTTP layer mocked, and neither ever injected a non-2xx mid-poll. They pass against the bug. And nothing executed github-action/action.yml at all, which is the file the customer's error came from. test-action.yml drives the ROOT action.yml, a different action that scans locally. Of the jobs in test-github-action.yml, two run hand-copied reimplementations of the action's bash (their own headers admit the duplication) and one greps the YAML as text. So the workflow that fires on github-action/** changes ran, and still executed none of the code. The gap was COVERAGE, and #220 closed it. The skip pattern would not have mattered. Three things found on the way there do: 1. publish-python had no `needs:`. publish-node has needed the test jobs since it was written; the Python half published to PyPI in parallel with the tests, ungated. A red suite blocked the npm release and shipped the PyPI one anyway — in a dual-implementation product where the two versions must match, that diverges them at the registry, the one place users cannot see it. Now gated. (publish.yaml also runs no pytest anywhere; filed separately.) 2. backend-api rendered identically whether it tested the backend or nothing. Its only real step is gated on RAFTER_API_KEY, which has never been set on this repo, so "backend-api ✓" has always meant "checked out and built". It now says so, loudly, in the log and the step summary. 3. test-node and test-python were skipped on internal PRs into main. On #220 — which changed both clients — neither ran. They now run on every PR. The premise that our own work is tested locally first is also weaker than it looks: this repo has test files that fail locally for environmental reasons, so "green on my machine" is not a signal anyone can act on. Cost is ~4 minutes of wall clock (234s and 100s, in parallel). The expensive part, the 6-way cross-platform grid with 3 macOS runners, stays gated — this reverses part of #219 narrowly and deliberately, not wholesale. Also established, not changed here: main has no branch protection at all. The only ruleset targets refs/heads/prod and contains no required-status-checks rule, so no check is required anywhere and a red PR can merge into main. That is a policy call, not a workflow fix. Co-authored-by: achebe <hello@rafter.so>
Rome-1
added a commit
that referenced
this pull request
Sep 1, 2026
requests' SessionRedirectMixin.rebuild_auth strips Authorization on a host change and leaves arbitrary custom headers intact; axios/follow-redirects does the same. So `x-api-key` rides a 302 to whatever host it points at. Nothing in this CLI needs to follow a redirect, so nothing does any more. PRE-EXISTING, not introduced by #220. The retry loop added there raises exposure from one transmission to as many as five, which is why it matters more today than it did last week, but it is not the cause. The action's curl paths were never affected — verified, no -L or --location on any of the eight curl invocations in github-action/action.yml. Every authenticated call site, not just the poll path: 14 in Node behind a shared `apiClient` (axios instance, maxRedirects: 0), 13 in Python behind api_get/api_post (allow_redirects forced False, so no call site can opt back in). Deliberately left alone: update-checker's npm registry call and the Slack/Discord webhook posts, none of which carry the key. WHAT THE SECURITY REVIEW CAUGHT, and it would have shipped a broken CLI: API/API_BASE end in "/" and 11 call sites concatenated "/static/...", building https://rafter.so/api//static/scan. Production answers that with a 308 to the single-slash form. It worked only because the client followed the redirect — so refusing redirects turned every core command into a hard failure. Verified against the live API: the double-slash URL 308s, the single-slash one reaches the endpoint. Both runtimes now build URLs through apiUrl()/api_url(), and a test in each fails on any `${API}/` or `{API_BASE}/` construction. Every other test mocks the transport, which is why nothing caught this. Also from that review: - The message told users to point --rafter-url at the final URL. That flag does not exist in the CLI — it is a GitHub Action input. Removed the instruction rather than shipping advice nobody can follow. - A redirect Location is attacker-controlled if the endpoint is. Header values cannot carry CR/LF but ESC is legal, so the raw value could rewrite the user's terminal. Both runtimes strip non-printables and cap at 200 chars, asserted with an ANSI sequence in the fixture. - The source-scanning guards only caught the most literal bypass. They now also match the .request() form and flag any second axios.create() / requests.Session() built outside the api utils. - The Node test shim made axios and apiClient the same mock, so a regression to bare axios would still have passed. create() now returns a distinct object and the tests watch that instance; mutation-tested by reverting one call site to bare axios, which the guard catches. A refused redirect now explains itself instead of surfacing a bare 302. Co-authored-by: achebe <hello@rafter.so>
This was referenced Sep 2, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes the CLI-side half of sable-l10k — an AppSumo customer reported their scan failing in GitHub Actions with:
Reproduced first
Reproduced in a real GitHub Actions run (not locally — the failure is in the poll path after submission, so a local
rafter runproves nothing). The backend was replaced with a localhost mock that injects one transient 500 into an otherwise healthy poll sequence (processing → 500 → completed). The run died on a scan that completed on the very next poll, with the customer's message byte-for-byte.The bug
Every poll path treated any non-2xx as fatal and exited immediately — while the transport-error branch three lines above already retried. A curl-level failure was survivable; an HTTP-level one was not. That asymmetry is the defect.
A report is not durable the instant a scan flips to
completed, so a 5xx there is expected and survivable. It shows up more in CI than locally because CI polls from a different network path.The Python loop was worse: it called
.json()on the 500 body, read no status, fell out of the loop, and wrote the error payload out as if it were results — a silent wrong answer rather than a loud failure.The contract (now in
shared-docs/CLI_SPEC.md)2, unchangedOn giving up, the message names the scan id, the
rafter get <id>retry, and the dashboard.Object not foundsurvives as supporting detail, not as the whole explanation — storage-layer jargon reaching a paying customer is its own defect.Applied identically to
github-action/action.yml(poll loop and results fetch — the results fetch runs the instant status flips to completed, which is the likeliest moment for the object to be unreadable),node/src/commands/backend/scan-status.ts, andpython/rafter_cli/commands/backend.py.Also here, from the security review of this diff
.errorbefore it reaches::error::/::warning::. A response body containing a newline could forge workflow commands (::add-mask::,::stop-commands::). Same class as the pre-existing sinks, but this diff widened it from 2 to 6, so it is fixed here.statusoutput plumbing — the newunreadablestatus was written by the poll step but the action's declared output read only from the results step, which never runs on that path. Consumers saw an empty string. Now falls back to the poll step (this also fixes the same latent bug forfailed/timeout).Two pre-existing issues the review surfaced are filed separately rather than widened here:
sable-2s6p(x-api-keyforwarded across a redirect) andsable-r63p(unsanitizedscan_idwritten to$GITHUB_OUTPUT).Testing
github-action/tests/mock-rafter-api.py— no API key, no credit spend — asserting that a transient 500 is survived and a genuinely missing report still fails the buildpnpm run buildclean; existing backend/scan suites pass; the three action bash unit tests passNote
Root cause of the 500 itself is not addressed here and is likely server-side (
securable/merkleowns the storage path). This is the client-side fix, which stands regardless of where the root cause lands. I could not capture a production report id or raw 500 body — no Rafter API key is available to this agent.