nvx-rs: Windows pipe transfers can time out before their deadline, so the restore driver's 60 s budget test fails (flaky nvx-rs / windows-latest) #1482

Summary

Two push runs of feature/nvx-refactor failed in nvx-rs / windows-latest because host::restore_driver::tests::ready_has_sixty_seconds_and_start_thirty_from_ready_for_each_pending_accept_and_read saw a restore fail with Expired after 59.9993 s and 59.9994 s of its 60 s budget. The test is right: the restore gave up before its deadline. On Windows, every pending read and write of a control transport waits in overlapped(), which waits for the time left rounded down to whole milliseconds and takes WAIT_TIMEOUT for the end of the deadline without checking it. A pending transfer can therefore fail with TimedOut up to about a millisecond before its deadline. In a probe of dev's transport, 2% of the pending reads and writes that timed out did.

The defect is on dev too: overlapped() differs there only in waiting at least 1 ms, and the callers that take its TimedOut for a passed deadline are the same. Nothing on dev fails because of it yet. The only dev test that I found timing a pending pipe transfer against its deadline passed 200 of 200 local runs, and no CI run failed it in the past month. #1476 added the restore driver's test to feature/nvx-refactor, and it will reach dev with that branch. With overlapped() waiting again after WAIT_TIMEOUT until Instant::now() reaches the deadline, as ProcessHandle::wait does, the probe saw no early timeout.

Incident

• Workflow: CI run 42993194889, attempt 1, push to feature/nvx-refactor at d40228be1, which host: import retained types from their low-level owners (SL6.0b) #1477 (SL6.0b) landed.
• Failed job: nvx-rs / windows-latest, step Check nvx-rs, in the cargo test --locked --all-features command of the composite action's Test step (action.yml#L63-L71). Of the library's 1,471 tests, 1,453 passed, 17 were ignored, and this one failed. Required status check failed only because this job did.
• Runner: GitHub-hosted windows-latest, Windows Server 2025 Datacenter, image windows-2025-vs2026 20261103.298.1, runner 2.338.2, Rust 1.95.0.
• Second occurrence: CI run 42994995631, attempt 1, push at a53a2626d, which SL3.5a: provision typed EROFS/GPT images and bounded RAM uppers #1466 (SL3.5a) landed, failed the same job in the same way on the same image, with activate-read: 59.9994275s.
• Neither host: import retained types from their low-level owners (SL6.0b) #1477 nor SL3.5a: provision typed EROFS/GPT images and bounded RAM uppers #1466 changes the restore driver, its test, the transport, the session, or the platform layer: from 35cedfdbc, which host: drive a restore over NVXC for blocking callers (SL4.3) #1476 landed, to a53a2626d, the diff of nvx-rs/src/host/{restore_driver.rs,restore_driver/,transport.rs,session.rs,platform/} is empty. Both runs completed; neither was superseded or cancelled.

Decisive output, from the first run:

test host::restore_driver::tests::ready_has_sixty_seconds_and_start_thirty_from_ready_for_each_pending_accept_and_read has been running for over 60 seconds
test host::restore_driver::tests::ready_has_sixty_seconds_and_start_thirty_from_ready_for_each_pending_accept_and_read ... FAILED

failures:

---- host::restore_driver::tests::ready_has_sixty_seconds_and_start_thirty_from_ready_for_each_pending_accept_and_read stdout ----

thread '<unnamed>' (8516) panicked at src\host\restore_driver\tests.rs:489:9:
activate-read: 59.9993305s, Machine(RestoreError { phase: Activate, attribution: Unknown, evidence: Expired, guest_may_have_run: true, message: "restore failed during Activate: Expired", source: None })

thread 'host::restore_driver::tests::ready_has_sixty_seconds_and_start_thirty_from_ready_for_each_pending_accept_and_read' (2316) panicked at src\host\restore_driver\tests.rs:525:5:
a scoped thread panicked


