The Road to defmt-1.0

[jonathanpallant]

The Road to Defmt 1.0

What is defmt?

The defmt library is described in the defmt book as:

a highly efficient logging framework that targets resource-constrained devices, like microcontrollers.

It should be noted that according to this intro, it doesn't target microcontrollers exclusively, nor does it target Arm systems in particular. This intro does, however call out high efficiency as a key feature.

Fundamentally, defmt is many different things wearing a trenchcoat. It is:

1. An API for libraries to emit logging calls:

   info!("Received buffer {=[u8]} at {=u32:us}", buffer, rx_timestamp);

   These calls are similar to, but not fully compatible with, the std::fmt machinery used in println! and friends. In particular defmt supports =u32 and similar to specify the type of the value being printed, but std::fmt does not. We added this to save space because then the type of the value doesn't need to be serialised into the logging frame.

2. An implementation of that API, contained in the defmt crate. This includes macros which emit magically named symbols that intern the format strings and other metadata using (3), then call into the registered global defmt transport using (3) to send messages using (4).

3. A stable ABI for a registered global defmt transport to receive messages from logging calls made in libraries (where the library is totally unaware of and decoupled from the chosen logging implementation). This is done using the Logger trait, and the global_logger! macro.

4. A mechanism for emitting log messages as both interned strings (at compile time) and log frames (at run time). As this mechanism can change over time, it is identified with a Defmt Version value. A Defmt Version is a string, but currently each prior version has had a simple numeric value; the current Defmt Version is "4". This version number unambiguously identifies both the the string interning mechanism (5) and the wire format (6), which then allows the defmt logs to be reconstituted.

   The Defmt Version produced by the defmt crate is indicated in the ELF symbol table by a symbol with a name like _defmt_version_ = X. As of defmt-0.3.8, that symbol is called _defmt_version_ = 4 to indicate Defmt Version 4. Note that it does not indicate the version number of the defmt crate. It would in theory be possible for one version of the defmt crate to offer multiple Defmt Versions, controlled with feature flags - although it is highly likely that only one could be selected at a time to avoid conflicts.

   Adding a new Defmt Version is not considered a breaking change, because of this mechanism to self-describe which version it is using, although it may require users to update any host tools (like probe-rs) to use a new enough version of defmt-decoder. Dropping support within defmt-decoder for an older wire format is considered a breaking change to that crate.

5. A mechanism for embedding defmt interned strings and metadata in such a way that they do not occupy space in the target's flash, but can be read by a host-side tool like defmt-decoder. In Defmt Version 4, the data is stored as JSON formatted symbol names within an ELF file, such that each is allocated a unique 'memory address' (which acts as the interned string's ID).

   These symbols are placed within a NOLOAD section and so do not occupy any storage space on the target. Here is an example of a symbol from Defmt Version 4, as viewed with objdump:

   00000002 g     O .defmt	00000001 {"package":"dk","tag":"defmt_debug","data":"Initializing the board","disambiguator":"15307126232750674618","crate_name":"dk"}
   

   We can see it lies at memory address 0x0000_0002, thus giving it an ID of 2. The JSON encoded object tells of which package generated the message, the log level, and the string itself.

6. A mechanism for encoding defmt log messages into defmt log frames (the wire format). Any given Defmt Version may have multiple options for how this encoding is performed, which will be indicated using symbols within the .demft section, like _defmt_encoding_ = rzcobs.

7. A trait, defmt::Format, which lets user-defined data types present a mechanism by which they can be encoded into the 'wire format'. This then allows them to be passed as arguments to the defmt logging macros in (1). There is an associated derive-macro which can automatically implement this trait on any struct or enum comprising only values that implement that trait (in a similar vein to derive(Debug) for core::fmt::Debug).

8. A reference logging transport called defmt-rtt which sends encoded defmt frames over Segger's Real Time Transport (RTT). RTT is an in-memory ringbuffer which is written to by the target's CPU and read from by a debug probe under the control of a host machine. RTT is usually used to send strings (like a serial port) but we use it to send encoded defmt frames.

9. A reference logging parser library called defmt-parser, which can read defmt log frames (e.g. as received over RTT via a debug probe connected to an MCU that is using defmt-rtt as its logging transport) and turn them into Rust structures.

