LWN: Comments on "Reimplementing printk()"

Reimplementing printk()

jdel — Wed, 06 Mar 2019 13:10:46 +0000

printk goes straight out serial console ports. journald just taps into a copy of the console data to log it locally.

Reimplementing printk()

jogness — Wed, 06 Mar 2019 10:46:13 +0000

If you can call dmesg, I expect you can read /dev/kmsg as well. Take a look at the output of:

cat /dev/kmsg

The second field is the sequence number. You can read about the format here:

https://www.kernel.org/doc/Documentation/ABI/testing/dev-...

Reimplementing printk()

gravious — Wed, 06 Mar 2019 07:39:18 +0000

The older distros you care about won't have this new printk() stuff backported, surely?

Reimplementing printk()

Cyberax — Thu, 28 Feb 2019 20:34:46 +0000

I get piped dmesg output. I can play with its options but I don't see how I can make it print sequence numbers.

Reimplementing printk()

Cyberax — Wed, 27 Feb 2019 22:15:03 +0000

I'm dreaming about the moment I can do this :( For now there's still RHEL6 and Amazon Linux 1 that I need to support.

Reimplementing printk()

claytonc — Wed, 27 Feb 2019 21:00:56 +0000

Maybe they are on a distro without systemd?

Reimplementing printk()

rweikusat2 — Wed, 27 Feb 2019 20:54:00 +0000

Diagnostic output isn't supposed to be "parsed by software", that's usually just a crude attempt at getting around lack of an interfacen supposed to provided what said software really wants to have. Hence, optimizing the output format to make the crude workaround easier to implement at the expense of making the intended purpose (debugging) more complicated are a bad idea.

There's nothing "controversial" here, just lack of understanding.

Reimplementing printk()

vadim — Wed, 27 Feb 2019 16:44:46 +0000

Why not take advantage of that journald already has the metadata needed to uniquely identify a line?

Reimplementing printk()

jogness — Wed, 27 Feb 2019 11:10:33 +0000

Isn't dmesg just using /dev/kmsg? Or are you using "dmesg -S"?

Print less

LtWorf — Wed, 27 Feb 2019 10:39:18 +0000

Ah, had this discussion with a coworker, who doesn't want to remove the "verbose" from tar in build logs… Which makes build logs 99% the same list of files over and over.

Reimplementing printk()

Cyberax — Wed, 27 Feb 2019 09:45:06 +0000

I can't read /dev/kmsg, it might not be accessible. dmesg is all I can reliably get :(

Reimplementing printk()

jani — Wed, 27 Feb 2019 09:42:45 +0000

> I guess this idea could be as controversial as systemd :-)

That part would be https://lwn.net/Articles/464276/

Reimplementing printk()

NAR — Wed, 27 Feb 2019 09:24:05 +0000

If logs are parsed by software, what about using a more structured log format like logmft? I guess this idea could be as controversial as systemd :-)

Reimplementing printk()

jogness — Wed, 27 Feb 2019 08:49:05 +0000

The point of making emergency messages stand out is exactly for easier automatic processing. From the cover letter:

"Right now the emergency messages are set apart from the non-emergency messages using '\n'. There have been requests that some special markers could be specifiable to make it easier for parsers."

Reimplementing printk()

jogness — Wed, 27 Feb 2019 08:45:12 +0000

You really should be using the sequence number. That is a reliable, monotonically increasing value. (For my proposal as well.) Also, it allows you to identify if messages are missing.

Reimplementing printk()

Cyberax — Wed, 27 Feb 2019 07:06:36 +0000

The application itself is designed to be restartable and I'm using the timestamp to find out unsynchronized logs - I'm just checking the last uploaded log timestamp and then proceed to sync everything that is at or after that timestamp.

Multiple entries with the same timestamp are treated just fine (de-duped), the problem is timestamps going backwards.

I guess I'll have to add more complicated logic to detect unsynchronized messages.

Print less

shemminger — Wed, 27 Feb 2019 06:06:01 +0000

What about silence?
99% of what is in the kernel log is leftovers that some developer was too timid or vain to remove.

Reimplementing printk()

smurf — Wed, 27 Feb 2019 03:40:00 +0000

What does your tool do with boot messages? Today, the first 20 lines or so always end up with a timestamp of zero.

In any case, if I were you I'd add my own timestamp (time when the message was read from the kernel).

Reimplementing printk()

Cyberax — Wed, 27 Feb 2019 01:23:25 +0000

I have a tool that depends on increasing message timestamps (it uses them as a position marker). Would it be possible to add an option to fall back to the previous behavior for timestamps?

Reimplementing printk()

gdt — Wed, 27 Feb 2019 00:43:23 +0000

Options to make messages stand out more tend to be painful when automatically processing log messages. Kernel programmers are humans and want log output tuned for humans, but many more log readers are scripts using some sort of regular expression.