From 87015d0256e5c3888681da6d469e515b58efbb5f Mon Sep 17 00:00:00 2001 From: Brian Cully Date: Wed, 24 Jul 2019 17:35:24 -0400 Subject: Use log crate instead of hand-rolled solution. * Remove my logging macros except *_now variants, since those are still handy. * Move log flush into RTC handler. This probably belongs in a separate timer at some point. * Change all old log messages to log crate's macros, except the Panic and HardFault calls. --- app/Cargo.lock | 16 ++++++ app/src/log.rs | 95 ----------------------------------- app/src/logger.rs | 139 ++++++++++++++++++++++++++++++++++++++++++++++++++++ app/src/macros.rs | 20 +------- app/src/main.rs | 52 ++++++++++++++------ app/src/rtc.rs | 3 ++ app/src/usb.rs | 72 +++++++++++++-------------- app/src/usb/pipe.rs | 46 +++++++---------- 8 files changed, 248 insertions(+), 195 deletions(-) delete mode 100644 app/src/log.rs create mode 100644 app/src/logger.rs (limited to 'app') diff --git a/app/Cargo.lock b/app/Cargo.lock index ca61229..6cabc74 100644 --- a/app/Cargo.lock +++ b/app/Cargo.lock @@ -68,6 +68,11 @@ name = "bitfield" version = "0.13.2" source = "registry+https://github.com/rust-lang/crates.io-index" +[[package]] +name = "cfg-if" +version = "0.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" + [[package]] name = "clint" version = "0.2.0" @@ -133,6 +138,14 @@ dependencies = [ "typenum 1.10.0 (registry+https://github.com/rust-lang/crates.io-index)", ] +[[package]] +name = "log" +version = "0.4.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +dependencies = [ + "cfg-if 0.1.9 (registry+https://github.com/rust-lang/crates.io-index)", +] + [[package]] name = "nb" version = "0.1.2" @@ -242,6 +255,7 @@ dependencies = [ "cortex-m 0.6.0 (registry+https://github.com/rust-lang/crates.io-index)", "cortex-m-rt 0.6.8 (registry+https://github.com/rust-lang/crates.io-index)", "embedded-hal 0.2.3 (registry+https://github.com/rust-lang/crates.io-index)", + "log 0.4.7 (registry+https://github.com/rust-lang/crates.io-index)", "nb 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)", "panic-halt 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)", "rb 0.1.0", @@ -341,12 +355,14 @@ dependencies = [ "checksum as-slice 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "293dac66b274fab06f95e7efb05ec439a6b70136081ea522d270bc351ae5bb27" "checksum bare-metal 0.2.4 (registry+https://github.com/rust-lang/crates.io-index)" = "a3caf393d93b2d453e80638d0674597020cef3382ada454faacd43d1a55a735a" "checksum bitfield 0.13.2 (registry+https://github.com/rust-lang/crates.io-index)" = "46afbd2983a5d5a7bd740ccb198caf5b82f45c40c09c0eed36052d91cb92e719" +"checksum cfg-if 0.1.9 (registry+https://github.com/rust-lang/crates.io-index)" = "b486ce3ccf7ffd79fdeb678eac06a9e6c09fc88d33836340becb8fffe87c5e33" "checksum cortex-m 0.5.10 (registry+https://github.com/rust-lang/crates.io-index)" = "3c0b159a1e8306949579de3698c841dba58058197b65c60807194e4fa1e7a554" "checksum cortex-m 0.6.0 (registry+https://github.com/rust-lang/crates.io-index)" = "f3c18719fdc57db65668bfc977db9a0fa1a41d718c5d9cd4f652c9d4b0e0956a" "checksum cortex-m-rt 0.6.8 (registry+https://github.com/rust-lang/crates.io-index)" = "7e1ccc9052352415ec4e3f762f4541098d012016f9354a1a5b2dede39b67f426" "checksum cortex-m-rt-macros 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)" = "d7ae692573e0acccb1579fef1abf5a5bf1d2f3f0149a22b16870ec9309aee25f" "checksum embedded-hal 0.2.3 (registry+https://github.com/rust-lang/crates.io-index)" = "ee4908a155094da7723c2d60d617b820061e3b4efcc3d9e293d206a5a76c170b" "checksum generic-array 0.12.3 (registry+https://github.com/rust-lang/crates.io-index)" = "c68f0274ae0e023facc3c97b2e00f076be70e254bc851d972503b328db79b2ec" +"checksum log 0.4.7 (registry+https://github.com/rust-lang/crates.io-index)" = "c275b6ad54070ac2d665eef9197db647b32239c9d244bfb6f041a766d00da5b3" "checksum nb 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)" = "b1411551beb3c11dedfb0a90a0fa256b47d28b9ec2cdff34c25a2fa59e45dbdc" "checksum panic-halt 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)" = "de96540e0ebde571dc55c73d60ef407c653844e6f9a1e2fdbd40c07b9252d812" "checksum paste 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)" = "1f4a4a1c555c6505821f9d58b8779d0f630a6b7e4e1be24ba718610acf01fa79" diff --git a/app/src/log.rs b/app/src/log.rs deleted file mode 100644 index 6cfba8f..0000000 --- a/app/src/log.rs +++ /dev/null @@ -1,95 +0,0 @@ -use rb::{Reader, RingBuffer, Writer}; - -use core::fmt::{self, Write}; -use embedded_hal::{digital::v2::OutputPin, serial}; -use trinket_m0::{ - gpio::{Pa6, Pa7, PfD}, - sercom::{Sercom0Pad2, Sercom0Pad3, UART0}, -}; - -static mut LB: RingBuffer = RingBuffer::::new(0); - -struct JoinedRingBuffer<'a> { - lbr: Reader<'a, u8>, - lbw: Writer<'a, u8>, -} - -impl<'a> JoinedRingBuffer<'a> { - const fn new(rb: &'a RingBuffer) -> Self { - let (lbr, lbw) = rb.split(); - Self { lbr: lbr, lbw: lbw } - } -} - -impl Write for JoinedRingBuffer<'_> { - fn write_str(&mut self, s: &str) -> Result<(), fmt::Error> { - for b in s.bytes() { - if let Err(_) = self.lbw.unshift(b) { - // Ignore buffer full errors for logging. - return Ok(()); - } - } - Ok(()) - } -} - -static mut LOGBUF: JoinedRingBuffer = unsafe { JoinedRingBuffer::new(&LB) }; -static mut UART0: usize = 0; - -pub struct Processor { - uart: W, - led: L, -} - -impl Processor -where - W: serial::Write, - L: OutputPin, -{ - pub fn new(uart: W, led: L) -> Self { - // Unsafe because we're creating a mutable alias. - unsafe { UART0 = core::mem::transmute(&uart) }; - Self { - uart: uart, - led: led, - } - } - - pub fn task(&mut self) { - // Unsafe due to mutable static. - if unsafe { LOGBUF.lbr.is_empty() } { - return; - } - self.led.set_high().ok(); - // Unsafe due to mutable static. - while let Some(b) = unsafe { LOGBUF.lbr.shift() } { - nb::block!(self.uart.write(b)).ok(); - } - self.led.set_low().ok(); - } -} - -// Write to the UART right now, instead of putting it on a ring -// buffer. This function is a huge hack, and only useful for debugging -// either before the main loop starts or if the ring buffer is broken. -pub unsafe fn write_fmt_now(args: fmt::Arguments, nl: bool) { - if UART0 == 0 { - return; - } - let uart: &mut UART0>, Sercom0Pad2>, (), ()> = - core::mem::transmute(UART0); - fmt::write(uart, args).expect("writing fmt now to uart"); - if nl { - uart.write_str("\r\n").expect("writing nl now to uart"); - } -} - -pub fn write_fmt(args: fmt::Arguments, nl: bool) { - // Unsafe due to mutable static. - unsafe { - fmt::write(&mut LOGBUF, args).expect("writing fmt to log"); - if nl { - LOGBUF.write_str("\r\n").expect("writing nl to log"); - } - } -} diff --git a/app/src/logger.rs b/app/src/logger.rs new file mode 100644 index 0000000..7e90572 --- /dev/null +++ b/app/src/logger.rs @@ -0,0 +1,139 @@ +use crate::logln_now; + +use rb::{Reader, RingBuffer, Writer}; + +use core::cell::UnsafeCell; +use core::fmt::{self, Write}; +use embedded_hal::{digital::v2::OutputPin, serial}; +use log::{Level, Metadata, Record}; +use trinket_m0::{ + gpio::{Pa6, Pa7, PfD}, + sercom::{Sercom0Pad2, Sercom0Pad3, UART0}, +}; + +static mut UART0: usize = 0; + +struct JoinedRingBuffer<'a> { + lbr: Reader<'a, u8>, + lbw: Writer<'a, u8>, +} + +impl<'a> JoinedRingBuffer<'a> { + const fn new(rb: &'a RingBuffer) -> Self { + let (lbr, lbw) = rb.split(); + Self { lbr: lbr, lbw: lbw } + } +} + +impl fmt::Write for JoinedRingBuffer<'_> { + fn write_str(&mut self, s: &str) -> Result<(), fmt::Error> { + for b in s.bytes() { + if let Err(_) = self.lbw.unshift(b) { + // Ignore buffer full errors for logging. + return Ok(()); + } + } + Ok(()) + } +} + +static mut LB: RingBuffer = RingBuffer::::new(0); +static mut JRB: JoinedRingBuffer = unsafe { JoinedRingBuffer::new(&LB) }; + +// The UART isn't necessarily Sync, so wrap it in something that +// is. As long as flush() is only called from one thread, we're fine, +// but this is a guarantee that the logger module doesn't make. +pub struct WriteWrapper { + w: W, +} +impl WriteWrapper +where + W: serial::Write, +{ + pub const fn new(writer: W) -> Self { + Self { w: writer } + } +} +unsafe impl Sync for WriteWrapper {} + +pub struct SerialLogger { + writer: UnsafeCell>, + led: UnsafeCell, +} + +impl SerialLogger +where + W: serial::Write, + L: OutputPin + Send + Sync, +{ + pub fn new(writer: WriteWrapper, led: L) -> Self { + // Stash this for unsafe usage in case there's an issue with + // the rest of the logging. + unsafe { UART0 = core::mem::transmute(&writer.w) }; + Self { + writer: UnsafeCell::new(writer), + led: UnsafeCell::new(led), + } + } +} +unsafe impl Send for SerialLogger {} +unsafe impl Sync for SerialLogger {} + +impl log::Log for SerialLogger +where + W: serial::Write, + L: OutputPin + Send + Sync, +{ + fn enabled(&self, metadata: &Metadata) -> bool { + metadata.level() <= Level::Info + } + + fn log(&self, record: &Record) { + if !self.enabled(record.metadata()) { + return; + } + + let jrb = unsafe { &mut JRB }; + write!( + jrb, + "[{}] {} -- {}\r\n", + record.level(), + record.target(), + record.args() + ) + .ok(); + } + + fn flush(&self) { + // Unsafe due to mutable static. We can only deal with the + // tail position of the buffer here to keep things safe. + let jrb = unsafe { &mut JRB }; + if jrb.lbr.is_empty() { + return; + } + + let led = unsafe { &mut (*self.led.get()) }; + let writer = unsafe { &mut (*self.writer.get()) }; + + led.set_high().ok(); + while let Some(b) = jrb.lbr.shift() { + nb::block!(writer.w.write(b)).ok(); + } + led.set_low().ok(); + } +} + +// Write to the UART right now, instead of putting it on a ring +// buffer. This function is a huge hack, and only useful for debugging +// either before the main loop starts or if the ring buffer is broken. +pub unsafe fn write_fmt_now(args: fmt::Arguments, nl: bool) { + if UART0 == 0 { + return; + } + let uart: &mut UART0>, Sercom0Pad2>, (), ()> = + core::mem::transmute(UART0); + fmt::write(uart, args).expect("writing fmt now to uart"); + if nl { + uart.write_str("\r\n").expect("writing nl now to uart"); + } +} diff --git a/app/src/macros.rs b/app/src/macros.rs index fe262b4..46d2d07 100644 --- a/app/src/macros.rs +++ b/app/src/macros.rs @@ -1,23 +1,7 @@ -#[macro_export] -macro_rules! logln { - ($($arg:tt)*) => { - crate::log::write_fmt(format_args!($($arg)*), true); - }; - (_) => {}; -} - -#[macro_export] -macro_rules! log { - ($($arg:tt)*) => { - crate::log::write_fmt(format_args!($($arg)*), false); - }; - (_) => {}; -} - #[macro_export] macro_rules! logln_now { ($($arg:tt)*) => { - unsafe {crate::log::write_fmt_now(format_args!($($arg)*), true);} + unsafe {crate::logger::write_fmt_now(format_args!($($arg)*), true);} }; (_) => {}; } @@ -25,7 +9,7 @@ macro_rules! logln_now { #[macro_export] macro_rules! log_now { ($($arg:tt)*) => { - unsafe {crate::log::write_fmt_now(format_args!($($arg)*), false);} + unsafe {crate::logger::write_fmt_now(format_args!($($arg)*), false);} }; (_) => {}; } diff --git a/app/src/main.rs b/app/src/main.rs index 1025fae..b9f626e 100755 --- a/app/src/main.rs +++ b/app/src/main.rs @@ -5,7 +5,7 @@ #![allow(dead_code)] mod dotstar; -mod log; +mod logger; mod macros; mod rtc; mod usb; @@ -17,12 +17,14 @@ use clint::HandlerArray; use cortex_m::asm::wfi; use cortex_m_rt::{entry, exception, ExceptionFrame}; use embedded_hal::digital::v2::OutputPin; +use log::{error, info, LevelFilter}; use smart_leds::colors; use smart_leds_trait::SmartLedsWrite; use trinket_m0::{ self as hal, clock::GenericClockController, - gpio::{OpenDrain, Output, Pa10}, + gpio::{OpenDrain, Output, Pa10, Pa6, Pa7, PfD}, + sercom, target_device::{interrupt, Interrupt}, time::*, CorePeripherals, Peripherals, @@ -61,8 +63,23 @@ fn main() -> ! { red_led.set_low().expect("turning off red LED"); unsafe { LED = core::mem::transmute(&red_led) } - let mut processor = log::Processor::new(uart, red_led); - logln_now!("setting up dotstar"); + // We do the transmute because, while all the underlying data is + // static, we're unable to get a referecence to the UART or LED + // until run-time. Another option would be to use Option in the + // SerialLogger definition, but that requires a check every time + // they might be used. + let uart_wrapped = logger::WriteWrapper::new(uart); + let logger = logger::SerialLogger::new(uart_wrapped, red_led); + + // Wow, would I love to not be annotating this type. + let logger_ref: &'static logger::SerialLogger< + sercom::UART0>, sercom::Sercom0Pad2>, (), ()>, + Pa10>, + > = unsafe { core::mem::transmute(&logger) }; + unsafe { log::set_logger_racy(logger_ref).expect("couldn't set logger") }; + log::set_max_level(LevelFilter::Trace); + + info!("setting up dotstar"); let mut dotstar = dotstar::new( peripherals.SERCOM1, @@ -77,10 +94,10 @@ fn main() -> ! { let black = [colors::BLACK]; let blue = [colors::DARK_MAGENTA]; - logln_now!("setting up timer"); + info!("setting up timer"); let mut rtc_handler = rtc::setup(peripherals.RTC, &mut clocks); - logln_now!("setting up usb host"); + info!("setting up usb host"); let (mut usb_host, mut usb_handler) = usb::USBHost::new( peripherals.USB, pins.usb_sof, @@ -92,7 +109,7 @@ fn main() -> ! { &mut peripherals.PM, ); - logln!("setting up handlers"); + info!("setting up handlers"); HANDLERS.with_overrides(|hs| { hs.register(0, &mut rtc_handler); core.NVIC.enable(Interrupt::RTC); @@ -101,7 +118,7 @@ fn main() -> ! { unsafe { core.NVIC.set_priority(Interrupt::USB, 0) }; core.NVIC.enable(Interrupt::USB); - logln!("Boot up complete."); + info!("Boot up complete."); let mut last_tick = 0; loop { @@ -112,13 +129,11 @@ fn main() -> ! { let tick = rtc::millis(); if tick >= last_tick + 1_024 { last_tick = tick; - //logln!("{}: tick", rtc::millis()); + // info!("{}: tick\r\n", rtc::millis()); } usb_host.task(); - processor.task(); - dotstar .write(blue.iter().cloned()) .expect("turning on dotstar"); @@ -135,7 +150,9 @@ fn panic_handler(pi: &core::panic::PanicInfo) -> ! { logln_now!("~~~ PANIC ~~~"); logln_now!("{}", pi); + logln_now!("flushing log"); loop { + log::logger().flush(); wfi() } } @@ -145,8 +162,11 @@ fn HardFault(ef: &ExceptionFrame) -> ! { let red_led: &mut Pa10> = unsafe { core::mem::transmute(LED) }; red_led.set_high().ok(); + log::logger().flush(); logln_now!("!!! Hard Fault - ef: {:?} !!!", ef); + logln_now!("flushing log"); loop { + log::logger().flush(); wfi() } } @@ -156,7 +176,7 @@ fn DefaultHandler(interrupt: i16) { let red_led: &mut Pa10> = unsafe { core::mem::transmute(LED) }; red_led.set_high().ok(); - logln_now!("*** Default Handler: {} ***", interrupt); + info!("*** Default Handler: {} ***", interrupt); } #[exception] @@ -164,7 +184,7 @@ fn NonMaskableInt() { let red_led: &mut Pa10> = unsafe { core::mem::transmute(LED) }; red_led.set_high().ok(); - logln_now!("+++ NonMaskableInt +++"); + info!("+++ NonMaskableInt +++"); } #[exception] @@ -172,7 +192,7 @@ fn SVCall() { let red_led: &mut Pa10> = unsafe { core::mem::transmute(LED) }; red_led.set_high().ok(); - logln_now!("+++ SVCall +++"); + info!("+++ SVCall +++"); } #[exception] @@ -180,7 +200,7 @@ fn PendSV() { let red_led: &mut Pa10> = unsafe { core::mem::transmute(LED) }; red_led.set_high().ok(); - logln_now!("+++ PendSV +++"); + info!("+++ PendSV +++"); } #[exception] @@ -188,7 +208,7 @@ fn SysTick() { let red_led: &mut Pa10> = unsafe { core::mem::transmute(LED) }; red_led.set_high().ok(); - logln_now!("+++ SysTick +++"); + info!("+++ SysTick +++"); } #[interrupt] diff --git a/app/src/rtc.rs b/app/src/rtc.rs index 0d39d31..79e450a 100644 --- a/app/src/rtc.rs +++ b/app/src/rtc.rs @@ -1,4 +1,5 @@ use core::sync::atomic::{AtomicUsize, Ordering}; +use log; use trinket_m0::{clock::GenericClockController, RTC}; struct Clock(AtomicUsize); @@ -67,5 +68,7 @@ fn handler(rtc: &mut RTC) { CLOCK.set(TICKS); } ADD = !ADD; + + log::logger().flush(); } } diff --git a/app/src/usb.rs b/app/src/usb.rs index acb4457..a5788a1 100644 --- a/app/src/usb.rs +++ b/app/src/usb.rs @@ -1,12 +1,14 @@ mod pipe; mod usbproto; -use crate::{log, log_now, logln, logln_now, rtc}; use pipe::{DataBuf, PipeErr, PipeTable, USBPipeType, USBToken}; use rb::{Reader, RingBuffer, Writer}; use usbproto::*; +use crate::rtc; + use embedded_hal::digital::v2::OutputPin; +use log::{info, warn}; use trinket_m0::{ calibration::{usb_transn_cal, usb_transp_cal, usb_trim_cal}, clock::{ClockGenId, ClockSource, GenericClockController}, @@ -155,7 +157,7 @@ impl USBHost { rc.host_enable_pin = Some(he_pin.into_open_drain_output(port)); } - logln_now!("setting up usb clock"); + info!("setting up usb clock"); pm.apbbmask.modify(|_, w| w.usb_().set_bit()); // Set up USB clock from 48MHz source on generic clock 6. @@ -172,7 +174,7 @@ impl USBHost { } pub fn reset_periph(&mut self) { - log!("resetting usb"); + info!("resetting usb"); // Reset the USB peripheral and wait for sync. self.usb.host().ctrla.write(|w| w.swrst().set_bit()); while self.usb.host().syncbusy.read().swrst().bit_is_set() {} @@ -220,14 +222,14 @@ impl USBHost { // Set VBUS OK to allow host operation. self.usb.host().ctrlb.modify(|_, w| w.vbusok().set_bit()); - logln!("...done"); + info!("...done"); } pub fn task(&mut self) { static mut LAST_EVENT: Event = Event::Error; unsafe { if LAST_EVENT != LATEST_EVENT { - logln!("new event: {:?}", LATEST_EVENT); + info!("new event: {:?}", LATEST_EVENT); } } @@ -257,12 +259,9 @@ impl USBHost { let bits = self.usb.host().intflag.read().bits(); unsafe { if LAST_CBITS != cbits || LAST_FLAGS != bits || LAST_TASK_STATE != self.task_state { - logln!( + info!( "cb: {:x}, f: {:x} changing state {:?} -> {:?}", - cbits, - bits, - LAST_TASK_STATE, - self.task_state, + cbits, bits, LAST_TASK_STATE, self.task_state, ); } LAST_CBITS = cbits; @@ -271,7 +270,7 @@ impl USBHost { }; if let Some(_event) = self.events.shift() { - // logln!("Found event: {:?}", event); + // info!("Found event: {:?}", event); // self.task_state = match event { // Event::None => TaskState::Detached(DetachedState::Illegal), // Event::Detached => { @@ -342,7 +341,7 @@ impl USBHost { AttachedState::WaitResetComplete => { if self.usb.host().intflag.read().rst().bit_is_set() { - logln!("reset was sent"); + info!("reset was sent"); self.usb.host().intflag.write(|w| w.rst().set_bit()); // Make sure we always have a control pipe set up. @@ -375,7 +374,7 @@ impl USBHost { self.task_state = match self.configure_dev(0, 0, low_speed) { Ok(_) => TaskState::Steady(SteadyState::Running), Err(e) => { - logln!("Enumeration error: {:?}", e); + warn!("Enumeration error: {:?}", e); TaskState::Steady(SteadyState::Error) } } @@ -403,14 +402,11 @@ impl USBHost { )?; let desc = vol_descr.get(); - logln_now!( + info!( " -- len: {}, ver: {:04x}, bMaxPacketSize: {}, bNumConfigurations: {}", - desc.b_length, - desc.bcd_usb, - desc.b_max_packet_size, - desc.b_num_configurations + desc.b_length, desc.bcd_usb, desc.b_max_packet_size, desc.b_num_configurations ); - logln_now!(" -- vid: {:x}, pid: {:x}", desc.id_vendor, desc.id_product); + info!(" -- vid: {:x}, pid: {:x}", desc.id_vendor, desc.id_product); // Assign address to this device and: // - Stash bMaxPacketSize @@ -425,12 +421,12 @@ impl USBHost { 0, None, )?; - logln_now!(" -- address set"); + info!(" -- address set"); // Delay according to §9.2.6.3 of USB 2.0 let until = rtc::millis() + 300; while rtc::millis() < until {} - logln_now!("getting config"); + info!("getting config"); let tmp: USBConfigurationDescriptor = Default::default(); //let vol_descr = ::vcell::VolatileCell::new(tmp); self.control_req( @@ -444,10 +440,10 @@ impl USBHost { )?; //let desc = vol_descr.get(); - logln_now!("cdesc.len: {}", tmp.b_length); + info!("cdesc.len: {}", tmp.b_length); // Once addressed, SET_CONFIGURATION(0) - logln_now!("+++ setting configuration"); + info!("+++ setting configuration"); let conf: u8 = 0; self.control_req( new_address, @@ -458,7 +454,7 @@ impl USBHost { 0, None, )?; - logln_now!(" -- configuration set"); + info!(" -- configuration set"); // Now we should be able to access it normally. @@ -502,13 +498,13 @@ impl USBHost { if let Some(b) = buf { match bm_request_type.direction() { USBSetupDirection::DeviceToHost => { - logln_now!("buf0: {:?}", &b); + info!("buf0: {:?}", &b); pipe.in_transfer(&b, NAK_LIMIT)?; - logln_now!("buf1: {:?}", &b); + info!("buf1: {:?}", &b); } USBSetupDirection::HostToDevice => { - logln_now!("Should OUT for {}b", b.len); + info!("Should OUT for {}b", b.len); } } } @@ -532,7 +528,7 @@ impl USBHost { // TODO: should probably make `pipe.send` have optional // `DataBuf`, rather than exposing `dispatch_retries`. - logln_now!("dispatching status stage"); + info!("dispatching status stage"); pipe.dispatch_retries(token, NAK_LIMIT)?; Ok(()) } @@ -556,36 +552,36 @@ pub fn handler(usbp: usize, events: &mut EventWriter) { let usb: &mut USB = unsafe { core::mem::transmute(usbp) }; let flags = usb.host().intflag.read(); - logln!("USB - {:x}", flags.bits()); + info!("USB - {:x}", flags.bits()); let mut unshift_event = |e: Event| { unsafe { LATEST_EVENT = e }; if let Err(_) = events.unshift(e) { - logln!("Couldn't write USB event to queue."); + info!("Couldn't write USB event to queue."); } }; if flags.hsof().bit_is_set() { - logln!(" +hsof"); + info!(" +hsof"); usb.host().intflag.write(|w| w.hsof().set_bit()); unshift_event(Event::Attached); } if flags.rst().bit_is_set() { // We seem to get this whenever a device attaches/detaches. - logln!(" +rst"); + info!(" +rst"); usb.host().intflag.write(|w| w.rst().set_bit()); unshift_event(Event::Detached); } if flags.uprsm().bit_is_set() { - logln!(" +uprsm"); + info!(" +uprsm"); usb.host().intflag.write(|w| w.uprsm().set_bit()); unshift_event(Event::Detached); } if flags.dnrsm().bit_is_set() { - logln!(" +dnrsm"); + info!(" +dnrsm"); usb.host().intflag.write(|w| w.dnrsm().set_bit()); unshift_event(Event::Detached); } @@ -593,19 +589,19 @@ pub fn handler(usbp: usize, events: &mut EventWriter) { if flags.wakeup().bit_is_set() { // §32.8.5.8 - since VBUSOK is set, then this happens when a // device is connected. - logln!(" +wakeup"); + info!(" +wakeup"); usb.host().intflag.write(|w| w.wakeup().set_bit()); unshift_event(Event::Attached); } if flags.ramacer().bit_is_set() { - logln!(" +ramacer"); + info!(" +ramacer"); usb.host().intflag.write(|w| w.ramacer().set_bit()); unshift_event(Event::Detached); } if flags.dconn().bit_is_set() { - logln!(" +dconn"); + info!(" +dconn"); usb.host().intflag.write(|w| w.dconn().set_bit()); usb.host().intenclr.write(|w| w.dconn().set_bit()); usb.host().intflag.write(|w| w.ddisc().set_bit()); @@ -615,7 +611,7 @@ pub fn handler(usbp: usize, events: &mut EventWriter) { } if flags.ddisc().bit_is_set() { - logln!(" +ddisc"); + info!(" +ddisc"); usb.host().intflag.write(|w| w.ddisc().set_bit()); usb.host().intenclr.write(|w| w.ddisc().set_bit()); // // Stop reset signal, in case of disconnection during reset diff --git a/app/src/usb/pipe.rs b/app/src/usb/pipe.rs index 12ca4cb..908c8e5 100644 --- a/app/src/usb/pipe.rs +++ b/app/src/usb/pipe.rs @@ -12,10 +12,10 @@ use pck_size::PckSize; use status_bk::StatusBk; use status_pipe::StatusPipe; -use crate::logln_now; use crate::rtc; use core::convert::TryInto; +use log::info; // FIXME: this stuff is needed for PipeRegs, and while tied to samd, // it shouldn't be tied to trinket_m0. Will need to figure out a @@ -70,13 +70,13 @@ impl PipeTable { let pregs = PipeRegs::from(host, i); let pdesc = &mut self.tbl[i]; - logln_now!("setting paddr of pipe {} to {}:{}", i, addr, ep); - logln_now!("cpipe0: {:x}", pdesc.bank0.ctrl_pipe.read().bits()); + info!("setting paddr of pipe {} to {}:{}", i, addr, ep); + info!("cpipe0: {:x}", pdesc.bank0.ctrl_pipe.read().bits()); pdesc.bank0.ctrl_pipe.write(|w| { w.pdaddr().set_addr(addr); w.pepnum().set_epnum(ep) }); - logln_now!("cpipe1: {:x}", pdesc.bank0.ctrl_pipe.read().bits()); + info!("cpipe1: {:x}", pdesc.bank0.ctrl_pipe.read().bits()); Pipe { num: i, regs: pregs, @@ -103,7 +103,7 @@ impl Pipe<'_, '_> { // byte_count section of register is 14 bits. assert!(buf.len < 16_384); - logln_now!("p{}: sending {:?}", self.num, buf); + info!("p{}: sending {:?}", self.num, buf); // Equiv to UHD_Pipe_Write(epAddr: 0, sizeof(setup_packet), &setup_packet) self.desc @@ -129,7 +129,7 @@ impl Pipe<'_, '_> { // byte_count section of register is 14 bits. assert!(buf.len < 16_384); - logln_now!("p{}: Should IN for {}b.", self.num, buf.len); + info!("p{}: Should IN for {}b.", self.num, buf.len); // TODO: should just pass pipe and pregs in, probably. TODO: // merge with stuff in `send_to_pipe` that also does this. self.desc @@ -162,14 +162,14 @@ impl Pipe<'_, '_> { ) -> Result<(), PipeErr> { assert!(retries > 0); - logln_now!("initial regs"); + info!("initial regs"); self.log_regs(); let until = rtc::millis() + USB_TIMEOUT; let mut last_result: Result<(), PipeErr> = Err(PipeErr::SWTimeout); let mut naks = 0; while naks <= retries { - logln_now!("p{}: dispatch {:?} retry {}", self.num, token, naks); + info!("p{}: dispatch {:?} retry {}", self.num, token, naks); self.dispatch_packet(token); last_result = self.dispatch_result(token, until); @@ -201,13 +201,9 @@ impl Pipe<'_, '_> { let bin = self.regs.binterval.read().bits(); let sts = self.regs.status.read().bits(); let ifl = self.regs.intflag.read().bits(); - logln_now!( + info!( "p{}: cfg: {:x}, bin: {:x}, sts: {:x}, ifl: {:x}", - self.num, - cfg, - bin, - sts, - ifl + self.num, cfg, bin, sts, ifl ); // Pipe RAM regs @@ -217,15 +213,9 @@ impl Pipe<'_, '_> { let sbk = self.desc.bank0.status_bk.read().bits(); let hcp = self.desc.bank0.ctrl_pipe.read().bits(); let spi = self.desc.bank0.status_pipe.read().bits(); - logln_now!( + info!( "p{}: adr: {:x}, pks: {:x}, ext: {:x}, sbk: {:x}, hcp: {:x}, spi: {:x}", - self.num, - adr, - pks, - ext, - sbk, - hcp, - spi + self.num, adr, pks, ext, sbk, hcp, spi ); } @@ -253,17 +243,17 @@ impl Pipe<'_, '_> { if self.is_transfer_complete(token)? { return Ok(()); } else if self.regs.intflag.read().stall().bit_is_set() { - logln_now!("stall"); + info!("stall"); self.log_regs(); self.regs.intflag.write(|w| w.stall().set_bit()); return Err(PipeErr::Stall); } else if self.regs.intflag.read().trfail().bit_is_set() { - logln_now!("trfail"); + info!("trfail"); self.log_regs(); self.regs.intflag.write(|w| w.trfail().set_bit()); return Err(PipeErr::TransferFail); } else if self.desc.bank0.status_bk.read().errorflow().bit_is_set() { - logln_now!("errorflow"); + info!("errorflow"); self.log_regs(); self.desc .bank0 @@ -271,7 +261,7 @@ impl Pipe<'_, '_> { .write(|w| w.errorflow().clear_bit()); return Err(PipeErr::Flow); } else if self.desc.bank0.status_pipe.read().touter().bit_is_set() { - logln_now!("touter"); + info!("touter"); self.log_regs(); self.desc .bank0 @@ -279,7 +269,7 @@ impl Pipe<'_, '_> { .write(|w| w.touter().clear_bit()); return Err(PipeErr::HWTimeout); } else if self.desc.bank0.status_pipe.read().dtgler().bit_is_set() { - logln_now!("dtgler"); + info!("dtgler"); self.log_regs(); self.desc .bank0 @@ -288,7 +278,7 @@ impl Pipe<'_, '_> { return Err(PipeErr::DataToggle); } } - logln_now!("swtimeout"); + info!("swtimeout"); self.log_regs(); Err(PipeErr::SWTimeout) } -- cgit v1.2.3