nvx-rs: read OpenVMM's fatal error before a chain of any length, and name repeated CPUID record entries

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
 

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<Vec
         .map_err(failed)
 }
 
-/// Returns the last line with which OpenVMM reported the error that ended it, among the last
-/// [`FATAL_TAIL_BYTES`] of the VMM's log at `path`, cut to [`MAX_FATAL_CHARS`], or none if they
-/// hold none, or the log cannot be read: the line that leads OpenVMM's fatal error, then the
-/// error's time ABI code, if it has one, as [the attribution of evidence](Evidence#attribution)
-/// describes. If the line does not name a forward that OpenVMM cannot bind,
+/// Returns the last line with which OpenVMM reported the error that ended it in the VMM's log at
+/// `path`, cut to [`MAX_FATAL_CHARS`], or none if the log holds none, or cannot be read: the line
+/// that leads OpenVMM's fatal error, then the error's time ABI code, if it has one, as [the
+/// attribution of evidence](Evidence#attribution) describes. The line is looked for back from the
+/// log's end, as [`last_line_start`] reads it, so that the error's chain, which follows the line,
+/// may be of any length. If the line does not name a forward that OpenVMM cannot bind,
 /// [`failure::FORWARD_BIND_TEXT`], but a cause of the error's chain that follows it does, the
 /// cause follows the line, after `: `, cut to [`MAX_FATAL_CHARS`] too, without the indentation and
 /// the number with which the chain lists it.
 fn read_fatal(path: &Path) -> Option<String> {
     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<String> {
     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<Option<u64>> {
+    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]