CI: savevm monitor command times out against a flat 5s budget (windows-x86 TCG and macos-x86 HVF)

[mobileskyfi]

Current signature

QEMU snapshot creation intermittently exceeds the generic 5 s monitorCommand() deadline:

• originally observed in disk.test.ts on windows-x86/TCG;
• reproduced in run 30507484030 by the rollback example on macos-x86/HVF;
• recent Windows full-suite runs were green, so the defect is intermittent/load-sensitive rather than Windows- or TCG-specific.

The #101 phase breakdown on the macOS recurrence is decisive:

connect=1ms first-byte=2ms prompt=2ms command-written=3ms
response-first-byte=3ms bytes=545

The monitor connected, greeted, accepted savevm, and streamed 545 bytes before the wrapper timed out at 5000 ms. This rules out connect/prompt failure and strongly supports a legitimate long-running savevm operation being forced through the flat fast-query default.

Defect

QuickCHR.snapshot() calls monitorCommand(..., undefined, ...), inheriting the 5 s default used for short commands such as info status. savevm writes guest RAM plus disk delta and its duration depends on host disk/load and accelerator/runtime class. It needs an operation-specific deadline; raising the global monitor default would make unrelated monitor wedges slower to detect.

Proposed approach

1. Define measured operation budgets for savevm, loadvm, and delvm separately from fast monitor queries.
2. Pass the relevant explicit budget from the QuickCHR snapshot operations rather than changing the generic default.
3. Preserve the existing timeout phase/byte-count evidence and add an anchor test for it.
4. Reproduce with targeted disk.test.ts/rollback runs on macos-x86 HVF and windows-x86 TCG, including a deliberately constrained deadline to verify the failure path.
5. Coordinate the nesting with CI: retune oversized boot envelopes from path-specific timing data without losing forensic headroom #106/CI: evidence-preserving per-file watchdog and incremental run ledger #77 so operation timeout + cleanup/forensics fits inside the enclosing test/file cap.

Done-when

• Long snapshot operations use explicit, measurement-backed deadlines; fast monitor queries retain a tight default.
• Timeout errors retain connect/prompt/write/response phase timings and received-byte count.
• Targeted macos-x86 HVF and windows-x86 TCG snapshot/rollback runs pass repeatedly, and a forced timeout remains an honest attributed failure.
• The budget contract is documented in the QEMU/CI instructions as appropriate.

Independent Wave 1 work under #110; it does not block #109 or #77.

[mobileskyfi]

Ran the specific test:

gh workflow run integration.yml --ref main \
  -f platforms=windows-x86 \
  -f routeros-targets=stable,long-term,testing \
  -f test-filter=disk.test.ts \
  -f run-examples=false

Which seem to pass:

gh run view 28762319627 

✓ main Integration · 28762319627
Triggered via workflow_dispatch about 5 minutes ago

JOBS
✓ Plan matrix (platforms × targets) in 2s (ID 85279919092)
- Lint PowerShell examples in 0s (ID 85279919389)
✓ Integration (windows/x86_64 · stable) in 3m16s (ID 85279925562)
✓ Integration (windows/x86_64 · testing) in 3m28s (ID 85279925569)
✓ Integration (windows/x86_64 · long-term) in 3m39s (ID 85279925572)
- Examples smoke (${{ matrix.label }} · ${{ matrix.target }}) in 0s (ID 85279926053)
✓ Aggregate metrics → ci-data in 8s (ID 85280236442)

ANNOTATIONS
- Running test/integration/disk.test.ts
Integration (windows/x86_64 · stable): .github#26

- Running test/integration/disk.test.ts
Integration (windows/x86_64 · testing): .github#26

- Running test/integration/disk.test.ts
Integration (windows/x86_64 · long-term): .github#26

! Node.js 20 is deprecated. The following actions target Node.js 20 but are being forced to run on Node.js 24: actions/download-artifact@v6. For more information see: https://github.blog/changelog/2025-09-19-deprecation-of-node-20-on-github-actions-runners/
Aggregate metrics → ci-data: .github#2


ARTIFACTS
integration-logs-windows-x86-long-term
integration-logs-windows-x86-testing
integration-logs-windows-x86-stable

For more information about a job, try: gh run view --job=<job-id>
View this run on GitHub: https://github.com/tikoci/quickchr/actions/runs/28762319627

[mobileskyfi]

Reproduced narrowly on Windows TCG — and hypothesis 1 is now measured out

