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);