a command overrunning a 60s timeout discards the prepared guest

[tobias-carlbom]

A command that overruns a timeout of 60 s or more makes WinQuick discard a
healthy prepared guest, rebuild it five times and cold boot, turning a 60 s
timeout into 242 s of wall time. The next run then pays another 10.9 s to
rebuild the state.

Nothing is corrupted and it recovers on its own, so this is a cost and
diagnostics problem rather than a correctness one. Reporting it because the
trigger is a normal workload: a build or test suite that runs longer than a
generous --timeout is exactly the case the flag exists for.

Environment

WinQuick	0.4.2 (homebrew tap)
QEMU	11.1.1 (homebrew bottle)
Host	Apple M1, 8 cores, 16 GiB, macOS 26.4
Guest	Validation OS arm64, 10.0.26100.9278

Reproduce

winquick run --verbose --timeout 60 -- cmd /c "ping -n 200 127.0.0.1 >nul"

Reproduced on every attempt.

[ 70.2s] winquick: the guest has not acknowledged the command yet but has moved 152 MiB
                   - it is working, not halted; waiting for the command instead
[ 70.3s] winquick: the prepared guest timed out without ever taking the command;
                   discarding it and booting cold for this run
[ 70.3s] winquick: preparing a reusable Windows image (one-off, takes a few seconds)
[ 80.9s] winquick: ready state built in 10.6s (423 MiB)
[ 92.6s] winquick: newly built ready state did not work (attempt 1 of 5):
                   timed out waiting for WQGO.TXT from the guest
   ... attempts 2, 3, 4, 5, each ~22s, all failing identically ...
[181.9s] winquick: 5 prepared guests in a row came back silent, but this QEMU has
                   restored one before; leaving the fast path on
[182.0s] winquick: cold boot
[242.0s] winquick: the command did not finish within 60 s - raise it with `--timeout`

The lines at 70.2 s and 70.3 s contradict each other: the run proves the guest
is alive, then concludes it never took the command.

Cause

warm_execute decides whether the guest accepted the command by re-probing the
raw GO flag (src/runner.rs:1344):

let took_it = mailbox::probe(&mbox, mailbox::GO).is_none();

A guest hammering the FAT volume has not flushed its delete of that flag, so it
reads as never having taken the command, even though PROOF_OF_LIFE_BYTES and
still_moving proved it alive one line earlier. That verdict reaches
a_cold_boot_would_help (src/runner.rs:1053), which discards the ready state
and falls through to the cold path.

I am not suggesting the byte counters be trusted instead. The comment at
src/runner.rs:1080 explains why that is worse: a guest wedged at 98% of a
processor also looks alive by that measure, and trusting it once left a machine
failing every run for eight hours. Preferring the flag is the safe side of that
tradeoff, and ACKNOWLEDGEMENT_IS_CERTAIN bounds the damage by keeping short
timeouts off the cold path entirely.

The part that looks worth changing is what happens afterwards.

The five prepare attempts cannot succeed here

PREPARE_ATTEMPTS = 5 (src/runner.rs:1241) is there for a freeze that comes
back silent. In this cascade all five attempts fail with the same
timed out waiting for WQGO.TXT at about 11.7 s each, and those failures are
caused by the command rather than by an unlucky freeze.

Control, running winquick reset first and then one command, three trials each:

fresh prepare, then	failed prepare attempts	total
cmd /c ver	0 (3 of 3 trials)	11 s
ping -n 200, overrunning the timeout	3 to 5 consecutive	147 s to 242 s

A freshly built state serves a light command first time, every time. The same
build fails repeatedly when the injected command is the heavy one, because each
newly prepared guest is handed the same command and trips the same unflushed
acknowledgement. The loop is rebuilding state to fix something the state was
never responsible for, at roughly 22 s per attempt.

A second trace shows the same thing without any misdiagnosis involved. With
--timeout 59 starting from no ready state, attempts 1 to 3 failed identically
and attempt 4 succeeded, then ran to the timeout:

[  0.0s] winquick: no ready state yet
[ 22.4s] winquick: newly built ready state did not work (attempt 1 of 5): timed out waiting for WQGO.TXT
[ 44.8s] winquick: newly built ready state did not work (attempt 2 of 5): timed out waiting for WQGO.TXT
[ 67.2s] winquick: newly built ready state did not work (attempt 3 of 5): timed out waiting for WQGO.TXT
[147.0s] winquick: the guest has not acknowledged the command yet but has moved 145 MiB
                   - it is working, not halted; waiting for the command instead
[147.0s] winquick: the command did not finish within 59 s - raise it with `--timeout`

Suggestions

