I initially thought to post this to StackOverflow because my interest was primarily from a programming focus, but after reading about the history tag (and the question it linked to), I posted it to softwareengineering.se to get insight on the practical/present-day "software engineering" aspects. The fundamentally historical nature of my question was unavoidable, however, so now it's over here.
I'm currently getting orientated about how logging works on Linux, and am a tad confused about an implementation detail seemingly not covered by RFC 5424 or RFC 3164: the format used to write data to /dev/log.
TL;DR: I'm trying to identify a) what "the /dev/log format" is called, and b) where its semantics are formally specified. I have been unable to identify any RFC or other citable reference for either - only code implementing specific rules without rhyme or reason.
While I initially became interested in the subject while evaluating the pros and cons of syslog() versus other logging strategies (writing to stdout/stderr and/or files; sending to other types of logging servers; etc), at one point I realized I was completely unable to identify how/where "the /dev/log format" fits into the bigger picture. Every single question out there about syslog formats or protocols discusses the RFCs, and completely ignores what rules govern how data leaves syslog() and makes it to the syslog server in the first place.
It's almost like this specific corner of UNIX has disappeared so completely into the woodwork, it's like no longer exists... all while trillions of log messages get written using this "format"(?) every day.
So, this question is an attempt to try to disambiguate this particular detail, simply for the sake of doing so, characterize the format, and identify citable references.
Log lines seem to need to be formatted in a very specific way to be accepted (in my case by systemd-journald - firstly priority/facility information (enclosed in <>), followed by a very specifically-formatted timestamp, what seems to be commonly referred to as a tag, and then the message:
# logger -s hi <13>Mar 5 14:04:11 i336: hi # journalctl -qn1 -o short-iso-precise 2021-03-05T14:04:11.430504+1100 h0nk i336[2505]: hi
# logger -s -t tag hi <13>Mar 5 14:04:37 tag: hi # journalctl -qn1 -o short-iso-precise 2021-03-05T14:04:37.050891+1100 h0nk tag[3151]: hi
# logger -s -t tag -i hi <13>Mar 5 14:04:40 tag[3248]: hi # journalctl -qn1 -o short-iso-precise 2021-03-05T14:04:40.278630+1100 h0nk tag[3248]: hi
(-s causes logger to copy what it sent to stderr; -t tag changes the tag logger uses from my username to whatever name I specify; and -i adds a PID.)
I note that systemd-journald parses and throws away the supplied timestamp and PID (if provided) and determines this information itself (which is why the PID is always present, and why I'm able to ask for milliseconds with short-iso-precise when none was provided):
# echo '<13>Jan 1 00:00:00 test[1234]: hi' | ncat -uU /dev/log # journalctl -qn1 Mar 5 14:06:12 h0nk test[5593]: hi # journalctl -qn1 -o short-iso-precise 2021-03-05T14:06:12.538712+1100 h0nk test[5593]: hi
From a security perspective this makes a lot of sense.
However, I've found that if I even deviate slightly from the format of
<p>Mmm _d HH:MM:SS tagwithnospaces: message
then everything goes sideways very quickly.
It would seem that logger's --rfc5424 and --rfc3164 options are intended exclusively for connecting to syslog servers over UDP or TCP. Using these options when sending data to /dev/log produce disastrous results.
RFC 5424 format (header defined in section 6) blows up right from the get-go:
# logger -s --rfc5424 hi
<13>1 2021-03-05T15:05:04.773304+11:00 h0nk i336 - - [timeQuality tzKnown="1" isSynced="1" syncAccuracy="648500"] hi
# journalctl -qn1 -o short-iso-precise
2021-03-05T15:05:04.773384+1100 h0nk logger[29306]: 1 2021-03-05T15:05:04.773304+11:00 h0nk i336 - - [timeQuality tzKnown="1" isSynced="1" syncAccuracy="648500"] hi
Curiously, while RFC 3164 format (header defined in section 4.1.2) is largely similar to... whatever format logger uses without specifying an RFC option, even the addition of RFC 3164's hostname field is enough to break things:
# logger -s --rfc3164 hi
<13>Mar 5 14:20:51 h0nk i336: hi
# journalctl -qn1 -o short-iso-precise
2021-03-05T14:20:51.638518+1100 h0nk unknown[27148]: h0nk i336: hi
^ O.o
Side-question: I'm guessing the RFC formats preserve the leading <nnn> priority field so that status information ("emergency", "critical", etc) is always transmitted correctly. Is this correct?
The date itself also seems to be a particularly sensitive value. Altering it even slightly instantly causes systemd-journald to regard the whole line as corrupted:
# echo '<13>Jan 1 00:00:00 test[1234]: hi' | ncat -uU /dev/log
^ two spaces
# journalctl -qn1 -o short-iso-precise
2021-03-05T14:17:04.484309+1100 h0nk test[21585]: hi
# echo '<13>Jan 1 00:00:00 test[1234]: hi' | ncat -uU /dev/log
^ one space
# journalctl -qn1 -o short-iso-precise
2021-03-05T14:06:23.414986+1100 h0nk ncat[5877]: Jan 1 00:00:00 test[1234]: hi
Interestingly, BusyBox's syslogd also carefully scrutinizes the date (syslogd.c:829), to the extent of making exact, hard-coded assumptions about where certain characters are:
/* Jan 18 00:11:22 msg... */
/* 01234567890123456 */
if (len >= 16 && msg[3] == ' ' && msg[6] == ' '
&& msg[9] == ':' && msg[12] == ':' && msg[15] == ' '
) {(Busybox syslogd also makes reference to the time being exactly 15 chars long in L286.)
I'm fascinated by why the date seems to need to be specified so very carefully.
I found glibc's implementation of syslog() (syslog.c:223) insightful to study:
it uses the format "
%h %e %T"%h->%b;%b= abbreviated month name according to locale%e= day of month with leading space%T= time like%H:%M:%S- the trailing space after the timestamp matches up (mind-numbingly exactingly) with BusyBox syslogd's
msg[15] == ' 'check (!)
it uses the (glibc-internal?) function
strftime_l(), which (as noted in time.h:101), "take[s] the information from the provided locale and not the global locale";strftime_l()here is passed_nl_C_locobj_ptr(defined in locale.h:17), which is an internal pointer to_nl_C_locobj(defined in xlocale.c:34) an (also-internal) glibc-global reference to C locale definitions.
logger uses different header-formatting functions depending on the mode it's called in: syslog_rfc3164_header(), syslog_rfc5424_header(), and syslog_local_header(). The important part of syslog_local_header() is:
if (ctl->pid)
snprintf(pid, sizeof(pid), "[%d]", ctl->pid);
...
xasprintf(&ctl->hdr, "<%d>%s %s%s: ", ctl->pri, rfc3164_current_time(),
ctl->tag, pid);There's that format again. Priority, time, tag, PID.
rfc3164_current_time() is a wrapper for gettimeofday() and localtime() that bundles a list of abbreviated English month names as a portable alternative to glibc's locale dance.
Given the strong similarity in RFC 3164's date format to the dates used in the "local" "/dev/log format", it makes a lot of sense to reuse the date-formatting function. But significantly, this is the only thing that can be reused, as the "local" format as a whole is still distinct from the RFC 3164 format.
Question: What is the /dev/log format's provenance?
logger's "local" canonicalization is the closest I've been able to come to disambiguating the /dev/log format with a name distinct from the network/RFC formats. I've not found anywhere else that tries to name this distinction, it just uses it.
I've not tested other syslog daemons (like rsyslog, syslog-ng, etc), and I don't know if they accept RFC-formatted lines of text over /dev/log, but given BusyBox's exactness, I wouldn't be surprised if this is some sort of violation...
...but at the same time, what standard or policy would define this behavior as a violation in the first place?
I get the impression this is a standard "by convention", and that explicit ratification has been sidestepped due to the use of exactingly specific parsers in practice.
Is this assumption correct?
NB. I stumbled on this great answer to the question of the significance of the /dev/log file itself, which points out that applications running in chroots might send to a relative /dev/log path. This is a good point, and I use "the /dev/log format" very much for want of the right name to give it.
