knurling-rs / defmt

Efficient, deferred formatting for logging on embedded systems

defmt

defmt ("de format", short for "deferred formatting") is a highly efficient logging framework that targets resource-constrained devices, like microcontrollers.

For more details about the framework check the book at https://defmt.ferrous-systems.com.

The git version of the defmt book can be viewed at https://defmt-next.ferrous-systems.com/.

Setup

New project

The fastest way to get started with defmt is to use our app-template to set up a new Cortex-M embedded project.

Existing project

To include defmt in your existing project, follow our Application Setup guide.

MSRV

defmt always compiles on the latest stable rust release. This is enforced by our CI building and testing against this version.

It still might work on older rust versions, but this isn't ensured.

defmt ecosystem

The following diagram illustrates the user-facing and internal crates of the defmt framework.

Developer Information

Running Tests

Tests are run using cargo xtask -- although this is simply an alias (defined in .cargo/config.toml) for cargo run --package xtask --.

To see a list of options, see xtask/src/main.rs, or run:

$ cargo xtask help

For example, to run all the tests, run:

$ cargo xtask test-all

You will need qemu-system-arm installed and in your $PATH for some of the tests (e.g. test-snapshot).

Support

defmt is part of the Knurling project, Ferrous Systems' effort at improving tooling used to develop for embedded systems.

If you think that our work is useful, consider sponsoring it via GitHub Sponsors.

License

Licensed under either of

