diff --git a/CHANGELOG.md b/CHANGELOG.md index f968573..5041be5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,23 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.3.0] - 2024-04-22 + +### Added +- `initlog` feature +- `UsbDeviceCtx::initialize` which initializes logging by +default if `initlog` feature is enabled +- `Device::poll` which allows calling `poll` from the test case + +### Fixed +- Termination condition in `Device::ep_raw`. Data phase stops +when `UsbClass` does not consume data from the endpoint buffer +- Incorrect internal `UsbBusImpl::ep_is_empty` condition check + +### Changed +- Significanlty improved logging +- `UsbDeviceCtx::post_poll` renamed and changed to `UsbDeviceCtx::hook` + ## [0.2.1] - 2024-04-13 ### Fixed @@ -27,7 +44,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 First version. -[Unreleased]: https://github.com/vitalyvb/usbd-class-tester/compare/v0.2.1...HEAD +[Unreleased]: https://github.com/vitalyvb/usbd-class-tester/compare/v0.3.0...HEAD +[0.3.0]: https://github.com/vitalyvb/usbd-class-tester/compare/v0.2.1...v0.3.0 [0.2.1]: https://github.com/vitalyvb/usbd-class-tester/compare/v0.2.0...v0.2.1 [0.2.0]: https://github.com/vitalyvb/usbd-class-tester/compare/v0.1.0...v0.2.0 [0.1.0]: https://github.com/vitalyvb/usbd-class-tester/releases/tag/v0.1.0 diff --git a/Cargo.toml b/Cargo.toml index 5750491..d3b9117 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "usbd-class-tester" -version = "0.2.1" +version = "0.3.0" edition = "2021" description = "Library for testing usb-device device classes." @@ -13,5 +13,16 @@ exclude = [ ".github", ] +[features] +default = ["initlog"] +initlog = ["dep:env_logger"] + [dependencies.usb-device] version = "0.3.2" + +[dependencies.log] +version = "0.4" + +[dependencies.env_logger] +version = "0.11" +optional = true diff --git a/README.md b/README.md index b2ce704..2159938 100644 --- a/README.md +++ b/README.md @@ -96,3 +96,5 @@ fn test_interface_get_status() { } ``` +USB debug logging can be enabled, for example, by running tests with: +`$ RUST_LOG=trace cargo test -- --nocapture` diff --git a/src/bus.rs b/src/bus.rs index 9a4bbeb..0250e2e 100644 --- a/src/bus.rs +++ b/src/bus.rs @@ -4,6 +4,7 @@ //! //! This implementation is not complete and probably buggy. //! +use log::{debug, info, trace}; use std::{cell::RefCell, cmp::min, rc::Rc}; use usb_device::bus::PollResult; @@ -51,6 +52,13 @@ impl EndpointImpl { self.setup = setup; self.read_ready = true; } + + debug!( + "EP : set data to read: {} bytes, setup: {}", + self.read_len, setup + ); + trace!("EP : {} {:02x?}", if setup { "<==" } else { "<--" }, data); + self.read_len } @@ -62,16 +70,23 @@ impl EndpointImpl { self.read_ready = true; self.read_len += len; } + + debug!("EP : append data to read: {}", len); + trace!("EP : <-+ {:02x?}", &data[..len]); + len } /// Returns data that was written by usb-device to the Endpoint fn get_write(&mut self, data: &mut [u8]) -> usize { let res = self.write_len; - dbg!("g", self.write_len); self.write_len = 0; data[..res].clone_from_slice(&self.write[..res]); self.write_done = true; + + debug!("EP : retrieve written data: {}", res); + trace!("EP : --> {:02x?}", &data[..res]); + res } } @@ -146,8 +161,8 @@ impl UsbBusImpl { pub(crate) fn ep_is_empty(&self, ep_addr: EndpointAddress) -> bool { let ep = self.epidx(ep_addr).borrow(); match ep_addr.direction() { - UsbDirection::In => ep.write_done, - UsbDirection::Out => ep.read_ready, + UsbDirection::In => ep.write_len == 0, + UsbDirection::Out => ep.read_len == 0, } } @@ -247,9 +262,12 @@ impl usb_device::bus::UsbBus for EmulatedUsbBus { }) } - fn enable(&mut self) {} + fn enable(&mut self) { + info!("Bus: enable"); + } fn force_reset(&self) -> UsbDeviceResult<()> { + info!("Bus: force reset not supported"); Err(UsbError::Unsupported) } @@ -280,7 +298,11 @@ impl usb_device::bus::UsbBus for EmulatedUsbBus { ep_in.write_done = false; } - // dbg!("WER", mask_in_complete, mask_ep_out, mask_ep_setup); + debug!( + "Bus: poll results: in: {:02x} out {:02x} setup {:02x}", + mask_in_complete, mask_ep_out, mask_ep_setup + ); + if mask_in_complete != 0 || mask_ep_out != 0 || mask_ep_setup != 0 { PollResult::Data { ep_in_complete: mask_in_complete, @@ -297,7 +319,13 @@ impl usb_device::bus::UsbBus for EmulatedUsbBus { let mut ep = io.epidx(ep_addr).borrow_mut(); let len = min(buf.len(), min(ep.read_len, ep.max_size)); - dbg!("read len from", buf.len(), len, ep_addr); + debug!( + "Bus: reading from EP {} {:#?} {} bytes into {} byte buffer", + ep_addr.index(), + ep_addr.direction(), + len, + buf.len() + ); if len == 0 { return Err(UsbError::WouldBlock); @@ -318,18 +346,22 @@ impl usb_device::bus::UsbBus for EmulatedUsbBus { } fn reset(&self) { + info!("Bus: reset"); todo!() } fn resume(&self) { + info!("Bus: resume"); todo!() } fn suspend(&self) { + info!("Bus: suspend"); todo!() } fn set_device_address(&self, addr: u8) { + debug!("Bus: set device address: {}", addr); self.usb_address.replace(addr); } @@ -351,9 +383,12 @@ impl usb_device::bus::UsbBus for EmulatedUsbBus { let offset = ep.write_len; let mut len = 0; - dbg!("write", buf.len()); - if buf.len() > ep.max_size { + debug!( + "Bus: EP {} {:#?} buffer overflow", + ep_addr.index(), + ep_addr.direction() + ); return Err(UsbError::BufferOverflow); } @@ -365,7 +400,13 @@ impl usb_device::bus::UsbBus for EmulatedUsbBus { len += 1; } - dbg!("wrote", len); + debug!( + "Bus: wrote to EP {} {:#?} {} bytes", + ep_addr.index(), + ep_addr.direction(), + len + ); + ep.write_len += len; ep.write_done = false; Ok(len) diff --git a/src/lib.rs b/src/lib.rs index 3e52d85..7541aa3 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -95,7 +95,11 @@ //! } //! ``` //! +//! USB debug logging can be enabled, for example, by running tests with: +//! `$ RUST_LOG=trace cargo test -- --nocapture` +//! +use log::{debug, info, warn}; use std::fmt::Debug; use std::marker::PhantomData; use std::{cell::RefCell, rc::Rc}; @@ -117,7 +121,7 @@ use usbdata::*; pub mod prelude { pub use crate::bus::EmulatedUsbBus; pub use crate::usbdata::{CtrRequestType, SetupPacket}; - pub use crate::{AnyResult, AnyUsbError, Device, UsbDeviceCtx}; + pub use crate::{AnyResult, AnyUsbError, Device, HookAction, HookWhen, UsbDeviceCtx}; } const DEFAULT_EP0_SIZE: u8 = 8; @@ -187,6 +191,39 @@ pub enum AnyUsbError { UserDefinedString(String), } +/// Specifies why `Device::hook()` was called. +#[derive(Debug, PartialEq, Clone, Copy)] +pub enum HookWhen { + /// After `poll()` from `with_usb()` after initialization + /// and before device setup. + InitIdle, + /// After `poll()` once Setup packet is sent during the transaction. + AfterSetup(EndpointAddress), + /// After `poll()` once some portion of data is sent to + /// the device. + DataOut(EndpointAddress), + /// After `poll()` once some portion of data is received from + /// the device. + DataIn(EndpointAddress), + /// After a manual `poll()` from `with_usb()`'s `case`. + ManualPoll, +} + +/// Specifies what `Device::hook()`'s caller should +/// do. +#[derive(Debug, PartialEq, Eq, Default, Clone, Copy)] +pub enum HookAction { + /// Proceed normally + #[default] + Default, + /// Force polling again. + ForcePoll, + /// Do not call `poll` again even if would + /// call it normally and act as if `poll` + /// returned `false`. + Stop, +} + /// Holds results for endpoint read/write operations #[derive(Debug, Default)] pub struct RWRes { @@ -260,7 +297,28 @@ pub trait UsbDeviceCtx: Sized { /// Optional. Called after each `usb-device` `poll()`. /// /// Default implementation does nothing. - fn post_poll(&mut self, _cls: &mut impl UsbClass) {} + fn hook(&mut self, cls: &mut Self::C<'_>, when: HookWhen) -> HookAction { + let _ = cls; + let _ = when; + HookAction::Default + } + + /// Optional. Called by `with_usb` every time. + /// + /// Default implementation initializes `env_logger` logging suitable + /// for tests with `debug` level if `initlog` feature is enabled. + /// + /// `trace` logging level can be enabled via environment variable: + /// `RUST_LOG=trace cargo test -- --nocapture`. + fn initialize(&mut self) { + #[cfg(feature = "initlog")] + let _ = + env_logger::Builder::from_env(env_logger::Env::default().default_filter_or("debug")) + .is_test(true) + .format_target(false) + .format_timestamp(None) + .try_init(); + } /// Optional. If returns `true`, `Device::setup()` is not /// called to initialize and enumerate device in @@ -355,6 +413,10 @@ pub trait UsbDeviceCtx: Sized { mut self, case: for<'a> fn(cls: Self::C<'a>, dev: Device<'a, Self::C<'a>, Self>), ) -> AnyResult<()> { + self.initialize(); + + warn!("#### with_usb start"); + let stio: UsbBusImpl = UsbBusImpl::new(); let io = Rc::new(RefCell::new(stio)); let bus = EmulatedUsbBus::new(&io); @@ -363,20 +425,21 @@ pub trait UsbDeviceCtx: Sized { let mut cls = self.create_class(&alloc)?; - let mut usb_dev = self.build_usb_device(&alloc)?; + let usb_dev = self.build_usb_device(&alloc)?; let skip_setup = self.skip_setup(); - usb_dev.poll(&mut [&mut cls]); - self.post_poll(&mut cls); - let mut dev = Device::new(io.as_ref(), self, usb_dev); + dev.do_poll(&mut cls, HookWhen::InitIdle); + if !skip_setup { + warn!("#### with_usb device setup"); dev.setup(&mut cls)?; } // run test + warn!("#### with_usb case"); case(cls, dev); Ok(()) @@ -415,6 +478,31 @@ where &mut self.dev } + fn do_poll(&mut self, d: &mut C, when: HookWhen) -> bool { + let mut res; + loop { + res = self.dev.poll(&mut [d]); + match self.ctx.hook(d, when) { + HookAction::Default => return res, + HookAction::ForcePoll => continue, + HookAction::Stop => return false, + } + } + } + + /// Call `usb-device` poll(). + /// + /// Most `Device` operations call poll() automatically + /// and this is usually enough for smaller transfers. + /// + /// Must be called, for example, to gradually process + /// emulated endpoint's buffer if `UsbClass`` blocks and + /// is unable to process data until some action is + /// pefromed on it. + pub fn poll(&mut self, d: &mut C) -> bool { + self.do_poll(d, HookWhen::ManualPoll) + } + /// Perform EP0 Control transfer. `setup` is `SetupPacket`. /// If transfer is Host-to-device and /// `data` is `Some`, then it's sent after the Setup packet @@ -489,10 +577,11 @@ where let out0 = EndpointAddress::from_parts(ep_index, UsbDirection::Out); let in0 = EndpointAddress::from_parts(ep_index, UsbDirection::In); + info!("#### EP {} transaction", ep_index); + if let Some(setup_bytes) = setup_bytes { self.usb.borrow().set_read(out0, setup_bytes, true); - self.dev.poll(&mut [d]); - self.ctx.post_poll(d); + self.do_poll(d, HookWhen::AfterSetup(out0)); if self.usb.borrow().stalled(ep_index) { return Err(AnyUsbError::EP0Stalled); } @@ -504,14 +593,23 @@ where if let Some(val) = data { sent = Some(self.usb.borrow().append_read(out0, val)); for i in 1..129 { - let res = self.dev.poll(&mut [d]); - self.ctx.post_poll(d); + let before_bytes = self.usb.borrow().ep_data_len(out0); + let res = self.do_poll(d, HookWhen::DataIn(out0)); + let after_bytes = self.usb.borrow().ep_data_len(out0); + if !res { - // class has no data to consume + debug!("#### EP {} class has no data to consume", ep_index); break; } if self.usb.borrow().ep_is_empty(out0) { - // consumed all data + debug!("#### EP {} consumed all data", ep_index); + break; + } + if before_bytes == after_bytes { + debug!( + "#### EP {} poll didn't consume any data, have {} bytes", + ep_index, after_bytes + ); break; } if i >= 128 { @@ -528,8 +626,7 @@ where loop { let one = self.usb.borrow().get_write(in0, &mut out[len..]); - self.dev.poll(&mut [d]); - self.ctx.post_poll(d); + self.do_poll(d, HookWhen::DataOut(in0)); if self.usb.borrow().stalled(ep_index) { return Err(AnyUsbError::EPStalled); }