Advanced logging with the systemd journal

Needle in a Haystack

Article from Issue 184/2016
Author(s):

The new logging component included with systemd offers some advanced features you won't find in Syslog.

Syslog, the default logging mechanism on Unix and Linux, dates from the early 1980s and was originally developed by Eric Allman – initially for Sendmail. Later, the tool established itself as a universal solution for logging system and error messages of all kinds. Among Linux distributions, Syslog was the generally accepted standard for many years. But while Syslog was marching to triumph, it revealed a number of weaknesses:

  • The protocol does not provide authentication; anyone can generate spoofed log entries for any application.
  • Syslogd transmits all messages in plain text, and anyone can read them.
  • The timestamp does not contain any information about the time zone.
  • As its transport protocol, Syslog uses the connectionless UDP, which does not guarantee that all messages arrive.
  • Browsing the log files is a relatively complicated process, requiring tools that search for text patterns.
  • The metadata that the Syslog protocol stores is incomplete.
  • You can't log binary data.
  • Syslog is only one of several logs on Linux, and the user must separately access UTMP/WTMP, Lastlog, audit, kernel logs, and firmware logs, as well as a variety of application-specific logs.
  • Log rotation and compression are available but not flexible. Rotation only applies to fixed intervals but does not include disk utilization, and compression usually only works during rotation.

The Syslog protocol was first standardized in 2001 in RFC 3164. Developers soon created alternatives that corrected some of the weaknesses, including Syslog-ng and Rsyslog. Syslog-ng supports dozens of features that go beyond the old Syslog daemon's feature set; however, some of these features – including encryption, multi-line messages, and failover on the client side – only exist in a commercial premium edition.

Rsyslog is also far more powerful than its role model Syslog, supporting a variety of data sources and allowing message translation to other formats. However, a third alternative has stepped into the ring with Syslog and its children: Journald, the systemd logging component.

How the Journal Works

The creators of the systemd logging component had lofty goals. They wanted to fix the shortcomings of earlier tools, but they also wanted a simple and reliable solution that didn't need maintenance. Other objectives were portability, security, and performance. The developers wanted a design that delivered tight integration into the overall system and harmonized with existing logging systems.

The solution differed considerably from the previous Syslog daemon. Applications no longer hand over one formatted line for each entry to the logging system. Many entries are key-value pairs separated by line breaks. Entries can contain both well-known and application-specific pairs. The values are usually strings, but they can also contain binary data.

The logging service itself adds some metadata (e.g., timestamps, hostname, service name, PID, UID, and so on), which means this information can no longer be spoofed by a client.

Messages added by the system begin with an underscore (Listing 1). All fields that make up a log entry are stored as individual objects and referenced by all log messages that need them. Nothing is stored twice on disk, which saves so much space that the new system does not use significantly more disk space than the classic Syslog, even though it stores far more metadata.

Listing 1

Journal Entry

01 _SERVICE=systemd-logind.service
02 MESSAGE=User peter logged in
03 MESSAGE_ID=455bcde45271414bc8bc9570f222f24a9
04 _EXE=/lib/systemd/systemd-logind
05 _COMM=systemd-logind
06 _CMDLINE=/lib/systemd/systemd-logind
07 _PID=4711
08 _UID=0
09 _GID=0
10 _SYSTEMD_CGROUP=/system/systemd-logind.service
11 _CGROUPS=cpu:/system/systemd-logind.service
12 PRIORITY=6
13 _BOOT_ID=422bc3d27149bc8bcde5870f222f24a9
14 _MACHINE_ID=c686f3b6547f45ee0b43ceb6eda479721
15 _HOSTNAME=poseidon
16 LOGIN_USER=500

Messages from non-privileged users are stored in individual journal files, which the user can read. However, log entries for system services are only accessible to root and the users of a group specifically assigned rights for the information. Context is not lost because the client transparently merges all messages that a specific user is permitted to read to create a large virtual log file. Recurring events, such as "User logged in" can be marked with a 128-bit message ID, thus allowing for quick filtering with similar events.

The Journal daemon automatically rotates log files when certain size limits are exceeded. Rotation ensures that the system does not exceed a predetermined disk utilization level. In addition, a single client is limited to a maximum number of log messages in a certain period. This maximum is correlated with the free disk space: If the disk is empty, the Journal daemon is generous, but if it is almost full, the daemon only allows a few messages per client.

An attacker who does successfully break into a system often tries to cover the tracks by manipulating the system logs. The plain-text format of the old Syslog daemon made this obfuscation very simple. But Journald maintains a cryptographic hash of all messages and a hash of the preceding entry, which creates a chain in which the last entry can easily authenticate all preceding entries. Log manipulation is thus easily recognized.

