... deswegen hier.
Aktuell ist mein Internet kaputt (der Tiefbau muss anrücken, das dauert vermutlich eine Woche). Und wie schon hier (https://forum.fhem.de/index.php/topic,125799.msg1204140.html#msg1204140) kurz angedeutet, aber dann doch auf der falschen Baustelle, habe ich bei fehlender Internetverbindung mehrmals pro Stunde laut freezemon ca 40-sekündige Hänger. Dabei glaube ich verstanden zu haben, dass von all den genannten Routinen vermutlich immer nur eine auffällig ist (und die anderen mehr oder weniger "mithängen"), d.h. der kleinste gemeinsame Nenner aus den unterschiedlichen Meldungen ist der wahrscheinliche Kandidat. Richtig?
Den Telegram-Bot habe ich schon mal stillgelegt, der war für 50% der Meldungen verantwortlich.
In den ersten 20 Stunden des Tages hatte ich die meisten Treffer allein oder in Kombination mit
Zitat... freezemon: possible freeze starting at 07:15:40, delay is 40.622 possibly caused by: tmr-CUL_HM_ActCheck(N/A) tmr-CODE(0x6498d70)(GetUpdate) tmr-HttpUtils_TimeoutErr(N/A)
wobei tmr-CODE... 123x, CUL_HM_ActCheck 121x (aber nie ohne tmr-CODE) und der HttpUtils_Timeout 49x (ebenfalls nie ohne tmr-CODE) auftaucht.
Hat jemand eine Idee, was das ist?
setz mal attr freezedetect fm_logFile ./log/freeze-%Y%m%d.logdadurch erhältst Du ein freezemonlog mit verbose-level 5 zu Zeitpunkt des freezes. Vermutlich wirst Du eine Zeile--- log skips xy.123 secs.finden. Davor ist der Bösewicht.
Have luck
Markus
CODE sind wohl anonyme subs, kann sein, dass das mit HTTP-utils zusammenhängt (wer einen callback angibt, bekommt weniger Verbindungsversuche).
Was zu CUL_HM gehört, schaue ich mir bei Gelegenheit mal an, glaube aber, das ist ein false positive im Zusammenhang mit ActionDetector.
"attr global dnsServer" nicht gesetzt, oder nicht erreichbar?
ansonnsten ist http-utils natürlich naheliegend.
@Pfriemler - sorry fürs Kapern
Interessant was Freezemon mittlerweile alles kann...
Aber schlau werd ich trotzdem nicht draus - Zugegeben ein Zugriff auf den Raum Everything bedeutet schon arbeit für FHEM
2022.02.01 21:59:12.314 5: End notify loop for VBBZaehler
2022.02.01 21:59:12.666 4: Connection accepted from WEB_192.168.1.177_54391
2022.02.01 21:59:12.667 4: Connection accepted from WEB_192.168.1.177_54392
2022.02.01 21:59:12.667 5: GET /fhem?room=all HTTP/1.1
Host: 192.168.1.5:8083
Connection: keep-alive
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.99 Safari/537.36
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
Referer: http://192.168.1.5:8083/fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2022-02.log
Accept-Encoding: gzip, deflate
Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7
Cookie: stay_login=1; id=ahQWxj7o18tsBT25u2UXlbm0xJVR9Rc_1aUAMniqA2gfuB3L7xC5T8PJ4MQ0Cn7x_tN0SMLqLvsJBXDG9AqThc; smid=laj5x2TOo1iIdPRNFKhUARm3t5IRuqpzozDke2JtMWXhJmYf1lqRsvoTfKgRtNQtk8ZlxJAaT8vDUwG0bvT-gw
2022.02.01 21:59:12.668 4: WEB_192.168.1.177_54391 GET /fhem?room=all; BUFLEN:0
--- log skips 1.262 secs.
2022.02.01 21:59:13.930 5: SYSMON DS716: Set.759 DS716 ?
2022.02.01 21:59:14.011 5: TelegramBot_Set XXXXXXXX_Bot: called
2022.02.01 21:59:14.013 5: msgConfig globalMsg: called function msgConfig_Set()
2022.02.01 21:59:14.074 4: WEB: /fhem?room=all / RL:47729 / text/html; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate
2022.02.01 21:59:14.080 4: AddRQueue [FE A2 00 00 00 06] 00 03 30 C8 00 2D
2022.02.01 21:59:14.080 5: SimpleWrite [FE A2 00 00 00 06] 00 03 30 C8 00 2D
2022.02.01 21:59:14.086 4: AddRQueue [FB AD 00 00 00 06] 00 01 00 18 00 08
2022.02.01 21:59:14.086 5: adding to RQUEUE - 1
2022.02.01 21:59:14.086 4: AddRQueue [FB AE 00 00 00 06] 00 01 00 40 00 10
2022.02.01 21:59:14.086 5: adding to RQUEUE - 2
2022.02.01 21:59:14.086 4: AddRQueue [FB AF 00 00 00 06] 00 01 02 40 00 08
2022.02.01 21:59:14.086 5: adding to RQUEUE - 3
2022.02.01 21:59:14.087 4: AddRQueue [FB B0 00 00 00 06] 00 01 30 00 00 48
2022.02.01 21:59:14.087 5: adding to RQUEUE - 4
2022.02.01 21:59:14.087 4: AddRQueue [FB B1 00 00 00 06] 00 01 30 50 00 18
2022.02.01 21:59:14.087 5: adding to RQUEUE - 5
2022.02.01 21:59:14.087 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2022.02.01 21:59:14.087 ---------------------
[Freezemon] myFreezemon: possible freeze starting at 21:59:13, delay is 1.087 possibly caused by: tmr-ModbusTCPServer_HandleReadQueue(WagoController) tmr-harmony_ping(HarmonyHub) tmr-ModbusTCPServer_Poll(WagoController)
Was kann ich tun..?
Zitat von: Beta-User am 01 Februar 2022, 20:55:34
Was zu CUL_HM gehört, schaue ich mir bei Gelegenheit mal an, glaube aber, das ist ein false positive im Zusammenhang mit ActionDetector.
Ich denke auch, das ist nur völlig unschuldiger Beifang.
Zitat von: der-Lolo am 01 Februar 2022, 22:09:25
Was kann ich tun..?
Wovon redest Du? "delay is 1.087"? Ich bekomme regelmäßig 2-sekündige Freezes wenn ich die config sichere oder auch nur eine DOIF-DEF ändere.
Zitat von: KölnSolar am 01 Februar 2022, 20:54:55
Have luck
Danke, hatte ich.
2022.02.01 22:45:42.332 5: next ActionDetector check in 600 sec
2022.02.01 22:45:42.333 4: GMC: GetUpdate called (update)
2022.02.01 22:45:42.334 4: GMC: UpdateTimer called from GetUpdate with cmd next sets timer to call update function in 600.0 sec at 22:55:42.333, interval 600Der Actiondetector springt exakt alle 10 Minuten an, und fast zeitgleich GMC dazu:
defmod GMC HTTPMOD http://www.gmcmap.com/historyData.asp?Param_ID=xxxxxxxxxxx&systemTimeZone=1 600
Damit rufe ich die Daten meines (die meiste Zeit offline befindichen) Geigerzählers vom Webportal ab. Dass DAS Ding die Probleme verursacht, darauf wäre ich im Traum nicht gekommen. Aber offenbar klar:
2022.02.01 22:45:42.337 5: HttpUtils url=http://www.gmcmap.com/historyData.asp?Param_ID=58970700611&systemTimeZone=1 NonBlocking via http
--- log skips 40.042 secs.
2022.02.01 22:46:22.380 4: HttpUtils: gethostbyname www.gmcmap.com failed"attr GMC disable 1" - und die 40-Sekunden-Freezes sind weg. Ich mach mal n "gelöst" vornedran...
Markus: DANKE! (thumbsup)
Zitat von: frank am 01 Februar 2022, 21:43:08
"attr global dnsServer" nicht gesetzt, oder nicht erreichbar?
ansonnsten ist http-utils natürlich naheliegend.
Nicht gesetzt. War bisher nicht wirklich nötig.
Damit sollten Telegram und der GMC dann also nicht mehr hängen? dann wäre das die Lösung... werde das hier morgen aktualisieren..."attr global dnsServer 192.168.178.1" ist gesetzt 10h und Telegram und GMC wieder enabled - telebot meldet "NonBlockingGet: returned DNS 192.168.178.1 timed out" und das war's und von GMC bekomme ich gar nichts mehr mit.
Dieser Punkt geht an frank!
Zitat von: Pfriemler am 01 Februar 2022, 23:42:07
Nicht gesetzt. War bisher nicht wirklich nötig. Damit sollten Telegram und der GMC dann also nicht mehr hängen? dann wäre das die Lösung... werde das hier morgen aktualisieren...
Zitat
2022.02.01 22:45:42.337 5: HttpUtils url=http://www.gmcmap.com/historyData.asp?Param_ID=58970700611&systemTimeZone=1 NonBlocking via http
--- log skips 40.042 secs.
2022.02.01 22:46:22.380 4: HttpUtils: gethostbyname www.gmcmap.com failed
Jep, die Namensauflösung ist OHNE gesetztes Attribut mittels System-Aufrufen und blockierend.
Ohne Internet/DNS nat. dann bis zum Netzwerk-Timeout (40s?)
Bei gesetztem Attribut ist die Namensauflösung non-blocking "in fhem" implementiert (so die Theorie)...
Bin gespannt auf das Ergebnis :)
Gruß, Joachim
Zitat von: MadMax-FHEM am 02 Februar 2022, 00:21:01
Jep, die Namensauflösung ist OHNE gesetztes Attribut mittels System-Aufrufen und blockierend.
Jetzt hab ich's auch begriffen ;D
So ein bisschen verwundert es mich schon: Sehr viele Geräte bei mir sind manuell konfiguriert mit fester IP und DNS auf die Fritte (teilweise mit sekundärem). Auch der Raspi ist in /etc/dhcpcd.conf auf "static domain_name_servers=192.168.178.1" eingestellt. Die Fritte kennt den Zustand der Internetverbindung ja bestens und sollte DNS-Anfragen eigentlich zügig mit einer Fehlermeldung beantworten, so dass ich gar nicht kapieren mag, warum es auf OS-Ebene ins timeout läuft.
Bei gesetztem dnsServer und deaktiviertem Telegram-Polling bekomme ich bei einem manuellen "get update" die Fehlermeldung nach <4 Sekunden. Da geht's also.
Jetzt muss es nur noch laufen, wenn das Internet irgendwann mal wieder da ist. Aber da bin ich zuversichtlich. Das freezelog-File hat keine neuen Einträge seit gestern (Schwelle steht auf 4 Sekunden). Die vielen kleineren Hänger bis 1,5s kommen jetzt noch oft von Diagrammaufrufen mit vielen Punkten und dürften der Rechenleistung meines Raspi 3B mit microSD-Karte geschuldet sein - jedenfalls beunruhigt mich das nicht weiter.
Zitat von: rudolfkoenig am 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.
Zitat von: rudolfkoenig am 30 Januar 2017, 09:34:44
1. Die betroffenen Module deaktiveiren (ignore/disable), oder wenn das nicht hilft, loeschen (vorher backup machen).
2. Die betroffenen Modul-Autoren ermahnen, eine Nicht-Blockierende Variante des Internet-Zugriffs verwenden, FHEM bietet sowas auch an mit HttpUtils_NonblockingGet
3. Falls das Modul HttpUtils_NonblockingGet verwendet, dann kann sich der Aufruf immer noch an dem OS-DNS-Lookup blockieren. Das kann man mit "attr global dnsServer 8.8.8.8" (bzw. eine andere passende IP-Addresse) auf nicht-blockierend umstellen.
Ein globales Timeout gibt es nicht, da jedes Modul eine beliebige Methode verwenden kann. Beim (blockierenden) GetHttpFile/GetFileFromURL ist die Voreinstellung 4 Sekunden + DNS-Lookup-Timeout. Die 4 Sekunden kann das aufrufende Modul aendern, der Benutzer nur indirekt, was das Modul das anbietet.
ZitatBeim (blockierenden) GetHttpFile/GetFileFromURL ist die Voreinstellung 4 Sekunden + DNS-Lookup-Timeout.
Das erklärt die Verzögerung der Meldung bei Telegram. Offenbar kommt die Fehlermeldung vom DNS der Fritte also unmittelbar. Blockierend ist Telegram mit dnsServer auf jeden Fall nicht mehr, freezemon findet nichts verdächtiges mehr. Soweit bestens.
ZitatFalls das Modul HttpUtils_NonblockingGet verwendet, dann kann sich der Aufruf immer noch an dem OS-DNS-Lookup blockieren. Das kann man mit "attr global dnsServer 8.8.8.8" (bzw. eine andere passende IP-Addresse) auf nicht-blockierend umstellen.
Schon klar. Das Setzen des Attributs macht die Aufrufe aus FHEM-Sicht nicht-blockierend und das ist in jedem Fall eine Verbesserung. Bleibt die Frage, wann die Fehlermeldung dann letztlich kommt und verarbeitet wird. Auch der Mechanismus hinter dnsServer muss ja irgendein timeout haben. Vermutlich spielt das aber nur für das aufrufende Modul eine Rolle und fällt in aller Regel nicht einmal auf. Insofern finde ich die Lösung mit der Fritte als DNS eher besser.
Bleibt die Frage, warum das OS-DNS-Lookup offenbar trotz meiner Einstellungen erst nach mehr als 30 Sekunden timeout liefert. Ballert das die Anfragen in Kette raus und akzeptiert die negative Antwort erst nach einem Timeout? denn die Fritte antwortet doch - nach obiger Annahme - sofort damit, damit die Anfrage nicht bedient werden kann.
Inzwischen funktioniert - o mirakulöses Wunder der Götter in vodafone-rot - mein Internet wieder. Und FHEM auch, als sei nix gewesen. Was zu erwarten war.