Re: printk: what is going on with additional newlines?

[Sergey Senozhatsky]

Hello Linus,

On (09/17/17 08:35), Linus Torvalds wrote:
> On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky
> <sergey.senozhatsky@xxxxxxxxx> wrote:
> >
> > so... I think we don't have to update 'struct printk_log'. we can store
> > that "extended data" at the beginning of every message, right after the
> > prefix.
> 
> No, we really can't. That just means that all the tools would have to
> be changed to get the normal messages without the extra crud. And
> since it will have lost the difference, that's not even easy to do.

well, that extra crud is meant to be there only when people explicitly
enable CONFIG_PRINTK_ADD_EXTRA_CRUD_PLEASE. so it's a debugging option.


> So this is exactly the wrong way around.
> 
> If people want to see the extra data, it really should be extra data
> that you can get with a new interface from the kernel logs. Not a
> "let's just a add it to all lines and make every line uglier and
> harder to read.

there is another reason why I think that, yes, we probably better do
it some other way. and the reason is that not every message that looks
like !PREFIX (does not start with KERN_SOH_ASCII) is _actually_ a
!PREFIX message. the normal/usual way is to have something like

	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");

but some messages look like

	printk("%s", KERN_SOH_ASCII %d "foo bar\n");

so we end up having a "normal" message with KERN_SOH_ASCII %d at
offsets 0 and 1 in the resulting text, but only after we do vscnprintf()
in vprintk_emit(). so the proposed _pre-processing_ is complicated.
post-processing -- the one we do in vprintk_emit() -- is still simple.


that's why last night I thought that may be we can do something more
radical - double the number of logbuf lines. IOW, every time we do

	log_store(facility, level, lflags, 0, dict, dictlen, text, text_len)

we also will do

	static char ext_data[...];

	size_t ext_sz = sprintf(ext_data, .....);
	log_store(facility, level, lflags, 0, dict, dictlen, ext_data, ext_sz);

so every message will now have "extra message" before (or after) it. we
do log_store() under logbuf lock, so no other messages should appear
(um, hopefully). every extra message will contain "[extra:" text, so it'll
be possible to filter it out... but, once again, the extra stuff is printed
only when people ask for it.


we are currently looking at
	lkml.kernel.org/r/1504613201-23868-1-git-send-email-prarit@xxxxxxxxxx

which will definitely break some user space tools (well, if enabled in
.config); so I thought that may be that "helpful" timestamp can go as
extra payload.

p.s.
while I'm not entire sold on the whole timestamps in printk help
resolve issues thing. first, printk() can spin on logbuf lock before
it will read the timestamp. second, between
printk()->va_start->vprintk_func->{...this_cpu_read...}->vprintk_emit->logbuf_lock->...

and printk_get_ts() many things can happen - irq, preemption, etc. - so
timestamp that we take under ->logbuf_lock is of somewhat questionable
accurateness.

	-ss