FHEM Absturz: Umstellung Sommerzeit

[curt]

RPi4, FHEM aktuell.

Ich habe einen gepflegten Absturz von FHEM zu vermelden - und zwar ziemlich genau zur Umstellung auf Sommerzeit. Günstigerweise bin ich ein Nachtmensch und bekam das zeitnah mit (FTUI-Display fing an zu spinnen).
Interessanterweise passieren da mehrere (ggf. unabhängige) Dinge gleichzeitig bzw. gehen gleichzeitig schief. Mir ist unklar, was da ganz genau den Absturz auslöste: Wenn das ein Bug in einem Modul sein sollte, wäre es wohl von allgemeinem Interesse.

Schauen wir mal gemeinsam, viele Augen sehen mehr:

Los geht es bereits 01:35 Uhr, ZWave-Dongle kann sich nicht mehr mit einem (!) Thermostaten verständigen. Der ist aber ausgerechnet im gleichen Raum, Funkweg 5 Meter. Beispielhaft die erste Meldung; es kommen dann Unmengen weitere:

Code Auswählen Erweitern


2021.03.28 01:35:10.014 2: ERROR: Thermostat_Arbeitszimmer: cleaning commands without ack after 5s
2021.03.28 01:35:10.017 2: ZWDongle_ProcessSendStack: no ACK, resending message 0109001320023104258f58


Schauen wir direkt auf die Zeitumstellung: ZWave-Dongle zickt jetzt richtig, parallel findet freezemon, dass das alles Mist sei. Dann geht es weiter mit quengelndem ZWave-Dongle.

Code Auswählen Erweitern


2021.03.28 01:59:57.450 2: ZWDongle_ProcessSendStack: no ACK, resending message 01090013200231042501d6
2021.03.28 01:59:57.450 1: ERROR: max send retries reached, removing 01090013200231042501d6 from dongle sendstack
2021.03.28 03:00:00.074 1: [Freezemon] freezemon: possible freeze starting at 01:35:05, delay is 1495.074 possibly caused
by: tmr-Nmap_statusRequest(Netzwerk) tmr-DOIF_TimerTrigger(Cron.PollZwaveThermostat)
2021.03.28 03:00:00.591 2: ZWDongle_ProcessSendStack: no ACK, resending message 010900132002310425a374
2021.03.28 03:00:00.983 2: ZWDongle_ProcessSendStack: no ACK, resending message 010900132002310425f324


Jetzt mault auch noch fhemweb rum:

Code Auswählen Erweitern


2021.03.28 03:00:01.146 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed (peer: 192.168.127.x)


03:07 wird es wieder spannend, wir nähern uns dem FHEM-Absturz. Es gibt einen Zeitversatz von ca. -2min. Mir ist dabei unklar, ob die reload-Error-Meldung schon vom Neustart ist.

Code Auswählen Erweitern


2021.03.28 03:07:13.602 2: ERROR: Thermostat_Arbeitszimmer: cleaning commands without ack after 5s
2021.03.28 03:07:13.661 2: ZWDongle_ProcessSendStack: no ACK, resending message 01090013200231042525f2
2021.03.28 03:05:50 1: reload: Error:Modul 99_email deactivated:


Und wir fahren wieder hoch:

Code Auswählen Erweitern


2021.03.28 03:05:50.073 1: Including fhem.cfg
2021.03.28 03:05:51.632 2: eventTypes: loaded 7684 lines from ./log/eventTypes.txt
2021.03.28 03:07:42.787 1: SignalNano_433: DoInit, /dev/serial/by-id/usb-1a86_USB2.0-Serial-if00-port0
2021.03.28 03:07:47.024 1: TRX: Init OK
...


Wen adressiere ich vor Schreck?
@rudolfkoenig @KernSani

[rudolfkoenig]

Zu ZWDongle: mir ist nicht bekannt, dass der Stick ueber eine Uhrzeit verfuegt, geschweige denn Zeitumstellung. Wenn das Problem nicht zufaellig ist, dann wird es eine externe Ursache haben, wie ein Geraet, was bei der Uhrzeitumstellung Funk stoert.
Achtung bei Verwendung von freezemon: es wurde als Verursacher von Speicherloch gemeldet. Ob es nur im Zusammenhang mit apptime oder alleine, ist mir nicht klar.

FHEMWEB SSL: die Meldung "SSL accept attempt failed" kommt direkt aus der externen Bibliothek (openssl, IO::Socker::SSL)
Womoeglich gibt es einen unberechtigten Timeout bei der SSL-Verbindungsaufbau, wuerde aber bedeuten, das irgendwer fuer timeouts nicht die UNIX Sekundenanzahl, sondern formatierte localtime Strings verwendet. Ich stufe das als unwahrscheinlich ein, und das Ganze als Zufall.

Die Absturz-Ursache ist vermutlich das reload, und dazu kann ich nichts sagen, sowas wird von fhem.pl oder einen meiner Module nicht automatisch ausgeloest.
reload gehoert eigentlich entfernt, weil es die internen Datenstrukturen nicht anpasst, sondern nur die Funktionen ersetzt, und das ist den Benutzern schwer zu erklaeren.

