Der schönste Rivva-Bug (und: Verschenke mein Buch)

20. Juni 2012 – Es begab sich so im Oktober 2008 zu einer Zeit, in der ich nur einen einzelnen Server hatte. An jenem Morgen gab Rivva kein einziges Lebenszeichen mehr von sich. Dennoch: Ich konnte mich ohne Umwege auf der Maschine anmelden. Was war hier los?

Wie sich zu meiner Überraschung herausstellte, war überhaupt nichts los. Die Kiste war praktisch in Ruhe:

top: Keine Last.

ps: Prozessliste normal. Dann:

dmesg: Im syslog kein einziger Hinweis.

Nichtsdestotrotz: Das System lief ja überhaupt nicht mehr!???

Reflexartig:

df: 0% Plattenplatz.

Ahso! Nur wie denn das, bitte schön?

Erstes Hindernis: Rettung und Rekonstruktion sind gar nicht so einfach, sind die Festplatten erst einmal zu 100% vollgelaufen. Der Linux Kernel läuft scheinbar unbeeindruckt weiter. Nur dass eben jede, wirklich kleinste Schreiboperation sofort zum Abbruch führt. Jetzt noch ein Programm zur Fehlerdiagnose installieren, haut nicht mehr hin.

Ich fand bald heraus, dass zwei der Logdateien meines Crawlers eine Größe von je vielen hundert GBs erreicht hatten. Wie das Logging so aus dem Ruder laufen konnte, dazu musste ich anschließend erst einmal meinen Code befragen.

Hier das Szenario, wie es sich in der Nacht abgespielt haben muss. Die Kettenreaktion hat mich schwer beeindruckt:

Ein Blog hatte das Abrufen seiner URL inmitten der Dateiübertragung abgebrochen, aber Status 200 OK übermittelt.
Die Präambel des Downloads gab an, das Datei-Encoding wäre ISO-8859-1.
Mein Crawler normalisiert alle Inhalte auf UTF-8-Kodierung. Also kurz iconv angeworfen…
Hier geschah das erste Unglück: Die Datei war ja unvollständig. Der Konverter generierte daraus eine nicht mehr enden wollende Reihe von Zeichen. Eine Endlosschleife im endlichen Automaten!?
Mein Bot brach ab und protokollierte die Fehlerursache. An dieser Stelle geschah der zweite Fehler: Ich hatte den dummen Bot so programmiert, dass er die komplette Exception Message loggen sollte. Die nicht enden wollende Reihe von Zeichen wurde so auch noch hübsch auf Platte gebannt: Hunderte Milliarden Mal wiederholte sich ein und die selbe Bytesequenz.
Die Festplatte war jetzt zu circa zwei Drittel gefüllt. Noch ist alles gut. Bis Stunden später ein wichtiger Job seine Arbeit machte…
Morgens in der Früh rotiert ein logrotate Daemon alle Logdateien des Systems. Die Anweisung lautet copytruncate, d.h. das originale Log File wird gekürzt, nachdem eine Kopie erstellt wurde. In diesem Moment nimmt der Schaden seinen finalen Verlauf. Für die Kopie ist endgültig kein Platz mehr. Oy vey!

Was lehrt uns dieser Fall? Protokolliere Fehlernachrichten nie in voller Länge (jedenfalls solange sie außerhalb der eigenen Codegrenzen generiert werden).

Auch nach Jahren finde ich diesen Bug immer noch ausgesprochen hübsch.

Vor sieben Jahren ist mein TDD-Buch erschienen. Das Buch beschreibt, wie man Software in kleinen sicheren Schritten entwickelt.

Mittlerweile ist es nicht mehr im Druck. Als Autor möchte man natürlich so weit und breit wie möglich gelesen werden.

Ich freue mich deshalb riesig über das Einverständnis des dpunkt.verlags, das Buch ab heute kostenlos als eBook anbieten zu können.

Free Download: Testgetriebene Entwicklung mit JUnit & FIT (PDF)