FHEM Absturz durch AT-Device mit Sonnenuntergang und Steckdose via CUL_HM

[Allgaeuer]

Hallo,

alle paar Wochen stürzt mein FHEM komplett ab. Ich konnte die Ursache soweit einkreisen, dass der Absturz immer damit zusammenhängt, wenn ich einen Schaltbefehl via AT-Device durch "Sonnenuntergang" an das Device schicke:

Diese Fehlermeldung taucht im Logfile auf:

Code Auswählen Erweitern

2024.04.05 19:50:26 3: CUL_HM set HM_Steckdose_2_Sw on noArg
Error parsing time at /usr/lib/arm-linux-gnueabihf/perl/5.28/Time/Piece.pm line 583.
2024.04.05 19:51:57 1: Including fhem.cfg

Im Filelog dazu diese Meldungen:

Code Auswählen Erweitern

2024-04-05_19:50:26 HM_Steckdose_2 commState: CMDs_pending
2024-04-05_19:50:26 HM_Steckdose_2_Sw commState: CMDs_pending
2024-04-05_19:50:26 HM_Steckdose_2 CMDs_pending
2024-04-05_19:50:26 HM_Steckdose_2_Sw set_on noArg
2024-04-05_19:50:26 HM_Steckdose_2 commState: CMDs_processing...
2024-04-05_19:50:26 HM_Steckdose_2_Sw commState: CMDs_processing...
2024-04-05_19:50:26 HM_Steckdose_2_Sw trigLast: fhem:02
2024-04-05_19:50:26 Weihnachtskugel_abends_Licht_an Next: 19:51:51

Zum Vergleich die Einträge bei normalen Ablauf:
Logfile:

Code Auswählen Erweitern

2024.04.04 19:49:01 3: CUL_HM set HM_Steckdose_2_Sw on noArg
Filelog:

Code Auswählen Erweitern

2024-04-04_19:49:01 HM_Steckdose_2 commState: CMDs_pending
2024-04-04_19:49:01 HM_Steckdose_2_Sw commState: CMDs_pending
2024-04-04_19:49:01 HM_Steckdose_2 CMDs_pending
2024-04-04_19:49:01 HM_Steckdose_2_Sw set_on noArg
2024-04-04_19:49:01 HM_Steckdose_2 commState: CMDs_processing...
2024-04-04_19:49:01 HM_Steckdose_2_Sw commState: CMDs_processing...
2024-04-04_19:49:01 HM_Steckdose_2_Sw trigLast: fhem:02
2024-04-04_19:49:01 Weihnachtskugel_abends_Licht_an Next: 19:50:26
2024-04-04_19:49:01 HM_Steckdose_2_Sw commState: CMDs_processing...
2024-04-04_19:49:01 HM_Steckdose_2 commState: CMDs_done
2024-04-04_19:49:01 HM_Steckdose_2 CMDs_done
2024-04-04_19:49:01 HM_Steckdose_2_Sw commState: CMDs_done
2024-04-04_19:49:01 HM_Steckdose_2_Sw deviceMsg: on (to VCCU)
2024-04-04_19:49:01 HM_Steckdose_2_Sw level: 100
2024-04-04_19:49:01 HM_Steckdose_2_Sw pct: 100
2024-04-04_19:49:01 HM_Steckdose_2_Sw on
2024-04-04_19:49:01 HM_Steckdose_2_Sw timedOn: off


Beim Absturz fehlen im Filelog die Zeilen nach "Weihnachtskugel_abends_Licht_an.."

die Definition des AT-Device sieht so aus:

Code Auswählen Erweitern


*{sunset("REAL",0,"16:30","21:30")} set HM_Steckdose_2_Sw on
Würde mich freuen, wenn jemand einen Tip hat, wie ich das verhindern kann.

Danke und Gruß,

Allgäuer

[betateilchen]

