pandad: add more context to spi logs (#32639)

* pandad: add more context to spi logs

* cleanup

---------

Co-authored-by: Comma Device <device@comma.ai>

selfdrive/pandad/panda_comms.h

@@ -56,6 +56,13 @@ private:
 };
 
 #ifndef __APPLE__
+struct __attribute__((packed)) spi_header {
+  uint8_t sync;
+  uint8_t endpoint;
+  uint16_t tx_len;
+  uint16_t max_rx_len;
+};
+
 class PandaSpiHandle : public PandaCommsHandle {
 public:
   PandaSpiHandle(std::string serial);
@@ -79,5 +86,8 @@ private:
   int spi_transfer(uint8_t endpoint, uint8_t *tx_data, uint16_t tx_len, uint8_t *rx_data, uint16_t max_rx_len, unsigned int timeout);
   int spi_transfer_retry(uint8_t endpoint, uint8_t *tx_data, uint16_t tx_len, uint8_t *rx_data, uint16_t max_rx_len, unsigned int timeout);
   int lltransfer(spi_ioc_transfer &t);
+
+  spi_header header;
+  uint32_t xfer_count = 0;
 };
 #endif

selfdrive/pandad/spi.cc

@@ -28,13 +28,6 @@ enum SpiError {
   ACK_TIMEOUT = -3,
 };
 
-struct __attribute__((packed)) spi_header {
-  uint8_t sync;
-  uint8_t endpoint;
-  uint16_t tx_len;
-  uint16_t max_rx_len;
-};
-
 const unsigned int SPI_ACK_TIMEOUT = 500; // milliseconds
 const std::string SPI_DEVICE = "/dev/spidev0.0";
 
@@ -55,6 +48,11 @@ private:
   std::recursive_mutex &m;
 };
 
+#define SPILOG(fn, fmt, ...) do {  \
+      fn(fmt, ## __VA_ARGS__);     \
+      fn("  %d / 0x%x / %d / %d", \
+         xfer_count, header.endpoint, header.tx_len, header.max_rx_len); \
+      } while(0)
 
 PandaSpiHandle::PandaSpiHandle(std::string serial) : PandaCommsHandle(serial) {
   int ret;
@@ -178,7 +176,7 @@ int PandaSpiHandle::bulk_transfer(uint8_t endpoint, uint8_t *tx_data, uint16_t t
     }
 
     if (d < 0) {
-      LOGE("SPI: bulk transfer failed with %d", d);
+      SPILOG(LOGE, "SPI: bulk transfer failed with %d", d);
       comms_healthy = false;
       return d;
     }
@@ -247,7 +245,7 @@ int PandaSpiHandle::spi_transfer_retry(uint8_t endpoint, uint8_t *tx_data, uint1
   } while (ret < 0 && connected && !timed_out);
 
   if (ret < 0) {
-    LOGE("transfer failed, after %d tries, %.2fms", timeout_count, millis_since_boot() - start_time);
+    SPILOG(LOGE, "transfer failed, after %d tries, %.2fms", timeout_count, millis_since_boot() - start_time);
   }
 
   return ret;
@@ -270,20 +268,20 @@ int PandaSpiHandle::wait_for_ack(uint8_t ack, uint8_t tx, unsigned int timeout,
   while (true) {
     int ret = lltransfer(transfer);
     if (ret < 0) {
-      LOGE("SPI: failed to send ACK request");
+      SPILOG(LOGE, "SPI: failed to send ACK request");
       return ret;
     }
 
     if (rx_buf[0] == ack) {
       break;
     } else if (rx_buf[0] == SPI_NACK) {
-      LOGD("SPI: got NACK");
+      SPILOG(LOGD, "SPI: got NACK");
       return SpiError::NACK;
     }
 
     // handle timeout
     if (millis_since_boot() - start_millis > timeout) {
-      LOGD("SPI: timed out waiting for ACK");
+      SPILOG(LOGW, "SPI: timed out waiting for ACK");
       return SpiError::ACK_TIMEOUT;
     }
   }
@@ -334,7 +332,8 @@ int PandaSpiHandle::spi_transfer(uint8_t endpoint, uint8_t *tx_data, uint16_t tx
   assert(tx_len < SPI_BUF_SIZE);
   assert(max_rx_len < SPI_BUF_SIZE);
 
-  spi_header header = {
+  xfer_count++;
+  header = {
     .sync = SPI_SYNC,
     .endpoint = endpoint,
     .tx_len = tx_len,
@@ -352,7 +351,7 @@ int PandaSpiHandle::spi_transfer(uint8_t endpoint, uint8_t *tx_data, uint16_t tx
   transfer.len = sizeof(header) + 1;
   ret = lltransfer(transfer);
   if (ret < 0) {
-    LOGE("SPI: failed to send header");
+    SPILOG(LOGE, "SPI: failed to send header");
     return ret;
   }
 
@@ -370,7 +369,7 @@ int PandaSpiHandle::spi_transfer(uint8_t endpoint, uint8_t *tx_data, uint16_t tx
   transfer.len = tx_len + 1;
   ret = lltransfer(transfer);
   if (ret < 0) {
-    LOGE("SPI: failed to send data");
+    SPILOG(LOGE, "SPI: failed to send data");
     return ret;
   }
 
@@ -383,7 +382,7 @@ int PandaSpiHandle::spi_transfer(uint8_t endpoint, uint8_t *tx_data, uint16_t tx
   // Read data
   rx_data_len = *(uint16_t *)(rx_buf+1);
   if (rx_data_len >= SPI_BUF_SIZE) {
-    LOGE("SPI: RX data len larger than buf size %d", rx_data_len);
+    SPILOG(LOGE, "SPI: RX data len larger than buf size %d", rx_data_len);
     return -1;
   }
 
@@ -391,11 +390,11 @@ int PandaSpiHandle::spi_transfer(uint8_t endpoint, uint8_t *tx_data, uint16_t tx
   transfer.rx_buf = (uint64_t)(rx_buf + 2 + 1);
   ret = lltransfer(transfer);
   if (ret < 0) {
-    LOGE("SPI: failed to read rx data");
+    SPILOG(LOGE, "SPI: failed to read rx data");
     return ret;
   }
   if (!check_checksum(rx_buf, rx_data_len + 4)) {
-    LOGE("SPI: bad checksum");
+    SPILOG(LOGE, "SPI: bad checksum");
     return -1;
   }