target-side `env_logger`-like env filter #519

japaric · 2021-06-24T16:37:51Z

This PR implements an alternative approach to disabling/enabling logging in crates. Currently we use Cargo features.
This PR removes the need for those Cargo features and replaces them with the env variable: DEFMT_LOG.

The DEFMT_LOG env var specifies which crates should emit defmt logs and at which level. Its syntax is the same as the syntax used by the env_logger crate.

The DEFMT_LOG env var parser currently rejects paths that include modules: so DEFMT_LOG=krate=info is OK, but DEFMT_LOG=krate::module=info is rejected. This is intentional and should let us accept module paths and filter based on modules in the future (as in add module support in a backwards compatible fashion). No longer true, DEFMT_LOG now supports module paths.

One of the main advantages of DEFMT_LOG is that allows filtering logs with module level granularity. The current Cargo features based approach is more coarse grained and only supports enabling / disabling entire crates.

NOTE this is a target side emit filter and orthogonal to the host side display filter proposed in knurling-rs/probe-run#74. Disabling logs with the target filter makes the target program smaller (, maybe also slightly faster) and it reduces the amount of data sent from the target to the host. Disabling logs with the host filter does not change the target program at all not it changes the amount of data transmitted from the target to the host.

Changing the value of the DEFMT_LOG env var causes all crates that transitively depend on the defmt_macros crate to be recompiled.

Example usage:

$ bat src/bin/hello.rs

fn main() -> ! {
    defmt::info!("hello");
    foo::foo();
    bar::bar();
    app::exit()
}

mod foo {
    pub fn foo() {
        defmt::info!("foo");
    }
}

mod bar {
    pub fn bar() {
        defmt::info!("bar");
    }
}

$ DEFMT_LOG=hello::foo cargo r --bin hello
0 INFO  foo
└─ hello::foo::foo @ src/bin/hello.rs:16

$ DEFMT_LOG=hello::bar cargo r --bin hello
0 INFO  bar
└─ hello::bar::bar @ src/bin/hello.rs:22

$ DEFMT_LOG=hello::foo,hello::bar cargo r --bin hello
0 INFO  foo
└─ hello::foo::foo @ src/bin/hello.rs:16
1 INFO  bar
└─ hello::bar::bar @ src/bin/hello.rs:22

$ DEFMT_LOG=hello cargo r --bin hello
0 INFO  hello
└─ hello::__cortex_m_rt_main @ src/bin/hello.rs:8
1 INFO  foo
└─ hello::foo::foo @ src/bin/hello.rs:16
2 INFO  bar
└─ hello::bar::bar @ src/bin/hello.rs:22

$ rg '\[features' Cargo.toml || echo no Cargo features
no Cargo features

how to test this

as this is not even merged into the main branch and breaking changes (with respect to defmt v0.2.0) have landed into defmt, the whole process is quite involved

install a probe-run that uses the decoder in this branch

$ git clone https://github.com/knurling-rs/probe-run
$ cd probe-run
$ # change the `#[dependencies]` section
$ edit Cargo.toml

 colored = "2.0"
-defmt-decoder = { version = "=0.2.2", features = ['unstable'] }
+defmt-decoder = { git = "https://github.com/knurling-rs/defmt", branch = "env-filter", features = ['unstable'] }
 difference = "2.0"

$ cargo install --path .

use [patch.crates-io] in Cargo.toml (the one in the root of the workspace) to use the git version of defmt instead of v0.2.x. The app-template already includes this section in its Cargo.toml

[patch.crates-io]
defmt = { git = "https://github.com/knurling-rs/defmt", branch = "env-filter" }
defmt-rtt = { git = "https://github.com/knurling-rs/defmt", branch = "env-filter" }
defmt-test = { git = "https://github.com/knurling-rs/defmt", branch = "env-filter" }
panic-probe = { git = "https://github.com/knurling-rs/defmt", branch = "env-filter" }

IMPORTANT use branch = "env-filter" instead of rev = "somehash"

set the PROBE_RUN_IGNORE_VERSION env variable before you run your firmware e.g.

$ PROBE_RUN_IGNORE_VERSION=1 cargo run --bin hello

