Adding USB trace support

Author: ryan-summers

Cargo.toml

@@ -14,6 +14,7 @@ defmt = { version = "0.3", optional = true }
 portable-atomic = { version = "1.2.0", default-features = false }
 num_enum = { version = "0.7.1", default-features = false }
 heapless = "0.8"
+log = { version = "0.4", default-features = false, optional = true}
 
 [dev-dependencies]
 rusb = "0.9.1"
@@ -23,6 +24,9 @@ rand = "0.8.5"
 # Use a 256 byte buffer for control transfers instead of 128.
 control-buffer-256 = []
 
+# Enable logging and tracing via the `log` crate
+log = ["dep:log"]
+
 # Use larger endpoint buffers for highspeed operation (default fullspeed)
 #
 # Note: usb-device doesn't truly support high speed enumeration yet, so setting this will make

src/control_pipe.rs

@@ -63,6 +63,7 @@ impl<B: UsbBus> ControlPipe<'_, B> {
     }
 
     pub fn reset(&mut self) {
+        usb_trace!("Control pipe reset");
         self.state = ControlState::Idle;
     }
 
@@ -87,6 +88,7 @@ impl<B: UsbBus> ControlPipe<'_, B> {
 
         // Now that we have properly parsed the setup packet, ensure the end-point is no longer in
         // a stalled state.
