Dinge, die ich an systemd mag: Logging

2020-04-25

systemd ist jetzt schon eine Weile da:

$ grep systemd /var/log/pacman.log | head -n 1
[2012-06-05 17:37] installed systemd-tools (184-2)

Trotzdem habe ich noch nicht so ganz Frieden damit geschlossen. Ich strebe nach Einfachheit und Minimalismus, was oft mit systemd in Konflikt steht und auch der Grund ist, warum ich mich letztlich doch immer wieder mit diesem Thema auseinandersetze. Aber lassen wir mal so langweiliges Zeugs wie „das ist Bloat!!1!“ außen vor.

Konzentrieren wir uns mal auf ein paar gute Aspekte. In diesem Fall: Logging.

An der Stelle will ich betonen, dass ich hier über Konzepte und Ideen reden will und nicht notwendigerweise über systemds derzeitige Implementierung, mit der ich größtenteils eh nicht vertraut bin.

Einfach stdout und stderr benutzen

Daemons sollten einfach nach stdout und stderr schreiben. systemd unterstützt und fördert das. (Docker und Kubernetes auch. Vielleicht auch noch andere, aber sicher nicht SysV Init.)

Das sollte der universelle Standard sein, wenn man mich fragt.

Es macht den eigentlichen Daemon deutlich einfacher. Soll sich die Plattform um das Aufsammeln der Logs kümmern. Häufig wird systemd (zu Recht) vorgeworfen, dass es einen „Lock-In-Effekt“ erzeugt, in diesem Fall sorgt es aber sogar für bessere Portabilität: Selbst mit einem ganz einfachen Init-System kann man ein kleines Shellskript um den Daemon drumherum schreiben, das stdout und stderr in eine Datei umleitet und dann benutzt man eben das traditionelle Logrotate.

Keine gesonderten Codepfade mehr, die entscheiden, ob nun syslog() benutzt oder, schlimmer, in eine eigene Logfile geschrieben wird. Oder noch schlimmer, es wird eine ganz eigene Bibliothek gelinkt.

Es macht auch die Entwicklung einfacher, weil man sein Programm einfach in einem Terminal starten und seinen Output sehen kann.

Zu guter Letzt: Wenn man stdout und stderr auffängt, bekommt man sämtlichen Output. Nicht nur die Zeilen, von denen das Programm dachte, dass sie würdig seien, in einer Log zu landen. Man sieht auch andere interne Fehler, möglicherweise in Situationen, in denen das Programm schon gar nicht mehr anders konnte, als nach stderr zu schreiben. Oder man denke an zusätzliche Skripte, die vom Daemon gestartet werden – deren Output landet dann auf natürlichem Wege auch im Journal.

Interessantes Detail zur derzeitigen Implementierung: Wenn systemd ein Programm startet, verbindet es dessen stdout und stderr mit einem Socket. Genauer gesagt, direkt mit journald. Das heißt, dass man niemals das Journal stoppen und neustarten darf. Ansonsten verlieren alle laufenden Daemons ihre Verbindung und können nicht mehr loggen, bis sie selbst neugestartet werden.

Das war bei syslog() anders: Es verbindet sich neu mit /dev/log und im schlimmsten Fall fällt es auf das Schreiben nach /dev/console zurück. Das war in der libc implementiert, ist also nichts, was jeder Daemon für sich neu erfinden hätte müssen.

Der „Workaround“ in systemd dafür ist, den Hauptprozess (PID 1) das Socket vom Journal verwalten zu lassen: Er hält den Dateideskriptor und gibt ihn an den eigentlichen Journal-Prozess wieder weiter, falls der mal neustarten muss. Man kann also durchaus systemctl restart systemd-journald ausführen, die Daemons bleiben dann verbunden. Das funktioniert auch, wenn journald mal abstürzt oder anderweitig gekillt wird. Man darf bloß kein systemctl stop systemd-journald machen, weil es dann das Socket freigeben wird.

Ist also bisschen ein Trade-Off. Man ersetzt den Retry-Mechanismus von syslog(), der mal in der libc war, mit zusätzlichem Socket-Handling-Code im Haupt-systemd. Ich glaube aber, dass das hauptsächlich ein Verschieben von Komplexität ist und nicht wirklich neue erzeugt.

Schluss mit dem elenden Logrotate

Das ist wahrscheinlich trivial, aber ich muss es trotzdem erwähnen.

Danke, dass das endlich ein Ende hat.

