25 May 2005

Syslog is broken, will someone please fix it?

Update 2010-11-30: Recent Linux systems seem to be settling on rsyslog as syslog implementation of choice. It supports RFC5424 format, which fixes these problems. Just add

$ActionFileDefaultTemplate RSYSLOG_SyslogProtocol23Format

in /etc/rsyslog.conf and you’re done. Original article follows…


Consider the following entries in auth.log:

`Update 2010-11-30: Recent Linux systems seem to be settling on rsyslog as syslog implementation of choice. It supports RFC5424 format, which fixes these problems. Just add

$ActionFileDefaultTemplate RSYSLOG_SyslogProtocol23Format

in /etc/rsyslog.conf and you’re done. Original article follows…


Consider the following entries in auth.log:

`

Quick quiz: How long was paul logged on for?

If you answered “about 10 minutes”, you’re wrong. In fact, the correct answer is “either 10 minutes or 1 hour 10 minutes, there’s no way to tell”.

The problem is that BSD syslog writes its timestamps modified by whatever the local time zone offset is; but unfortunately, it doesn’t bother to record the offset anywhere. At the end of October, the time zone offset changes for most US systems, as daylight saving time ends.

In other words: There are going to be two 01:55s on October 30th, because at 2am the time zone switches and we go back to 01:00. In the example above, we don’t know which 01:55 was the one paul logged in at, so we can’t tell how long he was logged in for.

In the real world, there will often be extra information that will allow us to work out what time the syslog entry must have been written. For example:

``Update 2010-11-30: Recent Linux systems seem to be settling on rsyslog as syslog implementation of choice. It supports RFC5424 format, which fixes these problems. Just add

$ActionFileDefaultTemplate RSYSLOG_SyslogProtocol23Format

in /etc/rsyslog.conf and you’re done. Original article follows…


Consider the following entries in auth.log:

`Update 2010-11-30: Recent Linux systems seem to be settling on rsyslog as syslog implementation of choice. It supports RFC5424 format, which fixes these problems. Just add

$ActionFileDefaultTemplate RSYSLOG_SyslogProtocol23Format

in /etc/rsyslog.conf and you’re done. Original article follows…


Consider the following entries in auth.log:

`

Quick quiz: How long was paul logged on for?

If you answered “about 10 minutes”, you’re wrong. In fact, the correct answer is “either 10 minutes or 1 hour 10 minutes, there’s no way to tell”.

The problem is that BSD syslog writes its timestamps modified by whatever the local time zone offset is; but unfortunately, it doesn’t bother to record the offset anywhere. At the end of October, the time zone offset changes for most US systems, as daylight saving time ends.

In other words: There are going to be two 01:55s on October 30th, because at 2am the time zone switches and we go back to 01:00. In the example above, we don’t know which 01:55 was the one paul logged in at, so we can’t tell how long he was logged in for.

In the real world, there will often be extra information that will allow us to work out what time the syslog entry must have been written. For example:

``

Because there are enough events in this example, we can see the discontinuity in the log, and deduce that the first entry must have been written at the earlier 01:55.

Still, that’s hardly an acceptable approach, especially given that there are many log files where events are expected to occur less often than once an hour. (e.g. failed su attempts!)

Given that syslog is one of the major security tools on every single Unix box worldwide, I find it remarkable that this problem has either been overlooked until now, or has been deemed too unimportant to fix.

Of course, you can set up a central syslog server, and run it under UTC. End of problem, right? Well, not quite–because you still need to worry about the time zone configuration of the clients.

I’ve taken a look at the various syslog implementations out there for Linux, and it appears that every single one of them is broken by default; however, there are three that allow you to configure them to always record the exact time of events.

  1. multilog records timestamps as 64 bit hexadecimal TAI atomic clock timestamps. Admirably precise, but a pain in the ass for humans. Also, it requires that you drink the djb daemontools Kool-Aid, and I’m not ready for that.
  2. rsyslog is a fork of sysklogd. Amongst other things, it adds support for RFC 3339 timestamps, i.e. timestamps in a useful format. Unfortunately, there’s no Debian package yet.
  3. syslog-ng is an allegedly very popular replacement for sysklogd. It is possible to configure it to generate useful timestamps by replacing all the file directives in syslog-ng.conf. You’ll need to change { file( ... ); };

    to something like

    { file( ... template("$ISODATE $FACILITY@$HOST $PRIORITY $MSGn")); };

    everywhere. A pain, but you only have to do it once. Supposedly syslog-ng version 2 has a template system for doing this, but it’s not stable yet (i.e. it’s not even in debian-unstable).

So, there we have it. If you run a Unix box with the time zone set to something other than UTC, chances are it is throwing away information and not always recording the exact time of log events. Take a look and see. If it is, you now know how to fix it.

Related posts

If you liked that post, you might like one of these:

© mathew 2017