• Apache License, Version 2.0 (LICENSE-APACHE or http://www.apache.org/licenses/LICENSE-2.0)

• MIT license (LICENSE-MIT or http://opensource.org/licenses/MIT)

at your option.

Contribution

Unless you explicitly state otherwise, any contribution intentionally submitted for inclusion in the work by you, as defined in the Apache-2.0 license, shall be licensed as above, without any additional terms or conditions.

defmt's Issues

bitfields: enhance formatting

currently BitFields are formatted as {:#b} but that may not be the most ergonomic option.

• display values in the "most readable" format but that's sort of arbitrary => binary as default; hex for multiples of 8?
• extra bonus points for underscores (readability++)

note:
you'll probably have to update en/decoding tests

casting inside a logging macro call causes compile error

binfmt::info!("Hello {:u8}", 42u16 as u8);

currently yields

error[E0308]: mismatched types
  --> src/bin/log.rs:27:5
   |
27 |     binfmt::info!("Hello {:u8}", 42u16 as u8);
   |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   |     |
   |     expected `&u8`, found `u8`
   |     help: consider borrowing here: `&binfmt::info!("Hello {:u8}", 42u16 as u8);`
   |
   = note: this error originates in a macro (in Nightly builds, run with -Z macro-backtrace for more info)

error[E0606]: casting `&u16` as `u8` is invalid
  --> src/bin/log.rs:27:5
   |
27 |     binfmt::info!("Hello {:u8}", 42u16 as u8);
   |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   |     |
   |     cannot cast `&u16` as `u8`
   |     help: dereference the expression: `*binfmt::info!("Hello {:u8}", 42u16 as u8);`
   |
   = note: this error originates in a macro (in Nightly builds, run with -Z macro-backtrace for more info)

error: aborting due to 2 previous errors; 1 warning emitted

Some errors have detailed explanations: E0308, E0606.
For more information about an error, try `rustc --explain E0308`.
error: could not compile `firmware`.

probe-run: error when all logs are disabled

Steps to reproduce: remove all the logs statements from firmware/nrf52/src/bin/log.rs

$ cargo rb log
Error: RTT control block not available
$ echo ?
1

In this scenario probe-run should flash and reset the device; then (if there's no RTT block) detach from the device and exit with exit-code=0.

usize/isize support

needs to be added to the parser, encoder, decoder and formatter.
Also impl Format for {i,u}size

Decoder needs to distinguish between "needs more data" and "corrupted stream"

Currently it just returns a () error type, so we cannot tell apart these two cases. This means that there's no way to detect stream errors.

The decoder can use a library like anyhow to provide rich text-based errors too.

improve error message for unknown formatting parameters

Currently it says "invalid bitfield range"

info!("{:MyType}", x);
//    ^^^^^^^^^^^ error: invalid bitfield range

move top-level README into mdbook

It has become too long; sections and a side navigation bar would help

`binfmt-macros`: use `binfmt-parser`

remove the parse function in there, which is an old version of binfmt_parser::parse, and use binfmt_parser

add user documentation for `intern!`

bitfield: accept larger integer types

info!("x={:0..4}", x) currently requires that x has type u8.
This macro should accept inputs of type u16 and u32.
One way to implement this is to add a new sealed Truncate trait and implement it for primitive types.

mod sealed {
    pub trait Truncate<U> {
        fn truncate(self) -> U;
    }

    impl Truncate<u8> for u8 {
        fn truncate(self) -> u8 {
            self
        }
    }

    // repeat for u32 and u64
    impl Truncate<u8> for u16 {
        fn truncate(self) -> u8 {
            self as u8
        }
    }

    // also impl Truncate<{u16,u32}>
}

pub mod export {
    pub fn truncate<T>(x: impl crate::sealed::Truncate<T>) -> T {
        x.truncate()
    }
}

Then the macro expansion should be changed from:

_fmt_.u8(arg0);

To

_fmt_.u8(binfmt::export::truncate(arg));

This may affect type inference causing the following expression to not compiler info!("{:0..4}", 42). (default type is i32 but i32 doesn't implement the Truncate trait)

Option/Result Format impl: cannot be decoded

let res: Result<i8, i8> = Ok(42);
binfmt::info!("Hello {:?}", res);

$ cargo run # qemu-run
Error: couldn't decode all data (remaining: [2, 0, 1, 1, 0, 2a])

add API docs to the `binfmt` crate

cargo doc -p binfmt --target thumbv7m-none-eabi --open looks quite empty at the moment

array byte support

e.g. {:[u8; 32}. parser, decoder and encoder needs to be added.
Also while doing this impl Format for [u8; N] for N up to 32.

qemu-run can drop log messages

Not sure why, but sometimes the last log messages get lost. This might require adding more messages to the test program to show up.

Macros don't support trailing commas

Or at least write! doesn't, I haven't checked the others yet.

`#[global_logger]` design and RTT implementation

encode and format bitfields

probe-run: reject ELFs that use the hard-float ABI

hard-float support is not yet implemented (see #31)

For now probe-run should emit an error message if it receives an ELF that uses the hard float ABI.
It should be possible to detect these ELFs using the xmas_elf API (the info may be architecture/ARM specific).

impl Format for [T]

This one is going to require some design work.

encode and format floats

to_bits then to_le_bytes

qemu-run: lingering QEMU process using 100% CPU

After running cargo rb log in firmware/qemu I now have a qemu-system-arm process running that uses 100% CPU, even after Cargo has exited. I'm not sure what's required to reproduce this.

probe-run: device emitted non-zero exit code

Currently asm::bkpt makes probe-run exit with exit-code = 0.
To implement target side unit testing on stable we need a wait to exit probe-run with non-zero exit code.
Here's one way to do that:

• modify probe-run to exit with SIGABT exit code (134) when it sees that the top function in the call stack is HardFault
• device: override HardFault to do loop { asm::bkpt }
• device: make panic_handler call asm::udf (unlike panic-abort this would work on stable)

result: panic! and checked stack overflows now exit probe-run with exit-code=134

derive(Format): add a field attribute to skip field

Like #[serde(skip)]
Fields marked with this attribute will not be serialized / formatted

probe-run: virtual unwind support for hard-float targets

The virtual unwinder doesn't expect floating pointer (FP) registers to be pushed on exception entry.

The Cortex-M is smart about this: it only pushes FP registers if the preempted context was using them.
The unwinder will need to compute at runtime whether the FP registers were pushed or not (there should be some flag/register pushed onto the stack that contains this info) and update the per-frame SP value accordingly while walking up the stack.

[research] extract span information from DWARF?

proc_macro::Span::{source_file,start,end} are unstable. See if we can instead extract span information from DWARF information, which is part of the ELF metadata.

If we add this metadata to a log frame then we could (a) display it in the console output or (b) implement go to definition in interactive front ends.

derive(Format): support more than 256 variants

the discriminant should be encoded in the smallest integer (LE encoding) that can enumerate all the variants. Previous discussion

probe-run: non-binfmt mode

Currently probe-run expects a single RTT up channel that sends binfmt-encoded data.

We should add a non-binfmt mode (behind a CLI flag) where probe-run prints str data RTT up channels.
With that mode we can replace the dk-run in embedded-trainings-2020 with probe-run.
probe-run is a more general purpose version of dk-run (--chip is not hardcoded).

derive(Format): add field attribute to rename a field

Like #[serde(rename)].
This will cause a struct field to be renamed when formatted.

#[derive(Format)]
struct S {
    #[binfmt(rename = "loop")]
    _loop: u32,
}

info!("{:?", s) -> S { loop: 42 }

encode and format slices

prefix with LEB(length) then send data as it is

`binfmt-parser`: return "fragments" instead of just parameters?

binfmt_parser::parse extracts only the parameters from a format string.
Instead it could return "fragments" (Vec<Fragment>) that are either a "piece" of the format string or a parameter.
String pieces contain no parameters (e.g. {:?}), have been "unescaped" ({{ -> {) and can be e.g. directly printed to the console.

enum Fragment<'f> {
   /// A piece of the format string that contains no parameters
   Piece(Cow<'f, str>),
   Parameter(Parameter),
}

I think this would let us remove the span field from Parameter and likely also simplify the "formatting" operation.

(binfmt_decoder::Table could also be modified to be a map from string index to the "fragments" (Vec<Fragment>) of the format string instead of a map from string index to unprocessed format strings)

cc @jonas-schievink

#[derive(Format)] produces syntax error with readme example

#[derive(Format)]
struct Header {
    source: u8,
    destination: u8,
    sequence: u16,
}

#[derive(Format)]
enum Request {
    GetDescriptor { descriptor: Descriptor, length: u16 },
    SetAddress { address: u8 },
}

produces:

error: expected `,`
  --> src/lib.rs:278:21
   |
15 |     GetDescriptor { descriptor: Descriptor, length: u16 },
   |                     ^^^^^^^^^^

error: expected one of `.`, `;`, `?`, `}`, or an operator, found `f`
  --> src/lib.rs:276:10
   |
13 | #[derive(Format)]
   |          ^^^^^^ expected one of `.`, `;`, `?`, `}`, or an operator
   |
   = note: this error originates in a derive macro (in Nightly builds, run with -Z macro-backtrace for more info)

error: proc-macro derive produced unparseable tokens
  --> src/lib.rs:276:10
   |
13 | #[derive(Format)]
   |          ^^^^^^

error[E0412]: cannot find type `Descriptor` in this scope
  --> src/lib.rs:278:33
   |
15 |     GetDescriptor { descriptor: Descriptor, length: u16 },
   |                                 ^^^^^^^^^^ not found in this scope

error: aborting due to 4 previous errors

The "cannot find type" is expected (but should also be fixed, to make the example copy-and-paste-able), but the parse errors shouldn't be happening.

handle positional arguments

currently, this will incorrectly not compile:

binfmt::info!("Hello {0:u8} {0:u8}!", 42);
//^ error: format string requires 2 arguments but only 1 were provided

The reason for this could be the nargs check in Codegen::new()
Positional arguments should be recognized and treated correctly.

note from @japaric: while we're at it, keep ordering in mind!

info!("Hello {1:u16} {0:u8}", 42u8, 256u16);

That will send [$index, $timestamp, $u16, $u8]. The decoder expects $u8 first since it's assigned index 0.

the issue is resolved if:

• the above examples don't fail
• we at least have tests covering the above two examples

derive(Format): number of supported enum variants

enum support is currently limited to 256 variants (u8). For future compat we could lower the limit to 128; that would let us move to LEB128 (but maybe not vint64?) w/o breaking the binary format. Alternatively, we could say than we'll never support more than 256 variants in binary version 1 (and I hope we'll never have a version 2).

cc @jonas-schievink

qemu-run: Ctrl+C doesn't work

When adding a panic!() call to firmware/qemu/src/bin/log.rs and running cargo rb log, qemu will enter the panic-halt infinite loop with no way out. Ctrl+C seems to be ignored, and even Ctrl+Z does not suspend the process. The only way to quit it is to manually kill the right PID(s).

encode and format bools

TODO:

• extend function set in src/libs.rs::Formatter
• impl Format for bool, bitfield etc. in src.impls.rs
• fill in todos in Codegen::new() in macros

notes from @japaric :
slice -> prefix with LEB(length) then send data as it is
f32 -> to_bits then to_le_bytes
bitfields -> to_le_bytes
bools -> compress then treat as array (no length in the payload)

issue is done if

• formatters are implemented (duh)
• there are tests to confirm this
• (firmware/log.rs has been extended to demonstrate some of them)

macros: remove public `write` function

the write! macro is no longer exposed in the public API (#83).
Instead of having derive(Format) call into binfmt::export::write! do the write! expansion in the macros::format function

decoder: pre-processed Arg (e.g. real structs instead of nested format strings)

The existing Format (and the upcoming FormatSlice) variants are a bit problematic/annoying because they require re-parsing the format string during display and (further) serialization.

If instead we assume that Arg will either be a primitive, a struct or a enum (the last two could recursively contain a struct or enum but ultimately contain primitives) then we can pre-process the Arg and flatten it in some cases.
A flattened Arg variant may look like this:

// (more optimized representations are possible:
//  e.g. interned strings or interned struct layouts)
enum Val<'t> {
    Ixx(i64),
    Uxx(u64),
    Bool(bool),
    F32(f32),
    Struct {
        name: String,
        fields: HashMap<String, Val>,
    },
    // Enum, etc.
}

This structure is easier to print and serialize, into say JSON, for inter-op with front-ends.

With this representation, data like this:

info!("x={:?}", 42u8);
[
    $index1, // "x={:?}"
    $index2, // "{:u8}"
    42,
]

can be processed into Val::Uxx(42) (last two bytes) -- today that would be Arg::Format { format: "{:u8}", args: [Arg::Uxx(8)] }

And data like this:

[
    $index1, // "X {{ y: {:?} }}"
    $index2, // "Y {{ z: {:u8} }}"
    42,
]

can be decoded into (hypothetical hash map literal) Struct { name: "X", fields: { "y": Struct { name: "Y", fields: { "z": Uxx(42) } } } } -- today that's two nested Arg::Format values

Then log frames can become something like this:

struct Frame<'t> {
    pub level: Level,
    // Processed format string
    pub pieces: Vec<Piece<'t>>,
    pub timestamp: u64,
    pub args: Vec<Val<'t>>,
}

enum Piece<'t> {
    Str(&'t str),
    // index into `self.args` (simplified: bitfields make this more complex)
    Param(usize),
}

But to make this work we need to constrain Format implementations.
Right now they can be too free-form because write! is public.
The user could write:

struct S {
    x: u8,
}

impl Format {
    fn format(&self, f: &mut Formatter) {
        write!(f, "S; x = {:u8};", self.x)
    }
}

The chosen format string wouldn't match the decoder expectation (S {{ x: {:u8} }}) and it would not be possible to process it as a Val::Struct

To avoid that issue we can remove write! from the public API and instead provide customization of the Format implementation through attributes (like serde does)
.
For example, #[rename] could be used to rename fields and #[skip] could be used to skip fields.

// "S {{ loop: {:u8} }}"
#[derive(Format)]
struct S {
    #[rename = "loop"]
    _loop_: u8,
    #[skip]
    secret_key: [u8; 16],
}

Thoughts? @jonas-schievink

Investigate efficiency of using leb64 for 32-bit values

We currently encode string indices, timestamps, slice lengths and isize/usize with leb64, which makes use of 64-bit arithmetic. We should investigate whether using a 32-bit version for most of these (except timestamps, which are always up to 64 bits) makes formatting more efficient.

bitfield: further compression

info!("x={:10..14}", u16_value) sends u16_value over the wire.
We can save bandwidth by sending only the higher byte (u16_value >> 8) as u8.

`binfmt-macros`: fix logging level filter logic

To match the spec. Currently, the logic looks like this:

if cfg!(feature = "binfmt-on") {
    if binfmt::export::Level::Info >= binfmt::export::threshold() {

this is not quite right because threshold in defined in binfmt and we want the log statement to be filtered based on the Cargo feature of the crate calling into the macro so instead we need something like this for info!:

if cfg!(feature = "binfmt-on") &&
    (cfg(feature = "binfmt-info") ||
        (!cfg(feature = "binfmt-warn") && !cfg(feature = "binfmt-error"))) {

binfmt-warn means only WARN level and up.
binfmt-error means only ERROR level and up.
If only binfmt-on is enabled then INFO level is logged regardless of the state of debug_assertions
The debug! macro will need to include a cfg!(debug_assertions) somewhere.
Logging levels will likely need to be "cascaded" in the Cargo.toml of the caller crate to make the above work:

[features]
binfmt-on = []
binfmt-trace = ["binfmt-debug", "binfmt-info", "binfmt-warn", "binfmt-error"]
binfmt-debug = ["binfmt-info", "binfmt-warn", "binfmt-error"]
binfmt-info = ["binfmt-warn", "binfmt-error"]
binfmt-warn = ["binfmt-error"]
binfmt-error = []

If we need that then the user documentation will need to be updated.

Or there may be a different way to set this up.

align `winfo!()` with `info!()`

currently, the implementation of winfo!() is prefixed with

// TODO share more code with `log`

It seems to be used in unit tests for encoding only (i.e. in encode.rs) so it should be reusing the code running for info!()– otherwise we can't really trust the tests to break (i.e. if we change info! but forget to update winfo! as well)

syntax checked `write!` macro

for now the write! macro has been removed from the public API because it's too free form.
We'll need the write! macro for things like svd2rust integration (derive is not flexible enough) so we want a public write! macro but that's syntax checked: the format string should be a valid struct ("S {{ field: {:u8} }} }") or valid enum.

We can start with just checked struct syntax. enum syntax is a bit harder: how do we want to expose it to the user so that they cannot misuse?

`{:str}` expects a `Str`

but should accept a &str. This doesn't compile but should:

info!("Hello, {:str}", "world");
//~^ error: expected struct `binfmt::Str`, found `&str`

support passing interned string literals

currently, binfmt only supports passing string values to a format string, like so:

info!("They said: {:str}", "Hi!"); // on-the-wire = [$index-they, $timestamp, $length, b'H', b'i', b'!']

This is not ideal, as the entire string value ("Hi!") has to be sent over the wire rather than just an index.
Therefore, we'd also like to support passing interned (i.e. predefined) string literals to a format string, like so:

let s: Str = intern!("Hi!");
info!("They said: {:istr}", s); // on-the-wire = [$index-they, $timestamp, $index-hi]

To do this, we'll need to

• introduce a new formatting parameter (for example {:istr}– preferrably a name that is less similar to the already-existing {:str})
• extend parser/lib.rs to recognize the new formatting parameter
• extend parse_args to handle this parameter (implementation note from @japaric: &'t str in them would be pointing into the table: &'t [u8] (like the Format.format string does) not into bytes. Rationale: table lives for as long as the decoder/printer program is running (i.e. effectively it will never be deallocated); on the other hand, bytes may be a temporary stack allocated buffer.)
• extend docs to explain the difference
• add tests

decoder can't handle fmt strings with `bool` and Structs containing `bool`

Introduced by #65:

binfmt::info!("{:bool} {:?}", true, Flags {a: true, b: false, c: true }); is not correctly decoded to true Flags { a: true, b: false, c: true }.

The problem is that currently, each new {:?} will lead to a new Arg::Format pushed to args in parse_args(). If this Arg contains booleans that are part of a bool compression package, parsing will go wrong.

Notes:

• the current assumption is that after #20, we'll be able to modify the decoding to fix this bug.
• There's a (commented out because failing) test called bools_bool_struct() in decoder/lib.rs that can be used as a starting point.

`binfmt-macros`: add macros for other logging levels

currently only info! is supported. Don't forget to re-export the macros from the binfmt crate.

decoder: recognize bools compressed into one byte even if there's other data between them

Given a format string

"hidden bools {:bool} {:u8} {:bool} {:bool}"

currently, the decoder is only able to handle format string arguments that are serialized as:

[<index>, <timestamp>, 0b1, <u8 value>, 0b10]
      first bool value ^^^              ^^^^ last two bool values (packed into one byte)

but it should be able to (also?) handle

[<index>, <timestamp>, 0b110, <u8 value>]
                        ^^^^ all three bool values (packed into one byte)

Open Questions

• should both behaviours be acceptable?

The issue is resolved if the following boxes are ticked:

• clarify spec
• implement handling
• add/modify tests

document `probe-run`

this is more of a standalone tool that supports binfmt but for now let's document it in the binfmt book

`binfmt-macros`: support encoding more types

{:[u8]} and other types are not currently supported.

To be done after #14.

probe-run: add `--list-chips` flag

like cargo-flash --list-chips this should list all the chips supported by probe-rs.
You'll want to use the probe_rs::config::registry::families() API for this.