Re: kernel CI: printk loglevels in kernel boot logs?

[Petr Mladek]

On Wed 2017-11-22 20:52:45, Fengguang Wu wrote:
> On Wed, Nov 22, 2017 at 09:38:21PM +0900, Sergey Senozhatsky wrote:
> > On (11/22/17 12:34), Petr Mladek wrote:
> > [..]
> > > > > > This is espeically useful when ingesting kernel logs into advanced
> > > > > > search/analytics frameworks (I'm playing with and ELK stack: Elastic
> > > > > > Search, Logstash, Kibana).
> > [..]
> > > To make it clear. I understand that "show_loglevel" command line argument
> > > would be useful for you. But I am afraid that it is not worth changing
> > > the format. There would need to be wide interest into the change.
> > > Also there would need to be evidence that the existing solutions
> > > (dmesg --raw, console_loglevel) are not enough in many real life
> > > scenarios.
> > 
> > well, I think that that "consoles_format=syslog" command line parameter
> > will be enabled only by those who actually want to have it - Fengguang's
> > build robot and kernelCI (+ may be more setups).  so I'd probably assume
> > there are low risks here. may be I'm wrong.
> 
> Yes, since it needs explicit enabling, local parsers should stay
> working. Unless we send dmesg to other developers, but then they
> might also receive $(dmesg --raw) outputs and need to handle <%u>
> prefixes, too.

I would have agreed with this few days ago. But I am not sure now.

We tried to upstream a feature that allowed to use different clocks
for the printk timestamps. The current one is local clock. Some
people were interested into the real time clock that would allow
to match messages from userspace. Some other users were interested
into boot time clock that would count also the time when the system
is suspended.

We made this configurable (config option + command line option).
I thought that it was safe because local clock stayed default
and the other possibilities would be used just for debugging.

Linus rejected this, see
https://lkml.kernel.org/r/CA+55aFwUfA__6MgMgjENnx+_RYY2ZOOLiSx2ea1AvYhSZN+78A@xxxxxxxxxxxxxx
https://lkml.kernel.org/r/CA+55aFzLH9crdMtUFkD-PtNGuxu_fsG5GH2ACni69ug9iM=09g@xxxxxxxxxxxxxx
https://lkml.kernel.org/r/CA+55aFzzvBD4_WYm-5Bm7TeRGR8nNu1oz0oWNcRNmTNJm=M4Lw@xxxxxxxxxxxxxx


The feature with timestamps was more complicated. The different time
sources had problems on its own. We had troubles to suggest a good
one. Therefore it was wrong to just move the complex decision to
a poor user.

But one thing is similar. Both features change to format/semantic
of the printed lines (extra field for message level vs. semantic
of the timestamp). In case of the timestamps, Linus was aware
o f a clear userspace dependency (systemd expected time since boot).
The question if there is a user space application that depends
on the message format on the consoles. I have no idea. I would
imagine that there are some system monitors that expect
the strings starting with the timestamp.

You might argue that this will get disabled by default. But
the local clock stayed default in the above feature as well.


One thing is that there is CONFIG_PRINTK_TIME and printk.time
command line option. Therefore the format already is kind
of configurable. But I doubt that this is disabled on
any sane system.


Anyway, I would like to wait a bit for the discussion
about the timestamps feature before we add this
console_format stuff. We still need to discuss
how to pass the timestamps to the user and I would
like to hear Linus' opinion there.

You might want to follow/join the discussion around
alternative approach by Thomas Gleixner, see
https://lkml.kernel.org/r/20171115181531.322572387@xxxxxxxxxxxxx
It does not solve the userspace side at the moment.

Best Regards,
Petr