defmt::println!() prints a <lvl> prefix

[ia0]

I don't think this used to be the case. Is this a mis-configuration from my part?

I don't have a small repro, but a big repro would be:

git clone https://github.com/google/wasefire.git
cd wasefire
./script/setup.sh
cargo xtask applet rust hello runner nordic --log=debug

which outputs:

DEBUG Runner starts.
└─ runner_nordic::__cortex_m_rt_main @ crates/runner-nordic/src/main.rs:118 
DEBUG Runner is initialized.
└─ runner_nordic::__cortex_m_rt_main @ crates/runner-nordic/src/main.rs:195 
DEBUG Loading applet.
└─ wasefire_scheduler::{impl#6}::run @ crates/scheduler/src/lib.rs:231 
DEBUG Schedule thread init[].
└─ wasefire_scheduler::{impl#6}::call @ crates/scheduler/src/lib.rs:421 
DEBUG Thread is done.
└─ wasefire_scheduler::{impl#6}::process_answer @ crates/scheduler/src/lib.rs:435 
DEBUG Schedule thread main[].
└─ wasefire_scheduler::{impl#6}::call @ crates/scheduler/src/lib.rs:421 
DEBUG Calling Debug(Println(Sig))
└─ wasefire_scheduler::{impl#6}::process_applet @ crates/scheduler/src/lib.rs:408 
<lvl> 0.095169: hello world
└─ wasefire_board_api::debug::Api::println @ crates/board/src/debug.rs:27  
DEBUG Thread is done.
└─ wasefire_scheduler::{impl#6}::process_answer @ crates/scheduler/src/lib.rs:435 

We can see that defmt::debug!() prints DEBUG while defmt::println!() prints <lvl>. In the past, it would look like this (no <lvl> prefix, the line would start with the timestamp, at least as far as I remember):

0.095169: hello world
└─ wasefire_board_api::debug::Api::println @ crates/board/src/debug.rs:27  

[jonathanpallant]

I think this is a probe-rs CLI tool bug. I see it too.

[ia0]

Thanks! I've created https://github.com/probe-rs/probe-rs/issues/2523 to track it there. Feel free to close this issue.

[bugadani]

Hi! I'm responding here because I don't consider this a probe-rs issue, though I can be convinced.

probe-rs uses defmt-decoder to format defmt messages. If a record has no log level (i.e. by using println!()), defmt-decoder prints <lvl>.

The change on probe-rs's part may be that we previously used custom format strings, and changed that to FormatterFormat::Default { ... } (sorry, the links point into the PR's closed-by-default rtt.rs, open that and you'll see the highlights). As far as I can tell, though, the defaults use the same format strings that we used prior to that change.

Let me know if there is a way in probe-rs to disable <lvl> tags without hiding all the useful log levels.

[ia0]

Thanks for the links! I've taken a look at probe-rs and defmt quickly and here is my understanding:

• In the past, probe-rs used to build a format string and call defmt with it.
• Now, probe-rs uses the default defmt format string (unless --log-format is provided).
• The default defmt format string depends on location and timestamp only.

So it looks like my problem is indeed defmt-related. My feature request would be:

• Make InternalFormatter hold 2 format strings: one when there's a level and one when there's not.
• Change FormatterFormat::Custom to take 2 format strings (same semantics as above).
• Duplicate the 4 format constants with FormatterFormat::Default to remove the {L} for the second format string.
• Propagate the change to probe-rs adding a --print-format flag in addition to --log-format (if only one is provided, the other one is equal removing any {L} as needed).

In my particular case, I would probably configure it like so:

• {t} {L} {s}\n└─ {m} @ {F}:{l} when there is a level
• {t} {s} when there's not (because I don't care about the location for println)

If defmt decides to use this as its default (i.e. use only 2 constants without log level, ignoring location), then even better because I won't need to pass flags to probe-rs.

Opinions?

[jonathanpallant]

Ah ... ugh. I appreciate you both digging in to this - I'm travelling today and only have my phone. I'll make a note to look at this Monday.

[ia0]

Have a safe travel! You can read the following on Monday. I just wanted to dump it now while it's fresh in my head.

Here is a commit that uses 2 different formatter depending on whether there is a log-level.

However, I think there might be a better solution: Add support for if-then-else in the formatter syntax. There's already a notion of nested log segments. We could use this to implement the same kind of if-then-else as in zsh prompts. For example, the default constants could change:

• From {L} {s} to {?L:{L} }{s}
• From {t} {L} {s}\n└─ {m} @ {F}:{l} to {t} {?L:{L} }{s}{?L:\n└─ {m} @ {F}:{l}}

We essentially extend the grammar of log segments to something like this:

segment := string
         | '{' meta (':' param)* '}'
         | '{' segment* ('%' param)* '}'
         | '{' '?' cond ':' segment* ('!' segment*)? '}'  // NEW

meta := 'L' | 's' | 't' | ...
param := 'bold' | 'underline' | ...
cond := 'L'  // NEW

The segment '{' '?' cond ':' segment* '}' means that if the condition holds (in the case of L that the log-level is defined), then the nested segments are processed, otherwise the whole condition segment is skipped.

The segment '{' '?' cond ':' segment* '!' segment* '}' is similar, except that if the condition does not hold, then instead of skipping the whole condition segment, the second group of nested segments are processed instead.

[bugadani]

I think simply not printing <lvl> could be a reasonable solution, either by changing {L} (which sounds reasonable considering how people treat <lvl>), or by introducing a new backwards-compatible placeholder for the "maybe-level".

If you allow configuring a different string for print and log, someone might expect per-loglevel configurability, too. Even two is stretching the limit in my opinion, I really wouldn't like to expose two CLI switches just for this in probe-rs(-tools). We have a number of places where we expect a single log string, along with timestamp and location enabling flags. Doubling those won't be ergonomic.

[ia0]

someone might expect per-loglevel configurability

I don't think so. Logging and printing are 2 different use-cases (although it's true that some use printing for debugging which is what logging is for). They happen to benefit from the same optimization that defmt is doing, so are provided by the same crate, but this doesn't mean they should behave the same. In particular, the log crate which is for logging, doesn't provide a println macro. That's also why I don't expect location for println because it's not meant for debugging. The timestamp is a nice feature, but I'm also fine if it's not used. Essentially, defmt::println!() could really just print its input (as with format {s}) without any additional information.

To recap the alternatives:

• Always use {s} for printing (impossible to customize), probably the best option.
• Always use {s} if no timestamp or {t} {s} if timestamp (impossible to customize further), acceptable option.
• Permit customization, probably a bad idea.

[andresovela]

Hi, as the author of the PRs that brought about these changes, I think this is just a bug that was introduced when I refactored the Formatter.

My understanding is that println!() should print without any format.

I had originally added the <lvl> to preserve log alignment when mixing logs with prints, so that the output looks like this

[INFO ] Something using info!()
[<lvl>] Something using println!()
[DEBUG] Something using debug!()

and not like this

[INFO ] Something using info!()
Something using println!()
[DEBUG] Something using debug!()

However it was decided that println!() shouldn't have any format. See https://github.com/knurling-rs/defmt/pull/765#issuecomment-1695624121 for context.

At this point I think I agree that println() should print only what the user is printing. I think adding special formatting only for prints is a bad idea.

[ia0]

Perfect! Thanks a lot for the response and the link. I indeed remembered that I had to add the timestamp myself, but couldn't find the reference. Good to know it's a defmt bug and the behavior will be for println to just print its input regardless of any configuration.

[andresovela]

I'll submit a PR to fix this issue