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

[Ingo Molnar <mingo@kernel.org>]

* Kay Sievers <kay@vrfy.org> wrote:

> From: Kay Sievers <kay@vrfy.org>
>
> Subject: printk: support structured and multi-facility log messages
> 
> Kernel log messages are the primary source of information about the overall
> state of the system and connected devices. Traditional kernel messages are
> mostly human language, targeted at a human reading them. This part of the
> picture works very well since a very long time.
> 
> However, most machines run unattended almost all of their time, and
> software, and not humans, need to process the kernel messages. Having
> a machine making sense out of human language messages is inefficient,
> unreliable, and sometimes plain impossible to get right. With human
> language messages all useful information about their context,
> available at the time of creation of the messages, is just thrown
> away. Later, software consumers of the messages will need to apply
> magic to reconstruct what the context might have been, to be able to
> interpret the messages.
> 
> This patch extends printk() to be able to attach arbitrary key/value
> pairs to logged messages, to carry machine-readable data which
> describes the context of the log message at time of its
> creation. Users of the log can retrieve, along with the human-readable
> message, a key/value dictionary to reliably identify specific devices,
> drivers, subsystems, classes and types of messages.
> 
> Various features of this patch:
> 
> - Record-based stream instead of the traditional byte stream
>   buffer. All records carry a 64 bit timestamp, the syslog facility
>   and priority in the record header.
> 
> - Records consume almost the same amount, sometimes less memory than
>   the traditional byte stream buffer (if printk_time is enabled). The record
>   header is 16 bytes long, plus some padding bytes at the end if needed.
>   The byte-stream buffer needed 3 chars for the syslog prefix, 15 char for
>   the timestamp and a newline.
> 
> - Buffer management is based on message sequence numbers. When records
>   need to be discarded, the reading heads move on to the next full
>   record. Unlike the byte-stream buffer, no old logged lines get
>   truncated or partly overwritten by new ones. Sequence numbers also
>   allow consumers of the log stream to get notified if any message in
>   the stream they are about to read gets discarded during the time
>   of reading.
> 
> - Better buffered IO support for KERN_CONT continuation lines, when printk()
>   is called multiple times for a single line. The use of KERN_CONT is now
>   mandatory to use continuation; a few places in the kernel need trivial fixes
>   here. The buffering could possibly be extended to per-cpu variables to allow
>   better thread-safety for multiple printk() invocations for a single line.
> 
> - Full-featured syslog facility value support. Different facilities
>   can tag their messages. All userspace-injected messages enforce a
>   facility value > 0 now, to be able to reliably distinguish them from
>   the kernel-generated messages. Independent subsystems like a
>   baseband processor running its own firmware, or a kernel-related
>   userspace process can use their own unique facility values. Multiple
>   independent log streams can co-exist that way in the same
>   buffer. All share the same global sequence number counter to ensure
>   proper ordering (and interleaving) and to allow the consumers of the
>   log to reliably correlate the events from different facilities.
> 
> - Output of dev_printk() is reliably machine-readable now. In addition
>   to the printed plain text message, it creates a log dictionary with the
>   following properties:
>     SUBSYSTEM=     - the driver-core subsytem name
>     DEVICE=
>       b12:8        - block dev_t
>       c127:3       - char dev_t
>       n8           - netdev ifindex
>       +sound:card0 - subsystem:devname
> 
> - Support for multiple concurrent readers of /dev/kmsg, with read(),
>   seek(), poll() support. Output of message sequence numbers, to allow
>   userspace log consumers to reliably reconnect and reconstruct their
>   state at any given time. After open("/dev/kmsg"), read() always
>   returns *all* buffered records. If only future messages should be
>   read, SEEK_END can be used. In case records get overwritten while
>   /dev/kmsg is held open, or records get faster overwritten than they
>   are read, the next read() will return -EPIPE and the current reading
>   position gets updated to the next available record. The passed
>   sequence numbers allow the log consumer to calculate the amount of
>   lost messages.
> 
>   $ cat /dev/kmsg
>   PRIORITY=5
>   SEQNUM=0
>   TIMESTAMP=0
>   MESSAGE=Linux version 3.4.0-rc1+ (kay@mop) (gcc version 4.7.0 20120315 ...
> 
>   ...
> 
>   PRIORITY=7
>   SEQNUM=268
>   TIMESTAMP=399682
>   MESSAGE=pci_root PNP0A03:00: host bridge window [io  0x0000-0x0cf7] (ignored)
>   SUBSYSTEM=acpi
>   DEVICE=+acpi:PNP0A03:00
> 
>   ...
> 
>   SYSLOG_FACILITY=3
>   PRIORITY=6
>   SEQNUM=863
>   TIMESTAMP=2479024
>   MESSAGE=udevd[71]: starting version 182
> 
>   ...
> 
>   PRIORITY=6
>   SEQNUM=1012
>   TIMESTAMP=4069447
>   MESSAGE=usb 2-1.4: MAC-Address: 02:80:37:e6:12:00
>   SUBSYSTEM=usb
>   DEVICE=c189:130

Hm, this seems to be a conceptual duplication of the console 
tracepoint that include/trace/events/printk.h already offers.

Have you looked at using that and extending it with a new 
tracepoint and new fields (with log priority level) where 
needed?

If you use it via a perf fd then you'll have structured logging, 
a record formatted ring-buffer, multiple readers support, 
filtering support, etc. - and of course you'll have access to a 
lot more tracepoints as well, should the system logging facility 
decide to log MCE events, etc.

I.e. it will provide (vastly) more capabilities, it would be 
much more extensible - and the patch from you would shrink as 
well, drastically.

IMHO the last thing we need is Yet Another Logging Facility.

Thanks,

	Ingo