[RFC] environment variable based, target side log filter

[japaric]

UPDATE(2021-09-20) RFC was accepted and its status changed to "needs implementation"

(less hand-way, more fleshed out version of the "RFC" in PR #519, which is a Proof of Concept of this feature)

Changelog

• 2021-09-13 DEFMT_LOG defaults to ERROR log level when unset, which matches RUST_LOG, so there's no divergence between the 2 as it was wrongly indicated in original the RFC text (this behavior was also already implemented and tested in the PoC PR)

---

Summary

• Remove the existing Cargo feature based, target side log filter
• Add an environment variable based, target side log filter (a la env_logger / RUST_LOG)

Rationale

The existing Cargo featured based log filter has several usability issues:

• It requires setting up Cargo features in a library or application (modifying the crate's Cargo.toml) to use it. This is rather unusual in the crate ecosystem. The author is not aware of any other crate that requires this so this is a "minus" in terms of learnability / familiarity.
• The above point leads to Cargo feature proliferation (see Alternatives to Cargo feature proliferation #255), which has been perceived as a downside
• If you add defmt as a dependency, use the log macros in your library but forget to add the Cargo features then the log filtering mechanism will not only not work for you but you will also make it impossible for downstream users to enable / disable the logs that your library has. So in that sense, the feature is error-prone.
• This filter has crate-level granularity: i.e. you cannot select INFO messages from krate::module_a AND ERROR messages from krate::module_b; you can only pick either INFO messages from krate OR ERROR messages from krate. See Controlling logging more granularly than crate-level #459

On the other hand, moving to RUST_LOG-like log filter has the following advantages:

• Familiarity. People that have done Rust development for the desktop have very likely used the env_logger crate, either directly as an integrator of log + env_lolgger or indirectly as an end-user. For instance, probe-run uses env_logger and supports the RUST_LOG env var.
• No extra setup = impossible to misuse = interoperability just works. No Cargo features need to be added to your library, which means it will interoperate with other crates as soon as you use one of the defmt log macros.
• It can filter log messages with module level granularity: i.e. you will be able to select INFO messages from krate::module_a AND ERROR messages from krate::module_b

Detailed design

User-facing interface

The design of the env-var based log filter will closely match env_logger's user-facing API, with the main difference being that defmt will use the DEFMT_LOG env var, instead of RUST_LOG. That way both env vars can be used in a project: e.g. RUST_LOG applies to probe-run tool, DEFMT_LOG applies to the firmware itself.

In terms of features, DEFMT_LOG will expose all of RUST_LOG log level-filtering features. Example below:

$ export DEFMT_LOG=warn,krate::noisy=off,krate::important=trace

When the DEFMT_LOG env var is unset, only ERROR level log messages will be emitted. This behavior matches RUST_LOG's.

DEFMT_LOG will not support RUST_LOG regex filtering as this is better served by a host side display filter in probe-run itself (see knurling-rs/probe-run#74 (comment))

$ # '/' is NOT supported; this is invalid syntax
$ export DEFMT_LOG=krate::haystack/needle

Compile-time, binary-size effect

Unlike RUST_LOG which filters log messages at runtime. DEFMT_LOG will filter log messages at compile time. The upside is that only the messages for the log levels you have chosen will be included in your firmware message: this results in binary size savings compared to env_logger which leaves all the logging code in the image. The downside is that changing the contents of the DEFMT_LOG env var will cause part of your dependency graph to be recompiled; in contrast, changing RUST_LOG does not recompile anything so it's instantaneous.

Library changes

No changes will be made to the API of the defmt library as part of this proposal.

defmt-test

In the current implementation, defmt-test uses defmt::trace! to report progress. With the move to DEFMT_LOG, this will result in no progress being reported because leaving DEFMT_LOG unset disables trace-level log messages.

As part of this proposal, defmt-test will be modified to report its test progress messages with defmt::println! (see #541): these messages cannot be filtered.

Downsides

The switch to DEFMT_LOG is not without downsides: one won't be able to set a default log level for a crate, which was possible to do with the Cargo feature based log filter. That being said, that particular use case could be served by a separate feature: for example, an item-level macro that sets a default log level for the whole crate but that default level can be overridden with DEFMT_LOG, e.g. DEFMT_LOG=krate=off or DEFMT_LOG=krate=error. Sample syntax -- not part of this proposal:

#[cfg(test)]
defmt::default_log_level!(trace);

#[cfg(not(test))]
defmt::default_log_level!(info);

How to teach this

• The 'setup' section of the book will be simplified to not mention Cargo features
• The 'filtering' section of the book will be updated to use DEFMT_LOG
• The 0.2.x -> 0.3.x migration guide will
  • instruct users to remove defmt-* Cargo features
  • tell them about DEFMT_LOG and mention that it has the same syntax as and behaves similarly to RUST_LOG
  • point to the updated 'filtering' section of the book for more details

Alternatives

Co-existence

Instead of removing the Cargo featured based log filter it could be kept and co-exist with DEFMT_LOG. This results in several complications, however:

• it won't solve the Cargo feature proliferation issue
• user documentation will need to elaborate on when to use one over the other and when to use both
• users of 0.3.x may gravitate towards only using DEFMT_LOG and not add defmt-* Cargo features to their libraries, rendering them unusable with the Cargo feature based mechanism

This would have been worthwhile as a transition phase in which DEFMT_LOG is added to v0.2.x and then Cargo features are phased out in 0.3.0 but there are no more 0.2.x releases planned so co-existence in 0.3.x is not worth the trouble in the author's opinion

[japaric]

Updated a mistake of mine in the text (also noted in the changelog section):

DEFMT_LOG defaults to ERROR log level when unset, which matches RUST_LOG, so there's no divergence between the 2 as it was wrongly indicated in original the RFC text (this behavior was also already implemented and tested in the PoC PR)

[japaric]

this was implemented in PR #519