10. A reference logging decoder library called defmt-decoder, which can read structures that represent defmt log frames (e.g. as output by defmt-parser) and turn them into formatting Unicode strings.

11. A reference logging parser binary called defmt-print, which uses defmt-decoder to decode standard input, and prints formatted log message to standard output.

There is a delicate balance between these components. As one example, it is important that a tool that uses defmt-decoder (e.g. the popular probe-rs programming tool) uses a version that knows about the various different Defmt Versions that it might encounter. In addition, is important that a defmt transport like defmt-rtt is compatible with the defmt logging crate being used - even if you are using a driver crate that hasn't been updated for some time and was written to use an older version of the defmt library. Because the logging library and the transport communicate through magically named macro-generated extern "C" functions, we must limit users to a single instance of the defmt crate in the dependency tree. This means major version bumps on the defmt crate have ecosystem-splitting effects that we really want to avoid.

What does a 1.0 mean?

A 1.0 release is a commitment to stability, as demonstrated to great effect by the Rust Project itself.

The current Rust language is the result of a lot of iteration and experimentation. The process has worked out well for us: Rust today is both simpler and more powerful than we originally thought would be possible. But all that experimentation also made it difficult to maintain projects written in Rust, since the language and standard library were constantly changing.

The 1.0 release marks the end of that churn. This release is the official beginning of our commitment to stability, and as such it offers a firm foundation for building applications and libraries. From this point forward, breaking changes are largely out of scope (some minor caveats apply, such as compiler bugs).

When we started, defmt was a novel idea and no-one was certain it would work out in practice. The response has been remarkable:

• There are currently 427 crates on crates.io which depend on defmt (mostly libraries using defmt to emit logs, but also some defmt transports)
• There are currently over 5000 repositories on Github which depend on defmt (a mixture of libraries and binaries)

However, to get there, defmt has had to change and adapt. Currently we are on defmt v0.3.8, which implements Defmt Version 4, and defmt-decoder v0.3.11, which can interpret Defmt Version 4 and Defmt Version 3.