[curt]

Guten Morgen Rudolf,
danke für Deine schnelle Reaktion.

Wenn ich mich selbst bespiegele, halte ich ein oder auch drei Abstütze im Jahr für tolerierbar. Bei einem derart komplexen System mit derart vielen Autoren ist das eher konzeptgemäß, also ich habe da jetzt nicht wirklich ein Problem. Mir geht es eher darum, zu erzählen was passierte: Vielleicht sagt der eine oder andere Modul-Autor: Au Backe, Zeitumstellung hatte ich ja gar nicht auf dem Schirm.

Zu ZWDongle: mir ist nicht bekannt, dass der Stick ueber eine Uhrzeit verfuegt, geschweige denn Zeitumstellung. Wenn das Problem nicht zufaellig ist, dann wird es eine externe Ursache haben, wie ein Geraet, was bei der Uhrzeitumstellung Funk stoert.

Daran dachte ich als erstes, in meinem Arbeitszimmer wird ja rumgefunkt, da wird jeden Verschwörungstheoretiker direkt schwindlig, nebst Funkkopfschmerzen. Bei intensivem Nachdenken kommt da eher ein Eigenheimnachbar (ich habe viele, die wild rumfunken) in Frage: Jemand hat ein Gerät ohne Zeitsynchronisation, das kloppt wild den Kanal zu. Das erklärt aber nur ansatzweise, warum ausgerechnet der Thermostat im Arbeitszimmer spann ... ok: Ich muss mit einem ganz konkreten Nachbar reden - Funkstecke knapp 10 Meter.

Achtung bei Verwendung von freezemon: es wurde als Verursacher von Speicherloch gemeldet. Ob es nur im Zusammenhang mit apptime oder alleine, ist mir nicht klar.

Ohne dem Autoren weh tun zu wollen, das ist in Zweifelsfällen ein wichtiges Modul: Irgendwann hatte ich es installiert, die Ergebnisse genau beobachtet ... und dann vergessen. Eigentlich kann das (bei mir) weg.

FHEMWEB SSL: die Meldung "SSL accept attempt failed" kommt direkt aus der externen Bibliothek (openssl, IO::Socker::SSL)
Womoeglich gibt es einen unberechtigten Timeout bei der SSL-Verbindungsaufbau, wuerde aber bedeuten, das irgendwer fuer timeouts nicht die UNIX Sekundenanzahl, sondern formatierte localtime Strings verwendet. Ich stufe das als unwahrscheinlich ein, und das Ganze als Zufall.

Hmmm.
Das betraf den Kanal zu meinem PC; anders gesagt: Da ist ein großer Bildschirm mit einem Haufen Dedöhns - eins davon ist die ständig mitlaufende FTUI-Oberfläche. Und die riss es tatsächlich (unabhängig von der Frage Absturzursache FHEM) weg. - Ok, buchen wir unter "ist Protokoll".

Die Absturz-Ursache ist vermutlich das reload, und dazu kann ich nichts sagen, sowas wird von fhem.pl oder einen meiner Module nicht automatisch ausgeloest.
reload gehoert eigentlich entfernt, weil es die internen Datenstrukturen nicht anpasst, sondern nur die Funktionen ersetzt, und das ist den Benutzern schwer zu erklaeren.

Kannst Du das bitte etwas genauer ausführen?

Hintergrund:
Das löste bei dem Mail-Modul aus. Dieses wird aber nicht aktiv angesprochen; das steht (stand) in einer Device, ohne dass es auch nur einen zu adressierenden Mailserver gab ... (jaja, sag nix).

Zum guten Schluss möchte ich anmerken, dass ich mir keinen Reim auf den Zeitversatz von -2 Minuten im Protokoll machen kann. Eigentlich geht es ntp ganz gut.

P.S: Zitatebenen korrigiert.

[rudolfkoenig]

Kannst Du das bitte etwas genauer ausführen?

Man aendert das Modul, fuehrt neue Variablen ein, die im Initialize/Define/etc befuellt werden. Oder mit anderen Werten Initialisiert werden.
Reload ueberschreibt nur die Funktionen, aendert den Inhalt der "alten" Variablen aber nicht passend: das neue ReadFn/SetFn/etc ist verwirrt/funktioniert nicht richtig.

[betateilchen]

reload gehoert eigentlich entfernt, weil es die internen Datenstrukturen nicht anpasst, sondern nur die Funktionen ersetzt

Diese Idee ist nicht neu, darüber wird seit 2014 diskutiert.
Mach das doch endlich...

[rudolfkoenig]

Heisst aber, dass Editieren der 99_myUtils.pm ueber das Frontend nicht mehr moeglich ist, bzw. immer einen Neustart erfordert.
Bis ein Schlaumeier das nachimplementiert, weil die Mechanismen im Code erhalten bleiben.

[betateilchen]

Heisst aber, dass Editieren der 99_myUtils.pm ueber das Frontend nicht mehr moeglich ist, bzw. immer einen Neustart erfordert.

