[Vorläufig gelöst] Fhem blockiert völlig, Service läuft aber noch

Gisbert · 10 April 2019, 09:58:07

Hallo,

ich stehe seit gestern abend vor einem Rätsel.
Gestern abend und heute morgen blockierte Fhem völlig, d.h. kein Zugriff auf die Weboberfläche, keine Logdaten für jeweils 1-2 Stunden. Ich habe es jeweils bemerkt, als ich die Weboberfläche öfnnen wollte und keine Verbindung hinbekam.

Ich habe dann auf der Systemebene (Debian9) den fhem.service gestoppt und wieder gestartet, danach lief/läuft es jetzt wieder.
Im logfile finde ich die folgenden Einträge kurz vor dem Einfrieren und bis zum shudown:

Code Auswählen

2019.04.09 20:58:19 3: [Freezemon] myFreezemon: possible freeze starting at 20:58:15, delay is 4.078 possibly caused by: tmr-HttpUtils_Err(N/A) 
2019.04.09 21:59:08 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/HttpUtils.pm line 866.
2019.04.09 21:59:08 3: bft.Lev.WillyBrandtRing: Read response to update didn't match any Reading
2019.04.09 21:59:08 1: [Freezemon] myFreezemon: possible freeze starting at 20:58:23, delay is 3645.359 possibly caused by: tmr-HttpUtils_Err(N/A) 
2019.04.09 21:59:09 4: DLNARenderer: try to renew subscriptions for services, device DLNA_f47b5e48e6d6 with timeout: 1800
2019.04.09 21:59:10 0: Server shutdown
2019.04.09 21:59:10 1: Shutdown executed
.
.
.
2019.04.10 07:25:03 3: [Freezemon] myFreezemon: possible freeze starting at 07:25:01, delay is 2.907 possibly caused by: tmr-TRAFFIC_StartUpdate(ZuhauseDormagen) tmr-TRAFFIC_StartUpdate(ZuhauseDeutz) tmr-HTTPMOD_GetUpdate(AVIAXpress.Leverkusen) tmr-HTTPMOD_GetUpdate(bft.Lev.WillyBrandtRing) tmr-HTTPMOD_GetUpdate(Jet.Koeln.Berg.Gladbacher.Str) tmr-HTTPMOD_GetUpdate(Jet.Koeln.Worringen) tmr-HTTPMOD_GetUpdate(PM.Koeln.Liebigstr) 
2019.04.10 07:25:08 3: Jet.Koeln.Worringen: Read callback: Error: https://www.clever-tanken.de/tankstelle_details/2210: Can't connect(2) to https://www.clever-tanken.de:443:  SSL wants a read first
2019.04.10 07:25:08 3: [Freezemon] myFreezemon: possible freeze starting at 07:25:04, delay is 4.856 possibly caused by: tmr-FW_closeInactiveClients(N/A) 
2019.04.10 07:25:08 3: AVIAXpress.Leverkusen: Read callback: Error: read from https://www.clever-tanken.de:443 timed out
2019.04.10 08:54:33 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/HttpUtils.pm line 866.
2019.04.10 08:54:34 3: PM.Koeln.Liebigstr: Read response to update didn't match any Reading
2019.04.10 08:54:34 1: [Freezemon] myFreezemon: possible freeze starting at 07:25:13, delay is 5361.005 possibly caused by: tmr-HMUARTLGW_CheckCredits(myHmUARTLGW1) tmr-HMLAN_KeepAliveCheck(HMLAN1) tmr-HttpUtils_Err(N/A) 
2019.04.10 08:54:34 4: [SamsungAV] SamsungTV not able to connect to 192.168.1.32:55000 with http://192.168.1.32:55000/ - code:  - error: connect to http://192.168.1.32:55000 timed out
2019.04.10 08:54:36 0: Server shutdown
2019.04.10 08:54:36 1: PERL WARNING: Use of uninitialized value $warncellId in division (/) at .//FHEM/55_DWD_OpenData.pm line 838.
2019.04.10 08:54:36 1: PERL WARNING: Use of uninitialized value $warncellId in numeric eq (==) at .//FHEM/55_DWD_OpenData.pm line 838.
2019.04.10 08:54:36 1: Shutdown executed

Freezemon liefert heute morgen im fraglichen Zeitraum das folgende log:

Code Auswählen

[Freezemon] myFreezemon: possible freeze starting at 07:25:04, delay is 4.856 possibly caused by: tmr-FW_closeInactiveClients(N/A)
2019.04.10 07:25:03.941 4: BlockingCall (freezemon_processBlocking): created child (11133), uses telnetForBlockingFn_1554862329 to connect back
2019.04.10 07:25:03.942 5: [Freezemon] myFreezemon: Blocking Call started with PID 11133
2019.04.10 07:25:03.950 5: Cmd: >{BlockingStart('441')}<
--- log skips 4.765 secs.
2019.04.10 07:25:08.715 4: HttpUtils: https://www.clever-tanken.de/tankstelle_details/2210: Can't connect(2) to https://www.clever-tanken.de:443: SSL wants a read first
2019.04.10 07:25:08.715 3: Jet.Koeln.Worringen: Read callback: Error: https://www.clever-tanken.de/tankstelle_details/2210: Can't connect(2) to https://www.clever-tanken.de:443: SSL wants a read first
2019.04.10 07:25:08.716 4: Jet.Koeln.Worringen: Read callback: request type was update retry 0, body empty
2019.04.10 07:25:08.716 5: Jet.Koeln.Worringen: ExtractSid called, context reading, num
2019.04.10 07:25:08.717 4: Jet.Koeln.Worringen: CheckAuth decided no authentication required
2019.04.10 07:25:08.718 5: Cmd: >{BlockingStart('442')}<
2019.04.10 07:25:08.787 5: HttpUtils request header:
GET /tankstelle_details/13783 HTTP/1.0
Host: www.clever-tanken.de
User-Agent: fhem
Accept-Encoding: gzip,deflate
Content-Length: 0
Content-Type: application/x-www-form-urlencoded

2019.04.10 07:25:08.853 5: HttpUtils request header:
GET /tankstelle_details/48568 HTTP/1.0
Host: www.clever-tanken.de
User-Agent: fhem
Accept-Encoding: gzip,deflate
Content-Length: 0
Content-Type: application/x-www-form-urlencoded

2019.04.10 07:25:08.856 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2019.04.10 07:25:08.856 ---------------------
2019.04.10 07:25:08.857 5: [Freezemon] myFreezemon found something that's not a REF FW_closeInactiveClients $VAR1 = 0;

2019.04.10 07:25:08.858 5: Freezemon: something went wrong FW_closeInactiveClients $VAR1 = 0;

[Freezemon] myFreezemon: possible freeze starting at 07:25:04, delay is 4.856 possibly caused by: tmr-FW_closeInactiveClients(N/A) 
=========================================================
[Freezemon] myFreezemon: possible freeze starting at 08:55:20, delay is 5.081 possibly caused by: tmr-CUL_HM_sndIfOpen(HMLAN1) tmr-CODE(0x55d9537025b8)(__ANON__) tmr-CODE(0x55d954563a20)(__ANON__) tmr-CUL_HM_procQs(N/A)
2019.04.10 08:55:19.450 5: HMUARTLGW myHmUARTLGW1 read raw (27): fd0004000204011916fd000d000000436f5f4350555f417070d831
2019.04.10 08:55:19.450 5: HMUARTLGW myHmUARTLGW1 read (8): fd0004000204011916 crc OK
2019.04.10 08:55:19.451 5: HMUARTLGW myHmUARTLGW1 recv: 00 0401, state 2
2019.04.10 08:55:19.451 5: HMUARTLGW myHmUARTLGW1 read (17): fd000d000000436f5f4350555f417070d831 crc OK
2019.04.10 08:55:19.451 5: HMUARTLGW myHmUARTLGW1 recv: 00 00436F5F4350555F417070, state 2
2019.04.10 08:55:19.451 4: HMUARTLGW myHmUARTLGW1 currently running Co_CPU_App
2019.04.10 08:55:19.454 5: Cmd: >{BlockingStart('3')}<
2019.04.10 08:55:19.530 5: HttpUtils request header:
GET /ripple-kurs.html HTTP/1.0
Host: www.coinkurs.com
User-Agent: fhem
Accept-Encoding: gzip,deflate
Content-Length: 0
Content-Type: application/x-www-form-urlencoded

2019.04.10 08:55:19.592 5: HttpUtils request header:
GET /tankstelle_details/15539 HTTP/1.0
Host: www.clever-tanken.de
User-Agent: fhem
Accept-Encoding: gzip,deflate
Content-Length: 0
Content-Type: application/x-www-form-urlencoded

2019.04.10 08:55:19.593 5: Cmd: >{BlockingStart('4')}<
2019.04.10 08:55:19.597 5: Cmd: >{BlockingStart('5')}<
2019.04.10 08:55:19.667 5: HttpUtils request header:
GET /litecoin-kurs.html HTTP/1.0
Host: www.coinkurs.com
User-Agent: fhem
Accept-Encoding: gzip,deflate
Content-Length: 0
Content-Type: application/x-www-form-urlencoded

Fhem ist seit heute morgen (sehr früh) aktuell, Linux Update vor ein paar Tagen.
Was kann die Ursache sein - und was kann ich tun, um es nicht wieder zu einem völligen Blockieren kommen zu lassen?

Viele Grüße Gisbert

frank · 10 April 2019, 10:08:47

hattest du vielleicht ein speicherproblem auf dem server?
gibt es "cannot fork" einträge in fhem.log?

Gisbert · 10 April 2019, 19:36:40

Hallo frank,

Speicherprobleme sollte es keine geben. Auf der SSD habe ich in der root-Partition von 16 GB gerade 21% belegt. Es läuft noch ein UniFi-Controller in der gleichen Partition. Kann der sich plötzlich so viel Platz nehmen? Wenn das Problem wieder auftaucht, dann schau ich nach dem belegten Speicher.

Gibt es irgendeine weitere Idee?
Bis jetzt gab es offenbar kein weiteres Problem seit heutemorgen, aber irgendwie schon beängstigend.

Viele Grüße Gisbert

MadMax-FHEM · 10 April 2019, 20:30:19

Die Meldung "cannot fork..." und die Frage von frank zielt auf Hauptspeicher nicht auf Festplattenplatz...

Aha den Unify Controller auf dem selben PI...
...hab schon wo gelesen, dass ein PI (ohne sonst was) schon grad so für den Controller reicht...

Gruß, Joachim

KölnSolar · 10 April 2019, 20:38:43

Zitataber irgendwie schon beängstigend.

Beängstigend find ich, dass SamsungAV u. DLNA_Renderer im Log auftauchen.

Irgendwie scheint doch da kein Netzwerkzugriff möglich gewesen zu sein. $:-\$
Grüße Markus

Gisbert · 10 April 2019, 21:14:42

Hallo Markus,

beide Devices laufen auf verbose 5.
Meine Heizung und mein Auto haben mich am WE auf Trab gehalten; ich bin noch nicht weitergekommen, bzw. habe seit der letzten Konversation noch nicht weiter gemacht, ... aber Ostern kommt bald, da hab ich mehr Zeit, hoffentlich.

Viele Grüße Gisbert

PS: Hast du vielleicht noch eine weitere Idee? Ich glaube nicht, dass die beiden TV-Devices der Grund für das madsive Blockieren sind.

thorschtn · 11 April 2019, 10:05:38

Die Timeouts bei bspw. Deinen clever-tanken Abfragen halte ich durchaus für relevant. Ich hatte früher auch gelegentlich solche Hänger, die ließen sich oft auf Probleme/Erreichbarkeiten bei http-Abfragen zurück führen. Bei mir war es teilweise so, dass dann der FHEM-Perl-Prozess auf 100% Prozessor-Last lief, die FHEM-Oberfläche nicht mehr erreichbar war und nur noch ein "killall -9 perl" half. Ich kann Dir aber nicht mehr genau sagen, welche Module das betraf. Ich hatte beispielsweise mal nen defekten WLAN Repeater, der in meinem Netzt unkontrolliert nen DHCP Server aufgemacht hat, mit einer Route und mit IP-Adressen, die gar nicht zu meinem Netz passten. Das hatte zur Folge, dass einzelne Geräte, die ihre Lease erneuer haben und eine falsche IP-Adresse bekamen, dann bei mir im Netz nicht mehr erreichbar waren. Und diese Nicht-Erreichbarkeit einzelner Devices hat dann zu Hängern im FHEM geführt. Auch mit dem DLNA_Renderer hatte ich mal ähnliche Probleme, kann ich aber nicht mehr genauer rekonstruieren, den nutze ich schon ewig nicht mehr. Ich würde genau da ansetzen, ich behaupte, es wird genau ein Device / Modul sein, welches da blockiert....

Gisbert · 11 April 2019, 18:19:51

Hallo thorschtn,

vielen Dank für deine wertvollen Hinweise. Bei den clever-tanken-Abfragen werde ich als erstes ansetzen, d.h. ich werde die Abfragefrequenz reduzieren. Nachts habe ich es in der Zwischenzeit schon abgestellt. Wenn ich jetzt noch die Abfrage an meine Abwesenheit von zuhause koppele, dann reduziere ich weiter die Anzahl der möglichen timeouts.

Der DLNARenderer ist erst kürzlich dazu gekommen. Da werde ich auf jeden Fall auch ansetzen.

Viele Grüße Gisbert

Markus M. · 11 April 2019, 22:38:54

