CI: windows-x86 TCG savevm monitor command times out in disk snapshot test

[mobileskyfi]

Observation

A full Windows TCG integration leg failed in run 28749608475, job 85246320853:

• job: Integration (windows/x86_64 - stable)
• runner: Windows Server 2025 / windows-2025-vs2026
• Bun: 1.3.14
• QEMU: 11.0.50 (v11.0.0-12631-g54e84cdc7a) from Chocolatey
• RouterOS target: stable resolved to 7.23.1
• quickchr accel: Windows TCG, x86 guest

Failure was isolated to test/integration/disk.test.ts:

QuickCHRError: Monitor command timed out
code: BOOT_TIMEOUT
at src/lib/channels.ts:92
(fail) disk support > monitor savevm/loadvm restores guest state on qcow2 boot disk [43735.36ms]

The failed machine (integration-snapshot-savevm) had already booted normally according to metrics:

{"kind":"boot","platform":"windows-x86","host":"win32","name":"integration-snapshot-savevm","version":"7.23.1","arch":"x86","accel":"tcg","boot_ms":34019}

So this is not the #79 clean() reboot timeout and not the #69 first-new-credential REST reset. The failure is after boot, while sending the QEMU monitor savevm snap1 command through Windows TCP-localhost monitor channel (portBase + 6).

What is not yet proven

The current evidence does not tell whether:

1. savevm under Windows TCG sometimes legitimately takes longer than the current monitorCommand() default timeout of 5s;
2. the TCP monitor channel connects but stops delivering the post-command (qemu) prompt;
3. QEMU itself wedges during savevm; or
4. this was one runner-load event.

Later green Windows jobs are not sufficient to call this fixed: the later windows/x86_64 - stable pass I checked was a filtered #69 probe, and the earlier windows/x86_64 - 7.20.8 pass was the old TCG smoke path (anchor.test.ts only). Neither reran this snapshot test.

Local control

On the Intel Mac local host, pinned to the same RouterOS version but using x86/HVF rather than Windows/TCG, the disk file passes:

QUICKCHR_DATA_DIR=/tmp/quickchr-windows-flake-local-data \
HOME=/tmp/quickchr-windows-flake-local-home \
QUICKCHR_INTEGRATION=1 \
QUICKCHR_TEST_TARGET=7.23.1 \
bun test test/integration/disk.test.ts

Result:

(pass) disk support > QuickCHR.add + first start materializes bootSize/extraDisks and guest sees extra drives [24310.99ms]
(pass) disk support > monitor savevm/loadvm restores guest state on qcow2 boot disk [30255.99ms]
2 pass, 0 fail

This rules out a broad current-code snapshot regression, but does not reproduce the Windows TCG bucket.

Investigation plan

First reproduce in the exact CI bucket, narrowly:

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

Run it several times. If it flakes, add a Windows-focused probe/lab rather than changing timeouts blindly. The probe should log, per monitor command:

• TCP connect duration to monitor 127.0.0.1:portBase+6
• time to first (qemu) prompt
• time from command write to first response byte
• time to final (qemu) prompt
• raw cleaned monitor response or timeout phase
• info status, info chardev, info block, savevm snap1, info snapshots, loadvm snap1, delvm snap1
• machine.json, qemu.log, QEMU command line, platform-info.txt, boot-log/metrics

Decision points:

• If savevm returns successfully with a 15s/30s timeout and no other symptoms, the default monitor-command timeout is underpowered for Windows TCG snapshot creation.
• If connect/prompt is fast but post-command prompt never returns, treat this as a QEMU monitor/channel or savevm wedge and preserve the machine directory for post-mortem.
• If info status shows paused/restore/saving state after timeout, capture that as QEMU-side state rather than retrying over it.
• If focused disk.test.ts never reproduces but full Windows suite does, investigate cumulative runner load or prior tests affecting QEMU/TCP monitor behavior.

Related context: #31 fixed real snapshot correctness; #40 tracks Windows support broadly. This issue is the narrow CI flake for Windows TCG monitor/snapshot timing.

[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