transceivers: mitigate "stuck" front-io I2C

app/medusa/base.toml

@@ -131,7 +131,7 @@ name = "drv-transceivers-server"
 features = ["vlan"]
 priority = 6
 max-sizes = {flash = 65536, ram = 16384}
-stacksize = 4096
+stacksize = 4352
 start = true
 task-slots = [
     "i2c_driver",

app/sidecar/base.toml

@@ -247,7 +247,7 @@ name = "drv-transceivers-server"
 features = ["vlan", "thermal-control"]
 priority = 7
 max-sizes = {flash = 65536, ram = 16384}
-stacksize = 4096
+stacksize = 4352
 start = true
 task-slots = [
     "i2c_driver",

drv/fpga-api/src/lib.rs

@@ -29,6 +29,10 @@ pub enum FpgaError {
     AuxReadError,
     AuxMissingBlob,
     CommsError,
+
+    /// The SP decided to bail because the FPGA appears to be "stuck" on busy.
+    /// See: https://github.com/oxidecomputer/hubris/issues/2070
+    BusyTimeout,
 }
 
 // TODO is this right? We cause clients to panic if we die; should we have a
@@ -52,6 +56,7 @@ impl From<FpgaError> for u16 {
             FpgaError::AuxReadError => 0x0504,
             FpgaError::AuxMissingBlob => 0x0505,
             FpgaError::CommsError => 0x0506,
+            FpgaError::BusyTimeout => 0x0507,
         }
     }
 }
@@ -86,6 +91,7 @@ impl core::convert::TryFrom<u16> for FpgaError {
                 0x0504 => Ok(FpgaError::AuxReadError),
                 0x0505 => Ok(FpgaError::AuxMissingBlob),
                 0x0506 => Ok(FpgaError::CommsError),
+                0x0507 => Ok(FpgaError::BusyTimeout),
                 _ => Err(()),
             },
         }

drv/front-io-api/src/transceivers.rs

@@ -7,7 +7,7 @@ use core::sync::atomic::{AtomicU32, Ordering};
 use crate::{Addr, FrontIOError, Reg};
 use drv_fpga_api::{FpgaError, FpgaUserDesign, ReadOp, WriteOp};
 use drv_transceivers_api::{ModuleStatus, NUM_PORTS};
-use ringbuf::Count;
+use ringbuf::{Count, counted_ringbuf, ringbuf_entry};
 use transceiver_messages::ModuleId;
 use userlib::UnwrapLite;
 use zerocopy::{
@@ -700,6 +700,34 @@ impl core::ops::Index<LogicalPort> for LogicalPortFailureTypes {
     }
 }
 
