“Irgendwas ist mit dem Caddy instabil geworden seit dem Logs-Update”. Es sind Nachrichten wie diese, die man während einer laufenden Alpha-Version eigentlich nicht mehr lesen möchte. Schon gar nicht, wenn das, was man zuletzt als Änderung deployed hat, letztlich nur ein paar Zeilen Config waren, um mehr Logging zu aktivieren - und die sollen plötzlich dazu führen, dass allein der Start von Caddy plötzlich so lange dauert, dass er in einen Timeout läuft?

Spoiler: Es waren letztlich gar nicht die Logs.

Aber der Reihe nach, ausgehend vom Symptom. Was wir zunächst einmal festgestellt haben, ist dieses:

[root@theia ~]# time systemctl reload caddy
Job for caddy.service failed because a timeout was exceeded.
See "systemctl status caddy.service" and "journalctl -xeu caddy.service" for details.

real	1m31.195s
user	0m0.009s
sys	0m0.010s

Im Journal steht … absolut nichts, was hier eine Erklärung liefern könnte. Also muss die Wunderwaffe aller Sysadmins ran: strace. Und das zeigt, dass sich Caddy sehr lange mit dem Lesen dieser Informationen aufhält:

[...]
read(3, "r:58153 - nsfs nsfs rw\n177903 17"..., 1024) = 1024
read(3, "sfs rw\n177912 177726 0:4 net:[40"..., 1024) = 1024
read(3, "1 177680 0:4 net:[4026532538] /r"..., 1024) = 1024
read(3, "net:[4026532836] /run/systemd/mo"..., 1024) = 1024
read(3, "systemd/mount-rootfs/run/netns r"..., 1024) = 1024
read(3, "kal_ns rw master:58153 - nsfs ns"..., 1024) = 1024
read(3, "run/systemd/mount-rootfs/run/net"..., 1024) = 1024
read(3, "unt-rootfs/run/netns/nxt8cld_ns "..., 1024) = 1024
read(3, "netns/ba8kal_ns rw master:58153 "..., 1024) = 1024
[...]

File descriptor 3 ist in diesem Fall /proc/1845/mountinfo, und in dieser Datei stehen normalerweise ein paar Dutzend Zeilen drin, die ganzen System-Mounts von /proc, /sys, /dev, das Root-Blockdevice und je nach Distribution noch ein paar weitere Mounts für Kernel- und systemd-Geschichten. Auf meinem lokalen Laptop zum Beispiel sind es 26:

jonas@laptop:~$ wc -l /proc/self/mountinfo
26 /proc/self/mountinfo

Und auf unserem Test-Host müssten es bestimmt ähnlich viele sein - oder?

[root@theia ~]# wc -l /proc/self/mountinfo
32576 /proc/self/mountinfo

Äh, ja. Das soll wohl nicht so sein. Was steht denn da bitte drin? Stellt sich raus:

Sehr, sehr viele netns-Einträge.

netns, das bezieht sich auf “Network Namespaces”. Wir benutzen dieses Feature, um den Netzwerkverkehr von Usern untereinander abzuschotten: Einerseits können so zwei User beiden den gleichen Port in ihrem jeweiligen Network Namespace belegen und als Web Backend exponieren; andererseits wird verhindert, dass der rein interne Port für andere User auf dem jeweiligen Host “hintenrum” erreichbar ist. Wir nutzen bei uns konkret pam_isolate, was die Network Namespaces für die User anlegt.

Hier ein kleines Beispiel, wie das normalerweise in der Mount-Tabelle so aussieht, wenn man Network Namespaces anlegt, hier exemplarisch einfach mal mit ip netns add. Übrigens, wer mehr darüber erfahren möchte, was hierbei dann im Hintergrund passiert, dem sei dieser wunderbare Blogpost empfohlen: What does ip netns add actually do? - für mich waren die darin enthaltenen Details jedenfalls sehr hilfreich beim Debugging dieses Problems. Aber nun erstmal zum Beispiel:

jonas@laptop:~$ sudo ip netns add hund_ns
jonas@laptop:~$ sudo ip netns add katze_ns
jonas@laptop:~$ sudo ip netns add maus_ns

Ergebnis:

jonas@laptop:~$ mount | grep netns
tmpfs on /run/netns type tmpfs (rw,nosuid,nodev,noexec,relatime,size=196528k,mode=755,inode64)
nsfs on /run/netns/hund_ns type nsfs (rw)
nsfs on /run/netns/hund_ns type nsfs (rw)
nsfs on /run/netns/katze_ns type nsfs (rw)
nsfs on /run/netns/katze_ns type nsfs (rw)
nsfs on /run/netns/maus_ns type nsfs (rw)
nsfs on /run/netns/maus_ns type nsfs (rw)

Es gibt also einen “Basis-Mountpoint” /run/netns (den es vorher nicht gab, der aber beim Anlegen des ersten Network Namespaces entsteht), und dann pro angelegtem Network Namespace zwei Mounts. Und wieviele sind es auf unserem Test-Host?

[root@theia ~]# grep test_ns /proc/self/mountinfo | wc -l
3612

Gut, da läuft also was grandios falsch. Einfach mal rebooten.

Zu diesem Zeitpunkt wussten wir noch nicht, dass es gerade der Reboot war, mit dem wir uns den beobachteten Effekt überhaupt erst initial eingetreten hatten. Aber das Puzzle setzt sich gleich zusammen, keine Sorge.

Die Antwort ist 42, aber nicht immer

Nach dem Reboot hatte jeder Asteroid 42 Mounts. Immerhin, weniger als 3612. Aber eben auch viel mehr als die 2, die wir erwartet hatten.

Egal, wie oft wir dann Network Namespaces per Hand gelöscht und wieder angelegt haben: Es waren immer 42 Mounts. Zu dem Zeitpunkt hatten wir noch die Theorie, dass es vielleicht einfach immer mehr werden, weil wir irgendwo was nicht richtig weggeräumt haben und beim Booten zusätzliche angelegt werden. Also:

Reboot.

Reboot.

Reboot.

Am Anfang waren die Zahlen noch lustige Überraschungen. Wir hatten ja die 3612 vom Ausgangszeitpunkt. Wir hatten die 42. Dann hatten wir 1806. Dann nochmal 42. Dann auch mal 6. Aber niemals 2. Es war zum Mäusemelken.

Um das Ganze noch schlimmer zu machen, haben wir dann plötzlich bemerkt, dass für einige Asteroids auch die zugehörigen Network Namespaces fehlten, was in der Praxis bedeutet, dass ihr Web-Stack dann nicht erreichbar ist. Frisch aufgesetzte Test-Hosts, drei Asteroids angelegt: Alles funktioniert wunderbar. Einmal rebootet: Von den drei Asteroids haben nur einer oder zwei ihren jeweiligen Network Namespace - den dann aber 42 Mal oder je nachdem wieviel der Zufall sich nun gerade ausgedacht hatte. Und im Log des Bootvorgangs findet sich für die Asteroids, wo der Network Namespace fehlt, dieser obskure Eintrag:

Jul 17 00:28:53 moondust.uberspace.de systemd-executor[539]: [pam_isolate] Starting network setup
Jul 17 00:28:53 moondust.uberspace.de systemd-executor[539]: [pam_isolate] Checking if veth_1002_out already exists from a previous user
Jul 17 00:28:53 moondust.uberspace.de systemd-executor[539]: mkdir error: EEXIST: File exists
Jul 17 00:28:53 moondust.uberspace.de systemd-executor[539]: [pam_isolate] open_session: Namespace error mkdir error: EEXIST: File exists

“mkdir error: EEXIST: File exists”. Hm.

Ratet, was nirgendwo im gesamten Sourcecode von pam_isolate steht: Richtig, mkdir.

jonas@laptop:/tmp/pam_isolate$ grep -r mkdir . | wc -l
0

Zu diesem Zeitpunkt hatte ich das mental zurückgestellt, denn immerhin: Wenn wir die systemd-User-Instanzen der Asteroids, denen die gefehlt haben, neu gestartet haben, dann hatten auch die ihren Network Namespace. Nur eben 42 Mal. Oder wie oft auch immer.

