decoder: add support for customizable logger formatting #765

andresovela · 2023-07-15T13:43:49Z

A pain point for me when using defmt is that I can't easily customize the format in which the logs are printed.

This PR replaces the current PrettyLogger with a new StdoutLogger (seemed like a better name to me since the other logger is called JsonLogger), that supports an optional format string. If no format string is provided, a default format is used that looks pretty much the same as the current format, with the exception that the location is not "dimmed".

The formatting options I added are completely arbitrary and not set in stone. I just chose what made sense to me. This is from what I wrote in the docs:

 /// An optional `log_format` string can be provided to format the way
 /// logs are printed. A format string could look as follows:
 /// "{t} [{L}] Location<{f}:{l}> {s}"
 ///
 /// The arguments between curly braces are placeholders for log metadata.
 /// The following arguments are supported:
 /// - {t} : log timestamp
 /// - {f} : file name (e.g. "main.rs")
 /// - {F} : file path (e.g. "home/app/main.rs")
 /// - {m} : module path (e.g. "foo::bar::some_function")
 /// - {l} : line number
 /// - {L} : log level (e.g. "INFO", "DEBUG", etc)
 /// - {s} : the actual log
 ///
 /// For example, with the log format shown above, a log would look like this:
 /// "23124 [INFO] Location<main.rs:23> Hello, world!"

The new format is easily changeable and extendable. Some things that I think could be implemented but I chose not to waste time on before getting community feedback are:

Support for a new formatting option to set/reset colors
Support for escaped curly braces (the parser currently does not support random curly braces in the format string)
Support for field widths (e.g. {t:8} or something like that to specify that the timestamp must be at least 8 characters wide)

This PR is also an alternative to #762 (I think)

Urhengulas · 2023-07-17T11:32:28Z

Thank you for the PR. I am looking into it

Urhengulas

I do like the idea!

Such a mechanism is common practice in many other logging systems, so I don't know why we did not think about it before.

Left a few comments.

decoder/src/log/json_logger.rs

decoder/src/log/stdout_logger.rs

decoder/src/log/format.rs

decoder/src/log/stdout_logger.rs

andresovela · 2023-07-17T18:57:45Z

I made the requested changes and I added an extra host_log_format option. It made sense to implement it after reading some of the issues in probe-run.

decoder/src/log/json_logger.rs

Urhengulas

I played around with the feature and really like it. It gives users all the flexibility they need.

I've noticed a few details which changed with your PR. Some of these changes might be okay, but I wanted to make sure none of them happen accidentally, and some plainly need to be fixed.

Please have a look at these probe-run invocations as context

$ # before PR without timestamp
$ DEFMT_LOG=trace cargo run -q --bin levels
(HOST) INFO  flashing program (2 pages / 8.00 KiB)
(HOST) INFO  success!
────────────────────────────────────────────────────────────────────────────────
INFO  info
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:10
TRACE trace
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:11
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
println
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:15
────────────────────────────────────────────────────────────────────────────────
(HOST) INFO  device halted without error

$ # before PR with timestamp
$ DEFMT_LOG=trace cargo run -q --bin levels
0 INFO  info
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:10
1 TRACE trace
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:11
2 WARN  warn
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:12
3 DEBUG debug
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:13
4 ERROR error
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:14
5 println
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:15

$ # after PR without timestamp
$ DEFMT_LOG=trace cargo run -q --bin levels
(HOST) INFO flashing program (2 pages / 8.00 KiB)
(HOST) INFO success!
────────────────────────────────────────────────────────────────────────────────
 INFO info
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:10
 TRACE trace
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:11
 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
────────────────────────────────────────────────────────────────────────────────
(HOST) INFO device halted without error

$ # after PR with timestamp
$ DEFMT_LOG=trace cargo run -q --bin levels
0 INFO info
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:10
1 TRACE trace
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:11
2 WARN warn
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:12
3 DEBUG debug
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:13
4 ERROR error
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:14
5 <lvl> println
└─ levels::__cortex_m_rt_main @ src/bin/levels.rs:15

timestamp

With your PR and the default format, if there is no timestamp, the first character is a space. Before this was not the case¹, but the log line just started with the log level. This should be fixed.

println

The idea of defmt::println is that the log message is printed without the log level and timestamp. With your PR it emits a <lvl> as log level. This should be fixed.

bold messages

With your PR all messages are bold. Before only log messages were bold, but println and host messages were normal. This is okay if it changes, but I would probably err for making all log messages normal (and the metadata dimmed).

space between timestamp and log message

Before, there were enough spaces between the log level and the log message so the beginning of the log message was aligned. With the PR there is always just one space. I think this is okay if it changes.

Actually there was a similar bug https://github.com/knurling-rs/defmt/issues/602 ↩

decoder/src/log/stdout_logger.rs

andresovela · 2023-07-19T20:05:56Z

With your PR and the default format, if there is no timestamp, the first character is a space. Before this was not the case, but the log line just started with the log level. This should be fixed.

Unless I'm misunderstanding the circumstances under which the timestamp would not be available, I'd argue that the previous behavior is not the right behavior in the context of the new formatting system in this PR.

I'm assuming that a timestamp is not available if the user does not provide a defmt::timestamp!() implementation. If the format specifies that a timestamp should be printed, I think printing 0 illustrates the issue better than just not printing it.

I also just don't see how I can implement the previous behavior nicely in the current system. If the user does not intend to provide a defmt::timestamp!() implementation, I think the right call would be to guide the user to remove the timestamp from the log format.

For example if I want the following format:

T1234 | INFO | Hello

I think it'd be better to print

T0 | INFO | Hello

than

T| INFO | Hello

andresovela · 2023-07-19T20:12:44Z

The idea of defmt::println is that the log message is printed without the log level and timestamp. With your PR it emits a <lvl> as log level. This should be fixed.

I've fixed this. I think I hadn't understood the purpose of that println function before. I actually think that whole thing should be revamped, and we should instead have info_raw!(), debug_raw!(), ... macros, that print logs without formatting but preserve log level information for filtering purposes.

I see the value for a println!() macro that always prints regardless of the configured log level, but I still think these logs should have format. I think this is a subject for future discussion and should be addressed in a future PR if there's a desire for such a thing.

andresovela · 2023-07-19T20:13:46Z

With your PR all messages are bold. Before only log messages were bold, but println and host messages were normal. This is okay if it changes, but I would probably err for making all log messages normal (and the metadata dimmed).

I've fixed this, with the exception of the dimmed metadata. I think further formatting options should be added in future PRs.

andresovela · 2023-07-19T20:18:51Z

Before, there were enough spaces between the log level and the log message so the beginning of the log message was aligned. With the PR there is always just one space. I think this is okay if it changes.

I didn't understand this comment, but I think we should extend the formatting options with a field width specifier in a future PR. I think that would address this in a better way.

Then you could have something like "{L} {f:25} {s}" that would print something like:

INFO main.rs                   Hello, world!
INFO decoder.rs                Decoding...

without the need to special-case everything internally and allowing for better user-customization.

andresovela · 2023-07-20T05:02:36Z

space between timestamp and log message

Ah I see what you mean now, but I don't understand why this is not working. The width specifier is already there. Any ideas?

Urhengulas · 2023-07-24T08:24:04Z

Unless I'm misunderstanding the circumstances under which the timestamp would not be available, I'd argue that the previous behavior is not the right behavior in the context of the new formatting system in this PR.

I'm assuming that a timestamp is not available if the user does not provide a defmt::timestamp!() implementation. If the format specifies that a timestamp should be printed, I think printing 0 illustrates the issue better than just not printing it.

Or we have a <time> default.

I also just don't see how I can implement the previous behavior nicely in the current system. If the user does not intend to provide a defmt::timestamp!() implementation, I think the right call would be to guide the user to remove the timestamp from the log format.

I agree. I am unsure if we easily know if there is a timestamp implementation or not.

Urhengulas · 2023-07-24T08:46:17Z

I am unsure if we easily know if there is a timestamp implementation or not.

It seems that adding a defmt_decoder::Table::has_timestamp() method does the job:

diff --git a/decoder/src/lib.rs b/decoder/src/lib.rs
index cf7fa12..7da00bf 100644
--- a/decoder/src/lib.rs
+++ b/decoder/src/lib.rs
@@ -271,6 +271,10 @@ impl Table {
     pub fn encoding(&self) -> Encoding {
         self.encoding
     }
+
+    pub fn has_timestamp(&self) -> bool {
+        self.timestamp.is_some()
+    }
 }
 
 // NOTE follows `parser::Type`

I tested it with a small project and adding and removing the timestamp implementation.

andresovela · 2023-07-24T10:04:46Z

So what would you like me to do about this?

Urhengulas · 2023-07-25T12:01:07Z

So what would you like me to do about this?

I propose the following:

timestamp implementation	timestamp in log_format	action
yes	yes	just display it
yes	no	just not display it
no	yes	warn that there is no timestamp implementation and that it should be added or the timestamp should be removed from the log_format
no	no	just not display it

Do you agree?

andresovela · 2023-07-25T13:33:44Z

I agree with the warning, but what do I print with the logs in that case? ""? " "? "0"?

andresovela · 2023-07-25T22:15:27Z

I added an info struct to the defmt logger API, and I added the warning in probe-run

Urhengulas · 2023-07-26T09:37:16Z

I agree with the warning, but what do I print with the logs in that case? ""? " "? "0"?

<time>?

andresovela · 2023-07-26T09:52:41Z

Done

ia0 · 2023-08-23T09:00:52Z

My understanding is that with this PR, the println format is hard-coded and it is not possible to add the timestamp as it used to be the case (IIRC). Is this by design or it would be possible to let the user customize the println format too? (like for the log and host log format)

andresovela · 2023-08-28T12:37:06Z

Hi @ia0,

According to @Urhengulas this is by design:

println

The idea of defmt::println is that the log message is printed without the log level and timestamp. With your PR it emits a <lvl> as log level. This should be fixed.

I also argued that a discussion should be had about what we want println to do:

I've fixed this. I think I hadn't understood the purpose of that println function before. I actually think that whole thing should be revamped, and we should instead have info_raw!(), debug_raw!(), ... macros, that print logs without formatting but preserve log level information for filtering purposes.

I see the value for a println!() macro that always prints regardless of the configured log level, but I still think these logs should have format. I think this is a subject for future discussion and should be addressed in a future PR if there's a desire for such a thing.

ia0 · 2023-08-28T12:45:06Z

Thanks for the response! I'm working around by adding the timestamp directly in the println call. However, if the goal is for println to not show any timestamp information, then target timestamp should not be sent for those messages. When I use probe-run --json I can see the target_timestamp field being populated on println calls.

Urhengulas · 2023-08-28T17:12:57Z

Thanks for the response! I'm working around by adding the timestamp directly in the println call. However, if the goal is for println to not show any timestamp information, then target timestamp should not be sent for those messages. When I use probe-run --json I can see the target_timestamp field being populated on println calls.

Hei 👋🏾

I agree that we need to make the logging story more clear, I am gonna put some time into that soon™️

I would be interested why you cannot use the logging macros (e.g. info, debug) if you want the timestamp?

ia0 · 2023-08-28T17:44:48Z

I would be interested why you cannot use the logging macros (e.g. info, debug) if you want the timestamp?

Because that's something I want always printed, regardless of log level.

andresovela mentioned this pull request Jul 15, 2023

Add support for log_format option for defmt_decoder knurling-rs/probe-run#416

Merged

Urhengulas requested changes Jul 17, 2023

View reviewed changes

andresovela requested a review from Urhengulas July 17, 2023 19:06

andresovela added 11 commits July 19, 2023 01:14

Add support for customizable logger formatting

9c61879

print: add support for log_format for decoder

d445bed

Fix CI (fmt, clippy, changelog)

02716c3

cargo fmt

7d65adc

Remove unnecessary Ok(())

3549fad

Handle log format parsing error

11fdfc4

cargo fmt

802f1b8

Remove dbg! in test

ea295e8

Fix wrong comment about module_path

d67d1e5

Apply requested changes

938d34c

Add host_log_format option

0379d13

andresovela force-pushed the customizable-logger branch from 812824d to 0379d13 Compare July 18, 2023 23:16

Urhengulas requested changes Jul 19, 2023

View reviewed changes

decoder/src/log/json_logger.rs Outdated Show resolved Hide resolved

Urhengulas requested changes Jul 19, 2023

View reviewed changes

decoder/src/log/stdout_logger.rs Outdated Show resolved Hide resolved

andresovela added 3 commits July 19, 2023 21:51

Fix defmt::println!() output being printed with formatting

431fb80

Fix printing empty timestamp

a0fca7a

Fix host logs being printed in bold

b28d4ea

andresovela requested a review from Urhengulas July 19, 2023 20:20

Sort log parameters alphabetically in documentation

9769b95

Fix width of level log segments

2f2ff22

cargo fmt

5e142f8

Add DefmtLoggerInfo to provide information about the logger

17c6962

Change timestamp placeholder for when a timestamp is not available

9ddb4cd

Urhengulas approved these changes Aug 1, 2023

View reviewed changes

Update CHANGELOG.md

1696e49

Urhengulas enabled auto-merge August 1, 2023 09:32

Urhengulas added this pull request to the merge queue Aug 1, 2023

Merged via the queue into knurling-rs:main with commit 85c4073 Aug 1, 2023
15 checks passed

andresovela deleted the customizable-logger branch August 1, 2023 09:44

andresovela mentioned this pull request Aug 1, 2023

decoder: add support for color, style, width and alignment to format #769

Merged

whitequark mentioned this pull request Aug 3, 2023

decoder: allow disabling location printing for defmt frames #762

Closed

This was referenced Aug 23, 2023

Add xtask --print-timestamp option for debug::println() in applets google/wasefire#204

Closed

Add option to print timestamp or use a custom format for println #774

Closed

Sympatron mentioned this pull request Feb 7, 2024

Documentation for logger formatting #810

Closed

mhatzl mentioned this pull request Mar 12, 2024

[defmt-test] Not possible to show location of test functions in stdout logger #820

Open

andresovela mentioned this pull request May 31, 2024

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

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

decoder: add support for customizable logger formatting #765

decoder: add support for customizable logger formatting #765

andresovela commented Jul 15, 2023 •

edited

Loading

Urhengulas commented Jul 17, 2023

Urhengulas left a comment

andresovela commented Jul 17, 2023

Urhengulas left a comment

andresovela commented Jul 19, 2023 •

edited

Loading

andresovela commented Jul 19, 2023

andresovela commented Jul 19, 2023 •

edited

Loading

andresovela commented Jul 19, 2023

andresovela commented Jul 20, 2023

Urhengulas commented Jul 24, 2023

Urhengulas commented Jul 24, 2023 •

edited

Loading

andresovela commented Jul 24, 2023

Urhengulas commented Jul 25, 2023

andresovela commented Jul 25, 2023

andresovela commented Jul 25, 2023

Urhengulas commented Jul 26, 2023

andresovela commented Jul 26, 2023

ia0 commented Aug 23, 2023

andresovela commented Aug 28, 2023

println

ia0 commented Aug 28, 2023

Urhengulas commented Aug 28, 2023

ia0 commented Aug 28, 2023

decoder: add support for customizable logger formatting #765

decoder: add support for customizable logger formatting #765

Conversation

andresovela commented Jul 15, 2023 • edited Loading

Urhengulas commented Jul 17, 2023

Urhengulas left a comment

Choose a reason for hiding this comment

andresovela commented Jul 17, 2023

Urhengulas left a comment

Choose a reason for hiding this comment

timestamp

println

bold messages

space between timestamp and log message

Footnotes

andresovela commented Jul 19, 2023 • edited Loading

andresovela commented Jul 19, 2023

andresovela commented Jul 19, 2023 • edited Loading

andresovela commented Jul 19, 2023

andresovela commented Jul 20, 2023

Urhengulas commented Jul 24, 2023

Urhengulas commented Jul 24, 2023 • edited Loading

andresovela commented Jul 24, 2023

Urhengulas commented Jul 25, 2023

andresovela commented Jul 25, 2023

andresovela commented Jul 25, 2023

Urhengulas commented Jul 26, 2023

andresovela commented Jul 26, 2023

ia0 commented Aug 23, 2023

andresovela commented Aug 28, 2023

println

ia0 commented Aug 28, 2023

Urhengulas commented Aug 28, 2023

ia0 commented Aug 28, 2023

andresovela commented Jul 15, 2023 •

edited

Loading

andresovela commented Jul 19, 2023 •

edited

Loading

andresovela commented Jul 19, 2023 •

edited

Loading

Urhengulas commented Jul 24, 2023 •

edited

Loading