Things I like about systemd: Logging

2020-04-25

systemd has been around for a while now:

$ grep systemd /var/log/pacman.log | head -n 1
[2012-06-05 17:37] installed systemd-tools (184-2)

Still, I have not made peace with it, yet. I strive for simplicity and minimalism, which often conflicts with systemd and which is also the reason why I keep revisiting this topic. But let’s leave boring issues like “it’s bloated!!1!” aside.

Let’s focus on some good aspects. In this case: Logging.

I want to stress that I’m talking about concepts and ideas here, not necessarily about systemd’s current implementation, which I’m largely not familiar with anyway.

Just use stdout and stderr

Just have your daemon write to stdout and stderr. systemd supports and encourages this. (Docker and Kubernetes do, too. Maybe others, but certainly not SysV init.)

This should be the universal standard, if you ask me.

It makes the daemon itself much simpler. Let the platform take care of collecting your logs. systemd is often being blamed for a “lock-in effect” (rightfully so), but in this case, it actually promotes portability: Even with the most simplistic init system, you can write a short shell script as a wrapper that redirects stdout and stderr to a file, and then you run traditional logrotate.

No more extra code paths to decide whether to call syslog() or, worse, write your own log file. Or even worse than that, link to a special library.

Also makes development easier, because you can just run your program in a terminal and it’ll show its log output.

Last but not least: By capturing stdout and stderr, you get all output. Not just those lines that the program explicitly marked as log output. You also get to see other internal error messages, possibly in situations where the program can’t do anything anymore besides writing to stderr. Or think of additional scripts spawned by a daemon – their output naturally ends up in the journal as well.

Interesting detail about the current implementation: When systemd starts your program, it connects its stdout and stderr to a socket. More specifically, directly to journald. This means you must not stop and then restart journald, or all running services will no longer be able to deliver log messages until they, in turn, are restarted.

This was different with syslog(): It connects to /dev/log afresh and can even fall back to printing on /dev/console if that fails. This was implemented in libc, so it’s nothing that each and every daemon had to reimplement.

systemd “works around” the issue by having the main systemd process (PID 1) manage journald’s socket: It holds an open file descriptor and passes it to the actual journald, should it happen to restart. You can indeed do systemctl restart systemd-journald, daemons will stay connected. This even works if journald crashes or gets killed otherwise. It only fails if you do systemctl stop systemd-journald, because then it releases the active socket.

So, yeah, there’s a trade-off. You replace the retry mechanism from syslog() that was once implemented in libc by additional socket management code in main systemd. I think that’s mostly shifting complexity, not creating new one.

No more bloody logrotate

This is probably trivial, but I still have to mention it.

Thank you for finally ending this.

I’ve been called at night many times, because somewhere some daemon ran amok or got spammed, so the hard drive filled up, logging stopped, and because it was a weird system, there was not even a separate partition for /var/log, so everything stopped.

I just poked journald for a while and tried to get into the same situation. I couldn’t. It does not fill up the hard drive with pointless logs anymore. Not even with rate limiting disabled. It simply deletes old journal archives and frees up space, essentially recycling them.

You can, of course, force the issue by having something else fill up the drive. journald will not magically discard old logs in this situation. Maybe it could be a little more aggressive here, but it’s not an easy choice: Maybe the logs contain that one important debugging hint on why the other thing spammed the disk.

(The situation is a bit different if a normal daemon runs amok and spams the journal massively while something else fills the disk. This will cause journald to recycle archives at a high frequency and, during that operation, it will notice that disk space is getting scarce and reduce its reservation.)

Easy time-based searching

This is great:

journalctl --since='2020-04-15 15:00' --until='2020-04-16 16:00'

Yes, I know how to do that with traditional logging. But don’t tell me it’s not tedious.

And … if you have ever dealt with crappy applications that dump stuff like stack traces in multi-line log entries, you know the pain. Yes, for example OpenBSD’s syslogd simply strips newlines to restore the grep-ability. That’s not bad, but sadly, that can also make the log message really hard to read.

Yes, I consider such applications to be broken. But they’re a reality.

Uniform logging

Do this:

journalctl -u nginx

You get the logs of that unit. This works for all units. No more searching in /var/log, because some clever daemon decided to write to /var/log/foo/main.log … or was it /var/opt/foo/logs/main.log? Oh, no, right! It was /opt/foo/log/main.log. Dang, /opt/foo/log exists but is empty, it was /opt/foo/logs.

Of course, this only works if daemons actually write to stdout/stderr or syslog. If they still write custom logs, then you’re out of luck. But this server right here, for example, is configured to send everything to syslog/journal. Aside from /var/log/pacman.log, there’s nothing but the journal in /var/log.

Unsolved issue: Multiple logs of a single application. Think web server vhosts. In theory, this could be done through syslog tags, as in date | logger -t nginx/uninformativ.de, but I haven’t seen this in the wild.

Future blog posts like this one?

Benno Rice said in his talk The Tragedy of systemd (35:55):

What I would challenge everyone here is: Look at systemd and try to find at least one thing that you like. And then go see if you can implement it.

I like to write and run my own software. I sometimes publish it, but not in an effort to convince other people to use it. (It’s more because I sometimes get asked, “what is that you’re running there?”, and I want to be able to point at a repo.) I’m just a hobbyist and I do it for fun. It’s certainly an intriguing topic, so, yeah, maybe one day I’ll give it a try. Maybe. Just maybe.

Another important point from that talk (20:20), that I’d like to close with:

I think there’s an important distinction to be drawn between “systemd, the implementation” and systemd as a set of ideas.

Comments?