try setting / changing the value of the DEFMT_LOG env variable!

$ export PROBE_RUN_IGNORE_VERSION=1
$ DEFMT_LOG=hello=trace cargo run --bin hello
0 INFO  Hello, world!
└─ hello::__cortex_m_rt_main @ src/bin/hello.rs:8

As there's other breaking-change work currently ongoing (#508) I plan to leave this work on hold for now -- but will be answering to feedback! -- and resume it when that's concluded.

Unresolved questions

rename DEFMT_LOG to DEFMT_CAPTURE or DEFMT_TARGET_CAPTURE? if we keep the DEFMT_LOG name, what should we name the env var to be used in display filter via env variable probe-run#74?

TODO list

RFC approval
address inline TODO comments
support log level without module path e.g. DEFMT_LOG=info
support the off pseudo log-level (disables logging)
fix module path handling so that DEFMT_LOG=krate::module doesn't match krate::module1, krate::module2, etc.
fix CI
documentation. important changes in behavior to note
- default log level is error (when DEFTM_LOG is not set)
- compilation profile (dev / profile) has no effect on the log level filter
- "this removes the ability to set a default log level"

closes #183
closes #255
closes #459

japaric · 2021-06-24T17:14:13Z

macros/src/env_filter.rs

+
+    // TODO unclear if we want the same behavior as `env_logger`
+    #[test]
+    fn when_duplicates_entries_in_defmt_log_use_last_entry() {


actually, now I see that this an override mechanism (from right to left) which is a reasonable thing to have. For example, RUST_LOG=info,krate=trace means: "emit info level logs from all crates, but (override) for the krate emit trace level logs"

japaric · 2021-06-25T11:46:16Z

one big difference between this approach and the current one is that: which profile (dev vs release) is used to compile the code has no effect on the target-side filtering with the env_logger approach. Unsure if that's good or bad but it's different.

$ # see issue description example

$ # defmt 0.2.0
$ cargo r --bin hello
0 ERROR a
1 WARN  b
2 INFO  c
3 DEBUG d
4 TRACE e

$ # defmt 0.2.0
$ cargo r --bin hello --release
0 ERROR a
1 WARN  b
2 INFO  c

$ # this PR
$ cargo r --bin hello
0 ERROR a

$ # this PR
$ cargo r --bin hello --release
0 ERROR a

jonas-schievink · 2021-06-25T22:47:25Z

I think another important thing to note is that this removes the ability to set a default log level. This is potentially useful when writing tests, when you don't want to set the same environment variable all the time. (something like dotenv can work around this, but that seems suboptimal, since it's a third-party tool)

Urhengulas · 2021-06-28T10:34:28Z

@japaric: Looks great! Could you please elaborate how the default levels and following line fit together? I am a bit confused by this 🙈

defmt/macros/src/lib.rs

Line 479 in 688f3eb

let logging_enabled = level >= env_filter.level();

Urhengulas · 2021-06-28T10:36:20Z

I think another important thing to note is that this removes the ability to set a default log level. This is potentially useful when writing tests, when you don't want to set the same environment variable all the time. (something like dotenv can work around this, but that seems suboptimal, since it's a third-party tool)

@jonas-schievink: You mean that one can't set a default for your own crate? Cause afai understand there are still some default levels. Do you see any other use cases where this would be a "problem" (or annoyance), except testing?

jonas-schievink · 2021-06-28T11:55:46Z

Right, there's a fixed default to error messages. Previously you could set default Cargo features to configure any default you like (and when testing it's useful to enable more than just errors, for example the defmt-test progress messages are at info level).

japaric · 2021-06-29T09:52:31Z

Could you please elaborate how the default levels and following line fit together? I am a bit confused by this

that line of code means log at this level or higher "severity". For instance if you set DEFMT_LOG=info you get info, warn and error level logs. If you don't set the env var you get only error level logs. In code, the "severity" in defined in the enum declaration (note the derive(PartialOrd)):

defmt/parser/src/lib.rs

Lines 137 to 144 in fde2aab

    
           #[derive(Clone, Copy, Debug, PartialEq, PartialOrd)] 
        
           pub enum Level { 
        
               Trace, 
        
               Debug, 
        
               Info, 
        
               Warn, 
        
               Error, 
        
           }

So trace < debug < info < warn < error in terms of severity. This is the same as the log crate.

japaric · 2021-06-29T10:06:06Z

I think another important thing to note is that this removes the ability to set a default log level.

good point. I have noted this down in the issue description as a reminder to add it to the documentation.

thinking about the case of testing, in std code one can use the following code as a "setup" for unit tests:

std::env::set_var("RUST_LOG", "my_crate=trace");
env_logger::init();

this is not possible with DEFMT_LOG because the filtering happens at compile time, not runtime.

in the particular case, of testing embedded code the only way to set DEFMT_LOG I can think of is setting it in xtasks. So cargo xtask test target would do DEFMT_LOG=my_crate=trace cargo test -p fw-tests; cargo xtask test host-target could do DEFMT_LOG=my_crate=trace cargo run -p firmware; cargo test -p host-target-tests etc. Using xtasks it's certainly more heavyweight than what one can do today but if you already set up xtask for testing your embedded code then it doesn't seem that much extra work.

Urhengulas · 2021-06-29T10:35:48Z

Could you please elaborate how the default levels and following line fit together? I am a bit confused by this

that line of code means log at this level or higher "severity". For instance if you set DEFMT_LOG=info you get info, warn and error level logs. If you don't set the env var you get only error level logs. In code, the "severity" in defined in the enum declaration (note the derive(PartialOrd)):

defmt/parser/src/lib.rs

Lines 137 to 144 in fde2aab

#[derive(Clone, Copy, Debug, PartialEq, PartialOrd)]

pub enum Level {

Trace,

Debug,

Info,

Warn,

Error,

}

So trace < debug < info < warn < error in terms of severity. This is the same as the log crate.

Okay, I think I got it now:

if you don't mention your crate in DEFMT_LOG you only get error logs
if you just mention it without setting an explicit level you get trace
if you mention it with a level you get this one

Correct? I guess I was mainly confused about the two different defaults.

japaric · 2021-06-29T10:46:27Z

Correct? I guess I was mainly confused about the two different defaults.

