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.

7 files changed, 232 insertions, 195 deletions

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<u8> = RingBuffer::<u8>::new(0);
-
-struct JoinedRingBuffer<'a> {
-    lbr: Reader<'a, u8>,
-    lbw: Writer<'a, u8>,
-}
-
-impl<'a> JoinedRingBuffer<'a> {
-    const fn new(rb: &'a RingBuffer<u8>) -> 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<W, L> {
-    uart: W,
-    led: L,
-}
-
-impl<W, L> Processor<W, L>
-where
-    W: serial::Write<u8>,
-    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<Sercom0Pad3<Pa7<PfD>>, Sercom0Pad2<Pa6<PfD>>, (), ()> =
-        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<u8>) -> 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<u8> = RingBuffer::<u8>::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: W,
+}
+impl<W> WriteWrapper<W>
+where
+    W: serial::Write<u8>,
+{
+    pub const fn new(writer: W) -> Self {
+        Self { w: writer }
+    }
+}
+unsafe impl<W> Sync for WriteWrapper<W> {}
+
+pub struct SerialLogger<W, L> {
+    writer: UnsafeCell<WriteWrapper<W>>,
+    led: UnsafeCell<L>,
+}
+
+impl<W, L> SerialLogger<W, L>
+where
+    W: serial::Write<u8>,
+    L: OutputPin + Send + Sync,
+{
+    pub fn new(writer: WriteWrapper<W>, 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<W, L> Send for SerialLogger<W, L> {}
+unsafe impl<W, L> Sync for SerialLogger<W, L> {}
+
+impl<W, L> log::Log for SerialLogger<W, L>
+where
+    W: serial::Write<u8>,
+    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<Sercom0Pad3<Pa7<PfD>>, Sercom0Pad2<Pa6<PfD>>, (), ()> =
+        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::Sercom0Pad3<Pa7<PfD>>, sercom::Sercom0Pad2<Pa6<PfD>>, (), ()>,
+        Pa10<Output<OpenDrain>>,
+    > = 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<Output<OpenDrain>> = 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<Output<OpenDrain>> = 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<Output<OpenDrain>> = 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<Output<OpenDrain>> = 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<Output<OpenDrain>> = 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<Output<OpenDrain>> = 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)
     }