Part of the ci:slow-platform-flake series (#76 #79 #80 #91). Evidence from:

• Run A — full matrix, all platforms × stable,long-term,testing, examples on: 30279318703
• Run B — the narrow repro this issue asked for, test-filter=start-stop.test.ts,disk.test.ts, run-examples=false: 30289164062

It reproduces, and it alternates legs

Leg	Run A	Run B (narrow)
windows/x86_64 · stable	fail (savevm)	pass
windows/x86_64 · long-term	pass	fail (savevm)
macos/x86_64 · stable	fail — rollback example, same message	pass
macos/x86_64 · long-term	(runner lost, #76)	pass

~50 % on Windows TCG, and it does reproduce in a two-file run, so this is not "one runner-load event" (hypothesis 4). Run B's Windows long-term artifact:

start-stop.test.ts 471s pass
disk.test.ts        89s fail
  (pass) QuickCHR.add + first start materializes bootSize/extraDisks [45024ms]
  (fail) monitor savevm/loadvm restores guest state on qcow2 boot disk [44016ms]
        QuickCHRError: Monitor command timed out   (src/lib/channels.ts:92)

The machine was healthy — boot metric {"name":"integration-snapshot-savevm","version":"7.21.5","accel":"tcg","boot_ms":33999} — so the 5 s budget expired on the monitor command itself, ~10 s after a clean 34 s boot. Runner windows-latest, 4× EPYC 7763, QEMU 11.0.91 (v11.1.0-rc1-12127-g1c26c3e070), TCG.

New: it is not Windows-only

In Run A the identical Monitor command timed out hit macos/x86_64 · stable through the rollback example, which drives the same savevm/loadvm path. macOS uses a unix-socket monitor channel, Windows uses TCP localhost (portBase + 6). So the failure is not a property of the Windows TCP channel alone — though Windows is heavily over-represented.

Hypothesis 1 measured and rejected

This issue listed "savevm under Windows TCG sometimes legitimately takes longer than the 5 s default" as unproven. Measured directly against a 512 MB guest with a 192 M qcow2 boot disk (Intel Mac, current main), calling monitorCommand() with a large explicit timeout so the true duration is visible:

HVF:  savevm 0.32s   loadvm 0.16s   delvm 0.00s
TCG:  savevm 0.32s   loadvm 0.18s   delvm 0.00s

A ~15× margin against the 5 s budget, and forcing TCG does not move it (QUICKCHR_ACCEL=tcg, the override added in #99). Snapshot work is not what consumes the budget. That pushes weight onto hypothesis 2 — the monitor channel connects but the post-command (qemu) prompt never arrives — and keeps hypothesis 3 (QEMU wedging inside savevm) open.

Caveat: measured on a fast host with NVMe. It does not prove a contended 4-core CI runner with a slower disk stays under 5 s; it does show there is no inherent TCG cost, which was the stated hypothesis.

Independent design gap, regardless of root cause

Boot timeouts scale by accel via accelTimeoutFactor(), but the snapshot commands do not. src/lib/quickchr.ts:818 (savevm) and :854 (loadvm) pass undefined and inherit monitorCommand()'s flat 5000 ms, while stop() passes 4000 and info cpus / info balloon pass 3000. Of every monitor command quickchr issues, savevm/loadvm are the only ones whose cost scales with guest RAM and host disk speed — they are the last ones that should be on an unscaled default.

Fixing that is worthwhile on its own merits, but on this evidence it would be masking, not fixing: 0.32 s does not become >5 s from load alone, and a bumped timeout would hide whatever is actually stalling the prompt. The probe described in this issue's investigation plan (per-phase timing: connect → first prompt → command write → first response byte → final prompt, plus info status after a timeout) is still the right next step.

[mobileskyfi]

Per-phase monitor timings landed — the timeout now says where it stalled

Branch ci/boot-failure-forensics, commit dda5b47. Run 30308608464 includes disk.test.ts on windows-x86 · long-term, the leg that failed narrow in Run B.

This issue's next step was "per-phase timing: connect → first prompt → command write → first response byte → final prompt, plus info status after a timeout". monitorCommand() now records exactly that and renders it into the error:

Monitor command timed out after 5000ms: "savevm quickchr-snap" — connect=1ms first-byte=4ms
prompt=4ms command-written=4ms response-first-byte=never bytes=120

Verified against a live CHR on the Intel Mac (forced 1 ms budget):

Monitor command timed out after 1ms: "info block" — connect=3ms first-byte=never
prompt=never command-written=never response-first-byte=never bytes=0

Reading it: prompt=never = the monitor never greeted us. command-written=<n>ms with response-first-byte=never = QEMU took the command and went quiet — hypothesis 2 confirmed. Both non-null with a late final prompt = the command genuinely ran long, i.e. hypothesis 3 / a real timeout-envelope problem. Those three were indistinguishable before; the bare Monitor command timed out is gone.

info status after a timeout is covered from the boot side (captureBootFailure() runs info status/info block/info chardev), but not yet on a bare monitor timeout — a monitor that just stalled is unlikely to answer a follow-up on the same channel, so I left that out rather than add a second 5 s stall to every failure. Reconsider if the phase line turns out to be ambiguous in practice.

Left the 5 s budget alone, per the argument in the previous comment: 0.32 s measured does not become >5 s from load, so bumping it would mask the stalled prompt rather than fix it. The unscaled savevm/loadvm timeout (quickchr.ts:818/:854) remains a real design gap — worth fixing on its own merits once the phase data says what is actually stalling, not before.