yes, that is correct. The "defaults" match the behavior of the env_logger crate. (TBH I didn't know about the trace default when you specify only the crate name nor the off pseudo-level until I started writing tests for this feature and had to read the env_logger docs in more detail though I have used the crate several times before)

japaric · 2021-07-02T15:32:19Z

pushed very WIP module path support. This works:

fn main() -> ! {
    defmt::info!("hello");
    foo::foo();
    bar::bar();
    app::exit()
}

mod foo {
    pub fn foo() {
        defmt::info!("foo");
    }
}

mod bar {
    pub fn bar() {
        defmt::info!("bar");
    }
}

$ DEFMT_LOG=hello::foo cargo r --bin hello
0 INFO  foo
└─ hello::foo::foo @ src/bin/hello.rs:16

$ DEFMT_LOG=hello::bar cargo r --bin hello
0 INFO  bar
└─ hello::bar::bar @ src/bin/hello.rs:22

$ DEFMT_LOG=hello::foo,hello::bar cargo r --bin hello
0 INFO  foo
└─ hello::foo::foo @ src/bin/hello.rs:16
1 INFO  bar
└─ hello::bar::bar @ src/bin/hello.rs:22

$ DEFMT_LOG=hello cargo r --bin hello
0 INFO  hello
└─ hello::__cortex_m_rt_main @ src/bin/hello.rs:8
1 INFO  foo
└─ hello::foo::foo @ src/bin/hello.rs:16
2 INFO  bar
└─ hello::bar::bar @ src/bin/hello.rs:22

japaric · 2021-07-29T11:59:43Z

status update: jonas-schievink pointed out that with this change, the defmt-test test-runner will not print its progress unless the DEFMT_LOG var is set to info, which is a regression in functionality of the default behavior.

To address the issue, I have proposed adding a println! macro that cannot be filtered in RFC #541. This would be used in defmt-test to preserve the progress output. Until a decision is made on that (by accepting it or proposing a different solution) this PR is blocked.

japaric · 2021-09-08T10:23:00Z

Update: I have fleshed out the RFC text in the PR description and moved it to issue #571. This PR is blocked on that RFC being approved and defmt::println! being implemented.

japaric · 2021-09-13T12:27:47Z

update: rebased the PR and addressed inline comments. this is still missing the defmt_test update indicated in the RFC (#571); that update requires println! (PR #569). The other thing that's missing is fixing the snapshot tests, which requires changes to the xtask (setting DEFMT_LOG there)

japaric · 2021-09-30T13:35:44Z

xtask/src/main.rs

@@ -346,9 +346,19 @@ fn test_single_snapshot(
        args.extend_from_slice(&["--features", features]);
    }

+    // matches the behavior of the old Cargo-feature-based log filter
+    // TODO(japaric) the new log filter doesn't depend on the compilation profile so


I plan to do this in a follow-up PR. I want to avoid the churn in this PR.

book/src/SUMMARY.md

Urhengulas

Looks very good.

One question regarding file-structure: Shouldn't macros/src/function_like/log.rs be macros/src/function_like/log/mod.rs? That's the usual structure I know.

(We can also fix this in a follow-up PR, since it seems that other modules in macros also not comply with it)

japaric · 2021-10-04T08:41:09Z

bors r=Urhengulas

bors · 2021-10-04T08:45:44Z

Merge conflict.

implements RFC #571

fixes test-book

japaric · 2021-10-04T09:01:57Z

rebased
bors r=Urhengulas

bors · 2021-10-04T09:08:31Z

Build succeeded:

ci

600: only run snapshot & backcompat tests in dev mode r=jonas-schievink a=japaric the log filter no longer depends on the compilation profile so there's no longer a reason to run these tests in release mode follow up of #519 (comment) Co-authored-by: Jorge Aparicio <jorge.aparicio@ferrous-systems.com>

547: Migration guide `v0.2.x` to `v0.3.0` r=japaric a=Urhengulas Migration guide from `defmt v0.2.x` to version `v0.3.0`. https://deploy-preview-547--admiring-dubinsky-56dff5.netlify.app/migration-02-03.html Fixes #530. ### TODO - [x] #505: Logger trait v2 - [x] #521: [3/n] Remove u24 - [x] #522: Replace `µs` hint with `us` - [x] (no adaption needed) ~~#508: [5/n] Format trait v2~~ - [x] #519: `DEFMT_LOG` - [x] #550: `defmt::flush()` - [x] knurling-rs/probe-run#198, knurling-rs/probe-run#250, Co-authored-by: Johann Hemmann <johann.hemmann@code.berlin>

This was referenced Jun 24, 2021

Alternatives to Cargo feature proliferation #255

Closed

emit filter (target side): mechanism to filter dev and release profiles differently #183

Closed

japaric commented Jun 24, 2021

View reviewed changes

mattico mentioned this pull request Jun 24, 2021

Using defmt to trace function execution #520

Open

japaric mentioned this pull request Jul 2, 2021

Controlling logging more granularly than crate-level #459

Closed

Urhengulas added the status: blocked Blocked on another issue, or on upstream libraries label Jul 7, 2021

japaric force-pushed the env-filter branch from a189eeb to f48f35b Compare July 9, 2021 11:11

This was referenced Jul 15, 2021

display filter via env variable knurling-rs/probe-run#74

Open

[RFC] defmt::println! #541

Closed

[RFC] defmt-test: env-var based test filter #544

Open

Urhengulas mentioned this pull request Jul 21, 2021

Migration guide v0.2.x to v0.3.0 #547

Merged

7 tasks

japaric added this to the v0.3.0 milestone Jul 29, 2021

Lotterleben assigned japaric Sep 6, 2021

japaric mentioned this pull request Sep 8, 2021

[RFC] environment variable based, target side log filter #571

Closed

japaric force-pushed the env-filter branch from 4b6b0a9 to 9bc7649 Compare September 13, 2021 12:23

japaric mentioned this pull request Sep 23, 2021

unused _defmt symbols are kept by the linker #588

Open

japaric force-pushed the env-filter branch from bbf6222 to f73b593 Compare September 30, 2021 13:07

japaric marked this pull request as ready for review September 30, 2021 13:35

japaric commented Sep 30, 2021

View reviewed changes

japaric changed the title ~~[RFC] [PoC] target-side env_logger-like env filter~~ target-side env_logger-like env filter Sep 30, 2021

japaric removed their assignment Sep 30, 2021

Urhengulas reviewed Sep 30, 2021

View reviewed changes

book/src/SUMMARY.md Show resolved Hide resolved

Urhengulas approved these changes Oct 1, 2021

View reviewed changes

japaric removed the status: blocked Blocked on another issue, or on upstream libraries label Oct 4, 2021

japaric added 9 commits October 4, 2021 10:56

environment variable based, target side log filter

09c71b6

implements RFC #571

use proc-macro-error

e7e62ae

improve error messages

5b4361b

update book

1c3dfd8

set DEFMT_LOG in test-snapshot

afdb56c

make should-panic unit tests pass again

0813c64

xtask: set CARGO_CRATE_NAME when invoking mdbook

4303c0f

fixes test-book

add a follow-up cleanup TODO comment

6ec5121

book: rm unlinked file

9ad3fc1

japaric force-pushed the env-filter branch from 4c8c636 to 9ad3fc1 Compare October 4, 2021 09:01

bors bot merged commit 0009d50 into main Oct 4, 2021

bors bot deleted the env-filter branch October 4, 2021 09:08

japaric mentioned this pull request Oct 5, 2021

only run snapshot & backcompat tests in dev mode #600

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

target-side `env_logger`-like env filter #519

target-side `env_logger`-like env filter #519

japaric commented Jun 24, 2021 •

edited

Loading

japaric Jun 24, 2021

japaric commented Jun 25, 2021

jonas-schievink commented Jun 25, 2021

Urhengulas commented Jun 28, 2021 •

edited

Loading

Urhengulas commented Jun 28, 2021 •

edited

Loading

jonas-schievink commented Jun 28, 2021

japaric commented Jun 29, 2021

japaric commented Jun 29, 2021

Urhengulas commented Jun 29, 2021

japaric commented Jun 29, 2021

japaric commented Jul 2, 2021

japaric commented Jul 29, 2021

japaric commented Sep 8, 2021

japaric commented Sep 13, 2021

japaric Sep 30, 2021 •

edited

Loading

Urhengulas left a comment

japaric commented Oct 4, 2021

bors bot commented Oct 4, 2021

japaric commented Oct 4, 2021

bors bot commented Oct 4, 2021

target-side env_logger-like env filter #519

target-side env_logger-like env filter #519

Conversation

japaric commented Jun 24, 2021 • edited Loading

how to test this

Unresolved questions

TODO list

japaric Jun 24, 2021

Choose a reason for hiding this comment

japaric commented Jun 25, 2021

jonas-schievink commented Jun 25, 2021

Urhengulas commented Jun 28, 2021 • edited Loading

Urhengulas commented Jun 28, 2021 • edited Loading

jonas-schievink commented Jun 28, 2021

japaric commented Jun 29, 2021

japaric commented Jun 29, 2021

Urhengulas commented Jun 29, 2021

japaric commented Jun 29, 2021

japaric commented Jul 2, 2021

japaric commented Jul 29, 2021

japaric commented Sep 8, 2021

japaric commented Sep 13, 2021

japaric Sep 30, 2021 • edited Loading

Choose a reason for hiding this comment

Urhengulas left a comment

Choose a reason for hiding this comment

japaric commented Oct 4, 2021

bors bot commented Oct 4, 2021

japaric commented Oct 4, 2021

bors bot commented Oct 4, 2021

target-side `env_logger`-like env filter #519

target-side `env_logger`-like env filter #519

japaric commented Jun 24, 2021 •

edited

Loading

Urhengulas commented Jun 28, 2021 •

edited

Loading

Urhengulas commented Jun 28, 2021 •

edited

Loading

japaric Sep 30, 2021 •

edited

Loading