From 6856d4769eec361fdf83dd185091222e7575e3a1 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Thu, 29 Oct 2026 20:33:24 -0700 Subject: [PATCH 1/3] nvx-rs: read OpenVMM's fatal error before a chain of any length A clone whose VMM exits before its restore-ready event reads, from the VMM's log, the line with which OpenVMM reported the error that ended it, and attributes the failure to an incompatible host when the line's time ABI code, such as E_CPU_SURFACE, says so. OpenVMM writes that line first, then the error's chain. read_fatal looked for the line in the last 64 KiB of the log alone, which held it while OpenVMM's CPU checks named at most 16 differences. Since microsoft/openvmm#4804, which #1014 pinned, they name every difference that they find, together, in one cause of the chain: about 7.5 KB on the Azure test hosts, and 61,717 bytes for the Turin profile when every register of every entry differs in both comparisons and the backend supports none of the profile, but more for a pass-through backend whose VP 0 reads non-zero values at entries outside the profile's tables, each of which the error names, or for a snapshot record of up to the 1024 entries that the decoder admits. A chain longer than 64 KiB pushed the line out of the tail, so the failure kept its lost status, whose outcome is unknown, rather than the incompatible host, and lost OpenVMM's line from its message. read_fatal now reads the log back from its end, 64 KiB at a time, until it finds the last line that starts with "fatal error: ", then reads that line and the chain that follows it, so that the line keeps its attribution after a chain of any length. A log without the line is read whole, a block at a time. Tests check that the line is read before a chain several blocks long, whether or not a line precedes it, with a cause that names a forward that OpenVMM cannot bind after a long one, and wherever a block starts around the line: after the newline before it, at its start, or within its prefix; and that a long log that only quotes the line holds none. Follow-up to #568. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- nvx-rs/src/host/template/clone/records.rs | 128 +++++++++++++++++----- 1 file changed, 98 insertions(+), 30 deletions(-) diff --git a/nvx-rs/src/host/template/clone/records.rs b/nvx-rs/src/host/template/clone/records.rs index 03e7a0873..308b9c336 100644 --- a/nvx-rs/src/host/template/clone/records.rs +++ b/nvx-rs/src/host/template/clone/records.rs @@ -35,10 +35,10 @@ //! a longer text, as the diagnosis of a caller that fails the clone may be, its first and its last //! characters, with an ellipsis between them, so that a read, which takes at most 64 KiB of a //! record, takes every record that a failure writes. A record of another format fails rather -//! than being read. The failure of a VMM that exited before its restore-ready event reads the end -//! of the launch's log for the line with which OpenVMM reported the error that ended it, which the -//! record's message keeps, and whose time ABI code may attribute the failure, as [the attribution -//! of evidence](Evidence#attribution) describes. +//! than being read. The failure of a VMM that exited before its restore-ready event reads the +//! launch's log back from its end for the line with which OpenVMM reported the error that ended +//! it, which the record's message keeps, and whose time ABI code may attribute the failure, as +//! [the attribution of evidence](Evidence#attribution) describes. //! //! A release of the clone's lease removes both, as it removes the clone's other files, so that //! the records of a clone last as long as its lease, which a failure whose teardown is unresolved @@ -109,9 +109,11 @@ const PROGRESS_WHAT: &str = "clone progress log"; /// What messages call the record of a clone's failure. const FAILURE_WHAT: &str = "clone failure record"; -/// The most bytes at the end of a VMM's log in which a failure looks for the line of OpenVMM's -/// fatal error, which OpenVMM writes as it exits, followed by the error's chain alone. -const FATAL_TAIL_BYTES: u64 = 64 * 1024; +/// The bytes of a VMM's log that a failure reads at a time as it looks back from the log's end for +/// the line of OpenVMM's fatal error, which OpenVMM writes as it exits, followed by the error's +/// chain alone, of any length: the chain of a failed CPU check names every difference that the +/// check found. +const FATAL_BLOCK_BYTES: u64 = 64 * 1024; /// The most characters of the line of OpenVMM's fatal error that the record of a failure keeps. const MAX_FATAL_CHARS: usize = 1024; @@ -392,7 +394,7 @@ impl Recorder { /// Returns `fault`, of the clone that got as far as `progress`, which is the loss of a VMM /// that exited before its restore-ready event, with the line with which OpenVMM reported the - /// error that ended the VMM after its message, if the VMM's log ends with one, as + /// error that ended the VMM after its message, if the VMM's log holds one, as /// [`read_fatal`] reads it, and the message does not hold it yet, as the message of a failure /// that a reattach resolves may, and with the line's evidence, if it is evidence, as [the /// attribution of evidence](Evidence#attribution) describes. Returns any other fault as it is. @@ -970,31 +972,27 @@ fn read_private(path: &Path, description: &str, limit: u64) -> Result Option { let mut log = open_regular(path).ok()?; - let length = log.metadata().ok()?.len(); - log.seek(SeekFrom::Start(length.saturating_sub(FATAL_TAIL_BYTES))) - .ok()?; - let mut tail = Vec::new(); - log.take(FATAL_TAIL_BYTES).read_to_end(&mut tail).ok()?; - let text = String::from_utf8_lossy(&tail); - let lines: Vec<&str> = text.lines().collect(); - let at = lines - .iter() - .rposition(|line| line.starts_with(failure::FATAL_PREFIX))?; - let mut fatal: String = lines[at].chars().take(MAX_FATAL_CHARS).collect(); + let start = last_line_start(&mut log, failure::FATAL_PREFIX.as_bytes()).ok()??; + log.seek(SeekFrom::Start(start)).ok()?; + let mut rest = Vec::new(); + log.read_to_end(&mut rest).ok()?; + let text = String::from_utf8_lossy(&rest); + let mut lines = text.lines(); + let mut fatal: String = lines.next()?.chars().take(MAX_FATAL_CHARS).collect(); if !fatal.contains(failure::FORWARD_BIND_TEXT) { - let forward = lines[at + 1..] - .iter() - .map(|line| cause(line)) + let forward = lines + .map(cause) .find(|cause| cause.starts_with(failure::FORWARD_BIND_TEXT)); if let Some(forward) = forward { fatal.push_str(": "); @@ -1004,6 +1002,38 @@ fn read_fatal(path: &Path) -> Option { Some(fatal) } +/// Returns the offset in `log` of its last line that starts with `prefix`, or none if no line +/// does, reading the log back from its end, [`FATAL_BLOCK_BYTES`] at a time: a line starts at +/// the start of the log, and after each newline. +fn last_line_start(log: &mut File, prefix: &[u8]) -> io::Result> { + let length = log.seek(SeekFrom::End(0))?; + let mut block = Vec::new(); + let mut end = length; + while end > 0 { + let start = end.saturating_sub(FATAL_BLOCK_BYTES); + // The block's read goes on past its end by the prefix's length, which a line that starts + // at its end would begin with. + let stop = length.min(end + prefix.len() as u64); + block.resize((stop - start) as usize, 0); + log.seek(SeekFrom::Start(start))?; + log.read_exact(&mut block)?; + let starts = block[..(end - start) as usize] + .iter() + .enumerate() + .rev() + .filter(|&(_, &byte)| byte == b'\n') + .map(|(newline, _)| newline + 1) + .chain((start == 0).then_some(0)); + for line in starts { + if block[line..].starts_with(prefix) { + return Ok(Some(start + line as u64)); + } + } + end = start; + } + Ok(None) +} + /// Returns the cause of an error's chain that `line` lists, as OpenVMM writes the chain after the /// line that leads its fatal error, ` N: CAUSE` for each of several causes, or ` CAUSE` for /// one alone: without its indentation, and its number, if it has one. @@ -1530,9 +1560,9 @@ mod tests { ); fs::write(&path, &log).unwrap(); assert_eq!(read_fatal(&path).as_deref(), Some(fatal)); - // The line is looked for at the end of a long log, and kept to its first characters. + // The last line of a long log is read, kept to its first characters. let long = format!("fatal error: {}", "x".repeat(2 * MAX_FATAL_CHARS)); - let filler = "a line of the VMM's log\n".repeat(2 * FATAL_TAIL_BYTES as usize / 24); + let filler = "a line of the VMM's log\n".repeat(2 * FATAL_BLOCK_BYTES as usize / 24); fs::write( &path, format!("fatal error: an earlier one\n{filler}{long}\n"), @@ -1541,9 +1571,47 @@ mod tests { let read = read_fatal(&path).unwrap(); assert_eq!(read.chars().count(), MAX_FATAL_CHARS); assert!(long.starts_with(&read)); - // A log without a fatal error, or one that only names it, holds none. + // A log without a fatal error, or one that only names it, holds none, however long. fs::write(&path, "the VMM exited\nwarning: fatal error: quoted\n").unwrap(); assert_eq!(read_fatal(&path), None); + fs::write( + &path, + format!("{filler}warning: fatal error: quoted\n{filler}"), + ) + .unwrap(); + assert_eq!(read_fatal(&path), None); + } + + #[test] + fn the_line_of_openvmm_s_fatal_error_is_read_before_a_chain_of_any_length() { + let (_directory, private) = private_dir(); + let path = private.join("openvmm.log"); + let block = FATAL_BLOCK_BYTES as usize; + // A failed CPU check names every difference that it found, in a cause that may take + // several blocks of the log, after the line, which may be the log's first. + let fatal = "fatal error: [E_CPU_SURFACE] failed to launch vm worker"; + let differences = "CPUID 0x1 ECX differs; ".repeat(3 * block / 23); + for before in ["", "a line of the VMM's log\n"] { + let log = format!("{before}{fatal}\n\nCaused by:\n {differences}\n"); + fs::write(&path, &log).unwrap(); + assert_eq!(read_fatal(&path).as_deref(), Some(fatal)); + } + // A cause that names a forward that OpenVMM cannot bind follows the line after it. + let forward = "failed to create socket for port forward (Tcp 127.0.0.1:18080)"; + let log = format!("{fatal}\n\nCaused by:\n 0: {differences}\n 1: {forward}\n"); + fs::write(&path, &log).unwrap(); + assert_eq!(read_fatal(&path), Some(format!("{fatal}: {forward}"))); + // The line is read wherever a block starts around it: after the newline before the line, + // at the line's start, within its prefix, or after it. + let filler = "a line of the VMM's log\n".repeat(2 * block / 24); + let prefix = failure::FATAL_PREFIX.len(); + for from_end in block - 2..=block + prefix + 2 { + let rest = "y".repeat(from_end - fatal.len() - 2); + let log = format!("{filler}{fatal}\n{rest}\n"); + assert_eq!(log.len() - log.find(fatal).unwrap(), from_end); + fs::write(&path, &log).unwrap(); + assert_eq!(read_fatal(&path).as_deref(), Some(fatal), "{from_end}"); + } } #[test] From 30ff242013af49c5dba2f664a21c6bda35f67baf Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Thu, 29 Oct 2026 20:36:20 -0700 Subject: [PATCH 2/3] openvmm: name repeated and unordered entries of a CPUID record Pin microsoft/openvmm#4818 at bcfc47cff6606afadffef97551e538962895b598, two commits on e4c741e18, the previous pin, which is the head of feature/microvm/dev. When the effective CPUID that a restore recomputes differs from the snapshot's record, OpenVMM's E_CPU_SURFACE error names every entry that differs. It kept only the last listing of an entry that the record lists more than once, and named a record out of order only when nothing else differed, so a record that no OpenVMM writes, but that the decoder admits, could hide differences: a changed listing followed by the entry's own was reported as the same entries in another order. The first commit tests the error's every register, value, and mask, and the order of the entries that only one side has. The second compares every listing of an entry and names each that differs, each entry listed more than once, and a record out of order, whatever else differs. The error keeps its code, and names the differences of a record that OpenVMM writes as before. The protocol vectors and built-in CPU profiles that nvx-rs copies are unchanged. Refs #568 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- openvmm | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/openvmm b/openvmm index e4c741e18..bcfc47cff 160000 --- a/openvmm +++ b/openvmm @@ -1 +1 @@ -Subproject commit e4c741e1860de1e2149b3dd5d41863468705b02c +Subproject commit bcfc47cff6606afadffef97551e538962895b598 From 0853bdc753618a0ef49de9a60abf270ff068f9fe Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Thu, 29 Oct 2026 20:38:15 -0700 Subject: [PATCH 3/3] doc: map the CPUID record reporting in the OpenVMM roadmap Record the two commits that the previous commit pins as positions 366 and 367 of the microVM chain, and move the NVX pin to bcfc47cff. Positions 366 and 367 make the restore's comparison of the effective CPUID with a snapshot's record name every difference of a record that the decoder admits although no OpenVMM writes it: each entry that the record lists more than once, each of its listings that differs, and a record out of order, together with the entries that differ. They also test each register, value, and mask that the error names. They change only the first CPU check of the VM worker's time ABI, its tests, and the snapshot guide's description of it; say so in the table's remarks. The pin is now 210 commits past the mapped tip. Positions 362-365 are no longer only a proposal: microsoft/openvmm#4804 merged them, so position 365, e4c741e18, is the head of feature/microvm/dev. Say so in the scope, and name microsoft/openvmm#4818 as the proposal of positions 366 and 367. Refs #568 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- doc/openvmm-upstream-roadmap.md | 52 ++++++++++++++++++--------------- 1 file changed, 28 insertions(+), 24 deletions(-) diff --git a/doc/openvmm-upstream-roadmap.md b/doc/openvmm-upstream-roadmap.md index 76a7314e3..b4b9ea266 100644 --- a/doc/openvmm-upstream-roadmap.md +++ b/doc/openvmm-upstream-roadmap.md @@ -9,25 +9,27 @@ - Mapped fork tip: `a0556d7d85ce1fff89f5b45a98f15c5c79cbb6fb`, position 157. The graph, PR summary, and commit mapping below cover positions 001-157 and the fixups at positions 334-340, 344, and 345. -- NVX's pinned OpenVMM revision: `e4c741e1860de1e2149b3dd5d41863468705b02c`, position 365. - Positions 362-365, which microsoft/openvmm#4804 proposes for `feature/microvm/dev`, are - four commits on position 361, `c32c57d12`, the head of `feature/microvm/dev` since - microsoft/openvmm#4807 merged positions 360 and 361. Those are two commits on position 359, - `bd2b27a2e`, which microsoft/openvmm#4794 merged with positions 355-358. Positions 355-359 - are five commits on position 354, `832d5bb48`, which microsoft/openvmm#4775 merged with - position 353. Positions 353 and 354 are two commits on position 352, `b92daa350`, which - microsoft/openvmm#4773 merged with positions 350 and 351. Positions 350-352 are three commits - on position 349, `d2338ea22`, which microsoft/openvmm#4769 merged with position 348. Positions - 348 and 349 are two commits on position 347, `57d0a18b3`, which microsoft/openvmm#4767 merged - with position 346. Positions 346 and 347 are two commits on position 345, `e68871cc6`, which - microsoft/openvmm#4762 merged with position 344. Positions 344 and 345 are two commits on - position 343, `a12d9167f`, which microsoft/openvmm#4749 merged with positions 341 and 342. - Positions 341-343 are three commits on position 340, `2b681564d`, which microsoft/openvmm#4735 - merged with position 339. Positions 339 and 340 are two commits on position 338, `8a0d945ed`, - which microsoft/openvmm#4734 merged, and position 338 is one commit on `79a501b63`, the head - of the `feature/microvm/release/v2.3` branch of microsoft/openvmm. The pin is 208 commits - past the mapped tip on the same first-parent chain. Positions 158-333, 341-343, and 346-365 - are not yet assigned to PRs; see [Commits after the mapped tip](#commits-after-the-mapped-tip). +- NVX's pinned OpenVMM revision: `bcfc47cff6606afadffef97551e538962895b598`, position 367. + Positions 366 and 367, which microsoft/openvmm#4818 proposes for `feature/microvm/dev`, are two + commits on position 365, `e4c741e18`, the head of `feature/microvm/dev` since + microsoft/openvmm#4804 merged positions 362-365. Those are four commits on position 361, + `c32c57d12`, which microsoft/openvmm#4807 merged with position 360. Positions 360 and 361 are + two commits on position 359, `bd2b27a2e`, which microsoft/openvmm#4794 merged with positions + 355-358. Positions 355-359 are five commits on position 354, `832d5bb48`, which + microsoft/openvmm#4775 merged with position 353. Positions 353 and 354 are two commits on + position 352, `b92daa350`, which microsoft/openvmm#4773 merged with positions 350 and 351. + Positions 350-352 are three commits on position 349, `d2338ea22`, which microsoft/openvmm#4769 + merged with position 348. Positions 348 and 349 are two commits on position 347, `57d0a18b3`, + which microsoft/openvmm#4767 merged with position 346. Positions 346 and 347 are two commits on + position 345, `e68871cc6`, which microsoft/openvmm#4762 merged with position 344. Positions 344 + and 345 are two commits on position 343, `a12d9167f`, which microsoft/openvmm#4749 merged with + positions 341 and 342. Positions 341-343 are three commits on position 340, `2b681564d`, which + microsoft/openvmm#4735 merged with position 339. Positions 339 and 340 are two commits on + position 338, `8a0d945ed`, which microsoft/openvmm#4734 merged, and position 338 is one commit + on `79a501b63`, the head of the `feature/microvm/release/v2.3` branch of microsoft/openvmm. The + pin is 210 commits past the mapped tip on the same first-parent chain. Positions 158-333, + 341-343, and 346-367 are not yet assigned to PRs; see + [Commits after the mapped tip](#commits-after-the-mapped-tip). - Upstream main: `22c0485be597f87a76771e1db03eaa823a685ffc` (2026-10-22), the fork base. ## Upstream status @@ -317,8 +319,8 @@ The physical branch is one first-parent chain: -> PR14 fixup [336] -> PR09 fixup [337] -> PR02 fixup [338] -> PR20 fixup [339] -> PR23 fixup [340] -> unassigned [341-343] -> PR18 fixups [344-345] - -> unassigned [346-365] - -> e4c741e18 (NVX pin) + -> unassigned [346-367] + -> bcfc47cff (NVX pin) ``` For upstream review, PR01-PR08 and PR14 can be rebased independently onto current upstream main, @@ -340,8 +342,8 @@ PR18's position 111. ## Commits after the mapped tip -The NVX pin extends the chain past position 157 without merges. Of the 208 later commits, -positions 158-333, 341-343, and 346-365 are not yet classified or assigned to PRs, positions +The NVX pin extends the chain past position 157 without merges. Of the 210 later commits, +positions 158-333, 341-343, and 346-367 are not yet classified or assigned to PRs, positions 334-337 are the fixups of the `feature/microvm/release/v2.3` rebase, position 338 is a PR02 fixup, positions 339 and 340 are PR20 and PR23 fixups, and positions 344 and 345 are PR18 fixups. @@ -396,6 +398,7 @@ This table groups them by topic in chain order; ranges are inclusive, as in the | 355-359 | `2607a7d55..bd2b27a2e` | 5 | microVM virtio devices reach only the RAM ranges of the e820 map: guest memory views that admit only a set of ranges, a virtio queue that refuses a descriptor unless its memory admits the whole buffer, an MMIO transport that restricts device DMA and marks a device that addresses other memory as needing reset, and the loader's e820 RAM ranges, to which every microVM device is restricted (microsoft/openvmm#4794) | | 360-361 | `c9ac93a63..c32c57d12` | 2 | CPU profile validation checks the CPU time bits, so a snapshot's host profile document must fix them too, and the catalog verifies each pinned profile once per process, before a partition uses it: its static data must form a valid profile whose canonical encoding is the encoding that snapshots embed, while the tests keep checking its digest (microsoft/openvmm#4807) | | 362-365 | `69ddc715b..e4c741e18` | 4 | The microVM's `E_CPU_SURFACE` errors name every CPUID difference rather than the first 16, each entry of a snapshot's effective CPUID record on one line with the registers in which it differs, and VP 0's non-zero CPUID entries outside the profile's tables together with the results that VP 0 does not observe; and the VM worker runs every CPU check of a partition, the comparison with the snapshot's record, the check of VP 0's CPUID, and the check that the backend supports the profile, even after one fails, and reports their failures together (microsoft/openvmm#4804) | +| 366-367 | `e51ab72d3..bcfc47cff` | 2 | The restore's comparison of the effective CPUID with a snapshot's record names every difference of a record that the decoder admits although no OpenVMM writes it, each entry that the record lists more than once, each of its listings that differs, and a record out of order, together with the entries that differ; and its tests check each register, value, and mask that the error names (microsoft/openvmm#4818) | Some of these commits change mapped work rather than add to it. Positions 246-250 remove the legacy microVM clock paths and change files that PR10 and PR17 also change. Position 252 makes @@ -415,7 +418,8 @@ loader, and microVM worker. Positions 360 and 361 change only `cpu_profile`, the profile crate that positions 159-269 add, one of its test helpers in `virt_mshv`, and the snapshot guide, so they build on that fork-only code. Positions 362-365 change only the CPU checks of the VM worker's time ABI, which positions 159-269 also add, and the snapshot guide's -description of them. +description of them. Positions 366 and 367 change only the first of those checks, the +comparison with a snapshot's record, its tests, and the snapshot guide's description of it. ## PR summary