diff --git a/.github/workflows/test-github-action.yml b/.github/workflows/test-github-action.yml index b7836ee7..38875523 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,184 @@ 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, with the right status + run: | + cat mock.log + 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: the results fetch retried and completed." + test-yaml-validity: name: action.yml is valid YAML runs-on: ubuntu-latest diff --git a/CHANGELOG.md b/CHANGELOG.md index 3f5b87fa..6cfa1a95 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,20 @@ 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 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 ### Added diff --git a/github-action/action.yml b/github-action/action.yml index 32a9b812..e096efad 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,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, 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: 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,19 +93,28 @@ 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}" 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') + # $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"') + 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 @@ -121,38 +131,97 @@ 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. + 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="" + + # 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)" - 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 } 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)), $(( (DEADLINE - $(date +%s)) / 60 ))m of ${TIMEOUT_MINUTES}m budget left)" sleep 10 POLL_COUNT=$((POLL_COUNT+1)) done @@ -180,23 +249,54 @@ 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}" + echo "status=unreadable" >> "$GITHUB_OUTPUT" + 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}" + # 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 - } - 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}" @@ -297,7 +397,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 new file mode 100644 index 00000000..2b77ab97 --- /dev/null +++ b/github-action/tests/mock-rafter-api.py @@ -0,0 +1,101 @@ +#!/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 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 +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_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" + +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"] + + 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( + FAIL_STATUS, + {"error": "Failed to fetch report from storage: Object not found"}, + ) + + if n < COMPLETE_AFTER: + 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/github-action/tests/test-action-yml-defaults.sh b/github-action/tests/test-action-yml-defaults.sh index 084748e6..59444a34 100755 --- a/github-action/tests/test-action-yml-defaults.sh +++ b/github-action/tests/test-action-yml-defaults.sh @@ -66,6 +66,103 @@ 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 + + +# 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 ea551f20..2aa1bb85 100644 --- a/node/src/commands/backend/scan-status.ts +++ b/node/src/commands/backend/scan-status.ts @@ -2,63 +2,299 @@ 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 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; + +/** + * 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; + 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); + } + if (status === 404) return scanExists; + return status >= 500 || status === 408; +} + +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)}…` + : flat; +} + +function describeHttpError(e: any): string { + const status = e?.response?.status; + const data = e?.response?.data; + let detail: unknown = ""; + if (typeof data === "string") { + detail = data; + } else if (data && typeof data === "object") { + detail = (data as any).error ?? data; + } else if (e instanceof Error) { + detail = e.message; + } + const detailText = truncate(detail); + return status + ? `HTTP ${status}${detailText ? ` — ${detailText}` : ""}` + : detailText || 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, + 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 ` + + `${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}` + ); +} + +export const BASE_BACKOFF_MS = 2000; + +/** 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); +} + +/** + * 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 {} + +/** + * 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 = ""; + /** False once any failure carried no HTTP response at all. */ + lastReachedServer = true; + + record(detail: string, reachedServer: boolean): number { + this.consecutive += 1; + this.total += 1; + this.last = detail; + this.lastReachedServer = reachedServer; + 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. + */ +async function pollUntilReadable( + scan_id: string, + headers: any, + fmt: string, + budget: FailureBudget, + scanExists: boolean, + onRetry?: RetryNotice +): Promise { + for (;;) { + try { + 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, scanExists)) throw e; + + const attempt = budget.record( + describeHttpError(e), + e?.response?.status !== undefined + ); + if (budget.exhausted) { + throw new PollGaveUpError( + unreadableReportMessage( + scan_id, + budget.last, + budget.total, + budget.lastReachedServer + ) + ); + } + + const waitMs = backoffMs(attempt); + onRetry?.(attempt, waitMs, budget.last); + await new Promise((r) => setTimeout(r, waitMs)); + } + } +} + +/** + * 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 { - // First poll + 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; } 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(); + + 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, budget, true, 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; } } + } 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 { - 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; - } - } } } 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..b4bf1ba3 --- /dev/null +++ b/node/tests/scan-poll-transient-500.test.ts @@ -0,0 +1,385 @@ +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, + 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"; + +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(() => { + // Belt and braces: every test restores real timers itself (see above), but + // a failing assertion can skip that line. + 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; + vi.useRealTimers(); + + 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; + vi.useRealTimers(); + + 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; + vi.useRealTimers(); + + 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)); + + 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; + vi.useRealTimers(); + + 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; + vi.useRealTimers(); + + expect(code).toBe(EXIT_GENERAL_ERROR); + 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( + Object.assign(new Error("read ECONNRESET"), { + isAxiosError: true, + code: "ECONNRESET", + request: {}, + }) + ) + .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; + vi.useRealTimers(); + + expect(code).toBe(EXIT_SUCCESS); + }); +}); + +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. + // 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("…"); + }); +}); + +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/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 ea988cae..5e7314b1 100644 --- a/python/rafter_cli/commands/backend.py +++ b/python/rafter_cli/commands/backend.py @@ -88,40 +88,267 @@ 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 + +#: 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 exhausting its retry budget. + + Carries the customer-facing message so callers need not rebuild it. + """ + + +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 + + +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. + """ + if status_code == 404: + return scan_exists + return status_code >= 500 or status_code == 408 + + +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 + + +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 = _truncate(detail) + return f"HTTP {status_code}" + (f" \u2014 {detail}" if detail else "") + + +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. ``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"{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}" + ) + + +class _FailureBudget: + """A failure budget shared across every poll in one interactive 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. + """ + + 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, 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: + """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( + f"{API_BASE}/static/scan", + headers=headers, + params={"scan_id": scan_id, "format": fmt}, + timeout=API_TIMEOUT_SHORT, + ) + # Any 2xx is a success, matching the Node runtime's axios default. + if 200 <= resp.status_code < 300: + budget.reset() + return resp + 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, + ) + 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, reached_server) + if budget.exhausted: + 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: + print( + f"Report not readable yet ({budget.last}); retrying in {wait}s " + f"({attempt}/{MAX_TRANSIENT_POLL_FAILURES})", + file=sys.stderr, + ) + 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: - 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() 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, 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() status = data.get("status") if status == "completed": @@ -255,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 new file mode 100644 index 00000000..3d7299a5 --- /dev/null +++ b/python/tests/test_scan_poll_transient_500.py @@ -0,0 +1,303 @@ +"""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 ( + 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 + +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 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_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 + # 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()] + 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..cd23373d 100644 --- a/shared-docs/CLI_SPEC.md +++ b/shared-docs/CLI_SPEC.md @@ -126,6 +126,30 @@ 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 + +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 | +|--------------------------|----------| +| 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. | + +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`. 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: + +- 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] Check API quota and usage statistics.