Httputil - Verbindung wird nach jeder Transaktion geschlossen

[mike3436]

Ich habe vor längerer Zeit im Modul 26_tahoma die zyklische https-Kommunikation zum Somfy Server von LWP::UserAgent auf das interne HttpUtil umgeschrieben. Grundsätzlich hat die Kommunikation vorher funktioniert, aber es gab manchmal Probleme mit Blockieren die dann natürlich das ganze FHEM ins Stocken gebracht haben. Ende 2016 habe ich dann auf HttpUtils umgestellt, nachdem ich aus anderen Modulen herausgelesen hatte, wie man hierin mit Cockies arbeiten muss.

Vor einem Monat wurde ich von einem Benutzer darauf aufmerksam gemacht, dass der Traffik doch recht hoch ist, und ich habe das ganze dann untersucht:
Es wird alle 2s eine Abfrage des Status vom Server gelesen. Dazu wird eine HTTPS Verbindung zum Server aufgebaut, die Abfrage per HttpUtils_NonblockingGet gestellt. Die Antwort wird dann Asynchron verarbeitet. Soweit funktioniert alles. Im Wireshark sieht man aber, dass die Verbindung zum Server unmittelbar nach Eintreffen der Antwort sauber abgebaut wird (FIN ...). Ich habe schon allemöglichen Debug-Ausgaben ins HttpUtil integriert, um dem Problem auf die Spur zu kommen, aber leider Erfolglos.

Code Auswählen Erweitern


  #"User-Agent":"TaHoma/7980 CFNetwork/758.5.3 Darwin/15.6.0","Proxy-Connection":"keep-alive","Accept":"*/*","Connection":"keep-alive","Content-Length":"49","Accept-Encoding":"gzip, deflate","Content-Type":"application/x-www-form-urlencoded","Accept-Language":"de-de","Host":"www.tahomalink.com"
  $param->{header} = {'User-Agent' => $hash->{userAgent} }; #, 'Accept-Language' => "de-de", 'Accept-Encoding' => "gzip, deflate"};
  $param->{header}{Cookie} = $hash->{HTTPCookies} if ($hash->{HTTPCookies});
  $param->{compress} = 1;
  $param->{keepalive} = 1;

  $param->{url} = $hash->{url} . $param->{page} . '.json';
  my $find = "../";
  $find = quotemeta $find; # escape regex metachars if present
  $param->{url} =~ s/$find//g;

  $hash->{request_active} = 1;
  $hash->{request_time} = time;
 
  my($err,$data) = HttpUtils_NonblockingGet($param);


Das keepalive wird gesetzt und ist auch in den Daten als Keep-Alive zu sehen.

Code Auswählen Erweitern


2018.04.06 18:09:53 4: myTahoma: refreshing event
2018.04.06 18:09:53 4: myTahoma: tahoma_getEvents
2018.04.06 18:09:53 5: myTahoma: tahoma_UserAgent_NonblockingGet page=getEvents
2018.04.06 18:09:53 5: HttpUtils url=https://www.tahomalink.com/enduser-mobile-web/externalAPI/json/getEvents
2018.04.06 18:09:53 5: IP: www.tahomalink.com -> 178.32.15.131
2018.04.06 18:09:53 5: HttpUtils request header:
GET /enduser-mobile-web/externalAPI/json/getEvents HTTP/1.0
Host: www.tahomalink.com
Accept-Encoding: gzip,deflate
Connection: keep-alive
User-Agent: TaHoma/7980 CFNetwork/758.5.3 Darwin/15.6.0
Cookie: JSESSIONID=F2B1AE9C1BB75945D8F2A68EE5BC932B

2018.04.06 18:09:53 4: https://www.tahomalink.com/enduser-mobile-web/externalAPI/json/getEvents: HTTP response code 200
2018.04.06 18:09:53 5: HttpUtils https://www.tahomalink.com/enduser-mobile-web/externalAPI/json/getEvents: Got data, length: 2
2018.04.06 18:09:53 5: HttpUtils response header:
HTTP/1.1 200 OK
Date: Fri, 06 Apr 2018 16:09:53 GMT
Server: Apache
Strict-Transport-Security: max-age=31536000; includeSubDomains
Content-Type: application/json;charset=UTF-8
Content-Length: 2
Keep-Alive: timeout=5, max=50
Connection: Keep-Alive
2018.04.06 18:09:53 5: myTahoma: tahoma_dispatch data=[]
2018.04.06 18:09:53 5: myTahoma: tahoma_parseGetEvent

