weidner/archives/2012/05/

Wer zu spät kommt, den bestraft das Gateway

Das hat mich einiges an Zeit und Nerven gekostet.

Ein Kollege von mir betreut ein Programm, das Daten mit verschiedenen Servern via HTTP austauscht. Was für ein Programm und was für Server ist für die Geschichte unerheblich, nur dass die Daten via HTTP ausgetauscht werden und über unsere Proxy-Server laufen. Bei Verbindungsproblemen bin ich zuständig. Und Verbindungsprobleme gab es. Zu genau einem Server, mit allen anderen funktionierte es. Mit diesem Server eigentlich auch, bis vor einigen Monaten. Ein Anruf beim Betreiber des Servers brachte nichts, denn laut seiner Aussage funktioniert der Server mit allen anderen, nur eben bei uns nicht. Und bei der Fehlersuche helfen, wollte oder konnte er nicht.

Da wir zu dem Programm keine ausreichenden Unterlagen hatten, blieb mir nichts weiter, als mich auf die Verbindung zu konzentrieren. Also mitzuschneiden und zu sehen, ob ich etwas erkennen kann. Ich habe tcpdump angeworfen und die Übertragung protokolliert. Diese selbst ist relativ simpel: unser Clientprogramm sendet via POST-Request eine Datei an eine URL und bekommt mit der Antwort eine andere Datei zurück. Der HTTP-Statuscode war 200 OK, wenn es funktionierte und 502 Bad Gateway, wenn es nicht funktionierte.

Um unseren Proxy-Server als Fehlerquelle auszuschließen, wurde der Client-Rechner für die DMZ vorbereitet, dort installiert, die Datenübertragung gestartet und — die Verbindung funktionierte. Wie kommt das denn, dachte ich und: ich will erst in einem Mitschnitt sehen, was anders war, als bei der Übertragung durch die Proxy-Server. Bei diesem Test hatte ich noch keinen Mitschnitt laufen lassen, das wollte ich nachholen. Also habe ich tcpdump auf dem Paketfilter angeworfen und die Verbindung protokolliert, die jetzt wieder nicht funktionierte. Also nochmal, diesmal funktionierte es, und nochmal und nochmal. Die POST-Requests, die funktionierten, unterschieden sich im Mitschnitt nur unwesentlich von denen, die nicht funktionierten.

Vom Serverbetreiber war keine Hilfe zu erwarten, vom Herstellersupport auch nicht. Was ich brauchte, war eine Idee, einen Ansatz um der Ursache auf die Schliche zu kommen (oder genügend Zeit und Muße, um das Problem wissenschaftlich anzugehen). Da Zeit und Muße in unserer Firma ein rares Gut sind, musste ich auf eine Idee hoffen. Manchmal hilft auch die pure Verzweiflung, aber nicht immer.

In diesem Fall hatte ich Glück, denn mir kam die Idee, auf das Zeitverhalten der Übertragung zu achten. Dazu habe ich bei Wireshark die Möglichkeit, den Zeitstempel der einzelnen Datenpakete relativ zum ersten Paket darstellen zu lassen. Und dann ergab es sich fast wie von selbst (es hat schon noch etwas Arbeit gemacht, aber das war Routine). Alle Anfragen, die mit 200 Ok beantwortet wurden, waren in weniger als drei Sekunden beim Server angekommen. Bis auf eine hatten alle Anfragen, welche vom Server mit 502 Bad Gateway beantwortet wurden, mehr als drei Sekunden bis zum Server benötigt. Anscheinend hatten wir es da mit einem sehr ungeduldigen Gateway beim Server zu tun. Immerhin geht die Verbindung über Internet, da kann man schlecht für drei Sekunden Übertragungszeit garantieren.

Um die Annahme mit Messdaten zu unterlegen, habe ich ein kurzes Skript geschrieben, mit dem ich die Übertragungszeit für eine Anfrage beliebig verzögern konnte. Alle Tests damit verstärkten meine Vermutung, das es an der Zeit für die Übertragung der Anfrage lag. Mit diesem Wissen und den Testergebnissen im Rücken konnten wir schließlich den Serverbetreiber bewegen, den Timeout an seinem Gateway zuzugeben und sogar etwas zu vergrößern, so dass anschließend auch das Programm meines Kollegen wieder Daten zuverlässig übertragen konnte.

Zumindest habe ich wieder eine Lektion für die Fehlersuche gelernt.

Paketmitschnitt mit tcpdump

Um die Verbindung für die spätere Analyse mitzuschneiden verwende ich gern tcpdump. Dabei ist wichtig, dass auf dem Rechner, auf dem ich das einsetze, alle Datenpakete vorbeikommen. Also starte ich tcpdump auf einem der Rechner, die an der Verbindung beteiligt sind, oder auf einem Router beziehungsweise Paketfilter dazwischen. In diesem Fall wollte ich sehen, was überhaupt zwischen Client und Server gesendet wird, und habe jeweils die kompletten Datenpakete protokolliert. Dazu gibt es die Option -s bei tcpdump, die leicht unterschiedlich eingesetzt wird. So sieht der Aufruf auf Linux etwa so aus:

# tcpdump -s0 -w test.pcap host client and host server

Und auf OpenBSD:

# tcpdump -s1500 -w test.pcap host client and host server

Das tcpdump Programm auf Linux interpretiert die Größe 0 für die mitgeschnittenen Pakete als: soviel wie gerade ankommt, während das auf OpenBSD auf eine feste Größe angewiesen ist. 1500 Byte reicht für Ethernet aus.

Analyse mit Wireshark

Nachdem ich mir die Mitschnitte auf einen Rechner mit installiertem Wireshark kopiert habe, öffne ich die Dateien damit.

Im Menü View gibt es den Punkt Time Display Format, und dort stelle ich ein: Seconds since beginning of capture.

Dann gehe ich auf das erste Datenpaket der TCP-Verbindung und rufe das Kontextmenü mit der rechten Maustaste auf. Dort wähle ich Follow TCP Stream.

Nun sind im Hauptbildschirm die Datenpakete eingeschränkt auf genau eine Anfrage nebst Antwort. Ich suche nach dem ersten Datenpaket, in dem der Server Daten sendet (dieses enthält im Datenbereich "HTTP/1.1 ..."). Das letzte ACK-Paket vom Server davor zeigt die Zeit, zu der die Anfrage vollständig beim Server angekommen war. Von dieser Zeit ziehe ich die Zeit des allerersten Pakets dieser Verbindung ab und habe damit die Übertragungszeit für die Anfrage.

Jetzt wechsle ich wieder in das Fenster Stream Content, welches mir den Inhalt der Übertragung anzeigt und notiere mir dort, ob der Server mit HTTP/1.1 200 OK oder HTTP/1.1 502 Bad Gateway geantwortet hatte. Anschließend wähle ich unten den Schaltknopf Filter Out This Stream und kann mich nun der nächsten Anfrage auf die gleiche Weise nähern.

Posted 2012-05-25
Tags: