Track managed sandbox lifecycle bugs: on Windows, provision waits out its timeout for a lock file that refuses access for good #464

Current bug hunt: 2026-10-23

Baseline: origin/dev at c406f80d. Every permalink below uses this SHA.

Hunt: one time-boxed pass of about 45 minutes, which started at 06:00 −03:00 on 2026-10-23 and stopped when finding 1 was confirmed, at about 06:27. It focused on the nvx-rs host store's lifecycle locks and removal, which #754 reworked, and on the nvx-rs sandbox lifecycle lock over them, which no open bug-hunt issue covers. This issue is reopened because the sandbox lifecycle that it tracks, whose lifecycle lock #476 added, now lives in nvx-rs sandbox. No repository files were modified and nothing was committed. The reproduction ran on Windows 11 (NTFS) with Rust 1.95.0, as a scratch test in a git archive copy of the baseline's nvx-rs, outside the checkout.

• Make provision fail at once with the denied access, as start, stop, and deprovision do, and add a CLI regression test.

1. On Windows, provision waits out its timeout for a lock file that refuses access for good, and reports it as a transition in progress

• Impact: the provision fails anyway, but only after the whole lifecycle timeout, and with an error that points to a concurrent transition that does not exist, hiding the real cause. A caller that retries transition in progress errors keeps retrying a failure that can't clear on its own.
• Likelihood: low. It needs an existing state directory, without config.json, whose sandbox.lock Windows refuses to open for writing for good: a read-only file, as a copy or restore can leave, or a directory at that path.

Trace:

• provision accepts an existing state directory and then calls LifecycleLock::acquire(&state_dir, timeout, true).
• LifecycleLock::acquire tries the store's lock every 25 ms with a deadline that has passed, so that it can check Ctrl-C between tries, and classifies each failure by the Python OSError class of its cause (os_error_class). For a provision on Windows, its PermissionDenied arm retries every denial, for "a removed lock file until its last handle closes", until the deadline, and then fails with transition_in_progress().
• Since 1b42703 ("nvx-rs: stop waiting for a lock file that Windows refuses for good"), the store tells those cases apart itself. take_lifecycle_lock probes a denied lock file with an open without access rights. It waits for a removed one and reports ErrorKind::TimedOut once the deadline passes. It fails with the denied access once a second open at once is refused too, as lock_existing's contract says. The store tests check both: locks_wait_for_a_removed_lock_file_that_a_handle_keeps (both locks report TimedOut, which acquire's first arm already retries) and locks_refuse_a_lock_file_that_refuses_access_for_good (both lock_for_provision and lock_existing fail at once for a read-only lock file and for a directory).
• That commit changed only the store. The CLI arm, from 345eac3, still swallows the denial that the store now reports as permanent. The arm applies only to provision: start, stop, exec, and deprovision report the same denial at once.

Trigger: on Windows, a private state directory without config.json whose sandbox.lock is read-only, or is a directory, then nvx-rs sandbox provision --state-dir DIR …, or nvx.py sandbox provision, which runs it.

Expected: provision fails at once, as start and deprovision on the same directory do: error: cannot lock DIR\sandbox.lock: [WinError 5] Access is denied.

Actual: provision retries for its whole --timeout (60 s by default), and then fails with error: another lifecycle transition of the sandbox is still in progress.

Reproduction: this test, appended to a scratch copy of nvx-rs/tests/cli.rs, uses its populated_root, provision, lifecycle, run, and text helpers with the fake OpenVMM, and passes --timeout 5 to keep the run short. Run it with cargo +1.95.0 test --locked --features cli,testing --test cli zz_repro -- --nocapture:

#[cfg(windows)]
#[test]
fn zz_repro_provision_waits_out_a_lock_file_refused_for_good() {
    let root = populated_root();
    // Control: a fresh state directory provisions at once.
    let started = Instant::now();
    let mut arguments = provision(&root, "control", "fake_guest_features=16");
    arguments.extend(["--timeout".to_owned(), "5".to_owned()]);
    let output = run(&root, &arguments);
    println!(
        "control provision: status {:?} after {:.2?}; stderr: {:?}",
        output.status.code(),
        started.elapsed(),
        text(&output.stderr)
    );
    for kind in ["read-only", "directory"] {
        let state = root.path.join(kind);
        nvx::host::store::SandboxStore::create(&state).unwrap();
        let lock = state.join("sandbox.lock");
        if kind == "read-only" {
            fs::write(&lock, b"").unwrap();
            let mut permissions = fs::metadata(&lock).unwrap().permissions();
            permissions.set_readonly(true);
            fs::set_permissions(&lock, permissions).unwrap();
        } else {
            fs::create_dir(&lock).unwrap();
        }
        for operation in ["provision", "start", "deprovision"] {
            let mut arguments = if operation == "provision" {
                provision(&root, kind, "fake_guest_features=16")
            } else {
                lifecycle(operation, &root, kind)
            };
            arguments.extend(["--timeout".to_owned(), "5".to_owned()]);
            let started = Instant::now();
            let output = run(&root, &arguments);
            println!(
                "{kind} sandbox.lock, {operation}: status {:?} after {:.2?}; stderr: {:?}",
                output.status.code(),
                started.elapsed(),
                root.normalize(&text(&output.stderr))
            );
        }
        if kind == "read-only" {
            let mut permissions = fs::metadata(&lock).unwrap().permissions();
            #[allow(clippy::permissions_set_readonly_false)]
            permissions.set_readonly(false);
            fs::set_permissions(&lock, permissions).unwrap();
        }
    }
}