Hast du zufällig Vodafone DSL? Da gab es bundesweite Ausfälle.
Eventuell verursacht eines deiner Module bei Internet- bzw. DNS-Ausfall Probleme

frank · 12 April 2019, 10:45:02

HTTPMOD (zb clever-tanken) ist ja non-blocking, verzögert fhem also nicht.
bei "read timeout" braucht der server zu lange für die antwort. => zb attr timeout verlängern.
ausserdem hast du scheinbar "viele" abfragen parallel. nutze attr alignTime, um die requests zu entzerren. das könnte auch positiv auf "connect timeout" wirken.

grundsätzlich scheint mir clever-tanken auch sehr "ausgelastet" zu sein. wenn man die preise mal 2-4 wochen plottet, kann man die requests eigentlich auch abschalten, da die preisstrategie dann offensichtlich ist.

rudolfkoenig · 12 April 2019, 12:47:37

ZitatHTTPMOD (zb clever-tanken) ist ja non-blocking, verzögert fhem also nicht.

Stimmt so nur fuer die eigentliche HTTP-Abfrage, das DNS-Lookup ist immer noch blockierend.
Um das zu vermeiden kann man "attr global dnsServer 8.8.8.8" (oder Vergleichbares) setzen.

Gisbert · 13 April 2019, 21:11:04

Hallo frank und Rudi,

ich hab die folgenden Vorschläge umgesetzt:

attr alignTime zur Entzerrung der requests, verbunden mit einer signifikanten Reduktion selbiger
attr global dnsServer 8.8.8.8

Freezes tauchen signifikant seltner auf, teilweise stundenlang gar keine. Auch die Einträge im logfile sehen jetzt nicht mehr verdächtig aus, wobei ich das aber nicht systematisch verfolgt habe.

Ich werde die Sache mit geringerer Priorität weiterverfolgen und mich anderweitig mit Fhem beschäftigen.
Um das Thema als gelöst zu betrachten, ist es vielleicht noch zu früh, aber immerhin als vorläufig gelöst.

Viele Grüße Gisbert

CoolTux · 13 April 2019, 21:16:12

Zitat von: Gisbert am 13 April 2019, 21:11:04
Hallo frank und Rudi,

ich hab die folgenden Vorschläge umgesetzt:

attr alignTime zur Entzerrung der requests, verbunden mit einer signifikanten Reduktion selbiger
attr global dnsServer 8.8.8.8
Freezes tauchen signifikant seltner auf, teilweise stundenlang gar keine. Auch die Einträge im logfile sehen jetzt nicht mehr verdächtig aus, wobei ich das aber nicht systematisch verfolgt habe.

Ich werde die Sache mit geringerer Priorität weiterverfolgen und mich anderweitig mit Fhem beschäftigen.
Um das Thema als gelöst zu betrachten, ist es vielleicht noch zu früh, aber immerhin als vorläufig gelöst.

Viele Grüße Gisbert

~~Deinen global DNS Eintrag solltest Du auf einen DNS Server innerhalb Seines Netzes setzen. Nicht auf einen im Internet der ja nicht erreichbar ist bei Ausfall.~~

Siehe Rudis Erklärung

Gisbert · 13 April 2019, 21:43:14

Hallo CoolTux,

ZitatDeinen global DNS Eintrag solltest Du auf einen DNS Server innerhalb Seines Netzes setzen. Nicht auf einen im Internet der ja nicht erreichbar ist bei Ausfall.

Jetzt bin ich etwas verwirrt, denn einen Internetausfall hatte ich eigentlich nicht.
Ich hatte bis dahin als DNS Server den Server, auf dem Fhem und Pihole läuft: attr global dnsServer 192.168.xx.yy.
Ich weiß nicht, ob diese Konstruktion in Ordnung ist.

Viele Grüße Gisbert

rudolfkoenig · 13 April 2019, 22:21:00

Mit "attr dnsServer" werden DNS-Lookups fuer HttpUtils_NonblockingGet nicht mehr blockierend durchgefuehrt, egal wo der DNS-Server ist, da eine selbst implementierte Routine verwendet wird, die die globale FHEM Select-Schleife verwendet.

Ohne dieses Attribut blockiert der DNS-lookup immer, bis die Routine aus dem "normalen" externen Bibliothek fertig ist, auch mit HttpUtils_NonblockingGet.Mit funktionierenden Internet ist dieses Blockieren kaum merkbar, ohne dagegen schon.

Mein Beispiel funktioniert "immer", da 8.8.8.8 ein bekannter DNS-Server von Google ist.
Man kann aber gerne stattdessen den lokalen DNS-Server verwenden, aber dessen IP kenne ich nicht.