(Grosses Vorbild für diesen (ebenso grossen) Artikel: Anatomy of a Bug – lesenswert! Fazit: Microsoft sucks, as always)

Den letzten Dienstag-Nachmittag wollte ich ursprünglich vollständig meinem Vortrag vom Donnerstag widmen. Leider kam ich nur etwa eine Stunde dazu, danach hielt mich mein Debian-Server bis in die frühen Morgenstunden in Schach.

Vorneweg muss ich sagen, dass mein Server seit Jahren zufriedenstellend läuft. Er ist es, dem ich die Faszination für Linux zu verdanken habe. Er ist es auch, der mich über meinen Windows-Horizont hinausblicken liess und mir zeigte, wie schön, kontrollierbar und funktionell die Welt ausserhalb von Redmond ist.

Letzten Dienstag passierte aber zum ersten Mal (seit ich mich erinnern kann) die Nagelprobe schlechthin. Obwohl ich durch die Jahre hinweg viel über das Funktionieren von Linux gelernt hatte, stand ich zum ersten Mal vor einem unüberwindbaren Berg. Vorerst. Ohne fremde Hilfe bekam ich die Kiste nicht mehr ordnungsgemäss zum Laufen. Was war vorgefallen?

Erste unerklärliche Symptome

Alles begann damit, dass ich wieder einmal das System auf den neuesten Stand bringen wollte. apt-get update, danach apt-get upgrade. Alles verlief wie am Schnürchen, bis bei der Installation des letzten Paketes ssl-cert etwas aus dem Ruder lief:

apt-get upgrade
Setting up ssl-cert (1.0.12) ...

Nach etwa fünf Minuten des Wartens begann ich mich zu fragen, wieso das Paket immer noch nicht fertig installiert war. Natürlich hatte ich das Update in keiner screen-Session gestartet, was die Fehlersuche erschwerte: Ich konnte nicht schnell mal mit Ctrl-A-D in ein verfügbares Shell wechseln und entschied mich deshalb für Ctrl-C, was die Installation abbrach.

Gruppen erstellen schlägt fehl

Ein zweiter Login-Versuch per SSH schlug aus unerklärlichen Gründen fehl. Komisch. Ich vermutete, dass dies mit dem nicht installierten ssl-cert zusammenhing (ssl und ssh haben ja beide die Verschlüsselung gemeinsam). Indem ich das Paket richtig installierte, wollte ich dieses b-Problem lösen. Doch erneut hängte sich die Installation an derselben Stelle auf. Was war da nur los? Ich nahm die Fehlermeldung, die apt-get ausspuckte, genauer unter die Lupe:

addgroup: `/usr/sbin/groupadd -g 111 ssl-cert' exited from signal 2.  Aborting.

So so, das Installations-Script konnte keine Gruppe erstellen? Wieso denn das?

Als erstes fasste ich Platzprobleme ins Auge. df -h – sah alles nicht besorgniserregend aus. / (Root) verfügte vielleicht noch 20MB freien Speicher – zu wenig? Konnte das Hinzufügen einer Gruppe wirklich 20MB mit temporären Daten füllen? Ich löschte deshalb vorsorglich rm -R /usr/share/doc/; ein Verzeichnis, das via einer Google-Suche als vernachlässigbar taxiert wurde. Mit über 100MB an freiem Speicher machte ich mich erneut an die Installation.

Leider brachte dies nichts, wieder hängte sich die Installation, wieder mit derselben Meldung. Hatte die Kiste etwa ihre Tage?

Nun gut, gab es vielleicht ein generelles Problem mit dem Hinzufügen von Gruppen? In der Tat: groupadd resp. addgroup hängten beide, wenn ich manuell eine neue Gruppe hinzufügen wollte!

Als Linux-Kenner weiss man ja, dass die Datei /etc/group eine – wie in der Unix-Tradition üblich – simple Textdatei war. Ich fügte also mittels vim eine neue Zeile am Ende ein:

ssl-cert:x:110

Eine erneute Installation funktionierte nun.

Nicht zu vergessen sind übrigens auch (group|shadow).lock-Dateien, die als Überbleibsel noch vorhanden sein können. Ich habe solche einige Male gelöscht, weiss aber rückblickend nicht, ob dies einen Einfluss auf die Problematik gehabt hat.

sshd spinnt

Mir war es weiterhin nicht möglich, eine zusätzliche SSH-Verbindung aufzubauen. Langsam beschlich mich ein ungutes Gefühl. Was war hier nur los? Ein Neustart des Daemons mittels /etc/init.d/ssh restart brachte nichts. (Nebenbemerkung: Fantastisch, wie das im guten alten Linux funktioniert! Obwohl ich den Daemon abschoss und neu startete, blieb meine Terminal-Sitzung selbstverständlich bestehen. Man stelle sich dies bei Microsoft Windows vor. Unmöglich! Entweder hätte man den Server sowieso bereits zehn Mal neu starten müssen, um so weit zu kommen, oder aber zumindest die Terminal-Sitzung wäre gekappt worden).

Nach dem Neustart des Daemons lauschte nicht mal mehr jemand auf Port 22 … Ziel jetzt: Die einzige noch bestehende Verbindung zum Server nicht verlieren. Ich wollte verhindern, den 15″ CRT in die Stube tragen und an den KVM-Switch anschliessen zu müssen.

Okey – was könnte mir helfen, den Fehler einzugrenzen? Langsam aber sicher vermutete ich ein Problem mit der Benutzerverwaltung. Denn per Zufall entdeckte ich, dass auch ein su mario hängen blieb. Keine Gruppen mehr hinzufügbar, kein su, kein SSH-Login – diese Dinge hatten alles mit Nutzern zu tun.

Prozess-Flut

Ein intuitiver Blick in die Liste der Prozesse (ps ax) offenbarte mir ein grauenhaftes Bild. Unzählige /USR/BIN/CRON-Prozesse standen da aufgelistet, die sich nicht freiwillig beenden lassen wollten.

Im Netz fand ich die Lösung, wie ich unzählige Prozesse mit einem Einzeiler abschiessen konnte:

ps ax | grep CRON | awk '{print $1}' | xargs kill -HUP

BTW: Ich liebe Pipes (tönt wieder neunmalklug, nicht?)

Leider behob die Terminierung der Prozesse meine Probleme nicht.

Ein Neustart des Systems (zu besten Zeiten über 100 Tage Uptime *snüff*) wurde unausweichlich …

Doch weder ein shutdown now noch ein reboot per SSH brachten den Server zum Herunterfahren. Zwar ging der Hinweis an alle User über die Konsole, aber auch nach drei Minuten stand meine SSH-Verbindung noch.

Wäre der Neustart schon traurig genug gewesen, nun musste ich also tatsächlich noch den Monitor in die Stube tragen und an den Server anschliessen, um die Kiste von der physischen Konsole aus herunterzufahren.

Nach dem Kraftakt kam der Schreck: Ich konnte mich auf via Keyboard nicht mehr einloggen. Das Passwort wurde zwar akzeptiert, doch auch hier hing das System. Ich las zwar „You have new mail“, doch weiter kam ich nicht. Mit Drücken von Ctrl-C gelangte ich zwar wieder in die Login-Maske, aber das war ja eigentlich nicht gewünscht …

Ein Druck auf den Reset-Knopf am Gehäuse bereitete der Odyssee ein Ende.

Problems? Linux: Be Root, Windows: Reboot

Nicht ganz, leider:

 3295 ?        S      0:00 /USR/SBIN/CRON
 3297 ?        S      0:00 /USR/SBIN/CRON
 3298 ?        S      0:00 /USR/SBIN/CRON
 3303 ?        S      0:00 /USR/SBIN/CRON
 3307 ?        S      0:00 /USR/SBIN/CRON
 3308 ?        S      0:00 /USR/SBIN/CRON
 3309 ?        S      0:00 /USR/SBIN/CRON
 3316 ?        S      0:00 /USR/SBIN/CRON
 3325 ?        S      0:00 /USR/SBIN/CRON
 3579 ?        Ss     0:00 sshd: bittorrent [priv]
 3581 ?        Z      0:00 [sshd] 
 3640 ?        S      0:00 /USR/SBIN/CRON
 3641 ?        S      0:00 /USR/SBIN/CRON
 3642 ?        S      0:00 /USR/SBIN/CRON
 3643 ?        S      0:00 /USR/SBIN/CRON
 3644 ?        S      0:00 /USR/SBIN/CRON
 4569 ?        S      0:00 /USR/SBIN/CRON
 4570 ?        S      0:00 /USR/SBIN/CRON
 4571 ?        S      0:00 /USR/SBIN/CRON
 4572 ?        S      0:00 /USR/SBIN/CRON
 4573 ?        S      0:00 /USR/SBIN/CRON
 4574 ?        S      0:00 /USR/SBIN/CRON
 4658 ?        S      0:00 /USR/SBIN/CRON
 4659 ?        S      0:00 /USR/SBIN/CRON
 4660 ?        S      0:00 /USR/SBIN/CRON
 4661 ?        S      0:00 /USR/SBIN/CRON
 4662 ?        S      0:00 /USR/SBIN/CRON
 4663 ?        S      0:00 /USR/SBIN/CRON
 4664 ?        S      0:00 /USR/SBIN/CRON
 4737 ?        S      0:00 /USR/SBIN/CRON
 4738 ?        S      0:00 /USR/SBIN/CRON
 4739 ?        S      0:00 /USR/SBIN/CRON
 4740 ?        S      0:00 /USR/SBIN/CRON
 4741 ?        S      0:00 /USR/SBIN/CRON
 4752 ?        S      0:00 /USR/SBIN/CRON
 4753 ?        S      0:00 /USR/SBIN/CRON
 4754 ?        S      0:00 /USR/SBIN/CRON
 4755 ?        S      0:00 /USR/SBIN/CRON
 4756 ?        S      0:00 /USR/SBIN/CRON
 4757 ?        S      0:00 /USR/SBIN/CRON
 4758 ?        S      0:00 /USR/SBIN/CRON
 4759 ?        S      0:00 /USR/SBIN/CRON
 4760 ?        S      0:00 /USR/SBIN/CRON
 4761 ?        S      0:00 /USR/SBIN/CRON
 4762 ?        S      0:00 /USR/SBIN/CRON
 4763 ?        S      0:00 /USR/SBIN/CRON
 4764 ?        S      0:00 /USR/SBIN/CRON
 4765 ?        S      0:00 /USR/SBIN/CRON
 4766 ?        S      0:00 /USR/SBIN/CRON
 4767 ?        S      0:00 /USR/SBIN/CRON
 4768 ?        S      0:00 /USR/SBIN/CRON
 4779 ?        S      0:00 /USR/SBIN/CRON
 4780 ?        S      0:00 /USR/SBIN/CRON
 4781 ?        S      0:00 /USR/SBIN/CRON
 4782 ?        S      0:00 /USR/SBIN/CRON
 4783 ?        S      0:00 /USR/SBIN/CRON
 4784 ?        S      0:00 /USR/SBIN/CRON

Böser cron?

Der Täter schien gefasst: cron! Wieso nur? Und bei welchem Eintrag in der /etc/crontab verschluckte er sich?

Nach und nach schaltete ich Zeile für Zeile ab, dennoch wurden in der Zeit mehrere Reboots nötig: Immer wieder begann das System zu zicken. Immerhin fand ich mit der Zeit heraus, dass ein /etc/init.d/reboot stop einen softwaremässigen Reboot auslöste. Der Gang zum Server entfiel.

Ich fand in dieser Übung heraus, dass es unzählige Orte gibt, wo cron-Jobs abgelegt werden:

/etc/crontab
/etc/cron.d
/etc/cron.hourly
/etc/cron.daily
/etc/cron.weekly
/etc/cron.monthly
/var/spool/cron/crontabs/<username>

Da die zeilenweise Aktivierung/Deaktivierung nicht den gewünschten Effekt brachte, verschob ich nach und nach jedes einzelne Verzeichnis. Schlussendlich liefen gar keine Cron-Jobs mehr. Das war überaus unbefriedigend. Vorbeugend entschied ich mich, in /etc/init.d/cron ein exit 0 einzubauen, um den Daemon bei den gehäuften Reboots standardmässig nicht mehr zu starten.

lsof und strace

Welcher cron-Job nicht zu Ende geführt werden konnte, entzog sich meiner Kenntnis. Was ich aber genauer analysieren konnte waren die einzelnen Prozesse. lsof, das ich vor wenigen Tagen entdeckt hatte, half aber nicht gross weiter. Mehr versprach ich mir von strace. Ein Tool, das es erlaubt, laufende Prozesse zu analysieren. Auch dies half mir vorerst nicht weiter.

Schlaf

Mittlerweile hatte es Mitternacht geschlagen – der Server lief mehr oder weniger produktiv, verrichtete seine Arbeit und liess mich auch wieder einloggen oder sulen. Das Problem resp. dessen Ursache war zwar noch nicht behoben, ich hatte das System aber zumindest wieder so weit, dass ich damit anständig arbeiten konnte.

syslog-ng!

Dem Mailverkehr mit Kollege Liechti nach zu urteilen hatte ich die Ursache um spätestens 10:32 Uhr des nächsten Tages eingekreist: syslog-ng, der Syslog-Daemon. Nicht der Cron-Daemon war es, der die /USR/SBIN/CRON nicht beenden liess, sondern syslog-ng! Mein Verdikt im breitesten Berndeutsch:

Sit ig das Scheiss-Ding deaktiviert ha, chani eich ume jede cron-job la loufe, woni ufem System finge. Si hängesech nüm.

Mit strace fand ich später heraus, dass tatsächlich dieses ominöse /dev/log die Hänger verursachte:

connect(7, {sa_family=AF_FILE, path="/dev/log"}, 16")

meldete das Debugging-Tool.

/dev/log am Arsch

Ich stiess im Laufe der Recherche über /dev/log auf die Mailing-Liste von syslog-ng und verfasste einen Symptombeschrieb.

Etwas später entdeckte ich in derselben Liste eine Person, die genau mit demselben Problem zu kämpfen hatte.

Ich erhielt einige Antworten auf meine Anfrage, worunter sich auch der hauptsächliche Entwickler Balazs Scheidler zu Wort meldete und auf einen seiner früheren Posts verwies:

It came to my attention that syslog-ng 1.6.10 broke file(„/proc/kmsg“)
support with the recent performance improvement patches as /proc/kmsg
does not support nonblocking mode.

The issue might cause the complete system to deadlock. Non-Linux
platforms, or installation where /proc/kmsg is not directly processed by
syslog-ng is not affected.

I’m going to release 1.6.11 as soon as possible to fix this issue.

—
Bazsi

sysklogd

Ich sicherte folglich die syslog-ng.conf, entfernte den Syslogger mit apt-get remove syslog-ng und installierte apt-get install sysklogd. Seither hatte ich Ruhe.

syslog-ng – neuer Versuch

Heute Abend nun entschied ich mich, auf eine syslog-ng-Version zu wechseln, die den Bazsi erwähnten Bug (noch) nicht aufwies. Ich fand unter den Debian stable-Packages die Version 1.6.5, welche ich als .deb herunterlud, danach das System mit apt-get remove sysklogd bereit für den Neuankömmling machte und diesen dann mittels dpkg -i syslog-ng_1.6.5-2.2_i386.deb auch installierte. Nur noch die syslog-ng.conf zurück an den angestammten Platz, und fertig ist die ursprünglich lange funktionierende Konfiguration.

apt-pinning

Damit mir die 1.9.x-Development-Series von syslog-ng nicht mehr ungewollt auf die Kiste kommt, habe ich nun die Datei /etc/apt/preferences erstellt und folgenden Inhalt hineinkopiert:

Package: *
Pin: release a=stable
Pin-Priority: 700

Package: *
Pin: release a=testing
Pin-Priority: 650

Package: *
Pin: release a=unstable
Pin-Priority: 600

Package: syslog-ng
Pin: version 1.6.5*
Pin-Priority: 1000

Die Pin-Priority: 1000 bedeutet soviel wie „Überschreibe die Version 1.6.5* des Packetes syslog-ng auf keinen Fall mit einer anderen Version“.

apt

In der Tat ist dies das erste Mal seit der Installation von Debian, dass mir ein testing-Paket mein System zerschossen hat. Unglaublich. Wenn man überlegt, wie bspw. Branchenriese Microsoft mit seinen (produktiven!) Patches herumeiert …

Fazit

Wieder habe ich eine Menge über Linux gelernt, viele neue Tools kennengelernt und mich im Eruierern von Fehlern im Betriebssystem geübt.

Der Vortrag ist übrigens trotz dem Pikett-Einsatz als erfolgreich eingestuft worden.

Dank für die moralische Unterstützung: Kollege Liechti & Kollege Burgdorfer