From d587e72783c710985d41be237521c70889c72a83 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Mon, 19 Oct 2026 14:50:28 -0300 Subject: [PATCH] nvx-rs: report time-ABI repair failures through one Runtime method A failure of restore-time repair is a fatal time-ABI event: it has the repair source and the restore phase, and it stops the VM with the repair power-off status unless the tools run report-only. commands::repair_failed passed those three to Runtime::fail_fatal, and daemon.rs spelled them out again at six sites, each with G_REPAIR_SUPPRESSION. restore_work also inlined the body of release_suppression. No unit test reached any of them, because Runtime::emit_event opened /dev/kmsg and /dev/console itself, so #605, #606, and #607 left this refactor until a test seam existed. Runtime::repair_failure, beside Runtime::conformance_failure, now passes the repair status, source, and phase. repair_failed and the six daemon sites call it, and restore_work calls release_suppression. Two new PrivilegedOps methods, write_kernel_log and write_console, are the seam. RealOps runs the code with which emit_event wrote an event's kernel log record and console line, and the FakeOps of the unit tests records their bytes, as it already records port writes and power-off requests. Behavior is unchanged. Every repair failure passes the status, code, source, phase, and detail that it passed before. An event writes the same bytes, with the same open flags, to the kernel log, port B, and the console, in that order, and reads the asynchronous-output flag at the same points. A new unit test checks a repair failure's event line at all three destinations and its power-off status, with and without report-only mode, in the glibc and musl test runs. The microVM restore scenarios run restore_work, and so release_suppression, in guests on KVM, MSHV, and WHP. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- nvx-rs/src/guest/time/commands.rs | 18 ++--- nvx-rs/src/guest/time/daemon.rs | 44 +++--------- nvx-rs/src/guest/time/system.rs | 110 +++++++++++++++++++++++------- 3 files changed, 101 insertions(+), 71 deletions(-) diff --git a/nvx-rs/src/guest/time/commands.rs b/nvx-rs/src/guest/time/commands.rs index 9246a311..4bba54f9 100644 --- a/nvx-rs/src/guest/time/commands.rs +++ b/nvx-rs/src/guest/time/commands.rs @@ -8,16 +8,16 @@ use super::checks::{self, BootLog, Checks}; use super::cpu_mask::CpuMask; use super::daemon::{self, Promoter, RestoreSignal}; use super::decoders::{self, GENERATION_ID_SIZE, PACKET_HEADER_SIZE, PacketHeader, RestorePacket}; -use super::events::{CheckId, EventSource, ViolationCode}; +use super::events::{CheckId, ViolationCode}; use super::state::{ CheckState, CheckStatus, Discontinuity, DowntimeSource, SampleRejection, TimeState, }; use super::system::{ self, PORTB_GENERATION_ID_AVAILABLE, PORTB_PACKET_AVAILABLE, PORTB_TIME_WINDOW, - PRIVATE_FILE_MODE, PortIo, PowerOffStatus, RESTORE_PATH, RESTORE_TEMP_PATH, Runtime, - SELECT_GENERATION_ID, SELECT_PACKET, SNAPSHOT_ACKNOWLEDGE, SampleError, clock_ns, cpu_time_ns, - current_frequency, initial_sample, portb_read, set_frequency, state_apply, state_load, - state_store, step_clock, suppression_restore, suppression_save, + PRIVATE_FILE_MODE, PortIo, RESTORE_PATH, RESTORE_TEMP_PATH, Runtime, SELECT_GENERATION_ID, + SELECT_PACKET, SNAPSHOT_ACKNOWLEDGE, SampleError, clock_ns, cpu_time_ns, current_frequency, + initial_sample, portb_read, set_frequency, state_apply, state_load, state_store, step_clock, + suppression_restore, suppression_save, }; use super::{DEFERRED_START_NS, NSEC_PER_USEC, Phase, USAGE}; use crate::guest::parse::parse_decimal; @@ -399,13 +399,7 @@ fn repair_failed( code: ViolationCode, detail: impl AsRef<[u8]>, ) -> Result<(), CommandError> { - runtime.fail_fatal( - PowerOffStatus::Repair, - code, - EventSource::Repair, - Phase::Restore, - detail.as_ref(), - ); + runtime.repair_failure(code, detail.as_ref()); Err(CommandError::Operation) } diff --git a/nvx-rs/src/guest/time/daemon.rs b/nvx-rs/src/guest/time/daemon.rs index 9602ac53..2bea7e42 100644 --- a/nvx-rs/src/guest/time/daemon.rs +++ b/nvx-rs/src/guest/time/daemon.rs @@ -497,23 +497,12 @@ pub(crate) fn restore_work( grace_period_release() }; if !released { - runtime.fail_fatal( - PowerOffStatus::Repair, + runtime.repair_failure( ViolationCode::RepairSuppression, - EventSource::Repair, - Phase::Restore, b"the RCU grace-period release failed", ); } - if let Err(detail) = suppression_restore(true) { - runtime.fail_fatal( - PowerOffStatus::Repair, - ViolationCode::RepairSuppression, - EventSource::Repair, - Phase::Restore, - &detail, - ); - } + release_suppression(runtime); let verdict = checks::check_timer_list(checks.online, checks::TIMER_LIST_WAIT); checks.record(runtime, verdict); if let Err(error) = checks::record_check( @@ -559,13 +548,7 @@ fn start_restore(runtime: &Runtime<'_>, daemon: &mut Daemon, restore: PendingRes let (new_cpus, generation) = match parse_restore_state() { Ok(value) => value, Err(detail) => { - runtime.fail_fatal( - PowerOffStatus::Repair, - ViolationCode::RepairSuppression, - EventSource::Repair, - Phase::Restore, - &detail, - ); + runtime.repair_failure(ViolationCode::RepairSuppression, &detail); return; } }; @@ -586,11 +569,8 @@ fn start_restore(runtime: &Runtime<'_>, daemon: &mut Daemon, restore: PendingRes } Ok(ForkResult::Parent(process)) => process, Err(error) => { - runtime.fail_fatal( - PowerOffStatus::Repair, + runtime.repair_failure( ViolationCode::RepairSuppression, - EventSource::Repair, - Phase::Restore, format!("cannot start the restore work: {}", error.desc()).as_bytes(), ); return; @@ -603,16 +583,11 @@ fn start_restore(runtime: &Runtime<'_>, daemon: &mut Daemon, restore: PendingRes }); } -/// Restores saved stall settings after a worker deadline or completion. +/// Restores the saved stall-detector settings when repair step 7 ends, or when its worker passes +/// its deadline or fails, and reports a repair failure if it cannot. fn release_suppression(runtime: &Runtime<'_>) { if let Err(detail) = suppression_restore(true) { - runtime.fail_fatal( - PowerOffStatus::Repair, - ViolationCode::RepairSuppression, - EventSource::Repair, - Phase::Restore, - &detail, - ); + runtime.repair_failure(ViolationCode::RepairSuppression, &detail); } } @@ -629,11 +604,8 @@ fn reap_children(runtime: &Runtime<'_>, daemon: &mut Daemon) { ChildStatus::Signaled(signal) => signal, _ => 0, }; - runtime.fail_fatal( - PowerOffStatus::Repair, + runtime.repair_failure( ViolationCode::RepairSuppression, - EventSource::Repair, - Phase::Restore, format!("the restore work ended with signal {signal}").as_bytes(), ); } diff --git a/nvx-rs/src/guest/time/system.rs b/nvx-rs/src/guest/time/system.rs index 31211013..900d7a27 100644 --- a/nvx-rs/src/guest/time/system.rs +++ b/nvx-rs/src/guest/time/system.rs @@ -150,6 +150,11 @@ pub(crate) trait PrivilegedOps: Sync { fn adjust_clock(&self, adjustment: ClockAdjustment) -> Result; /// Stops the VM with `status`, which in production does not return. fn power_off(&self, status: PowerOffStatus); + /// Appends `record` to the kernel log, when the process may write it. + fn write_kernel_log(&self, record: &[u8]); + /// Writes `separator` and then `line` to the console, or to standard error when the console + /// does not open. + fn write_console(&self, separator: &[u8], line: &[u8]); } /// An MSR device, or the token of a test's fake. @@ -214,6 +219,27 @@ impl PrivilegedOps for RealOps { fn power_off(&self, status: PowerOffStatus) { sys::power_off(status.code()) } + + fn write_kernel_log(&self, record: &[u8]) { + let flags = OpenFlags::O_WRONLY | OpenFlags::O_CLOEXEC; + if let Ok(log) = sys::open(kernel::KERNEL_LOG_DEVICE, flags, Mode::empty()) { + let _ = log.write_all(record); + } + } + + fn write_console(&self, separator: &[u8], line: &[u8]) { + let flags = OpenFlags::O_WRONLY | OpenFlags::O_NOCTTY | OpenFlags::O_CLOEXEC; + match sys::open(kernel::CONSOLE_DEVICE, flags, Mode::empty()) { + Ok(console) => { + let _ = console.write_all(separator); + let _ = console.write_all(line); + } + Err(_) => { + sys::write_standard_error(separator); + sys::write_standard_error(line); + } + } + } } /// Returns the negative `errno` of an MSR access, or zero for one that succeeded, as the time @@ -302,10 +328,8 @@ impl<'a> Runtime<'a> { clock_ns(sys::Clock::Boottime), detail, ); - let flags = OpenFlags::O_WRONLY | OpenFlags::O_CLOEXEC; - if let Ok(log) = sys::open(kernel::KERNEL_LOG_DEVICE, flags, Mode::empty()) { - let _ = log.write_all(&[KERNEL_LOG_PRIORITY, line.as_bytes()].concat()); - } + self.ops + .write_kernel_log(&[KERNEL_LOG_PRIORITY, line.as_bytes()].concat()); if let Ok(ports) = self.ports() { if self.async_output.load(Ordering::Relaxed) { ports.outb(Port::PortbData, b'\n'); @@ -314,7 +338,12 @@ impl<'a> Runtime<'a> { ports.outb(Port::PortbData, byte); } } - self.console_write(line.as_bytes()); + let separator: &[u8] = if self.async_output.load(Ordering::Relaxed) { + b"\n" + } else { + b"" + }; + self.ops.write_console(separator, line.as_bytes()); let _ = count_violation(); } @@ -342,24 +371,16 @@ impl<'a> Runtime<'a> { } } - /// Writes one event to the console or standard error fallback. - fn console_write(&self, line: &[u8]) { - let flags = OpenFlags::O_WRONLY | OpenFlags::O_NOCTTY | OpenFlags::O_CLOEXEC; - let separator: &[u8] = if self.async_output.load(Ordering::Relaxed) { - b"\n" - } else { - b"" - }; - match sys::open(kernel::CONSOLE_DEVICE, flags, Mode::empty()) { - Ok(console) => { - let _ = console.write_all(separator); - let _ = console.write_all(line); - } - Err(_) => { - sys::write_standard_error(separator); - sys::write_standard_error(line); - } - } + /// Reports that restore-time repair failed, a fatal event of the restore phase, and powers off + /// with the repair status unless report-only. + pub(crate) fn repair_failure(&self, code: ViolationCode, detail: &[u8]) { + self.fail_fatal( + PowerOffStatus::Repair, + code, + EventSource::Repair, + Phase::Restore, + detail, + ); } } @@ -712,6 +733,10 @@ pub(crate) mod tests { pub(crate) adjustments: Mutex>, /// The last power-off status, or zero. pub(crate) power: AtomicUsize, + /// Kernel log records, in order. + pub(crate) kernel_log: Mutex>, + /// Console output, in order. + pub(crate) console: Mutex>, } impl FakeOps { @@ -723,6 +748,8 @@ pub(crate) mod tests { output: Mutex::new(Vec::new()), adjustments: Mutex::new(Vec::new()), power: AtomicUsize::new(0), + kernel_log: Mutex::new(Vec::new()), + console: Mutex::new(Vec::new()), } } } @@ -767,6 +794,16 @@ pub(crate) mod tests { self.power .store(usize::from(status.code()), Ordering::Relaxed); } + + fn write_kernel_log(&self, record: &[u8]) { + self.kernel_log.lock().unwrap().extend_from_slice(record); + } + + fn write_console(&self, separator: &[u8], line: &[u8]) { + let mut console = self.console.lock().unwrap(); + console.extend_from_slice(separator); + console.extend_from_slice(line); + } } #[test] @@ -861,6 +898,33 @@ pub(crate) mod tests { assert_eq!(ops.power.load(Ordering::Relaxed), 195); } + #[test] + fn repair_failures_report_restore_events_and_power_off_unless_report_only() { + for (report_only, prefix, power) in [ + (false, "NVX-TIME-ABI", PowerOffStatus::Repair.code()), + (true, "NVX-TIME-REPORT", 0), + ] { + let ops = FakeOps::new([]); + let runtime = Runtime::new(&ops, report_only); + runtime.set_generation(4); + runtime.repair_failure(ViolationCode::RepairSuppression, b"cannot restore"); + let line = String::from_utf8(ops.console.lock().unwrap().clone()).unwrap(); + let start = format!( + "{prefix}-VIOLATION: v=1 code=G_REPAIR_SUPPRESSION source=repair phase=restore \ + generation=4 boottime_ns=" + ); + assert!(line.starts_with(&start), "{line}"); + assert!(line.ends_with(" detail=\"cannot restore\"\n"), "{line}"); + assert_eq!( + *ops.kernel_log.lock().unwrap(), + [KERNEL_LOG_PRIORITY, line.as_bytes()].concat() + ); + let port: Vec<_> = line.bytes().map(|byte| (Port::PortbData, byte)).collect(); + assert_eq!(*ops.output.lock().unwrap(), port); + assert_eq!(ops.power.load(Ordering::Relaxed), usize::from(power)); + } + } + #[test] fn modes_of_the_runtime_files_match_the_c_program() { assert_eq!(DIRECTORY_MODE.bits(), 0o755);