Open Source im professionellen Einsatz
Linux-Magazin 02/2016
© Sergey Lavrentev, 123RF

© Sergey Lavrentev, 123RF

Fortschrittliches Logging mit dem Systemd-Journal

Nadel im Heuhaufen

Seit der Fedora-Version 20 gibt es kein "/var/log/messages" mehr, und auch der klassische Syslog-Daemon läuft dort nicht. Trotzdem kann der Admin nach Herzenslust in Systemmeldungen stöbern – und das sogar viel bequemer als früher.

1845

Syslog, der standardmäßige Logging-Mechanismus unter Unix und Linux, stammt aus den frühen 1980er Jahren, damals wurde er von Eric Allman zuerst für Sendmail entwickelt. Später etablierte sich das Tool als Universallösung für das Logging von System- und Fehlermeldungen aller Art. Auch unter den Linux-Distributionen war Syslog lange der allgemein akzeptierte Standard. Doch bereits während seines Siegeszugs offenbarte das Werkzeug auch eine Reihe von Schwachstellen:

  • Das Protokoll sieht keine Authentifizierung vor, jedermann kann Logeinträge vorgeblich im Namen einer beliebigen Applikation generieren.
  • Syslogd überträgt alle Meldungen im Klartext, jeder darf sie mitlesen.
  • Die Zeitstempel enthalten keine Information über die Zeitzone.
  • Als Transportprotokoll kommt das verbindungslose UDP zum Einsatz, das nicht dafür garantiert, dass alle Meldungen auch ankommen.
  • Es gibt außerdem keine verbindlichen Vorgaben, wie die Protokolleinträge für Severity und Facility zu verwenden sind. In der Folge ist ihr Gebrauch uneinheitlich.
  • Die Logdateien lassen sich wegen des Formats nur verhältnismäßig umständlich mit Tools für die Textmustersuche durchforsten.
  • Die Metadaten, die das Syslog-Protokoll speichert, sind unvollständig.
  • Binärdaten lassen sich auf diese Weise nicht loggen.
  • Syslog ist nur eines unter diversen Logs unter Linux, daneben gibt es eigene Logs für UTMP/WTMP, Lastlog, Audit, Kernel-Logs, Firmware-Logs und eine Vielzahl applikationsspezifischer Logs.
  • Log-Rotation und -Kompression sind zwar vorhanden, aber nicht flexibel. So kümmert sich die Rotation nur um feste Intervalle, nicht um die Auslastung der Platten, und die Kompression funktioniert in der Regel nur bei der Rotation.

Das Syslog-Protokoll wurde erstmals 2001 im RFC 3164 standardisiert. Aber es dauerte nicht lange, da entwickelten sich Alternativen, die einige der Schwächen behoben, darunter Syslog-ng und Rsyslog. Syslog-ng kennt Dutzende Features, die über den alten Syslog-Daemon hinausgehen, allerdings sind manche – darunter Verschlüsselung, Multiline-Messages oder das Failover auf Client-Seite – nur in einer kostenpflichtigen Premium Edition zu haben, nicht in der kostenlosen Version.

Auch Rsyslog ist weitaus mächtiger als sein Vorbild. Es versteht eine Vielzahl von Datenquellen und übersetzt deren Meldungen in unterschiedliche Formate. Das Ziel seines Schöpfers Rainer Gerhards war es vor allem, der Open-Source-Welt eine weitere Wahlmöglichkeit neben dem Monopolisten Syslog-ng zu bieten. Nun allerdings könnte ein dritter Bewerber den Konkurrenzkampf zwischen den beiden Syslog-Nachfolgern für sich entscheiden: Journald, die Logging-Komponente von Systemd.

So funktioniert das Journal

Die Systemd-Loggingkomponente hatte sich von Anfang an hohe Ziele gesteckt. Sie wollte nicht nur alle Defizite ihrer Vorgänger beheben, sondern sollte drüber hinaus einfach sein und keine Maintenance benötigen. Weitere Ziele waren Robustheit, Portabilität und Performanz. Angestrebt waren die enge Integration in das Gesamtsystem und die Vereinheitlichung der bestehenden Loggingsysteme. Die Sicherheit sollte einen hohen Wert besitzen und skalierbar sollte das Ganze auch noch sein.

Das Funktionsprinzip des Journals unterscheidet sich deutlich vom bisherigen Syslog-Daemon. Hier übergeben die Applikationen nicht eine formatierte Zeile pro Eintrag, sondern viele, durch Zeilenschaltungen getrennte Key-Value-Paare an das Loggingsystem. Deren Anzahl ist nicht begrenzt und es können sowohl wohlbekannte wie applikationsspezifische Paare sein. Die Werte sind normalerweise Strings, sie dürfen aber auch Binärdaten enthalten.

Der Loggingservice selbst ergänzt etliche Metadaten (beispielsweise Zeitstempel, Hostname, Servicename, PID, UID und so weiter) – diese Angaben kann also kein Client mehr fälschen. Die vom System hinzugefügten Einträge beginnen mit einem Unterstrich (Listing 1). Alle Felder, aus denen ein Logeintrag besteht, werden als einzelne Objekte abgelegt und von allen Logmeldungen, die sie brauchen, referenziert. So landet nichts doppelt auf der Platte, was so viel Platz spart, dass der Bedarf gegenüber dem klassischen Syslog nicht merklich steigt, obwohl das Systemd-Journal viel mehr Metadaten speichert.

Die Meldungen von unprivilegierten Nutzern nehmen individuelle Journal-Files auf, die der jeweilige Nutzer lesen kann. Logeinträge von Systemservices sind dagegen nur Root und den Nutzern einer bestimmten Gruppe zugänglich. Trotz der Trennung in einzelne Files geht der Zusammenhang nicht verloren, denn der Client führt am Ende wieder alle Meldungen, die ein bestimmter Benutzer sehen darf, transparent in einem großen virtuellen Logfile zusammen. Wiederkehrende Ereignisse wie "User logged in" können mit einer 128-Bit-Message-ID gekennzeichnet sein, über die sich gleichartige Ereignisse schnell ausfiltern lassen.

Der Journal-Daemon rotiert automatisch Logfiles, wenn bestimmte Größenlimits überschritten werden. Die Rotation achtet dabei auch darauf, dass ein vorgegebener Füllungsgrad der Platten nicht überschritten wird. Daneben ist auch die Menge an Logmeldungen begrenzt, die ein einzelner Client in einer bestimmten Zeit einliefern darf. Auch diese Rate ist mit dem freien Plattenplatz korreliert: Ist die Platte leer, gibt sich der Journal-Daemon generös, ist sie fast voll, erlaubt er nur noch wenige Meldungen pro Client.

Wenn Hacker erfolgreich in ein System eingebrochen sind, versuchen sie oft ihre Spuren zu verwischen, indem sie die Systemlogs manipulieren. Bei dem reinen Textformat des alten Syslog-Daemon war das noch sehr einfach. Journald führt stattdessen einen kryptographischen Hash aller Messages sowie einen Hash des jeweils vorangehenden Eintrags mit. Das ergibt eine Kette, in der der letzte Eintrag alle vorausgehenden authentifiziert. Manipulationen der Logs sind so leicht erkennbar.

Spreu und Weizen

Zu den zahlreichen Vorteilen des Systemd-Journals beim Speichern der Logmeldungen kommen gravierende Verbesserungen für den Admin, der die Einträge durchforsten will. Der Schlüssel zur Suche in den Logs ist das Kommando »journalctl« . Wer dieses Kommando ohne weitere Parameter als Benutzer Root aufruft, erhält eine Liste aller aufgelaufenen Syslog-Nachrichten, beginnend mit den ältesten. Diese Liste sieht auf den ersten Blick ganz ähnlich aus wie das alte File »/var/log/messages« , aber auf den zweiten Blick erkennt man schon die ersten Verbesserungen (Listing 2):

  • Zeilen mit der Priorität Error oder höher erscheinen rot eingefärbt.
  • Zeilen mit der Priorität Notice/Warning sind fett gedruckt.
  • Die Zeitstempel sind in die lokale Zeitzone konvertiert.
  • Die Ausgabe erfolgt automatisch seitenweise wie mit »less« .
  • Es werden alle gespeicherten Daten ausgegeben, auch die aus rotierten Logfiles.
  • Vor den Einträgen, die zu einem neuen Bootvorgang gehören, wird zur besseren Orientierung automatisch eine Hinweiszeile eingefügt.

