ci: investigate intermittent Linux/KVM Ubuntu timesync boot stalls

[ppenna]

Status update - September 21, 2026: The intermittent boot stall remains
unresolved. Draft #173 fixes missing failure-diagnostic retention only;
it does not change OpenVMM runtime behavior or close this issue.

The detailed 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

• Attempt: attempt 2, successful
• Job: OpenVMM vmm-tests / Linux / KVM
• Runner: azure-kvm-3
• Affected test: passed in 285.252s
• Full test phase: 620.444s; 58/58 passed and 37 skipped

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.

[ppenna]

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.