diff --git a/CHANGELOG.md b/CHANGELOG.md index a058fc6..fb9bc56 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,8 +7,13 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0. ## [Unreleased] +### Added +* A new `log` feature can be enabled to provide logging and tracing information about the USB +interface. + ### Changed * Invalid LangIDs will default to `EN_US` +* Changed handling of EP0 state to eliminate unexpected issues with device enumeration ## [0.3.1] - 2023-11-15 diff --git a/Cargo.toml b/Cargo.toml index 36bbeb4..80b3733 100644 --- a/Cargo.toml +++ b/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 diff --git a/src/control_pipe.rs b/src/control_pipe.rs index f6e3958..c3d2a56 100644 --- a/src/control_pipe.rs +++ b/src/control_pipe.rs @@ -63,15 +63,18 @@ impl ControlPipe<'_, B> { } pub fn reset(&mut self) { + usb_trace!("Control pipe reset"); self.state = ControlState::Idle; } pub fn handle_setup(&mut self) -> Option { let count = match self.ep_out.read(&mut self.buf[..]) { - Ok(count) => count, + Ok(count) => { + usb_trace!("Read {} bytes on EP0-OUT: {:?}", count, &self.buf[..count]); + count + } Err(UsbError::WouldBlock) => return None, Err(_) => { - self.set_error(); return None; } }; @@ -79,8 +82,7 @@ impl ControlPipe<'_, B> { let req = match Request::parse(&self.buf[0..count]) { Ok(req) => req, Err(_) => { - // Failed to parse SETUP packet - self.set_error(); + // Failed to parse SETUP packet. We are supposed to silently ignore this. return None; } }; @@ -89,6 +91,8 @@ impl ControlPipe<'_, B> { // a stalled state. self.ep_out.unstall(); + usb_debug!("EP0 request received: {:?}", req); + /*sprintln!("SETUP {:?} {:?} {:?} req:{} val:{} idx:{} len:{} {:?}", req.direction, req.request_type, req.recipient, req.request, req.value, req.index, req.length, @@ -102,7 +106,6 @@ impl ControlPipe<'_, B> { if req.length as usize > self.buf.len() { // Data stage won't fit in buffer - self.set_error(); return None; } @@ -141,9 +144,15 @@ impl ControlPipe<'_, B> { } }; + usb_trace!( + "Read {} bytes on EP0-OUT: {:?}", + count, + &self.buf[i..(i + count)] + ); self.i += count; if self.i >= self.len { + usb_debug!("Request OUT complete: {:?}", req); self.state = ControlState::CompleteOut; return Some(req); } @@ -154,11 +163,19 @@ impl ControlPipe<'_, B> { | ControlState::DataInLast | ControlState::DataInZlp | ControlState::StatusOut => { + usb_debug!( + "Control transfer completed. 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 +198,7 @@ impl ControlPipe<'_, B> { return false; } + usb_trace!("wrote EP0: ZLP"); self.state = ControlState::DataInLast; } ControlState::DataInLast => { @@ -197,8 +215,9 @@ impl ControlPipe<'_, B> { // IN-complete status. Just ignore this indication. } _ => { - // Unexpected IN packet - self.set_error(); + // If we get IN-COMPLETE indications in unexpected states, it's generally because + // of control flow in previous phases updating after our packet was successfully + // sent. Ignore these indications if they don't drive any further behavior. } }; @@ -213,9 +232,14 @@ impl 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: {:?}", _err); + return; + } }; + usb_trace!("wrote EP0: {:?}", &buffer[self.i..(self.i + count)]); + self.i += count; if self.i >= self.len { @@ -232,7 +256,10 @@ impl ControlPipe<'_, B> { pub fn accept_out(&mut self) -> Result<()> { match self.state { ControlState::CompleteOut => {} - _ => return Err(UsbError::InvalidState), + _ => { + usb_debug!("Cannot ACK, invalid state: {:?}", self.state); + return Err(UsbError::InvalidState); + } }; let _ = self.ep_in.write(&[]); @@ -243,7 +270,10 @@ impl ControlPipe<'_, B> { pub fn accept_in(&mut self, f: impl FnOnce(&mut [u8]) -> Result) -> Result<()> { let req = match self.state { ControlState::CompleteIn(req) => req, - _ => return Err(UsbError::InvalidState), + _ => { + usb_debug!("EP0-IN cannot ACK, invalid state: {:?}", self.state); + return Err(UsbError::InvalidState); + } }; let len = f(&mut self.buf[..])?; @@ -259,7 +289,10 @@ impl ControlPipe<'_, B> { pub fn accept_in_static(&mut self, data: &'static [u8]) -> Result<()> { let req = match self.state { ControlState::CompleteIn(req) => req, - _ => return Err(UsbError::InvalidState), + _ => { + usb_debug!("EP0-IN cannot ACK, invalid state: {:?}", self.state); + return Err(UsbError::InvalidState); + } }; self.static_in_buf = Some(data); @@ -277,6 +310,7 @@ impl ControlPipe<'_, B> { } pub fn reject(&mut self) -> Result<()> { + usb_debug!("EP0 transfer rejected"); if !self.waiting_for_response() { return Err(UsbError::InvalidState); } @@ -286,6 +320,7 @@ impl ControlPipe<'_, B> { } fn set_error(&mut self) { + usb_debug!("EP0 stalled - error"); self.state = ControlState::Error; self.ep_out.stall(); self.ep_in.stall(); diff --git a/src/device.rs b/src/device.rs index 61aed60..2bd8555 100644 --- a/src/device.rs +++ b/src/device.rs @@ -204,23 +204,12 @@ impl UsbDevice<'_, B> { // Pending events for endpoint 0? if (eps & 1) != 0 { - // 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 - // internal state properly. - if (ep_in_complete & 1) != 0 { - let completed = self.control.handle_in_complete(); - - if !B::QUIRK_SET_ADDRESS_BEFORE_STATUS - && completed - && self.pending_address != 0 - { - self.bus.set_device_address(self.pending_address); - self.pending_address = 0; - - self.device_state = UsbDeviceState::Addressed; - } - } + usb_debug!( + "EP0: setup={}, in_complete={}, out={}", + ep_setup & 1, + ep_in_complete & 1, + ep_out & 1 + ); let req = if (ep_setup & 1) != 0 { self.control.handle_setup() @@ -237,6 +226,26 @@ impl UsbDevice<'_, B> { Some(req) if req.direction == UsbDirection::Out => { self.control_out(classes, req) } + + None if ((ep_in_complete & 1) != 0) => { + // We only handle EP0-IN completion if there's no other request being + // processed. EP0-IN tokens may be issued due to completed STATUS + // phases of the control transfer. If we just got a SETUP packet or + // an OUT token, we can safely ignore the IN-COMPLETE indication and + // continue with the next transfer. + let completed = self.control.handle_in_complete(); + + if !B::QUIRK_SET_ADDRESS_BEFORE_STATUS + && completed + && self.pending_address != 0 + { + self.bus.set_device_address(self.pending_address); + self.pending_address = 0; + + self.device_state = UsbDeviceState::Addressed; + } + } + _ => (), }; @@ -250,18 +259,21 @@ impl UsbDevice<'_, B> { for i in 1..MAX_ENDPOINTS { if (ep_setup & bit) != 0 { for cls in classes.iter_mut() { + usb_trace!("Handling EP{}-SETUP", i); cls.endpoint_setup(EndpointAddress::from_parts( i, UsbDirection::Out, )); } } else if (ep_out & bit) != 0 { + usb_trace!("Handling EP{}-OUT", i); 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{}-IN", i); for cls in classes.iter_mut() { cls.endpoint_in_complete(EndpointAddress::from_parts( i, @@ -289,6 +301,7 @@ impl 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 +327,7 @@ impl 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 +339,14 @@ impl 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 +359,12 @@ impl 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 +374,7 @@ impl 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 +400,7 @@ impl 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 +429,13 @@ impl 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 +446,20 @@ impl 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 +470,13 @@ impl 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 +506,10 @@ impl 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 +522,7 @@ impl UsbDevice<'_, B> { } if self.control.waiting_for_response() { + usb_debug!("Rejecting control transfer due to waiting response"); let _ = self.control.reject(); } } diff --git a/src/lib.rs b/src/lib.rs index 201f6b2..b33c4b8 100644 --- a/src/lib.rs +++ b/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))] diff --git a/src/macros.rs b/src/macros.rs new file mode 100644 index 0000000..e6edd32 --- /dev/null +++ b/src/macros.rs @@ -0,0 +1,24 @@ +#[cfg(all(feature = "log", not(feature = "defmt")))] +macro_rules! usb_log { + (trace, $($arg:expr),*) => { log::trace!($($arg),*) }; + (debug, $($arg:expr),*) => { log::trace!($($arg),*) }; +} + +#[cfg(feature = "defmt")] +macro_rules! usb_log { + (trace, $($arg:expr),*) => { defmt::trace!($($arg),*) }; + (debug, $($arg:expr),*) => { defmt::debug!($($arg),*) }; +} + +#[cfg(not(any(feature = "log", feature = "defmt")))] +macro_rules! usb_log { + ($level:ident, $($arg:expr),*) => {{ $( let _ = $arg; )* }} +} + +macro_rules! usb_trace { + ($($arg:expr),*) => (usb_log!(trace, $($arg),*)); +} + +macro_rules! usb_debug { + ($($arg:expr),*) => (usb_log!(debug, $($arg),*)); +}