+/// Time in ms the SP is willing to wait for an I2C transaction to complete
+/// before deciding to bail. The FPGA *should* be giving up after roughly
+/// 27ms (https://github.com/oxidecomputer/quartz/pull/452), but we are
+/// not seeing this happen in all failure modes. Rather than get stuck,
+/// the SP will declare a timeout on its own when necessary.
+///
+/// See: https://github.com/oxidecomputer/hubris/issues/2070
+const I2C_BUSY_TIMEOUT_MS: u64 = 50;
+
+#[derive(Copy, Clone, PartialEq, Count)]
+enum Trace {
+    #[count(skip)]
+    None,
+    /// We timed out while attempting to poll a port.
+    PollTimeout { port: PortLocation, status: u8 },
+    /// A port was busy when we tried to start a transaction.
+    StillBusy { port: PortLocation, status: u8 },
+}
+counted_ringbuf!(Trace, 16, Trace::None);
+
+/// Busy flags and port status as reported by the front-io FPGA.
+#[derive(IntoBytes, Default, FromBytes)]
+#[repr(C)]
+struct BusyAndPortStatus {
+    busy: u16,
+    status: [u8; 16],
+}
+
 #[derive(Copy, Clone)]
 pub struct PortI2CStatus {
     pub stretching_seen: bool,
@@ -1079,6 +1107,12 @@ impl Transceivers {
         buf: &mut [u8],
     ) -> Result<PortI2CStatus, FpgaError> {
         let port_loc = port.into();
+
+        // Set an upper deadline on how long we will wait for the FPGA to
+        // complete a transaction, before we declare it failed ourselves.
+        let deadline = userlib::sys_get_timer()
+            .now
+            .saturating_add(I2C_BUSY_TIMEOUT_MS);
         loop {
             let status_byte = self.get_i2c_status(port_loc)?;
             let status = PortI2CStatus::new(status_byte);
@@ -1092,6 +1126,13 @@ impl Transceivers {
                 return Ok(status);
             }
 
+            if userlib::sys_get_timer().now >= deadline {
+                ringbuf_entry!(Trace::PollTimeout {
+                    port: port_loc,
+                    status: status_byte,
+                });
+                return Err(FpgaError::BusyTimeout);
+            }
             userlib::hl::sleep_for(1);
         }
     }
@@ -1189,6 +1230,51 @@ impl Transceivers {
         Ok(())
     }
 
+    /// Check if the given i2c ports are idle, or are in a stuck-busy state.
+    pub fn check_i2c_idle(&self, mask: LogicalPortMask) -> ModuleResult {
+        let mut physical_failure = FpgaPortMasks::default();
+        let mut physical_error = FpgaPortMasks::default();
+        let phys_mask: FpgaPortMasks = mask.into();
+        let mut failure_types = LogicalPortFailureTypes::default();
+
+        for fpga_index in phys_mask.iter_fpgas() {
+            let status_all: BusyAndPortStatus =
+                match self.fpga(fpga_index).read(Addr::QSFP_I2C_BUSY0) {
+                    Ok(data) => data,
+                    Err(_) => {
+                        *physical_error.get_mut(fpga_index) =
+                            PhysicalPortMask(0xffff);
+                        continue;
+                    }
+                };
+
+            let busy = PhysicalPortMask(
+                status_all.busy & phys_mask.get(fpga_index).get(),
+            );
+            for port in (0..16).map(PhysicalPort) {
+                if !busy.is_set(port) {
+                    continue;
+                }
+                ringbuf_entry!(Trace::StillBusy {
+                    port: PortLocation {
+                        controller: fpga_index,
+                        port,
+                    },
+                    status: status_all.status[port.0 as usize],
+                });
+                physical_failure.get_mut(fpga_index).set(port);
+                let logical_port =
+                    port.to_logical_port(fpga_index).unwrap_lite();
+                failure_types.0[logical_port.0 as usize] =
+                    FpgaI2CFailure::I2CTransactionTimeout;
+            }
+        }
+        let error = mask & LogicalPortMask::from(physical_error);
+        let failure = mask & LogicalPortMask::from(physical_failure);
+        let success = mask & !(error | failure);
+        ModuleResult::new(success, failure, error, failure_types).unwrap_lite()
+    }
+
     /// Waits for all of the I2C busy bits to go low
     ///
     /// Returns a set of masks indicating which channels (among the ones active
@@ -1206,14 +1292,12 @@ impl Transceivers {
         let phys_mask: FpgaPortMasks = mask.into();
         let mut failure_types = LogicalPortFailureTypes::default();
 
-        #[derive(IntoBytes, Default, FromBytes)]
-        #[repr(C)]
-        struct BusyAndPortStatus {
-            busy: u16,
-            status: [u8; 16],
-        }
         for fpga_index in phys_mask.iter_fpgas() {
             let fpga = self.fpga(fpga_index);
+            let mut timed_out = PhysicalPortMask(0);
+            let deadline = userlib::sys_get_timer()
+                .now
+                .saturating_add(I2C_BUSY_TIMEOUT_MS);
             // This loop should break immediately, because I2C is fast
             let status_all = loop {
                 // Two bytes of BUSY, followed by 816bytes of port status
@@ -1227,7 +1311,18 @@ impl Transceivers {
                         BusyAndPortStatus::default()
                     }
                 };
-                if status_all.busy == 0 {
+                // Are any items still busy? If not, we're done here!
+                let busy = status_all.busy & phys_mask.get(fpga_index).get();
+                if busy == 0 {
+                    break status_all;
+                }
+
+                // If anything is still busy, AND it has been more than the
+                // chosen deadline, declare those ports as a "failure", which
+                // is an emulated FPGA timeout.
+                // See https://github.com/oxidecomputer/hubris/issues/2070
+                if userlib::sys_get_timer().now >= deadline {
+                    timed_out = PhysicalPortMask(busy);
                     break status_all;
                 }
                 userlib::hl::sleep_for(1);
@@ -1245,10 +1340,19 @@ impl Transceivers {
                 }
 
                 // cast status byte into a type
-                let failure = FpgaI2CFailure::try_from(
-                    status_all.status[port.0 as usize],
-                )
-                .unwrap_lite();
+                let failure = if timed_out.is_set(port) {
+                    ringbuf_entry!(Trace::PollTimeout {
+                        port: PortLocation {
+                            controller: fpga_index,
+                            port,
+                        },
+                        status: status_all.status[port.0 as usize],
+                    });
+                    FpgaI2CFailure::I2CTransactionTimeout
+                } else {
+                    FpgaI2CFailure::try_from(status_all.status[port.0 as usize])
+                        .unwrap_lite()
+                };
 
                 // if a failure occurred, mark it and record the failure type
                 if failure != FpgaI2CFailure::NoError {

drv/transceivers-server/src/main.rs

@@ -410,6 +410,19 @@ struct XcvrApi {
 }
 
 impl XcvrApi {
+    /// Determine if the given port is stuck-busy, or if it is in the idle
+    /// state, as expected.
+    fn check_port_idle(&self, port: LogicalPort) -> Result<(), FpgaError> {
+        let result = self.transceivers.check_i2c_idle(port.as_mask());
+        if !result.error().is_empty() {
+            Err(FpgaError::CommsError)
+        } else if !result.failure().is_empty() {
+            Err(FpgaError::BusyTimeout)
+        } else {
+            Ok(())
+        }
+    }
+
     /// Returns the temperature from a CMIS transceiver.
     ///
     /// `port` is a logical port index, i.e. 0-31.
@@ -439,6 +452,8 @@ impl XcvrApi {
         port: LogicalPort,
         reg: u8,
     ) -> Result<Celsius, FpgaError> {
+        // Bail if port is still busy
+        self.check_port_idle(port)?;
         let result = self.transceivers.setup_i2c_read(reg, 2, port.as_mask());
         if !result.error().is_empty() {
             return Err(FpgaError::CommsError);
@@ -471,6 +486,8 @@ impl XcvrApi {
         &mut self,
         port: LogicalPort,
     ) -> Result<ManagementInterface, FpgaError> {
+        // Bail if port is still busy
+        self.check_port_idle(port)?;
         let result = self.transceivers.setup_i2c_read(0, 1, port.as_mask());
         if !result.error().is_empty() {
             return Err(FpgaError::CommsError);
@@ -589,6 +606,9 @@ impl ServerImpl {
             ..
         } = self;
 
+        // Accumulate ports to disable (but don't disable them in the loop), to
+        // avoid issues with the borrow checker.
+        let mut to_disable = LogicalPortMask(0);
         for (i, data) in ports.iter_mut().enumerate() {
             let port_idx = i as u8;
             let port = LogicalPort(port_idx);
@@ -629,6 +649,18 @@ impl ServerImpl {
                             port,
                             err
                         });
+                        // If we are unable to get information due to a
+                        // timeout, then we count it towards disabling this
+                        // port. We repeat the check done below, because it is
+                        // only handled by xcvrs with established models.
+                        if err == FpgaError::BusyTimeout {
+                            data.consecutive_errors =
+                                data.consecutive_errors.saturating_add(1);
+                            if data.consecutive_errors >= MAX_CONSECUTIVE_ERRORS
+                            {
+                                to_disable.set(port);
+                            }
+                        }
                     }
                 }
             } else if !operational && data.model.is_some() {
@@ -657,9 +689,8 @@ impl ServerImpl {
             }
         }
 
-        // Accumulate ports to disable (but don't disable them in the loop), to
-        // avoid issues with the borrow checker.
-        let mut to_disable = LogicalPortMask(0);
+        // Checks made for xcvrs that already have defined models (from
+        // the loop above)
         for (i, data) in ports.iter_mut().enumerate() {
             let port = LogicalPort(i as u8);
             let Some(m) = data.model.as_ref() else {
@@ -699,6 +730,13 @@ impl ServerImpl {
                     e.ringbuf(port);
 
                     match e {
+                        // Check for hubris#2070 timeouts declared by the SP
+                        TempReadError::UnexpectedFpgaErr(
+                            FpgaError::BusyTimeout,
+                        ) => {
+                            data.consecutive_errors =
+                                data.consecutive_errors.saturating_add(1);
+                        }
                         // Failure to read neither increments nor resets the
                         // counter of errors
                         TempReadError::UnknownInterface