Serial output and logging on a microcontroller
Step 8 of 10, and the step that gives the firmware a voice. Step 7 left it reading a BMP280 and pacing the breath with the temperature, and the LED was the only output the board had: a reading the firmware took was a brightness, and nothing else. This step puts a UART on the board and a defmt logger behind it, so a reading becomes a line of text on a terminal and a record in a log. It starts from tag stm32-ch07 and ends at stm32-ch08.
Everything here was captured on Rust 1.99.0 with edition 2024, the compiler this track is written against, with stm32f4xx-hal 0.23.0, embedded-hal 1.0.0, bmpe280 1.0.5, defmt 1.2.0 and defmt-rtt 1.3.1.
Why not println!
Section titled “Why not println!”Step 4 took std away: the firmware is no_std, and println! lives in std. A microcontroller has no stdout to print to anyway. What a no_std firmware has instead is core::fmt::Write, a trait with one method, write_str — and anything that implements it can be the target of write! and writeln!. On the board that is the hal’s Serial. Here is the same shape against a mock that keeps the bytes instead of sending them:
use core::fmt::Write;
/// The UART end of the link, as far as the host side cares: a sink that/// keeps what would have gone out over the wire. On the board this is/// the hal's `Serial`, whose `write_str` blocks until the peripheral/// has taken each byte.struct MockUart { transmitted: Vec<u8>,}
impl Write for MockUart { fn write_str(&mut self, s: &str) -> core::fmt::Result { self.transmitted.extend_from_slice(s.as_bytes()); Ok(()) }}
fn main() { let mut uart = MockUart { transmitted: Vec::new(), }; // The reading the firmware took in step 7, reported the plain way: // no level, no timestamp, the number already turned into text. let temperature = 25.16f64; writeln!(uart, "temperature {temperature:.2} C").unwrap(); println!( "{} bytes: {:?}", uart.transmitted.len(), String::from_utf8(uart.transmitted).unwrap() );}20 bytes: "temperature 25.16 C\n"Twenty bytes for one reading, and the whole line goes out over the wire every time. The other cost is flash, and it is the larger one. Measured on this machine, step 7’s firmware links .text at 0x1305c (77,916 bytes) and .rodata at 0x2f24 (12,068); this step’s links .text at 0x166c4 (91,844) and .rodata at 0x3cf4 (15,604), which is 17.5 KB more. A build of this step’s firmware with the port and the writeln! but with defmt taken back out links .text at 0x154dc (87,260) and .rodata at 0x35ec (13,804), which splits the growth: the port and the one line of text account for about 11 KB, defmt and RTT for the remaining 6.4 KB. That 11 KB is the UART instance plus the machinery that turns a number into text — nothing else on this firmware does that, and the number is an f64. That is the trade the rest of this step is about: the text line is universal and costs bandwidth and flash on every reading, while defmt pays its 6.4 KB once and then sends a smaller frame — and needs a probe attached to say anything, which is the other half of the trade.
The UART
Section titled “The UART”USART2’s TX and RX are muxed onto PA2 and PA3, and the Nucleo wires those two pins to the ST-Link’s virtual COM port, so the board’s own USB cable is the whole cable: the output shows up on the host as a serial device at 115200 baud, eight data bits, no parity, one stop bit — the hal’s SerialConfig::default(). An external USB-TTL adapter works too; the firmware does not care what is listening.
The port joins main() after the sensor, and the pins are handed over in their plain split state, as the I2C bus’s were in step 7 — the constructor moves them into alternate mode itself:
// USART2's TX and RX are muxed onto PA2 and PA3, which the Nucleo // wires to the ST-Link's virtual COM port: the firmware's plain // text output shows up on the host as a serial device, with no // hardware beyond the board's own USB cable. The pins are handed // over plain, as the bus's were, and the constructor moves them // into alternate mode itself. `SerialConfig::default()` is 115200 // baud, eight data bits, no parity, one stop bit. // // The `Result` is real — a baud rate the bus clock cannot produce // is an error — but 16 MHz divided down to 115200 is comfortably // inside the peripheral's range, so a failure here means the port // is unusable and the board says so the only way it can. let mut serial = match dp.USART2.serial( (gpioa.pa2, gpioa.pa3), SerialConfig::default(), &mut rcc, ) { Ok(serial) => serial, Err(_) => stall_lit(), };Serial implements core::fmt::Write itself, one byte at a time, blocking on each — which is why writeln! on it needs no wrapper of its own. Two imports make it work: core::fmt::Write for the trait, and the hal’s Serial and Config types.
What the firmware logs
Section titled “What the firmware logs”sense — the loop since step 6, renamed in step 7 — gains the serial port and two reports per reading. The loop is the whole change:
if button.tick() { breath.toggle(); // A pause and a resume leave no trace on the board — the // LED going dark is all the signal there is — so they are // worth a record of their own. if breath.running { defmt::info!("breath resumed"); } else { defmt::info!("breath paused"); } } // One write per tick, running or paused. On this chip the error // type is `Infallible`, so the unwrap cannot fire. led.set_duty_cycle_percent(breath.duty()).unwrap(); delay.delay_ms(1); TICKS.fetch_add(1, Ordering::Relaxed); breath.advance();
since_reading += 1; if since_reading >= READING_TICKS { since_reading = 0; // The driver returns degrees Celsius as an `f64`; on this // chip that is a software double, and one reading every // half second is not where the cycles go. let reading = sensor.measure(); breath.set_half(half_for(reading.temperature)); // The same number, twice. The first report formats it into // text on the spot — the whole line, every character, goes // out over the wire. The second hands defmt the raw bytes // and a reference to the format string. `.ok()` because a // UART that cannot take a byte is not worth stopping the // firmware over. writeln!(serial, "temperature {:.2} C", reading.temperature).ok(); defmt::info!("temperature {=f64} C", reading.temperature); } }}Every reading is reported twice, in the two encodings this step is about. A button press gets a defmt record of its own, because a pause leaves no trace in the readings. The timestamp comes from TICKS, an AtomicU32 the loop increments once per millisecond; the firmware has no clock peripheral wired up yet, and the loop’s own pace is the clock there is.
defmt is a logging framework built for exactly this situation. Three things about it are worth understanding before the code, and all three show up in the block below.
The format string is checked when the crate compiles, not when the record is emitted. Every argument must implement defmt’s Format trait, and a type that doesn’t is a compile error:
/// A reading as the driver hands it back: degrees Celsius and pascals.struct Reading { temperature: f64, pressure: f64,}
fn main() { let reading = Reading { temperature: 25.16, pressure: 101310.73, }; // Logging a struct defmt has never heard of. `Format` is the trait // every argument must implement, and this one doesn't — the // compiler says so here, not at run time on the board. defmt::info!("{=?}", reading);}error[E0277]: the trait bound `Reading: Format` is not satisfied --> src/main.rs:15:5 | 15 | defmt::info!("{=?}", reading); | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ unsatisfied trait bound |help: the trait `Format` is not implemented for `Reading` --> src/main.rs:2:1 | 2 | struct Reading { | ^^^^^^^^^^^^^^ = help: the following other types implement trait `Format`: &T &mut T () (T0, T1) (T0, T1, T2) (T0, T1, T2, T3) (T0, T1, T2, T3, T4) (T0, T1, T2, T3, T4, T5) and 125 othersnote: required by a bound in `defmt::export::fmt` --> /Users/rango/.cargo/registry/src/rsproxy.cn-e3de039b2554c837/defmt-1.2.0/src/export/mod.rs:137:15 |137 | pub fn fmt<T: Format + ?Sized>(f: &T) { | ^^^^^^ required by this bound in `fmt` = note: this error originates in the macro `defmt::info` (in Nightly builds, run with -Z macro-backtrace for more info)
For more information about this error, try `rustc --explain E0277`.error: could not compile `verify` (bin "verify") due to 1 previous errorThe fix is one line — #[derive(defmt::Format)] on the struct — and the point is that the mistake cannot reach the board.
The format string itself is stored once. Each log statement interns its string into a .defmt section of the firmware image, and the record that goes over the wire carries a small reference to it instead of the text. The decoder on the host resolves the reference against the image.
And the arguments travel as their raw bytes, not as text. A logger is how all of this leaves the chip: the Logger trait, with acquire, write, flush and release. The block below is a complete defmt program that runs on this machine — the same trait defmt-rtt implements on the board, pointed at a Vec instead of a ring buffer. The article needs the crate:
[dependencies]defmt = "1.2.0"use core::sync::atomic::{AtomicU64, Ordering};use defmt::{global_logger, Encoder, Logger};use std::sync::Mutex;
/// The loop's own clock, standing in for the firmware's tick counter:/// one increment per record, which is what makes the second record's/// timestamp a one.static TICKS: AtomicU64 = AtomicU64::new(0);defmt::timestamp!("{=u64}", TICKS.fetch_add(1, Ordering::Relaxed));
/// One record as two views: the payload `Logger::write` was handed, and/// the encoded bytes that would go on the wire.struct Record { payload: Vec<u8>, wire: Vec<u8>,}
static RECORDS: Mutex<Vec<Record>> = Mutex::new(Vec::new());static PAYLOAD: Mutex<Vec<u8>> = Mutex::new(Vec::new());static CURRENT: Mutex<Vec<u8>> = Mutex::new(Vec::new());static ENCODER: Mutex<Encoder> = Mutex::new(Encoder::new());
/// A logger that keeps every record instead of sending it anywhere./// This is the trait the firmware's RTT logger implements; the firmware/// writes the encoded bytes to a ring buffer the probe reads, and this/// one writes them to a `Vec`.#[global_logger]struct Recorder;
unsafe impl Logger for Recorder { fn acquire() { PAYLOAD.lock().unwrap().clear(); CURRENT.lock().unwrap().clear(); ENCODER .lock() .unwrap() .start_frame(|b| CURRENT.lock().unwrap().extend_from_slice(b)); } unsafe fn flush() {} unsafe fn write(bytes: &[u8]) { PAYLOAD.lock().unwrap().extend_from_slice(bytes); ENCODER .lock() .unwrap() .write(bytes, |b| CURRENT.lock().unwrap().extend_from_slice(b)); } unsafe fn release() { ENCODER .lock() .unwrap() .end_frame(|b| CURRENT.lock().unwrap().extend_from_slice(b)); RECORDS.lock().unwrap().push(Record { payload: std::mem::take(&mut *PAYLOAD.lock().unwrap()), wire: std::mem::take(&mut *CURRENT.lock().unwrap()), }); }}
fn hex(bytes: &[u8]) -> String { bytes .iter() .map(|b| format!("{b:02X}")) .collect::<Vec<_>>() .join(" ")}
fn main() { // The reports the firmware makes, at three different levels. Only // two of the three come out: `info` is below the level defmt // defaults to, so the macro compiles it out entirely. defmt::println!("temperature {=f32} C", 25.16f32); defmt::info!("breath paused by a button press"); defmt::error!("sensor did not answer at 0x76");
for record in RECORDS.lock().unwrap().iter() { println!( "payload {:>2} bytes: {}", record.payload.len(), hex(&record.payload) ); println!( "wire {:>2} bytes: {}", record.wire.len(), hex(&record.wire) ); }}payload 14 bytes: 09 00 00 00 00 00 00 00 00 00 AE 47 C9 41wire 9 bytes: 00 09 7E AE 47 C9 41 07 00payload 10 bytes: 08 00 01 00 00 00 00 00 00 00wire 5 bytes: 08 01 7A 7F 00Two records, not three — and that is the first thing to notice. The info record is gone: without the DEFMT_LOG environment variable set at build time, defmt compiles out everything below error, and nothing warns you that it did. The filter is a compile-time decision, so raising the level costs nothing at run time and changing it means a rebuild. The firmware sets it once in .cargo/config.toml, where it applies to every build:
[env]DEFMT_LOG = "info"defmt::println! is the escape hatch: it always logs, whatever the level.
Now the bytes. The first record’s payload is fourteen bytes long. The first two are the reference to the interned format string — the low sixteen bits of its address, which is why that pair is the one part of the payload that is not the same on every run: on a machine that randomises where the image loads, every run of the same binary gives it a different value. Run the program above twice and the two payloads differ in that pair and nowhere else. Everything after it is fixed. The next eight bytes are the timestamp, zero here because this was the first record. The last four are the argument: AE 47 C9 41 is 25.16f32 in little-endian, its raw bits, with no decimal point anywhere in the frame. The decoder formats the float on the host, where the cycles are free.
Twenty bytes of text, or a fourteen-byte payload whose format string was paid for once in flash — and the record carries a timestamp and a level that the text line doesn’t: the timestamp is eight bytes of the payload, and the level is metadata on the interned string, which is why the symbols above are tagged defmt_info and defmt_error and why it costs nothing per record. The wire line under each payload is what the Encoder makes of it: defmt hands the logger unencoded bytes and the logger encodes them, here into a Vec and on the board into the RTT buffer. The framing is rzCOBS, groups of seven bytes with a code byte that says which of them were zero, and a zero byte between frames — which is why the frame’s length moves when the string reference happens to contain a zero.
The firmware’s logger is defmt-rtt, and RTT is what gets the bytes off the chip. SEGGER’s Real Time Transfer is a ring buffer in the target’s RAM that the debugger reads over the same SWD lines the probe already uses for flashing. No extra pins, no baud rate, no second cable — and no output either, unless a probe is attached and reading. That is the trade against the UART, which works with nothing but the board’s own USB port.
Linking the logger is one import — use defmt_rtt as _; — and it needs a critical-section implementation, which is why the firmware’s cortex-m dependency carries the critical-section-single-core feature. What lands in the image is visible in the built ELF: the control block at 0x20000008 and a 1024-byte ring buffer in .uninit, which is the buffer’s default size:
20000008 D _SEGGER_RTT 7 .uninit 00000400 2000004c 2000004c BSS 8 .defmt 00000012 00000000 00000000The .defmt section is where the interned strings live, and the firmware’s five of them are right there in the symbol table — defmt mangles each one into a JSON symbol that carries the format string, the level and the crate. Sorted by address, which is the order the linker gave them:
00000002 N {"package":"firmware","tag":"defmt_info","data":"breath paused","disambiguator":"192297795817234645","crate_name":"firmware"}00000003 N {"package":"firmware","tag":"defmt_info","data":"breath resumed","disambiguator":"5775299010506604426","crate_name":"firmware"}00000004 N {"package":"firmware","tag":"defmt_info","data":"temperature {=f64} C","disambiguator":"1570905681675742151","crate_name":"firmware"}00000005 N {"package":"firmware","tag":"defmt_error","data":"panic: {=?}","disambiguator":"633691767066518043","crate_name":"firmware"}0000000c N {"package":"firmware","tag":"defmt_timestamp","data":"{=u32}","disambiguator":"10360713406377644163","crate_name":"firmware"}Each string exists once in the image, at an address the linker assigns from one upwards — those 00000002 to 00000005 are the references the records carry, and on the firmware they are small numbers rather than addresses because defmt’s own linker script lays the section out that way. The last one is the timestamp’s own format string, interned like any other. That script is the last piece of the setup: defmt’s build script generates a defmt.x, and the firmware’s .cargo/config.toml passes it to the linker next to cortex-m-rt’s link.x:
rustflags = ["-C", "link-arg=-Tlink.x", "-C", "link-arg=-Tdefmt.x"]Without it the interned strings are scattered across the image and the decoder on the host cannot find them. With it, probe-rs — the runner this track has used since step 2, and the program cargo run invokes here — decodes the frames as they arrive; its --log-format option exists for exactly this. The plain rtt-target crate is the other half of the story: it prints ordinary text over the same mechanism with rprintln!, but its API lets anything write to the channel, which can corrupt defmt’s stream — so the two crates cannot be linked together. Plain RTT text, or defmt over RTT: pick one.
Build it and run it
Section titled “Build it and run it”cargo build Compiling litrs v1.0.1 Compiling bitflags v1.3.2 Compiling defmt-rtt v1.3.1 Compiling time-core v0.1.9 Compiling powerfmt v0.2.1 Compiling num-conv v0.2.2 Compiling deranged v0.5.9 Compiling stm32f4xx-hal v0.23.0 Compiling embedded-dma v0.2.0 Compiling fugit-timer v0.1.3 Compiling embedded-hal-nb v1.0.0 Compiling embedded-storage v0.3.2 Compiling embedded-io v0.6.1 Compiling bare-metal v1.0.0 Compiling rand_core v0.9.5 Compiling rand_core v0.6.4 Compiling bmpe280 v1.0.5 Compiling document-features v0.2.12 Compiling time v0.3.55 Compiling syn v3.0.9 Compiling syn v2.0.119 Compiling thiserror-impl v2.0.21 Compiling cortex-m-rt-macros v0.7.7 Compiling enumflags2_derive v0.7.12 Compiling enumflags2 v0.7.12 Compiling defmt-parser v1.1.0 Compiling firmware v0.1.0 (/Users/rango/www/hackingwithrust/code/embedded-stm32) Finished `dev` profile [unoptimized + debuginfo] target(s) in 8.68sThat is the last stretch of a cold build. Cargo compiles dependencies in parallel, so the order of the lines varies between runs. The crates this step adds are bitflags, defmt, defmt-macros, defmt-parser, defmt-rtt, thiserror and thiserror-impl; four of them — defmt-macros, defmt-parser, thiserror and thiserror-impl — are proc-macro machinery that runs on the host while the firmware compiles and never reaches the image. No --target: .cargo/config.toml pins it, as it has since step 2. The path after the package name is this machine’s project directory, and the build time is this machine’s too.
With the board plugged in:
cargo run Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.13s Running `probe-rs run --chip STM32F401RE target/thumbv7em-none-eabihf/debug/firmware`Error: No connected probes were found.The last line is this machine again: no board attached, the same error a loose cable gives. Plug the Nucleo in and the same command writes the image, resets the chip and starts it, and probe-rs prints the decoded records as they arrive. What the board does then: every half second a reading arrives as a line of text on the virtual COM port and as a defmt record over RTT, and B1 still pauses and resumes the breath — now with a record saying so. If the sensor is not answering at 0x76, the start-up check fails as it did in step 7 and the LED goes solid; and if the firmware panics, the handler emits one last record before it takes the pin back.
Pitfalls
Section titled “Pitfalls”DEFMT_LOG defaults to error, and nothing tells you
Section titled “DEFMT_LOG defaults to error, and nothing tells you”The demo above proved it live: three records in, two out. A firmware that logs at info and prints nothing on the first run has usually just been built without the variable. It is read when the crate compiles, so there is no run-time flag and no warning — set it in .cargo/config.toml’s [env] section, as this firmware does, or export it for one build.
No timestamp! means no timestamps
Section titled “No timestamp! means no timestamps”defmt::timestamp! is a module-level declaration, and forgetting it is silent: defmt’s linker script provides a default that writes nothing, and the decoder turns timestamps off. A log without timestamps looks fine until the day it is needed for ordering.
RTT needs the probe at run time, the UART doesn’t
Section titled “RTT needs the probe at run time, the UART doesn’t”Unplug the debugger and the RTT stream goes nowhere — the buffer fills, and in defmt-rtt’s default blocking mode the firmware eventually stalls on a full buffer with nobody reading. The UART line keeps coming as long as the board has power. That is why this firmware reports readings on both.
The panic handler deliberately does not flush
Section titled “The panic handler deliberately does not flush”defmt::flush() blocks until the host has read the pending bytes. In the panic path that would trade a lit LED for a dark board the moment the probe is detached, so the handler logs, lights LD2 and stops. The record of a panic nobody was watching is lost; the signal is not.
Where the code lives
Section titled “Where the code lives”The project lives in embedded-stm32/ in the examples repository, one commit and one tag per article. This article’s end state is stm32-ch08:
git clone https://github.com/hackingwithrust/examples.gitcd examples/embedded-stm32git checkout stm32-ch08cargo buildIf a build misbehaves, checking out that tag and diffing it against your tree shows which line drifted.
Step 9, Async tasks on a microcontroller, takes the polling loop apart: an embassy executor, and several things at once instead of one thing in sequence. It isn’t on the site yet, so there is nothing to link to; the track overview keeps the list of what has landed.