debug(vcpu): log every KVM_RUN entry/exit/result and recv

Expand the ordered DBGSEQ trace to capture the full vCPU state machine:
- run_emulation: KVM_RUN enter, KVM_RUN exit reason (VcpuExit variant
  or errno), and the resulting VcpuEmulation
- paused(): blocking recv()
- exit(): entry + each recv() result in the Finish-wait loop
- running(): try_recv result + Finish
- send_event(): channel send, immediate_exit, kill result
- signal handler: receiving TID + fire count
- watchdog: kick stats + per-thread stacks + signal masks

Tracing is gated behind debug_enable_vcpu_trace() and only enabled by
test_build_and_boot_microvm, so the production vCPU path used by the
functional and performance tests is not flooded.

Signed-off-by: Riccardo Mancini <mancio@amazon.com>

Author: Manciukic

src/vmm/src/vstate/vcpu.rs

@@ -6,7 +6,7 @@
 // found in the THIRD-PARTY file.
 
 use std::os::fd::AsRawFd;
-use std::sync::atomic::{Ordering, fence};
+use std::sync::atomic::{AtomicI64, AtomicU8, AtomicU64, Ordering, fence};
 use std::sync::mpsc::{Receiver, Sender, TryRecvError, channel};
 use std::sync::{Arc, Barrier};
 use std::{fmt, io, thread};
@@ -32,6 +32,48 @@ use crate::vstate::vm::KvmVm;
 /// Signal number (SIGRTMIN) used to kick Vcpus.
 pub const VCPU_RTSIG_OFFSET: i32 = 0;
 
