Repository: knurling-rs/defmt (rust)

Issue:
defmt: flush API
# What

`defmt_rtt::flush()` is a blocking API that waits until the host has read all the pending data in the target's (caller's) RTT buffer

# Use case

Avoid decoding errors when doing a software reset, or calling `cortex_m::asm::{bootstrap,bootload}`

For example, this likely produces a decoding error in `probe-run`

``` rust
defmt::info!("about to reset!");
SCB::sys_reset();
```

To work around the decoding error you can add a delay

``` rust
defmt::info!("about to reset!");
cortex_m::asm::delay(1_000_000);
SCB::sys_reset();
```

It's not obvious how large to make the delay so the `flush` API would be the preferred option

``` rust
defmt::info!("about to reset!");
defmt_rtt::flush();
SCB::sys_reset();
```

# Unresolved questions

- Can we put the API in the `defmt` crate by making it transport agnostic somehow?
  - the problem with a transport specific API is that it cannot be used in libraries unless one is OK with forcing all users of the libraries to use that specific transport
- in the `defmt_rtt` implementation, how do we prevent the issue of blocking forever if no host / debugger is attached?

Pull request:
`defmt::flush()`
Fixes #515 

## TODO
- [x] skeleton: add method to trait, TODO-implements in crates and tests
- [x] defmt-rtt
- [x] defmt-semihosting
- [x] defmt-itm
- [x] adapt delays based on docs and testing