Danach wird die TCP/IP-Verbindung durch FIN vom Raspi geschlossen.

Problematisch sehe ich hier, dass alle 2s eine neue Verbindung geöffnet wird, und ein TCP-Port 'verbraten' wird.
Auch im aktuell neu installierten Pi-Hole Internet-Filter sieht man alle 2s eine DNS-Anfrage an www.tahomalink.com

[rudolfkoenig]

Ich habe HttpUtils.pm auf das Problem hin durchgesucht, und finde keine Stelle, wo die Verbindung zugemacht wird, und was zu den angehaengten Angaben (Code & Log) passt. Ich wuerde empfehlen, in HttpUtils_Close eine Log Zeile einzubauen und ein damit erstelltes Protokoll hier anzuhaengen, damit man grob weiss, wo Close passiert.

Auch im aktuell neu installierten Pi-Hole Internet-Filter sieht man alle 2s eine DNS-Anfrage an www.tahomalink.com

Die DNS Anfrage kann man vmtl. mit einem gesetzten "attr global dnsServer 8.8.8.8" (bzw. anderen DNS-Server) vermeiden

[mike3436]

Code Auswählen Erweitern

Ich wuerde empfehlen, in HttpUtils_Close eine Log Zeile einzubauen
Das habe ich schon so gemacht, aber das HttpUtils_Close ist es nicht, bzw. kommt nicht.
Ich habe quasi in alle Routinen ein Log3 eingefügt, um die Aufrufe zu verfolgen - auch in HttpUtils_ParseAnswer, wo noch ein direkter close stattfinden kann.

Nach Login und Abfrage der Konfiguration und  Stati ist die Sequenz immer gleichbleibend.
Bei den ersten Abfragen kommt auch ein geziehlter HttpUtils_Close, weil ein Close im Response vom Server drin steht.

Code Auswählen Erweitern


