Skip to content

openvmm ci: investigate intermittent Linux/KVM UEFI boot stalls on lazily fetched VHD reads #170

Open

Description

Status update - October 10, 2026: Still unresolved. With the
diagnostics that #173 retains, four Linux/KVM jobs from October 5 to 10 timed
out eight UEFI boot tests, both before and after BootSuccess. Every stalled
VM had a guest read outstanding on its lazily fetched boot disk, and three of
the four jobs logged Connection reset by peer from OpenVMM's HTTP blob
client, which has no timeout, retry, or keepalive. The
October 10 investigation update
has the evidence and proposed changes.

The September 21 investigation update
includes 28 focused native-KVM reproductions, six verified focused nested-KVM
reproductions, both complete KVM suites, exact boot-stage timings, artifact
identities, environment differences, and next discriminating checks.
A later CI run also passed on the original failing runner name and ID.

The original incident report is preserved below. Its references to the
"current dev head" describe the state at the incident, not the latest branch tip.


Summary

Linux/KVM CI intermittently stalls while booting the Ubuntu 25.04 UEFI guest for
multiarch::ic::openvmm_uefi_x64_ubuntu_2504_server_x64_timesync_ic.

The failing VM reached VM ready, began waiting for the firmware boot event, saved
one framebuffer screenshot, and then reported an unchanged framebuffer until Petri's
10-minute watchdog aborted the test. The test body never logged a guest time, so the
stall occurred before the time-sync assertions ran.

An immediate failed-jobs rerun passed on a different virtual-machine runner. The
same OpenVMM revision also passed this test in several earlier virtual-machine runs
and in both focused and full-suite bare-metal reproductions.

Current incident

  • Workflow: CI, run 35651853023, attempt 1
  • NVX head: caed7fad98837ac64310b5835370a47161e98058
  • OpenVMM source: 64054d7a7275c2c6d66c2bbb10f77ec777e11889
  • Failed job: OpenVMM vmm-tests / Linux / KVM
  • Failed step: Run OpenVMM tests on KVM
  • Runner: azure-kvm-esaurez-nvx-ci-linux-kvm-vmss000004
  • Labels: self-hosted, linux, kvm, virtual-machine
  • Test result: 57 passed, 1 failed, 37 skipped
  • Failed test duration: 602.044s
  • Full test phase: 941.838s
  • Classification: current dev head; not cancellation or supersession

The downstream Required status check failure only reflected the failed
openvmm-vmm-tests result.

Decisive trace

[petri] VM ready
[petri] Waiting for boot event...
[petri] Screenshot saved.
[petri] No change in framebuffer, skipping screenshot.
...
FAIL [602.044s] multiarch::ic::openvmm_uefi_x64_ubuntu_2504_server_x64_timesync_ic
Test timed out

The last substantive OpenVMM activity was approximately 4.85 seconds after launch.
Petri then emitted unchanged-framebuffer messages every two seconds until the global
watchdog fired. There were no guest time messages from the test body.

The same job successfully booted other Ubuntu 25.04 UEFI variants, including the
plain boot test, secure boot, VMGS, VLAN, and battery tests.

Immediate rerun

The rerun used the same NVX and OpenVMM revisions but moved from
azure-kvm-esaurez-nvx-ci-linux-kvm-vmss000004 to azure-kvm-3.

Recent successful virtual-machine runs

All entries below used the same OpenVMM pin.

Run Runner Affected test Full test phase
35603041650 azure-kvm-esaurez-nvx-ci-linux-kvm-vmss000005 277.662s 611.783s
35607488114 azure-kvm-esaurez-nvx-ci-linux-kvm-vmss000005 273.927s 607.584s
35609983784 azure-kvm-esaurez-nvx-ci-linux-kvm-vmss000005 282.185s 612.922s
35622360833 azure-kvm-2 283.047s 613.207s
35628432072 azure-kvm-1 303.827s 658.900s

These successful runs show that this test is consistently the longest selected KVM
test on virtual-machine runners, normally taking approximately 4.6-5.1 minutes.

Bare-metal reproduction

An isolated exact-SHA checkout was tested on prometheus32
(linux-kvm-baremetal):

cargo xflowey vmm-tests-run --release --ci-profile --skip-vhd-prompt \
  --filter "test(/^multiarch::ic::openvmm_uefi_x64_ubuntu_2504_server_x64_timesync_ic$/)"
  • Focused test: passed in 15.263s.
  • Original python3 scripts/nvx.py test-openvmm --backend kvm command: 58/58
    passed.
  • Affected test under the full suite: 19.635s.
  • Full test phase: 36.284s.
  • No OpenVMM process remained afterward.

