Logspam

Am Donnerstag abend wunderte ich mich über die extrem schnell wachsenden Logfiles des Gatling, den wir testweise als Ersatz für Apache und Proftpd auf dem Verteilserver der FeM e.V. für 2XC3-Videos verwenden. Innerhalb eines Tages sind über 140MB Log entstanden. Da musste was faul sein. Ein Blick in die Logfiles zeigte einen Client, der seit Stunden immer wieder eine Datei anfragte und diese auch brav ausgeliefert bekam. Weitere Ermittlungen mit tcpdump ergaben: Immer ein und dieselbe HTTP-GET Anfrage für eine bestimme wenige KB große Byterange. Da schien wohl ein Player in der Endlosschleife zu hängen. Auch nach dem Stoppen des Webserver traffen immer wieder Anfragen ein, die vom Kernel auf TCP-Ebene resetet wurden, da kein Programm auf dem gewünschten Port lauschte. Wie sich später herausstellte, war der Server am Vormittag mehere Stunden während Wartungsarbeiten runtergefahren, was den Client jedoch nicht zur Aufgabe überredete. Also wie geht man mit einem Client um, der sich weder durch Abarbeitung der gewünschten Anfrage, noch durch Ablehnung selbiger von seinem Vorhaben, mir meine Logfiles vollzuspammen, abbringen lässt. Eine Idee wäre gewesen die TCP-Verbindung zwar anzunehmen, aber nicht zu beantworten, sondern ins Timeout laufen zu lassen. Eine spontane Idee von cosrahn stellte sich aber als effektiver heraus:

cat /dev/zero | nc -p 80 -l

So würde die erste Anfrage auf Port 80 so lange mit Nullen beantwortet, bis die Gegenseite keine Lust mehr hat. Da 99,9% der Anfragen von diesem Client kamen, war die Wahrscheinlichkeit groß, den richtigen damit zu treffen. Wohl nicht groß genug, denn das erste Opfer war ein Suchmaschinencrawler. Aber schon beim zweiten Versuch bekam unsere Nervensäge einen Schwung Nullen. Und war scheinbar damit zufrieden, denn sie ward ab da nie wieder gesehen. Was es nicht alles für Software gibt... Ergebnise der Ursachenforschung: Alles fing am 2008-09-10 um 23:14:46.375373500 an:

2008-09-10 23:14:46.375376500 GET 73 /CCC/24C3/mp4/24c3-2276-en-space_communism-COMPATIBLE.mp4 141011139 AppleTV/2.1 [no_referrer]

Soweit so unspannend. Dieser Aufruf brach jedoch mit einer kaputten Röhre ab und eine knappe Sekunde später, kam die nächste Anfrage:

2008-09-10 23:14:46.692818500 socket_error 73 Broken pipe 2008-09-10 23:14:46.692821500 close/writefail 73 190 137076 2008-09-10 23:14:47.444218500 accept 73 $IP1 63950 29 2008-09-10 23:14:47.444220500 GET 73 /CCC/24C3/mp4/24c3-2276-en-space_communism-COMPATIBLE.mp4 141011139 CFNetwork/250 [no_referrer] 2008-09-10 23:14:47.515451500 socket_error 73 Broken pipe 2008-09-10 23:14:47.515454500 close/writefail 73 182 13236 2008-09-10 23:14:47.522374500 accept 73 $IP1 63951 29 2008-09-10 23:14:47.522375500 GET 73 /CCC/24C3/mp4/24c3-2276-en-space_communism-COMPATIBLE.mp4 141011638 CFNetwork/250 [no_referrer] 2008-09-10 23:16:35.661407500 request_done 73 189 141011912 2008-09-10 23:16:35.661410500 close/reqdone 73

Die dritte Antwort kam schließlich an. Knapp anderthalb Minuten später begann eine Requestorgie. Dieselbe IP fragte nun unentwegt ein kleines Häppchen dieses Videos an, und zwar teilweise 3 - 4 Mal IN DER SEKUNDE. 3 Minuten später war nach insgesamt 683 Anfragen wieder Ruhe.

2008-09-10 23:19:06.602376500 accept 19 $IP1 64644 38 2008-09-10 23:19:06.602380500 GET 19 /CCC/24C3/mp4/24c3-2276-en-space_communism-COMPATIBLE.mp4 43702 CFNetwork/250 [no_referrer] 2008-09-10 23:19:06.666856500 socket_error 19 Broken pipe 2008-09-10 23:19:06.666859500 close/writefail 19 197 13238

nur um 14 Sekunden später die nächste Datei zu versuchen:

