Search code examples
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:

  • The named pipes should exist before the writer application starts. I can create them with mkfifo beforehand, so this should not be a problem. It shouldn't be necessary to manage the pipes' existence with systemd, unless it makes the unit file(s) simpler or more robust somehow.
  • The reader processes that do the timestamp augmentation and log file writing should be up and running before the writer application starts up, which is a job for Before/After and Requires/Wants in the unit files, I believe.
  • The whole apparatus should survive restarts of either the writer application or the reader processes. E.g. if cat is used in a reader process, the writer quits and cat sees EOF and quits, the reader process should come back up and be ready when the writer process comes back up.
  • Any log rows written to the named pipes by the application while the respective reader processes are down are lost, but this is acceptable.

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:

    • Using stream logging in your Unit.
    • Writing a custom splitter to read in the logs and pipe them to systemd-cat with the correct levels. You would run this as a service that thing would talk to.
    • Variant: Write a custom parser and send the parsed logs directly to journald via sd_journal_send(3). You would use systemd to pipe the output of thing to the parser.
    • Use systemd to write stdout and stderr to a socket unit via the StandardOutput= and StandardError=.