Wheat and Chaff

Along with systemd journal's numerous advantages for saving log messages are some additional improvements for admins who need to browse the entries. The key for searching in the logs is the journalctl command. If you call this command without any further parameters as the root user, you will see a list of all existing messages, starting with the oldest. This list looks quite similar, at first glance, to the old /var/log/messages file. On closer inspection, however, you can already see some initial improvements (Listing 2):

Listing 2

Log Message Output

01 [root@localhost jcb]# journalctl
02
03 [...]
04 Jan 10 20:03:52 localhost.localdomain systemd[987]: Starting Paths.
05 Jan 10 20:03:52 localhost.localdomain systemd[987]: Reached target Paths.
06 Jan 10 20:03:52 localhost.localdomain systemd[987]: Starting Timers.
07 Jan 10 20:03:52 localhost.localdomain systemd[987]: Reached target Timers.
08 Jan 10 20:03:52 localhost.localdomain systemd[987]: Starting Sockets.
09 Jan 10 20:03:52 localhost.localdomain systemd[987]: Reached target Sockets.
10 Jan 10 20:03:52 localhost.localdomain systemd[987]: Starting Basic System.
11 Jan 10 20:03:52 localhost.localdomain systemd[987]: Reached target Basic System.
12 Jan 10 20:03:52 localhost.localdomain systemd[987]: Starting Default.
13 Jan 10 20:03:52 localhost.localdomain systemd[987]: Reached target Default.
14 Jan 10 20:03:52 localhost.localdomain systemd[987]: Startup finished in 13ms.
15 Jan 10 20:03:52 localhost.localdomain gdm-launch-environment][948]: pam_unix(gdm-launch-environment:session): session opened for user gdm
16 Jan 10 20:03:53 localhost.localdomain org.a11y.Bus[996]: Activating service name='org.a11y.atspi.Registry'
17 Jan 10 20:03:53 localhost.localdomain org.a11y.Bus[996]: Successfully activated service 'org.a11y.atspi.Registry'
18 Jan 10 20:03:53 localhost.localdomain org.a11y.atspi.Registry[1004]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.R
19 Jan 10 20:03:53 localhost.localdomain org.a11y.atspi.Registry[1004]: Xlib:  extension "XEVIE" missing on display ":0".
20 Jan 10 20:03:53 localhost.localdomain dbus[497]: [system] Activating via systemd: service name='org.freedesktop.UPower' unit='upower.service'
21 Jan 10 20:03:53 localhost.localdomain dbus[497]: [system] Successfully activated service 'org.freedesktop.UPower'
22 Jan 10 20:03:53 localhost.localdomain libvirtd[712]: Unsupported configuration: QEMU 2.1.2 is too new for help parsing
23 Jan 10 20:03:53 localhost.localdomain libvirtd[712]:Failed to probe capabilities for /usr/bin/qemu-kvm: Unsupported configuration:
24 Jan 10 20:03:53 localhost.localdomain gnome-session[991]: Entering running state (FETT)
25 Jan 10 20:03:53 localhost.localdomain dbus[497]: [system] Activating via systemd: service name='org.freedesktop.ColorManager' unit='colord
26 Jan 10 20:03:53 localhost.localdomain colord[1062]: Using mapping database file /var/lib/colord/mapping.db
27 lines 673-700
  • Lines with a priority of Error or higher are highlighted in red.
  • Lines with a priority of Notice/Warning are shown in bold type.
  • Timestamps are converted to the local time zone.
  • The output is automatically paged with less.
  • All stored data is output, including data from rotated logfiles.

Because it is better to avoid working as the root user, systemd additionally grants access to all logs to members of the adm group.

Searching through all the log entries is not very efficient. The journal thus provides powerful tools for filtering the logs. The simplest filter is:

journalctl -b

This command shows all the entries since the last boot. In addition, admins can restrict the output to logs with a particular priority using the -p parameter:

journalctl -b -p err

If the computer is rarely booted, the -b parameter is not very helpful. In that case, it is better to explicitly specify the time period:

journalctl -since=yesterday

If a longer period is required, you can enter --since or --until along with a date, optionally including a time:

journalctl --since=2015-11-15 --until="2015-11-16 20:59:59"

You might need to do more than just search for messages within a certain time period. One typical example is searching for all messages for a particular service (or systemd service unit). You can combine these additional filters with the date or time:

journalctl -u mysqld --since 9:00 --until 10:00

