FHEM Forum

FHEM => Anfängerfragen => Thema gestartet von: laufhem am 21 Juli 2022, 14:50:28

Titel: FHEM resetiert sich wegen Zugriff auf DWD Modul nach Update
Beitrag von: laufhem am 21 Juli 2022, 14:50:28
Hallo, ich habe eine Bakon-PV-Anlage und einen kleinen Stromzähler, der jeweils einen Impuls pro erzeugter kWh sendet, welchen ich mit einem RasperryPi an einem GPIO-Pin auslese.
Die "Statistik" in FHEM macht dann ein HourCounter:
CN.PVErtragAktuelleStunde

Dies hat bisher auch hervorragend geklappt. Gestern kam ich leider auf die Idee, FHEM und den RaspberryPi zu aktualisieren. (FHEM über update, der RPi hat nun Raspian Bullseye als Betriebssystem).
Prinzipiell scheint auch alles weiterhin zu funktionieren, nur dass der HourCounter nicht mehr korrekt zählt: Er resetiert sich immer wieder selbstständig auf die alten Werte vor dem Update.
appCountsPerHourTemp zählt zum Beispiel je nach dem bis 5 oder 10, aber springt dann wieder auf Null.
countsOverall springt auch regelmäßig wieder auf den Wert vor dem Update.
Kennt jemand dieses seltsame Phänomen? Woran kann das liegen? Die Kommunikation mit dem Stromzähler funktioniert ja offenbar, nur der selbstständige Reset ist seltsam.
Ich sehe auch sporadisch, dass FHEM in der Weboberfläche "Connection lost. Trying to reconnect in 5s" meldet (das kannte ich vorher nicht so in der Häufigkeit). Kann es sein, dass sich jedes Mal dann der HourCounter resetiert?

Vielen Dank für Hilfe!
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: Beta-User am 21 Juli 2022, 14:56:32
Mal unterstellt, FHEM startet sich nicht unmotiviert immer mal wieder ohne "save" (wegen systemd, das versehentlich der Ansicht ist, dass FHEM tot sei) würde ich darauf tippen (Glaskugel mangels anderer Info-Quelle), dass du die Rechte an der statefile verbogen hast.

"connection lost" kann viele Ursachen haben, Neustarts würden sich jedenfalls im Log finden (unterstellt, fhem darf dahin schreiben), (fhem-) uptime würde ggf. schnell zeigen, wie lange FHEM schon stressfrei läuft.
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: laufhem am 21 Juli 2022, 17:57:10
Hallo,

es liegt definitiv an ungewollten FHEM Neustarts.
uptime habe ich bisher maximal bei knapp über einer Minute gesehen: (00:01:05)

Ich habe auch gemerkt, dass einige Regeln (z.B. Rollladen zur Uhrzeit hochfahren) nicht mehr funktionieren - (wenn ich diese händisch auslöse, geht es aber).

Wie kann ich das Problem eingrenzen?
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: DetlefR am 21 Juli 2022, 18:32:13
Die aktuelle Log-Datei anhängen ist schon mal ein guter Anfang.
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: laufhem am 22 Juli 2022, 04:34:40
Die aktuelle Logfile ist bei mir tatsächlich mehrere hundert MB groß. Hier mal die interessantesten "ERRORs" daraus, ich hoffe, hier findet jemand eine Erklärung für die plötzlich auftretenden Einfrierer/Neustarts:

2022.07.22 04:24:45 3: DWD: GetAlertsAbort ERROR: downloading and processing weather alerts data failed (Process died prematurely)
Day '' out of range 1..31 at /usr/lib/arm-linux-gnueabihf/perl/5.32/Time/Piece.pm line 130.
...
2022.07.22 04:24:56 1: PERL WARNING: Use of uninitialized value $model in concatenation (.) or string at ./FHEM/58_GPIO4.pm line 113.
2022.07.22 04:24:56 1: PERL WARNING: Use of uninitialized value $model in concatenation (.) or string at ./FHEM/58_GPIO4.pm line 114.
...
2022.07.22 04:24:56 2: autocreate: define GPIO4__329000000000 GPIO4 00-329000000000
2022.07.22 04:24:56 1: define GPIO4__329000000000 GPIO4 00-329000000000: GPIO4: device family 00 not supported
2022.07.22 04:24:56 1: ERROR: GPIO4: device family 00 not supported
2022.07.22 04:24:56 1: usb create starting
...
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: Beta-User am 22 Juli 2022, 07:37:46
Eine Ursache könnte sein:
2022.07.22 04:24:56 1: usb create starting
Also: Im Wiki zu Pi findet sich ganz sicher ein Hinweis, wo das herkommt.

Ansonsten hast du "nur" ein paar Warnings gezeigt. Das ist unkritisch. "undefined subroutine"-Meldungen oä. hast du nicht?
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: laufhem am 22 Juli 2022, 09:31:59
OK, für das usbCreate habe ich nun
attr initialUsbCheck disable 1 gesetzt.

