Home / server / Questions / 1098069
In Process
mattpr
Asked: 2022-04-08 09:03:36 +0800 CST

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

  • 772

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:

logging monitoring systemd journald centralized-logging

1 Answers

  1. 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).

    • 2