Patch:
diff --git a/book/src/global-logger.md b/book/src/global-logger.md
index 48d6e54..c9fbd34 100644
--- a/book/src/global-logger.md
+++ b/book/src/global-logger.md
@@ -21,6 +21,9 @@ unsafe impl defmt::Logger for Logger {
     fn acquire() {
         // ...
     }
+    unsafe fn flush() {
+        // ...
+    }
     unsafe fn release() {
         // ...
     }
@@ -53,6 +56,7 @@ struct Logger;
 unsafe impl defmt::Logger for Logger {
     // ...
     # fn acquire() {}
+    # unsafe fn flush() {}
     # unsafe fn release() {}
     # unsafe fn write(bytes: &[u8]) {}
 }
diff --git a/firmware/defmt-itm/src/lib.rs b/firmware/defmt-itm/src/lib.rs
index 7110bfd..70a657e 100644
--- a/firmware/defmt-itm/src/lib.rs
+++ b/firmware/defmt-itm/src/lib.rs
@@ -16,7 +16,11 @@
 
 use core::sync::atomic::{AtomicBool, Ordering};
 
-use cortex_m::{interrupt, itm, peripheral::ITM, register};
+use cortex_m::{
+    asm, interrupt, itm,
+    peripheral::{itm::Stim, ITM},
+    register,
+};
 
 #[cfg(armv6m)]
 compile_error!(
@@ -64,6 +68,15 @@ unsafe impl defmt::Logger for Logger {
         unsafe { ENCODER.start_frame(do_write) }
     }
 
+    unsafe fn flush() {
+        // wait for the queue to be able to accept more data
+        while !stim_0().is_fifo_ready() {}
+
+        // delay "a bit" to drain the queue
+        // This is a heuristic and might be too short in reality. Please open an issue if it is!
+        asm::delay(100);
+    }
+
     unsafe fn release() {
         // safety: accessing the `static mut` is OK because we have disabled interrupts.
         ENCODER.end_frame(do_write);
@@ -84,5 +97,13 @@ unsafe impl defmt::Logger for Logger {
 fn do_write(bytes: &[u8]) {
     // NOTE(unsafe) this function will be invoked *after* `enable` has run so this crate now has
     // ownership over the ITM thus it's OK to instantiate the ITM register block here
-    unsafe { itm::write_all(&mut (*ITM::ptr()).stim[0], bytes) }
+    unsafe { itm::write_all(stim_0(), bytes) }
+}
+
+/// Get access to stimulus port 0
+///
+/// # Safety
+/// Can only be invoked *after* `enable` has run
+unsafe fn stim_0<'a>() -> &'a mut Stim {
+    &mut (*ITM::PTR).stim[0]
 }
diff --git a/firmware/defmt-rtt/src/lib.rs b/firmware/defmt-rtt/src/lib.rs
index 6dc1163..ed5ec60 100644
--- a/firmware/defmt-rtt/src/lib.rs
+++ b/firmware/defmt-rtt/src/lib.rs
@@ -8,6 +8,15 @@
 //! // src/main.rs or src/bin/my-app.rs
 //! use defmt_rtt as _;
 //! ```
+//!
+//! # Blocking/Non-blocking
+//!
+//! `probe-run` puts RTT into blocking-mode, to avoid losing data.
+//!
+//! As an effect this implementation may block forever if `probe-run` disconnects on runtime. This
+//! is because the RTT buffer will fill up and writing will eventually halt the program execution.
+//!
+//! `defmt::flush` would also block forever in that case.
 
 #![no_std]
 
@@ -47,6 +56,11 @@ unsafe impl defmt::Logger for Logger {
         unsafe { ENCODER.start_frame(do_write) }
     }
 
+    unsafe fn flush() {
+        // SAFETY: if we get here, the global logger mutex is currently acquired
+        handle().flush();
+    }
+
     unsafe fn release() {
         // safety: accessing the `static mut` is OK because we have disabled interrupts.
         ENCODER.end_frame(do_write);
@@ -91,22 +105,17 @@ const NOBLOCK_TRIM: usize = 1;
 
 impl Channel {
     fn write_all(&self, mut bytes: &[u8]) {
-        // NOTE `flags` is modified by the host after RAM initialization while the device is halted
-        // it cannot otherwise be modified so we don't need to check its state more often than
-        // just here
-        if self.flags.load(Ordering::Relaxed) == BLOCK_IF_FULL {
-            while !bytes.is_empty() {
-                let consumed = self.blocking_write(bytes);
-                if consumed != 0 {
-                    bytes = &bytes[consumed..];
-                }
-            }
-        } else {
-            while !bytes.is_empty() {
-                let consumed = self.nonblocking_write(bytes);
-                if consumed != 0 {
-                    bytes = &bytes[consumed..];
-                }
+        // the host-connection-status is only modified after RAM initialization while the device is
+        // halted, so we only need to check it once before the write-loop
+        let write = match host_is_connected(self) {
+            true => Channel::blocking_write,
+            false => Channel::nonblocking_write,
+        };
+
+        while !bytes.is_empty() {
+            let consumed = write(self, bytes);
+            if consumed != 0 {
+                bytes = &bytes[consumed..];
             }
         }
     }
@@ -172,6 +181,18 @@ impl Channel {
 
         len
     }
+
+    fn flush(&self) {
+        // return early, if host is disconnected
+        if !host_is_connected(self) {
+            return;
+        }
+
+        // busy wait, until the read- catches up with the write-pointer
+        let read = || self.read.load(Ordering::Relaxed);
+        let write = || self.write.load(Ordering::Relaxed);
+        while read() != write() {}
+    }
 }
 
 // make sure we only get shared references to the header/channel (avoid UB)
@@ -206,3 +227,8 @@ unsafe fn handle() -> &'static Channel {
 
     &_SEGGER_RTT.up_channel
 }
+
+fn host_is_connected(channel: &Channel) -> bool {
+    // we assume that a host is connected if we are in blocking-mode. this is what probe-run does.
+    channel.flags.load(Ordering::Relaxed) == BLOCK_IF_FULL
+}
diff --git a/firmware/defmt-semihosting/src/lib.rs b/firmware/defmt-semihosting/src/lib.rs
index 699f760..4d51842 100644
--- a/firmware/defmt-semihosting/src/lib.rs
+++ b/firmware/defmt-semihosting/src/lib.rs
@@ -37,6 +37,13 @@ unsafe impl defmt::Logger for Logger {
         unsafe { ENCODER.start_frame(do_write) }
     }
 
+    unsafe fn flush() {
+        // Do nothing.
+        //
+        // semihosting is fundamentally blocking, and does not have I/O buffers the target can control.
+        // After write returns, the host has the data, so there's nothing left to flush.
+    }
+
     unsafe fn release() {
         // safety: accessing the `static mut` is OK because we have disabled interrupts.
         ENCODER.end_frame(do_write);
diff --git a/firmware/qemu/src/bin/log.out b/firmware/qemu/src/bin/log.out
index 130270d..ff1f4c7 100644
--- a/firmware/qemu/src/bin/log.out
+++ b/firmware/qemu/src/bin/log.out
@@ -140,4 +140,7 @@
 0.000139 INFO 1
 0.000140 INFO 1
 0.000141 INFO ccbbaadd
-0.000142 INFO QEMU test finished!
+0.000142 INFO log data: 43981
+0.000143 INFO flush! 🚽
+0.000144 INFO log more data! 🎉
+0.000145 INFO QEMU test finished!
diff --git a/firmware/qemu/src/bin/log.release.out b/firmware/qemu/src/bin/log.release.out
index 7ac523f..ed00b9c 100644
--- a/firmware/qemu/src/bin/log.release.out
+++ b/firmware/qemu/src/bin/log.release.out
@@ -138,4 +138,7 @@
 0.000137 INFO 1
 0.000138 INFO 1
 0.000139 INFO ccbbaadd
-0.000140 INFO QEMU test finished!
+0.000140 INFO log data: 43981
+0.000141 INFO flush! 🚽
+0.000142 INFO log more data! 🎉
+0.000143 INFO QEMU test finished!
diff --git a/firmware/qemu/src/bin/log.rs b/firmware/qemu/src/bin/log.rs
index 8be6068..9b6ddb9 100644
--- a/firmware/qemu/src/bin/log.rs
+++ b/firmware/qemu/src/bin/log.rs
@@ -657,6 +657,12 @@ fn main() -> ! {
     struct NotFormatType;
     defmt::info!("{}", 0xCCBBAADD as *mut NotFormatType);
 
+    // tests for `defmt::flush()`
+    defmt::info!("log data: {}", 0xABCD);
+    defmt::info!("flush! 🚽");
+    defmt::flush();
+    defmt::info!("log more data! 🎉");
+
     defmt::info!("QEMU test finished!");
 
     loop {
diff --git a/macros/src/attributes/global_logger.rs b/macros/src/attributes/global_logger.rs
index e982ec2..724d2d4 100644
--- a/macros/src/attributes/global_logger.rs
+++ b/macros/src/attributes/global_logger.rs
@@ -43,6 +43,11 @@ fn codegen(strukt: &ItemStruct) -> TokenStream {
             <#ident as defmt::Logger>::acquire()
         }
 
+        #[no_mangle]
+        unsafe fn _defmt_flush()  {
+            <#ident as defmt::Logger>::flush()
+        }
+
         #[no_mangle]
         unsafe fn _defmt_release()  {
             <#ident as defmt::Logger>::release()
diff --git a/src/lib.rs b/src/lib.rs
index 89cbbe0..8be7648 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -277,6 +277,10 @@ pub use defmt_macros::write;
 /// # todo!()
 ///         // ...
 ///     }
+///     unsafe fn flush() {
+///         # todo!()
+///         // ...
+///     }
 ///     unsafe fn release() {
 /// # todo!()
 ///         // ...
@@ -351,15 +355,37 @@ pub use defmt_macros::bitflags;
 #[doc(hidden)] // documented as the `Format` trait instead
 pub use defmt_macros::Format;
 
-#[export_name = "__defmt_default_timestamp"]
-fn default_timestamp(_f: Formatter<'_>) {
-    // By default, no timestamp is used.
-}
-
 // There is no default timestamp format. Instead, the decoder looks for a matching ELF symbol. If
 // absent, timestamps are turned off.
+#[export_name = "__defmt_default_timestamp"]
+fn default_timestamp(_f: Formatter<'_>) {}
 
 #[export_name = "__defmt_default_panic"]
 fn default_panic() -> ! {
     core::panic!()
 }
+
+/// Block until host has read all pending data.
+///
+/// The flush operation will not fail, but might not succeed in flushing _all_ pending data. It is
+/// implemented as a "best effort" operation.
+///
+/// This calls the method `flush` of the used "global [`Logger`]". The logger is likely provided by
+/// [`defmt-rtt`](https://crates.io/crates/defmt-rtt) or [`defmt-itm`](https://crates.io/crates/defmt-itm).
+pub fn flush() {
+    extern "Rust" {
+        fn _defmt_acquire();
+        fn _defmt_flush();
+        fn _defmt_release();
+    }
+    // SAFETY:
+    // * we call these function in the correct order: first acquire the lock, then flush and
+    //   finally release the lock
+    // * these function should be provided by the macro `#[global_logger]` and therefore
+    //   trustworthy to call through FFI-bounds
+    unsafe {
+        _defmt_acquire();
+        _defmt_flush();
+        _defmt_release()
+    }
+}
diff --git a/src/traits.rs b/src/traits.rs
index f2b8e02..c6748b0 100644
--- a/src/traits.rs
+++ b/src/traits.rs
@@ -96,6 +96,15 @@ pub unsafe trait Logger {
     /// Panics if already acquired in the current execution context. Otherwise it must never fail.
     fn acquire();
 
+    /// Block until host has read all pending data.
+    ///
+    /// The flush operation must not fail. This is a "best effort" operation, I/O errors should be discarded.
+    ///
+    /// # Safety
+    /// Must only be called when the global logger is acquired in the current execution context.
+    /// (i.e. between `acquire()` and `release()`).
+    unsafe fn flush();
+
     /// Releases the global logger in the current execution context.
     ///
     /// This will be called by the defmt logging macros after writing each log frame.
@@ -106,8 +115,9 @@ pub unsafe trait Logger {
 
     /// Writes `bytes` to the destination.
     ///
-    /// This will be called by the defmt logging macros to transmit frame data. The write
-    /// operation must not fail. One log frame may cause multiple `write` calls.
+    /// This will be called by the defmt logging macros to transmit frame data. One log frame may cause multiple `write` calls.
+    ///
+    /// The write operation must not fail. This is a "best effort" operation, I/O errors should be discarded.
     ///
     /// The `bytes` are unencoded log frame data, they MUST be encoded with `Encoder` prior to
     /// sending over the wire.
@@ -117,6 +127,6 @@ pub unsafe trait Logger {
     ///
     /// # Safety
     /// Must only be called when the global logger is acquired in the current execution context.
-    /// (i.e. between acquire() and release())
+    /// (i.e. between `acquire()` and `release()`).
     unsafe fn write(bytes: &[u8]);
 }


Test patch:
diff --git a/tests/basic_usage.rs b/tests/basic_usage.rs
index b8cb1f9..e14da59 100644
--- a/tests/basic_usage.rs
+++ b/tests/basic_usage.rs
@@ -7,6 +7,7 @@ struct Logger;
 
 unsafe impl defmt::Logger for Logger {
     fn acquire() {}
+    unsafe fn flush() {}
     unsafe fn release() {}
     unsafe fn write(_bytes: &[u8]) {}
 }