Error getting authority: Timeout reached (g-io-error-quark, 24)
systemd ist ja ganz schön geil, finden wir. systemd kann einen ganz schön in den Hintern beißen, finden wir auch. So ist uns das gestern Nacht auf dem U7-Host kohoutek passiert. Warum der Host zwei Stunden lang nicht vollständig erreichbar war könnt ihr hier nachlesen.
Am 08.01. haben wir ein vergleichsweise großes Update für das Netzwerk-System unserer Hosts sowie unsere HTTP-nginx/httpd-Infrastruktur ausgerollt. Mehr dazu in einem weiteren Blogpost in den nächsten Tagen. Die allermeisten Hosts haben das gut vertragen, nicht aber kohoutek: Der reagierte nicht mehr auf SSH und die Serielle Console der VM war auch nur schwierig zu erreichen.
Wenn Hosts gar nicht mehr reagieren bleibt uns oft nichts anderes übrig als zu rebooten. Entweder das Problem löst sich dadurch von alleine oder der Reboot verschafft uns genug Zeit für eine tiefere Anaylse. Also haben wir auch hier ein beherztes virsh reboot kohoutek abgesetzt.
Anders als U6-Hosts rebooten U7-Hosts innerhalb weniger Minuten, manchmal sogar in unter einer. Nicht jedoch in diesem Fall. Auch nach 10 Minuten ließ sich der Host nicht via SSH erreichen. Ein Blick in die Console war eher ernüchternd:
[FAILED] Failed to start Login Service
So spontan war mir nicht klar, was genau der systemd Login Service tut, klang aber wichtig. Nach kurzer Recherche war dann auch klar: Ja, ist wichtig und sollte eigentlich in jedem Fall laufen. Vielleicht ist irgendwo ein Bit umgefallen und noch ein Reboot löst das Problem, aber, nein: Selbes Ergebnis.
Also, ran ans Werk! Die üblichen Verdächtigen wie systemctl status systemd-logind funktionierten zwar, wurden aber von eher, sagen wir mal “intern klingenden”, Fehlermeldungen begleitet:
[root@kohoutek ~]# systemctl status systemd-logind
Error getting authority: Error initializing authority: Error calling (...) for org.freedesktop.PolicyKit1: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.freedesktop.PolicyKit1': timed out (g-dbus-error-quark, 20)
(...)
Nach ein bisschen Hin und Her hat sich systemd dann zu einer Ausgabe überreden lassen:
[root@kohoutek ~]# systemctl status systemd-logind
● systemd-logind.service - Login Service
Loaded: loaded (/usr/lib/systemd/system/systemd-logind.service; static; vendor preset: disabled)
Active: inactive (dead) since Tue 2019-01-08 19:10:52 UTC; 2m ago
Process: 41222 ExecStart=/usr/lib/systemd/systemd-logind (code=exited, status=1/FAILURE)
Main PID: 41222 (code=exited, status=1/FAILURE)
Status: "Shutting down..."
Tja, ist also kaputt. Erstmal wenig aufschlussreich.. was sagt denn das Journal?
[root@kohoutek ~]# journalctl -f
(...)
systemd[1]: Starting Login Service...
systemd[1]: systemd-logind.service: main process exited, code=exited, status=1/FAILURE
systemd[1]: Failed to start Login Service.
systemd[1]: Unit systemd-logind.service entered failed state.
systemd[1]: systemd-logind.service failed.
systemd[1]: systemd-logind.service has no holdoff time, scheduling restart.
systemd[1]: Starting Login Service...
Unser logind startet also, failt dabei, probierts in der nächsten Sekunde wieder und failt dabei wieder. Hinweise auf die Ursache dieses Fails finden sich im Log aber auch keine. Egal, vielleicht reicht das ja schon um Leidensgenossen im Internet zu finden. Dabei kamen mehrere Kandidaten wie diverse SELinux-Probleme und ziemlich verzweifelte Arch-User auf, allerdings nichts, das uns an dieser Stelle weiterbringt. Wir brauchen also mehr Infos.
Ohne sinnvolle Meldungen im journal und ohne ein Service-Log in /var/log blieb dann nur noch Jonas’ ständiger Begleiter und Wunderwaffe: strace(1)! Schnell an einen gerade-noch-so-lebenden logind-Prozess gehängt uuund …
[root@stardust ~]# strace -s 1000 -p 41222
sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=3\nSYSLOG_FACILITY=4\nCODE_FILE=src/login/logind.c\nCODE_LINE=681\nCODE_FUNCTION=manager_connect_bus\nSYSLOG_IDENTIFIER=systemd-logind\n", 139}, {"MESSAGE=", 8}, {"Failed to enable subscription: Connection timed out", 51}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 199
sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=3\nSYSLOG_FACILITY=4\nCODE_FILE=src/login/logind.c\nCODE_LINE=1172\nCODE_FUNCTION=main\nERRNO=110\nSYSLOG_IDENTIFIER=systemd-logind\n", 135}, {"MESSAGE=", 8}, {"Failed to fully start up daemon: Connection timed out", 53}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 197
Aha! Eine Fehlermeldung! Warum die trotz einer offensichtlichen Weiterleitung an journald bzw. syslog nicht sichtbar war, wissen wir bis heute nicht. Das Stichwort Failed to fully start up daemon: Connection timed out führte uns dann aber schnell zum systemd Bug #1505: wenn zu viel auf ein Mal startet, läuft eine Messagequeue voll, irgendetwas blockt und der logind überlebt die Geschichte nicht.
In dem Issue ist von “16 unit startups in parallel” die Rede. Wir starten jedoch für jede Userin drei Services und damit insgesamt auch gerne Mal an die Tausend. Das war bisher kein Thema, jedoch scheinen ältere systemd-Versionen (wie die 219 von CentOS 7) hier noch unter Wachstumsschmerzen zu leiden. Wir müssen also zumindest temporär unsere 1.000 Units loswerden. Da das systemctl-Utility nicht verlässlich und vor allem nur unglaublich langsam funktioniert hat, ausnamsweise mit dem Holzhammer:
[root@stardust ~]# rm -f /etc/systemd/system/multi-user.target.wants/php-fpm@*
[root@stardust ~]# rm -f /etc/systemd/system/multi-user.target.wants/supervisord@*
Anschließend: Reboot, Daumen drücken und Tee trinken.
[root@kohoutek ~]# reboot
Error getting authority: Error initializing authority: Error calling StartServiceByName for org.freedesktop.PolicyKit1: Timeout was reached (g-io-error-quark, 24)
Failed to start reboot.target: Connection timed out
See system logs and 'systemctl status reboot.target' for details.
(diese Antwort auf “ey, reboot mal” fanden wir künstlerisch wertvoll.)
Nach einer für U7 typischeren Wartezeit von <2 Minuten war der Host dann auch wieder via SSH erreichbar. Der systemd-logind.service hat auch ohne Murren gestartet. Was natürlich nicht lief waren die Services aller User. Ein Uberspace-Host ohne User ist vergleichsweise langweilig, also, nochmal mit euren Services:
[root@kohoutek ~]# uberspace-run-for-users ln -s /etc/systemd/system/php-fpm@.socket /etc/systemd/system/multi-user.target.wants/php-fpm@UU.socket
[root@kohoutek ~]# uberspace-run-for-users ln -s /etc/systemd/system/supervisord@.service /etc/systemd/system/multi-user.target.wants/supervisord@UU.service
[root@kohoutek ~]# reboot
Und siehe da: Alles wieder gut :)
und jetzt?
Bisher schieben wir die User-Services schlicht mit dem ansible-Äquivalent von systemctl enable supervisord@blafoo.service in den “Autostart”. Dabei landen sie im multi-user.target und konkurrieren dort anscheinend zumindest mittelbar mit kritischen Services wie systemd-logind. Das ist nicht gerade elegant. Wir werden uns hier anschauen, ob wir die Services in ein späteres oder eigens definiertes Target schieben können. Unter Umständen hilft uns auch schon ein after=systemd-logind aus der Patsche.
In jedem Fall werden wir daran arbeiten diese beiden Welten besser zu entkoppeln, so dass dieser Bug uns (und euch) nicht ein zweites Mal beißen kann.