Stop logging in local time!

Inertia is a powerful force. The computing world retains a lot of practices that are odd little dysfunctional relics of past stages of its technology. The one I’m here to talk about today looks like this:

Mar 6 15:11:07 snark postfix/qmgr[3927]: 0422513A6C53: removed

That’s a log message hot’n’fresh from my /var/log/mail.log file. It’s entirely typical of traditional log formats on Unix systems, and these things offend the bejeezus out of me every time I see them. Now let me show you how this would look in a sane universe:

2018-03-06T15:11:07Z snark.thyrsus.com postfix/qmgr[3927]: 0422513A6C53: removed

Logging events in local time (and with only local hostnames, but that’s not the subject of today’s rant) is a dysfunctional remnant of the time before wide-area networks. It means that log timestamps aren’t directly comparable across hosts in different time zones. This is death on diagnostics for a large class of network-transaction bugs.

Actually it can mean a lot worse than that, even locally. An A&D regular who wishes to remain nameless recently told me of once having to help troubleshoot a medical-records system at a major hospital. It was unusable – they had to plan around this and retreat to a paper backup system – for two hours a year. Those two hours were just adjacent to daylight-saving-time changes. Yes, that’s right, stamp collisions due to logging in local time crashed their multi-megabuck investment.

Another place logging and displaying in local time is a bad mistake is in distributed version-control systems. I’ve never seen a case in which it was not more important to know the relative time of a sequence of commits than to know the, er, “absolute” local time of any of them. And, of course, committers may be scattered across multiple timezones. Thus, the way to reduce cognitive friction on people browsing the history is to refer all commit timestamps to common timebase.

Yes, git does get this wrong. Git timestamps are stored in UTC but displayed in local time in git log and elsewhere. To accomplish this git has to keep a local time zone offset with each date, a pointless “feature” that often causes me chronic problems too tedious to explain when I do repository conversions.

You know who got this right first? Military and civil aviation. Long before Internet traffic routinely crossed timezones, airplanes did. Requiring pilots and ground controllers to constantly track everybody’s timezones and do conversions on the fly would be confusing and dangerous, so…Zulu time for everybody. Loss-of-life risk is lower where we play (except maybe at that hospital?) but the underlying logic for ditching local time is the same.

EDIT: It has been pointed out to me that radio and telegraph operators faced similar situational stresses as far back as the mid-1800s. It’s not clear, however, how soon GMT became on-air standard time after it was formalized in 1847.

So next time you have to choose a time stamp format, cut the crap and go straight to RFC3339 (with the T in the middle, thank you). It has many advantages. It’s unambiguous, compact, compares correctly no matter where it came from, constant length, sorts lexicographically the same as its time order, and parses out of text as a single token that is easy to distinguish from anything but an RC3339 timestamp (that’s why you want to leave the T in the middle).

(But in case you’re tempted to think about Zulu for all purposes…bad idea. See also In defense of calendrical irregularity.)

And now, to conclude this public-service announcement, a filk I composed for the occasion. Take the tune from this and superimpose these lyrics:

Baby you'll come knockin' on my firewall
Just as I'm dealin' with a system stall
I said yeah, well, what'm I supposed to do?
I don't need no cracker gettin' in too.

NANOG says they have some trouble in town
Now you're shutting some daemons down

Stop logging in...
Stop logging in...
Stop logging in local time.

It's hard to know where the intruders came from
It's hard to know just what we've lost
This doesn't have to be the big net meltdown
This doesn't have to be anything at all.

I know you really want to tell me good-bye
I know you really want to run your own show

Baby you could never look me in the eye
Yeah you buckle with the weight of the words

Stop logging in...
Stop logging in...
Stop logging in local time.

There's people running 'round loose in the world
Ain't got nothing better to do
Than make a meal of some P.F.Y.
You need someone looking after you

I know you really want to tell me good-bye
I know you really want to run your own show

Baby you could never look me in the eye
Yeah you buckle with the weight of the words

Stop logging in...
Stop logging in...
Stop logging in local time.

Stop logging in local time!