The 1.0 release of defmt will mark an official end to the churn (although we've been basically doing that for a while anyway), and the beginning of the Knurling project's commitment to stability.

A proposal for a defmt 1.0 release

1. Libraries will be able to specify defmt = "1" in their Cargo.toml file. Subsequent releases of defmt will obey Semantic Versioning. There is currently no intention to ever produce a defmt 2.0 release.

2. There will be a final 0.3-series release of defmt, which imports defmt = "1" and re-exports a defmt-0.3 compatible API.

3. Any library currently using defmt = "^0.3" in their Cargo.toml file can replace that line with defmt = "1", and everything will continue to work, unless you are locked to a version of 0.3 prior to the final 1.0-compatible version.

4. A binary can link against a library using defmt = "^0.3" and a different library using defmt = "1", at the same time (this was/is not possible for defmt 0.3 and defmt 0.2), unless you are locked to a version of 0.3 prior to the final 1.0-compatible version.

5. The defmt-decoder will be updated to 1.0, which will be a breaking change for any binary or library using the existing version. These breaking changes will be documented, with common fixes identified. A PR will be produced for probe-rs to update to defmt-decoder 1.0. Subsequent releases of defmt-decoder will obey Semantic Versioning 2.0.0.

6. The ABI between the defmt library and the transport implementations (like defmt-rtt) will be stabilised as-is and documented in the defmt book.

7. The defmt-rtt transport will be updated to 1.0, but any application using defmt-rtt = "^0.3" can be updated to use defmt-rtt = "^1.0" with no further changes required to the program.

8. The list of Defmt Versions supported by defmt-decoder (and hence defmt-print) will be documented, including the period of time for which the Knurling Project is guaranteeing to support each of those formats with support and updates in defmt-decoder.

9. A mechanism will be documented whereby users can add their own custom Defmt Versions. A set of Defmt Versions will be reserved for private use, along the lines of the Unicode Private Use Area. This will allow users to fork the defmt crate and defmt-decoder crates for private use, confident that the production versions will never start producing output with a conflicting Defmt Version. Once fully developed, there is the option to upstream such changes, but where significant differences are to be found, we might want to optionally enable the new encoding to make upgrades easier for existing users.

   For example, a user might wish to change the wire format so that every defmt log frame includes a single byte to indicate the logging level, rather than that information only being available inside the interned metadata. They could temporarily fork the defmt and defmt-decoder crates and prototype these changes using a PUA Defmt Version (e.g. Version 1000). At a later time, this could be added to the defmt crate as part of, say Defmt Version 7, but as an optional feature enabled in much the same way that RZCOBS encoding is enabled currently (with a symbol called _defmt_encoding = rzcobs).

10. The defmt-parser library will remain an unstable, internal-only, tool. The defmt-decoder will be the stable mechanism to turn encoded binary data into Unicode text with optional ANSI escape-sequence based formatting.

Questions we anticipate might be Frequently Asked (QFA)

How do I use defmt on std?

The difference between defmt::info! and log::info! means it's not easy to just import either and have the same format string work. But people want to be able to test their libraries on Windows/macOS/Linux, and defmt currently explodes there with a linker error.

For example, this format string is legal for both because Square implements both defmt::Format and core::fmt::Debug:

#[derive(defmt::Format, Debug)]
struct Square { width: u32 }

log::info!("Square is {:?}", Square { width: 25 });
defmt::info!("Square is {:?}", Square { width: 25 });

This format string will not with with log, becuase it uses =u32 to specify the type of the argument as a u32.

defmt::info!("Square has width {=u32}", 25);

Using these type specifiers is popular with defmt, because it makes the encoded frame smaller (because the type information is in the interned metadata and so doesn't have to be included in the encoded frame).

We have some ideas about how to resolve this:

1. Implement a defmt transport that works on Windows/macOS/Linux, so you can just leave the defmt::info! (etc) calls in place. This also means the Windows/macOS/Linux defmt transport has to include the defmt-decoder crate and have some way of grabbing the interned strings using only their address, which might be impossible unless we add a feature flag to disable string interning (as part of some future Defmt Version) or find a way to make the Windows/Linux/macOS linkers less sad about our string interning mechanism.
2. Have an std feature in the defmt crate which makes it export macros with the same API and syntax, but that render the whole line to a String and then pass it to the log crate. Not super efficient, but if you are using libstd you probably aren't as fussed about performance as a no_std user would be.

We need to explore this before committing to a 1.0 release. Volunteers welcome!

Can defmt::Format be dyn-compatible?

Someone wants to be able to pass &dyn defmt::Format but can't because we have a static function in the trait.

Unfortunately I cannot see a way to remove it. The serialiser needs to report what kind of thing is being serialised so the deserialiser can unpack it. This is done using an interned string:

pub fn fmt<T: Format + ?Sized>(f: &T) {
    istr(&T::_format_tag());
    f._format_data();
}

pub fn fmt_slice<T: Format>(values: &[T]) {
    usize(&values.len());
    istr(&T::_format_tag());
    for value in values {
        value._format_data();
    }
}

If _format_tag() takes &self, then you can't call T::_format_tag() when serialising a slice, and we can't guarantee that the slice has non-zero length, so we can't call values[0]._format_tag() either. So the trait has to include a static method, and that means we can't have dynamic trait objects.

Runtime filtering

Someone is asking for target-side run-time filtering of log messages. In other words, to compile them all in (like with DEFMT_LOG=trace) but then control at run-time which modules have logging enabled, and which log levels get emitted. The problem is that the metadata about the log level and the source module goes into the magic symbol, but isn't available to defmt-rtt on the target at log time.

A solution may be possible where defmt gains a static AtomicU8 and makes choices about logging at run-time. Such a feature would be opt-in, but probably wouldn't require a new Defmt Version. This then also means that every transport (like defmt-rtt) gains the feature automatically because it happens inside defmt before frames are transported.

ASCII-safe encoding of frames

Currently we support either raw encoding or RZCOBS encoding of defmt frames.

We have been asked if (an ASCII compatible one) is possible.

We should be able to add this using a new encoding as part of some future Defmt Version N. The ASCII compatible encoding would be specified using a new symbol, like _defmt_encoding = base64.

Can I store metadata somewhere other an ELF file's symbols?

It's quite common for people to want to send defmt encoded logs Over The Air, because they are small. But they don't want to have their cloud service parsing ELF files. Instead, they'd like the interned strings stored in another format.

It's likely this could be achieved by writing a tool that processes an symbol table and produces a JSON file containing all the interned strings. We would then stabilise this JSON-encoded representation of the defmt metadata, alongside the the symbol-table version.

We should do some testing to see how the symbol interning works on macOS (Mach-O) and Windows (Portable Executable) as well.

Why can't filenames begin with digits?

Currently defmt cannot handle filenames that being with digits or are otherwise not a valid identifier.

This seems like the macro being overly strict. Reducing this restriction should be fine post-1.0, or even pre-1.0.

[chrysn]

Trench coat aspect 7 (Format trait) is the one stable aspect I care most about, as it is what libraries need to coordinate on for providing impls on their types even when they don't emit log events themselves. It depends only on the stability of the defmt::write! macro, not on the defmt::info! (item 1), which would come next on my list of priorities (when libraries do want to log).

[jonathanpallant]

Yes, good point, when people manually implement the defmt::Format trait they typically use the defmt::write! macro to write into the given Formatter object, as per https://docs.rs/defmt/latest/defmt/trait.Format.html.

So we have the keep the trait the same (or backwards compatible), but also keep the defmt::write! macro compatible.

[chrysn]

More precisely, reading this again: No, those users don't need a stable defmt::write! macro. They still only need a stable defmt::Format trait that's part of their public API; the implementation could still use a 0.4-or-whatever defmt, as long as it produces a correct implementation of the trait.

[jonathanpallant]

the cargo resolver will need to build the old-and-unchanging library with defmt-0.3.99, which will expose an API that works just like defmt-0.3.8 (same traits, same macros) but defmt-0.3.99 will contain a set of shims to bounce them into actual defmt-1.0, so we keep a consistent version of defmt across the build (because of the magic no-mangle extern C symbols and the links= attribute).

[jonathanpallant]

1. Implement a defmt transport that works on Windows/macOS/Linux...

2. Have an std feature in the defmt crate....

This looks plausible: #890

I am currently able to print the format string at run-time because it's now (optionally) in the value of the variable not the name of the variable. Rendering it shouldn't be hard from here.

[teburd]

I noted this on the Zephyr discord, but it'd be really nice to consider as part of 1.0 encoding the message identifiers in a way that doesn't constantly change using a hash rather than an indexed integer.

I don't have a lot of experience with pigweed but this looked really nice to me as one of the attributes of the pw_tokenize module used in their dictionary logging feature https://pigweed.dev/pw_tokenizer/tokenization.html#token-encoding

The identifier to the messages can still be a word in size so I don't think much is lost there.

[jonathanpallant]

Currently, because we use a simple index to identify the interned strings, the index calculation can be done by the linker, and the index is known to be small, so usually only takes one byte to encode.

What are the benefits of having a stable identifier for interned strings, and is it worth the cost of adding ~3 bytes to every log message sent?

[teburd]

I can see two main benefits.

Sensible behavior when the dictionary changes

Sensible behavior when multiple elf images (multiple dictionaries) make up the firmware.

These problems can be solved in other ways by adding some versioning marker or a custom mux/demux for identifying which stream matches which elf. But that’s extra work when really a single merged dictionary of all versions and all firmwares might’ve been tenable had the message ids been, mostly or completely, unique by hash instead.

Think Tock Apps or Zephyr Extensions, or even multiple firmware versions in the wild. All real world problems, all hassles with current Zephyr and Defmt style logging. Potentially less of a hassle with the pigweed method.

[jonathanpallant]

You make a good point, but I don't know that it's worth adding three bytes to every log message for every user. Perhaps there's a way to make it optional. I'll open a ticket and have a think!

[jonathanpallant]

#891 is the ticket.

[chrysn]

I also prefer short encodings, but have different encoding preferences (like, generate a fixed and growing set of table entries, and encode them in CBOR).

For the discussion at hand, maybe the takeaway is that the serialization format may go into a more diverse set of directions (which needs to be stable across an application but might have some configuration or other variability to that), and doesn't need to go for a stable series with top priority?