netvsp & net_mana - instrument VTL0 & host calls at risk of hanging (#3170)

There's a bunch of async operations with long or no timeout which are at
risk of hanging the NetVSP code; adding spans to those actions makes
them more obvious in tracing, with additional context to track down
miscreant calls or make a misbehaving VM more obvious.

---------

Co-authored-by: Ben Lewis <Ben.Lewis@microsoft.com>
Co-authored-by: Brian Perkins <Brian-Perkins@users.noreply.github.com>

Author: 3 people

openhcl/underhill_core/src/emuplat/netvsp.rs

@@ -462,7 +462,14 @@ impl HclNetworkVFManagerWorker {
         // method.
         *self.guest_state.offered_to_guest.lock().await = false;
         // Give the network stack a chance to prepare for the removal.
-        if let Err(err) = self.send_vf_state_change_notifications().await {
+        if let Err(err) = self
+            .send_vf_state_change_notifications()
+            .instrument(tracing::info_span!(
+                "sending VTL0 VF removal notice",
+                vtl2_vfid,
+                vtl0_bus = %bus_control))
+            .await
+        {
             tracing::error!(
                 vtl2_vfid,
                 err = err.as_ref() as &dyn std::error::Error,
@@ -840,13 +847,16 @@ impl HclNetworkVFManagerWorker {
                     if !self.guest_state.is_offered_to_guest().await
                         && self.guest_state.vtl0_vfid().await.is_some()
                     {
-                        tracing::info!(
-                            vtl2_vfid,
-                            vtl0_vfid = vtl0_vfid_from_bus_control(&self.vtl0_bus_control),
-                            "Adding VF to VTL0"
-                        );
                         if let Vtl0Bus::Present(vtl0_bus_control) = &self.vtl0_bus_control {
-                            match vtl0_bus_control.offer_device().await {
+                            match vtl0_bus_control
+                                .offer_device()
+                                .instrument(tracing::info_span!(
+                                    "adding VF to VTL0",
+                                    vtl2_vfid,
+                                    vtl0_vfid = vtl0_vfid_from_bus_control(&self.vtl0_bus_control)
+                                ))
+                                .await
+                            {
                                 Ok(_) => {
                                     *self.guest_state.offered_to_guest.lock().await = true;
                                 }
@@ -860,6 +870,12 @@ impl HclNetworkVFManagerWorker {
                                     );
                                 }
                             }
+                        } else {
+                            tracing::info!(
+                                vtl2_vfid,
+                                %self.vtl0_bus_control,
+                                "Ignoring VTL0 device request from guest"
+                            );
                         }
                     }
                 }

vm/devices/net/net_mana/src/lib.rs

@@ -69,6 +69,7 @@ use std::sync::atomic::Ordering;
 use std::task::Context;
 use std::task::Poll;
 use thiserror::Error;
+use tracing::Instrument;
 use user_driver::DeviceBacking;
 use user_driver::DmaClient;
 use user_driver::interrupt::DeviceInterrupt;
@@ -490,6 +491,10 @@ impl<T: DeviceBacking> Endpoint for ManaEndpoint<T> {
                 default_rxobj: None,
                 indirection_table: None,
             })
+            .instrument(tracing::info_span!(
+                "clearing rx configuration",
+                vport_id = self.vport.id()
+            ))
             .await
         {
             tracing::warn!(
@@ -499,12 +504,25 @@ impl<T: DeviceBacking> Endpoint for ManaEndpoint<T> {
         }
 
         self.queues.clear();
-        self.vport.destroy(std::mem::take(&mut self.arena)).await;
+        self.vport
+            .destroy(std::mem::take(&mut self.arena))
+            .instrument(tracing::info_span!(
+                "destroying vport resources",
+                vport_id = self.vport.id()
+            ))
+            .await;
         // Wait for all outstanding queues. There can be a delay switching out
         // the queues when an endpoint is removed, and the queue has access to
         // the vport which is being stopped here.
         if self.queue_tracker.0.load(Ordering::Acquire) > 0 {
-            self.queue_tracker.1.wait().await;
+            self.queue_tracker
+                .1
+                .wait()
+                .instrument(tracing::info_span!(
+                    "waiting for outstanding queues to stop",
+                    vport_id = self.vport.id()
+                ))
+                .await;
         }
     }
 

vm/devices/net/netvsp/src/lib.rs

@@ -1335,7 +1335,15 @@ impl VmbusDevice for Nic {
             }
 
             // Note that this await is not restartable.
-            self.coordinator.task_mut().endpoint.stop().await;
+            self.coordinator
+                .task_mut()
+                .endpoint
+                .stop()
+                .instrument(tracing::info_span!(
+                    "stopping coordinator endpoint",
+                    instance_id = %self.instance_id,
+                ))
+                .await;
 
             // Keep any VF's added to the guest. This is required to keep guest compat as
             // some apps (such as DPDK) relies on the VF sticking around even after vmbus