Mit CUL_HM hat das erstmal nichts zu tun, der Fehler tritt offenbar auf, wenn das at-Device nach der Ausführung versucht, den nächsten Zeitpunkt zur Ausführung zu berechnen.

Zum "Warum" fällt mir aber gerade nichts ein.

Vielleicht magst Du den Threadtitel anpassen, damit dort auch was von "at" steht. Das erhöht die Chancen, dass Rudi den Thread wahrnimmt und ihn nicht nach CUL_HM verortet und ignoriert.

Als Sofortmaßnahme könntest Du den verbose Level des at-device auf 5 setzen, damit man mehr Informationen im Logfile findet.

[Allgaeuer]

Hallo betateilchen,

Danke für den Tip, Titel ist angepasst und verbose ist auf 5 gesetzt. Mal schauen, wann der nächste Absturz kommt.

Gruß Allgäuer

[frank]

mit "set execNow" am at sollte das problem sofort kommen.

[Allgaeuer]

Hallo Frank,

Ich verstehe nicht ganz, was Du meinst. Der Absturz kommt nur sporadisch alle paar Wochen. "set execNow" kann ich ausführen, führt aber nicht zum Absturz.

Was mich auch noch irritiert: stacktrace ist schon seit Monaten gesetzt. Im Logfile habe ich trotzdem keine detaillierten Einträge, nur die eine Zeile mit ,, Error parsing time at...".

Der Absturz fallt nicht direkt auf, ich merke das erst am nächsten Morgen, wenn ,,komische" Mittelwerte in meiner Statistik angezeigt werden.

Gruß Allgäuer

[betateilchen]

Was mich auch noch irritiert: stacktrace ist schon seit Monaten gesetzt. Im Logfile habe ich trotzdem keine detaillierten Einträge, nur die eine Zeile mit ,, Error parsing time at..."

Das muss Dich nicht irritieren.

Die Meldung stammt von außerhalb FHEM und wird nur deshalb ins FHEM-Logfile geschrieben, weil die Standardausgabe dahin umgeleitet wird. Deshalb ist die Einstellung für stacktrace an dieser Stelle egal.


Mich würde interessieren, warum diese Meldung vom perl Modul Time::Piece überhaupt ausgegeben wird. Wenn ich mich recht erinnere, benutzen weder at, SUNRISE_EL oder die fhem.pl dieses Modul explizit. Time::Piece ist ja schon lange ein Kernelmodul, aber ich frage mich gerade, ob durch ein

Code Auswählen Erweitern

use Time::Piece in irgendeinem anderen Modul eventuell FHEM-eigene gleichnamige Funktionen überschrieben werden.

Deshalb bin ich gespannt, ob Rudi eine Idee hat, woher das Phänomen stammen kann.

Kannst Du mal bitte die Ausgabe von fheminfo send debug hier posten?

[Allgaeuer]

Hallo

,,fheminfo send debug" liefert:

Code Auswählen Erweitern


{"Air_Quality_Analytic":{"noModel":1},"CUL":{"noModel":1},"CUL_HM":{"CCU-FHEM":1,"HM-CC-RT-DN":3,"HM-ES-PMSW1-PL":2,"HM-MOD-RE-8":1},"DOIF":{"FHEM":9},"DWD_OpenData":{"noModel":1},"EnOcean":{"TF":1,"noModel":4},"Energy_Forecast":{"noModel":1},"Energy_Forecast_Analytic":{"noModel":1},"FHEMWEB":{"noModel":1},"FileLog":{"noModel":5},"HMCCU":{"noModel":1},"HMCCUDEV":{"noModel":2},"HMCCURPCPROC":{"noModel":1},"I2C_BME680":{"noModel":1},"JeeLink":{"LaCrosseITPlusReader.10.1h":1},"LaCrosse":{"noModel":3},"Landroid_DWD":{"noModel":1},"MQTT2_CLIENT":{"noModel":2},"MQTT2_DEVICE":{"noModel":2,"worx_landroid_mover":1},"ModbusRegister":{"noModel":76},"ModbusTCPServer":{"noModel":3},"OWTHERM":{"DS18B20":20},"OWX":{"noModel":1},"RPII2C":{"noModel":1},"SVG":{"noModel":2},"SYSSTAT":{"noModel":1},"TCM":{"ESP3":1},"at":{"noModel":15},"autocreate":{"noModel":1},"average":{"noModel":12},"dummy":{"noModel":10},"eventTypes":{"noModel":1},"logProxy":{"noModel":1},"notify":{"noModel":9},"statistics":{"noModel":42},"system":{"configType":"configFile","os":"linux","perl":"5.28.1","revision":"28499","uniqueID":"fab..."},"telnet":{"noModel":1}}
use Time::Piece verwende ich bei ein paar selbst erstellten Modulen. Soll ich diese Einträge löschen / auskommentieren?

Gruß Allgäuer

[betateilchen]

use Time::Piece verwende ich bei ein paar selbst erstellten Modulen. Soll ich diese Einträge löschen / auskommentieren?

Es wäre zumindest mal ein Ansatz, um der Ursache auf die Spur zu kommen. Wie gesagt, Time::Piece ist ein Modul, das man nicht mehr explizit zur Nutzung angeben muss, weil es seit perl 5.8 im Kernel vorhanden ist.

Aber Du nutzt auch DWD_OpenData - auch da wird Time::Piece explizit angegeben, um localtime und gmtime daraus zu exportieren. Warum auch immer.

Sollte die Nutzung in Deinen eigenen Modulen keine Abhilfe schaffen, wäre meine nächste Empfehlung, testweise auf DWD_OpenData zu verzichten.

[rudolfkoenig]

Hypothese:
einer der vielen von Time::Piece ueberschriebenen Zeitfunktionen verursacht bei unerwarteten Input das Beenden des FHEM Processes.
Ob das einfach durch die() oder SIGSEGV passiert, ist unklar, genauso, welche Inputs dafuer notwendig sind.

In meiner Version von Piece.pm (aus perl 5.38) ist Zeile 583 leer.

Welche Time::Perl Version wird verwendet?
Bei mir steht in der Zeile 22: our $VERSION = '1.3401_01';

Falls die Version aelter ist, dann waere, neben den Vorschlaegen von betateilchen, auch das Aktualisieren von perl eine Alternative.

[Allgaeuer]

Hallo Rudi und betateilchen,

a) in Piece.pm, Zeile 21 habe ich: $VERSION = '1.3204'

b) in Zeile 583:     my @vals = _strptime($string, $format, $islocal, $locales);

Zeile 576-586 steht:

Code Auswählen Erweitern

sub strptime {
    my $time = shift;
    my $string = shift;
    my $format = @_ ? shift(@_) : "%a, %d %b %Y %H:%M:%S %Z";
    my $islocal = (ref($time) ? $time->[c_islocal] : 0);
    my $locales = $LOCALE || &Time::Piece::_default_locale();
    $format = _translate_format($format, $strptime_trans_map);
    my @vals = _strptime($string, $format, $islocal, $locales);
#    warn(sprintf("got vals: %d-%d-%d %d:%d:%d\n", reverse(@vals[c_sec..c_year])));
    return scalar $time->_mktime(\@vals, $islocal);
}

Beim AT-Device habe ich jetzt Verbose=5 gesetzt und ich könnte auf den nächsten Absturz warten. Vielleicht sehen wir dann, was die eigentliche Ursache des Absturzes ist.

Wenn Ihr denkt, dass ich gleich bei allen Modulen (incl. DWD_OpenData) Time::Piece auskommentrieren soll, dann mache ich das natürlich. Hier vertraue ich auf Euch echte Experten. (Auf DWD_OpenData kann ich nicht verzichten, da hängt mein Mähroboter und PV-Prognose dran, die möchte ich nicht "totlegen").

Ich sage Euch beiden schon mal ganz herzlich Danke für den Support 

Gruß Allgäuer