Reproduction output ({root} is the test's temporary root):

control provision: status Some(0) after 303.37ms; stderr: ""
read-only sandbox.lock, provision: status Some(1) after 5.02s; stderr: "error: another lifecycle transition of the sandbox is still in progress\n"
read-only sandbox.lock, start: status Some(1) after 21.38ms; stderr: "error: cannot lock {root}\\read-only\\sandbox.lock: [WinError 5] Access is denied\n"
read-only sandbox.lock, deprovision: status Some(1) after 16.16ms; stderr: "error: cannot lock {root}\\read-only\\sandbox.lock: [WinError 5] Access is denied\n"
directory sandbox.lock, provision: status Some(1) after 5.02s; stderr: "error: another lifecycle transition of the sandbox is still in progress\n"
directory sandbox.lock, start: status Some(1) after 16.89ms; stderr: "error: cannot lock {root}\\directory\\sandbox.lock: [WinError 5] Access is denied\n"
directory sandbox.lock, deprovision: status Some(1) after 16.33ms; stderr: "error: cannot lock {root}\\directory\\sandbox.lock: [WinError 5] Access is denied\n"
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 27 filtered out; finished in 10.44s

Suggested fix: remove the arm at lock.rs#L138-L140, so that a denial that the store reports goes to error_with_cause, as it does for the other transitions. The store already reports a removed lock file as TimedOut, which the first arm retries. If a provision must also wait for a state directory that a concurrent deprovision left pending deletion, on a file system without POSIX deletion, handle that in the store's provision_lock with the same no-access probe. Don't retry every denial in the CLI. Add Windows tests at the CLI level: a provision with a read-only sandbox.lock fails at once with the denied access, and a provision still waits for a delete-pending lock file (with a helper like the store tests' delete_pending) and succeeds once its handle closes.

Fix check: the scratch copy was rerun with only those three lines removed, then restored. A second scratch test made sandbox.lock delete-pending, as a file system without POSIX deletion keeps a removed lock file, with SetFileInformationByHandle(FileDispositionInfo) like the store tests' delete_pending. It held that handle for 1 s while provision ran with --timeout 10.

# baseline (c406f80d)
delete-pending sandbox.lock held 1s, provision: status Some(0) after 1.01s; stderr: ""
read-only sandbox.lock, provision: status Some(1) after 5.02s; stderr: "error: another lifecycle transition of the sandbox is still in progress\n"
directory sandbox.lock, provision: status Some(1) after 5.02s; stderr: "error: another lifecycle transition of the sandbox is still in progress\n"
# with lock.rs#L138-L140 removed
delete-pending sandbox.lock held 1s, provision: status Some(0) after 1.02s; stderr: ""
read-only sandbox.lock, provision: status Some(1) after 17.73ms; stderr: "error: cannot lock {root}\\read-only\\sandbox.lock: [WinError 5] Access is denied\n"
directory sandbox.lock, provision: status Some(1) after 18.38ms; stderr: "error: cannot lock {root}\\directory\\sandbox.lock: [WinError 5] Access is denied\n"

With the arm removed, cargo +1.95.0 test --locked --features cli,testing passed --lib host::cli::sandbox::lock (4 tests), --lib host::store (52 passed, 1 ignored), and --test cli (27 tests, including the recorded Windows scenarios).

#[cfg(windows)]
#[allow(unsafe_code)]
#[test]
fn zz_repro_provision_waits_for_a_delete_pending_lock_file() {
    use std::os::windows::fs::OpenOptionsExt;
    use std::os::windows::io::AsRawHandle;

    use windows_sys::Win32::Foundation::HANDLE;
    use windows_sys::Win32::Storage::FileSystem::{
        DELETE, FILE_DISPOSITION_INFO, FILE_SHARE_DELETE, FILE_SHARE_READ, FILE_SHARE_WRITE,
        FileDispositionInfo, SetFileInformationByHandle,
    };

    let root = populated_root();
    let state = root.path.join("pending");
    nvx::host::store::SandboxStore::create(&state).unwrap();
    let lock = state.join("sandbox.lock");
    fs::write(&lock, b"").unwrap();
    let file = fs::OpenOptions::new()
        .access_mode(DELETE)
        .share_mode(FILE_SHARE_READ | FILE_SHARE_WRITE | FILE_SHARE_DELETE)
        .open(&lock)
        .unwrap();
    let disposition = FILE_DISPOSITION_INFO { DeleteFile: true };
    // SAFETY: the handle is open, and the information is a FILE_DISPOSITION_INFO of its size.
    let set = unsafe {
        SetFileInformationByHandle(
            file.as_raw_handle() as HANDLE,
            FileDispositionInfo,
            (&raw const disposition).cast(),
            size_of::<FILE_DISPOSITION_INFO>() as u32,
        )
    };
    assert_ne!(set, 0, "{}", std::io::Error::last_os_error());
    let mut arguments = provision(&root, "pending", "fake_guest_features=16");
    arguments.extend(["--timeout".to_owned(), "10".to_owned()]);
    let started = Instant::now();
    let output = thread::scope(|scope| {
        let worker = scope.spawn(|| run(&root, &arguments));
        thread::sleep(Duration::from_secs(1));
        drop(file);
        worker.join().unwrap()
    });
    println!(
        "delete-pending sandbox.lock held 1s, provision: status {:?} after {:.2?}; stderr: {:?}",
        output.status.code(),
        started.elapsed(),
        root.normalize(&text(&output.stderr))
    );
}

Checked, not filed

• Store lock retries (nvx-rs/src/host/store/mod.rs): take_lock's try_lock loop, pause, and Races::lost try once with a deadline that has passed, and alternate an immediate retry with a paused one, so lost races neither spin nor outlive the deadline.
• Store removal (nvx-rs/src/host/store/lifecycle.rs): remove_contents refuses while launch.json or runtime.json exists, removes the configuration record last, and refuses foreign entries. remove_directory_after and Lingering::wait remove the directory only while the path still names the held identity, and Lingering::wait reports a reprovision by looking up the configuration record by path. LockedStore's Drop removes only its own lock file, and only when the record is missing. Reviewed only; no reproduction.
• Caller file declarations (nvx-rs/src/host/store/caller.rs): CallerFiles refuses separators, Windows-reserved characters and device names, non-portable characters, the store's names in any ASCII case, both temporary-file forms, and .nfs*. is_store_temporary and is_report_staging match the names that write_private and the tempfile crate give. Reviewed only.

Validation limits

• Only Windows 11 on NTFS was exercised, with the fake OpenVMM of nvx-rs's CLI tests. No hypervisor or real OpenVMM was needed or used. Linux takes neither the CLI arm (cfg!(windows)) nor the store's Windows probe, so it isn't affected.
• A removed lock file that a file system without POSIX deletion keeps was simulated on NTFS with a non-POSIX delete disposition, as the store tests do, not on such a file system. A state directory that becomes pending deletion between prepare_state_directory and the lock, which the CLI arm may also have retried, was reviewed only.
• python scripts\nvx.py verify wasn't needed for this nvx-rs-only reproduction. The openvmm submodule of the checkout is uninitialized and was left untouched.

Earlier findings

python -B C:\Temp\repro_control_write_timeout.py C:\path\to\nvx

import sys
import threading
import time
import uuid
from pathlib import Path

import _winapi

sys.dont_write_bytecode = True
sys.path.insert(0, str(Path(sys.argv[1]).resolve() / "scripts"))
from nvx_tools import control_session


def read_exact(handle, length):
    data = bytearray()
    while len(data) < length:
        chunk, status = _winapi.ReadFile(handle, length - len(data))
        assert status == 0 and chunk, (status, chunk)
        data.extend(chunk)
    return bytes(data)


name = rf"\\.\pipe\nvx-write-timeout-{uuid.uuid4().hex}"
server = _winapi.CreateNamedPipe(
    name, _winapi.PIPE_ACCESS_DUPLEX, _winapi.PIPE_WAIT,
    1, 1024, 1024, 0, _winapi.NULL,
)
capability = b"\x11" * 32
instance = b"\x22" * 16
attached = threading.Event()
finished = threading.Event()
observed = {}
timeout = 0.05


def client():
    try:
        with control_session.ControlSession.connect(
            Path(name), capability, 2.0
        ) as session:
            observed["started"] = time.monotonic()
            attached.set()
            session.exec(
                ("/bin/true", "a" * 4000),
                timeout_ms=0,
                response_timeout=timeout,
            )
    except Exception as error:
        observed["error"] = f"{type(error).__name__}: {error}"
    finally:
        observed["finished"] = time.monotonic()
        finished.set()


worker = threading.Thread(target=client, daemon=True)
worker.start()
try:
    try:
        _winapi.ConnectNamedPipe(server)
    except OSError as error:
        if error.winerror != 535:  # ERROR_PIPE_CONNECTED
            raise
    header = control_session.OUTER_HEADER.unpack(
        read_exact(server, control_session.OUTER_HEADER.size)
    )
    assert header[:4] == (
        b"NVXS", 1, control_session.OUTER_HOST_ATTACH, 0
    ), header
    assert read_exact(server, header[-1]) == capability
    ready = control_session.OUTER_HEADER.pack(
        b"NVXS", 1, control_session.OUTER_READY, 0, instance, 1, 0, 0
    )
    written, status = _winapi.WriteFile(server, ready)
    assert status == 0 and written == len(ready), (written, status)
    assert attached.wait(2.0), observed
    blocked = not finished.wait(0.35)
    elapsed = time.monotonic() - observed["started"]
    print(f"authenticated attach completed: {attached.is_set()}")
    print(f"response_timeout: {timeout:.3f}s")
    print(f"still blocked after {elapsed:.3f}s: {blocked}")
    assert blocked, observed
finally:
    _winapi.CloseHandle(server)
    worker.join(2.0)
assert not worker.is_alive(), "client did not exit after server closed"
duration = observed["finished"] - observed["started"]
print(f"returned after server closed, at {duration:.3f}s")
print(f"result: {observed.get('error', 'unexpected success')}")
assert str(observed.get("error", "")).startswith(
    ("ControlEndpointClosed:", "BrokenPipeError:")
), observed
print("CONFIRMED: a blocked pipe write bypasses the operation timeout")

authenticated attach completed: True
response_timeout: 0.050s
still blocked after 0.351s: True
returned after server closed, at 0.352s
result: BrokenPipeError: [Errno 32] Broken pipe
CONFIRMED: a blocked pipe write bypasses the operation timeout