Das sind allerdings die "kritischsten" Warnungen aus der logfile. Keine undefined subroutines enthalten. Wird FHEM "extern" beendet? Wie kann ich das eingrenzen?
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: Otto123 am 22 Juli 2022, 09:51:32
Moin,

da ein LogFile mit mehrerer 100 MB irgendwie sinnlos ist, würde ich das mal auf Tageslog umstellen:
attr global logfile ./log/fhem-%Y-%m-%d.log
defmod Logfile FileLog ./log/fhem-%Y-%m-%d.log Logfile


Die Frage ist ja bei Laufzeiten von 1 minute, dass Du überhaupt die Änderung über die Web Oberfläche ausführen und save drücken kannst.

Du kannst FHEM auch mal beenden und im debug modus starten:
https://wiki.fhem.de/wiki/FHEM_startet_nicht_-_Tipps_zur_Fehlersuche

Vielleicht siehst Du dann was passiert ???

Gruß Otto
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: laufhem am 22 Juli 2022, 17:34:50
Zeitweise sehe ich eine höhere CPU Last von ca 100%, woraufhin fhem offenbar neu gestartet wird:

pi@raspberrypi:~ $ service fhem status
● fhem.service - FHEM Home Automation
     Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
     Active: active (running) since Fri 2022-07-22 16:57:01 CEST; 1min 1s ago
    Process: 2835 ExecStart=/usr/bin/perl fhem.pl fhem.cfg (code=exited, status=0/SUCCESS)
   Main PID: 2839 (perl)
      Tasks: 1 (limit: 2060)
        CPU: 12.622s
     CGroup: /system.slice/fhem.service
             └─2839 /usr/bin/perl fhem.pl fhem.cfg

Jul 22 16:56:59 raspberrypi systemd[1]: Starting FHEM Home Automation...
Jul 22 16:57:01 raspberrypi systemd[1]: Started FHEM Home Automation.
pi@raspberrypi:~ $ service fhem status
● fhem.service - FHEM Home Automation
     Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
     Active: activating (auto-restart) (Result: exit-code) since Fri 2022-07-22 16:58:05 CEST; 214ms ago
    Process: 2835 ExecStart=/usr/bin/perl fhem.pl fhem.cfg (code=exited, status=0/SUCCESS)
   Main PID: 2839 (code=exited, status=3)
        CPU: 12.819s

Jul 22 16:58:05 raspberrypi systemd[1]: fhem.service: Failed with result 'exit-code'.
Jul 22 16:58:05 raspberrypi systemd[1]: fhem.service: Consumed 12.819s CPU time.
Jul 22 16:58:05 raspberrypi systemd[1]: fhem.service: Scheduled restart job, restart counter is at 703.
Jul 22 16:58:05 raspberrypi systemd[1]: Stopped FHEM Home Automation.
Jul 22 16:58:05 raspberrypi systemd[1]: fhem.service: Consumed 12.819s CPU time.
Jul 22 16:58:05 raspberrypi systemd[1]: Starting FHEM Home Automation...



Eine Ausgabe über den Debugmodus (perl fhem.pl -d fhem.cfg) zeigt, dass er tatsächlich bei dem DWD Zugriff sich beendet:

2022.07.22 17:07:18 3: DWD: GetAlertsAbort ERROR: downloading and processing wea                                                                             ther alerts data failed (Process died prematurely)
Day '' out of range 1..31 at /usr/lib/arm-linux-gnueabihf/perl/5.32/Time/Piece.p                                                                             m line 130.


Nach Löschen des DWD devices läuft es scheinbar wieder stabiler.
Könnt ihr mir helfen, die Day '' out of range Meldung zu beheben?
Ist das ein Problem in der PERL-Installation oder FHEM?
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: Beta-User am 22 Juli 2022, 17:42:43
CPU bei 100% über längere Zeit ist nicht gut...

Die Ursache für den Aufruf ließe sich über "stacktrace" (Device global) finden, das klingt irgendwie nach einer Fehlkonfiguration bei was selbstgestricktem (im Zusammenhang mit event aggregator?).

Ansonsten ist es nach wie vor schwierig zu helfen, wenn die Infos so spärlich sind. Glaskugelfrage: CUL_HM ist im Einsatz? Dann Events an den Channel-Devices reduzieren.

Generell: Wie viele Events in welcher Zeit? (Das ist so eine Frage, die immer wieder kommt. @Otto: haben wir dazu was im Wiki?)
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: Otto123 am 22 Juli 2022, 23:18:38
Der Tag den er abrufen will  ist leer?
ZitatDay '' out of range 1..31

