net_mana: downgrading invalid OOB traces from ERROR to WARN (#2163)

erfrimod · web-flow · commit 7aa1add8ac0c · 2025-10-14T14:38:21.000-07:00
When `net_mana::tx_poll` receives an CQE_TX_INVALID_OOB it is currently
logged as an Error. These events occur when the metadata does not match
how HW parsed the packet. They can be a result of a Guest Bug, HW Bug,
or OpenHCL Bug. They are common, possibly due to Encap, and only effect
the specific packet. Unfortunately, their frequency is causing confusion
when triaging other issues as it is not clear that `ty: 35` aka
`CQE_TX_INVALID_OOB ` is safe to ignore. Downgrading the tracing to
Warning to help folks better understand invalid OOB issues are probably
not the cause of whatever they're seeing.

* Adding to tracelimit macros to create event_ratelimited where callers
may supply the Level.
* Modifying net_mana to trace CQE_TX_GDMA_ERR at ERROR and
CQE_TX_INVALID_OOB at WARN
* Adding two new tests, one for valid packets and one for an invalid LSO
segment count (1)
  * Refactoring test helpers in net_mana to support the new tests
* Modifying bnic to enforce LSO segment counts
* Adding BackendQueueStats to net_backent so that new tests in net_mana
can check Counters: tx_packets, tx_errors, rx_packets, rx_errors
diff --git a/Cargo.lock b/Cargo.lock
@@ -2398,6 +2398,7 @@ dependencies = [
  "slab",
  "task_control",
  "thiserror 2.0.16",
+ "tracelimit",
  "tracing",
  "vm_resource",
  "vmcore",
@@ -4415,6 +4416,7 @@ dependencies = [
  "futures-concurrency",
  "guestmem",
  "inspect",
+ "inspect_counters",
  "memory_range",
  "mesh",
  "net_backend_resources",
diff --git a/support/tracelimit/src/lib.rs b/support/tracelimit/src/lib.rs
@@ -295,3 +295,156 @@ macro_rules! info_ratelimited {
         }
     };
 }
+
+/// As [`tracing::event!`], but rate limited.
+///
+/// Can be called with optional parameters to customize rate limiting:
+/// - `period: <ms>` - rate limiting period in milliseconds
+/// - `limit: <count>` - maximum events per period
+///
+/// `level` is required and must be a compile-time literal identifier (ERROR, WARN, INFO, DEBUG, TRACE).
+#[macro_export]
+macro_rules! event_ratelimited_static {
+    // With both period and limit and level
+    (level: $level:ident, period: $period:expr, limit: $limit:expr, $($rest:tt)*) => {{
+        static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
+        if let Ok(missed_events) = RATE_LIMITER.event_with_config(Some($period), Some($limit)) {
+            $crate::tracing::event!(
+                $crate::tracing::Level::$level,
+                dropped_ratelimited = missed_events,
+                $($rest)*
+            );
+        }
+    }};
+    // With only period and level
+    (level: $level:ident, period: $period:expr, $($rest:tt)*) => {{
+        static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
+        if let Ok(missed_events) = RATE_LIMITER.event_with_config(Some($period), None) {
+            $crate::tracing::event!(
+                $crate::tracing::Level::$level,
+                dropped_ratelimited = missed_events,
+                $($rest)*
+            );
+        }
+    }};
+    // With only limit and level
+    (level: $level:ident, limit: $limit:expr, $($rest:tt)*) => {{
+        static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
+        if let Ok(missed_events) = RATE_LIMITER.event_with_config(None, Some($limit)) {
+            $crate::tracing::event!(
+                $crate::tracing::Level::$level,
+                dropped_ratelimited = missed_events,
+                $($rest)*
+            );
+        }
+    }};
+    // Default case (only level provided)
+    (level: $level:ident, $($rest:tt)*) => {{
+        static RATE_LIMITER: $crate::RateLimiter = $crate::RateLimiter::new_default();
+        if let Ok(missed_events) = RATE_LIMITER.event() {
+            $crate::tracing::event!(
+                $crate::tracing::Level::$level,
+                dropped_ratelimited = missed_events,
+                $($rest)*
+            );
+        }
+    }};
+}
+
+/// Helper macro for dynamically dispatching to [`event_ratelimited_static!`] based on a runtime level.
+///
+/// This macro accepts a runtime `tracing::Level` expression and dispatches to the appropriate
+/// compile-time level identifier. Allows the log level to be determined at runtime.
+///
+/// Examples:
+/// ```
+/// use tracing::Level;
+/// use tracelimit::event_ratelimited;
+/// event_ratelimited!(Level::ERROR, period: 1000, limit: 5, "custome period and limit");
+/// event_ratelimited!(Level::WARN, period: 10000, "custom period only");
+/// event_ratelimited!(Level::INFO, limit: 50, "custom limit only");
+/// event_ratelimited!(Level::TRACE, "simple message");
+/// ```
+#[macro_export]
+macro_rules! event_ratelimited {
+    // With period and limit and level
+    ($level:expr, period: $period:expr, limit: $limit:expr, $($rest:tt)*) => {
+        match $level {
+            $crate::tracing::Level::ERROR => {
+                $crate::event_ratelimited_static!(level: ERROR, period: $period, limit: $limit, $($rest)*);
+            }
+            $crate::tracing::Level::WARN => {
+                $crate::event_ratelimited_static!(level: WARN, period: $period, limit: $limit, $($rest)*);
+            }
+            $crate::tracing::Level::INFO => {
+                $crate::event_ratelimited_static!(level: INFO, period: $period, limit: $limit, $($rest)*);
+            }
+            $crate::tracing::Level::DEBUG => {
+                $crate::event_ratelimited_static!(level: DEBUG, period: $period, limit: $limit, $($rest)*);
+            }
+            $crate::tracing::Level::TRACE => {
+                $crate::event_ratelimited_static!(level: TRACE, period: $period, limit: $limit, $($rest)*);
+            }
+        }
+    };
+    // With period and level
+    ($level:expr, period: $period:expr, $($rest:tt)*) => {
+        match $level {
+            $crate::tracing::Level::ERROR => {
+                $crate::event_ratelimited_static!(level: ERROR, period: $period, $($rest)*);
+            }
+            $crate::tracing::Level::WARN => {
+                $crate::event_ratelimited_static!(level: WARN, period: $period, $($rest)*);
+            }
+            $crate::tracing::Level::INFO => {
+                $crate::event_ratelimited_static!(level: INFO, period: $period, $($rest)*);
+            }
+            $crate::tracing::Level::DEBUG => {
+                $crate::event_ratelimited_static!(level: DEBUG, period: $period, $($rest)*);
+            }
+            $crate::tracing::Level::TRACE => {
+                $crate::event_ratelimited_static!(level: TRACE, period: $period, $($rest)*);
+            }
+        }
+    };
+    // With limit and level
+    ($level:expr, limit: $limit:expr, $($rest:tt)*) => {
+        match $level {
+            $crate::tracing::Level::ERROR => {
+                $crate::event_ratelimited_static!(level: ERROR, limit: $limit, $($rest)*);
+            }
+            $crate::tracing::Level::WARN => {
+                $crate::event_ratelimited_static!(level: WARN, limit: $limit, $($rest)*);
+            }
+            $crate::tracing::Level::INFO => {
+                $crate::event_ratelimited_static!(level: INFO, limit: $limit, $($rest)*);
+            }
+            $crate::tracing::Level::DEBUG => {
+                $crate::event_ratelimited_static!(level: DEBUG, limit: $limit, $($rest)*);
+            }
+            $crate::tracing::Level::TRACE => {
+                $crate::event_ratelimited_static!(level: TRACE, limit: $limit, $($rest)*);
+            }
+        }
+    };
+    // Default case (only level provided)
+    ($level:expr, $($rest:tt)*) => {
+        match $level {
+            $crate::tracing::Level::ERROR => {
+                $crate::event_ratelimited_static!(level: ERROR, $($rest)*);
+            }
+            $crate::tracing::Level::WARN => {
+                $crate::event_ratelimited_static!(level: WARN, $($rest)*);
+            }
+            $crate::tracing::Level::INFO => {
+                $crate::event_ratelimited_static!(level: INFO, $($rest)*);
+            }
+            $crate::tracing::Level::DEBUG => {
+                $crate::event_ratelimited_static!(level: DEBUG, $($rest)*);
+            }
+            $crate::tracing::Level::TRACE => {
+                $crate::event_ratelimited_static!(level: TRACE, $($rest)*);
+            }
+        }
+    };
+}
diff --git a/vm/devices/net/gdma/Cargo.toml b/vm/devices/net/gdma/Cargo.toml
@@ -23,6 +23,7 @@ vm_resource.workspace = true
 
 inspect.workspace = true
 task_control.workspace = true
+tracelimit.workspace = true
 
 anyhow.workspace = true
 async-trait.workspace = true
diff --git a/vm/devices/net/gdma/src/bnic.rs b/vm/devices/net/gdma/src/bnic.rs
@@ -1,6 +1,7 @@
 // Copyright (c) Microsoft Corporation.
 // Licensed under the MIT License.
 
+use self::bnic_defs::CQE_TX_GDMA_ERR;
 use self::bnic_defs::CQE_TX_OKAY;
 use self::bnic_defs::MANA_CQE_COMPLETION;
 use self::bnic_defs::ManaCommandCode;
@@ -560,6 +561,30 @@ impl TxRxTask {
             meta.offload_tcp_segmentation = true;
         }
 
+        // With LSO, the first SGE is the header and the rest are the payload.
+        // For LSO, the requirements by the GDMA hardware are:
+        // - The first SGE must be the header and must be <= 256 bytes.
+        // - There should be at least two SGEs.
+        // Possible test improvement: Disable the Queue to mimick the hardware behavior.
+        if meta.offload_tcp_segmentation {
+            if sqe.sgl().len() < 2 {
+                tracelimit::error_ratelimited!(
+                    sgl_count = sqe.sgl().len(),
+                    "LSO enabled, but only one SGE"
+                );
+                self.post_tx_completion_error();
+                return Ok(());
+            }
+            if sge0.size > 256 {
+                tracelimit::error_ratelimited!(
+                    sge0_size = sge0.size,
+                    "LSO enabled and SGE[0] size > 256 bytes"
+                );
+                self.post_tx_completion_error();
+                return Ok(());
+            }
+        }
+
         let tx_segments = &mut self.tx_segment_buffer;
         tx_segments.clear();
         tx_segments.push(TxSegment {
@@ -582,6 +607,20 @@ impl TxRxTask {
         Ok(())
     }
 
+    // Possible test improvement: provide proper OOB data for the GDMA error.
+    fn post_tx_completion_error(&mut self) {
+        let tx_oob = ManaTxCompOob {
+            cqe_hdr: ManaCqeHeader::new()
+                .with_client_type(MANA_CQE_COMPLETION)
+                .with_cqe_type(CQE_TX_GDMA_ERR),
+            tx_data_offset: 0,
+            offsets: ManaTxCompOobOffsets::new(),
+            reserved: [0; 12],
+        };
+        self.queues
+            .post_cq(self.sq_cq_id, tx_oob.as_bytes(), self.sq_id, true);
+    }
+
     fn post_tx_completion(&mut self) {
         let tx_oob = ManaTxCompOob {
             cqe_hdr: ManaCqeHeader::new()
diff --git a/vm/devices/net/net_backend/Cargo.toml b/vm/devices/net/net_backend/Cargo.toml
@@ -24,6 +24,7 @@ futures-concurrency.workspace = true
 parking_lot.workspace = true
 tracing.workspace = true
 thiserror.workspace = true
+inspect_counters.workspace = true
 
 [lints]
 workspace = true
diff --git a/vm/devices/net/net_backend/src/lib.rs b/vm/devices/net/net_backend/src/lib.rs
@@ -21,6 +21,7 @@ use futures_concurrency::future::Race;
 use guestmem::GuestMemory;
 use guestmem::GuestMemoryError;
 use inspect::InspectMut;
+use inspect_counters::Counter;
 use mesh::rpc::Rpc;
 use mesh::rpc::RpcSend;
 use null::NullEndpoint;
@@ -144,6 +145,12 @@ pub enum TxError {
     #[error("unrecoverable error. {0}")]
     Fatal(#[source] anyhow::Error),
 }
+pub trait BackendQueueStats {
+    fn rx_errors(&self) -> Counter;
+    fn tx_errors(&self) -> Counter;
+    fn rx_packets(&self) -> Counter;
+    fn tx_packets(&self) -> Counter;
+}
 
 /// A trait for sending and receiving network packets.
 #[async_trait]
@@ -172,6 +179,11 @@ pub trait Queue: Send + InspectMut {
 
     /// Get the buffer access.
     fn buffer_access(&mut self) -> Option<&mut dyn BufferAccess>;
+
+    /// Get queue statistics
+    fn queue_stats(&self) -> Option<&dyn BackendQueueStats> {
+        None // Default implementation - not all queues implement stats
+    }
 }
 
 /// A trait for providing access to guest memory buffers.
diff --git a/vm/devices/net/net_mana/src/lib.rs b/vm/devices/net/net_mana/src/lib.rs
