ci: sandbox start waits out its timeout after OpenVMM exits, so failed_start races a 0.5 s deadline (flaky nvx-rs / windows-latest) #1017

Summary

The dev push run for 789a1a7 (#960) failed in nvx-rs / windows-latest because the failed_start case of the nvx-rs CLI tests got error[timed-out] where it expects error[exited]. The case runs sandbox start --timeout 0.5 against a fake OpenVMM that exits with status 5 as soon as it starts. start waits for OpenVMM's control endpoint until its timeout passes, without checking whether OpenVMM still runs, and only then polls OpenVMM once: if OpenVMM has exited by then, the start fails with exited and OpenVMM's status, and otherwise with timed-out. The case therefore passes only if the fake OpenVMM launches and exits within about 0.5 s, which it did not on the 4-vCPU runner, among the other cli tests.

#960 did not cause this: it changes neither the CLI nor its tests, the Linux leg of the same run passed, and the code is unchanged on the current dev head. Behind the intermittent test failure is a product defect. Every nvx-rs sandbox start whose OpenVMM exits before it serves its control endpoint waits out its whole --timeout, 60 s by default, before it reports the exit, where nvx::host::session::connect stops waiting once the VMM has exited.

Incident

• Workflow: CI run 40929156914, attempt 1, push to dev.
• Head: 789a1a73c2c55d37292e42a340e4fcb30d95e392, the merge of nvx-rs: mount a clone's export and set its network settings #960. Push runs on dev queue rather than cancel each other, so this run was not superseded. The later dev commits, 67f395e and 9a84f57, are [skip ci] updates of the module diagrams and performance baselines, so this run is the latest CI result for dev's code.
• Failed job: nvx-rs / windows-latest, step Check nvx-rs, in the Test step of the composite action: cargo +1.95.0 test --locked --all-features. In tests\cli.rs, 64 of 65 tests passed, and lifecycle::refusals_of_lifecycle_operations failed in its failed start case, the only one that passes --timeout 0.5.
• Runner: GitHub-hosted windows-latest (4 vCPUs), Windows Server 2025 10.0.26100, image windows-2025-vs2026 20261021.278.1, Rust 1.95.0.
• Downstream: Required status check failed, and Publish development release was skipped. All other jobs passed or were skipped by their own conditions, and Persist performance baseline recorded this head's performance history.

Decisive output:

---- lifecycle::refusals_of_lifecycle_operations stdout ----
case: operations without a sandbox
…
case: failed start
case: unusable guest RAM
case: concurrent starts

thread '<unnamed>' (1916) panicked at tests\cli\harness.rs:710:9:
assertion `left == right` failed: nvx-rs ["sandbox", "start", "--state-dir", "C:\\Users\\runneradmin\\AppData\\Local\\Temp\\nvx-cli-KpOM7b\\state", "--timeout", "0.5"] exited with Some(1)
stdout: 
stderr: error[timed-out]: managed control endpoint did not become available: //./pipe/openvmm-microvm-65b9fb6ddbb14494df4b5bb7ff7f1d5f

  left: "timed-out"
 right: "exited"

History

I checked the logs of every failed nvx-rs / * job, including earlier attempts of rerun runs, in the 1000 most recent CI runs, back to 2026-10-20. This is the only failure of refusals_of_lifecycle_operations among them. #825 added failed_start with its 0.5 s timeout (merged 2026-10-25), so the window covers every dev run of the case.

Root cause

Permalinks point to 789a1a7. The files are byte-identical on the current dev head, 9a84f57.

1. The case. failed_start provisions a sandbox whose fake OpenVMM exits with status 5 as soon as it has parsed its arguments (fake_openvmm.rs#L419-L422). It then runs sandbox start --timeout 0.5 twice and expects exited and status 5 (lifecycle.rs#L1035-L1058). It is one of the 11 cases of refusals_of_lifecycle_operations, which in_parallel checks in 4 threads (lifecycle.rs#L1368-L1374, harness.rs#L128-L145), while the test harness runs the other cli tests, 4 at a time on this runner. Each case has a root of its own, which on Windows holds a copy of the fake OpenVMM, and on POSIX hosts a link to it (harness.rs#L321-L331).
2. The endpoint wait ignores OpenVMM. start waits for the guest through check_ready and Session::connect (start.rs#L140-L141, start.rs#L231-L237). Session::connect retries the endpoint until the timeout passes, and then fails with timed-out and managed control endpoint did not become available (session.rs#L191-L231). It never checks whether OpenVMM still runs, so a start whose OpenVMM has exited keeps waiting for an endpoint that cannot appear.
3. The start looks at OpenVMM once, afterwards. For any failure but a closed endpoint, start gives OpenVMM no grace period (start.rs#L173-L181). end_failed_start polls OpenVMM once, and terminates it if it still runs (start.rs#L254-L291). Only a status from that poll turns the failure into exited with OpenVMM's status (start.rs#L191-L199); otherwise, it stays timed-out.
4. So the case races its own launch. It passes only if the fake OpenVMM launches and exits within about 0.5 s of its spawn. On an idle workstation, that takes far less: with the fix below, which ends a start as soon as OpenVMM exits, whole starts took 0.07–0.28 s. On the 4-vCPU runner, among the parallel tests, the fake had not exited by the deadline.
5. The library does not wait. nvx::host::session::connect checks between attempts that the VMM still runs, and fails with ProcessExited once it does not (session.rs#L95-L100). The CLI's session is a port of control_session.py, whose connect loops retried until the deadline, as this one does.

Reproduction

I used a 20-thread Windows 11 workstation with Rust 1.95.0 at 9a84f57, whose nvx-rs is identical to 789a1a7. No hypervisor is needed.

• Alone, lifecycle::refusals_of_lifecycle_operations --exact passed 20 of 20 runs.
• The whole cli test binary with 4 test threads, pinned with the processes that it starts to 4 CPUs, as on windows-latest, failed 1 of 10 runs with the CI signature: error[timed-out]: managed control endpoint did not become available: //./pipe/openvmm-microvm-…, left: "timed-out", right: "exited".

# PowerShell 7, from nvx-rs/ at 789a1a7.
$env:NVX_BUNDLE = 'skip'
cargo +1.95.0 test --locked --all-features --test cli --no-run
$cli = @(Get-ChildItem target\debug\deps\cli-*.exe | Sort-Object LastWriteTime)[-1].FullName
# The processes that this shell starts inherit its affinity: 4 CPUs, as windows-latest has.
[System.Diagnostics.Process]::GetCurrentProcess().ProcessorAffinity = [IntPtr]0xF
1..10 | ForEach-Object { & $cli --test-threads=4 *> "$env:TEMP\cli-$_.log"; "run ${_}: exit $LASTEXITCODE" }

The probe below isolates the mechanism, without load. It runs nvx-rs sandbox start against a root like the tests', whose fake OpenVMM exits with status 5 at once. Before the fix, the error depends on whether OpenVMM exited before the deadline, and every start lasts its whole timeout:

Every start left config.json, openvmm.log, and sandbox.lock, as the case expects.

# PowerShell 7. -Target is the target\debug directory of a build of the nvx-rs CLI tests, which
# holds nvx-rs.exe and nvx-fake-openvmm.exe. Runs `nvx-rs sandbox start` against a root like the
# tests' (nvx-rs/tests/cli/harness.rs), whose fake OpenVMM exits with status 5 at once.
param(
    [Parameter(Mandatory)] [string]$Target,
    [string]$Timeouts = '0.001,0.001,0.001,0.5,0.5,0.5,5,5'
)

$ErrorActionPreference = 'Stop'
$NvxRs = Join-Path $Target 'nvx-rs.exe'
$Fake = Join-Path $Target 'nvx-fake-openvmm.exe'
foreach ($path in $NvxRs, $Fake) { if (-not (Test-Path $path)) { throw "missing $path" } }

$Root = Join-Path ([System.IO.Path]::GetTempPath()) ("nvx-mechanism-" + [guid]::NewGuid().ToString('N').Substring(0, 8))
New-Item -ItemType Directory -Path $Root | Out-Null
$Root = (Resolve-Path $Root).Path

function Write-RootFile([string]$Relative, [string]$Text) {
    $path = Join-Path $Root $Relative
    New-Item -ItemType Directory -Force -Path (Split-Path $path) | Out-Null
    [System.IO.File]::WriteAllText($path, $Text)
}

function Invoke-Nvx([string[]]$Arguments) {
    $psi = [System.Diagnostics.ProcessStartInfo]::new($NvxRs)
    foreach ($argument in @('--root', $Root) + $Arguments) { $psi.ArgumentList.Add($argument) }
    $psi.WorkingDirectory = $Root
    $psi.UseShellExecute = $false
    $psi.RedirectStandardInput = $true
    $psi.RedirectStandardOutput = $true
    $psi.RedirectStandardError = $true
    foreach ($name in 'NVX_OPENVMM', 'NVX_AUTO_DOWNLOAD', 'GH_TOKEN', 'GITHUB_TOKEN', 'COLUMNS', 'LINES') {
        [void]$psi.Environment.Remove($name)
    }
    $watch = [System.Diagnostics.Stopwatch]::StartNew()
    $process = [System.Diagnostics.Process]::Start($psi)
    $process.StandardInput.Close()
    $stdout = $process.StandardOutput.ReadToEndAsync()
    $stderr = $process.StandardError.ReadToEndAsync()
    $process.WaitForExit()
    $watch.Stop()
    [pscustomobject]@{
        Code    = $process.ExitCode
        Seconds = [math]::Round($watch.Elapsed.TotalSeconds, 3)
        Stdout  = $stdout.Result.Trim()
        Stderr  = $stderr.Result.Trim()
    }
}

try {
    $provenance = @(
        @('openvmm.provenance.json', 'executable_sha256', '1e8c924cdaac227bf74b4a4a9bcdb9e8836a1355fd0408cc81dab5d9aa71eb4d'),
        @('vmlinux.provenance.json', 'kernel_sha256', 'a0c936696eb7d5ee3192bf53b9d281cecbb40ca9db520de72cb95817ad92ac72'),
        @('initramfs.provenance.json', 'initramfs_sha256', '2f77c2c97621e8bf69794e9d12815bb7c46338638f126bea8b18dfe02a684d62')
    )
    foreach ($entry in $provenance) {
        Write-RootFile "build/$($entry[0])" "{`n  `"format`": 1,`n  `"$($entry[1])`": `"$($entry[2])`"`n}`n"
    }
    $files = [ordered]@{
        'build/vmlinux' = "kernel`n"; 'build/initramfs.cpio.gz' = "initramfs`n"; 'distro.erofs' = "distro`n"
        'runtime.erofs' = "runtime`n"; 'custom.erofs' = "custom`n"; 'scratch.ext4' = "scratch`n"
        'share/file.txt' = "file`n"; 'share/sub/data.txt' = "data`n"; 'share/hidden/shown/data.txt' = "data`n"
        'share/writable/data.txt' = "data`n"; 'share2/data.txt' = "data`n"; 'single.txt' = "single`n"
    }
    foreach ($relative in $files.Keys) { Write-RootFile $relative $files[$relative] }
    New-Item -ItemType Directory -Force -Path (Join-Path $Root 'reports') | Out-Null
    $openvmm = Join-Path $Root 'openvmm/target/release/openvmm.exe'
    New-Item -ItemType Directory -Force -Path (Split-Path $openvmm) | Out-Null
    Copy-Item $Fake $openvmm

    $state = Join-Path $Root 'state'
    $provisioned = Invoke-Nvx @('sandbox', 'provision', '--state-dir', $state,
        '--layer', "distro,$(Join-Path $Root 'distro.erofs'),11111111-1111-1111-1111-111111111111",
        '--scratch', (Join-Path $Root 'scratch.ext4'), '--cmdline', 'fake_exit_on_start=5')
    "provision: code=$($provisioned.Code) stderr=$($provisioned.Stderr)"
    if ($provisioned.Code -ne 0) { throw 'provision failed' }

    "timeout`tcode`tseconds`tstderr`tstate_entries"
    foreach ($timeout in ($Timeouts -split ',')) {
        $started = Invoke-Nvx @('sandbox', 'start', '--state-dir', $state, '--timeout', $timeout)
        $entries = (Get-ChildItem -Name $state | Sort-Object) -join ','
        "$timeout`t$($started.Code)`t$($started.Seconds)`t$($started.Stderr)`t$entries"
    }
    $deprovisioned = Invoke-Nvx @('sandbox', 'deprovision', '--state-dir', $state)
    "deprovision: code=$($deprovisioned.Code) stderr=$($deprovisioned.Stderr)"
} finally {
    Remove-Item -Recurse -Force $Root -ErrorAction SilentlyContinue
}

Impact

• 789a1a7 has a red required check and no development release, and dev stays red until its next CI run.
• The failure ended the composite action on Windows, so this head lost the rest of cargo test --all-features, the default-feature and no-default-feature tests, artifact bundling, documentation, the minimum supported Rust version check, and the runtime adapter's protocol-only and host-only checks. nvx-rs: mount a clone's export and set its network settings #960 changes tests/runtime-adapter, so the last two matter. All of these pass locally on Windows at this head with the fix below. One local run of the default-feature tests failed two unrelated host::template::clone::tests::restore tests, which passed in the rerun and in 3 reruns of that module.
• Any nvx-rs sandbox start whose OpenVMM exits before it serves its control endpoint, such as one that refuses its configuration, waits out its whole --timeout, 60 s by default, before it reports the exit.

Suggested fix

• Between attempts, have start's endpoint wait check whether the OpenVMM that it launched has exited, through the launch's child (Launched::wait_timeout(Duration::ZERO)). It should then fail at once with exited and OpenVMM's status, as nvx::host::session::connect does. exec and stop find a running VM by its record and can keep the current wait.
• Give failed_start a generous --timeout, such as 60, and assert that the start ends before it. The case then checks that a start ends when OpenVMM exits, rather than racing OpenVMM's launch.
• Test the new wait on POSIX and Windows endpoints, and note the difference from nvx.py in nvx-rs/README.md.

I validated these changes locally. With them, the loaded reproduction passed 10 of 10 runs, and every start of the probe reported exited in under 0.3 s, whatever its timeout.

Related work

• nvx-rs: add the scenario tests that replace the CLI transcripts #825 added failed_start with its 0.5 s timeout.
• Failed sandbox start can kill OpenVMM mid-report, leaving a .tmp* file that blocks deprovision (flaky WHP sandbox-lifecycle) #438, fixed by sandbox: let a failed start's OpenVMM publish its outcome report #439, let a failed start's OpenVMM publish its outcome report after the control endpoint closes. This failure goes through the same end_failed_start path, with no grace period.