Mir ist aufgefallen, daß die Karopapier-App zumindest mit meinem Nexus 7 (Andriod-4.2.1) und meinem Router/Accesspoint (ein altes Soekris Net-4801 mit einem etwas veralteten OpenBSD-4.9) gerne mal "hängt". Das heißt, eigentlich hängt sie nicht, sondern macht augenscheinlich ungewöhnlich viel Traffic, was an den Blinkenlights auf meinem Router und dem DSL-Modem zu sehen ist. Außerdem neigt alles andere unter Android in dieser Situation zu einer gewissen Zähigkeit.
App-seitig äußert sich das darin, daß beim Laden eines Spiels das übliche "Spiel wird geladen" angezzeigt wird, dann aber über mehrere Minuten nichts passiert (abgesehen von den Blinkenlights auf Router und Modem). Irgendwann kommt dann die passende Meldung "Fehler beim Laden des Spiels."
Ich habe da mal etwas hinterhergesucht und mit Freuden festgestellt, daß ich auf meinem Router für WLAN und die ausgehende Leitung pflow angeknipst habe und das auf meinem PC mit nfcapd(1) aus dem NFDUMP-Projekt vorratsdatenspeichere.
Ein Blick in die Flows zeigt, daß da in der Tat ziemlich viel passiert. Hier mal eine Zusammenfassung über gut 8 Minuten:
$ nfdump -t 2013/02/14.21:35 -R nfcapd.201302142135:nfcapd.201302142140 -A proto,srcip,dstip 'host 46.4.100.200' Date flow start Duration Proto Src IP Addr Dst IP Addr Packets Bytes bps Bpp Flows 2013-02-14 21:35:03.006 503.000 TCP 46.4.100.200 91.3.5.68 6210 1.7 M 27312 276 1508 2013-02-14 21:35:03.006 503.000 TCP 91.3.5.68 46.4.100.200 9089 1.2 M 18665 129 1508 2013-02-14 21:35:57.006 440.000 TCP 46.4.100.200 192.168.1.12 5684 1.6 M 29260 283 1416 2013-02-14 21:35:57.006 440.000 TCP 192.168.1.12 46.4.100.200 8500 1.1 M 19498 126 1416 Summary: total flows: 5848, total bytes: 5.6 M, total packets: 29483, avg bps: 88629, avg pps: 58, avg bpp: 189 Time window: 2013-02-14 21:35:03 - 2013-02-14 21:43:26 Total flows processed: 6018, Blocks skipped: 0, Bytes read: 312992 Sys: 0.020s flows/second: 300900.0 Wall: 0.001s flows/second: 4348265.9
91.3.5.68 war zu dem Zeitpunkt die von meinem Provider dynamisch vergebene IP-Adresse, 192.168.1.12 ist die rfc-1918-Adresse, die ich meinem Nexus per DHCP verpasse, und 46.4.100.200 ist die Adresse vom Karopapier-Server. Die Verbindungen zwischen dem Nexus und Karopapier tauchen hier immer zweimal auf; einmal vor dem NAT (also zwischen dem Nexus und Karopapier), ein zweites mal danach (zwischen meiner dynmamischen IP-Adresse und Karopapier). Letztere weist ein paar Flows mehr auf, was einfach daran liegt, daß ich nebenher auch von meinem Desktop aus mit Karopapier getuschelt habe (für den sammle ich keine Flows, deshalb taucht der nicht explizit in der Liste da oben auf).
Nun sind 1416 Flows in 8 Minuten nicht der Weltuntergang, aber wenn man mal das -A ... wegläßt (sich also alle Flows auflisten lässt), gibt's schon etwas unschöne Peaks, z.B. um 21:39:00 (das ist mit -b erstellt, also vereinfacht gesagt eine Zeile pro Connection (hin und zurück, ist aber immer noch wg. NAT gedoppelt):
Date flow start Duration Proto Src IP Addr:Port Dst IP Addr:Port Out Pkt In Pkt Out Byte In Byte Flows 2013-02-14 21:39:00.006 7.000 TCP 192.168.1.12:44521 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 91.3.5.68:55100 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 91.3.5.68:53726 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 91.3.5.68:53378 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 192.168.1.12:57881 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 91.3.5.68:51227 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 91.3.5.68:53644 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 91.3.5.68:56387 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 192.168.1.12:43280 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 192.168.1.12:51830 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 192.168.1.12:39852 <-> 46.4.100.200:80 4 6 1133 760 2 2013-02-14 21:39:00.006 7.000 TCP 192.168.1.12:46039 <-> 46.4.100.200:80 4 6 1133 760 2
Das wären also effektiv 6 Connections in einer Sekunde. Und das dauerhaft über mehrere Minuten (siehe unten, da habe ich die komplette Ausgabe verlinkt), was nicht gerade normal aussieht. Didi war so freundlich, mir mal die Einträge für meine IP-Adresse an dem Tag aus seinem access.log rauszugreppen, und da wird das ganze mehr oder weniger bestätigt:
91.3.5.68 - - [14/Feb/2013:21:39:07 +0100] "GET /api/user/kili/dran.json HTTP/1.1" 200 557 "-" "Karopapier-App-Android" 91.3.5.68 - - [14/Feb/2013:21:39:07 +0100] "GET /api/user/kili/dran.json HTTP/1.1" 200 557 "-" "Karopapier-App-Android" 91.3.5.68 - - [14/Feb/2013:21:39:07 +0100] "GET /api/user/kili/dran.json HTTP/1.1" 200 557 "-" "Karopapier-App-Android" 91.3.5.68 - - [14/Feb/2013:21:39:07 +0100] "GET /api/user/kili/dran.json HTTP/1.1" 200 557 "-" "Karopapier-App-Android" 91.3.5.68 - - [14/Feb/2013:21:39:07 +0100] "GET /api/user/kili/dran.json HTTP/1.1" 200 557 "-" "Karopapier-App-Android" 91.3.5.68 - - [14/Feb/2013:21:39:07 +0100] "GET /api/user/kili/dran.json HTTP/1.1" 200 557 "-" "Karopapier-App-Android"
Hinweis: ich nehme hier die Einträge von 21:39:07, weil laut nfdump(1) die Flows jeweils eine Dauer von 7 s hatten, und handelsübliche Webserver loggen ja ganz zum Schluß, wenn der Request komplett verarbeitet und beantwortet wurde.
Bevor jetzt jemand jammert, ich würde mir hier irgendwas herbeihalluzinieren: hier sind die kompletten nfdump-Ausgaben und die von der App generierten access.log-Einträge. Viel Spaß beim Korrelieren.
Bleibt zum Schluß die Frage, wer hier einen Hirnregen braucht. Mein Router? Kann eigentlich nicht sein, weil alle Connections sauber durchgereicht werden, was ja auch Didis Ergrepnisse bestätigen. Die App? Das würde ich erstmal so pauschal bezweifeln, weil dann ja vermutlich ein paar mehr Leute in solche Probleme rennen müßten. Android-4.2.1? Vielleicht. Das zickt unabhäig von der App auch gelegentlich mal, allerdings nicht mit den oben beschroibenen Effekten. Letztlich glaube ich, daß es eine Kombination von App und Android-4.2.1 ist.
Das OpenBSD auf meinem Router ist inzwischen 5.7, mein Android ist 5.1.1, die Karopapier-App ist bei Version 2.3.0 angelangt, und Ulli hat da auch eigentlich was eingebaut, was das beschriebene Verhalten verhindern sollte. Tut es aber leider nicht. Deshalb habe ich mir ein kleines Script auf den Router gelegt, das einfach mal per ngrep(1) mitschnüffelt, ohne daß ich erst lange in die Manpage gucken muß:
ngrep -T -d ral0 -c 80 -W byline -O karo.pcap . 'host 192.168.1.12 and host 46.4.100.200'
Und heute hat die App auch mal wieder so einen Amoklauf hingelegt und ich habe das nicht gestoppt, sondern die App mal weiterlaufen lassen und mein Script angeworfen. Die Ausgabe habe ich mit script(1) gespeichert und anschlie^szlig;end von Daten, die niemanden etwas angehen (Cookies, Passwort beim Login der App nach dem Restart etc.) befreit.
Was sofort aufgefallen ist: nach einiger Zeit hören die Amokrequests auf, und die App schickt nur ein paar vereinzelte Requests raus, ohne darauf zunächst Antworten zu erhalten. Dann kommen nach einiger Zeit wieder Antworten, und der Amoklauf geht weiter. Hier habe ich mal Sekundenweise die Anzahl der Requests und Responses geplottet. Eine exaktere Auflistung ist in timing.txt zu finden. Die Spalten dort: Zeit seit Beginn der Aufzeichnung, Portnummer auf App-Seite (auf Karopapierseite ist die natürlich immer 80), Request bzw. Response.
Der komplette Mitschnit ist in k-xxx.txt nachzulesen. Die dort angegebenen Timestamps sind immer relativ zum vorherigen Match (kann ich bei Bedarf auch noch versuchen, relativ zum Beginn der Aufzeichnung zu konvertieren).
Übrigens: es ist ja in der Regel hilfreich, wenn man im mitgeschnippelten Traffic auch die Responses im lesbarer Form sieht. Da die App aber natürlich ein Accept-Encoding: gzip mitschickt, ist das alles komprimiert und entsprechend unlesbar. Deshalb habe ich noch ein wenig gezaubert: ich leite sämtlichen Traffic, der von meinem WLAN in Richtung www.karopapier.de (und zurück) läuft, erstmal auf Port 80 der WLAN-Adresse meines Routers um. Dort rennt ein relayd(8), der als transparenter Proxy konfiguriert ist, den ich aber bei Bedarf so umkonfiguriere, daß er Accept-Encoding-Header aus den Requests rauswirft. Dann kommen die Responses auch hübsch unkomprimiert zurück.
Das kann man im oben verlinkten Mitschnitt sehr gut in der Response mit "Date: Wed, 19 Aug 2015 11:42:08 GMT" sehen; vorher ist alles komprimiert, ab dieser Response ist alles unkomprimiert. Daß in den Requests nach wie vor Accept-Encoding: gzip zu sehen ist, liegt daran, daß ich den Traffic abschnorchele, bevor er zum relayd(8) umgebogen wird, also bevor der Header weggeworfen wird.
Wirklich schlau werde ich aus den Daten aber immer noch nicht. Ich frage mich z.B., was mir dieser Ausschnitt (aus timing.txt sagen soll:
10.825 45400 GET /api/user/kili/dran.json HTTP/1.1.
10.926 45400 HTTP/1.1 200 OK.
11.161 45400 GET /api/user/kili/dran.json HTTP/1.1.
11.926 45400 HTTP/1.1 200 OK.
13.926 45400 HTTP/1.1 200 OK.
17.926 45400 HTTP/1.1 200 OK.
25.527 43042 GET /api/chat/list.json?limit=1 HTTP/1.1.
25.709 43042 HTTP/1.1 200 OK.
Wieso kommen da auf den GET-Request um 11.161 gleich drei Responses, die aber im Abstand von zwei bzw. vier Sekunden? Waren das Retransmits vom Router zum Tablett? Etwas ähnliches ist auch noch ab 71.201 zu sehen. Vielleicht sollte ich mal einen genaueren Blick in das ebenfalls mitgeschnippelte pcap-File werfen. Und vielleicht sollte ich auch mal zur Abwechslung (oder parallel) den Traffic zwischen meinem Router und Karopapier mitschnippeln, um vergleichen zu können, was über das WLAN rein- und rausläuft, und was über meine externe Leitung.
Zum Impressum.