None of these require trusting the byte counters.

1. Stop the retry loop when a rebuilt state fails the same way as the one it
   replaced. That is evidence about the command, not the state, and it would cut
   about 88 s from the cascade while leaving the silent-freeze protection alone.
2. Reword the two messages. "it is working, not halted" and "timed out without
   ever taking the command" land 0.1 s apart and read as a contradiction.
   Neither mentions the likeliest cause, which is a command that needs longer.
3. Reconsider the 60 s threshold. The comment calls it well below the 300 s
   default, which holds for the default, but --timeout 60 is the round number
   a user reaches for first, and it opens the gate exactly there.

Minor, separate

winquick run --help describes --timeout as "give up after this many
seconds". The clock starts after first contact, not at launch, so a timed-out
run takes FIRST_CONTACT plus the timeout. Measured at 15 s for --timeout 5
across 7 runs and 20 s for --timeout 10. The behaviour is deliberate and well
argued in the source; only the help text is silent about the extra 10 s.

[tobias-carlbom]

Fixed. The cause is one step further down than the analysis here reached, and it makes most of the host-side machinery in the trace unfalsifiable.

Root cause

guest/agent.cmd deleted the go flag with the mailbox still mounted:

del %WQ%\WQGO.TXT
...
cmd /c %WQ%\WQCMD.CMD > %WQ%\WQOUT.TXT 2> %WQ%\WQERR.TXT   :: mailbox still mounted
mountvol %WQ% /P                                            :: only flush, after the command

Windows synchronises a FAT volume with the underlying disk at mount and dismount and at no other time — the fact the agent's own poll loop is built on. So the delete stayed in the guest's cache until the command finished and the volume was released.

The host reads the mailbox image directly. It could not see the acknowledgement while the acknowledgement was the thing being waited for.

That makes probe(GO).is_none() at runner.rs:1344 always false for any command still running, so the contradiction you spotted at 70.2 s / 70.3 s was not a race the workload sometimes wins — it was structural, and it applied to every command outliving the ten-second first-contact window. It also explains the second trace: ping -n 200 sleeps between pings, moves no measurable I/O, and so trips neither PROOF_OF_LIFE_BYTES nor still_moving. Each freshly prepared guest then failed at wait_until_gone for the same reason, which is why the five attempts could not succeed.

Fix

del %WQ%\WQGO.TXT >nul 2>&1
mountvol %WQ% /P >nul 2>&1        :: flush the acknowledgement to the host image
mountvol %WQ% %WQVOL% >nul 2>&1   :: take the volume back, so output has somewhere to go

Same round trip the poll loop already does every turn.

Measured on your reproducer, M1 / macOS 26.4 / QEMU 11.1.1:

winquick run --timeout 60 -- cmd /c "ping -n 200 127.0.0.1 >nul"
before	182 s, 5 discarded prepared guests, then a cold boot
after	60 s, no rebuild, prepared guest kept

Warm cmd /c ver is unchanged at 310 ms p50.

Your three suggestions

1. Stop the retry loop early — not taken. The cascade is gone at the root, and adding a heuristic on top of a fixed bug is exactly what produced the byte counters in the first place.
2. Reword the two messages — done, and the second now names a command that needs longer as the usual cause.
3. Reconsider the 60 s threshold — kept. You were right that 60 is the round number people reach for, but the constant was not the cause: the flag never arrived at any duration, so raising it would have moved the boundary without fixing anything. Its documentation was wrong and is corrected.

The --help note was right too — --timeout now says the clock starts when the guest takes the command.

Why the tests missed it

tests/integration.sh has covered this exact shape since v0.4.1 — slow command, timeout, assertions that the prepared guest survives and the run is not retried. Both used --timeout 2, which is below ACKNOWLEDGEMENT_IS_CERTAIN by construction: the range where the host declines to act on the verdict. The suite asserted the right properties at the one value for which they were free. It now runs the case at 60 s as well, a unit test asserts the agent dismounts between taking a command and starting it, and a new tests/firstrun.sh runs the whole thing against an install built from nothing.

For the record, this was not undiagnosed: docs/research.md has carried the cause and this exact one-line fix since v0.4.0 under "the guest-side half, not shipped here", deferred to avoid a runtime rebuild. That note is left in place with what the deferral actually cost.

Upgrading

The agent is baked into the image, so images built by an earlier WinQuick are stale. winquick doctor names each one and the command that rebuilds it — and setup --force alone is not enough, since the serviced images each have to be rebuilt by their own capability. Both of those were themselves wrong before this change and are fixed here.

Thanks for the report — the traces, the control runs and the pointer to runner.rs:1344 are what made it findable.