petri: detect hyper-v worker crash event and add logs

petri/src/vm/hyperv/powershell.rs

@@ -722,14 +722,14 @@ const HYPERV_VMMS_TABLE: &str = "Microsoft-Windows-Hyper-V-VMMS-Admin";
 
 /// Get Hyper-V event logs for a VM
 pub async fn hyperv_event_logs(
-    vmid: &Guid,
+    vmid: Option<&Guid>,
     start_time: &Timestamp,
 ) -> anyhow::Result<Vec<WinEvent>> {
-    let vmid = vmid.to_string();
+    let vmid = vmid.map(|id| id.to_string());
     run_get_winevent(
         &[HYPERV_WORKER_TABLE, HYPERV_VMMS_TABLE],
         Some(start_time),
-        Some(&vmid),
+        vmid.as_deref(),
         &[],
     )
     .await
@@ -801,8 +801,10 @@ pub const MSVM_TRIPLE_FAULT_INVALID_VP_REGISTER_ERROR: u32 = 18550;
 pub const MSVM_TRIPLE_FAULT_UNRECOVERABLE_EXCEPTION_ERROR: u32 = 18560;
 /// The vm was hibernated successfully.
 pub const MSVM_GUEST_HIBERNATE_SUCCESS: u32 = 18608;
+/// The vm has quit unexpectedly (the worker process terminated).
+pub const MSVM_VMMS_VM_TERMINATE_ERROR: u32 = 14070;
 
-const HALT_EVENT_IDS: [u32; 12] = [
+const HALT_EVENT_IDS: [u32; 13] = [
     MSVM_HOST_STOP_SUCCESS,
     MSVM_HOST_SHUTDOWN_SUCCESS,
     MSVM_GUEST_SHUTDOWN_SUCCESS,
@@ -815,6 +817,7 @@ const HALT_EVENT_IDS: [u32; 12] = [
     MSVM_TRIPLE_FAULT_INVALID_VP_REGISTER_ERROR,
     MSVM_TRIPLE_FAULT_UNRECOVERABLE_EXCEPTION_ERROR,
     MSVM_GUEST_HIBERNATE_SUCCESS,
+    MSVM_VMMS_VM_TERMINATE_ERROR,
 ];
 
 /// Get Hyper-V halt event logs for a VM

petri/src/vm/hyperv/vm.rs

@@ -46,6 +46,7 @@ pub struct HyperVVM {
     // state
     destroyed: bool,
     last_start_time: Option<Timestamp>,
+    last_log_flushed: Option<Timestamp>,
 }
 
 impl HyperVVM {
@@ -126,6 +127,7 @@ impl HyperVVM {
             driver,
             destroyed: false,
             last_start_time: None,
+            last_log_flushed: None,
         };
 
         // Remove the default network adapter
@@ -172,25 +174,35 @@ impl HyperVVM {
     }
 
     /// Get Hyper-V logs and write them to the log file
-    pub async fn flush_logs(&self) -> anyhow::Result<()> {
-        for event in powershell::hyperv_event_logs(&self.vmid, &self.create_time).await? {
-            self.log_file.write_entry_fmt(
-                Some(event.time_created),
-                match event.level {
-                    1 | 2 => Level::ERROR,
-                    3 => Level::WARN,
-                    5 => Level::TRACE,
-                    _ => Level::INFO,
-                },
-                format_args!(
-                    "[{}] {}: ({}, {}) {}",
-                    event.time_created, event.provider_name, event.level, event.id, event.message,
-                ),
-            );
+    pub async fn flush_logs(&mut self) -> anyhow::Result<()> {
+        let start_time = self.last_log_flushed.as_ref().unwrap_or(&self.create_time);
+        for event in powershell::hyperv_event_logs(Some(&self.vmid), start_time).await? {
+            self.log_winevent(&event);
+            if self.last_log_flushed.is_none_or(|t| t < event.time_created) {
+                // add 1ms to avoid duplicate log entries
+                self.last_log_flushed =
+                    Some(event.time_created.checked_add(Duration::from_millis(1))?);
+            }
         }
         Ok(())
     }
 
+    fn log_winevent(&self, event: &powershell::WinEvent) {
+        self.log_file.write_entry_fmt(
+            Some(event.time_created),
+            match event.level {
+                1 | 2 => Level::ERROR,
+                3 => Level::WARN,
+                5 => Level::TRACE,
+                _ => Level::INFO,
+            },
+            format_args!(
+                "[{}] {}: ({}, {}) {}",
+                event.time_created, event.provider_name, event.level, event.id, event.message,
+            ),
+        );
+    }
+
     /// Waits for an event emitted by the firmware about its boot status, and
     /// returns that status.
     pub async fn wait_for_boot_event(&mut self) -> anyhow::Result<FirmwareEvent> {
@@ -377,6 +389,7 @@ impl HyperVVM {
 
         let (halt_reason, timestamp) = self.wait_for_some(Self::halt_event).await?;
         if halt_reason == PetriHaltReason::Reset {
+            // add 1ms to avoid getting the same event again
             self.last_start_time = Some(timestamp.checked_add(Duration::from_millis(1))?);
         }
         Ok(halt_reason)
@@ -394,6 +407,19 @@ impl HyperVVM {
         }
         let event = events.first();
 
+        if event.is_some_and(|e| e.id == powershell::MSVM_VMMS_VM_TERMINATE_ERROR) {
+            tracing::error!("hyper-v worker process crashed");
+            // Get 5 seconds of non-vm-specific hyper-v logs preceding the crash
+            const COLLECT_HYPERV_CRASH_LOGS_SECONDS: u64 = 5;
+            let start_time = event
+                .unwrap()
+                .time_created
+                .checked_sub(Duration::from_secs(COLLECT_HYPERV_CRASH_LOGS_SECONDS))?;
+            for event in powershell::hyperv_event_logs(None, &start_time).await? {
+                self.log_winevent(&event);
+            }
+        }
+
         event
             .map(|e| {
                 Ok((
@@ -411,7 +437,8 @@ impl HyperVVM {
                         | powershell::MSVM_TRIPLE_FAULT_UNRECOVERABLE_EXCEPTION_ERROR => {
                             PetriHaltReason::TripleFault
                         }
-                        powershell::MSVM_STOP_CRITICAL_SUCCESS => PetriHaltReason::Other,
+                        powershell::MSVM_STOP_CRITICAL_SUCCESS
+                        | powershell::MSVM_VMMS_VM_TERMINATE_ERROR => PetriHaltReason::Other,
                         id => anyhow::bail!("Unexpected event id: {id}"),
                     },
                     e.time_created,
@@ -421,7 +448,7 @@ impl HyperVVM {
     }
 
     /// Wait for the VM shutdown ic
-    pub async fn wait_for_enlightened_shutdown_ready(&self) -> anyhow::Result<()> {
+    pub async fn wait_for_enlightened_shutdown_ready(&mut self) -> anyhow::Result<()> {
         self.wait_for(Self::shutdown_ic_status, powershell::VmShutdownIcStatus::Ok)
             .await
             .context("wait_for_enlightened_shutdown_ready")
@@ -440,10 +467,14 @@ impl HyperVVM {
     }
 
     async fn wait_for<T: std::fmt::Debug + PartialEq>(
-        &self,
+        &mut self,
         f: impl AsyncFn(&Self) -> anyhow::Result<T>,
         target: T,
     ) -> anyhow::Result<()> {
+        // flush the logs every time we start waiting for something in case
+        // they don't get flushed when the VM is destroyed.
+        // TODO: run this periodically in a task.
+        self.flush_logs().await?;
         loop {
             let state = f(self).await?;
             if state == target {
@@ -458,9 +489,11 @@ impl HyperVVM {
     }
 
     async fn wait_for_some<T: std::fmt::Debug + PartialEq>(
-        &self,
+        &mut self,
         f: impl AsyncFn(&Self) -> anyhow::Result<Option<T>>,
     ) -> anyhow::Result<T> {
+        // see comment in `wait_for` above
+        self.flush_logs().await?;
         loop {
             let state = f(self).await?;
             if let Some(state) = state {