From e4b15efcecd6d2198634c3f307eb55492169af23 Mon Sep 17 00:00:00 2001 From: achebe Date: Mon, 31 Aug 2026 16:58:25 -0700 Subject: [PATCH 1/4] fix: retry transient report-read failures during scan polling (sable-l10k) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 ` 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. --- .github/workflows/test-github-action.yml | 90 +++++++++- github-action/action.yml | 110 +++++++++--- github-action/tests/mock-rafter-api.py | 86 +++++++++ node/src/commands/backend/scan-status.ts | 158 ++++++++++++++--- node/src/utils/api.ts | 6 + node/tests/scan-poll-transient-500.test.ts | 177 +++++++++++++++++++ python/rafter_cli/commands/backend.py | 113 +++++++++++- python/tests/test_scan_poll_transient_500.py | 165 +++++++++++++++++ shared-docs/CLI_SPEC.md | 15 ++ 9 files changed, 863 insertions(+), 57 deletions(-) create mode 100644 github-action/tests/mock-rafter-api.py create mode 100644 node/tests/scan-poll-transient-500.test.ts create mode 100644 python/tests/test_scan_poll_transient_500.py diff --git a/.github/workflows/test-github-action.yml b/.github/workflows/test-github-action.yml index b7836ee7..76e81017 100644 --- a/.github/workflows/test-github-action.yml +++ b/.github/workflows/test-github-action.yml @@ -5,8 +5,9 @@ name: Test github-action/ Composite Action # are pure-bash unit tests of the threshold-eval and PR-comment logic # plus a drift detector on action.yml's load-bearing defaults. # -# An end-to-end test against the real Rafter API is a future addition -# (would require an injectable RAFTER_API_KEY secret and a fixture repo). +# The poll-path jobs DO drive the action end to end, against a localhost mock +# backend (github-action/tests/mock-rafter-api.py) rather than the real API, so +# they need no API key and spend no credits. on: push: branches: @@ -48,6 +49,91 @@ jobs: - name: Run action.yml defaults / drift check run: bash github-action/tests/test-action-yml-defaults.sh + # sable-l10k — a paying customer's run died on a single transient 500 during + # polling ("Failed to fetch report from storage: Object not found"). The + # report is not durable the instant a scan flips to completed, so that 500 is + # survivable and must be retried. These two jobs pin both halves of the + # contract: ride out the transient failure, still fail on a missing report. + test-poll-transient-500: + name: "Poll: rides out a transient 500" + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v4 + + - name: Start mock backend (500 on poll #2, then healthy) + env: + PORT: '8787' + FAIL_ON: '2' + run: | + nohup python3 github-action/tests/mock-rafter-api.py > mock.log 2>&1 & + for _ in $(seq 1 30); do + curl -sf -X POST -d '{}' http://127.0.0.1:8787/api/static/scan >/dev/null && break + sleep 1 + done + + - name: Run the action against the mock + id: scan + continue-on-error: true + uses: ./github-action + with: + api-key: 'not-a-real-key' + rafter-url: 'http://127.0.0.1:8787' + timeout-minutes: '2' + upload-sarif: 'false' + comment-on-pr: 'false' + + - name: Assert the scan survived the 500 + run: | + cat mock.log + echo "status output: '${{ steps.scan.outputs.status }}'" + if [ "${{ steps.scan.outputs.status }}" != "completed" ]; then + echo "FAIL: a single transient 500 during polling killed the run." + exit 1 + fi + echo "PASS: the action retried the transient 500 and completed." + + test-poll-report-never-readable: + name: "Poll: fails clearly when the report is really missing" + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v4 + + - name: Start mock backend (every poll 500s) + env: + PORT: '8788' + FAIL_ON: '2' + FAIL_FOREVER: '1' + run: | + nohup python3 github-action/tests/mock-rafter-api.py > mock.log 2>&1 & + for _ in $(seq 1 30); do + curl -sf -X POST -d '{}' http://127.0.0.1:8788/api/static/scan >/dev/null && break + sleep 1 + done + + - name: Run the action against the mock + id: scan + continue-on-error: true + uses: ./github-action + with: + api-key: 'not-a-real-key' + rafter-url: 'http://127.0.0.1:8788' + timeout-minutes: '2' + upload-sarif: 'false' + comment-on-pr: 'false' + + - name: Assert it failed, and said something actionable + run: | + cat mock.log + if [ "${{ steps.scan.outputs.status }}" = "completed" ]; then + echo "FAIL: an unreadable report was reported as a completed scan." + exit 1 + fi + if [ "${{ steps.scan.outcome }}" != "failure" ]; then + echo "FAIL: an unreadable report should fail the build." + exit 1 + fi + echo "PASS: an unreadable report still fails the build." + test-yaml-validity: name: action.yml is valid YAML runs-on: ubuntu-latest diff --git a/github-action/action.yml b/github-action/action.yml index 32a9b812..61418abd 100644 --- a/github-action/action.yml +++ b/github-action/action.yml @@ -55,8 +55,8 @@ outputs: description: 'Number of low/note findings' value: ${{ steps.results.outputs.low_count }} status: - description: 'Scan status (completed, failed, timeout)' - value: ${{ steps.results.outputs.status }} + description: 'Scan status: completed, failed, timeout, or unreadable (the scan may have finished but its report could not be read)' + value: ${{ steps.results.outputs.status || steps.poll.outputs.status }} runs: using: 'composite' @@ -73,7 +73,8 @@ runs: # We capture body+status separately so future failures self-explain # (instead of just "curl exit 22"). API key never echoed. BODY_FILE="$(mktemp)" - HTTP_CODE=$(curl -sS -o "$BODY_FILE" -w "%{http_code}" -X POST \ + HTTP_CODE=$(curl -sS --connect-timeout 10 --max-time 60 \ + -o "$BODY_FILE" -w "%{http_code}" -X POST \ -H "Content-Type: application/json" \ -H "x-api-key: ${RAFTER_API_KEY}" \ -d "{ @@ -92,7 +93,7 @@ runs: rm -f "$BODY_FILE" if [ "$HTTP_CODE" -lt 200 ] || [ "$HTTP_CODE" -ge 300 ]; then - ERROR=$(echo "$RESPONSE" | jq -r '.error // empty' 2>/dev/null || true) + ERROR=$(echo "$RESPONSE" | jq -r '.error // empty' 2>/dev/null | tr -d '\r\n' | cut -c1-200 || true) echo "::error::Rafter scan trigger failed: HTTP ${HTTP_CODE}" if [ -n "$ERROR" ]; then echo "::error::Server: ${ERROR}" @@ -121,13 +122,29 @@ runs: SCAN_ID: ${{ steps.scan.outputs.scan_id }} TIMEOUT_MINUTES: ${{ inputs.timeout-minutes }} run: | - MAX_POLLS=$(( TIMEOUT_MINUTES * 6 )) # Poll every 10s + # sable-l10k — a report is not durable the instant the scan flips to + # completed, so a poll can legitimately hit a 5xx (in practice + # "Failed to fetch report from storage: Object not found") on a scan + # that is perfectly healthy and readable seconds later. Retry those with + # backoff. Only give up once the failures stop looking transient. + # + # 404 counts as transient HERE and only here: the trigger step already + # handed us a scan_id, so a missing scan mid-poll is read-after-write + # lag rather than a wrong id. + MAX_TRANSIENT_FAILURES=5 + TRANSIENT_FAILURES=0 + LAST_ERROR="" + + # Wall-clock deadline so retry backoff cannot quietly stretch the + # documented timeout-minutes budget. + DEADLINE=$(( $(date +%s) + TIMEOUT_MINUTES * 60 )) POLL_COUNT=0 STATUS="pending" - while [ $POLL_COUNT -lt $MAX_POLLS ]; do + while [ "$(date +%s)" -lt "$DEADLINE" ]; do BODY_FILE="$(mktemp)" - HTTP_CODE=$(curl -sS -o "$BODY_FILE" -w "%{http_code}" \ + HTTP_CODE=$(curl -sS --connect-timeout 10 --max-time 60 \ + -o "$BODY_FILE" -w "%{http_code}" \ -H "x-api-key: ${RAFTER_API_KEY}" \ "${RAFTER_URL}/api/static/scan?scan_id=${SCAN_ID}") || { echo "::warning::curl transport error during poll (will retry)" @@ -140,19 +157,42 @@ runs: RESPONSE=$(cat "$BODY_FILE") rm -f "$BODY_FILE" + if [ "$HTTP_CODE" -ge 500 ] || [ "$HTTP_CODE" -eq 408 ] || [ "$HTTP_CODE" -eq 404 ]; then + ERROR=$(echo "$RESPONSE" | jq -r '.error // empty' 2>/dev/null | tr -d '\r\n' | cut -c1-200 || true) + LAST_ERROR="HTTP ${HTTP_CODE}${ERROR:+ — $ERROR}" + TRANSIENT_FAILURES=$((TRANSIENT_FAILURES+1)) + + if [ "$TRANSIENT_FAILURES" -ge "$MAX_TRANSIENT_FAILURES" ]; then + echo "::error::Rafter could not read the report for scan ${SCAN_ID} after ${MAX_TRANSIENT_FAILURES} attempts." + echo "::error::The scan itself may have finished — check it in your dashboard at ${RAFTER_URL}/dashboard" + echo "::error::Last response from the server: ${LAST_ERROR}" + echo "status=unreadable" >> "$GITHUB_OUTPUT" + exit 1 + fi + + BACKOFF=$(( 2 ** TRANSIENT_FAILURES )) # 2s, 4s, 8s, 16s + echo "::warning::Report not readable yet (${LAST_ERROR}); retrying in ${BACKOFF}s (${TRANSIENT_FAILURES}/${MAX_TRANSIENT_FAILURES})" + sleep "$BACKOFF" + POLL_COUNT=$((POLL_COUNT+1)) + continue + fi + if [ "$HTTP_CODE" -lt 200 ] || [ "$HTTP_CODE" -ge 300 ]; then - ERROR=$(echo "$RESPONSE" | jq -r '.error // empty' 2>/dev/null || true) + # 4xx other than 404/408: a bad key or a malformed request. Retrying + # will not help and would only delay a clear answer. + ERROR=$(echo "$RESPONSE" | jq -r '.error // empty' 2>/dev/null | tr -d '\r\n' | cut -c1-200 || true) echo "::error::Rafter scan poll failed: HTTP ${HTTP_CODE}${ERROR:+ — $ERROR}" exit 1 fi + TRANSIENT_FAILURES=0 STATUS=$(echo "$RESPONSE" | jq -r '.status // "unknown"') if [ "$STATUS" = "completed" ] || [ "$STATUS" = "failed" ]; then break fi - echo "Scan status: ${STATUS} (poll $((POLL_COUNT+1))/${MAX_POLLS})" + echo "Scan status: ${STATUS} (poll $((POLL_COUNT+1)))" sleep 10 POLL_COUNT=$((POLL_COUNT+1)) done @@ -180,23 +220,49 @@ runs: run: | # fetch_results : HTTP-status aware GET that surfaces # server error body on non-2xx (avoids silent curl exit 22 failures). + # + # sable-l10k — same read-after-write race as the poll loop, and worse + # here: this runs the instant the scan reports completed, which is the + # likeliest moment for the report object to not be readable yet. Retry + # transient failures with backoff rather than failing the build. fetch_results() { local out="$1" local url="$2" - local code - code=$(curl -sS -o "$out" -w "%{http_code}" \ - -H "x-api-key: ${RAFTER_API_KEY}" "$url") || { - echo "::error::curl transport error fetching ${url}" - cat "$out" || true + local attempt=1 + local max_attempts=5 + local code body err last="" + + while :; do + if code=$(curl -sS --connect-timeout 10 --max-time 60 \ + -o "$out" -w "%{http_code}" \ + -H "x-api-key: ${RAFTER_API_KEY}" "$url"); then + if [ "$code" -ge 200 ] && [ "$code" -lt 300 ]; then + return 0 + fi + body=$(cat "$out" || true) + err=$(echo "$body" | jq -r '.error // empty' 2>/dev/null | tr -d '\r\n' | cut -c1-200 || true) + last="HTTP ${code}${err:+ — $err}" + if [ "$code" -lt 500 ] && [ "$code" -ne 408 ] && [ "$code" -ne 404 ]; then + # Not transient — a bad key or malformed request. Say so now. + echo "::error::Rafter results fetch failed: ${last}" + return 1 + fi + else + last="curl transport error fetching ${url}" + fi + + if [ "$attempt" -ge "$max_attempts" ]; then + echo "::error::Rafter could not read the report for scan ${SCAN_ID} after ${max_attempts} attempts." + echo "::error::The scan itself finished — check it in your dashboard at ${RAFTER_URL}/dashboard" + echo "::error::Last response from the server: ${last}" return 1 - } - if [ "$code" -lt 200 ] || [ "$code" -ge 300 ]; then - local body err - body=$(cat "$out" || true) - err=$(echo "$body" | jq -r '.error // empty' 2>/dev/null || true) - echo "::error::Rafter results fetch failed: HTTP ${code}${err:+ — $err}" - return 1 - fi + fi + + local backoff=$(( 2 ** attempt )) + echo "::warning::Report not readable yet (${last}); retrying in ${backoff}s (${attempt}/${max_attempts})" + sleep "$backoff" + attempt=$((attempt+1)) + done } fetch_results "${{ runner.temp }}/rafter-results.json" "${RAFTER_URL}/api/static/scan?scan_id=${SCAN_ID}" diff --git a/github-action/tests/mock-rafter-api.py b/github-action/tests/mock-rafter-api.py new file mode 100644 index 00000000..990aac0f --- /dev/null +++ b/github-action/tests/mock-rafter-api.py @@ -0,0 +1,86 @@ +#!/usr/bin/env python3 +"""Minimal stand-in for the Rafter backend, used to reproduce sable-l10k. + +Serves the two endpoints the GitHub Action talks to and injects exactly one +transient 500 into the poll sequence: + + POST /api/static/scan -> 200 {"scan_id": ...} + GET /api/static/scan?scan_id=.. -> poll 1: 200 {"status": "processing"} + poll 2: 500 {"error": "Failed to fetch + report from storage: Object not found"} + poll 3: 200 {"status": "completed", ...} + +A backend that is eventually consistent about report objects looks exactly like +this from the client's side. The question the repro answers is whether the +action survives it. + +Env: + PORT listen port (default 8787) + FAIL_ON 1-based poll index that returns the 500 (default 2) + FAIL_FOREVER if "1", every poll from FAIL_ON onward 500s (persistent case) +""" +import json +import os +from http.server import BaseHTTPRequestHandler, HTTPServer +from urllib.parse import urlparse, parse_qs + +PORT = int(os.environ.get("PORT", "8787")) +FAIL_ON = int(os.environ.get("FAIL_ON", "2")) +FAIL_FOREVER = os.environ.get("FAIL_FOREVER") == "1" + +SCAN_ID = "repro-sable-l10k-0001" + +state = {"polls": 0} + + +class Handler(BaseHTTPRequestHandler): + def _send(self, code, payload): + body = json.dumps(payload).encode() + self.send_response(code) + self.send_header("Content-Type", "application/json") + self.send_header("Content-Length", str(len(body))) + self.end_headers() + self.wfile.write(body) + + def do_POST(self): + if urlparse(self.path).path != "/api/static/scan": + return self._send(404, {"error": "not found"}) + length = int(self.headers.get("Content-Length") or 0) + self.rfile.read(length) + self._send(200, {"scan_id": SCAN_ID}) + + def do_GET(self): + parsed = urlparse(self.path) + if parsed.path != "/api/static/scan": + return self._send(404, {"error": "not found"}) + + qs = parse_qs(parsed.query) + fmt = (qs.get("format") or ["json"])[0] + + state["polls"] += 1 + n = state["polls"] + + if n == FAIL_ON or (FAIL_FOREVER and n >= FAIL_ON): + # The verbatim customer-facing body. + return self._send( + 500, {"error": "Failed to fetch report from storage: Object not found"} + ) + + if n < FAIL_ON: + return self._send(200, {"scan_id": SCAN_ID, "status": "processing"}) + + completed = {"scan_id": SCAN_ID, "status": "completed", "vulnerabilities": []} + if fmt == "md": + completed["markdown"] = "# Rafter\n\nNo findings.\n" + elif fmt == "sarif": + completed = {"version": "2.1.0", "runs": []} + return self._send(200, completed) + + def log_message(self, fmt, *args): + # Keep the runner log readable: one line per request, to stderr. + super().log_message(fmt, *args) + + +if __name__ == "__main__": + print(f"mock rafter api on :{PORT} (500 on poll #{FAIL_ON}, forever={FAIL_FOREVER})", flush=True) + HTTPServer(("127.0.0.1", PORT), Handler).serve_forever() diff --git a/node/src/commands/backend/scan-status.ts b/node/src/commands/backend/scan-status.ts index ea551f20..80f22b80 100644 --- a/node/src/commands/backend/scan-status.ts +++ b/node/src/commands/backend/scan-status.ts @@ -2,14 +2,118 @@ import axios from "axios"; import ora from "ora"; import { API, + API_TIMEOUT_SHORT_MS, writePayload, EXIT_GENERAL_ERROR, EXIT_SCAN_NOT_FOUND } from "../../utils/api.js"; import { fmt as output } from "../../utils/formatter.js"; +/** + * sable-l10k — the report a scan writes is not durable the instant the scan + * flips to completed, so a poll can legitimately hit a 5xx (commonly + * "Failed to fetch report from storage: Object not found") on an otherwise + * healthy scan. Retry those instead of failing the whole run; a scan that + * would have succeeded 10 seconds later must not die on one bad read. + * + * 404 is transient HERE and only here: by the time the poll loop runs we have + * already been handed a scan_id, so a missing scan mid-poll is read-after-write + * lag, not a wrong id. The FIRST poll still treats 404 as fatal. + */ +export const MAX_TRANSIENT_POLL_FAILURES = 5; + +function isTransientPollError(e: any): boolean { + const status = e?.response?.status; + // No response at all: transport error (DNS, reset, timeout). + if (status === undefined) return true; + return status >= 500 || status === 408 || status === 404; +} + +function describeHttpError(e: any): string { + const status = e?.response?.status; + const data = e?.response?.data; + let detail = ""; + if (typeof data === "string") { + detail = data; + } else if (data && typeof data === "object") { + detail = (data as any).error ?? JSON.stringify(data); + } else if (e instanceof Error) { + detail = e.message; + } + return status ? `HTTP ${status}${detail ? ` — ${detail}` : ""}` : detail || String(e); +} + +/** + * The message a customer actually sees when the report never becomes readable. + * Storage-layer wording ("Object not found") is kept as supporting detail, not + * as the whole explanation, and the next action is spelled out. + */ +export function unreadableReportMessage(scan_id: string, lastError: string): string { + return ( + `Rafter could not read the report for scan ${scan_id} after ` + + `${MAX_TRANSIENT_POLL_FAILURES} attempts.\n` + + `The scan itself may have finished — retry with: rafter get ${scan_id}\n` + + `or open the scan in your dashboard at https://rafter.so/dashboard\n` + + `Last response from the server: ${lastError}` + ); +} + +const BASE_BACKOFF_MS = 2000; + +function backoffMs(consecutiveFailures: number): number { + // 2s, 4s, 8s, 16s, 32s + return BASE_BACKOFF_MS * 2 ** (consecutiveFailures - 1); +} + +/** + * Thrown when polling gives up after repeated transient failures. Carries the + * customer-facing message so callers do not have to rebuild it. + */ +export class PollGaveUpError extends Error {} + +/** + * One poll, with retry/backoff over transient failures. + * Non-transient errors are rethrown for the caller to classify. + */ +async function pollUntilReadable( + scan_id: string, + headers: any, + fmt: string, + onRetry?: (attempt: number, waitMs: number, detail: string) => void +): Promise { + let consecutiveFailures = 0; + let lastError = ""; + + for (;;) { + try { + return await axios.get(`${API}/static/scan`, { + params: { scan_id, format: fmt }, + headers, + // Without this a hung server stalls inside a single request, and the + // retry loop can only notice between attempts. + timeout: API_TIMEOUT_SHORT_MS, + }); + } catch (e: any) { + if (!isTransientPollError(e)) throw e; + + consecutiveFailures += 1; + lastError = describeHttpError(e); + + if (consecutiveFailures >= MAX_TRANSIENT_POLL_FAILURES) { + throw new PollGaveUpError(unreadableReportMessage(scan_id, lastError)); + } + + const waitMs = backoffMs(consecutiveFailures); + onRetry?.(consecutiveFailures, waitMs, lastError); + await new Promise((r) => setTimeout(r, waitMs)); + } + } +} + +const IN_PROGRESS = ["queued", "pending", "processing"]; + export async function handleScanStatus(scan_id: string, headers: any, fmt: string, quiet?: boolean): Promise { - // First poll + // First poll. A 404 here really does mean "no such scan" — do not retry it. let poll; try { poll = await axios.get( @@ -26,39 +130,43 @@ export async function handleScanStatus(scan_id: string, headers: any, fmt: strin } let status = poll.data.status; - if (["queued", "pending", "processing"].includes(status)) { - if (!quiet) { - const spinner = ora("Waiting for scan to complete... (this could take several minutes)").start(); - while (["queued", "pending", "processing"].includes(status)) { + if (IN_PROGRESS.includes(status)) { + const spinner = quiet + ? undefined + : ora("Waiting for scan to complete... (this could take several minutes)").start(); + const onRetry = quiet + ? undefined + : (attempt: number, waitMs: number, detail: string) => { + spinner!.text = + `Report not readable yet (${detail}); retrying in ${Math.round(waitMs / 1000)}s ` + + `(${attempt}/${MAX_TRANSIENT_POLL_FAILURES})`; + }; + + try { + while (IN_PROGRESS.includes(status)) { await new Promise((r) => setTimeout(r, 10000)); - poll = await axios.get( - `${API}/static/scan`, - { params: { scan_id, format: fmt }, headers } - ); + poll = await pollUntilReadable(scan_id, headers, fmt, onRetry); status = poll.data.status; if (status === "completed") { - spinner.succeed("Scan completed"); + spinner?.succeed("Scan completed"); return writePayload(poll.data, fmt, quiet); } else if (status === "failed") { - spinner.fail("Scan failed"); + spinner?.fail("Scan failed"); return EXIT_GENERAL_ERROR; } - } - console.error(`Scan status: ${status}`); - } else { - while (["queued", "pending", "processing"].includes(status)) { - await new Promise((r) => setTimeout(r, 10000)); - poll = await axios.get( - `${API}/static/scan`, - { params: { scan_id, format: fmt }, headers } - ); - status = poll.data.status; - if (status === "completed") { - return writePayload(poll.data, fmt, quiet); - } else if (status === "failed") { - return EXIT_GENERAL_ERROR; + if (spinner) { + spinner.text = "Waiting for scan to complete... (this could take several minutes)"; } } + } catch (e: any) { + spinner?.fail("Could not retrieve scan report"); + console.error( + output.error(e instanceof PollGaveUpError ? e.message : describeHttpError(e)) + ); + return EXIT_GENERAL_ERROR; + } + if (!quiet) { + console.error(`Scan status: ${status}`); } } else if (status === "completed") { if (!quiet) { diff --git a/node/src/utils/api.ts b/node/src/utils/api.ts index fef9426a..740431bd 100644 --- a/node/src/utils/api.ts +++ b/node/src/utils/api.ts @@ -8,6 +8,12 @@ export function apiUrl(path: string): string { } // Exit codes +/** + * Read timeout for short-lived API calls (status polls and the like), in ms. + * Mirrors the read half of Python's `API_TIMEOUT_SHORT`. + */ +export const API_TIMEOUT_SHORT_MS = 30_000; + export const EXIT_SUCCESS = 0; export const EXIT_GENERAL_ERROR = 1; export const EXIT_SCAN_NOT_FOUND = 2; diff --git a/node/tests/scan-poll-transient-500.test.ts b/node/tests/scan-poll-transient-500.test.ts new file mode 100644 index 00000000..132a38c3 --- /dev/null +++ b/node/tests/scan-poll-transient-500.test.ts @@ -0,0 +1,177 @@ +import { describe, it, expect, vi, beforeEach, afterEach } from "vitest"; + +/** + * sable-l10k — a paying customer's GitHub Actions run died on + * "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 healthy seconds later. These tests pin + * the contract: transient read failures are retried, genuinely-missing reports + * still fail, and the failure message is one a customer can act on. + */ + +vi.mock("axios"); +vi.mock("ora", () => ({ + default: () => ({ + start: vi.fn().mockReturnThis(), + succeed: vi.fn().mockReturnThis(), + fail: vi.fn().mockReturnThis(), + stop: vi.fn().mockReturnThis(), + text: "", + }), +})); + +import axios from "axios"; +import { + handleScanStatus, + unreadableReportMessage, + MAX_TRANSIENT_POLL_FAILURES, +} from "../src/commands/backend/scan-status.js"; +import { EXIT_SUCCESS, EXIT_GENERAL_ERROR, EXIT_SCAN_NOT_FOUND } from "../src/utils/api.js"; + +const mockedAxios = vi.mocked(axios, true); + +/** The verbatim body the customer saw. */ +const OBJECT_NOT_FOUND = { + response: { status: 500, data: { error: "Failed to fetch report from storage: Object not found" } }, +}; + +function httpError(status: number, error?: string) { + return { response: { status, data: error ? { error } : undefined } }; +} + +describe("handleScanStatus — transient poll failures (sable-l10k)", () => { + const headers = { "x-api-key": "test-key" }; + + beforeEach(() => { + vi.clearAllMocks(); + vi.spyOn(console, "error").mockImplementation(() => {}); + vi.spyOn(process.stdout, "write").mockImplementation(() => true); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + }); + + it("rides out a single 500 mid-poll and completes", async () => { + mockedAxios.get + .mockResolvedValueOnce({ data: { status: "processing" } }) + .mockRejectedValueOnce(OBJECT_NOT_FOUND) + .mockResolvedValueOnce({ data: { status: "completed", markdown: "# Done" } }); + + vi.useFakeTimers(); + const promise = handleScanStatus("s1", headers, "md"); + await vi.advanceTimersByTimeAsync(10000); // poll interval + await vi.advanceTimersByTimeAsync(2000); // first backoff + const code = await promise; + + expect(code).toBe(EXIT_SUCCESS); + expect(mockedAxios.get).toHaveBeenCalledTimes(3); + }); + + it("rides out several consecutive 500s, backing off between them", async () => { + mockedAxios.get + .mockResolvedValueOnce({ data: { status: "processing" } }) + .mockRejectedValueOnce(OBJECT_NOT_FOUND) + .mockRejectedValueOnce(OBJECT_NOT_FOUND) + .mockRejectedValueOnce(OBJECT_NOT_FOUND) + .mockResolvedValueOnce({ data: { status: "completed", markdown: "# Done" } }); + + vi.useFakeTimers(); + const promise = handleScanStatus("s1", headers, "md"); + await vi.advanceTimersByTimeAsync(10000); + await vi.advanceTimersByTimeAsync(2000 + 4000 + 8000); // 3 backoffs + const code = await promise; + + expect(code).toBe(EXIT_SUCCESS); + expect(mockedAxios.get).toHaveBeenCalledTimes(5); + }); + + it("treats a mid-poll 404 as read-after-write lag, not a missing scan", async () => { + mockedAxios.get + .mockResolvedValueOnce({ data: { status: "processing" } }) + .mockRejectedValueOnce(httpError(404)) + .mockResolvedValueOnce({ data: { status: "completed", markdown: "# Done" } }); + + vi.useFakeTimers(); + const promise = handleScanStatus("s1", headers, "md"); + await vi.advanceTimersByTimeAsync(10000); + await vi.advanceTimersByTimeAsync(2000); + const code = await promise; + + expect(code).toBe(EXIT_SUCCESS); + }); + + it("still reports 'not found' when the FIRST poll 404s", async () => { + mockedAxios.get.mockRejectedValueOnce(httpError(404)); + + const code = await handleScanStatus("nope", headers, "md"); + + expect(code).toBe(EXIT_SCAN_NOT_FOUND); + expect(mockedAxios.get).toHaveBeenCalledTimes(1); + }); + + it("gives up when the report never becomes readable", async () => { + mockedAxios.get.mockResolvedValueOnce({ data: { status: "processing" } }); + for (let i = 0; i < MAX_TRANSIENT_POLL_FAILURES; i++) { + mockedAxios.get.mockRejectedValueOnce(OBJECT_NOT_FOUND); + } + + vi.useFakeTimers(); + const promise = handleScanStatus("s1", headers, "md"); + await vi.advanceTimersByTimeAsync(10000); + await vi.advanceTimersByTimeAsync(2000 + 4000 + 8000 + 16000); + const code = await promise; + + expect(code).toBe(EXIT_GENERAL_ERROR); + // One in-progress poll plus exactly the allowed number of retries. + expect(mockedAxios.get).toHaveBeenCalledTimes(1 + MAX_TRANSIENT_POLL_FAILURES); + }); + + it("does not retry a non-transient error (403)", async () => { + mockedAxios.get + .mockResolvedValueOnce({ data: { status: "processing" } }) + .mockRejectedValueOnce(httpError(403, "Invalid API key")); + + vi.useFakeTimers(); + const promise = handleScanStatus("s1", headers, "md"); + await vi.advanceTimersByTimeAsync(10000); + const code = await promise; + + expect(code).toBe(EXIT_GENERAL_ERROR); + expect(mockedAxios.get).toHaveBeenCalledTimes(2); + }); + + it("retries transport errors that carry no HTTP response", async () => { + mockedAxios.get + .mockResolvedValueOnce({ data: { status: "processing" } }) + .mockRejectedValueOnce(new Error("ECONNRESET")) + .mockResolvedValueOnce({ data: { status: "completed", markdown: "# Done" } }); + + vi.useFakeTimers(); + const promise = handleScanStatus("s1", headers, "md"); + await vi.advanceTimersByTimeAsync(10000); + await vi.advanceTimersByTimeAsync(2000); + const code = await promise; + + expect(code).toBe(EXIT_SUCCESS); + }); +}); + +describe("unreadableReportMessage", () => { + it("gives the customer the scan id and a next step, not just storage jargon", () => { + const msg = unreadableReportMessage( + "scan-abc", + "HTTP 500 — Failed to fetch report from storage: Object not found" + ); + + expect(msg).toContain("scan-abc"); + expect(msg).toContain("rafter get scan-abc"); + expect(msg).toContain("dashboard"); + // The raw server wording survives as supporting detail... + expect(msg).toContain("Object not found"); + // ...but is not the whole message. + expect(msg.split("\n").length).toBeGreaterThan(1); + }); +}); diff --git a/python/rafter_cli/commands/backend.py b/python/rafter_cli/commands/backend.py index ea988cae..12ae30cb 100644 --- a/python/rafter_cli/commands/backend.py +++ b/python/rafter_cli/commands/backend.py @@ -88,6 +88,104 @@ def _confirm_plus_scan(mode: str, yes: bool) -> None: raise typer.Exit(code=EXIT_CONFIRMATION_REQUIRED) +# sable-l10k — the report a scan writes is not durable the instant the scan +# flips to completed, so a poll can legitimately hit a 5xx (commonly +# "Failed to fetch report from storage: Object not found") on an otherwise +# healthy scan. Retry those instead of failing the whole run; a scan that would +# have succeeded 10 seconds later must not die on one bad read. +MAX_TRANSIENT_POLL_FAILURES = 5 +_BASE_BACKOFF_SECONDS = 2 + +IN_PROGRESS = ("queued", "pending", "processing") + + +class PollGaveUpError(RuntimeError): + """Polling gave up after repeated transient failures. + + Carries the customer-facing message so callers need not rebuild it. + """ + + +def _is_transient_poll_status(status_code: int) -> bool: + """404 is transient HERE and only here. + + By the time the poll loop runs we have already been handed a ``scan_id``, so + a missing scan mid-poll is read-after-write lag, not a wrong id. The FIRST + poll still treats 404 as fatal. + """ + return status_code >= 500 or status_code in (404, 408) + + +def _describe_http_error(status_code: int, body: str) -> str: + detail = body + try: + parsed = json.loads(body) + if isinstance(parsed, dict): + detail = parsed.get("error") or body + except (ValueError, TypeError): + pass + detail = (detail or "").strip() + return f"HTTP {status_code}" + (f" — {detail}" if detail else "") + + +def unreadable_report_message(scan_id: str, last_error: str) -> str: + """The message a customer actually sees when the report never becomes readable. + + Storage-layer wording ("Object not found") is kept as supporting detail, not + as the whole explanation, and the next action is spelled out. + """ + return ( + f"Rafter could not read the report for scan {scan_id} after " + f"{MAX_TRANSIENT_POLL_FAILURES} attempts.\n" + f"The scan itself may have finished — retry with: rafter get {scan_id}\n" + f"or open the scan in your dashboard at https://rafter.so/dashboard\n" + f"Last response from the server: {last_error}" + ) + + +def _poll_until_readable(scan_id: str, headers: dict, fmt: str, quiet: bool): + """One poll, retrying transient failures with exponential backoff. + + Returns the successful response. Raises ``PollGaveUpError`` once the + transient failures stop looking transient, and re-raises anything else. + """ + consecutive_failures = 0 + last_error = "" + + while True: + try: + resp = requests.get( + f"{API_BASE}/static/scan", + headers=headers, + params={"scan_id": scan_id, "format": fmt}, + timeout=API_TIMEOUT_SHORT, + ) + transient = _is_transient_poll_status(resp.status_code) + if resp.status_code == 200: + return resp + if not transient: + raise PollGaveUpError( + _describe_http_error(resp.status_code, resp.text) + ) + last_error = _describe_http_error(resp.status_code, resp.text) + except requests.RequestException as e: + # Transport error (DNS, reset, timeout) — as retryable as a 5xx. + last_error = str(e) + + consecutive_failures += 1 + if consecutive_failures >= MAX_TRANSIENT_POLL_FAILURES: + raise PollGaveUpError(unreadable_report_message(scan_id, last_error)) + + wait = _BASE_BACKOFF_SECONDS * 2 ** (consecutive_failures - 1) + if not quiet: + print( + f"Report not readable yet ({last_error}); retrying in {wait}s " + f"({consecutive_failures}/{MAX_TRANSIENT_POLL_FAILURES})", + file=sys.stderr, + ) + time.sleep(wait) + + def _handle_scan_status_interactive( scan_id: str, headers: dict, fmt: str, quiet: bool ) -> int: @@ -108,20 +206,19 @@ def _handle_scan_status_interactive( data = poll.json() status = data.get("status") - if status in ("queued", "pending", "processing"): + if status in IN_PROGRESS: if not quiet: print( "Waiting for scan to complete... (this could take several minutes)", file=sys.stderr, ) - while status in ("queued", "pending", "processing"): + while status in IN_PROGRESS: time.sleep(10) - poll = requests.get( - f"{API_BASE}/static/scan", - headers=headers, - params={"scan_id": scan_id, "format": fmt}, - timeout=API_TIMEOUT_SHORT, - ) + try: + poll = _poll_until_readable(scan_id, headers, fmt, quiet) + except PollGaveUpError as e: + print(f"Error: {e}", file=sys.stderr) + raise typer.Exit(code=EXIT_GENERAL_ERROR) data = poll.json() status = data.get("status") if status == "completed": diff --git a/python/tests/test_scan_poll_transient_500.py b/python/tests/test_scan_poll_transient_500.py new file mode 100644 index 00000000..5e36a0b6 --- /dev/null +++ b/python/tests/test_scan_poll_transient_500.py @@ -0,0 +1,165 @@ +"""sable-l10k — transient poll failures must not kill a healthy scan. + +A paying customer's GitHub Actions run died on: + "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. These tests pin the +contract: transient read failures are retried, genuinely-missing reports still +fail, and the failure message is one a customer can act on. + +Mirrors node/tests/scan-poll-transient-500.test.ts. +""" +from __future__ import annotations + +import json +from unittest.mock import MagicMock, patch + +import pytest +import requests +import typer + +from rafter_cli.commands.backend import ( + MAX_TRANSIENT_POLL_FAILURES, + _handle_scan_status_interactive, + unreadable_report_message, +) +from rafter_cli.utils.api import EXIT_GENERAL_ERROR, EXIT_SCAN_NOT_FOUND, EXIT_SUCCESS + +OBJECT_NOT_FOUND_BODY = json.dumps( + {"error": "Failed to fetch report from storage: Object not found"} +) + +HEADERS = {"x-api-key": "test-key"} + + +def _resp(status_code: int, text: str = "", json_body=None) -> MagicMock: + resp = MagicMock() + resp.status_code = status_code + resp.text = text + resp.json.return_value = json_body if json_body is not None else {} + return resp + + +def _processing() -> MagicMock: + return _resp(200, json_body={"status": "processing"}) + + +def _completed() -> MagicMock: + return _resp(200, json_body={"status": "completed", "markdown": "# Done"}) + + +def _server_500() -> MagicMock: + return _resp(500, text=OBJECT_NOT_FOUND_BODY) + + +@pytest.fixture(autouse=True) +def _no_sleep(): + """Backoff is real time; tests should not pay for it.""" + with patch("rafter_cli.commands.backend.time.sleep"): + yield + + +class TestTransientPollFailures: + def test_rides_out_a_single_500_and_completes(self, capsys): + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_processing(), _server_500(), _completed()] + code = _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert code == EXIT_SUCCESS + assert get.call_count == 3 + + def test_rides_out_several_consecutive_500s(self): + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [ + _processing(), + _server_500(), + _server_500(), + _server_500(), + _completed(), + ] + code = _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert code == EXIT_SUCCESS + assert get.call_count == 5 + + def test_midpoll_404_is_lag_not_a_missing_scan(self): + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_processing(), _resp(404, text="{}"), _completed()] + code = _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert code == EXIT_SUCCESS + + def test_first_poll_404_still_reports_not_found(self): + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_resp(404, text="{}")] + with pytest.raises(typer.Exit) as exc: + _handle_scan_status_interactive("nope", HEADERS, "md", quiet=True) + + assert exc.value.exit_code == EXIT_SCAN_NOT_FOUND + assert get.call_count == 1 + + def test_gives_up_when_report_never_becomes_readable(self, capsys): + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_processing()] + [ + _server_500() for _ in range(MAX_TRANSIENT_POLL_FAILURES) + ] + with pytest.raises(typer.Exit) as exc: + _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert exc.value.exit_code == EXIT_GENERAL_ERROR + assert get.call_count == 1 + MAX_TRANSIENT_POLL_FAILURES + + err = capsys.readouterr().err + assert "rafter get s1" in err + assert "Object not found" in err + + def test_does_not_retry_a_non_transient_error(self): + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [ + _processing(), + _resp(403, text=json.dumps({"error": "Invalid API key"})), + ] + with pytest.raises(typer.Exit) as exc: + _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert exc.value.exit_code == EXIT_GENERAL_ERROR + assert get.call_count == 2 + + def test_retries_transport_errors(self): + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [ + _processing(), + requests.ConnectionError("ECONNRESET"), + _completed(), + ] + code = _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert code == EXIT_SUCCESS + + def test_a_500_body_is_never_mistaken_for_a_report(self): + """The pre-fix bug: the loop called .json() on the 500 body, got no + status, fell out of the loop and wrote the error payload out as if it + were results.""" + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_processing()] + [ + _server_500() for _ in range(MAX_TRANSIENT_POLL_FAILURES) + ] + with pytest.raises(typer.Exit): + _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + +class TestUnreadableReportMessage: + def test_gives_scan_id_and_a_next_step(self): + msg = unreadable_report_message( + "scan-abc", + "HTTP 500 — Failed to fetch report from storage: Object not found", + ) + + assert "scan-abc" in msg + assert "rafter get scan-abc" in msg + assert "dashboard" in msg + # The raw server wording survives as supporting detail... + assert "Object not found" in msg + # ...but is not the whole message. + assert len(msg.splitlines()) > 1 diff --git a/shared-docs/CLI_SPEC.md b/shared-docs/CLI_SPEC.md index fd01fb5a..cfbcdeb9 100644 --- a/shared-docs/CLI_SPEC.md +++ b/shared-docs/CLI_SPEC.md @@ -126,6 +126,21 @@ Retrieve results from a scan. **Vulnerability levels (JSON output):** The `level` field on each vulnerability uses SARIF standard values: `"error"`, `"warning"`, or `"note"`. +#### Poll-loop retry contract + +Once polling has begun (`rafter run` without `--skip-interactive`, or `rafter get --interactive`), a scan_id is known to exist, and a report is not necessarily durable the instant a scan flips to `completed`. Both runtimes therefore retry transient read failures instead of aborting the run: + +| Condition during polling | Behavior | +|--------------------------|----------| +| HTTP 5xx, 408, or 404 | Transient. Retried up to **5 consecutive times** with exponential backoff (2s, 4s, 8s, 16s). The counter resets on any successful poll. | +| Transport error (DNS, reset, timeout) | Same as above. | +| Other 4xx (401/403/429 …) | Not retried — reported immediately. | +| 404 on the **first** poll | Not retried — the scan genuinely does not exist. Exit code `2`. | + +After 5 consecutive transient failures the command exits `1` with a message naming the scan id, the `rafter get ` retry command, and the dashboard, with the raw server response as supporting detail. Raw storage-layer wording is never the whole message. + +The composite GitHub Action (`github-action/action.yml`) implements the same contract in its poll loop and its results fetch. + ### rafter usage [OPTIONS] Check API quota and usage statistics. From 26262d24af65363f6524909bd39e1e662ee399d5 Mon Sep 17 00:00:00 2001 From: achebe Date: Mon, 31 Aug 2026 17:05:59 -0700 Subject: [PATCH 2/4] test: restore real timers inside each test (Node 18 afterEach hang) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- node/tests/scan-poll-transient-500.test.ts | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/node/tests/scan-poll-transient-500.test.ts b/node/tests/scan-poll-transient-500.test.ts index 132a38c3..405c11d4 100644 --- a/node/tests/scan-poll-transient-500.test.ts +++ b/node/tests/scan-poll-transient-500.test.ts @@ -50,6 +50,8 @@ describe("handleScanStatus — transient poll failures (sable-l10k)", () => { }); afterEach(() => { + // Belt and braces: every test restores real timers itself (see above), but + // a failing assertion can skip that line. vi.useRealTimers(); vi.restoreAllMocks(); }); @@ -65,6 +67,7 @@ describe("handleScanStatus — transient poll failures (sable-l10k)", () => { await vi.advanceTimersByTimeAsync(10000); // poll interval await vi.advanceTimersByTimeAsync(2000); // first backoff const code = await promise; + vi.useRealTimers(); expect(code).toBe(EXIT_SUCCESS); expect(mockedAxios.get).toHaveBeenCalledTimes(3); @@ -83,6 +86,7 @@ describe("handleScanStatus — transient poll failures (sable-l10k)", () => { await vi.advanceTimersByTimeAsync(10000); await vi.advanceTimersByTimeAsync(2000 + 4000 + 8000); // 3 backoffs const code = await promise; + vi.useRealTimers(); expect(code).toBe(EXIT_SUCCESS); expect(mockedAxios.get).toHaveBeenCalledTimes(5); @@ -99,6 +103,7 @@ describe("handleScanStatus — transient poll failures (sable-l10k)", () => { await vi.advanceTimersByTimeAsync(10000); await vi.advanceTimersByTimeAsync(2000); const code = await promise; + vi.useRealTimers(); expect(code).toBe(EXIT_SUCCESS); }); @@ -123,6 +128,7 @@ describe("handleScanStatus — transient poll failures (sable-l10k)", () => { await vi.advanceTimersByTimeAsync(10000); await vi.advanceTimersByTimeAsync(2000 + 4000 + 8000 + 16000); const code = await promise; + vi.useRealTimers(); expect(code).toBe(EXIT_GENERAL_ERROR); // One in-progress poll plus exactly the allowed number of retries. @@ -138,6 +144,7 @@ describe("handleScanStatus — transient poll failures (sable-l10k)", () => { const promise = handleScanStatus("s1", headers, "md"); await vi.advanceTimersByTimeAsync(10000); const code = await promise; + vi.useRealTimers(); expect(code).toBe(EXIT_GENERAL_ERROR); expect(mockedAxios.get).toHaveBeenCalledTimes(2); @@ -154,6 +161,7 @@ describe("handleScanStatus — transient poll failures (sable-l10k)", () => { await vi.advanceTimersByTimeAsync(10000); await vi.advanceTimersByTimeAsync(2000); const code = await promise; + vi.useRealTimers(); expect(code).toBe(EXIT_SUCCESS); }); From 71ea09a4ddbf1c05848d4d16f6a31a51e3b9b764 Mon Sep 17 00:00:00 2001 From: achebe Date: Mon, 31 Aug 2026 17:49:53 -0700 Subject: [PATCH 3/4] fix: address adversarial review of the poll-retry change (sable-l10k) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 ", 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. --- .github/workflows/test-github-action.yml | 103 ++++++++++- CHANGELOG.md | 13 ++ github-action/action.yml | 43 ++++- github-action/tests/mock-rafter-api.py | 27 ++- .../tests/test-action-yml-defaults.sh | 67 +++++++ node/src/commands/backend/scan-status.ts | 151 +++++++++++----- node/tests/scan-poll-transient-500.test.ts | 131 +++++++++++++- node/tests/scan-remote.test.ts | 9 +- python/rafter_cli/commands/backend.py | 169 +++++++++++++----- python/tests/test_scan_poll_transient_500.py | 94 +++++++++- shared-docs/CLI_SPEC.md | 17 +- 11 files changed, 709 insertions(+), 115 deletions(-) diff --git a/.github/workflows/test-github-action.yml b/.github/workflows/test-github-action.yml index 76e81017..38875523 100644 --- a/.github/workflows/test-github-action.yml +++ b/.github/workflows/test-github-action.yml @@ -121,18 +121,111 @@ jobs: upload-sarif: 'false' comment-on-pr: 'false' - - name: Assert it failed, and said something actionable + - name: Assert it failed, with the right status run: | cat mock.log - if [ "${{ steps.scan.outputs.status }}" = "completed" ]; then - echo "FAIL: an unreadable report was reported as a completed scan." - exit 1 + FAIL=0 + if [ "${{ steps.scan.outputs.status }}" != "unreadable" ]; then + echo "FAIL: expected status=unreadable, got '${{ steps.scan.outputs.status }}'" + FAIL=1 fi if [ "${{ steps.scan.outcome }}" != "failure" ]; then echo "FAIL: an unreadable report should fail the build." + FAIL=1 + fi + # A composite action's log is not capturable from the calling step, + # so the CONTENT of the give-up message is asserted by the drift + # detector (github-action/tests/test-action-yml-defaults.sh) instead. + exit $FAIL + + # The 404-as-transient branch is the subtlest thing in the poll loop: it is + # correct only because the trigger step has already handed us a scan_id. + # Nothing else in CI exercises it, so a "simplification" that drops `-eq 404` + # from the transient condition would otherwise land green. + test-poll-transient-404: + name: "Poll: rides out a transient 404" + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v4 + + - name: Start mock backend (404 on poll #2, then healthy) + env: + PORT: '8789' + FAIL_ON: '2' + FAIL_STATUS: '404' + run: | + nohup python3 github-action/tests/mock-rafter-api.py > mock.log 2>&1 & + for _ in $(seq 1 30); do + curl -sf -X POST -d '{}' http://127.0.0.1:8789/api/static/scan >/dev/null && break + sleep 1 + done + curl -sf -X POST -d '{}' http://127.0.0.1:8789/api/static/scan >/dev/null || { + echo "FAIL: mock backend never started"; cat mock.log; exit 1; } + + - name: Run the action against the mock + id: scan + continue-on-error: true + uses: ./github-action + with: + api-key: 'not-a-real-key' + rafter-url: 'http://127.0.0.1:8789' + timeout-minutes: '2' + upload-sarif: 'false' + comment-on-pr: 'false' + + - name: Assert the scan survived the 404 + run: | + cat mock.log + if [ "${{ steps.scan.outputs.status }}" != "completed" ]; then + echo "FAIL: a transient 404 mid-poll killed the run." + exit 1 + fi + echo "PASS: the action treated a mid-poll 404 as read-after-write lag." + + # The results fetch runs the instant the scan reports completed — the + # likeliest moment for the report object to be unreadable. Its retry loop had + # no coverage at all, and it is where a failed read used to be reported to + # consumers as status=completed. + test-results-fetch-transient-500: + name: "Results fetch: rides out a transient 500" + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v4 + + - name: Start mock backend (poll succeeds, first results fetch 500s) + env: + PORT: '8790' + FAIL_ON: '2' + FAIL_COUNT: '1' + COMPLETE_AFTER: '1' + run: | + nohup python3 github-action/tests/mock-rafter-api.py > mock.log 2>&1 & + for _ in $(seq 1 30); do + curl -sf -X POST -d '{}' http://127.0.0.1:8790/api/static/scan >/dev/null && break + sleep 1 + done + curl -sf -X POST -d '{}' http://127.0.0.1:8790/api/static/scan >/dev/null || { + echo "FAIL: mock backend never started"; cat mock.log; exit 1; } + + - name: Run the action against the mock + id: scan + continue-on-error: true + uses: ./github-action + with: + api-key: 'not-a-real-key' + rafter-url: 'http://127.0.0.1:8790' + timeout-minutes: '2' + upload-sarif: 'false' + comment-on-pr: 'false' + + - name: Assert the results fetch retried rather than failing the build + run: | + cat mock.log + if [ "${{ steps.scan.outputs.status }}" != "completed" ]; then + echo "FAIL: a transient 500 on the results fetch killed the run (status='${{ steps.scan.outputs.status }}')." exit 1 fi - echo "PASS: an unreadable report still fails the build." + echo "PASS: the results fetch retried and completed." test-yaml-validity: name: action.yml is valid YAML diff --git a/CHANGELOG.md b/CHANGELOG.md index 3f5b87fa..94b494a2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,19 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Fixed + +- **A transient 500 during scan polling no longer kills the run** (sable-l10k). An AppSumo customer's GitHub Actions build died on `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 5xx on that read is survivable — but every poll path treated any non-2xx as fatal, while the transport-error branch three lines above already retried. All three surfaces (the composite action, `rafter run`, `rafter get --interactive`) now retry transient failures with exponential backoff (2s/4s/8s/16s) before giving up, and the give-up message names the scan id, the `rafter get ` retry, and the dashboard instead of leaking storage-layer wording. Full contract in `shared-docs/CLI_SPEC.md`. Both runtimes; end-to-end CI coverage against a mock backend, so no API key or credits are needed to exercise it. +- **Python: a failed poll could be written out as if it were scan results** (sable-l10k). The mid-poll loop called `.json()` on the response without checking the status code, so a 500 carrying a JSON error body parsed cleanly, yielded no `status`, fell out of the loop, and was emitted as the scan payload with exit code `0`. A non-JSON error body raised an unhandled `JSONDecodeError`. Both now fail loudly. **Behavior change:** genuine non-transient mid-poll failures that previously exited `0` with an error payload on stdout now exit `1` — check any pipeline that consumed that output. +- **GitHub Action: a failed results fetch reported the scan as `completed`** (sable-l10k). The declared `status` output read only from the results step, which does not run when the fetch fails. Consumers gating on `status == 'completed'` saw a clean scan, and the artifact upload published the error body as `rafter-results.json`. Both give-up paths in the results fetch now record `status=unreadable`, and the artifact upload is gated on a successful results fetch. +- **GitHub Action: server-controlled error text is sanitized before it reaches workflow commands** (sable-l10k). A response body containing a newline could forge `::error::`, `::add-mask::`, or `::stop-commands::` annotations. Error text from the API is now stripped of newlines and length-capped at every `::error::`/`::warning::` site. +- **GitHub Action: an unreachable API is reported as unreachable** (sable-l10k). Transport errors retried on a flat 10s interval without counting toward the failure budget, so a bad `rafter-url` or a down backend burned the whole `timeout-minutes` window and then reported `Scan did not complete within N minutes` — a timeout message for a DNS failure. They now share the same retry budget and exit with `status=unreachable`. + +### Changed + +- **`timeout-minutes` on the GitHub Action is now a wall-clock deadline**, not a poll count. Previously the action ran `timeout-minutes * 6` polls, each costing 10s *plus* API latency, so a slow API pushed real elapsed time past the documented budget. It is now enforced as a real deadline. **This can fail workflows that were relying on the overrun** — if a scan sits near the boundary, raise `timeout-minutes`. +- HTTP requests on the poll and results paths now carry connect/read timeouts (`--connect-timeout 10 --max-time 60` for curl, 30s for axios), so a hung server cannot stall inside a request that the retry loop only checks between attempts. + ## [0.10.0] - 2026-07-29 ### Added diff --git a/github-action/action.yml b/github-action/action.yml index 61418abd..df2a1402 100644 --- a/github-action/action.yml +++ b/github-action/action.yml @@ -27,7 +27,7 @@ inputs: required: false default: 'true' timeout-minutes: - description: 'Maximum time to wait for scan completion (minutes)' + description: 'Maximum wall-clock time to wait for scan completion (minutes). Enforced as a real deadline: before v0.11 this was a poll COUNT, so a slow API could overrun it.' required: false default: '10' rafter-url: @@ -55,7 +55,7 @@ outputs: description: 'Number of low/note findings' value: ${{ steps.results.outputs.low_count }} status: - description: 'Scan status: completed, failed, timeout, or unreadable (the scan may have finished but its report could not be read)' + description: 'Scan status: completed, failed, timeout, unreadable (the scan may have finished but its report could not be read), or unreachable (the Rafter API could not be contacted)' value: ${{ steps.results.outputs.status || steps.poll.outputs.status }} runs: @@ -98,14 +98,14 @@ runs: if [ -n "$ERROR" ]; then echo "::error::Server: ${ERROR}" else - echo "Server response: ${RESPONSE}" + echo "Server response: $(printf '%s' "$RESPONSE" | tr -d '\r\n' | cut -c1-500)" fi exit 1 fi SCAN_ID=$(echo "$RESPONSE" | jq -r '.scan_id // empty') if [ -z "$SCAN_ID" ]; then - ERROR=$(echo "$RESPONSE" | jq -r '.error // "Unknown error triggering scan"') + ERROR=$(echo "$RESPONSE" | jq -r '.error // "Unknown error triggering scan"' | tr -d '\r\n' | cut -c1-200) echo "::error::Failed to trigger scan (HTTP ${HTTP_CODE}): ${ERROR}" exit 1 fi @@ -131,6 +131,13 @@ runs: # 404 counts as transient HERE and only here: the trigger step already # handed us a scan_id, so a missing scan mid-poll is read-after-write # lag rather than a wrong id. + case "$TIMEOUT_MINUTES" in + ''|*[!0-9]*) + echo "::error::timeout-minutes must be a whole number of minutes, got '${TIMEOUT_MINUTES}'" + exit 1 + ;; + esac + MAX_TRANSIENT_FAILURES=5 TRANSIENT_FAILURES=0 LAST_ERROR="" @@ -147,10 +154,23 @@ runs: -o "$BODY_FILE" -w "%{http_code}" \ -H "x-api-key: ${RAFTER_API_KEY}" \ "${RAFTER_URL}/api/static/scan?scan_id=${SCAN_ID}") || { - echo "::warning::curl transport error during poll (will retry)" - cat "$BODY_FILE" || true + # A transport error is exactly as transient as a 5xx, and counts + # the same. Previously it retried on a flat 10s forever, which + # meant an unreachable backend reported "scan did not complete + # within N minutes" — a timeout message for a DNS failure. rm -f "$BODY_FILE" - sleep 10 + LAST_ERROR="curl transport error contacting ${RAFTER_URL}" + TRANSIENT_FAILURES=$((TRANSIENT_FAILURES+1)) + if [ "$TRANSIENT_FAILURES" -ge "$MAX_TRANSIENT_FAILURES" ]; then + echo "::error::Rafter could not reach the API for scan ${SCAN_ID} after ${MAX_TRANSIENT_FAILURES} attempts." + echo "::error::Check that ${RAFTER_URL} is reachable from this runner." + echo "::error::Last error: ${LAST_ERROR}" + echo "status=unreachable" >> "$GITHUB_OUTPUT" + exit 1 + fi + BACKOFF=$(( 2 ** TRANSIENT_FAILURES )) + echo "::warning::${LAST_ERROR}; retrying in ${BACKOFF}s (${TRANSIENT_FAILURES}/${MAX_TRANSIENT_FAILURES})" + sleep "$BACKOFF" POLL_COUNT=$((POLL_COUNT+1)) continue } @@ -192,7 +212,7 @@ runs: break fi - echo "Scan status: ${STATUS} (poll $((POLL_COUNT+1)))" + echo "Scan status: ${STATUS} (poll $((POLL_COUNT+1)), $(( (DEADLINE - $(date +%s)) / 60 ))m of ${TIMEOUT_MINUTES}m budget left)" sleep 10 POLL_COUNT=$((POLL_COUNT+1)) done @@ -245,6 +265,7 @@ runs: if [ "$code" -lt 500 ] && [ "$code" -ne 408 ] && [ "$code" -ne 404 ]; then # Not transient — a bad key or malformed request. Say so now. echo "::error::Rafter results fetch failed: ${last}" + echo "status=unreadable" >> "$GITHUB_OUTPUT" return 1 fi else @@ -255,6 +276,10 @@ runs: echo "::error::Rafter could not read the report for scan ${SCAN_ID} after ${max_attempts} attempts." echo "::error::The scan itself finished — check it in your dashboard at ${RAFTER_URL}/dashboard" echo "::error::Last response from the server: ${last}" + # Without this the declared `status` output falls back to the poll + # step, which already said `completed` — a failed report read would + # be reported to consumers as a clean scan. + echo "status=unreadable" >> "$GITHUB_OUTPUT" return 1 fi @@ -363,7 +388,7 @@ runs: gh pr comment "${{ github.event.pull_request.number }}" --body-file "$COMMENT_FILE" - name: Upload artifacts - if: always() && steps.poll.outputs.status == 'completed' + if: steps.results.outputs.status == 'completed' uses: actions/upload-artifact@v4 with: name: rafter-security-results diff --git a/github-action/tests/mock-rafter-api.py b/github-action/tests/mock-rafter-api.py index 990aac0f..2b77ab97 100644 --- a/github-action/tests/mock-rafter-api.py +++ b/github-action/tests/mock-rafter-api.py @@ -15,9 +15,17 @@ action survives it. Env: - PORT listen port (default 8787) - FAIL_ON 1-based poll index that returns the 500 (default 2) - FAIL_FOREVER if "1", every poll from FAIL_ON onward 500s (persistent case) + PORT listen port (default 8787) + FAIL_ON 1-based GET index that starts failing (default 2) + FAIL_STATUS status code to fail with (default 500; 404 exercises the + read-after-write-lag branch) + FAIL_FOREVER if "1", every GET from FAIL_ON onward fails (persistent case) + FAIL_COUNT how many consecutive GETs fail starting at FAIL_ON (default 1; + ignored when FAIL_FOREVER is set) + COMPLETE_AFTER GET index from which status is "completed" (default FAIL_ON, + i.e. as soon as the injected failures are done). Set it higher + than the failure window to make the RESULTS fetch fail rather + than the poll. """ import json import os @@ -26,7 +34,10 @@ PORT = int(os.environ.get("PORT", "8787")) FAIL_ON = int(os.environ.get("FAIL_ON", "2")) +FAIL_STATUS = int(os.environ.get("FAIL_STATUS", "500")) FAIL_FOREVER = os.environ.get("FAIL_FOREVER") == "1" +FAIL_COUNT = int(os.environ.get("FAIL_COUNT", "1")) +COMPLETE_AFTER = int(os.environ.get("COMPLETE_AFTER", str(FAIL_ON))) SCAN_ID = "repro-sable-l10k-0001" @@ -60,13 +71,17 @@ def do_GET(self): state["polls"] += 1 n = state["polls"] - if n == FAIL_ON or (FAIL_FOREVER and n >= FAIL_ON): + failing = (FAIL_FOREVER and n >= FAIL_ON) or ( + FAIL_ON <= n < FAIL_ON + FAIL_COUNT + ) + if failing: # The verbatim customer-facing body. return self._send( - 500, {"error": "Failed to fetch report from storage: Object not found"} + FAIL_STATUS, + {"error": "Failed to fetch report from storage: Object not found"}, ) - if n < FAIL_ON: + if n < COMPLETE_AFTER: return self._send(200, {"scan_id": SCAN_ID, "status": "processing"}) completed = {"scan_id": SCAN_ID, "status": "completed", "vulnerabilities": []} diff --git a/github-action/tests/test-action-yml-defaults.sh b/github-action/tests/test-action-yml-defaults.sh index 084748e6..8e00bf63 100755 --- a/github-action/tests/test-action-yml-defaults.sh +++ b/github-action/tests/test-action-yml-defaults.sh @@ -66,6 +66,73 @@ else echo "PASS: 'none' branch of threshold-eval does not set FAIL=1" fi +# ── sable-l10k: poll-path retry contract ───────────────────────────────── +# These properties are subtle and cheap to "simplify" away. Each one, if +# dropped, reproduces a bug a paying customer already hit. + +# 5. 404 must be in the poll loop's TRANSIENT condition. It is safe only +# because the trigger step already handed us a scan_id, so a missing scan +# mid-poll is read-after-write lag rather than a wrong id. +if grep -qE '\$HTTP_CODE" -ge 500 \] \|\| \[ "\$HTTP_CODE" -eq 408 \] \|\| \[ "\$HTTP_CODE" -eq 404' "$ACTION_YML"; then + echo "PASS: poll loop treats 5xx/408/404 as transient" +else + echo "FAIL: poll loop's transient condition changed — 404/408/5xx must all retry" + failures=$((failures+1)) +fi + +# 6. A transport error must count toward the SAME failure budget as a 5xx. +# When it did not, an unreachable backend reported "scan did not complete +# within N minutes" — a timeout message for a DNS failure. +if awk '/curl transport error contacting/,/^ \}/' "$ACTION_YML" \ + | grep -q 'TRANSIENT_FAILURES=\$((TRANSIENT_FAILURES+1))'; then + echo "PASS: transport errors count toward the transient-failure budget" +else + echo "FAIL: poll loop's transport-error branch no longer counts toward the budget" + failures=$((failures+1)) +fi + +# 7. The give-up message must be actionable: name the scan, and offer a next +# step. Raw storage wording ("Object not found") alone is not a message a +# customer can act on. +if grep -q 'could not read the report for scan \${SCAN_ID}' "$ACTION_YML" \ + && grep -q 'check it in your dashboard at' "$ACTION_YML"; then + echo "PASS: give-up message names the scan and offers a next step" +else + echo "FAIL: give-up message no longer names the scan id or a next step" + failures=$((failures+1)) +fi + +# 8. Both give-up paths in the results fetch must record status=unreadable. +# Without it the declared `status` output falls back to the poll step's +# `completed`, and a failed report read is reported as a clean scan. +unreadable_writes=$(grep -c 'status=unreadable' "$ACTION_YML" || true) +if [ "$unreadable_writes" -ge 3 ]; then + echo "PASS: poll and both results-fetch give-up paths record status=unreadable" +else + echo "FAIL: expected >=3 status=unreadable writes, found ${unreadable_writes}" + failures=$((failures+1)) +fi + +# 9. The artifact upload must be gated on the RESULTS step, not the poll step. +# Gated on the poll step it published the error body as rafter-results.json. +if grep -qE "if: steps\.results\.outputs\.status == 'completed'" "$ACTION_YML"; then + echo "PASS: artifact upload gated on a successful results fetch" +else + echo "FAIL: artifact upload is not gated on steps.results.outputs.status" + failures=$((failures+1)) +fi + +# 10. Backoff must be exponential. A flat or zeroed backoff gives an +# eventually-consistent object store no time to converge. +if grep -q 'BACKOFF=\$(( 2 \*\* TRANSIENT_FAILURES ))' "$ACTION_YML" \ + && grep -q 'backoff=\$(( 2 \*\* attempt ))' "$ACTION_YML"; then + echo "PASS: both retry loops back off exponentially" +else + echo "FAIL: a retry loop's backoff is no longer exponential" + failures=$((failures+1)) +fi + + echo "" echo "── results ───────────────────────────────────────────────────────────" echo "Failures: $failures" diff --git a/node/src/commands/backend/scan-status.ts b/node/src/commands/backend/scan-status.ts index 80f22b80..6bb61e7a 100644 --- a/node/src/commands/backend/scan-status.ts +++ b/node/src/commands/backend/scan-status.ts @@ -16,17 +16,50 @@ import { fmt as output } from "../../utils/formatter.js"; * healthy scan. Retry those instead of failing the whole run; a scan that * would have succeeded 10 seconds later must not die on one bad read. * - * 404 is transient HERE and only here: by the time the poll loop runs we have - * already been handed a scan_id, so a missing scan mid-poll is read-after-write - * lag, not a wrong id. The FIRST poll still treats 404 as fatal. + * 404 is transient only AFTER the scan is known to exist: once the first poll + * has succeeded, a missing scan is read-after-write lag rather than a wrong id. + * On the first poll a 404 is still fatal. */ export const MAX_TRANSIENT_POLL_FAILURES = 5; -function isTransientPollError(e: any): boolean { +/** + * Total transient failures tolerated across one `handleScanStatus` call. + * + * The consecutive counter resets on every success, which is what we want — a + * twenty-minute scan with one blip at minute 2 and another at minute 18 should + * not die. But reset-on-success alone means a backend alternating 200/500 + * forever never exhausts the budget, and the CLI has no wall-clock deadline to + * stop it. This is the backstop for that. + */ +export const MAX_TOTAL_TRANSIENT_POLL_FAILURES = 20; + +/** Longest single error detail we will echo back. Servers can be verbose. */ +const MAX_ERROR_DETAIL_CHARS = 200; + +/** + * Transient = the request never got an answer, or got one the server itself + * describes as temporary. + * + * `scanExists` gates 404: before the first successful poll a 404 means the + * scan id is wrong, and retrying it just delays a clear answer. + */ +function isTransientPollError(e: any, scanExists: boolean): boolean { const status = e?.response?.status; - // No response at all: transport error (DNS, reset, timeout). - if (status === undefined) return true; - return status >= 500 || status === 408 || status === 404; + if (status === undefined) { + // Retry only errors that came from the HTTP layer. A TypeError thrown from + // our own code also has no `response`, and must not be mistaken for a flaky + // backend and retried five times. + return Boolean(e?.isAxiosError || e?.request || e?.code); + } + if (status === 404) return scanExists; + return status >= 500 || status === 408; +} + +function truncate(s: string): string { + const flat = s.replace(/[\r\n]+/g, " ").trim(); + return flat.length > MAX_ERROR_DETAIL_CHARS + ? `${flat.slice(0, MAX_ERROR_DETAIL_CHARS)}…` + : flat; } function describeHttpError(e: any): string { @@ -40,6 +73,7 @@ function describeHttpError(e: any): string { } else if (e instanceof Error) { detail = e.message; } + detail = truncate(detail); return status ? `HTTP ${status}${detail ? ` — ${detail}` : ""}` : detail || String(e); } @@ -58,10 +92,10 @@ export function unreadableReportMessage(scan_id: string, lastError: string): str ); } -const BASE_BACKOFF_MS = 2000; +export const BASE_BACKOFF_MS = 2000; -function backoffMs(consecutiveFailures: number): number { - // 2s, 4s, 8s, 16s, 32s +/** 2s, 4s, 8s, 16s — the 5th failure gives up rather than sleeping again. */ +export function backoffMs(consecutiveFailures: number): number { return BASE_BACKOFF_MS * 2 ** (consecutiveFailures - 1); } @@ -71,6 +105,40 @@ function backoffMs(consecutiveFailures: number): number { */ export class PollGaveUpError extends Error {} +/** + * A failure budget shared across every poll in one `handleScanStatus` call. + * + * Counting per-request would let a backend that alternates 200/500 forever + * reset the counter on each success and never exhaust it — the CLI has no + * wall-clock deadline, so that loop would never end. + */ +class FailureBudget { + consecutive = 0; + total = 0; + last = ""; + + record(detail: string): number { + this.consecutive += 1; + this.total += 1; + this.last = detail; + return this.consecutive; + } + + /** A success clears the consecutive run, but never refunds the total. */ + reset(): void { + this.consecutive = 0; + } + + get exhausted(): boolean { + return ( + this.consecutive >= MAX_TRANSIENT_POLL_FAILURES || + this.total >= MAX_TOTAL_TRANSIENT_POLL_FAILURES + ); + } +} + +type RetryNotice = (attempt: number, waitMs: number, detail: string) => void; + /** * One poll, with retry/backoff over transient failures. * Non-transient errors are rethrown for the caller to classify. @@ -79,32 +147,31 @@ async function pollUntilReadable( scan_id: string, headers: any, fmt: string, - onRetry?: (attempt: number, waitMs: number, detail: string) => void + budget: FailureBudget, + scanExists: boolean, + onRetry?: RetryNotice ): Promise { - let consecutiveFailures = 0; - let lastError = ""; - for (;;) { try { - return await axios.get(`${API}/static/scan`, { + const res = await axios.get(`${API}/static/scan`, { params: { scan_id, format: fmt }, headers, // Without this a hung server stalls inside a single request, and the // retry loop can only notice between attempts. timeout: API_TIMEOUT_SHORT_MS, }); + budget.reset(); + return res; } catch (e: any) { - if (!isTransientPollError(e)) throw e; - - consecutiveFailures += 1; - lastError = describeHttpError(e); + if (!isTransientPollError(e, scanExists)) throw e; - if (consecutiveFailures >= MAX_TRANSIENT_POLL_FAILURES) { - throw new PollGaveUpError(unreadableReportMessage(scan_id, lastError)); + const attempt = budget.record(describeHttpError(e)); + if (budget.exhausted) { + throw new PollGaveUpError(unreadableReportMessage(scan_id, budget.last)); } - const waitMs = backoffMs(consecutiveFailures); - onRetry?.(consecutiveFailures, waitMs, lastError); + const waitMs = backoffMs(attempt); + onRetry?.(attempt, waitMs, budget.last); await new Promise((r) => setTimeout(r, waitMs)); } } @@ -113,19 +180,33 @@ async function pollUntilReadable( const IN_PROGRESS = ["queued", "pending", "processing"]; export async function handleScanStatus(scan_id: string, headers: any, fmt: string, quiet?: boolean): Promise { + const budget = new FailureBudget(); + + // Retries are printed to stderr, not just into the spinner: ora renders + // nothing on a non-TTY, and CI is exactly where this diagnostic matters. + const onRetry: RetryNotice | undefined = quiet + ? undefined + : (attempt, waitMs, detail) => { + console.error( + `Report not readable yet (${detail}); retrying in ${Math.round(waitMs / 1000)}s ` + + `(${attempt}/${MAX_TRANSIENT_POLL_FAILURES})` + ); + }; + // First poll. A 404 here really does mean "no such scan" — do not retry it. + // Transient 5xx IS retried, so that the `rafter get ` this command + // recommends on failure is not itself defeated by one bad read. let poll; try { - poll = await axios.get( - `${API}/static/scan`, - { params: { scan_id, format: fmt }, headers } - ); + poll = await pollUntilReadable(scan_id, headers, fmt, budget, false, onRetry); } catch (e: any) { - if (e.response?.status === 404) { + if (e?.response?.status === 404) { console.error(output.error(`Scan '${scan_id}' not found`)); return EXIT_SCAN_NOT_FOUND; } - console.error(output.error(`${e.response?.data || e.message}`)); + console.error( + output.error(e instanceof PollGaveUpError ? e.message : describeHttpError(e)) + ); return EXIT_GENERAL_ERROR; } @@ -134,18 +215,11 @@ export async function handleScanStatus(scan_id: string, headers: any, fmt: strin const spinner = quiet ? undefined : ora("Waiting for scan to complete... (this could take several minutes)").start(); - const onRetry = quiet - ? undefined - : (attempt: number, waitMs: number, detail: string) => { - spinner!.text = - `Report not readable yet (${detail}); retrying in ${Math.round(waitMs / 1000)}s ` + - `(${attempt}/${MAX_TRANSIENT_POLL_FAILURES})`; - }; try { while (IN_PROGRESS.includes(status)) { await new Promise((r) => setTimeout(r, 10000)); - poll = await pollUntilReadable(scan_id, headers, fmt, onRetry); + poll = await pollUntilReadable(scan_id, headers, fmt, budget, true, onRetry); status = poll.data.status; if (status === "completed") { spinner?.succeed("Scan completed"); @@ -154,9 +228,6 @@ export async function handleScanStatus(scan_id: string, headers: any, fmt: strin spinner?.fail("Scan failed"); return EXIT_GENERAL_ERROR; } - if (spinner) { - spinner.text = "Waiting for scan to complete... (this could take several minutes)"; - } } } catch (e: any) { spinner?.fail("Could not retrieve scan report"); diff --git a/node/tests/scan-poll-transient-500.test.ts b/node/tests/scan-poll-transient-500.test.ts index 405c11d4..44d706e1 100644 --- a/node/tests/scan-poll-transient-500.test.ts +++ b/node/tests/scan-poll-transient-500.test.ts @@ -25,7 +25,10 @@ import axios from "axios"; import { handleScanStatus, unreadableReportMessage, + backoffMs, + BASE_BACKOFF_MS, MAX_TRANSIENT_POLL_FAILURES, + MAX_TOTAL_TRANSIENT_POLL_FAILURES, } from "../src/commands/backend/scan-status.js"; import { EXIT_SUCCESS, EXIT_GENERAL_ERROR, EXIT_SCAN_NOT_FOUND } from "../src/utils/api.js"; @@ -108,6 +111,24 @@ describe("handleScanStatus — transient poll failures (sable-l10k)", () => { expect(code).toBe(EXIT_SUCCESS); }); + it("retries a transient 500 on the FIRST poll", async () => { + // The give-up message tells the user to run `rafter get `, which + // re-enters at the first poll. If that path did not retry, the remedy we + // recommend would be defeated by one bad read. + mockedAxios.get + .mockRejectedValueOnce(OBJECT_NOT_FOUND) + .mockResolvedValueOnce({ data: { status: "completed", markdown: "# Done" } }); + + vi.useFakeTimers(); + const promise = handleScanStatus("s1", headers, "md", true); + await vi.advanceTimersByTimeAsync(2000); + const code = await promise; + vi.useRealTimers(); + + expect(code).toBe(EXIT_SUCCESS); + expect(mockedAxios.get).toHaveBeenCalledTimes(2); + }); + it("still reports 'not found' when the FIRST poll 404s", async () => { mockedAxios.get.mockRejectedValueOnce(httpError(404)); @@ -150,10 +171,33 @@ describe("handleScanStatus — transient poll failures (sable-l10k)", () => { expect(mockedAxios.get).toHaveBeenCalledTimes(2); }); + it("does NOT retry a plain programming error", async () => { + // A TypeError thrown from our own code also has no `response`. Retrying it + // five times would report a local bug as a flaky backend. + mockedAxios.get + .mockResolvedValueOnce({ data: { status: "processing" } }) + .mockRejectedValueOnce(new TypeError("x is not a function")); + + vi.useFakeTimers(); + const promise = handleScanStatus("s1", headers, "md", true); + await vi.advanceTimersByTimeAsync(10000); + const code = await promise; + vi.useRealTimers(); + + expect(code).toBe(EXIT_GENERAL_ERROR); + expect(mockedAxios.get).toHaveBeenCalledTimes(2); + }); + it("retries transport errors that carry no HTTP response", async () => { mockedAxios.get .mockResolvedValueOnce({ data: { status: "processing" } }) - .mockRejectedValueOnce(new Error("ECONNRESET")) + .mockRejectedValueOnce( + Object.assign(new Error("read ECONNRESET"), { + isAxiosError: true, + code: "ECONNRESET", + request: {}, + }) + ) .mockResolvedValueOnce({ data: { status: "completed", markdown: "# Done" } }); vi.useFakeTimers(); @@ -167,6 +211,91 @@ describe("handleScanStatus — transient poll failures (sable-l10k)", () => { }); }); +describe("backoff schedule (sable-l10k)", () => { + const headers = { "x-api-key": "test-key" }; + + beforeEach(() => { + vi.clearAllMocks(); + vi.spyOn(console, "error").mockImplementation(() => {}); + vi.spyOn(process.stdout, "write").mockImplementation(() => true); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + }); + + it("is exponential, not flat — 2s, 4s, 8s, 16s", () => { + expect(BASE_BACKOFF_MS).toBeGreaterThan(0); + expect([1, 2, 3, 4].map(backoffMs)).toEqual([2000, 4000, 8000, 16000]); + }); + + /** + * Record every delay the code asks for and fire the callback immediately. + * This pins the SCHEDULE rather than an upper bound: with BASE_BACKOFF_MS + * mutated to 0, or `2 ** (n-1)` mistyped as `2 * (n-1)`, the recorded + * sequence changes and the test fails. A call-count assertion would not. + */ + function recordDelays(): number[] { + const delays: number[] = []; + const real = globalThis.setTimeout; + vi.stubGlobal("setTimeout", ((fn: any, ms?: number) => { + delays.push(ms ?? 0); + return real(fn, 0); + }) as any); + return delays; + } + + it("actually SLEEPS the 2/4/8/16 schedule between retries", async () => { + mockedAxios.get.mockResolvedValueOnce({ data: { status: "processing" } }); + for (let i = 0; i < MAX_TRANSIENT_POLL_FAILURES; i++) { + mockedAxios.get.mockRejectedValueOnce(OBJECT_NOT_FOUND); + } + + const delays = recordDelays(); + const code = await handleScanStatus("s1", headers, "md", true); + + expect(code).toBe(EXIT_GENERAL_ERROR); + // 10s poll interval, then the four backoffs preceding the fifth failure. + expect(delays).toEqual([10000, 2000, 4000, 8000, 16000]); + }); + + it("restarts the backoff after a successful poll clears the run", async () => { + // Two blips far apart must NOT add up to a give-up. + mockedAxios.get + .mockResolvedValueOnce({ data: { status: "processing" } }) + .mockRejectedValueOnce(OBJECT_NOT_FOUND) + .mockRejectedValueOnce(OBJECT_NOT_FOUND) + .mockResolvedValueOnce({ data: { status: "processing" } }) + .mockRejectedValueOnce(OBJECT_NOT_FOUND) + .mockRejectedValueOnce(OBJECT_NOT_FOUND) + .mockResolvedValueOnce({ data: { status: "completed", markdown: "# Done" } }); + + const delays = recordDelays(); + const code = await handleScanStatus("s1", headers, "md", true); + + expect(code).toBe(EXIT_SUCCESS); + expect(delays).toEqual([10000, 2000, 4000, 10000, 2000, 4000]); + }); + + it("caps TOTAL transient failures, so a flapping server cannot loop forever", async () => { + // Alternating success/failure resets the consecutive counter every time. + // Without a total cap, and with no wall-clock deadline in the CLI, that + // loop never terminates. + mockedAxios.get.mockResolvedValueOnce({ data: { status: "processing" } }); + for (let i = 0; i < MAX_TOTAL_TRANSIENT_POLL_FAILURES + 5; i++) { + mockedAxios.get + .mockRejectedValueOnce(OBJECT_NOT_FOUND) + .mockResolvedValueOnce({ data: { status: "processing" } }); + } + + recordDelays(); + const code = await handleScanStatus("s1", headers, "md", true); + + expect(code).toBe(EXIT_GENERAL_ERROR); + }); +}); + describe("unreadableReportMessage", () => { it("gives the customer the scan id and a next step, not just storage jargon", () => { const msg = unreadableReportMessage( diff --git a/node/tests/scan-remote.test.ts b/node/tests/scan-remote.test.ts index 709ff2b4..c2eefbac 100644 --- a/node/tests/scan-remote.test.ts +++ b/node/tests/scan-remote.test.ts @@ -91,14 +91,19 @@ describe("handleScanStatus", () => { expect(code).toBe(EXIT_GENERAL_ERROR); }); - it("returns EXIT_GENERAL_ERROR for non-404 network error", async () => { + // sable-l10k changed this: a 500 on the first poll is now RETRIED, because + // the give-up message tells the user to run `rafter get `, which + // re-enters here. A non-transient status is what still fails immediately. + // The retry/exhaustion paths are covered in scan-poll-transient-500.test.ts. + it("returns EXIT_GENERAL_ERROR for a non-transient error", async () => { mockedAxios.get.mockRejectedValueOnce({ - response: { status: 500, data: "Internal server error" }, + response: { status: 403, data: "Forbidden" }, message: "Request failed", }); const code = await handleScanStatus("s1", headers, "md"); expect(code).toBe(EXIT_GENERAL_ERROR); + expect(mockedAxios.get).toHaveBeenCalledTimes(1); }); it("polls when status is queued, then returns on completed", async () => { diff --git a/python/rafter_cli/commands/backend.py b/python/rafter_cli/commands/backend.py index 12ae30cb..6ee9fcb4 100644 --- a/python/rafter_cli/commands/backend.py +++ b/python/rafter_cli/commands/backend.py @@ -94,26 +94,65 @@ def _confirm_plus_scan(mode: str, yes: bool) -> None: # healthy scan. Retry those instead of failing the whole run; a scan that would # have succeeded 10 seconds later must not die on one bad read. MAX_TRANSIENT_POLL_FAILURES = 5 -_BASE_BACKOFF_SECONDS = 2 + +#: Total transient failures tolerated across one interactive call. +#: +#: The consecutive counter resets on every success, which is what we want — a +#: twenty-minute scan with one blip at minute 2 and another at minute 18 should +#: not die. But reset-on-success alone means a backend alternating 200/500 +#: forever never exhausts the budget, and the CLI has no wall-clock deadline to +#: stop it. This is the backstop for that. +MAX_TOTAL_TRANSIENT_POLL_FAILURES = 20 + +BASE_BACKOFF_SECONDS = 2 + +#: Longest single error detail we will echo back. Servers can be verbose. +MAX_ERROR_DETAIL_CHARS = 200 IN_PROGRESS = ("queued", "pending", "processing") class PollGaveUpError(RuntimeError): - """Polling gave up after repeated transient failures. + """Polling gave up after exhausting its retry budget. Carries the customer-facing message so callers need not rebuild it. """ -def _is_transient_poll_status(status_code: int) -> bool: - """404 is transient HERE and only here. +class PollFatalError(RuntimeError): + """A poll failed in a way retrying cannot fix (bad key, bad request). + + Distinct from :class:`PollGaveUpError` so that "we tried five times" is + never confused with "we did not try at all". + """ + + def __init__(self, message: str, status_code: "int | None" = None): + super().__init__(message) + self.status_code = status_code + - By the time the poll loop runs we have already been handed a ``scan_id``, so - a missing scan mid-poll is read-after-write lag, not a wrong id. The FIRST - poll still treats 404 as fatal. +def backoff_seconds(consecutive_failures: int) -> int: + """2s, 4s, 8s, 16s — the 5th failure gives up rather than sleeping again.""" + return BASE_BACKOFF_SECONDS * 2 ** (consecutive_failures - 1) + + +def _is_transient_poll_status(status_code: int, scan_exists: bool) -> bool: + """Transient = the server itself describes the condition as temporary. + + ``scan_exists`` gates 404: before the first successful poll a 404 means the + scan id is wrong, and retrying it just delays a clear answer. After it, a + missing scan is read-after-write lag. """ - return status_code >= 500 or status_code in (404, 408) + if status_code == 404: + return scan_exists + return status_code >= 500 or status_code == 408 + + +def _truncate(text: str) -> str: + flat = " ".join((text or "").split()) + if len(flat) > MAX_ERROR_DETAIL_CHARS: + return flat[:MAX_ERROR_DETAIL_CHARS] + "\u2026" + return flat def _describe_http_error(status_code: int, body: str) -> str: @@ -124,8 +163,8 @@ def _describe_http_error(status_code: int, body: str) -> str: detail = parsed.get("error") or body except (ValueError, TypeError): pass - detail = (detail or "").strip() - return f"HTTP {status_code}" + (f" — {detail}" if detail else "") + detail = _truncate(detail) + return f"HTTP {status_code}" + (f" \u2014 {detail}" if detail else "") def unreadable_report_message(scan_id: str, last_error: str) -> str: @@ -137,21 +176,56 @@ def unreadable_report_message(scan_id: str, last_error: str) -> str: return ( f"Rafter could not read the report for scan {scan_id} after " f"{MAX_TRANSIENT_POLL_FAILURES} attempts.\n" - f"The scan itself may have finished — retry with: rafter get {scan_id}\n" + f"The scan itself may have finished \u2014 retry with: rafter get {scan_id}\n" f"or open the scan in your dashboard at https://rafter.so/dashboard\n" f"Last response from the server: {last_error}" ) -def _poll_until_readable(scan_id: str, headers: dict, fmt: str, quiet: bool): - """One poll, retrying transient failures with exponential backoff. +class _FailureBudget: + """A failure budget shared across every poll in one interactive call. - Returns the successful response. Raises ``PollGaveUpError`` once the - transient failures stop looking transient, and re-raises anything else. + Counting per-request would let a backend that alternates 200/500 forever + reset the counter on each success and never exhaust it — the CLI has no + wall-clock deadline, so that loop would never end. """ - consecutive_failures = 0 - last_error = "" + def __init__(self) -> None: + self.consecutive = 0 + self.total = 0 + self.last = "" + + def record(self, detail: str) -> int: + self.consecutive += 1 + self.total += 1 + self.last = detail + return self.consecutive + + def reset(self) -> None: + """A success clears the consecutive run, but never refunds the total.""" + self.consecutive = 0 + + @property + def exhausted(self) -> bool: + return ( + self.consecutive >= MAX_TRANSIENT_POLL_FAILURES + or self.total >= MAX_TOTAL_TRANSIENT_POLL_FAILURES + ) + + +def _poll_until_readable( + scan_id: str, + headers: dict, + fmt: str, + quiet: bool, + budget: "_FailureBudget", + scan_exists: bool, +): + """One poll, retrying transient failures with exponential backoff. + + Returns the successful response. Raises ``PollGaveUpError`` once the retry + budget is spent and ``PollFatalError`` for anything retrying cannot fix. + """ while True: try: resp = requests.get( @@ -160,27 +234,29 @@ def _poll_until_readable(scan_id: str, headers: dict, fmt: str, quiet: bool): params={"scan_id": scan_id, "format": fmt}, timeout=API_TIMEOUT_SHORT, ) - transient = _is_transient_poll_status(resp.status_code) - if resp.status_code == 200: + # Any 2xx is a success, matching the Node runtime's axios default. + if 200 <= resp.status_code < 300: + budget.reset() return resp - if not transient: - raise PollGaveUpError( - _describe_http_error(resp.status_code, resp.text) + if not _is_transient_poll_status(resp.status_code, scan_exists): + raise PollFatalError( + _describe_http_error(resp.status_code, resp.text), + status_code=resp.status_code, ) - last_error = _describe_http_error(resp.status_code, resp.text) + detail = _describe_http_error(resp.status_code, resp.text) except requests.RequestException as e: # Transport error (DNS, reset, timeout) — as retryable as a 5xx. - last_error = str(e) + detail = _truncate(str(e)) - consecutive_failures += 1 - if consecutive_failures >= MAX_TRANSIENT_POLL_FAILURES: - raise PollGaveUpError(unreadable_report_message(scan_id, last_error)) + attempt = budget.record(detail) + if budget.exhausted: + raise PollGaveUpError(unreadable_report_message(scan_id, budget.last)) - wait = _BASE_BACKOFF_SECONDS * 2 ** (consecutive_failures - 1) + wait = backoff_seconds(attempt) if not quiet: print( - f"Report not readable yet ({last_error}); retrying in {wait}s " - f"({consecutive_failures}/{MAX_TRANSIENT_POLL_FAILURES})", + f"Report not readable yet ({budget.last}); retrying in {wait}s " + f"({attempt}/{MAX_TRANSIENT_POLL_FAILURES})", file=sys.stderr, ) time.sleep(wait) @@ -189,18 +265,23 @@ def _poll_until_readable(scan_id: str, headers: dict, fmt: str, quiet: bool): def _handle_scan_status_interactive( scan_id: str, headers: dict, fmt: str, quiet: bool ) -> int: - poll = requests.get( - f"{API_BASE}/static/scan", - headers=headers, - params={"scan_id": scan_id, "format": fmt}, - timeout=API_TIMEOUT_SHORT, - ) + budget = _FailureBudget() - if poll.status_code == 404: - print(f"Scan '{scan_id}' not found", file=sys.stderr) - raise typer.Exit(code=EXIT_SCAN_NOT_FOUND) - elif poll.status_code != 200: - print(f"Error: {poll.text}", file=sys.stderr) + # First poll. A 404 here really does mean "no such scan" — do not retry it. + # Transient 5xx IS retried, so that the `rafter get ` this command + # recommends on failure is not itself defeated by one bad read. + try: + poll = _poll_until_readable( + scan_id, headers, fmt, quiet, budget, scan_exists=False + ) + except PollFatalError as e: + if e.status_code == 404: + print(f"Scan '{scan_id}' not found", file=sys.stderr) + raise typer.Exit(code=EXIT_SCAN_NOT_FOUND) + print(f"Error: {e}", file=sys.stderr) + raise typer.Exit(code=EXIT_GENERAL_ERROR) + except PollGaveUpError as e: + print(f"Error: {e}", file=sys.stderr) raise typer.Exit(code=EXIT_GENERAL_ERROR) data = poll.json() @@ -215,8 +296,10 @@ def _handle_scan_status_interactive( while status in IN_PROGRESS: time.sleep(10) try: - poll = _poll_until_readable(scan_id, headers, fmt, quiet) - except PollGaveUpError as e: + poll = _poll_until_readable( + scan_id, headers, fmt, quiet, budget, scan_exists=True + ) + except (PollGaveUpError, PollFatalError) as e: print(f"Error: {e}", file=sys.stderr) raise typer.Exit(code=EXIT_GENERAL_ERROR) data = poll.json() diff --git a/python/tests/test_scan_poll_transient_500.py b/python/tests/test_scan_poll_transient_500.py index 5e36a0b6..19cd8d94 100644 --- a/python/tests/test_scan_poll_transient_500.py +++ b/python/tests/test_scan_poll_transient_500.py @@ -20,8 +20,11 @@ import typer from rafter_cli.commands.backend import ( + BASE_BACKOFF_SECONDS, + MAX_TOTAL_TRANSIENT_POLL_FAILURES, MAX_TRANSIENT_POLL_FAILURES, _handle_scan_status_interactive, + backoff_seconds, unreadable_report_message, ) from rafter_cli.utils.api import EXIT_GENERAL_ERROR, EXIT_SCAN_NOT_FOUND, EXIT_SUCCESS @@ -54,13 +57,96 @@ def _server_500() -> MagicMock: @pytest.fixture(autouse=True) -def _no_sleep(): - """Backoff is real time; tests should not pay for it.""" - with patch("rafter_cli.commands.backend.time.sleep"): - yield +def sleeps(): + """Backoff is real time; tests should not pay for it. + + Yields the mock so tests can assert the SCHEDULE, not just that sleeping + happened. Backoff is the fix — retrying five times inside a millisecond + gives an eventually-consistent store no time to converge. + """ + with patch("rafter_cli.commands.backend.time.sleep") as m: + yield m class TestTransientPollFailures: + def test_backoff_is_exponential_not_flat(self): + assert BASE_BACKOFF_SECONDS > 0 + assert [backoff_seconds(n) for n in (1, 2, 3, 4)] == [2, 4, 8, 16] + + def test_actually_sleeps_the_backoff_schedule(self, sleeps): + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_processing()] + [ + _server_500() for _ in range(MAX_TRANSIENT_POLL_FAILURES) + ] + with pytest.raises(typer.Exit): + _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + # 10s poll interval, then 2/4/8/16 between the four retries that + # precede giving up on the fifth failure. + assert [c.args[0] for c in sleeps.call_args_list] == [10, 2, 4, 8, 16] + + def test_caps_total_failures_so_a_flapping_server_cannot_loop_forever(self): + # Alternating success/failure resets the consecutive counter every + # time. Without a total cap, and with no wall-clock deadline in the + # CLI, that loop never terminates. + flapping = [_processing()] + for _ in range(MAX_TOTAL_TRANSIENT_POLL_FAILURES + 5): + flapping += [_server_500(), _processing()] + + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = flapping + with pytest.raises(typer.Exit) as exc: + _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert exc.value.exit_code == EXIT_GENERAL_ERROR + + def test_consecutive_counter_resets_on_a_successful_poll(self, sleeps): + # Two blips far apart must NOT add up to a give-up. + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [ + _processing(), + _server_500(), + _server_500(), + _processing(), + _server_500(), + _server_500(), + _completed(), + ] + code = _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert code == EXIT_SUCCESS + # Backoff restarts at 2s after the reset rather than continuing to 8s. + assert [c.args[0] for c in sleeps.call_args_list] == [10, 2, 4, 10, 2, 4] + + def test_first_poll_retries_a_transient_500(self): + # The give-up message tells the user to run `rafter get `, which + # re-enters at the first poll. If that path did not retry, the remedy + # we recommend would be defeated by one bad read. + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_server_500(), _completed()] + code = _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert code == EXIT_SUCCESS + assert get.call_count == 2 + + def test_any_2xx_counts_as_success(self): + # Node's axios accepts any 2xx; Python must not diverge. + accepted = _resp(202, json_body={"status": "completed", "markdown": "# Done"}) + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [accepted] + code = _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert code == EXIT_SUCCESS + + def test_retry_notice_goes_to_stderr(self, capsys): + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_processing(), _server_500(), _completed()] + _handle_scan_status_interactive("s1", HEADERS, "md", quiet=False) + + err = capsys.readouterr().err + assert "Report not readable yet" in err + assert "retrying in 2s" in err + def test_rides_out_a_single_500_and_completes(self, capsys): with patch("rafter_cli.commands.backend.requests.get") as get: get.side_effect = [_processing(), _server_500(), _completed()] diff --git a/shared-docs/CLI_SPEC.md b/shared-docs/CLI_SPEC.md index cfbcdeb9..a0951c42 100644 --- a/shared-docs/CLI_SPEC.md +++ b/shared-docs/CLI_SPEC.md @@ -128,18 +128,25 @@ Retrieve results from a scan. #### Poll-loop retry contract -Once polling has begun (`rafter run` without `--skip-interactive`, or `rafter get --interactive`), a scan_id is known to exist, and a report is not necessarily durable the instant a scan flips to `completed`. Both runtimes therefore retry transient read failures instead of aborting the run: +A report is not necessarily durable the instant a scan flips to `completed`, so a poll can hit a 5xx on a scan that is readable seconds later. Both runtimes retry transient read failures instead of aborting: | Condition during polling | Behavior | |--------------------------|----------| -| HTTP 5xx, 408, or 404 | Transient. Retried up to **5 consecutive times** with exponential backoff (2s, 4s, 8s, 16s). The counter resets on any successful poll. | +| HTTP 5xx or 408 | Transient. Retried up to **5 consecutive times** with exponential backoff (2s, 4s, 8s, 16s). | | Transport error (DNS, reset, timeout) | Same as above. | +| HTTP 404, **after** the scan is known to exist | Transient — read-after-write lag, not a wrong id. | +| HTTP 404 on the **first** poll | Not retried. The scan genuinely does not exist. Exit code `2`. | | Other 4xx (401/403/429 …) | Not retried — reported immediately. | -| 404 on the **first** poll | Not retried — the scan genuinely does not exist. Exit code `2`. | -After 5 consecutive transient failures the command exits `1` with a message naming the scan id, the `rafter get ` retry command, and the dashboard, with the raw server response as supporting detail. Raw storage-layer wording is never the whole message. +Two budgets bound the retries. The **consecutive** counter (5) resets on any successful poll, so a long scan with occasional blips is not killed by unrelated failures minutes apart. A **total** counter (20 per command invocation) does *not* reset, so a backend alternating success and failure cannot keep the loop alive indefinitely — the CLI has no wall-clock deadline of its own. -The composite GitHub Action (`github-action/action.yml`) implements the same contract in its poll loop and its results fetch. +After either budget is exhausted the command exits `1` with a message naming the scan id, the `rafter get ` retry, and the dashboard, with the raw server response as supporting detail. Raw storage-layer wording is never the whole message. The first poll retries transient 5xx precisely so that the recommended `rafter get ` is not itself defeated by one bad read. + +**The composite GitHub Action** (`github-action/action.yml`) implements the same classification in both its poll loop and its results fetch, with these differences forced by the shell: + +- It has no "first poll" distinction: by the time it polls, the trigger step has already returned a `scan_id`, so **every** 404 there is treated as read-after-write lag. A scan id the backend accepted but never persisted therefore fails after the 5-failure budget rather than immediately. +- Its poll loop is additionally bounded by a wall-clock deadline derived from `timeout-minutes`. Before v0.11 that input was a poll *count*, so a slow API could overrun it; it is now a real deadline. +- Its `status` output is `completed`, `failed`, `timeout`, `unreadable` (the scan may have finished but its report could not be read), or `unreachable` (the API could not be contacted). ### rafter usage [OPTIONS] From 25966759d05065b4dfda2f0c8d16631cac8fb439 Mon Sep 17 00:00:00 2001 From: achebe Date: Mon, 31 Aug 2026 18:14:42 -0700 Subject: [PATCH 4/4] fix: nested error body crashed the retry it was supposed to trigger (sable-l10k) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 ` 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. --- CHANGELOG.md | 3 +- github-action/action.yml | 9 ++ .../tests/test-action-yml-defaults.sh | 30 +++++++ node/src/commands/backend/get.ts | 15 +++- node/src/commands/backend/scan-status.ts | 79 ++++++++++++++--- node/tests/scan-poll-transient-500.test.ts | 83 ++++++++++++++++-- python/rafter_cli/commands/backend.py | 87 +++++++++++++++---- python/tests/test_scan_poll_transient_500.py | 52 +++++++++++ shared-docs/CLI_SPEC.md | 6 +- 9 files changed, 321 insertions(+), 43 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 94b494a2..6cfa1a95 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,12 +12,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - **A transient 500 during scan polling no longer kills the run** (sable-l10k). An AppSumo customer's GitHub Actions build died on `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 5xx on that read is survivable — but every poll path treated any non-2xx as fatal, while the transport-error branch three lines above already retried. All three surfaces (the composite action, `rafter run`, `rafter get --interactive`) now retry transient failures with exponential backoff (2s/4s/8s/16s) before giving up, and the give-up message names the scan id, the `rafter get ` retry, and the dashboard instead of leaking storage-layer wording. Full contract in `shared-docs/CLI_SPEC.md`. Both runtimes; end-to-end CI coverage against a mock backend, so no API key or credits are needed to exercise it. - **Python: a failed poll could be written out as if it were scan results** (sable-l10k). The mid-poll loop called `.json()` on the response without checking the status code, so a 500 carrying a JSON error body parsed cleanly, yielded no `status`, fell out of the loop, and was emitted as the scan payload with exit code `0`. A non-JSON error body raised an unhandled `JSONDecodeError`. Both now fail loudly. **Behavior change:** genuine non-transient mid-poll failures that previously exited `0` with an error payload on stdout now exit `1` — check any pipeline that consumed that output. - **GitHub Action: a failed results fetch reported the scan as `completed`** (sable-l10k). The declared `status` output read only from the results step, which does not run when the fetch fails. Consumers gating on `status == 'completed'` saw a clean scan, and the artifact upload published the error body as `rafter-results.json`. Both give-up paths in the results fetch now record `status=unreadable`, and the artifact upload is gated on a successful results fetch. -- **GitHub Action: server-controlled error text is sanitized before it reaches workflow commands** (sable-l10k). A response body containing a newline could forge `::error::`, `::add-mask::`, or `::stop-commands::` annotations. Error text from the API is now stripped of newlines and length-capped at every `::error::`/`::warning::` site. +- **GitHub Action: server-controlled error text is sanitized before it reaches workflow commands** (sable-l10k). A response body containing a newline could forge `::error::`, `::add-mask::`, or `::stop-commands::` annotations. Error text from the API is now stripped of newlines and length-capped at every site that echoes it, and the server-supplied `scan_id` is rejected unless it matches `^[A-Za-z0-9_-]+$` before it reaches `$GITHUB_OUTPUT` (where a newline would forge step outputs, including `status=completed`). - **GitHub Action: an unreachable API is reported as unreachable** (sable-l10k). Transport errors retried on a flat 10s interval without counting toward the failure budget, so a bad `rafter-url` or a down backend burned the whole `timeout-minutes` window and then reported `Scan did not complete within N minutes` — a timeout message for a DNS failure. They now share the same retry budget and exit with `status=unreachable`. ### Changed - **`timeout-minutes` on the GitHub Action is now a wall-clock deadline**, not a poll count. Previously the action ran `timeout-minutes * 6` polls, each costing 10s *plus* API latency, so a slow API pushed real elapsed time past the documented budget. It is now enforced as a real deadline. **This can fail workflows that were relying on the overrun** — if a scan sits near the boundary, raise `timeout-minutes`. +- `rafter get ` (without `--interactive`) now retries transient failures too. It is the command the poll loop's give-up message recommends, so a remedy defeated by the same transient failure it is recommended for was not a remedy. - HTTP requests on the poll and results paths now carry connect/read timeouts (`--connect-timeout 10 --max-time 60` for curl, 30s for axios), so a hung server cannot stall inside a request that the retry loop only checks between attempts. ## [0.10.0] - 2026-07-29 diff --git a/github-action/action.yml b/github-action/action.yml index df2a1402..e096efad 100644 --- a/github-action/action.yml +++ b/github-action/action.yml @@ -104,6 +104,15 @@ runs: fi SCAN_ID=$(echo "$RESPONSE" | jq -r '.scan_id // empty') + # $GITHUB_OUTPUT is a key=value file: a newline in a server-controlled + # scan_id forges arbitrary step outputs, including status=completed. + # It also reaches ::error:: annotations and a request URL. + case "$SCAN_ID" in + *[!A-Za-z0-9_-]*) + echo "::error::Rafter returned a malformed scan id; refusing to continue" + exit 1 + ;; + esac if [ -z "$SCAN_ID" ]; then ERROR=$(echo "$RESPONSE" | jq -r '.error // "Unknown error triggering scan"' | tr -d '\r\n' | cut -c1-200) echo "::error::Failed to trigger scan (HTTP ${HTTP_CODE}): ${ERROR}" diff --git a/github-action/tests/test-action-yml-defaults.sh b/github-action/tests/test-action-yml-defaults.sh index 8e00bf63..59444a34 100755 --- a/github-action/tests/test-action-yml-defaults.sh +++ b/github-action/tests/test-action-yml-defaults.sh @@ -133,6 +133,36 @@ else fi +# 11. Server-controlled error text must be newline-stripped and length-capped +# before it reaches a workflow command. A newline forges ::add-mask:: / +# ::stop-commands:: / fabricated ::error:: annotations. +sanitized=$(grep -cF 'cut -c1-' "$ACTION_YML" || true) +stripped=$(grep -cF "tr -d " "$ACTION_YML" || true) +if [ "$sanitized" -ge 5 ] && [ "$stripped" -ge 5 ]; then + echo "PASS: server-controlled text newline-stripped and capped at ${sanitized} sites" +else + echo "FAIL: expected >=5 sanitized sites, found cut=${sanitized} tr=${stripped}" + failures=$((failures+1)) +fi + +# 12. TIMEOUT_MINUTES is evaluated inside bash arithmetic, where a value like +# 'x[$(cmd)]' executes. It must be validated first. +if grep -q 'case "\$TIMEOUT_MINUTES" in' "$ACTION_YML"; then + echo "PASS: timeout-minutes validated before arithmetic evaluation" +else + echo "FAIL: timeout-minutes is no longer validated before arithmetic use" + failures=$((failures+1)) +fi + +# 13. The server-controlled scan id must be validated before it reaches +# \$GITHUB_OUTPUT, where a newline forges step outputs. +if grep -q 'case "\$SCAN_ID" in' "$ACTION_YML"; then + echo "PASS: scan id validated before it reaches \$GITHUB_OUTPUT" +else + echo "FAIL: scan id is no longer validated" + failures=$((failures+1)) +fi + echo "" echo "── results ───────────────────────────────────────────────────────────" echo "Failures: $failures" diff --git a/node/src/commands/backend/get.ts b/node/src/commands/backend/get.ts index 76019d12..66f47469 100644 --- a/node/src/commands/backend/get.ts +++ b/node/src/commands/backend/get.ts @@ -7,7 +7,7 @@ import { EXIT_GENERAL_ERROR, EXIT_SCAN_NOT_FOUND } from "../../utils/api.js"; -import { handleScanStatus } from "./scan-status.js"; +import { handleScanStatus, fetchScanWithRetry, PollGaveUpError } from "./scan-status.js"; export function createGetCommand(): Command { return new Command("get") @@ -20,9 +20,14 @@ export function createGetCommand(): Command { const key = resolveKey(opts.apiKey); if (!opts.interactive) { try { - const { data } = await axios.get( - `${API}/static/scan`, - { params: { scan_id, format: opts.format }, headers: { "x-api-key": key } } + // sable-l10k — retried, because this is the command the poll loop's + // give-up message recommends. A remedy defeated by the same transient + // failure it is recommended for is not a remedy. + const { data } = await fetchScanWithRetry( + scan_id, + { "x-api-key": key }, + opts.format, + opts.quiet ); const exitCode = writePayload(data, opts.format, opts.quiet); process.exit(exitCode); @@ -30,6 +35,8 @@ export function createGetCommand(): Command { if (e.response?.status === 404) { console.error(`Scan '${scan_id}' not found`); process.exit(EXIT_SCAN_NOT_FOUND); + } else if (e instanceof PollGaveUpError) { + console.error(e.message); } else if (e.response?.data) { console.error(e.response.data); } else if (e instanceof Error) { diff --git a/node/src/commands/backend/scan-status.ts b/node/src/commands/backend/scan-status.ts index 6bb61e7a..2aa1bb85 100644 --- a/node/src/commands/backend/scan-status.ts +++ b/node/src/commands/backend/scan-status.ts @@ -49,13 +49,17 @@ function isTransientPollError(e: any, scanExists: boolean): boolean { // Retry only errors that came from the HTTP layer. A TypeError thrown from // our own code also has no `response`, and must not be mistaken for a flaky // backend and retried five times. - return Boolean(e?.isAxiosError || e?.request || e?.code); + return Boolean(e?.isAxiosError || e?.request); } if (status === 404) return scanExists; return status >= 500 || status === 408; } -function truncate(s: string): string { +function truncate(value: unknown): string { + // A server is free to answer {"error": {"message": "..."}}. Coerce before + // touching string methods — this used to throw, which turned a retryable + // failure into an immediate crash with a nonsense message. + const s = typeof value === "string" ? value : JSON.stringify(value) ?? String(value); const flat = s.replace(/[\r\n]+/g, " ").trim(); return flat.length > MAX_ERROR_DETAIL_CHARS ? `${flat.slice(0, MAX_ERROR_DETAIL_CHARS)}…` @@ -65,16 +69,18 @@ function truncate(s: string): string { function describeHttpError(e: any): string { const status = e?.response?.status; const data = e?.response?.data; - let detail = ""; + let detail: unknown = ""; if (typeof data === "string") { detail = data; } else if (data && typeof data === "object") { - detail = (data as any).error ?? JSON.stringify(data); + detail = (data as any).error ?? data; } else if (e instanceof Error) { detail = e.message; } - detail = truncate(detail); - return status ? `HTTP ${status}${detail ? ` — ${detail}` : ""}` : detail || String(e); + const detailText = truncate(detail); + return status + ? `HTTP ${status}${detailText ? ` — ${detailText}` : ""}` + : detailText || String(e); } /** @@ -82,10 +88,23 @@ function describeHttpError(e: any): string { * Storage-layer wording ("Object not found") is kept as supporting detail, not * as the whole explanation, and the next action is spelled out. */ -export function unreadableReportMessage(scan_id: string, lastError: string): string { +export function unreadableReportMessage( + scan_id: string, + lastError: string, + attempts: number = MAX_TRANSIENT_POLL_FAILURES, + reachedServer: boolean = true +): string { + if (!reachedServer) { + return ( + `Rafter could not reach the API after ${attempts} attempts.\n` + + `Check your network and that https://rafter.so is reachable from here.\n` + + `Your scan id is ${scan_id} — the scan may still be running.\n` + + `Last error: ${lastError}` + ); + } return ( `Rafter could not read the report for scan ${scan_id} after ` + - `${MAX_TRANSIENT_POLL_FAILURES} attempts.\n` + + `${attempts} attempts.\n` + `The scan itself may have finished — retry with: rafter get ${scan_id}\n` + `or open the scan in your dashboard at https://rafter.so/dashboard\n` + `Last response from the server: ${lastError}` @@ -116,11 +135,14 @@ class FailureBudget { consecutive = 0; total = 0; last = ""; + /** False once any failure carried no HTTP response at all. */ + lastReachedServer = true; - record(detail: string): number { + record(detail: string, reachedServer: boolean): number { this.consecutive += 1; this.total += 1; this.last = detail; + this.lastReachedServer = reachedServer; return this.consecutive; } @@ -165,9 +187,19 @@ async function pollUntilReadable( } catch (e: any) { if (!isTransientPollError(e, scanExists)) throw e; - const attempt = budget.record(describeHttpError(e)); + const attempt = budget.record( + describeHttpError(e), + e?.response?.status !== undefined + ); if (budget.exhausted) { - throw new PollGaveUpError(unreadableReportMessage(scan_id, budget.last)); + throw new PollGaveUpError( + unreadableReportMessage( + scan_id, + budget.last, + budget.total, + budget.lastReachedServer + ) + ); } const waitMs = backoffMs(attempt); @@ -177,6 +209,31 @@ async function pollUntilReadable( } } +/** + * A single scan fetch with the same retry budget the poll loop uses. + * + * `rafter get ` is what the give-up message tells customers to run, so it + * must not be defeated by exactly the transient failure that produced the + * message. A 404 here is still fatal — that is a wrong id, not lag. + */ +export async function fetchScanWithRetry( + scan_id: string, + headers: any, + fmt: string, + quiet?: boolean +): Promise { + const budget = new FailureBudget(); + const onRetry: RetryNotice | undefined = quiet + ? undefined + : (attempt, waitMs, detail) => { + console.error( + `Report not readable yet (${detail}); retrying in ${Math.round(waitMs / 1000)}s ` + + `(${attempt}/${MAX_TRANSIENT_POLL_FAILURES})` + ); + }; + return pollUntilReadable(scan_id, headers, fmt, budget, false, onRetry); +} + const IN_PROGRESS = ["queued", "pending", "processing"]; export async function handleScanStatus(scan_id: string, headers: any, fmt: string, quiet?: boolean): Promise { diff --git a/node/tests/scan-poll-transient-500.test.ts b/node/tests/scan-poll-transient-500.test.ts index 44d706e1..b4bf1ba3 100644 --- a/node/tests/scan-poll-transient-500.test.ts +++ b/node/tests/scan-poll-transient-500.test.ts @@ -282,17 +282,88 @@ describe("backoff schedule (sable-l10k)", () => { // Alternating success/failure resets the consecutive counter every time. // Without a total cap, and with no wall-clock deadline in the CLI, that // loop never terminates. - mockedAxios.get.mockResolvedValueOnce({ data: { status: "processing" } }); - for (let i = 0; i < MAX_TOTAL_TRANSIENT_POLL_FAILURES + 5; i++) { - mockedAxios.get - .mockRejectedValueOnce(OBJECT_NOT_FOUND) - .mockResolvedValueOnce({ data: { status: "processing" } }); - } + // Endless flapping: the mock never drains, so the ONLY thing that can stop + // this loop is the total cap. (With the cap deleted the test hangs rather + // than passing on a drained-queue TypeError, which is what it used to do.) + // Hard stop well past the cap, so a missing cap fails loudly here instead + // of hanging the suite. + const ceiling = MAX_TOTAL_TRANSIENT_POLL_FAILURES * 4; + let call = 0; + mockedAxios.get.mockImplementation(async () => { + call += 1; + if (call > ceiling) { + throw new Error(`total transient-failure cap not enforced (${call} calls)`); + } + if (call === 1) return { data: { status: "processing" } }; + if (call % 2 === 0) throw OBJECT_NOT_FOUND; + return { data: { status: "processing" } }; + }); recordDelays(); const code = await handleScanStatus("s1", headers, "md", true); expect(code).toBe(EXIT_GENERAL_ERROR); + expect(call).toBeLessThanOrEqual(ceiling); + // Bounded by the TOTAL budget: one success per failure, plus the opener. + expect(call).toBe(MAX_TOTAL_TRANSIENT_POLL_FAILURES * 2); + }); + + it("reports the real attempt count, not the consecutive cap", async () => { + let call = 0; + mockedAxios.get.mockImplementation(async () => { + call += 1; + if (call === 1) return { data: { status: "processing" } }; + if (call % 2 === 0) throw OBJECT_NOT_FOUND; + return { data: { status: "processing" } }; + }); + const errors: string[] = []; + vi.spyOn(console, "error").mockImplementation((m: any) => { + errors.push(String(m)); + }); + + recordDelays(); + await handleScanStatus("s1", headers, "md", true); + + // 20 failures happened; claiming "after 5 attempts" would be a lie. + expect(errors.join("\n")).toContain(`after ${MAX_TOTAL_TRANSIENT_POLL_FAILURES} attempts`); + }); + + it("survives a nested JSON error object instead of crashing", async () => { + // A server may answer {"error": {"message": "..."}}. Calling string + // methods on that object used to throw, defeating the retry entirely. + const nested = { response: { status: 500, data: { error: { message: "nested" } } } }; + mockedAxios.get + .mockResolvedValueOnce({ data: { status: "processing" } }) + .mockRejectedValueOnce(nested) + .mockResolvedValueOnce({ data: { status: "completed", markdown: "# Done" } }); + + recordDelays(); + const code = await handleScanStatus("s1", headers, "md", true); + + expect(code).toBe(EXIT_SUCCESS); + expect(mockedAxios.get).toHaveBeenCalledTimes(3); + }); + + it("truncates a very long server error instead of echoing it whole", async () => { + const huge = "x".repeat(5000); + mockedAxios.get.mockRejectedValueOnce({ + response: { status: 500, data: { error: huge } }, + }); + for (let i = 0; i < MAX_TRANSIENT_POLL_FAILURES; i++) { + mockedAxios.get.mockRejectedValueOnce({ + response: { status: 500, data: { error: huge } }, + }); + } + const errors: string[] = []; + vi.spyOn(console, "error").mockImplementation((m: any) => { + errors.push(String(m)); + }); + + recordDelays(); + await handleScanStatus("s1", headers, "md", true); + + expect(errors.join("\n")).not.toContain(huge); + expect(errors.join("\n")).toContain("…"); }); }); diff --git a/python/rafter_cli/commands/backend.py b/python/rafter_cli/commands/backend.py index 6ee9fcb4..5e7314b1 100644 --- a/python/rafter_cli/commands/backend.py +++ b/python/rafter_cli/commands/backend.py @@ -148,8 +148,17 @@ def _is_transient_poll_status(status_code: int, scan_exists: bool) -> bool: return status_code >= 500 or status_code == 408 -def _truncate(text: str) -> str: - flat = " ".join((text or "").split()) +def _truncate(value) -> str: + """Coerce before truncating. + + A server is free to answer ``{"error": {"message": "..."}}``. This used to + call ``.split()`` on a dict, raising an ``AttributeError`` that no caller + catches — turning a retryable failure into an unhandled traceback. + """ + if value is None: + return "" + text = value if isinstance(value, str) else json.dumps(value, default=str) + flat = " ".join(text.split()) if len(flat) > MAX_ERROR_DETAIL_CHARS: return flat[:MAX_ERROR_DETAIL_CHARS] + "\u2026" return flat @@ -167,15 +176,29 @@ def _describe_http_error(status_code: int, body: str) -> str: return f"HTTP {status_code}" + (f" \u2014 {detail}" if detail else "") -def unreadable_report_message(scan_id: str, last_error: str) -> str: +def unreadable_report_message( + scan_id: str, + last_error: str, + attempts: int = MAX_TRANSIENT_POLL_FAILURES, + reached_server: bool = True, +) -> str: """The message a customer actually sees when the report never becomes readable. Storage-layer wording ("Object not found") is kept as supporting detail, not - as the whole explanation, and the next action is spelled out. + as the whole explanation, and the next action is spelled out. ``attempts`` is + the real count, which is not always ``MAX_TRANSIENT_POLL_FAILURES`` — the + total budget can trip first. """ + if not reached_server: + return ( + f"Rafter could not reach the API after {attempts} attempts.\n" + "Check your network and that https://rafter.so is reachable from here.\n" + f"Your scan id is {scan_id} \u2014 the scan may still be running.\n" + f"Last error: {last_error}" + ) return ( f"Rafter could not read the report for scan {scan_id} after " - f"{MAX_TRANSIENT_POLL_FAILURES} attempts.\n" + f"{attempts} attempts.\n" f"The scan itself may have finished \u2014 retry with: rafter get {scan_id}\n" f"or open the scan in your dashboard at https://rafter.so/dashboard\n" f"Last response from the server: {last_error}" @@ -194,11 +217,14 @@ def __init__(self) -> None: self.consecutive = 0 self.total = 0 self.last = "" + #: False once any failure carried no HTTP response at all. + self.last_reached_server = True - def record(self, detail: str) -> int: + def record(self, detail: str, reached_server: bool = True) -> int: self.consecutive += 1 self.total += 1 self.last = detail + self.last_reached_server = reached_server return self.consecutive def reset(self) -> None: @@ -244,13 +270,22 @@ def _poll_until_readable( status_code=resp.status_code, ) detail = _describe_http_error(resp.status_code, resp.text) + reached_server = True except requests.RequestException as e: # Transport error (DNS, reset, timeout) — as retryable as a 5xx. detail = _truncate(str(e)) + reached_server = False - attempt = budget.record(detail) + attempt = budget.record(detail, reached_server) if budget.exhausted: - raise PollGaveUpError(unreadable_report_message(scan_id, budget.last)) + raise PollGaveUpError( + unreadable_report_message( + scan_id, + budget.last, + attempts=budget.total, + reached_server=budget.last_reached_server, + ) + ) wait = backoff_seconds(attempt) if not quiet: @@ -262,6 +297,18 @@ def _poll_until_readable( time.sleep(wait) +def fetch_scan_with_retry(scan_id: str, headers: dict, fmt: str, quiet: bool): + """A single scan fetch with the same retry budget the poll loop uses. + + ``rafter get `` is what the give-up message tells customers to run, so + it must not be defeated by exactly the transient failure that produced the + message. A 404 here is still fatal — that is a wrong id, not lag. + """ + return _poll_until_readable( + scan_id, headers, fmt, quiet, _FailureBudget(), scan_exists=False + ) + + def _handle_scan_status_interactive( scan_id: str, headers: dict, fmt: str, quiet: bool ) -> int: @@ -435,17 +482,19 @@ def get( headers = {"x-api-key": key} if not interactive: - resp = requests.get( - f"{API_BASE}/static/scan", - headers=headers, - params={"scan_id": scan_id, "format": fmt}, - timeout=API_TIMEOUT, - ) - if resp.status_code == 404: - print(f"Scan '{scan_id}' not found", file=sys.stderr) - raise typer.Exit(code=EXIT_SCAN_NOT_FOUND) - elif resp.status_code != 200: - print(f"Error: {resp.text}", file=sys.stderr) + # sable-l10k — retried, because this is the command the poll loop's + # give-up message recommends. A remedy defeated by the same + # transient failure it is recommended for is not a remedy. + try: + resp = fetch_scan_with_retry(scan_id, headers, fmt, quiet) + except PollFatalError as e: + if e.status_code == 404: + print(f"Scan '{scan_id}' not found", file=sys.stderr) + raise typer.Exit(code=EXIT_SCAN_NOT_FOUND) + print(f"Error: {e}", file=sys.stderr) + raise typer.Exit(code=EXIT_GENERAL_ERROR) + except PollGaveUpError as e: + print(f"Error: {e}", file=sys.stderr) raise typer.Exit(code=EXIT_GENERAL_ERROR) data = resp.json() return write_payload(data, fmt, quiet) diff --git a/python/tests/test_scan_poll_transient_500.py b/python/tests/test_scan_poll_transient_500.py index 19cd8d94..3d7299a5 100644 --- a/python/tests/test_scan_poll_transient_500.py +++ b/python/tests/test_scan_poll_transient_500.py @@ -118,6 +118,58 @@ def test_consecutive_counter_resets_on_a_successful_poll(self, sleeps): # Backoff restarts at 2s after the reset rather than continuing to 8s. assert [c.args[0] for c in sleeps.call_args_list] == [10, 2, 4, 10, 2, 4] + def test_survives_a_nested_json_error_object(self): + # A server may answer {"error": {"message": "..."}}. Calling string + # methods on that object raised an AttributeError no caller catches, + # surfacing as a traceback and defeating the retry entirely. + nested = _resp(500, text=json.dumps({"error": {"message": "nested"}})) + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_processing(), nested, _completed()] + code = _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + assert code == EXIT_SUCCESS + + def test_truncates_a_very_long_server_error(self, capsys): + huge = "x" * 5000 + big = _resp(500, text=json.dumps({"error": huge})) + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_processing()] + [ + big for _ in range(MAX_TRANSIENT_POLL_FAILURES) + ] + with pytest.raises(typer.Exit): + _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + err = capsys.readouterr().err + assert huge not in err + assert "\u2026" in err + + def test_reports_the_real_attempt_count_not_the_consecutive_cap(self, capsys): + flapping = [_processing()] + for _ in range(MAX_TOTAL_TRANSIENT_POLL_FAILURES + 5): + flapping += [_server_500(), _processing()] + + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = flapping + with pytest.raises(typer.Exit): + _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + err = capsys.readouterr().err + # 20 failures happened; claiming "after 5 attempts" would be a lie. + assert f"after {MAX_TOTAL_TRANSIENT_POLL_FAILURES} attempts" in err + + def test_unreachable_api_is_not_blamed_on_the_report(self, capsys): + with patch("rafter_cli.commands.backend.requests.get") as get: + get.side_effect = [_processing()] + [ + requests.ConnectionError("no route to host") + for _ in range(MAX_TRANSIENT_POLL_FAILURES) + ] + with pytest.raises(typer.Exit): + _handle_scan_status_interactive("s1", HEADERS, "md", quiet=True) + + err = capsys.readouterr().err + assert "could not reach the API" in err + assert "could not read the report" not in err + def test_first_poll_retries_a_transient_500(self): # The give-up message tells the user to run `rafter get `, which # re-enters at the first poll. If that path did not retry, the remedy diff --git a/shared-docs/CLI_SPEC.md b/shared-docs/CLI_SPEC.md index a0951c42..cd23373d 100644 --- a/shared-docs/CLI_SPEC.md +++ b/shared-docs/CLI_SPEC.md @@ -128,7 +128,7 @@ Retrieve results from a scan. #### Poll-loop retry contract -A report is not necessarily durable the instant a scan flips to `completed`, so a poll can hit a 5xx on a scan that is readable seconds later. Both runtimes retry transient read failures instead of aborting: +A report is not necessarily durable the instant a scan flips to `completed`, so a poll can hit a 5xx on a scan that is readable seconds later. Both runtimes retry transient read failures instead of aborting. This applies to `rafter run`, `rafter get --interactive`, and plain `rafter get `: | Condition during polling | Behavior | |--------------------------|----------| @@ -140,7 +140,9 @@ A report is not necessarily durable the instant a scan flips to `completed`, so Two budgets bound the retries. The **consecutive** counter (5) resets on any successful poll, so a long scan with occasional blips is not killed by unrelated failures minutes apart. A **total** counter (20 per command invocation) does *not* reset, so a backend alternating success and failure cannot keep the loop alive indefinitely — the CLI has no wall-clock deadline of its own. -After either budget is exhausted the command exits `1` with a message naming the scan id, the `rafter get ` retry, and the dashboard, with the raw server response as supporting detail. Raw storage-layer wording is never the whole message. The first poll retries transient 5xx precisely so that the recommended `rafter get ` is not itself defeated by one bad read. +After either budget is exhausted the command exits `1`. If the failures reached the server, the message names the scan id, the `rafter get ` retry, and the dashboard, with the raw server response as supporting detail — raw storage-layer wording is never the whole message. If no failure reached the server at all, the message says so and points at connectivity rather than blaming the report. Both report the **real** number of attempts, which is not always 5: the total budget can trip first. + +`rafter get ` carries the same retry budget, so the remedy the give-up message recommends is not defeated by the transient failure that produced it. **The composite GitHub Action** (`github-action/action.yml`) implements the same classification in both its poll loop and its results fetch, with these differences forced by the shell: