logging: Proposals to optimize/minimize logged content

[pfalcon]

So, this was initially intended to be in the vein of #10644 and #10769, i.e. user'esque complaining of random, seemingly ungrounded changes.

Let's however accept that changes can be for good, and try to consider how to take a chance of switching from old to new logging to actually improve logging output, not just change it. Of course, for that we need to define criteria of what would be improvement:

1. Something which doesn't affect usability and user experience too much (maybe only slightly).
2. Something which changes objective characteristics in the desired direction, e.g. saves resources.

Ok, so let's look at the example of old log line (taken from #8187 (comment)):

[slip] [INF] slip_send: sent: pkt 0x20001ec4 llr: 14, len: 54

And new line:

[00:00:00.000,000] <dbg> net_if: init_iface(): (0x00402a00): On iface 0x004208a0

So, what we can see here?

1. Log level is suddenly in small letters with new logging, and suddenly in <xml> form. Actually, this change was the reason behind starting with this ticket. Older all-caps rendering really stand-out well. I even forgot that it had those square brackets around it, because all caps really stand out. Ergo, we don't really need any brackets, just caps! -2 chars
2. As can be seen, previously, we didn't have () at the end of function name in logging. No idea why they suddenly were added now. Yes, with them it's self-describing, and without them, the user would need to learn what that field means - but once (rather easy to remember hopefully). Again, could have -2 chars.
3. Timestamp is definitely good. But square brackers are again supefluous, -2 chars.

So, we could easily save 6 chars per entry-line. I understand those are probably not stored in logging buffer, but sanding them thru UART/whatever still takes extra time, still may wrap line for user which wouldn't be wrapped otherwise.

Examples of lines above with the propose changes:

00:00:00.000,000 INF slip: slip_send: sent: pkt 0x20001ec4 llr: 14, len: 54
00:00:00.000,000 DBG net_if: init_iface: (0x00402a00): On iface 0x004208a0

[pfalcon]

Calling to @carlescufi, @jukkar, @jhedberg, @nashif, and any other interested parties.

Btw, I would easily understand if somebody doesn't like my "improvements". In this case, I'd just humbly call to get back to the older logging format as familiar and well-know ;-). (Well, "XML in the logging output" what concerns me foremost, those <err> really cut on the eye. And no, not in the good way of making logging more visible, but as something foreign, whereas an eye tries to find warm cozy ERR, WRN, INF, DBG ;-) ).

[jukkar]

I am ok with current format, the color coding makes easy to spot errors anyway. One can save the log to file and then search errors, warnings etc anyway if needed. By reading the code, it is actually to my eyes easier to spot things if there are more of these [] or <> there.

In your example like
00:00:00.000,000 INF slip: slip_send: sent: pkt 0x20001ec4 llr: 14, len: 54
it is less clearer to spot the severity than if the line reads
[00:00:00.000,000] <inf> net_if: init_iface(): (0x00402a00): On iface 0x004208a0

The extra () in function name in your example is probably because of commit 6973c6a, so if CONFIG_LOG_FUNCTION_NAME=y, then the function name is added by logging subsystem, otherwise the thing found in net_core.h is used. In this case I added () as there were people asking for that (this can be removed of course and I personally find those () quite useless). The CONFIG_LOG_FUNCTION_NAME will be introduced by #10708 which does not seem to add the () to function name.

[nordic-krch]

Everybody will be biased regarding log output format as we get used to what we use (or we have bad xml memories) so we should find existing format that is accepted by majority or agree on something that is accepted by majority. I don't have strong opinions and 'compressed' proposal looks ok (except that there is a . between module name and function name). I took a liberty of adding | instead of spaces to create columns. What do you think?

00:00:00.000,000|INF|slip.slip_send: sent: pkt 0x20001ec4 llr: 14, len: 54
00:00:00.000,000|DBG|foo.my_foo.foo_prepare: prepare pkt len: 54

[pfalcon]

Everybody will be biased regarding log output format

Well, based on 3 opinions posted here, that's definitely true ;-).

00:00:00.000,000|INF|slip.slip_send

I don't like that, because unlike for @jukkar, for me all those []()<>| is a character noise, distracting from seeing important points, not helping. For me, coming from a space to all-caps is the best way to emphasize the severity field. Those | bars actually makes it harder to see individual fields, turning them into a single one visually, so spaces are important.

(except that there is a . between module name and function name)

Not sure about that either, doesn't give helpful mental model for the C code. Actually, that's another topic for a potential ticket: it's a useful feature assign arbitrary logger name (as seen in the output), but how does it happen that by default everywhere in Zephyr we don't use source file name as that (with extension stripped)? That already caused me 20secs of confusion. The only reason I didn't submit it yet is because I'm not exactly sure how it was in the old logger.

[zephyrbot]

Hi @nordic-krch,

This issue, marked as an Enhancement, was opened a while ago and did not get any traction. Please confirm the issue is correctly assigned and re-assign it otherwise.

Please take a moment to review if the issue is still relevant to the project. If it is, please provide feedback and direction on how to move forward. If it is not, has already been addressed, is a duplicate, or is no longer relevant, please close it with a short comment explaining the reason.

@pfalcon you are also encouraged to help moving this issue forward by providing additional information and confirming this request/issue is still relevant to you.

Thanks!