2018.05.23 23:18:23 5: myTahoma: tahoma_UserAgent_NonblockingGet page=getSetup
2018.05.23 23:18:23 3: HttpUtils_NonblockingGet
2018.05.23 23:18:23 1: HttpUtils_Connect
2018.05.23 23:18:23 1: HttpUtils_Connect2
2018.05.23 23:18:23 1: HttpUtils_ParseAnswer
2018.05.23 23:18:23 1: Close because server doesn't support keepalive
2018.05.23 23:18:23 1: HttpUtils_Close
2018.05.23 23:18:23 4: myTahoma: tahoma_dispatch data={"setup"
...
2018.05.23 23:18:25 5: myTahoma: tahoma_UserAgent_NonblockingGet page=getActionGroups
2018.05.23 23:18:25 3: HttpUtils_NonblockingGet
2018.05.23 23:18:25 1: HttpUtils_Connect
2018.05.23 23:18:25 1: HttpUtils_Connect2
2018.05.23 23:18:25 1: HttpUtils_ParseAnswer
2018.05.23 23:18:25 1: Close because server doesn't support keepalive
2018.05.23 23:18:25 1: HttpUtils_Close
2018.05.23 23:18:25 4: myTahoma: tahoma_dispatch data={"actionGroups":
...
2018.05.23 23:18:53 4: myTahoma: refreshing event
2018.05.23 23:18:53 4: myTahoma: tahoma_getEvents
2018.05.23 23:18:53 5: myTahoma: tahoma_UserAgent_NonblockingGet page=getEvents
2018.05.23 23:18:53 3: HttpUtils_NonblockingGet
2018.05.23 23:18:53 1: HttpUtils_Connect
2018.05.23 23:18:53 1: HttpUtils_Connect2
2018.05.23 23:18:53 1: HttpUtils_ParseAnswer
2018.05.23 23:18:53 5: myTahoma: tahoma_dispatch data=[]
2018.05.23 23:18:53 5: myTahoma: tahoma_parseGetEvent
2018.05.23 23:18:55 4: myTahoma: refreshing event
2018.05.23 23:18:55 4: myTahoma: tahoma_getEvents
2018.05.23 23:18:55 5: myTahoma: tahoma_UserAgent_NonblockingGet page=getEvents
2018.05.23 23:18:55 3: HttpUtils_NonblockingGet
2018.05.23 23:18:55 1: HttpUtils_Connect
2018.05.23 23:18:55 1: HttpUtils_Connect2
2018.05.23 23:18:55 1: HttpUtils_ParseAnswer
2018.05.23 23:18:55 5: myTahoma: tahoma_dispatch data=[]
2018.05.23 23:18:55 5: myTahoma: tahoma_parseGetEvent
2018.05.23 23:18:57 4: myTahoma: refreshing event
2018.05.23 23:18:57 4: myTahoma: tahoma_getEvents
2018.05.23 23:18:57 5: myTahoma: tahoma_UserAgent_NonblockingGet page=getEvents
2018.05.23 23:18:57 3: HttpUtils_NonblockingGet
2018.05.23 23:18:57 1: HttpUtils_Connect
2018.05.23 23:18:57 1: HttpUtils_Connect2
2018.05.23 23:18:57 1: HttpUtils_ParseAnswer
2018.05.23 23:18:57 5: myTahoma: tahoma_dispatch data=[]
2018.05.23 23:18:57 5: myTahoma: tahoma_parseGetEvent


Kann es sein, dass ich im Callback irgend was falsch mache?

[rudolfkoenig]

Das habe ich schon so gemacht, aber das HttpUtils_Close ist es nicht, bzw. kommt nicht.
Ich habe quasi in alle Routinen ein Log3 eingefügt, um die Aufrufe zu verfolgen - auch in HttpUtils_ParseAnswer, wo noch ein direkter close stattfinden kann.

Das duerfte aber nicht sein: egal wer das Schliessen der Verbindung initiiiert, wenn die Verbindung unterbrochen wird, dann muss in FHEM ein Close erfolgen, oder die Verbindungen bleiben in einem "Zombie" Zustand, und nach kurzer Zeit gehen FHEM die FileDeskriptoren aus, und das ist ja nicht das gemeldete Problem.

Aus dem angehaengten Log sieht man, dass FHEM manchmal die Verbindung zumacht, da der Server "Connection:close" gesetzt hat.
Ob es in den anderen Faellen eine neue Verbindung aufgebaut wird, oder nicht kann ich nicht beurteilen, da ich nicht weiss, an welchen Stellen du deine Log-Zeilen eingebaut hast. Kannst du bitte deine geaenderte Version von HttpUtils.pm hier anhaengen?

[mike3436]

Ich habe meine modifizierte HttpUtils.pm mal angehängt.

Aber mal eine Verständnisfrage:
wenn ich HttpUtils_NonblockingGet({Parameter}) Aufrufe, dann ist der Hash mit Parameter doch weg, sobald der Callback ausgeführt wurde, oder? Hier fehlt mir ein bischen das Verständnis dafür, wie perl damit anders umgehen könnte. Nach meinem Empfinden müsste ich den Parameter-Hash als globale Veriable halten, und nicht immer wieder einen neuen temporären Hash an HttpUtils_NonblockingGet übergeben. Wo bleibt denn sonst der Socket/Handle ($hash->{conn}) ab. Ich habe mir mehrere Module angesehen, aber es scheint überall so zu sein, wie ich es programmiet habe (und mir auch abgeschaut habe).

Gruß Rolf

[rudolfkoenig]

wenn ich HttpUtils_NonblockingGet({Parameter}) Aufrufe, dann ist der Hash mit Parameter doch weg, sobald der Callback ausgeführt wurde, oder?

Wenn man gerne die gleiche Verbindung wiederverwenden moechte (Stichwort Connection: keep-alive), dann muss man immer wieder den gleichen Hash uebergeben, sonst weiss HttpUtils nicht, ueber welche Verbindung die Daten gesendet werden. Dieser Hash kann auch der eigene Instanz-Hash sein, wenn man selbst kein FD braucht, und sonst nichts mit dem globalen selectlist zu tun hat.

Falls man keepalive spezifiziert, aber den hash nicht merkt, dann raeumt perl den Speicher fuer den Hash weg (da der Referenzzaehler 0 ist), und schliesst dabei auch den noch offenen Filedescriptor (habs gerade geprueft, da ich unsicher war). Das erklaert dann auch deine Symptome.

[mike3436]

Wenn man gerne die gleiche Verbindung wiederverwenden moechte (Stichwort Connection: keep-alive), dann muss man immer wieder den gleichen Hash uebergeben

Das hab ich mir dann auch so gedacht - ist ja programmteschnisch logisch - und habe das auch so in den YAMAHA Modulen gefunden, die als einziges keep-alive verwenden.
Ich habe es umgesetzt und läuft jetzt über 24h störungsfrei. Nach ca. 90s (nicht genau) sendet der Server immer ein "Connection: close" statt "Connection: Keep-Alive", aber damit kann ich leben - besser als alle 2s.

Danke für die Hilfe und deine Recherchen bezüglich Filedescriptor!