Nach einigen Reboots haben wir dann schließlich bemerkt: Die Anzahl ist nicht völlig zufällig. Wenn es nicht die erwarteten 2 Mounts sind, dann sind es entweder 6, oder 42, oder 1806.

Es geht um die Basis

Im Nachhinein betrachtet, weiß ich nicht, wieso uns das nicht früher aufgefallen ist, aber: In den betreffenden Situationen gab es auch den Basis-Mountpoint /run/netns nicht nur ein einziges Mal, sondern 5, 41 oder 1805 Mal. Es erschien insofern plötzlich naheliegend, dass es die Mounts der einzelnen Network Namespaces viel öfter als erwartet gab, in direktem Zusammenhang damit steht, wie oft es den Basis-Mountpoint gab. Und das brachte uns auf eine Idee: Wenn wir nach dem Löschen aller Network Namespaces auch den Basis-Mountpoint /run/netns selbst löschen (und nach einem einzigen umount /run/netns sind immer gleich alle davon weg, egal wieviele) und dann wieder anfangen, die systemd-User-Instanzen zu starten, dann… ist das Problem plötzlich weg.

Und plötzlich setzte sich im Kopf diese Beobachtung mit den vielen Basis-Mountpoints mit dem mkdir error: EEXIST: File exists zusammen: Gibt es hier vielleicht eine Race Condition? Im Sourcecode von iproute2 (zu dem Paket gehört der Befehl ip aus dem ip netns add ...) jedenfalls nicht: Da wird ein mkdir gemacht, und da wird spezifisch der Fehler EEXIST einfach ignoriert:

	/* Create the base netns directory if it doesn't exist */
	if (mkdir(NETNS_RUN_DIR, S_IRWXU|S_IRGRP|S_IXGRP|S_IROTH|S_IXOTH)) {
		if (errno != EEXIST) {
			fprintf(stderr, "mkdir %s failed: %s\n",
				NETNS_RUN_DIR, strerror(errno));
			return -1;
		}
	}

Der Code läuft also in jedem Fall durch (solange nichts anderes beim Anlegen schiefgegangen ist). Aber pam_isolate ist in Rust geschrieben und benutzt das rtnetlink-Modul, und da sieht’s etwas anders aus:

203        if nix::sys::stat::stat(dir_path).is_err() {
204            if let Err(e) = nix::unistd::mkdir(dir_path, mkdir_mode) {
205                log::error!("mkdir error: {}", e);

Also ein klassisches “schau nach, ob das Verzeichnis da ist, und wenn nicht, dann leg es an” - aber wenn das Verzeichnis nach der Prüfung, ob es da ist (bei der es nicht da ist) von jemand anderem angelegt wird: Dann schlägt das fehl. mkdir error: EEXIST: File exists eben.

Und wenn das Anlegen aber geklappt hat und dann jetzt mit dem Mounten weitergemacht wird, da gibt es natürlich die gleiche Race Condition in grün, nur dass ein weiteres mount nicht abbricht, sondern es wird einfach durchgeführt und dann ist der Mountpoint eben ein weiteres Mal da. Aber damit nicht genug: Wenn es den Ursprungsmountpoint mehrfach gibt, dann passiert das eben auch bei jedem Durchlauf gleich mehrfach:

[root@archlinux ~]# mount | grep test
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
[root@archlinux ~]# mount --bind /test /test
[root@archlinux ~]# mount | grep test
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
[root@archlinux ~]# mount --bind /test /test
[root@archlinux ~]# mount | grep test
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
[root@archlinux ~]# mount --bind /test /test
[root@archlinux ~]# mount | grep test
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)
tmpfs on /test type tmpfs (rw,nosuid,nodev,nr_inodes=1048576,inode64)

Ein Riesenspaß!

Wenn ein Reboot das Problem erst auslöst

Damit wurde dann aber auch klar, wieso das Problem bisher nicht aufgefallen ist: Wir hatten das Network-Namespace-Feature bisher erstmal nur für die SSH-Zugänge aktiviert, sprich, der Network Namespace ist erst beim ersten Login passiert - und der passiert ja eben erst dann, wenn irgendein User sich aktiv einloggt, und dann nur für diesen User. Und als wir pam_isolate dann auch für die systemd-User-Instanzen aktiviert haben, haben wir die User-Services nacheinander durchgetreten, und auch da hat alles funktioniert.

Erst als wir den Host rebootet haben, wurde schließlich die Situation ausgelöst, dass beim Booten systemd in hoher Parallelität alle systemd-User-Instanzen gleichzeitig zu starten versucht - und dann schlagen die Race Conditions aus dem rtnetlink-Modul gnadenlos zu: Die beim mkdir in der Form, dass dann User gar keinen Network Namespace haben, und die beim (blinden) Mounten, die bereits bestehende Mountpoints vervielfacht.

Es steckt leider kein echter Mathematiker in mir, wenngleich ein bisschen Neugierde für die interessante Zahlenfolge 2, 6, 42, 1806, … dennoch vorliegt. Das Internet hilft begrenzt und kann zumindest erklären, dass das passiert, wenn man eine Zahl wiederholt mit der darauffolgenden Zahl multipliziert, also n * (n+1). So kommt man von 2 über 2*3 auf 6, von 6 über 6*7 auf 42, von 42*43 auf 1806… aber das würde in unserem Fall implizieren, dass es irgendeine Komponente gibt, die einen weiteren Mount pro bestehend Mountpoint durchführt und dabei jedes Mal die jeweilige Basiszahl an Mountpoints hinzufügt. Außerdem hatten wir bei unserer initialen Beobachtung ja 3612 Mounts vorgefunden, was zwar das Doppelte von 1806 ist, aber in der Folge hätte nach 1806 eigentlich 1806*1807 = 3263442 folgen müssen… es bleibt rätselhaft. In einer Folge von Verdoppelungen wären ja umgekehrt keine Werte von 6 oder 42 zustandegekommen. Vielleicht treffen hier insofern einfach zwei unterschiedliche Phänomene zusammen. So ganz auf die Schliche gekommen sind wir diesem Detail bislang nicht, aber wichtiger für uns war dann erstmal einen Fix für die Situation zu finden.

Ein Pflaster, das ganz trivial hilft

Da jeder Asteroid und damit jeder Network Namespace eindeutig ist und auch nur einmal angelegt wird, haben wir da keine Race Condition; die bezieht sich ausschließlich auf das Basis-Verzeichnis /run/netns. Also müssen wir irgendwie vorziehen, dass es /run/netns gibt, bevor die systemd-User-Instanzen starten, denn wenn das /run/netns schon da ist, versucht ja niemand, es ein weiteres Mal anzulegen.

Unser Workaround ist nun ein simpler oneshot-Service, der explizit vor den systemd-User-Instanzen gestartet wird und schlichtweg einen Network Namespace anlegt und wieder löscht, womit ein funktionierendes /run/netns zurückbleibt (das erschien uns letztlich einfacher, als die nötigen Schritte einzeln per Hand oder mit einem eigenen Tool nachzubilden). So sieht’s aus:

[root@moondust ~]# cat /etc/systemd/system/netns-init.service
[Unit]
Description=Initialize /run/netns via dummy network namespace
DefaultDependencies=no
Before=basic.target user@.service

[Service]
Type=oneshot
ExecStart=/usr/bin/ip netns add dummy_init_ns
ExecStartPost=/usr/bin/ip netns delete dummy_init_ns
RemainAfterExit=yes

[Install]
WantedBy=sysinit.target

Nach mehreren Reboots eines Hosts, der bis dahin immer das Malheur aufgewiesen hatte und das nun in keinem Fall mehr tat, konnten wir mit diesem Workaround dieses Issue schließen und uns endlich wieder um die featuretechnische Weiterentwicklung der U8-Alpha machen.

Foto von Kaden Taylor auf Unsplash

• ← Vorheriger Post
• Nächster Post →