The host-type difference means this does not reproduce the nested/virtual-machine
condition, but it helps rule out a deterministic failure in the pinned source,
guest image, or test body.

Relevant control flow

timesync_ic first awaits PetriVmBuilder::run(). That builder waits for the
expected firmware boot event before returning the VM and agent to the test. UEFI
guests do not have the PCAT-only flaky_boot timeout/reset workaround, so this wait
can continue until the global 10-minute watchdog aborts the test.

Impact and investigation requests

  • A single intermittent boot stall fails the required dev CI status despite all
    other selected KVM tests passing.
  • The job log references petri.log and screenshot.png, but the workflow does not
    upload the failed test-results directory, so the screenshot and complete
    diagnostics are unavailable after the runner workspace is recycled.

Suggested next checks:

  1. Preserve target/vmm_tests/test_results as a workflow-attempt-scoped artifact
    when a VMM test fails.
  2. Inspect the frozen screenshot and Petri/OpenVMM diagnostics from the next
    occurrence.
  3. Determine why this UEFI guest can stop producing boot progress after device and
    framebuffer initialization on nested KVM.
  4. Decide whether UEFI boot-event waiting needs a bounded diagnostic/reset path
    analogous to the existing PCAT flaky_boot handling, without merely extending
    or retrying the overall test timeout.

Note

Runner naming update (2026-10-07): Names in linked historical jobs and dated tables remain exactly as GitHub reported them. Current sequential aliases and runner registrations are mapped by VM instance in #211's rename note. Use the current name when connecting to or scheduling a runner.

