Re: [PATCH] printk: support structured and multi-facility log messages

[ebiederm@xmission.com (Eric W. Biederman)]

Kay Sievers <kay@vrfy.org> writes:

> On Thu, 2012-04-05 at 10:09 -0700, Linus Torvalds wrote:
>> On Wed, Apr 4, 2012 at 12:59 PM, Kay Sievers <kay@vrfy.org> wrote:
>> > From: Kay Sievers <kay@vrfy.org>
>> > Subject: printk: support structured and multi-facility log messages
>
>> Other than this issue, I actually don't have any problems with the
>> code. Most of it seems fairly reasonable. But this one just made me go
>> "wtf, how can something so reasonable then be so completely crazy in
>> this regard".
>
> Binary support is just what we are required to support in userspace
> logging. We can surely live without that in the kernel.
>
> What we are looking for is mainly the 'context' of the message, and not
> possible binary data; and that will still be provided the same way with
> the now simpler and more line-based output.
>
> Better?
>
>   [root@mop ~]# cat /dev/kmsg
>   5,0,0;Linux version 3.4.0-rc1+ (kay@mop) (gcc version 4.7.0 20120315 ...
>   6,1,0;Command line: root=/dev/sda1 console=tty0 console=ttyS0
>   6,2,0;BIOS-provided physical RAM map:
>   6,3,0; BIOS-e820: 0000000000000000 - 000000000009f400 (usable)
>   6,4,0; BIOS-e820: 000000000009f400 - 00000000000a0000 (reserved)
>   6,5,0; BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
>   6,6,0; BIOS-e820: 0000000000100000 - 000000001fffd000 (usable)
>   6 ,7,0; BIOS-e820: 000000001fffd000 - 0000000020000000 (reserved)
>   6,8,0; BIOS-e820: 00000000feffc000 - 00000000ff000000 (reserved)
>   6,9,0; BIOS-e820: 00000000fffc0000 - 0000000100000000 (reserved)
>   6,10,0;NX (Execute Disable) protection: active
>   6,11,0;DMI 2.4 present.
>   [...]
>   4,382,6189353;sr0: scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
>   6,383,6190667;cdrom: Uniform CD-ROM driver Revision: 3.20
>   7,384,6193747;sr 1:0:0:0: Attached scsi CD-ROM sr0
>    SUBSYSTEM=scsi
>    DEVICE=+scsi:1:0:0:0

These aren't shell variables we are creating so why put the keys in
uppercase?  All that shouting hurts my eyes.

>   6,385,9202973;EXT4-fs (sda1): re-mounted. Opts: (null)
>   6,386,10929285;Bluetooth: Core ver 2.16
>   6,387,10930852;NET: Registered protocol family 31
>   6,388,10932686;Bluetooth: HCI device and connection manager initialized
>   6,389,10935723;Bluetooth: HCI socket layer initialized
>   6,390,10937847;Bluetooth: L2CAP socket layer initialized
>   ...

So I look at this output I look at how much more bloated my screen feels
as single lines turn into multiple lines and I ask.  Is there any reason
for not encoding structured syslog data the way structured data is
encoded in the syslog rfc RFC5424?  Especially as recently my screens
like to get shorter and wider.

Aka preceding the message with a string like:
[dev subsys="name" dev="major:minor]

aka
[dev subsys="scsi" dev_name="1:0:0:0"] sr 1:0:0:0: Attached scsi CD-ROM sr0

I can see arguments for going different ways but having multiple
sections for different kinds of values seems like a life saver for
long term maintenance.

Wrapping key/value pairs in [] seems compatible with what we are doing
with timestamps already.  So it feels more evolutionary.

Making the printk buffer record oriented might be totally reasonable,
however I have to point out that you can move to RFC5424 style
structured output in printks like dev_printk without changes to
printk at all.

Maybe I am wrong.  Maybe this is all good cleanup.  But it certainly
looks like doing everything the hard way.

>  #ifdef CONFIG_KEXEC
>  /*
> @@ -165,9 +622,9 @@ static int saved_console_loglevel = -1;
>  void log_buf_kexec_setup(void)
>  {
>  	VMCOREINFO_SYMBOL(log_buf);
> -	VMCOREINFO_SYMBOL(log_end);
>  	VMCOREINFO_SYMBOL(log_buf_len);
> -	VMCOREINFO_SYMBOL(logged_chars);
> +	VMCOREINFO_SYMBOL(log_first_idx);
> +	VMCOREINFO_SYMBOL(log_next_idx);
>  }
>  #endif

Is their an accompanying patch to update everyone's crash dump analysis
tools to extract the new format of the syslog ring buffer?

Eric