Add verbose defmt output like probe-rs

[dzamlo]

When using probe-rs with defmt We get timing and source info for each print. For example

0.000061 INFO  Hello World!
└─ blinky::____embassy_main_task::{async_fn#0} @ src/bin/blinky.rs:14

For coloring, only the level word (INFO, DEBUG, etc.) is colored. I found it more readable than coloring the whole line.

It would be nice to be able to get the same with espflash.

I think it should not be the default but should be behind a cli flag (-L defmt-verbose for example).

[bugadani]

I intentionally didn't do this originally for subjective reasons but I completely agree that it should be available as a -L option.

[SergioGasquez]

I've been working a bit on this feature, find changes in my branch. Currently, when using -L defmt-verbose:

[WARN] - Hello world!
└─ /home/sergio/Documents/Espressif/tests/defmt/src/main.rs:16
[INFO] - Loop...
└─ /home/sergio/Documents/Espressif/tests/defmt/src/main.rs:18
[INFO] - Loop...
└─ /home/sergio/Documents/Espressif/tests/defmt/src/main.rs:18
[INFO] - Loop...
└─ /home/sergio/Documents/Espressif/tests/defmt/src/main.rs:18

• The color is now only applied to the log level, as you suggested for both defmt and defmt-verbose
• Works with UART and RTT.
• Timestamp and code_location are not yet implemented
  • Is this even possible at the moment? @bugadani

[bugadani]

as you suggested for both defmt

oh but I like my fully colored log lines, they make it easier for me to read 😱 ( I probably got used to the monitor in esp-idf coloring everything but whatever :) )

Is this even possible at the moment?

I don't know, I didn't look into it.

[SergioGasquez]

oh but I like my fully colored log lines, they make it easier for me to read 😱 ( I probably got used to the monitor in esp-idf coloring everything but whatever :) )

TBH, I don't have a hard opinion on this, I may slightly prefer to have only the log level colored but happy to revert the change.

I don't know, I didn't look into it.

I'll take a deeper look at https://defmt.ferrous-systems.com/timestamps/https://defmt.ferrous-systems.com/design-timestamp and https://github.com/probe-rs/probe-rs/blob/master/probe-rs/src/bin/probe-rs/util/rtt.rs#L21-L57 (although our RTT implantation is being reevaluated)

[bugadani]

TBH, I don't have a hard opinion on this, I may slightly prefer to have only the log level colored but happy to revert the change.

There's probably no way to make everyone happy but IIRC the original behavior, i.e. when espflash was displaying colored esp-idf logs was to color everything. Deviating from that may mean inconsistent output based on what's being logged.

My intuition is that printing timestamps shouldn't be very hard and we're just not calling display_timestamp to add it to the output. I'm hoping there shouldn't be any changes necessary to any of the embedded code here, though if the question came up maybe things don't work as I imagine them?

[Vollbrecht]

i also still have an eye on the issue. i think we should go with a different approach here - we should provide 1-2 default sane options here, but for the rest we should follow an approach where the user is in controll

1. a flag that allows for a custom formater provided by the user like its possible here
2. a log level provider so a user can filter out without needing to reflash

[Vollbrecht]

So what i am saying is we maybe shouldn't duplicate the work here and just work with the upstream defmt_decoder::log and potential fix/add things there?

[bugadani]

Ideally we wouldn't duplicate anything but some of espflash's complications (like the address resolving and potentially mixed demft and non-defmt data) may make things a bit more difficult than what it seems at first glance.

[Vollbrecht]

yes i understand this, and probably the simplest way would be to only have this features for the defmt path inside the handle_defmt and not touch defmt_raw.

[SergioGasquez]

My intuition is that printing timestamps shouldn't be very hard and we're just not calling display_timestamp to add it to the output.

I gave it a try, but it was returning None not sure if I was doing something wrong.

[bugadani]

I gave it a try, but it was returning None not sure if I was doing something wrong.

I think it's because we don't output timestamps by default in esp-println/esp-hal. @Vollbrecht's esp-idf implementation does. If defmt allows distinguishing between the two, I'm pretty happy that we don't need to print a bunch of zeroes or require a timestamp for esp-hal based apps.

[Vollbrecht]

if you want this feature in esp-println you just need to implement the defmt timestamp! macro in the same place where the global_logger is impl - for example providing it a way to access the systimer. The rest then should work automagically

[bugadani]

if you want this feature in esp-println you just need to implement the defmt timestamp! macro in the same place where the global_logger is impl - for example providing it a way to access the systimer. The rest then should work automagically

IMO we should leave the option to the users. I don't find timestamps generally useful except for some niche cases.

[Vollbrecht]

yes but the problem is defmt really hates it when there are multiple potential places where it is implemented, so you probably should implement it in the highest crate in the dependancy chain possible, and gate it behind a feature flag

[bugadani]

yes but the problem is defmt really hates it when there are multiple potential places where it is implemented, so you probably should implement it in the highest crate in the dependancy chain possible, and gate it behind a feature flag

It has to work in the user's firmware. Esp-println doesn't depend on esp-hal and reading a timestamp would need more code to be duplicated than what could be called elegant I think.