Activity

  1. ppenna commented on Sep 21, 2026

    @ppenna
    ContributorAuthor

    Investigation update - September 21, 2026

    The intermittent boot stall is still unresolved. No OpenVMM runtime fix is
    claimed. The source-matched native and nested KVM reproductions below all passed,
    including cold-image-cache and CPU-constrained cases.

    Draft diagnostics PR: #173, commit
    44e99cde391f2977fcfdd4e0c6b66a9f59dd7f3b, branch
    ci/issue-170-vmm-diagnostics, against dev.

    The PR retains failed Petri logs, screenshots, and watchdog inspection data for
    seven days, with OS/backend/run-ID/attempt-scoped artifact names. It does not
    change the OpenVMM pin or source, test filters, assertions, timeouts, resets, or
    retries. It is intentionally draft; skipped backend checks are not runtime
    validation. A new failure after the diagnostics change is enabled is still
    needed to capture the original guest state.

    1. Exact incident and additional Azure evidence

    The original failure remains
    run 35651853023, attempt 1,
    job 106505935698,
    step Run OpenVMM tests on KVM.

    • NVX: caed7fad98837ac64310b5835370a47161e98058.
    • OpenVMM: 64054d7a7275c2c6d66c2bbb10f77ec777e11889.
    • This was a dev push failure, not a cancelled or superseded PR run.
      It was the current dev head at the incident, not the current head now.
    • The affected test failed after 602.044s; the suite reported
      57 passed, 1 failed, 37 skipped in 941.838s.
    • The downstream required-status failure merely reflected the VMM-test failure.

    Freshly checked logs add two successful runs beyond the original report:

    Run / attempt NVX head KVM runner Affected test Full KVM test phase
    35651853023 / 2 caed7fad98837ac64310b5835370a47161e98058 azure-kvm-3 PASS, 285.252s 58/58, 620.444s
    35661114943 / 1 4fff1a9e49f70f48aa64c009b0366649fee99798 azure-kvm-2 PASS, 278.708s 58/58, 611.734s
    35665322222 / 1 717345a61ce212b103603864d37b0d3e26acb61c azure-kvm-esaurez-nvx-ci-linux-kvm-vmss000004 PASS, 275.602s 58/58, 605.967s

    All use the same OpenVMM pin; each successful suite skipped 37 unselected tests.
    The last row used the original failing runner name and the same GitHub runner
    ID, 31
    . Its KVM job completed at 2026-09-21T23:14:46Z. That argues against a
    permanently broken runner registration, but does not establish that the host was
    never rebooted/reimaged or that its transient state was unchanged.

    The original failed runner and its successful rerun reported:

    • Microsoft Azure Linux 3.0, kernel 6.6.150.1-1.azl3.
    • Eight visible CPUs, Intel Xeon Platinum 8370C, approximately 31.3 GB RAM.
    • rustc 1.98.1 (48a229cea 2026-09-01).
    • cargo 1.98.1 (797e8a9bc 2026-08-05).
    • cargo-nextest 0.9.133, ci profile.
    • Mu/MSVM UEFI release v26.0.31,
      RELEASE-X64-VS2022-artifacts.tar.gz.
    • Lazy HTTP fetching of guest disk data was enabled.

    2. The stall boundary is narrower than "timesync failed"

    The failing VM configuration was a standard x86-64 UEFI guest with two VPs,
    4 GiB RAM, VMBus/SCSI storage, secure boot disabled, and an RTC offset of
    -40,000,000 ms (-40,000 seconds). The timesync test deliberately starts the
    RTC in the past. Its comparison loop runs only after config.run().await
    returns a VM and connected agent; it checks up to 30 samples for a guest clock
    within ten seconds of host time.

    The original embedded log timestamps are UTC. GitHub prints many of these
    captured lines later, when nextest reports the failure; use the embedded
    timestamps rather than the outer 20:54:45Z replay timestamps.

    Embedded timestamp / OpenVMM elapsed time Observed progress
    20:39:05.356465Z Petri starts its normal startup save/restore verification.
    20:39:05.361630Z VM ready: startup/save-restore completed.
    20:39:05.361662Z Waiting for boot event...
    About 1.86-1.90s after OpenVMM launch VMBus version negotiation, synthetic video setup/framebuffer mapping, and SCSI channel/protocol initialization complete.
    20:39:07.368066Z First screenshot saved. Its contents are unavailable.
    OpenVMM 4.854711514s Last ordinary device trace: watchdog_core: write 0 reg=Config on VP 0.
    Following ten minutes Repeated unchanged-framebuffer messages; no Got boot event: BootSuccess and no guest time message.
    20:49:05.362027Z Petri's ten-minute watchdog starts diagnostic collection.
    OpenVMM about 601.848s Both VP 0 and VP 1 stop on request; VMBus processes an inspection request.
    20:49:05.367812Z vmm inspect task finished.
    20:49:05.367968Z Diagnostic collection completes; Petri aborts the test.

    New useful observation: the VMM was responsive enough to stop both VPs and
    complete inspection in approximately 5.7 ms at the timeout. This is not
    evidence that the entire runner or VMM process was frozen. It still does not
    identify whether guest execution was spinning, waiting on I/O, or missing an
    interrupt.

    The trace explicitly references:

    test_results/
      multiarch__ic__openvmm_uefi_x64_ubuntu_2504_server_x64_timesync_ic/
        petri.log
        uefi.log
        openvmm.log
        screenshot.png
        timeout_inspect_vmm.log
    

    The watchdog did produce timeout_inspect_vmm.log; collection was not the
    failure. Retention was.

    3. Recovery of the original diagnostic files was checked

    • The Actions artifact API lists 13 artifacts for run 35651853023,
      consisting of executables/provenance, guest artifacts, benchmark results, and
      release packages. None contains the Petri VMM-test diagnostics.
    • The printed openvmm.dev/test-results link is not proof of an upload. The
      viewer's Azure Blob listing for prefix 35651853023_1/ returned
      <Blobs /> with no continuation token when checked on September 21.
    • The successful rerun and later successful jobs do not print the complete
      successful test's Petri trace into the job log, so their boot-event and
      agent-readiness timings cannot be reconstructed from the Actions console
      alone.
    • A collected shared GNU executable provenance artifact confirms a clean
      OpenVMM source at the incident pin. That shared build is not proof of
      the hash of the independently Flowey-built executable used by the VMM-test
      job.

    The failed screenshot, guest serial file, and inspection attachment have not
    been recovered. The passing reproduction's screenshot must not be substituted
    for the failed guest's screenshot.

    4. Extended native-KVM reproduction on prometheus32

    Used an isolated checkout at
    /home/ppenna/nvx-issue170-53d01ce9; the developer's original checkout was
    preserved.

    • NVX source: caed7fad98837ac64310b5835370a47161e98058.
    • OpenVMM source: 64054d7a7275c2c6d66c2bbb10f77ec777e11889, unchanged.
    • Host: Ubuntu 26.04, kernel 7.0.0-30-generic, Intel Xeon Silver 4114,
      40 logical CPUs, about 91 GiB RAM.
    • Host profile: linux-kvm-baremetal; /dev/kvm readable/writable.
    • Build toolchain: Rust/Cargo 1.98.0; nextest 0.9.133.
    • Fresh source build, release mode, original ci test profile.
    • Build-only resource settings: CARGO_BUILD_JOBS=8, CARGO_INCREMENTAL=0.
    • Explicit cold cases used a new PETRI_CACHE_DIR, without deleting another
      user's cache. Single-CPU cases confined only the test command and its
      children with taskset -c 0.
    Case Executions Outcome
    Normal focused boot with existing image cache 1 PASS, 14.630s
    Focused boot with an empty image cache 1 PASS, 67.163s
    Warm-cache repeated focused boot 20 All PASS, 13.791-15.577s
    Warm-cache focused boot confined to one host CPU 5 All PASS, 102.727-103.337s
    Empty-cache focused boot confined to one host CPU 1 PASS, 150.672s
    Original python3 scripts/nvx.py test-openvmm --backend kvm Full selection 58/58 PASS, 37 skipped, 36.336s; affected test 19.064s

    The 28 focused executions and full selection used the original OpenVMM code,
    without retrying a failed test. --repetitions was a deliberate repeated
    experiment, not a change to CI's pass/fail policy.

    Minimal commands, from the isolated NVX checkout:

    python3 scripts/nvx.py verify
    cd openvmm
    filter='test(/^multiarch::ic::openvmm_uefi_x64_ubuntu_2504_server_x64_timesync_ic$/)'
    
    cargo xflowey vmm-tests-run --release --ci-profile --skip-vhd-prompt \
      --filter "$filter"
    
    # Use a fresh, previously nonexistent directory for a cold-cache experiment.
    PETRI_CACHE_DIR="$PWD/target/issue170-new-cold-cache" \
      cargo xflowey vmm-tests-run --release --ci-profile --skip-vhd-prompt \
      --filter "$filter"
    
    cargo xflowey vmm-tests-run --release --ci-profile --skip-vhd-prompt \
      --filter "$filter" --repetitions 20
    
    taskset -c 0 cargo xflowey vmm-tests-run --release --ci-profile \
      --skip-vhd-prompt --filter "$filter" --repetitions 5

    5. Nested-KVM reproduction on the same physical server

    With approval, an isolated QEMU/KVM Linux VM was created on prometheus32.
    QEMU and nested-KVM support were already available; no host packages or
    host configuration were changed.

    • QEMU 10.2.1, q35,accel=kvm, -cpu host, four vCPUs, 12 GiB RAM.
    • Intermediate Linux guest: Ubuntu 26.04 cloud image, kernel
      7.0.0-31-generic; /dev/kvm usable inside it.
    • Host-built exact-source Flowey test archive, OpenVMM executable, firmware,
      and pipette were replayed inside the intermediate guest. These were not
      independently rebuilt with a different toolchain inside it.
    • Guest-local writable artifact/results directories and fresh guest image
      caches; original nextest ci profile and KVM test filter.
    • The nested guest's vhost_vsock and tun prerequisites were enabled only
      inside that disposable guest for the complete selection.
    Case Outcome
    Cold-cache focused test, complete successful command PASS, 96.114s
    Five warm-cache focused repetitions All PASS, 24.092-25.790s
    Complete KVM selection 58/58 PASS, 37 skipped, 437.709s; affected test 25.333s

    An earlier cold test body passed in 92.781s, but nextest then returned exit
    110 because its JUnit destination was on the read-only input export. The
    artifacts were copied into guest-local writable storage and the cold case
    was rerun successfully. The 92.781s attempt is not counted as a successful
    end-to-end command above.

    The nested replay command used the Flowey-produced archive rather than
    cargo nextest run -p vmm_tests without artifacts:

    export PETRI_REUSE_PREPPED_VHDS=1 RUST_BACKTRACE=1 RUST_LOG=trace
    export PETRI_CACHE_DIR=/var/tmp/nvx-issue170/cache-cold-verified
    export TEST_OUTPUT_PATH=/var/tmp/nvx-issue170/results-cold-verified
    export VMM_TESTS_CONTENT_DIR=/var/tmp/nvx-issue170/artifacts
    export VMM_TEST_IMAGES="$VMM_TESTS_CONTENT_DIR/images"
    
    /var/tmp/nvx-issue170/cargo-nextest nextest run \
      --profile ci \
      --config-file "$VMM_TESTS_CONTENT_DIR/.config/nextest.toml" \
      --workspace-remap "$VMM_TESTS_CONTENT_DIR" \
      --archive-file /var/tmp/nvx-issue170/nextest.tar.zst \
      --filter-expr \
      'test(/^multiarch::ic::openvmm_uefi_x64_ubuntu_2504_server_x64_timesync_ic$/)'

    For the full selection, the filter was read directly from
    nvx_tools.ci.OPENVMM_TEST_FILTERS["kvm"]; it was not relaxed.

    6. Stage timings distinguish slow boots from the failed boundary

    These are differences between timestamps in the preserved petri.log files,
    not estimates from total test durations. The last column includes OS boot and
    agent readiness; it is not a measurement of the time-sync correction itself.

    Case Waiting for boot event to BootSuccess BootSuccess to first guest time
    Native focused, warm cache 1.387s 10.540s
    Native focused, cold cache 23.275s 39.489s
    Native single-CPU, five warm cases 1.048-1.061s 98.361-99.136s
    Native single-CPU, cold cache 22.431s 124.002s
    Native full suite, affected case 1.185s 14.338s
    Nested KVM, cold cache 32.741s 57.333s
    Nested KVM, five warm cases 1.979-2.686s 17.711-19.027s
    Nested KVM full suite, affected case 2.015s 19.396s

    The one-CPU experiment made the overall test much slower but did not reproduce
    the incident's pre-boot-event stall.
    Most of its extra time occurred after
    BootSuccess. Cold image caches measurably slow the pre-boot stage, but none
    of the cold cases stalled indefinitely.

    7. Artifact identity and reproducibility limits

    The target Ubuntu 25.04 test guest, distinct from both host Linux installations,
    booted kernel 6.14.0-33-generic in the successful nested trace.

    Guest image URL:

    https://hvlitetestvhds.blob.core.windows.net/vhds/ubuntu-25.04-server-cloudimg-amd64.vhd
    

    Observed at 2026-09-21T23:32:43Z:

    Property Value
    ETag 0x8DF047D8A9E049C
    Last-Modified 2026-08-27T20:55:35Z
    Blob length 3,758,211,584 bytes
    Fixed-VHD disk length 3,758,211,072 bytes
    VHD unique ID 77043f59-552a-4a09-8afb-12f65e6443d3
    Footer Fixed VHD (type 2), checksum validated

    The ETag matches the value read from inside the nested guest before testing.
    The original failed CI trace did not record its ETag, so this does not prove
    the exact bytes served during that earlier failure.

    Reproduction artifact SHA-256 values:

    MSVM.fd:
    12386df9711285a2583cbae2a48207196533c8c4a3bb4f9ea4b52dfa74762592
    OpenVMM:
    8693fcce17ce9005cd013ee41f5f96c45276a2343066ef5ed0a6c6b4a20c6628
    pipette:
    be5a7e700a21a8ded9346b8ef9306aec81d72827b8a52ad1552d011fdcdb75ed
    

    Matching source revisions is not a complete environment match. Outstanding
    differences from the failed Azure job include Azure Linux/kernel 6.6 versus
    Ubuntu/kernel 7.0, Rust 1.98.1 versus 1.98.0, CPU model, outer virtualization
    stack, resource topology, scheduling, and network/cache state. The nested
    experiment is KVM-on-KVM, not a reproduction of Azure's outer host stack.
    These successful runs do not rule out a timing-sensitive or environment-specific
    OpenVMM/KVM/firmware/storage defect.

    8. Owning paths and next discriminating checks

    Inspected at OpenVMM 64054d7a7275c2c6d66c2bbb10f77ec777e11889:

    Path Relevance
    vmm_tests/vmm_tests/tests/tests/multiarch/ic.rs:103-137 RTC offset, VM/agent startup, then time-sync assertions.
    petri/src/vm/openvmm/start.rs:181-191 Resume and startup save/restore precede VM ready.
    petri/src/vm/mod.rs:1108-1174,2056-2098 Boot-event wait precedes agent connection/test execution.
    petri/src/vm/openvmm/mod.rs:107 and runtime.rs:125-138 The current flaky_boot timeout/reset quirk is PCAT-only; UEFI receives no such local timeout.
    petri/src/vm/mod.rs:1200-1241,3601-3621 Ten-minute watchdog, bounded inspection collection, and timeout_inspect_vmm.log.
    petri/src/vm/openvmm/mod.rs:303-353 Remote disk is RAM differencing over a SQLite read cache over an HTTP blob.
    petri/src/vm/mod.rs:3729-3758 PETRI_CACHE_DIR override, otherwise XDG/home-based image-cache location.
    vm/devices/storage/disk_blob/src/blob/http.rs:46-174 HTTP HEAD/range-read path; no explicit request/body deadline is configured in this implementation.
    .config/nextest.toml The VMM-test CI backup termination is after two ten-minute periods; Petri's own ten-minute watchdog fired first.

    NVX sets XDG_CACHE_HOME to <RUNNER_TEMP>/openvmm-cache for Linux test jobs.
    Consequently, an unspecified local warm home cache is not equivalent to CI's
    image-cache context. The cold-cache experiments above account for one part of
    that difference.

    The remaining hypotheses should be tested, not treated as established causes:

    1. Recover guest state at the original stall. Enable ci: preserve failed OpenVMM test diagnostics #173 and retain
      timeout_inspect_vmm.log, screenshot*.png, uefi.log, openvmm.log,
      petri.jsonl, and test identity before rerunning. Look first at VP
      instruction pointers/run state, pending interrupts/timers, and outstanding
      SCSI operations. The existing watchdog already obtains inspection data.
    2. Separate disk I/O from guest execution. A pending streamed HTTP read
      could plausibly leave firmware/bootloader waiting while the VMM remains
      inspectable. The source's lack of an explicit deadline and the cold/warm
      timing difference make this worth instrumenting, but neither proves that
      an HTTP read caused this incident. Compare the same runner with an empty
      cache, a known warm cache, and a fully local disk image; record HTTP request
      completion, ETag, SCSI state, and exact boot-stage timestamps.
    3. Match the runner environment before changing timer/reset behavior.
      Reproduce under Azure Linux 6.6.150.1-1.azl3 and Rust 1.98.1, preserving
      CPU topology and actual outer-host conditions as closely as possible.
      Snapshot relevant runner/kernel/KVM state at failure and compare it with
      the later passing run on runner ID 31.
    4. Use any failing inspection to select the controlling code path.
      Startup save/restore, SynIC/interrupt delivery, firmware execution, and
      storage are candidate paths, not diagnosed defects. Do not mask the
      original failure by broadening retries, extending watchdogs, or adding an
      unconditional UEFI reset.

    9. Retained evidence and change status

    • Original attempt-1 and attempt-2 CI console logs, both new successful CI
      logs, native command transcripts, native/nested boot-stage timing JSON,
      image identity, and shared-build provenance are retained in the local
      investigation session artifacts.
    • Native Petri logs remain in the isolated checkout under
      openvmm/target/issue170-*-results and openvmm/target/vmm_tests/test_results*.
      Flowey renames repetition results to test_results_<n> and later
      repetition groups reuse those names; therefore, some early per-repetition
      directories were overwritten. The complete 20-run console transcript is
      retained. Do not assume every individual native repetition has a separate
      surviving Petri directory.
    • Nested Petri logs, screenshots, and JUnit files were copied out before
      guest shutdown into issue170-nested-results.tar.gz, retained locally
      and at openvmm/target/issue170-nested-results.tar.gz in the isolated
      remote checkout. SHA-256:
      4da887fbdee4c9d3bbfb21ae8fbd795b9894f6da9e0d7f13293c8b3d5408f574.
    • The temporary nested VM was shut down. Its disks, cloud-init seed, and
      ephemeral SSH credentials were removed; no OpenVMM process or diagnostic
      port listener remained.
    • ci: preserve failed OpenVMM test diagnostics #173 contains only the workflow, regression test, and CI documentation.
      On its updated dev base, 254 Windows CLI tests ran successfully
      (one skipped), plus Ruff and both Pyright platform checks. Earlier
      incident-checkout validation covered the full Linux/Windows CLI suites,
      host-profile tests, 25 Linux Specula tests, and YAML parsing.

    Keep #170 open. The diagnostic-loss fix is ready for review as a draft;
    the guest-boot root cause and its corrective runtime change are still unknown.

  2. ppenna commented on Oct 10, 2026

    @ppenna
    ContributorAuthor

    Investigation update - October 10, 2026

    Retained diagnostics now localize the stall to boot-disk reads that never complete. With the diagnostics that #173 retains, four Linux/KVM jobs from October 5 to 10 timed out eight UEFI boot tests. In every stalled VM, the watchdog dump shows a guest SCSI READ that the boot disk's backend never completed. That disk streams its VHD on demand from Azure Blob Storage, and three of the four jobs also logged Connection reset by peer from OpenVMM's HTTP blob client, which has no timeout, retry, or keepalive. The stall occurs both before BootSuccess, as in the original incident, and after it. The runtime fix is still open.

    Occurrences

    Since 2026-10-04 17:28 UTC, the 300 most recent CI runs ran 205 Linux/KVM vmm-tests jobs across all attempts: 179 passed, 8 failed, 17 were cancelled, and 1 was still running. Four of the eight failures are this stall:

    Run / attempt Trigger Runner NVX / OpenVMM Timed-out tests Stage
    37374978866 / 1 PR, copilot/ci-azure-utility-20261002; run later cancelled azure-kvm-1 1c04aec08 / b7696e7b alpine_3_23_x64_boot_small, ubuntu_2404_server_x64_boot, ubuntu_2404_server_x64_smbios_dmi_uefi Before BootSuccess
    37701700274 / 1 PR, esaurez/nvx-image-slots-20261005 azure-kvm-2 59219c579 / 5ffe5c22 alpine_3_23_x64_boot_small, ubuntu_2404_server_x64_boot After BootSuccess
    37701700274 / 2 Rerun of the same head azure-kvm-1 59219c579 / 5ffe5c22 ic::openvmm_uefi_x64_ubuntu_2504_server_x64_timesync_ic After BootSuccess
    38018382082 / 1 dev push, merge of #455 azure-kvm-3 dcde299f7 / e5bf7977 alpine_3_23_x64_boot_small, ubuntu_2404_server_x64_boot After BootSuccess
    • Each test timed out after about 600.7 s, and every other selected test in those jobs passed. Attempt 3 of 37701700274 passed on azure-kvm-3.
    • Every timed-out test was reading its image while the job's read cache for that image was still empty.
    • The other four Linux/KVM failures were unrelated: a missing Rust toolchain, a CPU-profile test assertion, and NVX script-test failures in two runs. No Linux/MSHV or Windows/WHP vmm-tests failure in the window was a test timeout.
    • For the dev push, Required status check failed only on this job, and Publish development release and Persist performance baseline were skipped.

    Evidence

    Job Test Last guest progress (UTC) In flight on LUN 0:0:0 (submitted / completed)
    37374978866 / 1 alpine_3_23_x64_boot_small 21:36:37.3, GRUB Loading initial ramdisk ... 1 READ (720 / 719)
    37374978866 / 1 ubuntu_2404_server_x64_boot No serial output 1 READ (931 / 930)
    37374978866 / 1 ubuntu_2404_server_x64_smbios_dmi_uefi No serial output 1 READ (931 / 930)
    37701700274 / 1 alpine_3_23_x64_boot_small 23:35:23.7, * Cleaning /tmp directory ... [ ok ] 1 READ (649 / 648)
    37701700274 / 1 ubuntu_2404_server_x64_boot 23:35:28.7, Begin: Running /scripts/local-bottom ... done. 1 READ (306 / 305)
    37701700274 / 2 ubuntu_2504_server_x64_timesync_ic 00:04:37.9, cloud-init output 1 READ (3,437 / 3,436)
    38018382082 / 1 alpine_3_23_x64_boot_small 03:11:32.6, * Cleaning /tmp directory ... [ ok ] 1 READ (1,325 / 1,324)
    38018382082 / 1 ubuntu_2404_server_x64_boot 03:13:47.6, [ OK ] Closed syslog.socket 9 READs (663 / 654)
    • The reads were stuck in the disk backend. Each failure_inspect_vmm.log lists them in storvsp's in-flight io table, and ios_submitted exceeds ios_completed; a lost completion interrupt would leave the two equal. LUN 0:0:0 is a RAM differencing layer over the SQLite read cache over a blob layer at https://hvlitetestvhds.blob.core.windows.net/vhds/<image>.vhd over HTTP/1.1. The local cloud-init disk on LUN 0:0:1 had nothing outstanding. The VMM itself stayed responsive and completed the inspection.

    • The stall happens before and after BootSuccess. On October 5, all three VMs stopped in firmware or GRUB and never sent the boot event, which matches the original incident. In the other five, the guest OS had started.

    • The guests were blocked on disk I/O. Both Ubuntu 24.04 guests that reached the OS reported hung tasks; in 37701700274 / 1, copymods waited more than 368 s in ext4_lookup → __ext4_find_entry → __wait_on_buffer → bit_wait_io → io_schedule. No guest reported a SCSI timeout: Linux storvsc resets its command timer unconditionally because "the host guarantees to respond to each command".

    • The blob connections were being reset. Three of the four jobs logged scsi_error ... error=disk io error: io error: client error (SendRequest): connection error: Connection reset by peer (os error 104) op=READ near the stalls:

      • 37374978866 / 1: the concurrent timesync_ic test, at 21:35:30.6 and 21:35:32.5, about 25 s before the three stalled VMs started.
      • 37701700274 / 1: the concurrent ubuntu_2404_server_x64_smbios_dmi_uefi test, which reads the same blob, at 23:38:28.6 and 23:38:33.4.
      • 37701700274 / 2: the failing timesync_ic test itself, at 00:03:36.1, about a minute before its final stall.

      Reads that received a reset failed quickly, and those guests continued; the stalled reads never completed or failed.

    • Separate processes stalled together. On October 5, the two Ubuntu 24.04 VMs, started 65 ms apart on the same blob, each stopped with one read outstanding after exactly 930 completions. On October 7, two VMs stopped within 5 s of each other while a third kept running. Each OpenVMM process has its own HTTP client, which points at the network path rather than at one VM.

    • The SQLite read cache does not explain an indefinite hang. rusqlite sets a 5-second busy timeout on every connection, disk_layered only warns failed to populate read cache when a cache write fails, and no failing process logged that warning. No other test used the Alpine cache during any Alpine stall, and on October 10 the test sharing the Ubuntu 24.04 cache exited at 03:14:35 while nine reads stayed in flight until 03:20:00.

    • Not tied to a change or a runner. The four jobs span three NVX heads, three OpenVMM pins, and three runners. For the dev push, the e5bf7977 pin change only touches microVM networking, and none of the failing VMs has a NIC; the same pin passed this job on network: support IPv6 in the portable profile and its egress policies #455's pre-merge head 90efb165c, and the same four tests passed on Linux/MSHV in that run in 65-87 s.

    Root-cause hypothesis

    HttpBlob::read in vm/devices/storage/disk_blob/src/blob/http.rs (nanvix/openvmm e5bf7977; upstream microsoft/openvmm has the same gap) sends each range GET through a hyper_util legacy client built from HttpsConnector::new(). It sets no connect, response, or body deadline, no retry, and no TCP keepalive. When the network resets a connection, the read fails and the guest can recover. When a connection stops delivering data without a reset, the read never resolves, and the guest, whether in firmware, GRUB, or Linux, waits until Petri's watchdog fires. The Linux/KVM runners' path to Azure Blob Storage evidently resets or drops these connections intermittently.

    NVX increases the exposure. _prepare_openvmm_test_environment in scripts/nvx_tools/ci.py points XDG_CACHE_HOME at $RUNNER_TEMP/openvmm-cache, which the runner empties for every job, and run_openvmm_tests does not pass --no-lazy-fetch. Every Linux job therefore streams the Ubuntu 24.04, Ubuntu 25.04, and Alpine 3.23 images from an empty cache. On KVM, the first tests to read an image take about 200-290 s, while later tests on the warm cache take about 11-18 s.

    This is still a hypothesis. The dumps show the reads stuck in LUN 0:0:0's backend, but not which layer held them, and the network cause of the resets and silent drops is unknown.

    Proposed changes

    1. OpenVMM HttpBlob, for the root cause. Bound each range request with connect and response or body-inactivity timeouts, retry transient failures such as resets, timeouts, and 5xx responses on a fresh connection with capped backoff, and return DiskError::Io only after the retries run out. Consider enabling TCP keepalive. Cover a stalled response and a reset with the disk_blob test server in src/tests/http_server.rs, then promote the pin into NVX.
    2. Instrumentation. Expose in-flight blob requests, with their range and start time, through inspect, so the next watchdog dump shows directly whether the stuck read is waiting on HTTP.
    3. NVX CI exposure. On the self-hosted Linux runners, keep the Petri disk cache in a directory that survives between jobs instead of $RUNNER_TEMP, or pass --no-lazy-fetch so images download before any test starts. Either reduces how often a test depends on a live blob read; neither fixes the hang.
    4. No masking. Do not extend the watchdog, retry failed tests, or add an unconditional UEFI reset.

    Retained evidence

    The diagnostics artifacts expire seven days after upload:

    • openvmm-vmm-tests-Linux-kvm-37374978866-1 on 2026-10-12.
    • openvmm-vmm-tests-Linux-kvm-37701700274-1 on 2026-10-14.
    • openvmm-vmm-tests-Linux-kvm-37701700274-2 on 2026-10-15.
    • openvmm-vmm-tests-Linux-kvm-38018382082-1 on 2026-10-17.

    Copies of all four and of the failing job logs are retained in the local investigation session. No reproduction was attempted: the stall is intermittent, and a deterministic one needs a blob server that stalls or resets mid-response, as in change 1.

    Keep #170 open until the HttpBlob change lands and the Linux/KVM lane runs clean.

  3. changed the title [-]ci: investigate intermittent Linux/KVM Ubuntu timesync boot stalls[/-] [+]ci: investigate intermittent Linux/KVM UEFI boot stalls on lazily fetched VHD reads[/+] on Oct 10, 2026
  4. changed the title [-]ci: investigate intermittent Linux/KVM UEFI boot stalls on lazily fetched VHD reads[/-] [+]openvmm ci: investigate intermittent Linux/KVM UEFI boot stalls on lazily fetched VHD reads[/+] on Oct 30, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    confirmedIssue affects multiple people.

    Type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions