Meine Firma betreibt Webanwendungen (völlig unzusammenhängend: Wir tun noch ganz andere Dinge. Donnerstags z.B. gibt es Kuchen, mit einem E-Voting im Intranet, wo die Mitarbeiter sich die Kuchensorten wünschen können, die sie am liebsten haben. Und vor den meisten Nachtschichten gibt es Steaks. Laut den beiden Personalberatern auf der Party gestern sind das ein zehnmal besseres Argumente zur Anwerbung neuer Mitarbeiter als die Texte, die Marketing mich hat aufnehmen lassen. Und außerdem hab ich gestern eine echt faszinierende Archäologie-Professorin aus Chile kennengelernt. Und mein Schädel brummt - sieht so aus als käme ich jetzt in das Alter, wo ich einfach nimmer ohne Nebenwirkungen bis halb sechs feiern kann. Klasse Party, Steffi - danke für die Einladung!). Und vor zwei Wochen häuften sich die Beschwerden darüber, daß unsere Kunden bei bestimmten Aktionen nach ca. 10 Sekunden einen Fehler im Browser angezeigt bekamen (“Die Seite kann nicht angezeigt werden.”). Jetzt muß man wissen, daß wir doch einiges Erfahrung im Debugging solcher Anwendungen haben, und so haben sich “die üblichen Verdächtigen” (zu denen diesmal auch ich zählte) mal hingesetzt und recht zuversichtlich begonnen, den Fehler zu suchen.

Ich hab jetzt lange überlegt, wieviel ich über die Struktur der Anwendung bzw. Anbindung hier hinschreiben darf, aber eigentlich ist das alles so “Standard”, daß ich hier nichts unerwartetes ausplaudern werde. Deswegen mal kurz zum Überblick: Klassische “multiple screened subnets”-Architektur, von außen kommende SSL-Verbindungen passieren einen externen Paketfilter (im folgenden “EGW”, also “Exterior GateWay” genannt) und terminieren auf einem Loadbalancer wobei die Pakete einen weiteren Paketfilter (“IGW”, “Interior GateWay”) passieren. Dieser verteilt sie an einen klassischen Apache-Stack, wobei der Traffic nochmal durch das IGW muß. Nichts weltbewegendes (und die Beschreibung ist auch nicht 100%ig akkurat, aber das tut der Sache keinen Abbruch).

Wir haben das Debugging also mit den Tomcat-Logs angefangen (nach “hochdrehen” diverser Debugging-Levels) und stellten recht schnell fest, daß beim Tomcat immer, wenn der Fehler aufgetreten ist, anscheinend nur ein Request-Header angekommen ist, also kein Body. Verdacht Nummer eins war also, daß irgendwo zwischen httpd und Tomcat was verloren geht. Also haben wir den Apache mit mod_dumpio ausgestattet und die Requests angesegen. Und siehe da, der Request-Body war wirklich leer. Als nächstes wollten wir nun ein Kommunikationsproblem zwischen Loadbalancer und Applikationsserver ausschließen und haben deswegen tcpdump, ssldump und WireShark bemüht. Und auch hier das gleiche Ergebnis: Der Request-Body war wirklich leer. Parallel dazu haben wir natürlich alle Veränderungen untersucht, die wir am Live-System seit Auftauchen des Problems vorgenommen haben, und obwohl wir den Zeitrum recht schnell auf das Datum einer Livestellung eingrenzen konnten hat ein sorgfältiges Untersuchen der (recht trivialen) Änderungen dieses Tages nichts zu Tage gefördert, was dieses Verhalten in irgendeiner Weise hätte erklären können. Und somit war unsere Truppe zum ersten Mal ratlos.

Im nächsten Schritt haben wir dann angefangen, Paketlogs auf (fast) allen beteiligten Komponenten zu ziehen, also Applikationsserver, IGW und EGW (ich sag jetzt mal “show clock” in die Runde, die entsprechenden Leute wissen dann Bescheid, ne?). Und da wurde es dann wirklich merkwürdig: Wir sahen, daß der Client den Request-Body durchaus mitübermittelt hat - nur kam vom Loadbalancer nie ein ACK. Nach dem initialen “WTF?”, dutzenden weiterer Traces und diversen Schüssen in’s Blaue, was die Konfiguration des Loadbalancers anging haben unsere Netzwerker dann den initialen Trace nochmal in Ruhe angesehen und eine Merkwürdigkeit entdeckt: Bei Verbindungen die nicht in den Fehler gelaufen sind haben beide Seiten (also Client und Loadbalancer) ganz normal eine MSS announced. NB: Der Loadbalancer setzt hier 1380. Bei den Verbindungen, die fehlgeschlagen sind, hat unser Loadbalancer keine MSS im SYN-Paket mitgeschickt (zumindest sahen wir keine MSS-Option am internen Interface des EGW), was dann dazu geführt hat, daß der Client eigentlich die Default-MSS hätte nutzen müssen. Laut Stevens wäre das eigentlich die 536 (TCP/IP default MTU minus 40 für die Header) gewesen, aber hier hat uns ein dreckiger Hack erwischt, den wohl inzwischen alle Hersteller von Plaste-Routern implementiert haben: Es ist mittlerweile leider üblich, die MSS an die PMTU anzupassen (“clamp mss to path mtu”, und man muß sich schon fragen, wer sich das hat einfallen lassen. Die MSS bezieht sich auf die Endpunkte der Verbindung, die PMTU-Discovery dagegen auf den dazwischenliegenden Transportweg) - und das ist bei unserem Setup und den beteiligten Setups leider mehr als 1380 gewesen, also wurde die PMTU nicht angepasst, i.e. keine ICMP fragmentation needed;-Pakete erzeugt.. Noch dazu ist dieses MSS-Clamping an die PMTU anscheinend fehlerhaft implementiert, wenn gar keine MSS von der Gegenseite kam, vgl. hier und hier (eigentlich wäre das fast ein eigenes “WTF?” wert… aber da man leicht vergisst, daß “Outgoing” von einem Router aus gesehen ja durchaus in beide Richtungen ist, sind wir mal gnädig!). Sprich, bei den “kaputten” Verbindungen kam der Requests des Clients in zu großen Segmenten an - und der Loadbalancer hat die dann (“Sicherheitsfeature”) ohne Kommentar verworfen. Wir haben dann im Trace auch Retransmissions des Clients gesehen und waren schon relativ sicher, daß genau das das Problem ist - und damit dann ein zweites “WTF?” Denn wieso kriegt es der Loadbalancer bei einigen Verbindungen nicht auf die Reihe, im SYN-ACK eine MSS zu announcen? Der “quick and dirty”-Fix für das Problem war jetzt dann auch, den Loadbalancer so einzustellen, daß er auch zu große Segmente annimmt - das Problem war denn auch sofort behoben.

Zu dem Zeitpunkt fühlten sich unsere Netzwerker denn auch bei der Ehre gepackt und haben mal versucht, das alles nachzubauen:

  1. SYN-Paket vom Client mit announcter MSS von 1460 passiert das EGW. Da dieses auch als VPN-Gateway fungiert ersetzt es den MSS-Header durch 1380.
  2. Paket passiert zum ersten mal das IGW und wird zum Loadbalancer durchgereicht.
  3. Loadbalancer antwortet im SYN-ACK mit einer MSS von 1380 (und reicht den Request intern an die Serverfarm weiter).
  4. Antwort-Paket des Loadbalancers passiert IGW, es ist keine MSS zu finden.
  5. Client schickt Segmente mit einer Größe von 1460, die verworfen werden.

Wie kommt es zu sowas? Nach erneutem Debuggen hat sich herausgestellt, daß auf dem IGW für alle Verbindungen, die den entsprechenden Fehler aufwiesen, eine SYN-Flooding-Protection aktiv geworden ist (die in den Logs als “erfolgreich” auftaucht, was doof ist, wenn man in den Logs normalerweise immer auf Fehler filtert… “WTF?” Nummer drei), und die hat dann den MSS-Header aus dem Antwort-Paket an den Client entfernt… und kaputt implementiertes MSS-Clamping an die PMTU betrat die Bühne. Noch mehr Tracing und Loganalyse, erschwert durch eine Eigenheit in der Verteilung ankommender Requests auf die Backend-Server) hat dann eine extrem große Zahl von Requests der Form

1
GET /jkmountpoint/servlet/normal

gezeigt. Und mit dem Wissen bewaffnet haben wir uns dann nochmal die Eingangs erwähnten Änderungen an der Livestellung, die wir im Verdacht hatten, angesehen. Stellt sich raus, daß unsere Webentwickler eine AJAX-Library ausgetauscht haben, die einen Cursor-Style anpassen sollte. Und das hat der Internet Exploder nicht vertragen, weswegen er genau diesen Request dutzende Male abgeschickt hat.

Und was lernen wir daraus?

  • MSS-Clamping an die PMTU riecht nach totem Fisch.
  • Der Internet Explorer riecht ebenfalls nach totem Fisch.
  • Die Implementierung der SYN-Flooding-Protection in unserem IGW stinkt bestialisch.
  • Das Logging des Loadbalancers ist nicht hilfreich.
  • Das Mitlesen von SSL-Traffic in Wireshark ist extrem komfortabel.
  • Es ist gut, wenn auf allen Geräten die selbe Zeit eingestellt ist, gell?

Alles in allem sechs anstrengende, wenn auch lehrreiche Stunden. Ich gönne mir jetzt von Rachmaninov das Klavierkonzert Nummer 2, werde mich auf die Terasse begeben und auf meinem neu erworbenen Amazon Kindle meine Kenntnisse über Oracle RAC vertiefen. Schönen Sonntag Euch allen!