failures:
    host::restore_driver::tests::ready_has_sixty_seconds_and_start_thirty_from_ready_for_each_pending_accept_and_read

test result: FAILED. 1453 passed; 1 failed; 17 ignored; 0 measured; 0 filtered out; finished in 74.85s

The test waits out the deadlines of six stalled restores at once (tests.rs#L445-L452, #L522-L530). In both runs only activate-read failed: its stand-in VM takes the activate message and never answers, and its restore reported Expired in the Activate phase.

History

Since #1476 added the test on 2026-11-11, it ran in these CI runs of feature/nvx-refactor and of the pull requests into it, through 15:38 UTC. The Windows job failed it in 2 runs of 10, and the Linux job in none.

Run 43050413053 has five attempts, which reran a failed artifact build; all five carry the nvx-rs jobs of attempt 1. #1479's description reports one more failure, locally on Windows: in a parallel run of some of the library's tests at f5436a776, activate-read expired after 59.99996 s.

Over a longer window, I read the log of every failed nvx-rs job of the CI runs created from 2026-10-12 through 2026-11-11, in the 776 attempts, among 2,669 runs, that failed, were cancelled, or were rerun: 61 failed jobs, 26 of them on Windows. Only these two failed because a Windows wait ended before its deadline.

Root cause

Permalinks point to d40228be1, the head of the first incident, and to dev at 9a58df1ff.

1. The test holds the restore to its budget. restore() allows 60 s from its call to the guest's Ready (restore_driver.rs#L44, #L125). check_ended starts its clock before it calls restore(), and requires at least that budget to pass before the restore fails (tests.rs#L461, #L486-L492). An elapsed time of 59.9993305 s therefore means that the restore reported Expired at least 0.67 ms before its own deadline, and one of 59.9994275 s at least 0.57 ms before.
2. activate-read ends in one long transport read. The stand-in VM stalls once it has the activate message (tests.rs#L112). The driver waits for the reply in ControlSession::activate, with the restore's deadline (restore_driver.rs#L213-L217), and HostConnection::next_event turns the time left, about 60 s less what connecting and attaching took, into a single transport read (transport.rs#L375).
3. overlapped() gives up before the deadline. The Windows transport runs every read and write through overlapped() (endpoint.rs#L348-L379). It passes WaitForSingleObject the timeout rounded down to whole milliseconds (#L363-L367), and on WAIT_TIMEOUT it cancels the transfer and reports TimedOut (#L369-L373, #L385), without comparing Instant::now() with the deadline. Rounding down drops up to a millisecond. Windows also measures the wait with its own timer, not with the performance counter that Instant reads, and the probe below shows the wait itself ending before the milliseconds that it was given.
4. Every layer above takes that TimedOut for a passed deadline. next_event returns it as it is (transport.rs#L389-L391), though HostConnectionError::TimedOut says that "The deadline passed" (#L181-L183). The session maps it to SessionError::TimedOut (session.rs#L454, #L65-L73), and the driver records it as Expired (restore_driver.rs#L465).
5. Only the steps that wait in one long transfer are exposed. The restore-ready event and the connection are waited for in slices of at most 50 ms, and Watch::slice compares Instant with the deadline before each (restore_driver.rs#L378-L385), so a slice that ends early only starts another. attach-read reads the broker's attach response with the same deadline as activate-read (restore_driver.rs#L207), so it is as exposed. maps-read's 30 s budget runs from Ready, which leaves the test the time to Ready to spare.
6. dev has the same defect. On dev, overlapped() differs only in waiting at least 1 ms (endpoint.rs#L290-L321, #L305-L309); cli: run cold blockless VMs through the verified lifecycle (SL3.4a2) #1441 dropped that minimum on feature/nvx-refactor, so that a zero timeout polls. HostConnection::next_event returns its TimedOut as HostConnectionError::TimedOut, "The deadline passed" (nvxs.rs#L237-L253, #L55-L57), and the CLI's ProbedTransport::read passes on the TimedOut of its last slice the same way (cli/session.rs#L113-L127). Transport::write_all promises TimedOut only if the write has not ended by its timeout (platform/mod.rs#L90-L93), which an early cancellation breaks as well. The Windows ProcessHandle::wait already does what overlapped() lacks: on WAIT_TIMEOUT it returns only once Instant::now() has reached the deadline, and otherwise waits again (process.rs#L171-L188).

Reproduction

The restore driver's test is only on feature/nvx-refactor, takes a minute, and fails only when its wait ends within a millisecond of the deadline, so I reproduced the mechanism instead, on a 20-thread Windows 11 Enterprise workstation (10.0.26300) with Rust 1.95.0, in a copy of dev at 9a58df1ff.

• dev's transport, as it is. A scratch test in endpoint/tests.rs (below) gives each of 8 threads a named pipe whose server neither reads nor writes. For 30 s, four of the threads time PipeTransport::read, and four write_all, with deadlines 20 to 80 ms away. Of 2,052 reads that timed out, 45 (2.2%) did before their deadline, the earliest by 1.218 ms; of 2,050 writes, 41 (2.0%) did, the earliest by 1.137 ms. A read that ends 1.218 ms early lost more than its rounded-down fraction: its WaitForSingleObject returned at least 0.2 ms before the milliseconds that it was given, as Instant measures them.
• With the sketch below. With overlapped() waiting for the time left rounded up, and again after WAIT_TIMEOUT until Instant::now() reaches the deadline, the same probe saw none of 2,070 reads and none of 2,068 writes time out before their deadline. The earliest ended 0.124 ms after it, and the median lateness stayed about 8 ms, as before.
• The dev test. host::cli::session::tests::endpoints::writes_to_a_slow_endpoint_end_by_their_deadline checks one pending write against its 200 ms deadline (tests.rs#L719-L726, #L1172-L1186). Built with CI's toolchain and features, it passed 200 of 200 runs with --exact --test-threads 1, so it does not catch the defect in practice.

/// Scratch probe, not for the repository: how often a pending transfer's `TimedOut` comes before
/// the deadline that its timeout stood for.
#[test]
fn probe_transfers_that_time_out_before_their_deadline() {
    let seconds = std::env::var("PROBE_SECS")
        .ok()
        .and_then(|value| value.parse().ok())
        .unwrap_or(30u64);
    let results = std::sync::Mutex::new(Vec::new());
    std::thread::scope(|scope| {
        for thread in 0..8u64 {
            let results = &results;
            scope.spawn(move || {
                let endpoint = format!(
                    r"\\.\pipe\nvx-probe-{}-{thread}-{}",
                    std::process::id(),
                    crate::host::store::LaunchId::generate().unwrap().as_str()
                );
                let name = wide(&endpoint);
                // SAFETY: the name is NUL-terminated; this creates a fresh local byte pipe.
                let server = owned(unsafe {
                    CreateNamedPipeW(
                        name.as_ptr(),
                        PIPE_ACCESS_DUPLEX | FILE_FLAG_FIRST_PIPE_INSTANCE,
                        PIPE_TYPE_BYTE | PIPE_READMODE_BYTE | PIPE_WAIT | PIPE_REJECT_REMOTE_CLIENTS,
                        1,
                        4096,
                        4096,
                        0,
                        ptr::null(),
                    )
                })
                .unwrap();
                let mut transport =
                    connect_endpoint(&endpoint, std::process::id(), Duration::from_secs(2))
                        .unwrap();
                let writes = thread % 2 == 1;
                let data = vec![7u8; 64 * 1024];
                let mut buffer = [0u8; 64];
                let began = Instant::now();
                let mut index = thread;
                let mut outcomes = Vec::new();
                while began.elapsed() < Duration::from_secs(seconds) {
                    index += 8;
                    // 20 to 80 ms away, with a part below a millisecond, as a pending read's is.
                    let deadline =
                        Instant::now() + Duration::from_micros(20_000 + (index * 7_919) % 60_000);
                    let timeout = deadline.saturating_duration_since(Instant::now());
                    let error = if writes {
                        transport.write_all(&data, Some(timeout)).unwrap_err()
                    } else {
                        transport.read(&mut buffer, Some(timeout)).unwrap_err()
                    };
                    assert_eq!(error.kind(), io::ErrorKind::TimedOut, "{error}");
                    let now = Instant::now();
                    let micros = if now >= deadline {
                        (now - deadline).as_micros() as i64
                    } else {
                        -((deadline - now).as_micros() as i64)
                    };
                    outcomes.push((writes, micros));
                }
                drop(transport);
                drop(server);
                results.lock().unwrap().extend(outcomes);
            });
        }
    });
    let outcomes = results.into_inner().unwrap();
    for (label, writes) in [("reads", false), ("writes", true)] {
        let mut micros: Vec<i64> = outcomes
            .iter()
            .filter(|(kind, _)| *kind == writes)
            .map(|(_, micros)| *micros)
            .collect();
        micros.sort_unstable();
        let early = micros.iter().filter(|micros| **micros < 0).count();
        eprintln!(
            "PROBE {label}: {} timed out, {early} before their deadline; earliest {} us, median {} \
             us, latest {} us after it",
            micros.len(),
            micros[0],
            micros[micros.len() / 2],
            micros[micros.len() - 1]
        );
    }
}

# PowerShell 7, from nvx-rs/ of the copy.
$env:NVX_BUNDLE = 'skip'
$env:PROBE_SECS = '30'
cargo +1.95.0 test --locked --all-features --lib -- --exact host::platform::windows::endpoint::tests::probe_transfers_that_time_out_before_their_deadline --nocapture

# dev at 9a58df1ff
PROBE reads: 2052 timed out, 45 before their deadline; earliest -1218 us, median 8093 us, latest 33602 us after it
PROBE writes: 2050 timed out, 41 before their deadline; earliest -1137 us, median 8371 us, latest 36624 us after it
# with the sketch
PROBE reads: 2070 timed out, 0 before their deadline; earliest 124 us, median 7979 us, latest 17137 us after it
PROBE writes: 2068 timed out, 0 before their deadline; earliest 159 us, median 7862 us, latest 16588 us after it

--- a/nvx-rs/src/host/platform/windows/endpoint.rs
+++ b/nvx-rs/src/host/platform/windows/endpoint.rs
@@ -294,4 +294,5 @@ fn overlapped(
     start: impl FnOnce(HANDLE, *mut OVERLAPPED) -> i32,
 ) -> io::Result<usize> {
+    let deadline = timeout.map(|timeout| Instant::now() + timeout);
     // SAFETY: OVERLAPPED is plain data for which all-zero bytes are a valid initial state.
     let mut overlapped: OVERLAPPED = unsafe { std::mem::zeroed() };
@@ -303,11 +304,19 @@ fn overlapped(
         }
     }
-    let wait = timeout.map_or(INFINITE, |timeout| {
-        u32::try_from(timeout.as_millis())
-            .unwrap_or(INFINITE - 1)
-            .clamp(1, INFINITE - 1)
-    });
-    // SAFETY: the event belongs to the caller.
-    let signaled = unsafe { WaitForSingleObject(overlapped.hEvent, wait) } == WAIT_OBJECT_0;
+    let signaled = loop {
+        let wait = deadline.map_or(INFINITE, |deadline| {
+            let left = deadline.saturating_duration_since(Instant::now());
+            u32::try_from(left.as_nanos().div_ceil(1_000_000))
+                .unwrap_or(INFINITE - 1)
+                .min(INFINITE - 1)
+        });
+        // SAFETY: the event belongs to the caller.
+        if unsafe { WaitForSingleObject(overlapped.hEvent, wait) } == WAIT_OBJECT_0 {
+            break true;
+        }
+        if deadline.is_none_or(|deadline| Instant::now() >= deadline) {
+            break false;
+        }
+    };
     if !signaled {
         // SAFETY: cancels only the operation that uses this OVERLAPPED.

Impact

• feature/nvx-refactor. The test fails about one Windows run in five, which fails nvx-rs / windows-latest and Required status check; host: read strict snapshots through the platform layer (SL6.0a) #1479 already reports it as a pre-existing flake. The test reaches dev with the branch.
• Behavior. On Windows, a control-session read or write, and the restore-driver steps built on one, can give up about a millisecond before its deadline. Only a caller that checks the deadline exactly, as the test does, notices.
• Contracts. HostConnectionError::TimedOut says that the deadline passed, and Transport::write_all that the timeout did. On Windows, neither holds.

Suggested fix

Make overlapped() keep its deadline, on both branches:

1. Take the deadline from the timeout when the call starts.
2. Wait for the time left rounded up to whole milliseconds. Alternatively, as ProcessHandle::wait does with wait_step, sleep a remainder below a millisecond and then poll, so that the last check costs that remainder rather than a timer tick.
3. After WAIT_TIMEOUT, wait again while Instant::now() is before the deadline, and cancel the transfer only once it is not. A zero timeout still polls once, as cli: run cold blockless VMs through the verified lifecycle (SL3.4a2) #1441 needs on feature/nvx-refactor.

The sketch above does 1 to 3, except that it would repeat a failed wait until the deadline rather than end at once.

That covers every pending read and write of the Windows transport, and so the CLI's session, the restore driver, and the restore-ready listener. Keep the test's assertion, which checks the budget that restore() documents. Add a Windows test of the transport that, like the probe, times a few hundred pending reads and writes whose deadlines fall between milliseconds, and fails if any TimedOut comes before its deadline; at the probe's 2%, a few hundred transfers catch the defect nearly every run.

The failures are on feature/nvx-refactor, so a fix there stops them. dev needs the fix too, and a fix on dev changes the lines that #1441 changed on the branch.

Related work

• host: drive a restore over NVXC for blocking callers (SL4.3) #1476 (SL4.3, for nvx-rs slimming 3.2.1: NVXC asks for a capture and activates a restore, and a blocking driver restores #1113) added the restore driver and this test to feature/nvx-refactor.
• host: read strict snapshots through the platform layer (SL6.0a) #1479 reports the failure, in run 42994995631 and locally, as a pre-existing flake.
• cli: run cold blockless VMs through the verified lifecycle (SL3.4a2) #1441 dropped the 1 ms minimum wait of overlapped() on feature/nvx-refactor (24bf68f39), so that a zero timeout polls.
• nvx-rs: fix store lock release, Windows kill and wait, and keep every console #790, which took over nvx-rs: sleep a Windows wait's last millisecond instead of a timer tick #792, and nvx-rs: sleep a Linux wait's last millisecond instead of polling a whole one #815 made ProcessHandle::wait sleep its last fraction of a millisecond on Windows and Linux. It never returns before its deadline; overlapped() kept its rounding down.
• nvx-rs: extract the NVX mechanics from aci_edge_sandboxes #519 brought overlapped() into nvx-rs.
• 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, nvx-rs: the output-limit session test can close the stream before its guest's last send, so output_beyond_the_guest_limit_breaks_the_protocol panics with BrokenPipe (flaky nvx-rs / windows-latest) #1051, and ci: the IMDS deadline tests need the request's worker to reach connect within 0.2 s, so a runner stall fails them (flaky NVX CLI / Windows) #1239 are other Windows flakes, with other causes.

Done when

• On feature/nvx-refactor, overlapped() never reports TimedOut before its deadline, a Windows regression test checks it, and the restore driver's test keeps its assertion.
• dev has the same fix, directly or when feature/nvx-refactor merges.