+        usb_trace!("EP0 request received: {req:?}");
         self.ep_out.unstall();
 
         /*sprintln!("SETUP {:?} {:?} {:?} req:{} val:{} idx:{} len:{} {:?}",
@@ -142,8 +144,10 @@ impl<B: UsbBus> ControlPipe<'_, B> {
                 };
 
                 self.i += count;
+                usb_trace!("Read {count} bytes on EP0-OUT");
 
                 if self.i >= self.len {
+                    usb_debug!("Request OUT complete: {req}");
                     self.state = ControlState::CompleteOut;
                     return Some(req);
                 }
@@ -154,11 +158,19 @@ impl<B: UsbBus> ControlPipe<'_, B> {
             | ControlState::DataInLast
             | ControlState::DataInZlp
             | ControlState::StatusOut => {
+                usb_debug!(
+                    "Terminating DATA stage early. Current state: {:?}",
+                    self.state
+                );
                 let _ = self.ep_out.read(&mut []);
                 self.state = ControlState::Idle;
             }
             _ => {
                 // Discard the packet
+                usb_debug!(
+                    "Discarding EP0 data due to unexpected state. Current state: {:?}",
+                    self.state
+                );
                 let _ = self.ep_out.read(&mut []);
 
                 // Unexpected OUT packet
@@ -181,6 +193,7 @@ impl<B: UsbBus> ControlPipe<'_, B> {
                     return false;
                 }
 
+                usb_trace!("wrote EP0-IN: ZLP");
                 self.state = ControlState::DataInLast;
             }
             ControlState::DataInLast => {
@@ -192,12 +205,14 @@ impl<B: UsbBus> ControlPipe<'_, B> {
                 return true;
             }
             ControlState::Idle => {
+                usb_debug!("Ignoring EP0-IN while in IDLE");
                 // If we received a message on EP0 while sending the last portion of an IN
                 // transfer, we may have already transitioned to IDLE without getting the last
                 // IN-complete status. Just ignore this indication.
             }
             _ => {
                 // Unexpected IN packet
+                usb_debug!("Unexpected EP0-IN. Current state: {:?}", self.state);
                 self.set_error();
             }
         };
@@ -213,9 +228,14 @@ impl<B: UsbBus> ControlPipe<'_, B> {
             Ok(c) => c,
             // There isn't much we can do if the write fails, except to wait for another poll or for
             // the host to resend the request.
-            Err(_) => return,
+            Err(_err) => {
+                usb_debug!("Failed to write EP0-IN: {_err:?}");
+                return;
+            }
         };
 
+        usb_trace!("wrote EP0-IN: {:?}", &buffer[self.i..(self.i + count)]);
+
         self.i += count;
 
         if self.i >= self.len {
@@ -286,6 +306,7 @@ impl<B: UsbBus> ControlPipe<'_, B> {
     }
 
     fn set_error(&mut self) {
+        usb_debug!("EP0 stalled - error");
         self.state = ControlState::Error;
         self.ep_out.stall();
         self.ep_in.stall();

src/device.rs

@@ -204,6 +204,12 @@ impl<B: UsbBus> UsbDevice<'_, B> {
 
                 // Pending events for endpoint 0?
                 if (eps & 1) != 0 {
+                    usb_debug!(
+                        "EP0: setup={}, in={}, out={}",
+                        ep_setup & 1,
+                        ep_in_complete & 1,
+                        ep_out & 1
+                    );
                     // Handle EP0-IN conditions first. When both EP0-IN and EP0-OUT have completed,
                     // it is possible that EP0-OUT is a zero-sized out packet to complete the STATUS
                     // phase of the control transfer. We have to process EP0-IN first to update our
@@ -230,6 +236,10 @@ impl<B: UsbBus> UsbDevice<'_, B> {
                         None
                     };
 
+                    if let Some(_req) = req {
+                        usb_trace!("Handling EP0 request: {_req}");
+                    }
+
                     match req {
                         Some(req) if req.direction == UsbDirection::In => {
                             self.control_in(classes, req)
@@ -250,18 +260,21 @@ impl<B: UsbBus> UsbDevice<'_, B> {
                     for i in 1..MAX_ENDPOINTS {
                         if (ep_setup & bit) != 0 {
                             for cls in classes.iter_mut() {
+                                usb_trace!("Handling EP{i}-SETUP");
                                 cls.endpoint_setup(EndpointAddress::from_parts(
                                     i,
                                     UsbDirection::Out,
                                 ));
                             }
                         } else if (ep_out & bit) != 0 {
+                            usb_trace!("Handling EP{i}-OUT");
                             for cls in classes.iter_mut() {
                                 cls.endpoint_out(EndpointAddress::from_parts(i, UsbDirection::Out));
                             }
                         }
 
                         if (ep_in_complete & bit) != 0 {
+                            usb_trace!("Handling EP{i}-IN");
                             for cls in classes.iter_mut() {
                                 cls.endpoint_in_complete(EndpointAddress::from_parts(
                                     i,
@@ -289,6 +302,7 @@ impl<B: UsbBus> UsbDevice<'_, B> {
             }
             PollResult::Resume => {}
             PollResult::Suspend => {
+                usb_debug!("Suspending bus");
                 self.bus.suspend();
                 self.suspended_device_state = Some(self.device_state);
                 self.device_state = UsbDeviceState::Suspend;
@@ -314,6 +328,7 @@ impl<B: UsbBus> UsbDevice<'_, B> {
 
             match (req.recipient, req.request) {
                 (Recipient::Device, Request::GET_STATUS) => {
+                    usb_trace!("Processing Device::GetStatus");
                     let status: u16 = if self.self_powered { 0x0001 } else { 0x0000 }
                         | if self.remote_wakeup_enabled {
                             0x0002
@@ -325,12 +340,14 @@ impl<B: UsbBus> UsbDevice<'_, B> {
                 }
 
                 (Recipient::Interface, Request::GET_STATUS) => {
+                    usb_trace!("Processing Interface::GetStatus");
                     let status: u16 = 0x0000;
 
                     let _ = xfer.accept_with(&status.to_le_bytes());
                 }
 
                 (Recipient::Endpoint, Request::GET_STATUS) => {
+                    usb_trace!("Processing EP::GetStatus");
                     let ep_addr = ((req.index as u8) & 0x8f).into();
 
                     let status: u16 = if self.bus.is_stalled(ep_addr) {
@@ -343,10 +360,12 @@ impl<B: UsbBus> UsbDevice<'_, B> {
                 }
 
                 (Recipient::Device, Request::GET_DESCRIPTOR) => {
+                    usb_trace!("Processing Device::GetDescriptor");
                     UsbDevice::get_descriptor(&self.config, classes, xfer)
                 }
 
                 (Recipient::Device, Request::GET_CONFIGURATION) => {
+                    usb_trace!("Processing Device::GetConfiguration");
                     let config = match self.device_state {
                         UsbDeviceState::Configured => CONFIGURATION_VALUE,
                         _ => CONFIGURATION_NONE,
@@ -356,6 +375,7 @@ impl<B: UsbBus> UsbDevice<'_, B> {
                 }
 
                 (Recipient::Interface, Request::GET_INTERFACE) => {
+                    usb_trace!("Processing Interface::GetInterface");
                     // Reject interface numbers bigger than 255
                     if req.index > core::u8::MAX.into() {
                         let _ = xfer.reject();
@@ -381,6 +401,7 @@ impl<B: UsbBus> UsbDevice<'_, B> {
         }
 
         if self.control.waiting_for_response() {
+            usb_debug!("Rejecting control transfer because we were waiting for a response");
             let _ = self.control.reject();
         }
     }
@@ -409,11 +430,13 @@ impl<B: UsbBus> UsbDevice<'_, B> {
                     Request::CLEAR_FEATURE,
                     Request::FEATURE_DEVICE_REMOTE_WAKEUP,
                 ) => {
+                    usb_debug!("Remote wakeup disabled");
                     self.remote_wakeup_enabled = false;
                     let _ = xfer.accept();
                 }
 
                 (Recipient::Endpoint, Request::CLEAR_FEATURE, Request::FEATURE_ENDPOINT_HALT) => {
+                    usb_debug!("EP{} halt removed", req.index & 0x8f);
                     self.bus
                         .set_stalled(((req.index as u8) & 0x8f).into(), false);
                     let _ = xfer.accept();
@@ -424,17 +447,20 @@ impl<B: UsbBus> UsbDevice<'_, B> {
                     Request::SET_FEATURE,
                     Request::FEATURE_DEVICE_REMOTE_WAKEUP,
                 ) => {
+                    usb_debug!("Remote wakeup enabled");
                     self.remote_wakeup_enabled = true;
                     let _ = xfer.accept();
                 }
 
                 (Recipient::Endpoint, Request::SET_FEATURE, Request::FEATURE_ENDPOINT_HALT) => {
+                    usb_debug!("EP{} halted", req.index & 0x8f);
                     self.bus
                         .set_stalled(((req.index as u8) & 0x8f).into(), true);
                     let _ = xfer.accept();
                 }
 
                 (Recipient::Device, Request::SET_ADDRESS, 1..=127) => {
+                    usb_debug!("Setting device address to {}", req.value);
                     if B::QUIRK_SET_ADDRESS_BEFORE_STATUS {
                         self.bus.set_device_address(req.value as u8);
                         self.device_state = UsbDeviceState::Addressed;
@@ -445,11 +471,13 @@ impl<B: UsbBus> UsbDevice<'_, B> {
                 }
 
                 (Recipient::Device, Request::SET_CONFIGURATION, CONFIGURATION_VALUE_U16) => {
+                    usb_debug!("Device configured");
                     self.device_state = UsbDeviceState::Configured;
                     let _ = xfer.accept();
                 }
 
                 (Recipient::Device, Request::SET_CONFIGURATION, CONFIGURATION_NONE_U16) => {
+                    usb_debug!("Device deconfigured");
                     match self.device_state {
                         UsbDeviceState::Default => {
                             let _ = xfer.accept();
@@ -479,8 +507,10 @@ impl<B: UsbBus> UsbDevice<'_, B> {
 
                     // Default behaviour, if no class implementation accepted the alternate setting.
                     if alt_setting == DEFAULT_ALTERNATE_SETTING_U16 {
+                        usb_debug!("Accepting unused alternate settings");
                         let _ = xfer.accept();
                     } else {
+                        usb_debug!("Rejecting unused alternate settings");
                         let _ = xfer.reject();
                     }
                 }
@@ -493,6 +523,7 @@ impl<B: UsbBus> UsbDevice<'_, B> {
         }
 
         if self.control.waiting_for_response() {
+            usb_debug!("Rejecting control transfer due to waiting response");
             let _ = self.control.reject();
         }
     }

src/lib.rs

@@ -36,6 +36,9 @@
 #![no_std]
 #![warn(missing_docs)]
 
+#[macro_use]
+mod macros;
+
 /// A USB stack error.
 #[derive(Copy, Clone, Eq, PartialEq, Debug)]
 #[cfg_attr(feature = "defmt", derive(defmt::Format))]