Ich bin so oft nachts rausgeklingelt worden, weil irgendwo irgendein Daemon amokgelaufen ist oder von Spam/Bots getroffen wurde, also lief die Platte voll, Logging hörte auf und dann war das ein komisches System, das trotz allem keine eigene Partition für /var/log hatte, also ist alles stehengebelieben.

Ich habe eben auf journald eingedrescht und versucht, es in dieselbe Situation zu bringen. Hab’s nicht geschafft. Es müllt die Platte nicht mehr mit sinnlosen Logs zu. Auch nicht, wenn Rate-Limiting deaktiviert ist. Es löscht dann einfach alte Journal-Archive und gibt Platz frei.

Man kann es natürlich absichtlich kaputtmachen, indem etwas anderes die Platte zumüllt. journald wird dann nicht auf magische Weise seine eigenen Logs opfern. Vielleicht könnte es da ein bisschen aggressiver sein, aber es ist auch keine leichte Entscheidung: Vielleicht steht in den Logs der eine wichtige Debugging-Hinweis drin, der verrät, wieso der andere Dienst durchgedreht ist.

(Ein bisschen anders ist die Situation, wenn ein normaler Daemon amokläuft und das Journal massiv zumüllt und währenddessen noch etwas anderes die Platte vollschreibt. Das zwingt das Journal dazu, seine eigenen Archive häufig zu rotieren und währenddessen wird es die neue Platzsituation berücksichtigen, seine eigene Reservierung also reduzieren.)

Einfaches zeitbasiertes Suchen

Das ist schon toll:

journalctl --since='2020-04-15 15:00' --until='2020-04-16 16:00'

Ja, ich weiß schon, wie ich grep benutzen kann bei traditionellen Logs. Aber man möge mir nicht sagen, dass das nicht lästig ist.

Und … wenn man schonmal mit mistigen Anwendungen zu tun hatte, die einfach sowas wie Stacktraces in mehrzeiligen Logeinträgen ausspucken, dann kennt man den Schmerz dabei. Ja, zum Beispiel OpenBSDs syslogd wirft einfach Newlines raus und stellt die grep-barkeit wieder her. Das ist schon gar nicht schlecht, aber leider kann das auch dafür sorgen, dass man es kaum mehr lesen kann.

Ja, ich betrachte solche Anwendungen auch als kaputt. Sie sind aber eine Realität.

Einheitliches Logging

Man führe aus:

journalctl -u nginx

Und dann kriegt man die Logs dieser Unit. Das geht für alle Units. Kein Suchen mehr in /var/log, weil ein cleveres Programm der Meinung ist, nach /var/log/foo/main.log zu schreiben … oder war es /var/opt/foo/logs/main.log? Oh, nein, richtig! Es war /opt/foo/log/main.log. Mist, /opt/foo/log gibt es zwar, ist aber leer. Es wäre /opt/foo/logs gewesen.

Natürlich funktioniert das nur, wenn die Daemons tatsächlich nach stdout/stderr oder syslog schreiben. Wenn die immer noch eigene Logs erzeugen, hat man Pech. Aber zum Beispiel dieser Server hier ist so konfiguriert, dass alles nach syslog/journal schreibt. Abgesehen von /var/log/pacman.log und dem Journal liegt nichts in /var/log rum.

Ungelöstes Problem: Mehrere Logs einer einzelnen Anwendung. Man denke an VHosts eines Webservers. In der Theorie könnte man das über syslog-Tags lösen, also date | logger -t nginx/uninformativ.de. Habe ich aber noch nicht „in the wild“ gesehen.

Zukünftige Blogposts dieser Art?

Benno Rice sagt in seinem Talk The Tragedy of systemd (35:55):

What I would challenge everyone here is: Look at systemd and try to find at least one thing that you like. And then go see if you can implement it.

Ich schreibe gerne meine eigene Software und benutze die dann auch. Manchmal veröffentliche ich sie, will aber eigentlich keinen überzeugen, dass das der geilste Scheiß ist. (Es ist eher so, dass ich manchmal gefragt werden, „was ist denn das, was du da benutzt?“, und dann will ich ein Repo haben, auf das ich zeigen kann.) Ich bin nur ein Hobby-Bastler und mache das zum Spaß. Es ist trotzdem ein sehr interessantes Thema und, ja, vielleicht probiere ich es irgendwann mal. Vielleicht. Ganz vielleicht.

Ein anderer wichtiger Punkt aus dem Talk (20:20), mit dem ich schließen möchte:

I think there’s an important distinction to be drawn between “systemd, the implementation” and systemd as a set of ideas.

Comments?