loggingsystemdnamed-pipesmkfifo

Adding timestamps via named pipes or rsyslog to the log output of a systemd-managed service


I'm having to deal with a proprietary legacy service (running on Debian 10) that logs various (roughly) INFO and NOTICE level things things into stdout, and (roughly) WARNING and ERROR level things into stderr. Both can be written to files using the --stdout <path> and --stderr <path> command line parameters. Our systemd unit file for this daemon looks like this (pruned down to the bare essentials):

[Unit]
Description=Some legacy proprietary thing
After=network.target

[Service]
ExecStart=/usr/local/bin/thing \
  --stdout /var/log/thing/stdout.log \
  --stderr /var/log/thing/stderr.log

[Install]
WantedBy=multi-user.target

The problem is that the lines written to stdout.log and stderr.log do not contain timestamps, which we now need. The application is a black box to us, and modifying its logging output to include timestamps is not feasible.

In my research, I've come across two options that might work here. If you have others, I'd be keen to hear them.

OPTION 1

Create named pipes with mkfifo for both stdout and stderr, and make the legacy application use those as the --stdout and --stderr targets. Then, set up a process to read those pipes, piping each line to the ts command, which adds a nice timestamp, like this:

$ echo foo | ts '[%Y-%m-%d %H.%M.%.S]'
[2021-08-10 16.16.21.506571] foo

It is these timestamped lines that would then get written to log files, one for stdout and one for stderr, probably via piping.

OPTION 2

In the systemd unit file, we might be able to set StandardOutput and StandardError to syslog, and then set SyslogIdentifier to some string that we could use with rsyslog, adding a timestamp and writing the final row out to a log file.

Unfortunately, I haven't found a way to make systemd distinguish stdout and stderr: they would both just be sent to rsyslog without any information about which one was the origin. (I'm aware of SyslogLevelPrefix, but that requires the incoming log messages from our black box application to contain sd-daemon(3) style prefixes, and this is currently not feasible.)

DETAILS

Due to the problems inherent with option 2, I'll discuss option 1 further. If you know of a workaround to the syslog approach, do share nonetheless.

So, named pipes are great, but I don't know how to implement them in a systemd unit file. I imagine I'll have to have two separate reader processes, one for the stdout pipe and one for the stderr pipe, and therefore two new unit files. Some further notes:

With the writer process having the parameters --stdout /path/to/outfifo --stderr /path/to/errfifo, the reader processes could, in theory, be as simple as this:

cat /path/to/outfifo | ts '[%Y-%m-%d %H.%M.%.S]' > /var/log/thing/stdout_ts.log
cat /path/to/errfifo | ts '[%Y-%m-%d %H.%M.%.S]' > /var/log/thing/stderr_ts.log

Add to that a logrotate rule with copytruncate, and we're golden! Except I don't know how to do this in a systemd unit file, while satisfying the above restartability requirements.

If you can help with the unit file construction, or suggest an alternative approach, I'd be grateful.


Solution

  • journald can add timestamps, etc. for you.

    A simple solution would be to use systemd-cat:

    ExecStart=/bin/systemd-cat \
      --priority=info \
      --stderr-priority=warning \
      --identifier=thing \
      /usr/local/bin/thing
    

    If your thing emits logger prefixes for the priority levels (e.g. the line starts with <4> for warning messages) then you can use the --level-prefix flag instead of manually setting the priorities.

    Some other ideas include: