rsyslog: A New Log, and Tools

Please see Learning rsyslog for the introduction and index to this series of blog posts about rsyslog.

The crashes on my local machine leave no trace in the local logs, so I created a new log by writing a Bash script:

/usr/bin/date +%Y-%m-%d.%H%M: >> "${LOGFILE}"
/usr/bin/free >> "${LOGFILE}"

I added a crontab entry as root to run that every five minutes. What this doesn't do is use rsyslog in any way. Does that matter? Initially, no: it works fine, I get my local output. And if all you need is local logging, this is a viable (and probably preferable, given the complexity of rsyslog) solution. However: I'd like to control this output and route it with rsyslog.

Seriously though: if all you need is local logging, be satisfied with solutions like this. It works, and managing it with rsyslog is a world of pain so you'd better have a damn good reason to take the next step (remote logging is likely that reason).

The truth is, I'm not even sure that memory exhaustion is the problem on this machine. But that's what the metrics are for: wait for a crash and see what the log tells us.

If we want to extend this logging to use rsyslog, we have to find the entry points to the system. The primary one seemed to be that rsyslog ingests incoming log entries from sockets. Having learned that, I spent a lot of time struggling with this type of line in /etc/rsyslog.conf:

input(type="imuxsock" Socket="/var/run/log/localsocket" CreatePath="on")

And indeed, I did manage to create a socket. But having done that, you have to tell rsyslog through the configuration what to do with messages received through that channel, and I haven't managed that yet. In digging around to find out about that, I discovered there's a default socket already set up for rsyslog: /dev/log. So I abandoned my effort to create a socket and used that one instead. Creating a socket may yet prove useful, but not as a starting point.

While knowing about /dev/log and understanding its purpose is important, the final tool we'll use (that wraps up all the complexity of accessing rsyslog and its socket(s)) is the command line tool logger. Stick with me, this stuff is worth knowing.

My first reaction was to treat /dev/log like a pipe (a socket isn't the same as a pipe):

$ echo "GO log test 37" > /dev/log
bash: /dev/log: No such device or address
$ ls -l /dev/log
lrwxrwxrwx. 1 root root 28 Sep 26 15:58 /dev/log -> /run/systemd/journal/dev-log
$ ls -l /run/systemd/journal/dev-log
srw-rw-rw-. 1 root root 0 Sep 26 15:58 /run/systemd/journal/dev-log

Despite the initial rejection, the target exists and I do have write permission. The problem is, this isn't how you interact with sockets. If you're not familiar with sockets (and I wasn't), using them is ... well, another complicated Unixy thing you have to figure out. And like all Unixy things, there are a number of old, crufty, powerful tools for dealing with and debugging them. You may see mention of socat, but it's probably overkill. Most systems already have netcat (the binary is nc): it's meant for sending things over a network - but Unix sockets mostly behave like a network socket, so this is our tool. For Debian users you'll probably want to install the "netcat-openbsd" package: the default "netcat" package is actually what they call "netcat-traditional" and it doesn't support one very important command line switch (-U seen below). Fedora has defaulted to the more useful BSD implementation of netcat. I'm going to assume from now on that you have the BSD version installed.

$ echo "GO test 38" | nc --unixsock /dev/log
Ncat: Protocol wrong type for socket.

I have to admit, I still don't understand why that's not sufficient. But you have to be more explicit:

$ echo "GO test 39" | nc --unixsock --udp /dev/log

This returns silently on Fedora, and you'll find you now have a log message in /var/log/messages. Debian is a very, very different story. You have to use short options, so it becomes:

$ echo "GO test 39" | nc.openbsd -U -u /dev/log

Message from syslogd@pib at Oct 24 14:49:40 ...
  test 39

Wow - that's horrible on several levels (and I recommend you don't do it). The biggest problem is that rsyslog has somehow interpreted this as an "emerg" priority (I haven't got to priorities, we'll cover them in the next blog entry) and thus broadcast it to every terminal on the machine (including root's). This kind of thing is usually reserved for restarts and crashes: how a user-sent message could have triggered it, I don't know (well, I do know: the answer is "Debian's settings," but I disagree with them!). Next, it hung my console (doesn't happen on Fedora) until I hit control-C. And how/why is the behaviour on Debian so radically different than Fedora? (Again, "Debian settings.") The message didn't land in /var/log/messages. And finally, a relatively minor piece of news - rsyslog ate the leading "GO" from the message before broadcasting it.

Let's turn to the better tool for this work, logger "GO test 40". This can be run as a user, and returns silently on both Fedora and Debian. Happily the result is the same on both OSes: the full message lands in /var/log/messages. I'm not entirely happy about the idea that any user can spam the messages log at will, but the reality is that this problem would only be significant on a multi-user system with untrusted users - and such systems are vanishingly rare these days. What this means is we have a way to create log messages that are handled by rsyslog. Now we need to filter them - a way to tell rsyslog where different types of messages should go.

'Learning rsyslog' Index