Journalctl implicitly filters by _SYSTEMD_UNIT. But, what are the names of the other services, or systemd units, whose messages you might also want to filter out? To find out, type:

journalctl -F _SYSTEMD_UNIT

The -F parameter tells the command to list all the different values taken by the metadata parameter specified in the current log. If you want to see all the metadata ever recorded, instead of individual entries, use:

journalctl -o verbose -n

See Listing 3 for sample output.

Listing 3

Log with Metadata

01 jcb@localhost:~$ journalctl -o verbose -n
02 -- Logs begin at Sa 2015-01-10 20:03:48 CET, end at Mi 2015-11-25 13:32:42 CET.
03 Mi 2015-11-25 13:32:39.518585 CET s=47da77439d10498aafb608231cd005cd;i=190441;
04     _TRANSPORT=stdout
05     PRIORITY=6
06     SYSLOG_IDENTIFIER=gnome-session
07     _UID=1000
08     _GID=1000
09     _COMM=gnome-session
10     _EXE=/usr/bin/gnome-session
11     _CMDLINE=gnome-session
12     _CAP_EFFECTIVE=0
13     _AUDIT_SESSION=1
14     _AUDIT_LOGINUID=1000
15     _SYSTEMD_CGROUP=/user.slice/user-1000.slice/session-1.scope
16     _SYSTEMD_SESSION=1
17     _SYSTEMD_OWNER_UID=1000
18     _SYSTEMD_UNIT=session-1.scope
19     _SYSTEMD_SLICE=user-1000.slice
20     _MACHINE_ID=956fbf7078cb4692bed922be877f6778
21     _HOSTNAME=localhost.localdomain
22     _BOOT_ID=a552964bee8a4416b0e1134f2f197e64
23     _PID=2409
24     MESSAGE=(gnome-shell:2525): mutter-WARNING **: STACK_OP_LOWER_BELOW: window

The database containing the log entries is already automatically indexed with all the additional metadata fields (they all start with an underscore, as mentioned previously) and can be directly searched for their values. For example:

journalctl _UID=1000

or:

journalctl _EXE=/usr/bin/gnome-session

You can combine these search parameters. Journalctl logically ORs all the parameters. You could also exclusively OR the search parameters, which is equivalent to saying either/or. You can use the plus sign for an exclusive OR (Listing 4). This command discovers all the log entries that either originate from the user with the UID 1000 on the local host or the user with the UID 1100 on the host mercury.

Listing 4

Exclusive OR

01 journalctl _HOSTNAME=localhost.localdomain _UID=1000 + _HOSTNAME=mercury. localdomain _UID=1100

Conclusions

Systemd journal goes far beyond the traditional Syslog, offering a centralized, space-saving, and safe logging mechanism that automatically enriches the logs with a wealth of useful metadata. At the same time, the systemd journal has advanced search options that make it easy to home in on interesting messages.

A simple authentication mechanism ensures intelligent log rotation. The journal can also handle binary data and convert the timestamp to a local value. These advanced features place the systemd journal in a strong position to compete with the old Syslog and other logging alternatives.

Buy this article as PDF

Express-Checkout as PDF
Price $2.95
(incl. VAT)

Buy Linux Magazine

SINGLE ISSUES
 
SUBSCRIPTIONS
 
TABLET & SMARTPHONE APPS
Get it on Google Play

US / Canada

Get it on Google Play

UK / Australia

Related content

  • systemd Tips

    Sure, you've heard about systemd, which is rapidly replacing the old System V init system as the go-to service management daemon for the Linux world. But what can you do with systemd really? We'll show you some tricks for improving security, managing processes, and analyzing boot times with systemd.

  • Journalctl

    The journal is the systemd component responsible for viewing and managing logfiles.

  • Command Line: Systemd

    Wondering what all the fuss is about systemd? We explain the basic concepts and capabilities of the new system management suite – coming soon to a distro near you.

  • Professor Knopper's Lab – Removing systemd

    The systemd service manager has been widely adopted by many Linux distros, so why would you want to remove it? The professor reveals why and how.

  • Tutorials – Systemd

    Take control of the services running on your Linux machine

comments powered by Disqus

Direct Download

Read full article as PDF:

Price $2.95

News

njobs Europe
What:
Where:
Country:
Njobs Netherlands Njobs Deutschland Njobs United Kingdom Njobs Italia Njobs France Njobs Espana Njobs Poland
Njobs Austria Njobs Denmark Njobs Belgium Njobs Czech Republic Njobs Mexico Njobs India Njobs Colombia