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.