CI: provisioning.test.ts fixed 360s timeout can be shorter than the download-retry worst case

[mobileskyfi]

Observed

user provisioning > background mode: custom user created and accessible via REST timed out at its fixed 360s harness timeout, on a narrow windows-x86 / provisioning.test.ts / stable dispatch (unrelated investigation into a separate SSH batch-login probe issue on windows-x86 (branch diag/ssh-second-probe-diagnostic): https://github.com/tikoci/quickchr/actions/runs/29116483756/job/86441059513

19:03:06.588  Downloading CHR 7.23.2 (x86)...
19:05:06.615    Download failed (attempt 1/3), retrying in 2s...
19:07:08.629    Download failed (attempt 2/3), retrying in 4s...
19:09:06.014  (fail) user provisioning > background mode: custom user created and accessible via REST [360001.58ms]
19:09:06.014    ^ this test timed out after 360000ms.
19:09:06.473  Downloading CHR 7.23.2 (x86)...        <- next test, same image
19:09:12.658    Saved (succeeded in 6s)

Root cause (grounded, not a TCG-hang)

This is not the #76 silent-hang class — the log is fully accounted for. downloadImage()
(src/lib/images.ts) retries 3× with a 120s AbortSignal.timeout per attempt and 2s/4s
backoff — worst case ~366s (120+2+120+4+120). This test's timeout is a fixed
360_000, i.e. shorter than the download's own worst-case retry budget. When two
attempts genuinely fail (ordinary transient network flakiness against
download.mikrotik.com — the very next test's download of the identical image
succeeded in 6s, so this isn't a systemic/version-specific problem), bun's own
per-test timeout SIGTERMs the test 6s before downloadImage()'s retry loop would have
thrown its own clean DOWNLOAD_FAILED error. The failure is diagnosable in this case only
because the preceding Downloading CHR .../Download failed (attempt N/3) lines happened to
be in the log — a test that reached this point without a slow download would give no clue at
all, just a bare timeout.

This is the same class of gap #89 (fix(ci): scale examples-smoke per-test timeout for TCG platforms, merged as #90) already fixed for examples-smoke.test.ts — its PER_TEST_TIMEOUT
is now derived from defaultBootTimeout() with headroom instead of a flat constant.
provisioning.test.ts still has 6 tests on the old flat 360_000 pattern (lines 150, 191,
224, 260, 351, 537 as of this writing), all equally exposed: any one of them can lose a race
against a slow-but-legitimately-retrying download and fail as an undiagnosable timeout instead
of a clean download error.

Done-when

• provisioning.test.ts's fixed 360_000 timeouts account for the download retry worst
  case (~366s) plus boot/provisioning headroom, the same way examples-smoke.test.ts does
  post-examples-smoke: per-test timeout (360s) shorter than QuickCHR's own TCG boot budget (480s) — windows-x86 #89 — or downloadImage()'s own retry budget is tightened so it can never legitimately
  exceed a calling test's timeout.
• No code changes attempted yet — this is intentionally deferred (per current focus on CI: provisioning.test.ts fixed 360s timeout can be shorter than the download-retry worst case #91's
  SSH-probe diagnostic); filing now just to record accurate grounding before it's forgotten.

Cross-refs: #89/#90 (sibling fix for examples-smoke), #76 (a different windows/macOS TCG
symptom — silent hang, not this).

[mobileskyfi]

Two more download-timeout casualties, plus the upstream cause: the image cache key never rotates

Part of the ci:slow-platform-flake series (#76 #79 #80 #91). From Run A, 30279318703 (full matrix).

Integration (windows/x86_64 · long-term) — both failures were downloads, not code

##[group]test\integration\anchor.test.ts:
Downloading CHR 7.21.5 (x86)...
  https://download.mikrotik.com/routeros/7.21.5/chr-7.21.5.img.zip
  Download failed (attempt 1/3), retrying in 2s...
  Download failed (attempt 2/3), retrying in 4s...
(fail) RouterOS REST schema anchor > key REST endpoints have expected field structure [300005.44ms]
  ^ this test timed out after 300000ms.

The very next file (device-mode.test.ts) downloaded the same image successfully. Same job, second casualty:

Downloading packages for 7.22.1 (arm64)...
(fail) arm64 packages match 7.22.1 known list [120000.75ms]
  ^ this test timed out after 120000ms.
Downloading packages for 7.22.1 (x86)...
(pass) x86 packages match 7.22.1 known list [30191.78ms]

Only the Windows jobs logged Download failed retries anywhere in the matrix — the Linux and macOS legs downloaded cleanly in the same window. So the exposure is Windows-weighted, but the shape is exactly what this issue describes: a fixed per-test timeout that a download-retry worst case can exceed. anchor.test.ts (300 s) and the package-enumeration test (120 s) belong on the list alongside provisioning.test.ts (360 s).

Upstream cause worth fixing first: the cache never gains new versions

- name: Cache CHR images (POSIX)
  uses: actions/cache@v5
  with:
    path: ~/.local/share/quickchr/cache
    key: chr-images-${{ runner.os }}-${{ runner.arch }}-v1
    restore-keys: chr-images-${{ runner.os }}-

The key has no version component, so once created it hits exactly, and actions/cache does not re-save on an exact hit. The cache is frozen at whatever it held when first populated; every newly-resolved channel version is re-downloaded on every run, forever. Observed directly — the linux-x86 long-term leg logged Downloading CHR 7.21.5 (x86)... (cache restored successfully, image still absent), and the Windows legs re-downloaded chr-7.21.5.img.zip in both Run A and Run B.

That is what converts ordinary mikrotik.com slowness into red CI. Channels move (stable is now 7.23.2, long-term 7.21.5, testing 7.24rc2), so the frozen cache decays continuously. Options: put the resolved version set in the key, or a save-always-style rotation, or a dedicated pre-warm step outside the timed tests.

Related flake in the same run: quickstart hang, provably not code

Examples smoke (linux/x86_64 · testing) — quickstart (ts) hung the full 360 s and was killed (exit 143). The examples hardcode channel: "stable", so the stable, long-term and testing smoke legs on linux-x86 run byte-identical work — the other two passed in the same run. Same runner pool, same image, same code.

Observability gap that cost the diagnosis

run() in test/integration/examples-smoke.test.ts:104 collects stdout/stderr only after proc.exited:

const [out, errOut, code] = await Promise.all([
  new Response(proc.stdout).text(),
  new Response(proc.stderr).text(),
  proc.exited,
]);

When bun's per-test timeout SIGTERMs the example, that output is lost — we got exit 143 and an empty errOut, so there is no record of whether quickstart was mid-download, mid-boot, or wedged. Streaming the child's output (or draining it on timeout) would have answered this run's question without another CI round-trip. Worth pairing with the timeout work in this issue.

[mobileskyfi]

Cache-key rotation and the output gap are both fixed

Branch ci/boot-failure-forensics, commit dda5b47. Both were recorded here as causes rather than as their own work items; they were small and independent, so they went in with the diagnostics work.

Cache key. actions/cache skips its post-job save whenever the primary key hit exactly, so the static chr-images-${os}-${arch}-v1 meant any RouterOS version resolved after the cache was first populated re-downloaded on every run, forever. Now:

key: chr-images-${{ runner.os }}-${{ runner.arch }}-v2-${{ matrix.target }}-int-${{ github.run_id }}-${{ github.run_attempt }}
restore-keys: |
  chr-images-${{ runner.os }}-${{ runner.arch }}-v2-${{ matrix.target }}-
  chr-images-${{ runner.os }}-${{ runner.arch }}-v2-

The {run_id}-{run_attempt} tail guarantees a miss so every run re-saves; restore-keys does prefix restore, newest-first. -int- / -ex- keeps the integration and examples-smoke jobs from colliding on one key within a run — they cache the same path in parallel. Old entries age out under the repo's cache LRU cap. Rationale is in ci.instructions.md § CHR Image Caching so the next person doesn't "simplify" it back to a static key.

Lost quickstart output. examples-smoke.test.ts buffered both streams with new Response(proc.stdout).text(), which only yields once the child exits — so an example that hung until the per-test timeout produced nothing at all, which is exactly what happened here. Output now streams line-by-line with a [<example>:out] / [<example>:err] prefix as it arrives (under CI=true or QUICKCHR_STREAM_EXAMPLES=1), and a non-zero exit prints both streams — the old code logged only errOut, so an example failing a REST assertion on stdout reported an empty error.

Not addressed here: the 360 s fixed timeout in provisioning.test.ts that this issue is actually titled for. With the cache now re-saving, the download-retry worst case should stop being hit routinely — but that is a prediction, not a measurement, and the timeout is still nominally shorter than the retry envelope. Leaving this open until a few runs show whether the download exposure is actually gone.