Score:0

Set INFO/ERROR priority for messages logged to journal via stdout and stderr?

jp flag

We have many production apps (first and third-party) that leave logging up to the process that runs the app and just log to stdout for INFO and stderr for ERROR logs (ie only 2 log priorities: INFO|ERROR).

With a systemd service unit for an app this can be setup like this:

StandardOutput=journal
StandardError=journal

This allows devops to manage everything through systemd units and the journal in order to facilitate centralized log collection, monitoring whatever...and they don't need to worry about locating and parsing different logs in different formats/locations for every app they deploy.

systemd's journal has a message priority system compatible with syslog's 7 level message priority system. INFO is level 6 and ERROR is level 3. See references for more details.

The problem is... systemd/journal apparently does not distinguish between messages written to the journal from stdout vs stderr. Both stdout and stderr messages are all written to the journal with default priority of 6 (INFO).

Example: "Fancy App"

/opt/log-test.sh

#!/bin/bash

echo "This is ERROR" 1>&2
echo "This is INFO"

exit 0

/etc/systemd/system/log-test.service

[Unit]
Description=log test for journal

[Service]
Type=simple

ExecStart=/opt/log-test.sh

StandardOutput=journal
StandardError=journal
SyslogIdentifier=log-test

run it and check journal

$ systemctl start log-test
$ journalctl -u log-test
-- Logs begin at Thu 2022-04-07 08:17:16 UTC, end at Thu 2022-04-07 16:35:02 UTC. --
Apr 07 16:34:58 host.example.com systemd[1]: Started log test for journal.
Apr 07 16:34:58 host.example.com log-test.sh[29909]: This is ERROR
Apr 07 16:34:58 host.example.com log-test.sh[29909]: This is INFO
$ journalctl -u log-test -p 6   # syslog info priority
-- Logs begin at Thu 2022-04-07 08:17:16 UTC, end at Thu 2022-04-07 16:35:08 UTC. --
Apr 07 16:34:58 host.example.com systemd[1]: Started log test for journal.
Apr 07 16:34:58 host.example.com log-test.sh[29909]: This is ERROR
Apr 07 16:34:58 host.example.com log-test.sh[29909]: This is INFO
$ journalctl -u log-test -p 3   # syslog error priority
-- No entries --
$

You can see that both stderr and stdout messages are set to priority 6 (INFO) when written to the journal.

This is a problem because we don't have an easy way of differentiating output on stdout vs stderr when using stdio->journal as primary logging facility.

This has been discussed before and solutions are possible, but not implemented. I'm hoping the systemd team eventually implements this, but meanwhile I need a solution.

Has anyone found a reasonable solution to get messages written to stdout and stderr to be different priorities in the journal without modifying how an app does logging?

I don't want all the apps we deploy (not all written by us) to have to implement journal or syslog integrations in order to get log priority when we really only need two levels: INFO (stdout) and ERROR (stderr).

Much of what we deploy is not containerized, so relying on logging facilities of the container is also not a solution for us.

Having stderr and stdout go to journal/syslog at different priorities by default is pretty critical for making distributed log error monitoring easier (assuming good developer hygiene about only writing stuff that needs attention to stderr).

References:

Score:1
tz flag

If you have to use stdout/stderr, you may use sd-daemon logging prefix.

Prepend your stderr with <3> to send an ERROR priority journald log.

Using your log-test.sh and log-test.service:

#!/bin/bash

>&2 echo "<3>This is ERROR"
echo "This is INFO"

exit 0

And journalctl output:

$ journalctl -u log-test -p 3
May 02 01:22:58 host.example.com log-test.sh[29909]: This is ERROR

If your fancy-app has any API to write to syslog, you can use that to write to UNIX datagram /dev/log (usually writable by default, and logs to journald) instead of stdout/stderr. Use syslog tag to identify your fancy-app, syslog priority to error or info depending on your needs, and any syslog facility.

For example, in Bash we can use logger:

# emit INFO message to journalctl
$ logger -t fancy-app -u /dev/log -p user.info "This is INFO"

# emit ERROR message to journalctl
$ logger -t fancy-app -u /dev/log -p user.error "This is ERROR"

# show journald messages for fancy-app
$ journalctl -t fancy-app
May 02 01:23:38 host.example.com fancy-app[27302]: This is INFO
May 02 01:23:39 host.example.com fancy-app[27303]: This is ERROR

# show journald ERROR messages for fancy-app
$ journalctl -t fancy-app -p 3
May 02 01:23:39 host.example.com fancy-app[27303]: This is ERROR

Note that in most distros journald entries usually forwarded to local syslog daemon (syslog-ng, rsyslog, ...), so probably check your syslog filters, or maybe use local0...local7 facilities.

We have many production apps (first and third-party) that leave logging up to the container and just log to stdout for INFO and stderr for ERROR logs (ie only 2 log priorities: INFO|ERROR).

Most container engine should be able to log to syslog. Without knowing your container engine, I'll use Docker as an example.

Docker has syslog logging driver that can be used to send log messages using syslog format to any syslog target. You should be able to log to journald with something like:

docker run \
    --log-driver syslog \
    --log-opt syslog-address=unix:///dev/log \
    --log-opt syslog-facility=user \
    --log-opt tag=fancy-app \
    fancy-app:latest

Docker also has journald logging driver available. For example:

docker run \
    --log-driver journald \
    --log-opt tag=fancy-app \
    fancy-app:latest

Both logging drivers (syslog and journald) supports separation between stdout and stderr; i.e. stdout messages will be logged with INFO priority, and stderr messages will be logged with ERROR priority.

Philosophies and flame wars aside, why not log to real syslog? It is easier, stored in text format, and generally supported by log management softwares (see Graylog, Logstash, Papertrail).

mattpr avatar
jp flag
Thanks for your answer, I will digest the detail later today after some more coffees. We aren't using containers for many things, so that isn't an instant solution. Some of the rest looks helpful. We do central log aggregation with ELK or Graylog (currently graylog) and can use/transport both syslog and journal (via journalbeat now filebeat) to log aggregation cluster. The problem is still that we often can't control the app code we deploy (e.g. third party app we don't want to maintain a logging patch for) and often apps default to stdout/stderr...or worse their own logging files/formats.
mangohost

Post an answer

Most people don’t grasp that asking a lot of questions unlocks learning and improves interpersonal bonding. In Alison’s studies, for example, though people could accurately recall how many questions had been asked in their conversations, they didn’t intuit the link between questions and liking. Across four studies, in which participants were engaged in conversations themselves or read transcripts of others’ conversations, people tended not to realize that question asking would influence—or had influenced—the level of amity between the conversationalists.