dafür reicht ja ein einfaches notify auf

Code Auswählen Erweitern

2021-03-31 13:23:05 Global global FILEWRITE ./FHEM/99_myUtils.pm

[rudolfkoenig]

Und was genau mach dieses notify? shutdown restart?
Ist nicht wirklich Aequivalent mit der aktuellen Loesung.

[betateilchen]

Der Hinweis auf das notify bezog sich auf Deine Aussage

dass Editieren der 99_myUtils.pm ... immer einen Neustart erfordert.

Der notwendige Neustart ließe sich mit dem notify problemlos umsetzen, wenn ein Anwender das möchte.

Wobei man grundsätzlich darüber nachdenken könnte, die 99_xxUtils.pm als Ausnahme auch weiterhin automatisch neu zu laden. In dieser Datei werden nach meiner Erfahrung selten grundlegende Datenstrukturen, die für den Betrieb von FHEM erforderlich sind, angelegt bzw. verwaltet. In den allermeisten Fällen werden hier nur vom Anwender definierte Funktionen abgelegt.

(NB: im Rahmen meiner Überlegung in diesem Thread habe ich gerade festgestellt, dass in der commandref die Verlinkungen zum Attribut perlSyntaxCheck nicht funktionieren, was vermutlich daran liegt, dass dieses Attribut gar nicht in der commandref zu "global" auftaucht)

[rudolfkoenig]

(NB: im Rahmen meiner Überlegung in diesem Thread habe ich gerade festgestellt, dass in der commandref die Verlinkungen zum Attribut perlSyntaxCheck nicht funktionieren, was vermutlich daran liegt, dass dieses Attribut gar nicht in der commandref zu "global" auftaucht)

Danke fuer den Hinweis.
Die Ursache war, dass die Doku im notify.pm war (falsch), und ich in notify die Anker nach dem neuen "Standard" umgebaut habe (perlSyntaxCheck => notify-attr-perlSyntaxCheck).
Ich habe jetzt den Anker zurueckgeaendert, und die Doku zu global in commandref_frame verschoben.

[curt]

@rudolfkoenig
Schnickschnackschnuck ... wieder Umstellung auf Sommerzeit.

Ich arbeite so vor mich hin und denke weder an Sommerzeit noch an sonst Böses - und sehe aus dem Augenwinkel, dass das ständig mitlaufende FTUI auf Vivaldi Verbindungsfehler meldet. Ok, Firefox, konventioneller Weg. Das Gleiche, args. Ok, vermittels ssh auf den FHEM-Server: fhem läuft. Komisch. Ok, vielleicht hängt was - Reboot. Gleiches Spiel - fhem läuft, der fhemweb-Server liefert aber nicht aus.

Riesenschreck bekommen, SD-Card raus, vermittels dd ganz schnell noch Sicherung machen. Während die so vor sich hin rödelt, fällt mein Blick auf die Uhr ... so ca. 0320. Ahhh, warte, Sommerzeitumstellung, da war doch was?

Noch ein e2fsck über die ext4-SD-Card (keine Fehler), weiter geht's: Läuft.

Ich melde aber trotzdem mal, das da noch was hakt.

[rudolfkoenig]

Soweit ich sehe, war das Problem diesemal anders gelagert: FHEM ist nicht abgestuerzt, "nur" FHEMWEB(?) hat nicht geliefert.

Ich tippe auf ein Modul, was mit der Zeitumstellung nicht klar kommt, und Endlosschleife dreht.
Die Theorie hinkt etwas, wenn das Problem von Anderen nicht auch gemeldet wird.

Ist im FHEM-Log etwas zu sehen? Wann genau war dein reboot?

[curt]

Soweit ich sehe, war das Problem diesemal anders gelagert: FHEM ist nicht abgestuerzt, "nur" FHEMWEB(?) hat nicht geliefert.

Exakt.

Ich tippe auf ein Modul, was mit der Zeitumstellung nicht klar kommt, und Endlosschleife dreht.
Die Theorie hinkt etwas, wenn das Problem von Anderen nicht auch gemeldet wird.

Die schlafen um diese Uhrzeit.

Ist im FHEM-Log etwas zu sehen? Wann genau war dein reboot?

Ab ca. 0140 meldet sich massiv ZWDongle, er erreicht einen Themostaten (von acht) nicht mehr. Das ist ungewöhnlich.

Und direkt nach Zeitumstellung im Log:

Code Auswählen Erweitern


2022.03.27 03:00:05.344 1: FHEMWEB SSL/HTTPS error:  SSL accept attempt failed (peer: 192.168.127.105)
2022.03.27 03:00:11.246 3: Opening local_pybinding device ws:127.0.0.1:15733
2022.03.27 03:00:11.246 5: HttpUtils url=http://127.0.0.1:15733/ NonBlocking via http
2022.03.27 03:00:11.247 4: IP: 127.0.0.1 -> 127.0.0.1


Die 105 ist der angesprochene PC. (Obwohl es weitere Verbindungsversuche gab, tauchen die interessanterweise nicht mehr im Log auf, auch nicht der mit anderer IP...)