+/// DEBUG: global monotonic sequence counter for ordering log lines across threads.
+static DEBUG_SEQ: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64::new(0);
+
+/// DEBUG: whether verbose vCPU tracing is enabled. Off by default so the
+/// production vCPU path used by functional/performance tests is not flooded.
+/// Enabled explicitly by tests via `debug_enable_vcpu_trace()`.
+static DEBUG_TRACE_ENABLED: AtomicU8 = AtomicU8::new(0);
+
+/// DEBUG: enable verbose vCPU tracing for the current process. Intended to be
+/// called only from the relevant integration test.
+pub fn debug_enable_vcpu_trace() {
+    DEBUG_TRACE_ENABLED.store(1, Ordering::Relaxed);
+}
+
+/// DEBUG: emit an ordered log line with a sequence number.
+fn debug_seq_log(args: std::fmt::Arguments) {
+    if DEBUG_TRACE_ENABLED.load(Ordering::Relaxed) == 0 {
+        return;
+    }
+    let seq = DEBUG_SEQ.fetch_add(1, Ordering::SeqCst);
+    eprintln!("[DBGSEQ {seq}] {args}");
+}
+
+/// DEBUG: number of times the vCPU kick signal handler has fired (process-wide).
+pub static KICK_SIGNAL_COUNT: AtomicU64 = AtomicU64::new(0);
+/// DEBUG: TID observed inside the kick signal handler on its most recent firing.
+pub static KICK_SIGNAL_LAST_TID: AtomicI64 = AtomicI64::new(-1);
+
+/// DEBUG: returns (handler_fire_count, last_handler_tid) for the kick signal.
+pub fn debug_kick_signal_stats() -> (u64, i64) {
+    (
+        KICK_SIGNAL_COUNT.load(Ordering::SeqCst),
+        KICK_SIGNAL_LAST_TID.load(Ordering::SeqCst),
+    )
+}
+
+/// DEBUG: async-signal-safe gettid().
+fn debug_gettid() -> i64 {
+    // SAFETY: SYS_gettid is always available and takes no arguments.
+    unsafe { libc::syscall(libc::SYS_gettid) }
+}
+
 /// Errors associated with the wrappers over KVM ioctls.
 #[derive(Debug, thiserror::Error, displaydoc::Display)]
 pub enum VcpuError {
@@ -109,6 +151,10 @@ impl Vcpu {
     /// one.
     fn register_kick_signal_handler(&mut self) {
         extern "C" fn handle_signal(_: c_int, _: *mut siginfo_t, _: *mut c_void) {
+            // DEBUG: record which TID actually received the kick and how many times.
+            // Atomic stores + the gettid syscall are async-signal-safe.
+            KICK_SIGNAL_LAST_TID.store(debug_gettid(), Ordering::SeqCst);
+            KICK_SIGNAL_COUNT.fetch_add(1, Ordering::SeqCst);
             // We write to the immediate_exit from other thread, so make sure the read in the
             // KVM_RUN sees the up to date value
             fence(Ordering::Acquire);
@@ -181,6 +227,11 @@ impl Vcpu {
             .spawn(move || {
                 let filter = &*seccomp_filter;
                 self.register_kick_signal_handler();
+                debug_seq_log(format_args!(
+                    "vcpu{} thread started, tid={}",
+                    self.kvm_vcpu.index,
+                    debug_gettid()
+                ));
                 // Synchronization to make sure thread local data is initialized.
                 barrier.wait();
                 self.run(filter);
@@ -245,7 +296,12 @@ impl Vcpu {
         let mut state = StateMachine::next(Self::running);
 
         // Break this emulation loop on any transition request/external event.
-        match self.event_receiver.try_recv() {
+        let recv_result = self.event_receiver.try_recv();
+        debug_seq_log(format_args!(
+            "vcpu{} running: inner loop broke, try_recv = {:?}",
+            self.kvm_vcpu.index, recv_result
+        ));
+        match recv_result {
             // Running ---- Pause ----> Paused
             Ok(VcpuEvent::Pause) => {
                 // Nothing special to do.
@@ -280,7 +336,13 @@ impl Vcpu {
                     )))
                     .expect("vcpu channel unexpectedly closed");
             }
-            Ok(VcpuEvent::Finish) => return StateMachine::finish(),
+            Ok(VcpuEvent::Finish) => {
+                debug_seq_log(format_args!(
+                    "vcpu{} running: got Finish -> StateMachine::finish",
+                    self.kvm_vcpu.index
+                ));
+                return StateMachine::finish();
+            }
             // Unhandled exit of the other end.
             Err(TryRecvError::Disconnected) => {
                 // Move to 'exited' state.
@@ -295,6 +357,10 @@ impl Vcpu {
 
     // This is the main loop of the `Paused` state.
     fn paused(&mut self) -> StateMachine<Self> {
+        debug_seq_log(format_args!(
+            "vcpu{} paused: blocking on recv()",
+            self.kvm_vcpu.index
+        ));
         match self.event_receiver.recv() {
             // Paused ---- Resume ----> Running
             Ok(VcpuEvent::Resume) => {
@@ -363,6 +429,10 @@ impl Vcpu {
     // Note that this function isn't called when the guest asks for a CPU
     // reset via the i8042 controller on x86.
     fn exit(&mut self, exit_code: FcExitCode) -> StateMachine<Self> {
+        let idx = self.kvm_vcpu.index;
+        debug_seq_log(format_args!(
+            "vcpu{idx} exit() entered, exit_code={exit_code:?}"
+        ));
         if let Err(err) = self.exit_evt.write(1) {
             METRICS.vcpu.failures.inc();
             error!("Failed signaling vcpu exit event: {}", err);
@@ -373,7 +443,9 @@ impl Vcpu {
                 .send(VcpuResponse::Exited(exit_code))
                 .expect("vcpu channel unexpectedly closed");
             // Wait for and only accept 'VcpuEvent::Finish'.
-            if let Ok(VcpuEvent::Finish) = self.event_receiver.recv() {
+            let ev = self.event_receiver.recv();
+            debug_seq_log(format_args!("vcpu{idx} exit() recv = {ev:?}"));
+            if let Ok(VcpuEvent::Finish) = ev {
                 break;
             }
         }
@@ -384,15 +456,29 @@ impl Vcpu {
     ///
     /// Returns error or enum specifying whether emulation was handled or interrupted.
     pub fn run_emulation(&mut self) -> Result<VcpuEmulation, VcpuError> {
+        let idx = self.kvm_vcpu.index;
         if self.kvm_vcpu.fd.get_kvm_run().immediate_exit == 1u8 {
             warn!("Requested a vCPU run with immediate_exit enabled. The operation was skipped");
             self.kvm_vcpu.fd.set_kvm_immediate_exit(0);
+            debug_seq_log(format_args!(
+                "vcpu{idx} run_emulation: immediate_exit path -> Interrupted"
+            ));
             return Ok(VcpuEmulation::Interrupted);
         }
 
-        match self.kvm_vcpu.fd.run() {
+        debug_seq_log(format_args!("vcpu{idx} KVM_RUN enter"));
+        let run_result = self.kvm_vcpu.fd.run();
+        match &run_result {
+            Ok(exit) => debug_seq_log(format_args!("vcpu{idx} KVM_RUN exit: {exit:?}")),
+            Err(err) => debug_seq_log(format_args!("vcpu{idx} KVM_RUN err: errno={}", err.errno())),
+        }
+
+        match run_result {
             Err(ref err) if err.errno() == libc::EINTR => {
                 self.kvm_vcpu.fd.set_kvm_immediate_exit(0);
+                debug_seq_log(format_args!(
+                    "vcpu{idx} run_emulation: EINTR path -> Interrupted"
+                ));
                 // Notify that this KVM_RUN was interrupted.
                 Ok(VcpuEmulation::Interrupted)
             }
@@ -406,7 +492,11 @@ impl Vcpu {
 
                 Ok(VcpuEmulation::Paused)
             }
-            emulation_result => handle_kvm_exit(&mut self.kvm_vcpu.peripherals, emulation_result),
+            emulation_result => {
+                let res = handle_kvm_exit(&mut self.kvm_vcpu.peripherals, emulation_result);
+                debug_seq_log(format_args!("vcpu{idx} run_emulation result: {res:?}"));
+                res
+            }
         }
     }
 }
@@ -599,6 +689,7 @@ impl VcpuHandle {
     ///
     /// When [`vmm_sys_util::linux::signal::Killable::kill`] errors.
     pub fn send_event(&mut self, event: VcpuEvent) -> Result<(), VcpuSendEventError> {
+        debug_seq_log(format_args!("send_event: sending {:?} to channel", event));
         // Use expect() to crash if the other thread closed this channel.
         self.event_sender
             .send(event)
@@ -607,11 +698,17 @@ impl VcpuHandle {
         // Add a fence to ensure the write is visible to the vpu thread
         self.vcpu_fd.set_kvm_immediate_exit(1);
         fence(Ordering::Release);
-        self.vcpu_thread
+        let kill_res = self
+            .vcpu_thread
             .as_ref()
             // Safe to unwrap since constructor make this 'Some'.
             .unwrap()
-            .kill(sigrtmin() + VCPU_RTSIG_OFFSET)?;
+            .kill(sigrtmin() + VCPU_RTSIG_OFFSET);
+        debug_seq_log(format_args!(
+            "send_event: set immediate_exit=1, kill result: {:?}",
+            kill_res
+        ));
+        kill_res?;
         Ok(())
     }
 
@@ -624,13 +721,6 @@ impl VcpuHandle {
 // Wait for the Vcpu thread to finish execution
 impl Drop for VcpuHandle {
     fn drop(&mut self) {
-        // We assume that by the time a VcpuHandle is dropped, other code has run to
-        // get the state machine loop to finish so the thread is ready to join.
-        // The strategy of avoiding more complex messaging protocols during the Drop
-        // helps avoid cycles which were preventing a truly clean shutdown.
-        //
-        // If the code hangs at this point, that means that a Finish event was not
-        // sent by Vmm.
         self.vcpu_thread.take().unwrap().join().unwrap();
     }
 }

src/vmm/tests/integration_tests.rs

@@ -4,7 +4,6 @@
 #![allow(clippy::cast_possible_truncation, clippy::tests_outside_test_module)]
 
 use std::io::{Seek, SeekFrom};
-use std::os::unix::io::AsRawFd;
 use std::sync::{Arc, Mutex};
 use std::thread;
 use std::time::Duration;
@@ -43,38 +42,34 @@ fn check_booted_microvm(vmm: Arc<Mutex<Vmm>>, mut evmgr: EventManager) {
     vmm.lock().unwrap().stop(FcExitCode::Ok);
 
     // Watchdog: if the test hangs for 30s, dump all thread kernel stacks
-    let watchdog_vmm = vmm.clone();
-    let watchdog = thread::spawn(move || {
+    let watchdog = thread::spawn(|| {
         thread::sleep(Duration::from_secs(30));
-        eprintln!("=== WATCHDOG: test hung for 30s, dumping diagnostics ===");
-
-        // Dump VMM state
-        if let Ok(vmm_guard) = watchdog_vmm.lock() {
-            eprintln!("  shutdown_exit_code: {:?}", vmm_guard.shutdown_exit_code());
-            if let Some(kvm_vm) = vmm_guard.vm.as_kvm() {
-                // Check if exit_evt has a pending value
-                let exit_evt = kvm_vm.vcpus_exit_evt();
-                eprintln!("  vcpus_exit_evt fd: {}", exit_evt.as_raw_fd());
-                // Try a non-blocking read to see if the event was written
-                let val = exit_evt.read();
-                eprintln!("  vcpus_exit_evt read: {:?}", val);
-                eprintln!("  vcpus_handles count: {}", kvm_vm.vcpus_handles().len());
-            }
-        } else {
-            eprintln!("  WARNING: could not lock vmm (poisoned?)");
-        }
-
-        // Dump thread kernel stacks
+        eprintln!("=== WATCHDOG: test hung for 30s, dumping thread stacks ===");
+        let (kick_count, kick_tid) = vmm::vstate::vcpu::debug_kick_signal_stats();
+        eprintln!(
+            "  kick signal: handler fired {} times, last handler tid = {}",
+            kick_count, kick_tid
+        );
         let pid = std::process::id();
         if let Ok(entries) = std::fs::read_dir(format!("/proc/{pid}/task")) {
             for entry in entries.flatten() {
                 let tid = entry.file_name();
                 let tid = tid.to_string_lossy();
                 let stack_path = format!("/proc/{pid}/task/{tid}/stack");
                 let wchan_path = format!("/proc/{pid}/task/{tid}/wchan");
+                let status_path = format!("/proc/{pid}/task/{tid}/status");
                 let wchan = std::fs::read_to_string(&wchan_path).unwrap_or_default();
                 let stack = std::fs::read_to_string(&stack_path).unwrap_or_default();
                 eprintln!("--- TID {tid} wchan={} ---\n{stack}", wchan.trim());
+                // Dump signal state: SigBlk (blocked), SigPnd (thread-pending),
+                // ShdPnd (process-pending), SigCgt (caught). SIGRTMIN is signal
+                // 34 -> bit 33 -> mask 0x0000000200000000.
+                let status = std::fs::read_to_string(&status_path).unwrap_or_default();
+                for line in status.lines() {
+                    if line.starts_with("Sig") || line.starts_with("Shd") {
+                        eprintln!("  {tid}: {line}");
+                    }
+                }
             }
         }
         eprintln!("=== WATCHDOG: aborting ===");
@@ -89,6 +84,8 @@ fn check_booted_microvm(vmm: Arc<Mutex<Vmm>>, mut evmgr: EventManager) {
 
 #[test]
 fn test_build_and_boot_microvm() {
+    // DEBUG: enable verbose vCPU tracing for this test only.
+    vmm::vstate::vcpu::debug_enable_vcpu_trace();
     // Error case: no boot source configured.
     {
         let resources: VmResources = MockVmResources::new().into();