2008-09-10 23:19:20.159584500 accept 54 $IP1 64648 38 2008-09-10 23:19:20.174916500 GET 54 /CCC/24C3/mp4/24c3-2254-en-freifunkerei-COMPATIBLE.mp4 141891401 AppleTV/2.1 [no_referrer] 2008-09-10 23:19:20.473401500 socket_error 54 Broken pipe 2008-09-10 23:19:20.473404500 close/writefail 54 187 183156 2008-09-10 23:19:21.179885500 accept 54 $IP1 64649 38 2008-09-10 23:19:21.179887500 GET 54 /CCC/24C3/mp4/24c3-2254-en-freifunkerei-COMPATIBLE.mp4 141891401 CFNetwork/250 [no_referrer] 2008-09-10 23:19:21.248104500 socket_error 54 Broken pipe 2008-09-10 23:19:21.248106500 close/writefail 54 179 13236 2008-09-10 23:19:21.253173500 accept 54 $IP1 64650 38 2008-09-10 23:19:21.253175500 GET 54 /CCC/24C3/mp4/24c3-2254-en-freifunkerei-COMPATIBLE.mp4 141891900 CFNetwork/250 [no_referrer] 2008-09-10 23:21:12.671895500 request_done 54 186 141892174 2008-09-10 23:21:12.671898500 close/reqdone 54

Wie zu erwarten war, ging die Orgie weiter:

2008-09-10 23:21:12.763754500 accept 44 $IP1 64670 31 2008-09-10 23:21:12.763756500 GET 44 /CCC/24C3/mp4/24c3-2254-en-freifunkerei-COMPATIBLE.mp4 6460 CFNetwork/250 [no_referrer] 2008-09-10 23:21:12.763758500 request_done 44 194 6737

Mit immerhin 2148 Anfragen in den folgenden 4 Minuten. Und die nächste Datei:

2008-09-10 23:25:16.899816500 accept 49 $IP1 62786 27 2008-09-10 23:25:16.899819500 GET 49 /CCC/24C3/mp4/24c3-2133-en-building_a_hacker_space-COMPATIBLE.mp4 86446445 AppleTV/2.1 [no_referrer] 2008-09-10 23:25:17.226411500 socket_error 49 Broken pipe 2008-09-10 23:25:17.226413500 close/writefail 49 198 186033 2008-09-10 23:25:17.889025500 accept 49 $IP1 62787 27 2008-09-10 23:25:17.889028500 GET 49 /CCC/24C3/mp4/24c3-2133-en-building_a_hacker_space-COMPATIBLE.mp4 86446445 CFNetwork/250 [no_referrer] 2008-09-10 23:25:17.926603500 socket_error 49 Broken pipe 2008-09-10 23:25:17.926606500 close/writefail 49 190 13233 2008-09-10 23:25:17.970382500 accept 49 $IP1 62788 27 2008-09-10 23:25:17.970386500 GET 49 /CCC/24C3/mp4/24c3-2133-en-building_a_hacker_space-COMPATIBLE.mp4 86446944 CFNetwork/250 [no_referrer] 2008-09-10 23:26:25.563879500 request_done 49 196 86447215 2008-09-10 23:26:25.563882500 close/reqdone 49 ... 2008-09-10 23:26:25.643619500 accept 7 $IP1 62796 17 2008-09-10 23:26:25.643621500 GET 7 /CCC/24C3/mp4/24c3-2133-en-building_a_hacker_space-COMPATIBLE.mp4 4960 CFNetwork/250 [no_referrer] 2008-09-10 23:26:25.643622500 request_done 7 203 5234

Diesmal war aber nicht nach 4 Minuten schluss. Auch nach 4,5 Stunden und über 155000 Anfragen war kein Ende in Sicht. Denn die Zwangstrennung um 4:09 sorgte nur für 18 Sekunden Ruhe und dann eine neue IP mit weiteren 180000 Anfragen bis 07:32:27. Dann unterbricht diese Kette, weil wegen Wartungsarbeiten der Server einige Stunden runtergefahren werden musste. Wer jetzt glaubte, eine mehrstündige Zwangspause würde den Client stoppen, liegt falsch.

2008-09-11 13:04:30.601335500 starting_up 0 :: 80 2008-09-11 13:04:30.601338500 start_ftp 0 :: 21 2008-09-11 13:04:30.652079500 accept 7 $IP2 62782 1 2008-09-11 13:04:30.722534500 GET 7 /CCC/24C3/mp4/24c3-2133-en-building_a_hacker_space-COMPATIBLE.mp4 4960 CFNetwork/250 [no_referrer] 2008-09-11 13:04:30.768665500 request_done 7 203 5234

Der Server ist grade 0,05 Sekunden gestartet, da treffen erneut dieselben Anfragen ein. Bis zur Problembeseitigung gegen 20.39 Uhr kamen weitere 205500 Anfragen seit der Serverdowntime hinzu. Macht in der Summe 488447 Anfragen in fast 21 Stunden, über 2,4GB Traffic, 144MB Logfile und einige strapazierte Nerven. Der hier auftauchende User-Agent "CFNetwork/250" kommt wohl aus dem Hause Apple. Dazu passt auch die zeitliche Nähe der jeweils ersten Anfrage mit dem User-Agent "AppleTV/2.1". Ich stelle an diesem Punkt keine weiteren Vermutungen an und bitte jeden, sich selbst eine Meinung über die Qualität dieser Software zu bilden.