Better Logging

When I talk to people about system and service management, I often encounter a certain amount of uncertainty when the conversation turns to "systemd." Here, I'll provide a brief introduction and look at the arguments in favor of a new init system. You may have grown accustomed to a SysV-based init process at boot time over the years; however, this system is somewhat long in the tooth and no longer meets today's requirements in a useful way. So, it's time for a successor, which has actually existed for quite some time in the form of Upstart.

Upstart is to a great extent downwardly compatible with the old SysV system and solves many of the old problems. Rather than working through a predefined list of services to be started, Upstart is event-based, meaning that based on certain events, actions then take place. All these Event/Action rules are defined by the administrator or developer of a service in the Upstart configuration files, which is precisely the problem with Upstart. If you do not pay close attention to which events depend on other events, you end up with dependencies that cause services to wait on one another before starting. And, this is exactly the problem you want to avoid, right?

Problem Solved

Lennart Poettering and his team hope to solve this (and other) problems and even go one step further with their implementation of a new init system. The software, which goes by the name of systemd , simply starts all the services in parallel without worrying about dependencies. If a service wants access to another service, the requests are just queued until the desired service is available. This trick, known from Apple's launchd , ensures that a system boots up extremely fast.

On top of this function, systemd, of course, provides many other new features. An interesting aspect is that each process started by systemd ends up in a separate control group (cgroup) and is thus under the control of the kernel. A very good and very detailed description of the new init system can be found online [1].

At this point, I want to look at a particular feature of systemd that has been available since version 38: the journal. Journal is a new type of logging system, similar to systemd itself, which introduces radical changes and seeks to resolve some basic problems of the old syslogd, of which there are plenty. For example, the syslog protocol does not provide for authenticating log messages. An attacker could spoof or manipulate messages from a specific process.

The log format itself provides only a few fields that need to be used in each message – for example, the process name and ID. The message content is usually processed in a way that makes it easily human readable. However, manual scanning of logfiles is not really effective, so in most cases, a log parser is used. The parser has to take the opposite approach and disassemble the messages so that their information is legible – none of this is very effective.

Additionally, syslog messages are not the only logs on a system. There are also logs from other subsystems that do not rely on syslog. The audit and accounting subsystems are examples. Then, of course, plenty of applications do use their own logs. Thus, you need to deal with many different log mechanisms. The journald utility, which is built into systemd, tries to solve all of these problems and provides a unified log for all components of a system.

Applications and services can pass arbitrary metadata to journald. This is done either using printk(), the regular syslog() function, the native API, or /proc/proc/sys/kernel/core_pattern for coredumps. The information is passed in as key/value pairs and can be queried individually.

Log messages are cryptographically secured and protected against changes. User-related messages can thereby be viewed by the users themselves, whereas system messages are reserved for root or members of the adm group.

For an overview of all log messages, even from rotated logs, you simply call journalctl. The output and format are almost identical to a /var/log/messages file, with which you might already be familiar. You can even use the familiar tail options -f and -n to view only the last lines of the journal. Warning messages are bolded by journald, and error messages are output in red. If you only want to see the messages since the last boot, you can simply call journalctl with the -b option. Nice, but still not very exciting.

Because the journal for each log field has an index, the messages can be filtered quite nicely. If you want to see an overview of all the messages for a service from a specific time window, you could do so with the command:

# journalctl -u vsftpd --since=yesterday --until '2013-11-05 11:00'

No idea what systemd-units exist on the system? No problem: The systemctl list-unit-files command displays them. If you are only interested in services, you can restrict the output accordingly with --type=service. All told, systemd currently provides 12 different unit types.

However, how do you know which fields belong to a log message? In this case, the journald -o verbose option provides further help. All the fields in a message are then displayed in a key/value format. Armed with this information, you can carry on hunting. Want to see all messages for a certain user that have led to errors? No problem. If you pass in the desired field along with the err log priority, the two options are combined and the output shows the appropriate results:

# journalctl -p err _UID=1000

This just keeps getting better. Maybe next you would like to see all the relevant error messages for a specific SELinux domain. If so, the call would be:

# journalctl -p err _SELINUX_CONTEXT=Kontext

But what if you do not know exactly what name the context of the corresponding SELinux domain goes by? In that case, you leave the field for the context blank and press the tab key twice to view a list of all known context information from the logs. Then, you can choose the correct domain. Autocompletion works with all fields supported by the journal.

Search Included

Finally, don't forget that the journal messages for a particular service are used in the status output of systemd (Figure 1). Thus, all relevant log messages for a service are immediately visible, and you don't have to painstakingly search for them in the appropriate logfile later.

Figure 1: The systemctl tool shows the current log messages for a service when the service's status is queried.

The Author

Thorsten Scherf is a Principal Consultant for Red Hat EMEA. You can meet him as a speaker at conferences. He is also a keen marathon runner whenever time and his family permit.