Nehmt systemd, haben sie gesagt...
Wir hatten gestern Nachmittag eine längere Downtime von einigen supervisord-Instanzen. Betroffen waren ca. 10 Prozent unserer U7-User, und von denen wiederum betrieb nur ein Teil auch tatsächlich eigene Services unter supervisord. Dass damit effektiv nur eine überschaubare Zahl von Usern betroffen war, kann aber nicht darüber hinwegtäuschen, dass es für diese User eben eine sehr ärgerliche Einschränkung ihrer bei uns gehosteten Services darstellte, die auch für uns keinesfalls einen Normalzustand darstellt. Nach intensivem Debugging daher nun: Eine Spurensuche.
Es ist ein offenes Geheimnis, dass wir bei uns im Team systemd-Fürsprecher und systemd-Verächter haben. (Keine Sorge, wir kommen trotzdem alle gut miteinander aus.)
Was wir bauen, ist ein Produkt auf Basis einer Linux-Distribution (CentOS, der freien Variante von Red Hat Enterprise Linux). Wir bauen aber nicht selbst eine Linux-Distribution - die dafür nötige Womanpower wäre unmöglich für eine kleine Firma wie uns zu stemmen. Wir beschränken uns insofern darauf, lediglich einige zusätzliche Pakete zu bauen, wo wir Dinge anders als die Distribution machen wollen. Zum Beispiel, um mehrere Versionen einer Programmiersprache parallel anzubieten.
Ansonsten machen wir natürlich das, was jeder Admin in der Grundschule lernt: Updates. So auch heute mittag.
Was passiert hier gerade?
Als dann die ersten Meldungen eingingen, dass supervisord-Instanzen von Usern nicht liefen, wurden wir hellhörig, haben umgehend versucht, das nachzustellen, konnten jeweils verifizieren, dass die betreffenden Instanzen down waren. Allerdings ließen sie sich mit einem trivialen systemctl start supervisord@<user> wieder starten und liefen dann wieder fröhlich vor sich hin. Dachten wir. Deshalb haben wir das zunächst via Ansible einmal auf sämtliche Accounts angewendet.
Während wir dann weiter geforscht haben, warum die jeweiligen Instanzen nun down waren (supervisord abgestürzt? oomkiller am Werk?), haben wir bemerkt: Während wir fröhlich debuggen, sterben die Instanzen alle wieder weg. Was zum..?
Interessanterweise betraf das Problem nicht alle Instanzen, sondern jeweils nur eine Handvoll pro Host, konkret ca. 10-30, während alle anderen liefen.
Es ist nicht supervisord…
Im Lauf des Debuggings hat sich herausgestellt, dass das Problem nicht spezifisch für supervisord ist, sondern genauso auch den anderen Service betrifft, den wir pro User betreiben, nämlich php-fpm. Hier ist das Problem allerdings kein wirkliches Problem gewesen, denn php-fpm wird bei uns via Socket Activation gestartet, also erst beim tatsächlichen Zugriff auf eine .php-Datei. Wenn php-fpm also zwischenzeitlich wieder gestoppt war, hat der nächste HTTP-Request ihn automatisch via Socket Activation wieder angeworfen. Dass systemd ihn zwischenzeitlich stoppt, bleibt insofern unbemerkt.
Das Set der jeweils 10-30 betroffenen User war dabei interessanterweise statisch: Haben wir alle supervisord-Instanzen wieder gestartet, sind sie nach und nach binnen Minuten wieder gestoppt worden, und zwar für exakt die gleichen User wie vorher. Es gibt wohlgemerkt keinerlei Job von uns, der den supervisord unter irgendwelchen Umständen aktiv stoppen würde; er ist dafür designed, konstant durchzulaufen. Er wird nur dann gestoppt, wenn ein Account wegen Nichtzahlung deaktiviert wird, und das ist ein komplett ausgelagerter Prozess und konnte damit nicht die Ursache sein.
Zu diesem Zeitpunkt waren wir zugegebenermaßen etwas ratlos. Die Configs der verschiedenen Accounts wird komplett automatisch generiert und sind identisch. Starteten wir mit systemctl start supervisord@dbcheck die Instanz des Users dbcheck (ein spezieller Account, den es auf allen Hosts gibt und mit dem wir die Erreichbarkeit von Webserver, PHP und MariaDB testen), so klappte das, nur um kurz darauf wieder zu sterben:
Sep 18 17:58:09 pizarro.uberspace.de systemd[1]: Starting Provides a supervisord instance for each user....
Sep 18 17:58:09 pizarro.uberspace.de systemd[1]: Started Provides a supervisord instance for each user..
Sep 18 17:58:09 pizarro.uberspace.de uberspace-wrap-netns.sh[29008]: 2019-09-18 17:58:09,795 WARN No file matches via include "/home/dbcheck/etc/services.d/*.ini"
Sep 18 17:58:09 pizarro.uberspace.de uberspace-wrap-netns.sh[29008]: 2019-09-18 17:58:09,815 INFO RPC interface 'supervisor' initialized
Sep 18 17:58:09 pizarro.uberspace.de uberspace-wrap-netns.sh[29008]: 2019-09-18 17:58:09,815 INFO supervisord started with pid 29008
Sep 18 17:58:27 pizarro.uberspace.de systemd[1]: Stopping Provides a supervisord instance for each user....
Sep 18 17:58:27 pizarro.uberspace.de uberspace-wrap-netns.sh[29008]: 2019-09-18 17:58:27,122 WARN received SIGTERM indicating exit request
Sep 18 17:58:27 pizarro.uberspace.de systemd[1]: Stopped Provides a supervisord instance for each user..
Zwei Dinge waren auffällig: Zum einen besagt “systemd[1]: Stopping Provides a supervisord instance for each user….”, dass der Service nicht etwa stirbt, sondern dass vielmehr systemd ihn aktiv stoppt - etwas, was eigentlich nur dann passieren sollte, wenn irgendjemand systemctl stop <service> eingibt.
Sekunde 27
Die nächste Beobachtung war: Egal, wann der Service per Hand gestartet wird - systemd beendet ihn pünktlich zu Sekunde :27 wieder. Das ist ein Zeitpunkt, der mit keinem Cronjob, keinem Timer erklärbar ist.
Zu diesem Zeitpunkt waren wir an dem Punkt, dass wir gesagt haben: Okay, dieses Verhalten ist vollkommen irre, das gab es nie zuvor, systemd muss sich da an irgendwas ganz grob verschluckt haben (und, ja, das tut es öfter als einem lieb ist, wenn es nicht nur ein paar Services, sondern ein paar tausend Services verwaltet). Bei U7 gehen Reboots signifikant schneller als bei U6, deshalb sagten wir dann, okay, wir kommen nicht weiter, es muss ein Reboot sein.
Nach dem Reboot - im konkreten Fall von pizarro.uberspace.de - stellte sich umgehend exakt die gleiche Situation ein: supervisord@dbcheck wird automatisch gestoppt, und zwar exakt zur Sekunde :27. Alle weiteren supervisord-Instanzen folgten, und zwar exakt das gleiche Set an Usern, deren Config sich - nur um das nochmal zu betonen - in absolut keiner Weise von den anderen Usern unterscheidet, deren supervisord einwandfrei weiterlief.
Dinge, die wir entwickeln, unterliegen intensiven Tests. Jeder Code, den wir auf Hosts deployen, durchläuft automatische Checks: Wir bauen vollautomatisch eine komplette VM (mit Hilfe der GitLab-CI), deployen den aktellen Stand darauf und lassen eine umfangreiche Zahl an Tests darüber laufen. Was allerdings die Distribution angeht, da verlassen wir uns allerdings mehr oder weniger darauf, dass die Dinge eben so funktionieren wie vorgesehen. Red Hat Enterprise Linux bzw. CentOS ist in dieser Hinsicht an sich durchaus für seine Stabilität bekannt und dafür, via Backporting wirklich nur die nötigsten Dinge anzufassen, um Probleme und Schwachstellen zu fixen, so dass Updates hier normalerweise ein echter No-Brainer sind - und wir sie ja auch regelmäßig durchführen, ohne dass es zu Schwierigkeiten kommt.
The d in systemd stands for ‘dammmmit!’
Dennoch waren wir langsam an dem Punkt, dass wir an einen handfesten Bug in systemd zu glauben anfingen, und haben daher auf einem der betroffenen Hosts yum downgrade systemd systemd-sysv systemd-libs ausgeführt. Das Downgrade ist nur ein kleiner Sprung und sollte eigentlich nur Bugfixes enthalten, und auch keine sicherheits-relevanten Dinge. Aber tatsächlich: Nach dem Downgrade lief alles wieder exakt so, wie es sein sollte. Alle supervisord-Instanzen konnten gestartet werden und blieben dann auch gestartet. Dauerhaft - wir haben es noch mehrmals kontrolliert.
Bisher ist es uns nicht gelungen, dem ChangeLog und den dort verlinkten Bugzilla-Einträgen zu entnehmen, was genau hier passiert sein könnte. Ein Fehler unserer systemd-Service-Konfiguration ist zumindest einigermaßen unwahrscheinlich: Die hat sich zwischen Up- und Downgrade ja nicht geändert; das Verhalten von systemd allerdings schon. Eine Funktionalität, bei der systemd ohne Veranlassung von außen beginnt, Services zu stoppen, erscheint auch nicht wirklich ein “Feature” zu sein, sondern eher ein Bug, der sich offenbar eingeschlichen hat und nur unter bestimmten Konstellationen zur Ausführung kommt. Mit unseren systemd-Services in dreistelliger Zahl pro Host sind wir offenbar prädestiniert dafür, in Situationen zu laufen, in die sonst keiner läuft - unter anderem auch dafür, dass ein gleichzeitiger Start aller Services systemd gerne mal in einen Zustand bringt, sich unter so hohen Load zu setzen, dass der Start einzelner Services so lange dauert, dass systemd in einen Timeout läuft, einen automatischen Restart des Services triggert und sich damit manchmal so sehr ins Aus schießt, dass es alle Services im Kreis startet und effektiv gar nicht weiterkommt. Wir haben das inzwischen gelöst, in dem wir die Service-Starts etwas auseinandergedröselt haben, so dass das nun verlässlich funktioniert, aber allgemein: Wenn wir 300 Services starten wollen, sollte systemd uns auch 300 Services starten. Wie lange das dann dauert, steht auf einem anderen Blatt; wenn nach dem Start von 50 Services aber auch nach Minuten des Wartens überhaupt kein weiterer Fortschritt mehr zu ersehen ist, dann kann das kaum akzeptabel sein.
Ein Teil des Problems ist aus unserer Sicht an dieser Stelle aber auch der Umstand, dass die systemd-Version, die Red Hat mit RHEL/CentOS 7 liefert, nicht gerade taufrisch ist: Es ist nämlich die Version 219, aktuell ist systemd 243. Es kann also durchaus sein, dass wir mit systemd-Problemen zu tun haben, die in neueren systemd-Versionen gelöst sind. Auf der anderen Seite bringen neue Versionen eben nicht nur Bugfixes, sondern auch neue Features, sie verändern bestehende Features, sie ersetzen bestehende Features durch andere, was dann wiederum einen Umbau der eigenen Konfiguration bedingt. Red Hat ist daher damit beschäftigt, die systemd-Version, die sie für RHEL7 auserkoren haben, zu pflegen, in dem sie die aus ihrer Sicht relevanten Bugfixes neuerer Versionen backporten, so dass in der Regel Probleme gelöst werden, aber sich nichts Wesentliches am Verhalten verändert. Das ist natürlich ein Job für sich, der aber in der Regel dazu führt, dass man eben Updates “einfach so” machen kann. Auf der anderen Seite liegt es bei Red Hat, zu identifizieren bzw. zu entscheiden, welche Veränderungen an systemd zurückportiert werden und welche eben auch nicht. Im Zweifelsfall können wir schlicht nicht wissen, ob es um ein Problem geht, das bei systemd gelöst ist und Red Hat es nicht zurückportiert hat, oder um ein Problem, das auch die aktuellste systemd-Version noch betrifft. Eine Kern-Komponente einer Linux-Distribution auf eigene Faust durch eine neuere Version zu ersetzen, erschiene uns jedenfalls als noch weitaus problematischer.
Das soll keine Entschuldigung sein: Verantwortlich sind wir letztlich für das Gesamtprodukt, nicht nur für die von uns entwickelten Teile - die Wahl der Distribution und wie wir mit ihr arbeiten, ist ja durchaus unsere Entscheidung. Wir tragen diese Konsequenzen insofern so gut wir können - wir debuggen, schmeißen den Feierabend um, Leute unterbrechen ihren Urlaub, um zu helfen… alles, damit die Sachen wieder laufen, wie sie sollen. Einen unmittelbaren Einfluss darauf haben wir allerdings leider beim besten Willen nicht: Darauf, dass die Distribution tut, was sie soll, müssen wir uns weitestgehend verlassen können. In diesem Fall hieß das dann tatsächlich: einen partiellen Rollback ausführen.
Ausblick
Ein richtiges Fazit muss an dieser Stelle leider ausbleiben. Vermutlich hat systemd bei denen im Team, die es super finden, eine tiefe Schramme mehr bekommen, und das hat natürlich auch Auswirkungen darauf, wie wir unser Hostingprodukt künftig weiterentwickeln. Es ist aber eben auch nicht trivial, systemd durch etwas anderes zu ersetzen - entwickelt es sich doch zunehmend zum De-Facto-Standard mehrerer größerer Distributionen (als selbst Debian und Arch Linux sich für systemd entschieden haben, war im Grunde klar, dass alle anderen Init-Systeme eher zu Randerscheinungen werden), und es ist an sich durchaus in unserem Sinne, dass User die Möglichkeit haben, Linux-Kenntnisse von einer auf die andere Distribution zu übertragen, statt “Ach so, Debian (oder was auch immer), ich kann nur Red Hat (oder was auch immer)” sagen zu müssen. Im Prinzip hätten wir auf dieser Basis auch gerne “systemd user services” anstelle des weniger gebräuchlichen supervisord angeboten, um unsere Prämisse zu folgen, dass man bei uns nicht nur was über Uberspace, sondern über Linux allgemein lernt. Die hat Red Hat allerdings bei RHEL 7 noch explizit rausgepatcht - und wenn wir den heutigen Tag Revue passieren lassen, ist das vielleicht eigentlich auch ganz gut so.
Sich explizit gegen das Init-System des Distributors zu entscheiden, wäre schon gravierend. Andere Init-Systeme bringen natürlich auch ihrerseits wieder eigene Schmerzen mit - und in jedem Fall eine deutlich kleinere Userbasis als systemd, was zwar kein Problem per se ist, aber das führt an dieser Stelle vielleicht etwas weit. Jedoch: Wir brauchen eine Menge Zeit, um Uberspace für euch zu entwickeln - die Hosting-Plattform mit all ihren Features, die Website, die Dokumentation, die diversen Pakete, die nicht in CentOS enthalten sind, die wir aber als wichtig erachten. Und wir schwimmen nicht in Millionen von Risikokapitel, um da einfach mal ein paar Monate Womanpower draufwerfen zu können. Am offenen Herzen operierend das Init-System auszutauschen erscheint da nicht als die beste Idee, auch wenn es uns - das könnt ihr uns gerne glauben - heute mehr dazu in den Fingern juckt als je zuvor. Wir werden sehen, was die Zukunft bringt - und warten jetzt erstmal, was das nächste systemd-Update für Überraschungen bereithält.
Derweil entwickeln wir erstmal kurzfristig einen Check, der genau das, was heute unerwartet passiert ist, künftig zumindest überwacht, damit wir mitbekommen, wenn die supervisord-Instanzen einzelner User aus unerfindlichen Gründen plötzlich stoppen, um daraufhin entsprechend eingreifen zu können.