Weil es sich nicht empfiehlt, ständig unter der Benutzerkennung »root« zu arbeiten, gewährt Systemd daneben auch allen Usern Zugang zu allen Logs, die der Gruppe »adm« angehören.

Sämtliche Logeinträge durchzusehen ist wenig effizient. Das Journal hält deshalb mächtige Werkzeuge zum Filtern der Logs parat. Die einfachste Einschränkung ist:

journalctl -b

Sie zeigt alle Einträge seit dem letzten Booten an. Zudem kann der Admin die Ausgabe auf Logs einer bestimmten Priorität einschränken, dazu dient der Parameter »-p« :

journalctl -b -p err

Wird der Rechner nur selten gebootet, ist der Parameter »-b« allerdings nicht sehr hilfreich. In diesem Fall ist es besser, den Zeitraum explizit anzugeben:

journalctl --since=yesterday

Ist ein längerer Zeitraum gefragt, kann der Benutzer nach »--since« oder »--until« auch ein Datum eingeben, wahlweise inklusive Uhrzeit:

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

Nicht immer sind nur Meldungen in bestimmten Zeiträumen gefragt. Oft sind beispielsweise eher alle Meldungen eines bestimmten Dienstes (auch bekannt als Systemd-Service-Unit) interessant. Auch dieser Filter lässt sich natürlich mit einem Datum oder auch mit einer Uhrzeit kombinieren:

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

Hier filtert Journalctl implizit nach der »_SYSTEMD_UNIT« . Wie genau heißen doch gleich die anderen Dienste, sprich Systemd-Units, deren Meldungen man eventuell auch noch aussieben will? Hierbei hilft:

journalctl -F _SYSTEMD_UNIT

Der Parameter »-F« bewirkt, dass das Kommando alle unterschiedlichen Werte auflistet, die der danach angegebene Metadaten-Parameter im vorliegenden Log annimmt. Wer nicht nur einzelne, sondern alle Metadaten sehen will, die überhaupt gespeichert wurden (Listing 3), verwendet:

journalctl -o verbose -n

Der Clou dabei ist: Die Datenbank mit den Logeinträgen ist bereits automatisch nach allen ergänzten Metadaten-Feldern (sie beginnen – wie erwähnt – alle mit einem Unterstrich) indexiert und lässt sich direkt nach deren Werten durchforsten. Das geht zum Beispiel so:

journalctl _UID=1000

oder mit

journalctl _EXE=/usr/bin/gnome-session

Auch diese Suchparameter sind mit allen anderen kombinierbar. Dabei verknüpft Journalctl alle Parameter mit einem logischen Oder. Es ist aber auch möglich, die Suchparameter mit einem Exklusiv-Oder zusammenzufügen, was der Bedeutung eines Entweder-oder entspricht. Dafür dient das Pluszeichen, wie Listing 4 zeigt. Hier werden alle Logeinträge zu Tage befördert, die entweder vom Nutzer mit der UID 1000 des lokalen Hosts oder vom Nutzer mit der UID 1100 vom Host Merkur stammen.

Listing 1

Journal-Eintrag

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

Listing 2

Ausgabe von Logmeldungen

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]: Nicht unterstützte Konfiguration: 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: Nicht unterstützte Konfiguration:
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

Listing 3

Log mit Metadaten

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

Listing 4

Exklusive-OR-Verknüpfung

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

Diesen Artikel als PDF kaufen

Express-Kauf als PDF

Umfang: 3 Heftseiten

Preis € 0,99
(inkl. 19% MwSt.)

Linux-Magazin kaufen

Einzelne Ausgabe
 
Abonnements
 
TABLET & SMARTPHONE APPS
Bald erhältlich
Get it on Google Play

Deutschland

Ähnliche Artikel

comments powered by Disqus

Ausgabe 11/2017

Digitale Ausgabe: Preis € 6,40
(inkl. 19% MwSt.)

Stellenmarkt

Artikelserien und interessante Workshops aus dem Magazin können Sie hier als Bundle erwerben.