printk: support structured and multi-facility log messages

From: Kay Sievers <[email protected]>
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

---
 drivers/base/core.c    |   49 +
 drivers/char/mem.c     |   40 -
 include/linux/printk.h |   13 
 kernel/printk.c        | 1391 +++++++++++++++++++++++++++++++++----------------
 4 files changed, 1024 insertions(+), 469 deletions(-)

@@ -25,6 +25,7 @@
 #include <linux/mutex.h>
 #include <linux/async.h>
 #include <linux/pm_runtime.h>
+#include <linux/netdevice.h>
 
 #include "base.h"
 #include "power/power.h"

@@ -1843,15 +1844,57 @@ void device_shutdown(void)
  */
 
 #ifdef CONFIG_PRINTK
-
 int __dev_printk(const char *level, const struct device *dev,
 		 struct va_format *vaf)
 {
+	char dict[128];
+	size_t dictlen = 0;
+	const char *subsys;
+
 	if (!dev)
 		return printk("%s(NULL device *): %pV", level, vaf);
 
-	return printk("%s%s %s: %pV",
-		      level, dev_driver_string(dev), dev_name(dev), vaf);
+	if (dev->class)
+		subsys = dev->class->name;
+	else if (dev->bus)
+		subsys = dev->bus->name;
+	else
+		subsys = "(NULL subsystem)";
+
+	dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
+			    "SUBSYSTEM=%s\n", subsys);
+
+	/*
+	 * Add device identifier DEVICE=:
+	 *   b12:8         block dev_t
+	 *   c127:3        char dev_t
+	 *   n8            netdev ifindex
+	 *   +sound:card0  subsystem:devname
+	 */
+	if (MAJOR(dev->devt)) {
+		char c;
+
+		if (strcmp(subsys, "block") == 0)
+			c = 'b';
+		else
+			c = 'c';
+		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
+				   "DEVICE=%c%u:%u\n",
+				   c, MAJOR(dev->devt), MINOR(dev->devt));
+	} else if (strcmp(subsys, "net") == 0) {
+		struct net_device *net = to_net_dev(dev);
+
+		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
+				    "DEVICE=n%u\n", net->ifindex);
+	} else {
+		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
+				    "DEVICE=+%s:%s\n", subsys, dev_name(dev));
+	}
+
+	return printk_emit(0, level[1] - '0',
+			   dict, dictlen,
+			   "%s %s: %pV",
+			   dev_driver_string(dev), dev_name(dev), vaf);
 }
 EXPORT_SYMBOL(__dev_printk);
 

@@ -807,44 +807,6 @@ static const struct file_operations oldm
 };
 #endif
 
-static ssize_t kmsg_writev(struct kiocb *iocb, const struct iovec *iv,
-			   unsigned long count, loff_t pos)
-{
-	char *line, *p;
-	int i;
-	ssize_t ret = -EFAULT;
-	size_t len = iov_length(iv, count);
-
-	line = kmalloc(len + 1, GFP_KERNEL);
-	if (line == NULL)
-		return -ENOMEM;
-
-	/*
-	 * copy all vectors into a single string, to ensure we do
-	 * not interleave our log line with other printk calls
-	 */
-	p = line;
-	for (i = 0; i < count; i++) {
-		if (copy_from_user(p, iv[i].iov_base, iv[i].iov_len))
-			goto out;
-		p += iv[i].iov_len;
-	}
-	p[0] = '\0';
-
-	ret = printk("%s", line);
-	/* printk can add a prefix */
-	if (ret > len)
-		ret = len;
-out:
-	kfree(line);
-	return ret;
-}
-
-static const struct file_operations kmsg_fops = {
-	.aio_write = kmsg_writev,
-	.llseek = noop_llseek,
-};
-
 static const struct memdev {
 	const char *name;
 	umode_t mode;

@@ -863,7 +825,7 @@ static const struct memdev {
 	 [7] = { "full", 0666, &full_fops, NULL },
 	 [8] = { "random", 0666, &random_fops, NULL },
 	 [9] = { "urandom", 0666, &urandom_fops, NULL },
-	[11] = { "kmsg", 0, &kmsg_fops, NULL },
+	[11] = { "kmsg", 0644, &kmsg_fops, NULL },
 #ifdef CONFIG_CRASH_DUMP
 	[12] = { "oldmem", 0, &oldmem_fops, NULL },
 #endif

@@ -95,8 +95,19 @@ extern int printk_needs_cpu(int cpu);
 extern void printk_tick(void);
 
 #ifdef CONFIG_PRINTK
+asmlinkage __printf(5, 0)
+int vprintk_emit(int facility, int level,
+		 const char *dict, size_t dictlen,
+		 const char *fmt, va_list args);
+
 asmlinkage __printf(1, 0)
 int vprintk(const char *fmt, va_list args);
+
+asmlinkage __printf(5, 6) __cold
+asmlinkage int printk_emit(int facility, int level,
+			   const char *dict, size_t dictlen,
+			   const char *fmt, ...);
+
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 

@@ -289,6 +300,8 @@ extern void dump_stack(void) __cold;
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+extern const struct file_operations kmsg_fops;
+
 enum {
 	DUMP_PREFIX_NONE,
 	DUMP_PREFIX_ADDRESS,

I like this a lot, thanks for doing this.

Is there somewhere in Documentation/ABI that we can document this interface so that people know what it is, what is defined, and how to use it?

I just noticed that 'tail -f' doesn't seem to work on /dev/kmsg, should it? Or does it need to do something else to get "just the new ones"?

thanks,

greg k-h

It's the notation udev uses to identify its devices internally. I just added the above description to the source code so far. If we agree on that, or some other scheme, we should definitely copy that into the ABI docs. Along with a description of the semantics of the chardev regarding open() poll() and seek().

Yeah, 'tail' might not work, it expects a regular file. This is a chardev and it has not the regular file semantics which 'tail' expects; 'cat' should work fine. 'Real' tools will just use poll() to know when to get new messages out of the file descriptor.

Kay

Ok, that sounds good. I like the description, and implementation, so I have no objections to this patch, I'd be glad to queue it up through my tree to get testing in linux-next now if you want.

Ah, you are right, I forgot about the "real file" stuff with tail, the device node never gets updated with a timestamp.

thanks,

greg k-h

AFAIK tail looks at the file size/timestamp to detect modifications...

Thanks,
//richard

It uses inotify when available, these days.

Kay

[]

How does it do that?

[]

I suggest using lzo on the string portion.

The implementation doesn't show that?

As the used overall size is pretty much the same, that doesn't really seem necessary to me.

thanks,

greg k-h

Not so far as I can tell.

How are arbitrary key/value pairs attached
in a printk?

As dmesg output would still exist, compression could reduce the size of the duplicated logged output buffers significantly.

There are 120 lines in the changelog, and a 100 lines large comment block in the source code, and another 50 lines spread over the code, and the hexdump examples in it, and all that? Even without looking at a single line of code, it should be explained from different viewpoints more than once.

There are no other or duplicated buffers than the primary log buffer, which is exactly the same buffer as today's printk() uses. When this buffer is exported, the data is converted to a stream on-the-fly, and it's a feature, that such stream is human readable and not compressed output. I don't think there is much justification for a compression overhead and the problems it would introduce.

Kay

color me blind - but I could not find any example of how I specify key/value pairs when I use printk().

I could find lots of internal information - that parts looks to be extensively documented - good.

But how I as a user specify this I failed to find. Today I do:

    printk(KERN_ERR "foobar is bad");

But how is that extended to include the key/value pairs?

Sam

The use of structured data is mainly focused on subsystem specific users. Like the block layer or the network stack could invent a bunch of well-defined set of properties, and wrap the emission of these up in some common subsystem logging functions for their drivers to use. They would reflect common log events, meaningful in the context of a specific subsystem.

Think of it more like the model how we handle properties in uevents, it's a similar approach.

This is not so much intended to convert the (almost random) language in slightly better (random) key/value pairs. Userpace, which is the only reason to add that stuff in the first place, will need to know how to make sense out of the passed values, so in the future, we will need some kind of coordination per subsystem here.

For the current simple example in the patch, look where DEVICE= and SUBSYSTEM= are passed through dev_printk() -> vprintk_emit() -> log_store(), and then read through /dev/kmsg.

The output looks like something like this:
http://people.freedesktop.org/~kay/dev-kmsg.txt

Kay

I think this is generally less useful that you do.

I think you should highlight this in the changelog. People _will_ use it that way anyway.

I think you should separate your patch a bit.

Don't call it an extension to printk(), it's hardly that, printk() is a function call that emits stuff. The printk subsystem does a lot more.

perhaps:

changes for printk_emit()
changes for dev_printk
changes for devkmsg_

What do you do about "\n\n" in existing printks?

$ grep -rP --include=*.[ch] '\bprintk\b.*\\n\\n' *

Messages with non-printable characters are exported to the syslog() syscall or /proc/kmsg as they are, like it always was, but the export to /dev/kmsg encodes the MESSAGE= property as a binary property then.

Kay

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

General purpose kernel logging should not depend on _optional_ facilities mainly intended for debugging and profiling. This is stuff that should be used on every box out there, very much much unlike tracing.

I can understand that you propose the trace things, but I'm not convinced that tracing is the same as system logging, or it will ever become it.

Tracing is either duplicating everything in the kmsg buffer, or it will possibly provide dangling pointers into it. Both doesn't sound too convincing. If printk_time is used, you can even store more messages in the same buffer as today.

The added code is less than 100 lines, if you remove the export to /dev/kmsg. We get what we are looking for basically for free, without to mandate any additional subsystem to built into the kernel/.

I doubt we can here talk about "yet another logging"; it is exactly the intention _not _ to have another copy of the same data, like tracing would introduce. This is just an improved version of the good old kmsg buffer without really changing its interface.

Kay

Firstly, you modify printk() and make it less simple and break its ASCII oriented nature - which is my primary objection: if you want to emit binary data then use existing binary logging facilities.

If you want to extend the ASCII output then work in the ASCII, human readable space and improve it.

If you want binary record logging (I'm not convinced printk() should do that, btw. - we are keeping it ASCII for damn good reasons), use perf software events - check your kernel, those are enabled more widely than even CONFIG_PRINTK is enabled - so your whole "but I don't want to rely on a non-generic facility" objection is bogus: perf events, if you decide to use them, are as generic as it gets.

So unless you have better justification for it than what you listed so far, or unless you have a better implementation that either goes into the better binary logging or into the better ASCII logging direction:

Because this one is neither.

Thanks,

Ingo

Much nicer than I was afraid of. Gone are the insane UUID ideas.

However, some concerns remain:

Why has this been explicitly designed to be as ugly as humanly possible, and to be so inconvenient to parse too?

IOW, what's the advantage of the insanity? Especially since PRIORITY, SEQNUM and TIMESTAMP are fundamental, marking them and separating them from each other seems totally pointless. It's ugly for humans, and it's pointlessly harder for automation too, as far as I can tell.

I assume these is some reason for this, but I would want to know what that reason is. The above is hard to use with grep or any of the standard unix line-at-a-time tools, so it seems misdesigned. It looks to be designed for some hacky one-off special parsing tool.

So here's a serious suggestion: aim for "line oriented". And there's a really nice continuation character that people are getting used to, and that is widely used in another line-oriented record message model
- SMTP headers. It's "if the first character on a line is a space, it's a continuation of the previous record".

So if the format was

priority,seqnum,timestamp,message
[ possible continuation for multi-line things, and now only the
continuation-lines are tagged about what they are ]

it would be much more easily greppable etc, it would be more readable, and it would be *easier* to actually parse than that horrible format.

Please also make it very explicit that records have to be "strings". All your examples are strings, all our history is strings, and I want to make it clear that we don't do binary data in this thing.

You made the statement that you want to get away from 30 years of history, but the fact is, "30 years of history" is a damn good argument for "that thing worked".

Strings work. Embedded random binary crap? Not so much.

No "we're going to hide binary UUID's or firmware images here" crap.

I agree with having a length specifier, however, you seem to have some crazy definition where "\n\n" has special meaning.

That's stupid. Don't do it. Make it clear that things are strings, and the only thing that has special meaning is the NUL character. It's true in your examples, and it's just a good idea. But the reason I want to point it out is that from the code and comments, it's clear that you actually still think that "binary is acceptable" is true. It's not true, and it needs to not be true.

So this part looks fine, and we do the key/value pairs for other things:

But again, "opaque" had better still be "text", not random binary blobs. It's how environment variables work, it's how we're used to things, it's just how things work.

So make it opaque extra information, yes, but make sure it's still text.

Because this is just pure and utter *shit*:

Why? No thank you.

This part gets a big NAK from me.

I don't see the point of this. It's pure crap. There's no advantage. And the "use an uint64_t" is a classic case of just being a f*cking moron. There's no way we can *ever* support that kind of sizes for log messages in the kernel anyway. It's not like we can even support 32-bit random blobs. In fact, you use a 16-bit value for the dict-buffer size.

This is the kind of thinking and code that just makes me go "No way, not today, not ever". It's *stupid*.

So make the rule simple:
- it's text.
- it's not binary
- it's not arbitrarily sized
- it doesn't have crazy idiotic 64-bit binary numbers encoded in it.
- '\n\n' isn't special, NUL is. Because that's how we encode things.
If you want to escape something, you escape NUL and special characters using the standard *text* escaping mechanisms, not using some random hodge-podge that you just made up.

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".

Linus

Btw, we could certainly add more support for escaping into vsnprintf() itself.

For example, we already do all those nice helpers for converting different forms of common binary data into ascii: "%pU" for uuid's, '%pS' for symbol addresses etc.

If there really are cases where people want small blobs of data and it would make sense, we could easily do "%.*pQ" for "quoted blob" or whatever, where the precision is obviously the size of the blob (so "%.4pQ" would be a quoted four-byte entity.

We could also extend on the current '%pm', which was really designed for mac-addresses, but the format is actually just a hex sequence. We could extend that too to just take the precision into account, and just default to a six-byte mac address. But we could trivially make "%.16pm" print out a 16-byte hex string instead.

I would also be very open to having some auto-quoting support for '%s': it might even be something we could enable by default. So that if you print out strings that contain special characters (including '\n' etc), we could make sure that vsnprintf() actually quotes them. We don't have to follow the POSIX rules for things, after all.

So I'm very open to making it easier to use ASCII.

I'm *very* closed to making any kernel logging facility use binary data. If you want binary data, go somewhere else. Seriously.

Linus

Now that we're talking vsnprintf helpers... Wouldn't it be nice if those key/value pairs could be used in the message?

const char* kvpairs = "key=value\n";
printk_emit(..., kvpairs, ... "Something went wrong with %{key}s")

... with a saner choice of specifiers, of course.

Stijn

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
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
...

Thanks,
Kay

From: Kay Sievers <[email protected]>
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.

[root@mop ~]# cat /dev/kmsg
5,0,0;Linux version 3.4.0-rc1+ (kay@mop) (gcc version 4.7.0 20120315 ... 6,159,423091;ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) 7,160,424069;pci_root PNP0A03:00: host bridge window [io 0x0000-0x0cf7] (ignored)
SUBSYSTEM=acpi
DEVICE=+acpi:PNP0A03:00
6,339,5140900;NET: Registered protocol family 10 30,340,5690716;udevd[80]: starting version 181
6,341,6081421;FDC 0 is a S82078B
6,345,6154686;microcode: CPU0 sig=0x623, pf=0x0, revision=0x0 7,346,6156968;sr 1:0:0:0: Attached scsi CD-ROM sr0
SUBSYSTEM=scsi
DEVICE=+scsi:1:0:0:0
6,347,6289375;microcode: CPU1 sig=0x623, pf=0x0, revision=0x0

---
 drivers/base/core.c    |   52 +
 drivers/char/mem.c     |   40 -
 include/linux/printk.h |   13 
 kernel/printk.c        | 1333 +++++++++++++++++++++++++++++++++----------------
 4 files changed, 969 insertions(+), 469 deletions(-)

@@ -25,6 +25,7 @@
 #include <linux/mutex.h>
 #include <linux/async.h>
 #include <linux/pm_runtime.h>
+#include <linux/netdevice.h>
 
 #include "base.h"
 #include "power/power.h"

@@ -1843,15 +1844,60 @@ void device_shutdown(void)
  */
 
 #ifdef CONFIG_PRINTK
-
 int __dev_printk(const char *level, const struct device *dev,
 		 struct va_format *vaf)
 {
+	char dict[128];
+	size_t dictlen = 0;
+	const char *subsys;
+
 	if (!dev)
 		return printk("%s(NULL device *): %pV", level, vaf);
 
-	return printk("%s%s %s: %pV",
-		      level, dev_driver_string(dev), dev_name(dev), vaf);
+	if (dev->class)
+		subsys = dev->class->name;
+	else if (dev->bus)
+		subsys = dev->bus->name;
+	else
+		subsys = "(NULL subsystem)";
+
+	dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
+			    "SUBSYSTEM=%s", subsys);
+
+	/*
+	 * Add device identifier DEVICE=:
+	 *   b12:8         block dev_t
+	 *   c127:3        char dev_t
+	 *   n8            netdev ifindex
+	 *   +sound:card0  subsystem:devname
+	 */
+	if (MAJOR(dev->devt)) {
+		char c;
+
+		if (strcmp(subsys, "block") == 0)
+			c = 'b';
+		else
+			c = 'c';
+		dictlen++;
+		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
+				   "DEVICE=%c%u:%u",
+				   c, MAJOR(dev->devt), MINOR(dev->devt));
+	} else if (strcmp(subsys, "net") == 0) {
+		struct net_device *net = to_net_dev(dev);
+
+		dictlen++;
+		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
+				    "DEVICE=n%u", net->ifindex);
+	} else {
+		dictlen++;
+		dictlen += snprintf(dict + dictlen, sizeof(dict) - dictlen,
+				    "DEVICE=+%s:%s", subsys, dev_name(dev));
+	}
+
+	return printk_emit(0, level[1] - '0',
+			   dict, dictlen,
+			   "%s %s: %pV",
+			   dev_driver_string(dev), dev_name(dev), vaf);
 }
 EXPORT_SYMBOL(__dev_printk);
 

@@ -807,44 +807,6 @@ static const struct file_operations oldm
 };
 #endif
 
-static ssize_t kmsg_writev(struct kiocb *iocb, const struct iovec *iv,
-			   unsigned long count, loff_t pos)
-{
-	char *line, *p;
-	int i;
-	ssize_t ret = -EFAULT;
-	size_t len = iov_length(iv, count);
-
-	line = kmalloc(len + 1, GFP_KERNEL);
-	if (line == NULL)
-		return -ENOMEM;
-
-	/*
-	 * copy all vectors into a single string, to ensure we do
-	 * not interleave our log line with other printk calls
-	 */
-	p = line;
-	for (i = 0; i < count; i++) {
-		if (copy_from_user(p, iv[i].iov_base, iv[i].iov_len))
-			goto out;
-		p += iv[i].iov_len;
-	}
-	p[0] = '\0';
-
-	ret = printk("%s", line);
-	/* printk can add a prefix */
-	if (ret > len)
-		ret = len;
-out:
-	kfree(line);
-	return ret;
-}
-
-static const struct file_operations kmsg_fops = {
-	.aio_write = kmsg_writev,
-	.llseek = noop_llseek,
-};
-
 static const struct memdev {
 	const char *name;
 	umode_t mode;

@@ -863,7 +825,7 @@ static const struct memdev {
 	 [7] = { "full", 0666, &full_fops, NULL },
 	 [8] = { "random", 0666, &random_fops, NULL },
 	 [9] = { "urandom", 0666, &urandom_fops, NULL },
-	[11] = { "kmsg", 0, &kmsg_fops, NULL },
+	[11] = { "kmsg", 0644, &kmsg_fops, NULL },
 #ifdef CONFIG_CRASH_DUMP
 	[12] = { "oldmem", 0, &oldmem_fops, NULL },
 #endif

@@ -95,8 +95,19 @@ extern int printk_needs_cpu(int cpu);
 extern void printk_tick(void);
 
 #ifdef CONFIG_PRINTK
+asmlinkage __printf(5, 0)
+int vprintk_emit(int facility, int level,
+		 const char *dict, size_t dictlen,
+		 const char *fmt, va_list args);
+
 asmlinkage __printf(1, 0)
 int vprintk(const char *fmt, va_list args);
+
+asmlinkage __printf(5, 6) __cold
+asmlinkage int printk_emit(int facility, int level,
+			   const char *dict, size_t dictlen,
+			   const char *fmt, ...);
+
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 

@@ -289,6 +300,8 @@ extern void dump_stack(void) __cold;
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+extern const struct file_operations kmsg_fops;
+
 enum {
 	DUMP_PREFIX_NONE,
 	DUMP_PREFIX_ADDRESS,

[]

Not really, why the space between the 6 and the comma?

Bad commit changelog.

It does not extend printk(). printk() is a function call.

It extends the message logging subsystem to include the printk_emit() and vprintk_emit() functions, which can add decidedly not arbitrary key/value pairs, but some additional subsystem specific information.

No, it's not.

An output header simply contains additional structured information. The message portion can still be arbitrary gobbledygook.

I still think this should be 3 patches not 1.

I do agree that that would be lovely. That patch is really hard to read, and it would be helpful if some of it was split up a bit. For example, separating out the "move log buffer to be packetized" (without actually doing the new things) from for the "introduce new interfaces" would be quite nice.

In fact, I think I could merge something that does the packetization early, if it is fairly obvious that it doesn't do anything else. Just making the dmesg ASCII timestamp be something that is a "read buffer" time thing rather than "generate printk" time thing would be nice, and I think the sequence numbers can be useful even with all the old interfaces.

So if somebody wants to help with things like that, and try to turn this into a more gradual thing, I think we could merge at least some initial parts of this patch even for 3.4.

Anybody interested?

Linus

PS looking some more at the patch, it has some more obvious insanities in it. Doing "SUBSYSTEM=(NULL subsystem)" is clearly just insane. If you don't have a subsystem, you shouldn't have that key/value pair - saying you have a NULL subsystem is just crazy. Details like this would possibly stand out a bit more if it wasn't one big patch.

I think it'll be a lot more sensible to integrate this into a more granular printk subsystem so I've just done a move and split up of the printk bits.

kernel/printk.c -> kernel/printk/printk.c and a breakup of printk.c into 4 parts

kernel/printk/log_buf.[ch]
kernel/printk/console.[ch]
kernel/printk/kmsg.[ch]
kernek/printk/printk.c

I think that's a lot more readable/extensible and will make adding a new printk_emit and devkmsg a bit simpler to understand as well.

Maybe it'd be useful to then add some compression to the log_buf message string bits.

I'll submit that move/separate tomorrow but not any compression after a few more compilation tests w/ & w/o the appropriate CONFIG_ options.

Kay would have to respin though.

Here is only the conversion of the byte- to the record-buffer split out of the big patch.

Unfortunately, it's still pretty big, and the patch not easy to read; the code itself looks better than the patch. At this moment I have no convincing idea how to split that into more pieces.

Note: The output of a few continuation lines look wrong with the patch applied. There are two pending patches to add a couple of missing KERN_CONT prefixes for these users.

The crash dump symbol exports, and the printk trace point needs to be checked by people who know how they expect from them, and to adapt to the new buffer type; and if they can possibly make use of the new seqnums to find out if the data behind their pointers which they pass along is still valid when the buffer gets filled behind their back.

Kay

From: Kay Sievers <[email protected]>
Subject: printk: convert byte-buffer to variable-length record buffer

- 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.

---
 drivers/char/mem.c     |   55 +-
 include/linux/printk.h |   11 
 kernel/printk.c        | 1020 ++++++++++++++++++++++++++++---------------------
 3 files changed, 642 insertions(+), 444 deletions(-)

@@ -810,33 +810,54 @@ static const struct file_operations oldm
 static ssize_t kmsg_writev(struct kiocb *iocb, const struct iovec *iv,
 			   unsigned long count, loff_t pos)
 {
-	char *line, *p;
+	char *buf, *line;
 	int i;
-	ssize_t ret = -EFAULT;
+	int level = default_message_loglevel;
+	int facility = 1;	/* LOG_USER */
 	size_t len = iov_length(iv, count);
+	ssize_t ret = len;
 
-	line = kmalloc(len + 1, GFP_KERNEL);
-	if (line == NULL)
+	if (len > 1024)
+		return -EINVAL;
+	buf = kmalloc(len+1, GFP_KERNEL);
+	if (buf == NULL)
 		return -ENOMEM;
 
-	/*
-	 * copy all vectors into a single string, to ensure we do
-	 * not interleave our log line with other printk calls
-	 */
-	p = line;
+	line = buf;
 	for (i = 0; i < count; i++) {
-		if (copy_from_user(p, iv[i].iov_base, iv[i].iov_len))
+		if (copy_from_user(line, iv[i].iov_base, iv[i].iov_len))
 			goto out;
-		p += iv[i].iov_len;
+		line += iv[i].iov_len;
+	}
+
+	/*
+	 * Extract and skip the syslog prefix <[0-9]*>. Coming from userspace
+	 * the decimal value represents 32bit, the lower 3 bit are the log
+	 * level, the rest are the log facility.
+	 *
+	 * If no prefix or no userspace facility is specified, we
+	 * enforce LOG_USER, to be able to reliably distinguish
+	 * kernel-generated messages from userspace-injected ones.
+	 */
+	line = buf;
+	if (line[0] == '<') {
+		char *endp = NULL;
+
+		i = simple_strtoul(line+1, &endp, 10);
+		if (endp && endp[0] == '>') {
+			level = i & 7;
+			if (i >> 3)
+				facility = i >> 3;
+			endp++;
+			len -= endp - line;
+			line = endp;
+		}
 	}
-	p[0] = '\0';
+	line[len] = '\0';
 
-	ret = printk("%s", line);
-	/* printk can add a prefix */
-	if (ret > len)
-		ret = len;
+	printk_emit(facility, level, NULL, 0, "%s", line);
 out:
-	kfree(line);
+	kfree(buf);
 	return ret;
 }
 

@@ -95,8 +95,19 @@ extern int printk_needs_cpu(int cpu);
 extern void printk_tick(void);
 
 #ifdef CONFIG_PRINTK
+asmlinkage __printf(5, 0)
+int vprintk_emit(int facility, int level,
+		 const char *dict, size_t dictlen,
+		 const char *fmt, va_list args);
+
 asmlinkage __printf(1, 0)
 int vprintk(const char *fmt, va_list args);
+
+asmlinkage __printf(5, 6) __cold
+asmlinkage int printk_emit(int facility, int level,
+			   const char *dict, size_t dictlen,
+			   const char *fmt, ...);
+
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 

I'll spend some time on breaking up Kay's patch in the next couple of weeks.

I'll try to get my printk restructuring patch out by Monday.

I think Kay's still relatively large patch can be broken into a sequence of:

1. log_buf record oriented patch only
2. S
what I think is an
intelligible sequence of small concept pieces and submit it end of April. I'll be more or less unavailable until then though.

(grumble, evolution is a stupid email client, resending)

I'll spend some time on breaking up Kay's patch in the next couple of weeks.

I'll try to get my printk restructuring patch out by Monday.

I think Kay's still relatively large patch can be broken into a smaller sequence of:

1. Make log_buf ascii "record" oriented
2. Add struct for timestamp/sequence and integrate it into log_buf with syslog_print
3. Add printk_emit and key/value support into log_buf

After that, I'll try adding lzo compression to the message bits and see if that is any benefit.

After Monday, I'll be effectively unavailable for a few weeks though.

I didn't get it done, and I won't even try to
look at lkml again for a couple of weeks.

If anyone else does, great, otherwise I should
have what I think is an acceptable patch set
shortly after that.

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

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.

One of the questions that hasn't been raised yet, and which I personally consider crucial -- are we making printk() interface part of userspace ABI now by this?

Today, we are free to change any printk()s and not feel guilty about it at all. With this, we are making the whole thing much more systematic and friendly for automatic userspace consumption. Nnot really different to, for example uevents, which I believe everyone considers userspace ABI now.

Do we really want that?

Jiri Kosina
SUSE Labs

I hope not.

It _may_ be that new KEYWORD=VALUE combinations may become systematic and an ABI, but the content of the message is still arbitrary and should be designated as changeable without notice.

And how exactly do we prevent that? It's a systematic and well-defined interface between kernel and userspace, and as such it's hard to not consider it to be ABI.

I bet there would be "you broke my userspace app because it was depending on the printk() you just removed" bugreport coming from someone very soon.

We can then either start explaining why this structured and well-defined printk() is not ABI, or just don't allow for that to happen in the first place by keeping printk() what it has always been -- unstructured linear flow of log entries destined only to be read by humans.

Jiri Kosina
SUSE Labs

I think the commit log is poor.

printk() is effectively unmodified.

Generic helpers like dev_printk() can have an extra bit prepended in the form of device/class/name.

All dev_printk device/class/name does is show what device emitted a message. It doesn't limit the message content. The content of the message after that device/class/name is still arbitrary.

No other use has been proposed, that's why I think it's not all that valuable (yet?).

I do think that printk_emit, which I think is a bad name, ( maybe printk_tva() or printk_desc() ) has some value.

The record oriented change also has value as it can more easily be optionally extended to compress/decompress the text message to save memory space per record. Of course that'd only be valuable when CONFIG_LOG_BUF_SHIFT is large enough to gain something by using compression.