decoder: improve default format

[andresovela]

I have updated the default log format to something I consider more sensible. Whether this proposal is the best default or not is of course a very subjective matter.

The main and biggest problem with the current format is the two-line log on the "with location" variant. It introduces a lot of visual noise and it makes it pretty hard to read the logs IMO. It also introduces issues when the user wants to print a multi-line log for whatever reason. In the screenshots below I added an extra line just to emphasize an error, for example. The current version without location is not too bad actually.

The proposed format in this PR introduces the following improvements to the logging experience:

• Single line logs with decent alignment
• Replaces the full path of the log location to just the crate name and the two lowest levels of the file + line number
  • I chose to display the two lowest levels only to keep the location short
  • I feel like two levels is enough to find out where the log comes from
  • Just the filename is useless due to multiple files being called mod.rs in a single crate
• Show the crate name in bold for better visibility and contrast
• Color the entire log for warning and error logs for better visibility
• Got rid of the function name in the location
  • a lot of times this ends up being something not so useful due to async or closures, e.g. my_app::____embassy_main_task::{async_fn#0}

Logs with location before this PR

Logs with location after this PR

Logs without location before this PR

Logs without location after this PR

I hope the proposed format is reasonable. I have no idea why nobody has made an attempt to improve the current one yet, maybe it's not as annoying to others as it is for me. This not only an issue for my own codebases, but generally the default ends up being used as reference material, on blog posts, etc, for example this post on URLO.

Note that the log format continues to be customizable, so if anyone wants to change anything, the option is still there.

Another idea I had was to introduce a new location option that prints just the crate name instead of crate + file name + line number:

I think an option like that would probably be useful for some people as well.

[jonathanpallant]

Can we add in an option to put the logs back like they were? So anyone who doesn't want or like the new format can just add the option and go back to how they were?

[andresovela]

Sure, I can do that later today or tomorrow.

[andresovela]

Added FormatterFormat::Legacy as an option to retain the old format.

[jonathanpallant]

I tried with probe-rs, which just uses the default format.

Before:

$ DEFMT_LOG=debug cargo run --target=thumbv7em-none-eabi --bin levels -- --allow-erase-all
   Compiling defmt-macros v0.3.9
   Compiling defmt v0.3.8
   Compiling panic-probe v0.3.2
   Compiling defmt-rtt v0.4.1
   Compiling project v0.1.0 (/Users/jonathan/Documents/knurling/app-template)
    Finished dev [optimized + debuginfo] target(s) in 0.91s
     Running `probe-rs run --chip nRF52840_xxAA target/thumbv7em-none-eabi/debug/levels --allow-erase-all`
      Erasing ✔ [00:00:00] [#######################################################] 8.00 KiB/8.00 KiB @ 25.22 KiB/s (eta 0s )
  Programming ✔ [00:00:00] [#######################################################] 8.00 KiB/8.00 KiB @ 20.87 KiB/s (eta 0s )    Finished in 0.733s
INFO  info
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:10
WARN  warn
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:12
DEBUG debug
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:13
ERROR error
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:14
<lvl> println
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:15

After:

$ ../probe-rs/target/debug/probe-rs run --chip nRF52840_xxAA target/thumbv7em-none-eabi/debug/levels
     Erasing sectors ✔ [00:00:00] [################################################] 8.00 KiB/8.00 KiB @ 16.26 KiB/s (eta 0s )
 Programming pages   ✔ [00:00:00] [################################################] 8.00 KiB/8.00 KiB @ 11.97 KiB/s (eta 0s )    Finished in 1.221s
[INFO ] levels/bin/levels.rs:15                       info
[WARN ] levels/bin/levels.rs:17                       warn
[DEBUG] levels/bin/levels.rs:18                       debug
[ERROR] levels/bin/levels.rs:19                       error
println
➜  app-template git:(main) ✗

This looks like an improvement to me, but I'll go and ask the probe-rs people whether they consider this a breaking change or if they want to automatically pick it up.

[jonathanpallant]

They seem happy for it to go into 0.3.12, as they are pinned to ==0.3.11 anyway. @Dirbaio said:

I don't think i'd expect the cli output for logging to be stable? so 0.3.x should be okay

[jonathanpallant]

OK, I was testing the wrong version of probe-rs. I edited to correct the output.

The problem with removing the newline is that the location field is of variable length, and because it's now padded to the maximum location length, you get a lot of weird padding in the output for lines from locations that are shorter in length.

[Urhengulas]

I do like the current two line format, but I am honestly fine with any default. @jonathanpallant what is your call?

[jonathanpallant]

After a lot of discussion on the probe.rs matrix chat, we iterated to:

const FORMAT: &str                             = "{[{L}]%bold} {s}";
const FORMAT_WITH_LOCATION: &str               = "{[{L}]%bold} {s} {({c:bold}:{ff}:{l:1})%dimmed}";
const FORMAT_WITH_TIMESTAMP: &str              = "{t} {[{L}]%bold} {s}";
const FORMAT_WITH_TIMESTAMP_AND_LOCATION: &str = "{t} {[{L}]%bold} {s} {({c:bold}:{ff}:{l:1})%dimmed}";

[andresovela]

I pushed the new format :)

[jonathanpallant]

Ah, there's an issue. levels:bin/levels.rs:15 isn't clickable in VS Code. Maybe we should change the first : to a space.

[jonathanpallant]

Perhaps:

const FORMAT: &str = "{[{L}]%bold} {s}";
const FORMAT_WITH_LOC: &str = "{[{L}]%bold} {s} {({c:bold} {fff}:{l:1})%dimmed}";
const FORMAT_WITH_TS: &str = "{t} {[{L}]%bold} {s}";
const FORMAT_WITH_TS_AND_LOC: &str = "{t} {[{L}]%bold} {s} {({c:bold} {fff}:{l:1})%dimmed}";

1. I switched to fff, which gives VS Code enough context to open a file that's not in the current folder, but from a path dependency.
2. I replaced : with a space.
3. I renamed the variables so rustfmt doesn't wrap that last one onto a new line :)

2.00000000 [INFO ] info message was here (levels src/bin/levels.rs:15)
2.00000001 [WARN ] warn message was here (levels src/bin/levels.rs:17)
2.00000002 [DEBUG] debug message was here (levels src/bin/levels.rs:18)
2.00000003 [ERROR] error message was here (levels src/bin/levels.rs:19)
println message was here
2.00000005 [INFO ] info from the lib (test_lib test-lib/src/lib.rs:4)
2.00000006 [WARN ] warn from the lib (test_lib test-lib/src/lib.rs:6)
2.00000007 [DEBUG] debug from the lib (test_lib test-lib/src/lib.rs:7)
2.00000008 [ERROR] error from the lib (test_lib test-lib/src/lib.rs:8)
println from the lib

[andresovela]

I think trying to make the paths clickable is going to be very painful if we don't have the full path there. Sometimes it will work and sometimes it won't. Especially with dependencies from crates.io where the path would be something like:

/home/${USER}/.cargo/registry/src/index.crates.io-6f17d22bba15001f/panic-probe-0.3.1/src/lib.rs:104 

vscode won't be able to figure out anything just with panic_probe panic-probe-0.3.1/src/lib.rs:104 I think. In that case I would say showing panic_probe: src/lib.rs would be just as good.

[andresovela]

In the end it's just about striking a good balance, but I think having stuff work only sometimes is probably bad UX

[jonathanpallant]

In the end it's just about striking a good balance, but I think having stuff work only sometimes is probably bad UX

I see your point, but I don't think I want the full path, because they are so long.

For me src/lib.rs is no more helpful than lib.rs because lib.rs is always in src/. {fff} seemed like a good compromise (foobar/src/lib.rs), and makes the links in my test application broadly work - where VS Code can't unambiguously open the file, it gives me a pretty good list.

[jonathanpallant]

vscode won't be able to figure out anything just with panic_probe panic-probe-0.3.1/src/lib.rs:104 I think.

Unless you have the panic-probe-0.3.1 folder open, or any file in that folder open. Then it works it out.

[andresovela]

I definitely don't want the full path either. I'm fine with anything really, I think the new default would be a pretty good improvement, and it doesn't have to be set in stone forever, we can always adjust in the future if necessary.

[andresovela]

It'd be cool if we somehow could show the full path for files under the binary crate, and only crate: dir/file.rs for other crates.

[Urhengulas]

Make it clickable was one main reason to always show the full path by default, iirc.

Also probe-run did implement path shortening with the --shorten-path option (see https://github.com/knurling-rs/probe-run/blob/b4d99b621fc1de71cb2743fb10e015ff2905915b/src/cli.rs#L99-L101 and https://github.com/knurling-rs/probe-run/blob/b4d99b621fc1de71cb2743fb10e015ff2905915b/src/dep/mod.rs).

Maybe we can see if we can port that code to defmt-decoder or probe-rs?

[Urhengulas]

It'd be cool if we somehow could show the full path for files under the binary crate, and only crate: dir/file.rs for other crates.

Basically that was what --shorten-paths did.

[andresovela]

It sounds like that'd need to be implemented in probe-rs

[Urhengulas]

Here are the PRs that implemented shorten paths. It includes examples.

• https://github.com/knurling-rs/probe-run/pull/203
• https://github.com/knurling-rs/probe-run/pull/209
• https://github.com/knurling-rs/probe-run/pull/210

[jonathanpallant]

We decided to go back to probe-rs and ask if in fact the new log format should be in their repo, instead of being added to the library. We weren't sure if we wanted defmt-decoder to maintain a big list of possible log formats, or if that should be a tool-by-tool decision.

[jonathanpallant]

I added a bunch of comments, and pulled out some common code and put it behind a trait.

This now switches the default back as it was, so it requires probe-rs to implement some command line flags to a) pick a defmt formatting style, and b) show the user the list of possible defmt formatting styles.

Oh, I also rebased.

[andresovela]

Thanks for the help :)

I just wanted to mention that the original intention of this PR was to improve the default format, not to just add another formatting option (for that I could have just used the custom log format option for my own projects - which I already do and will probably continue to do).

[jonathanpallant]

Yeah, and I do appreciate that. It's just that we discussed this internally and we realised that as we have a bunch of users of this library that we don't know much about - people writing custom tools and not using probe-rs - and we weren't comfortable surprising them with a change to the default log format.

I think probe-rs is in a better position to change the defaults, because it's reasonable for binaries to have stronger opinions than libraries about console formatting. With these changes, hopefully that is really easy for them to do.

Edit to add: It is possible we could do a switch of the default in some future semver-breaking-change release.

[Urhengulas]

@andresovela @jonathanpallant Is this good to go?

[andresovela]

I think this was "blocked" on opening a PR on probe-rs to support this, but I've unfortunately changed projects and haven't been working on Rust stuff so I haven't gotten around this.

That said, I'm not sure what's defmt's policy on rolling out this sort of changes.

[jonathanpallant]

The view was expressed that it should be the binary that configures the library, rather than the library changing its default output.

[andresovela]

Yeah I remember. I think this PR is now mostly just code clean up.

[jonathanpallant]

reads

Oh yeah! OK, this is fine then. The default is unchanged - this just cleans it up and adds a second option for anyone who wants it.

[Urhengulas]

This PR contains a breaking change, because FormatterFormat gets a new variant and was not non_exhaustive before. I deem this okay, since defmt-decoder is still unstable at the moment and as far as I can see users of the decoder will pass the FormatterFormat into the decoder and not receive it as a value and pattern-match it.

[jonathanpallant]

I guess as long as probe-rs still builds, it's probably OK.

[Urhengulas]

I guess as long as probe-rs still builds, it's probably OK.

This is the only place they use it and that should be fine since they only construct it: https://github.com/probe-rs/probe-rs/blob/f8bff658f16196c12e888f626ba3618982d4220e/probe-rs-tools/src/bin/probe-rs/util/rtt.rs#L349-L355