nvx-rs: report time-ABI repair failures through one Runtime method

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

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(),
             );
         }

nvx-rs/src/guest/time/system.rs

@@ -150,6 +150,11 @@ pub(crate) trait PrivilegedOps: Sync {
     fn adjust_clock(&self, adjustment: ClockAdjustment) -> Result<ClockDiscipline, Errno>;
     /// 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<Vec<ClockAdjustment>>,
         /// The last power-off status, or zero.
         pub(crate) power: AtomicUsize,
+        /// Kernel log records, in order.
+        pub(crate) kernel_log: Mutex<Vec<u8>>,
+        /// Console output, in order.
+        pub(crate) console: Mutex<Vec<u8>>,
     }
 
     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);