Zu den Events pro Zeiteinheit wüsste ich nichts im Wiki. Kann man das irgendwie global messen?
Titel: Antw:HourCounter resetiert sich nach Update selbstständig
Beitrag von: MadMax-FHEM am 22 Juli 2022, 23:26:25
Zitat von: Otto123 am 22 Juli 2022, 23:18:38
Der Tag den er abrufen will  ist leer?
Zu den Events pro Zeiteinheit wüsste ich nichts im Wiki. Kann man das irgendwie global messen?

DOIF-Tools kann "sowas".
Es erfasst die Events pro Device und zeigt auch an, ob bereits event-on-... genutzt wird.
https://wiki.fhem.de/wiki/DOIFtools#Erfassen_und_Auswerten_von_Statistikdaten (müsste es sein)

Damit kann man ganz leicht die Devices finden, wo es am meisten lohnt: die meisten Events/Zeit...

Gruß, Joachim
Titel: FHEM resetiert sich wegen Zugriff auf DWD Modul nach Update
Beitrag von: laufhem am 25 Juli 2022, 10:34:57
Hallo zusammen,

nochmal zur Klarstellung: Das Problem mit FHEM-Neustarts nach ~1 Minute und sporadisch hoher CPU Last konnte eindeutig dem Zugriff auf das Wettermodul vom DWD zugeordnet werden ("Day '' out of range 1..31").
Nachdem das DWD Device gelöscht wurde, läuft FHEM bei mir wieder stabil und niedriglastig.
Das "eigentliche" Problem ist damit bei mir behoben; mit dem Nachteil, dass die Wettervorhersage nun nicht mehr verfügbar ist.

Um das Problem mit dem DWD Device zu lösen, müsste ich herausfinden, ob das "Day '' out of range 1..31" vom FHEM Update oder vom Raspian Update (/usr/lib/arm-linux-gnueabihf/perl/5.32/Time/Piece.p) kommt?


PS: CUL_HM ist nicht im Einsatz. Ich versuche alle Informationen bereit zu stellen, die dienlich sind. Sorry, wenn es "spärlich" ankommt, aber ich weiß ja auch nicht, welche Infos weiterhelfen.
Titel: Antw:FHEM resetiert sich wegen Zugriff auf DWD Modul nach Update
Beitrag von: Otto123 am 25 Juli 2022, 10:53:13
die Meldung kommt mMn vom Modul /Time/Piece.pm - dies wird offenbar mit leeren Day aufgerufen - warum kann ich nicht nachvollziehen. Müsste man suchen was da genau passiert...
@Beta-User gibts ähnliche Meldungen im Forum? Mir ist nichts aufgefallen.
Titel: Antw:FHEM resetiert sich wegen Zugriff auf DWD Modul nach Update
Beitrag von: frank am 25 Juli 2022, 10:54:23
ZitatUm das Problem mit dem DWD Device zu lösen, müsste ich herausfinden, ob das "Day '' out of range 1..31" vom FHEM Update oder vom Raspian Update (/usr/lib/arm-linux-gnueabihf/perl/5.32/Time/Piece.p) kommt?
theoretisch könnten auch die gelieferten daten "fehlerhaft" oder neu strukturiert sein.
vielleicht funktionieren andere messtationen besser/anders.
ausserdem kann man verbose hochdrehen.
Titel: Antw:FHEM resetiert sich wegen Zugriff auf DWD Modul nach Update
Beitrag von: Beta-User am 25 Juli 2022, 11:24:08
Zitat von: Otto123 am 25 Juli 2022, 10:53:13
die Meldung kommt mMn vom Modul /Time/Piece.pm - dies wird offenbar mit leeren Day aufgerufen - warum kann ich nicht nachvollziehen. Müsste man suchen was da genau passiert...
@Beta-User gibts ähnliche Meldungen im Forum? Mir ist nichts aufgefallen.
Mir wäre nichts bekannt. Das Modul selbst verwendet daraus localtime und gmtime, was an sich auch nicht problematisch sein dürfte. "stacktrace" zu aktivieren könnte helfen rauszufinden, von wo aus die Funktion (_mktime() in Time:Piece.pm) aufgerufen wird. Komisch ist da allerdings, dass gar kein Zeitstempel geschrieben wird. Ist FHEM da schon tot?!?

Die Fehlermeldung unmittelbar vorher ist mAn. auch unproblematisch, das ist die Anwort aus einem BlockingCall mit 60 Sek. timeout.

Jedenfalls sind beides nur Warnhinweise und eben gerade (nach meiner Interpretation) keine (für sich genommen) wirklich kritischen Meldungen.
Von daher bleibt mir nur die Spekulation, dass insgesamt zu viele forks (aus BlockingCall) da sein könnten und FHEM zu träge reagiert (aus systemd-Sicht).

Zitat von: frank am 25 Juli 2022, 10:54:23
theoretisch könnten auch die gelieferten daten "fehlerhaft" oder neu strukturiert sein.
Möglich wäre es, allerdings kann ich im Moment keinen Zusammenhang zwischen fehlerhaften Daten und dieser Funktion in Time::Piece.pm herstellen.