[Gelöst] Endlosschleife in ElectricityCalculator wegen Zeitumstellung?

[KyleK]

Hallo,

seit eben hab ich eine Endlosschleife in FHEM, was zu 100% Auslastung führt und das WEB-Interface nicht mehr erreichbar macht.

Ich glaube der Grund ist das Modul ElectricityCalculator.
Im Define des Moduls wird ein ElectricityCalculator_MidnightTimer angelegt, und dieser scheint in einer Endlosschleife zu laufen.

Das Modul hat Level5 Logausgaben, "time", "timelocal" und "nextMidnight".
Im Fall der Endlosschleife waren diese 3 Werte 1667170365.18888, 1667170365 und 1667080801.
Hier sieht man, dass "nextMidnight" vor "timeLocal" liegt.

Inzwischen ist es nach 00:00 Uhr, und FHEM läuft wieder fehlerfrei.
Das Problem scheint also nur zwischen 23 und 0 Uhr zu bestehen?

[isy]

Ich hatte um 23.00 ebenso einen Fhem Ausfall:
- Keine Web Oberfläche
- Perl auf 100% CPU

Bislang ungeklärt,  um 00.00 lief das System wieder.

[Beta-User]

Falls ihr einen patch vorschlagen wollt, wäre in https://forum.fhem.de/index.php/topic,123847.msg1184061.html#msg1184061 ggf. Material zu finden.

[rob]

Mich hats auch erwischt. Allerdings habe ich keinen ElectricityCalculator im Einsatz. Dafür WaterCalculator und GasCalculator. Da kann ich jetzt schlecht Unterstellungen betreiben ohne mehr zu wissen.
Leider hatte ich kein Verbose=5 und auch sonst keinen Watcher in FHEM aktiv.
Zumindest kann ich sagen, dass es nach Neustart mit dem Laden nach dieser Nachricht im LOG sofort auf 100% hochging:

Code Auswählen Erweitern


...
2022.10.30 23:17:57 0: Featurelevel: 6.1
2022.10.30 23:17:57 0: Server started with 458 defined entities (fhem.pl:26379/2022-09-03 perl:5.032001 os:linux user:messagebus pid:8258)
...

Exakt mit 00:00:01Uhr war lt. htop der Spuk vorbei. Welch Dé­jà-vu

Hat jmd. von Euch mehr Details/ Infos?

VG
rob

[isy]

Bei mir laufen Gas und Electricity Calculator.
Ich kann nicht sagen, wo die Ursache liegen könnte.
By the way - heute morgen zeigt der Electricity Calculator negative Werte an, Gas sieht OK aus.

Hier muss wohl der Modulautor mal den Code prüfen. Siehe Hinweis Beta-User.

Mit meinem Testsystem  kann ich evtl. unterstützen (Module einrichten und einen entsprechenden Counter finden oder definieren) , insofern das möglich ist.

[rob]

Gute Idee. Ich könnte ebenfalls testen, falls nötig. Könnte sein, dass man wieder die Systemzeit zurückdrehen müsste, um zu simulieren. Im worst case könnten alle drei Calculatoren betroffen sein.

Mein GasCounter hat zwei negative Werte: EnergyCostDayLast und EnergyDayLast. Hab ihn noch nicht lange genug, um das zu bewerten.
Der WaterCounter hat nix negatives.

VG
rob

[rob]

Hab mal doch das Testsystem angeworfen und mit WaterCalc begonnen. Ja, blockt reproduzierbar.
Freezemon sagt

Code Auswählen Erweitern


1 - 2022-10-30: s:22:26:43 e:22:59:25 f:1962.433 d:no bad guy found :-(
1 - 2022-10-30: s:23:00:02 e:00:00:00 f:3598 d:tmr-WaterCalculator_MidnightTimer(myWaterCalculator)

Log

Code Auswählen Erweitern


2022.10.31 00:00:00.000 1: [Freezemon] myfreezer: possible freeze starting at 23:00:02, delay is 3598 possibly caused by: tmr-WaterCalculator_MidnightTimer(myWaterCalculator)

Passt jetzt halt nicht zur Fred-Überschrift

Den GasCalc schau ich mir auch an.

VG
rob

[isy]

Guter Fund!
Ich komme heute erst am Abend zum Testen. Evtl. kann Sailor heute Abend auch mal schauen.

[rob]

Der GasCalc blockt leider auch.

Code Auswählen Erweitern


1 - 2022-10-30: s:22:07:56 e:22:59:49 f:3113.022 d:no bad guy found :-(
1 - 2022-10-30: s:23:00:02 e:00:00:00 f:3598 d:tmr-GasCalculator_MidnightTimer(Gaszaehler)


Mein Vorgehen:
- Docker FHEM taufrisch mit nix drin starten
- Counter + Calc anlegen
- FHEM updaten + restart
- Sys-Zeit setzen auf 30.10. 22:00Uhr
- ein setreading am Counter machen, im Calc wird reagiert
- Sys-Zeit setzen auf 30.10. 22:59Uhr
→ FHEM nicht erreichbar, sobald es 23:00Uhr ist

- Sys-Zeit setzen auf 30.10. 23:59Uhr
→ FHEM wieder erreichbar, sobald es 31.10. 00:00Uhr ist

Wenn Du mir für den EleCalc + dessen Counter eine Defi geben magst, kann ich den auch testen.

VG
rob

[isy]

Hallo rob,
das sieht bei mir so aus:
"SolarView:BKDY" ist der aktuelle Strombezug am 2-Wege-Zähler.
BKDY bekommt jede Minute einen aktuellen Wert.

VG Helmut

Code Auswählen Erweitern

define ke_StromVerbrauch ElectricityCalculator SolarView:BKDY.*
attr ke_StromVerbrauch BasicPricePerAnnum 60
attr ke_StromVerbrauch Currency €
attr ke_StromVerbrauch DecimalPlace 3
attr ke_StromVerbrauch ElectricityCounterOffset 0
attr ke_StromVerbrauch ElectricityKwhPerCounts 1
attr ke_StromVerbrauch ElectricityPricePerKWh 0.2088
attr ke_StromVerbrauch MonthOfAnnualReading 1
attr ke_StromVerbrauch MonthlyPayment 10
attr ke_StromVerbrauch ReadingDestination CalculatorDevice
attr ke_StromVerbrauch SiPrefixPower W
attr ke_StromVerbrauch alias StromVerbrauch (Bezug)
attr ke_StromVerbrauch event-on-change-reading .*
attr ke_StromVerbrauch room Keller
attr ke_StromVerbrauch stateFormat SolarView_BKDY_EnergyDay kWh, SolarView_BKDY_EnergyCostDay € heute
define ke_StromVerbrauchFileLog_1 FileLog ./log/ke_StromVerbrauchFileLog_1-%Y-%m.log ke_StromVerbrauch:SolarView_BKDY_EnergyCostDay:.*
attr ke_StromVerbrauchFileLog_1 addLog ke_StromVerbrauch:SolarView_BKDY_EnergyCostDay:300
attr ke_StromVerbrauchFileLog_1 room System

[rob]

Danke Dir.

Ja, blockt ebenfalls:

Code Auswählen Erweitern


1 - 2022-10-30: s:22:16:39 e:22:59:30 f:2571.672 d:no bad guy found :-(
1 - 2022-10-30: s:23:00:02 e:00:00:00 f:3598 d:tmr-ElectricityCalculator_MidnightTimer(ke_StromVerbrauch)


Heißt, beim Raten mit welchem Modul ich starte, hatte ich 0% Risiko daneben zu liegen 
In allen drei Fällen also der MidnightTimer.

Viele Grüße
rob

[Nestor]

Code Auswählen Erweitern

        my $EpochNextMidnight = timelocal(1, 0, 0, $mday, $mon, $year+1900) + 86400;


https://svn.fhem.de/trac/browser/trunk/fhem/FHEM/73_ElectricityCalculator.pm#L605

The code expects the same number of seconds in every day (86400) which you can't assume with daylight saving.
Yet another DST bug in Fhem because every module keeps manually calculating time differences.

[Nestor]

@rob Can you test this patch?

Code Auswählen Erweitern

--- - 2022-10-31 17:22:58.750295332 +0100
+++ /srv/fhem/FHEM/73_ElectricityCalculator.pm 2022-10-31 17:22:08.191859193 +0100
@@ -602,7 +599,7 @@

### Start timer for execution around midnight
my ($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) = localtime(time);
- my $EpochNextMidnight = timelocal(1, 0, 0, $mday, $mon, $year+1900) + 86400;
+ my $EpochNextMidnight = Time::Local::timelocal_nocheck(1, 0, 0, $mday+1, $mon, $year+1900);
InternalTimer($EpochNextMidnight, "ElectricityCalculator_MidnightTimer", $ElectricityCalcDev, 0);

### For debugging purpose only


Code Auswählen Erweitern


# 1667080801 = Sun Oct 30 2022 00:00:01 GMT+0200 (CES)
fhem> { my ($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) = localtime(1667080801);; FmtDateTime(timelocal(1, 0, 0, $mday, $mon, $year+1900) + 86400) }
2022-10-30 23:00:01
fhem> { my ($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) = localtime(1667080801);; FmtDateTime(Time::Local::timelocal_nocheck(1, 0, 0, $mday+1, $mon, $year+1900)) }
2022-10-31 00:00:01


The sane way would be to use DateTime module....
https://perldoc.perl.org/5.30.3/perlfaq4#How-do-I-find-yesterday's-date?

[rob]

...Can you test this patch?...

Sure Thank you very much for your support.

I just patched "73_ElectricityCalculator.pm" inside my test instance in its last state, which is already up to date and has an EleCalc-device running. I edited line #156 so the block looks like that:

Code Auswählen Erweitern


        ### Start timer for execution around midnight
        my ($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) = localtime(time);
        #my $EpochNextMidnight = timelocal(1, 0, 0, $mday, $mon, $year+1900) + 86400;
        my $EpochNextMidnight = Time::Local::timelocal_nocheck(1, 0, 0, $mday+1, $mon, $year+1900);
        InternalTimer($EpochNextMidnight, "ElectricityCalculator_MidnightTimer", $hash, 0);

After setting the sys-time back to 30.11. 22:20, I restarted FHEM and set the time to 22:59. No freeze happend as the time reached 23:00 
I also set the time to 23:59 what made no difference - just to keep my test procedure.

Freezemon tells me:

Code Auswählen Erweitern


1 - 2022-10-30: s:22:16:39 e:22:59:30 f:2571.672 d:no bad guy found :-(
1 - 2022-10-30: s:23:00:02 e:00:00:00 f:3598 d:tmr-ElectricityCalculator_MidnightTimer(ke_StromVerbrauch)
1 - 2022-10-30: s:22:22:30 e:22:59:17 f:2207.463 d:no bad guy found :-(
1 - 2022-10-30: s:23:01:11 e:23:59:05 f:3474.089 d:no bad guy found :-(

The first two lines come from my testing before the patch. Looks promising, doesn't it?

The other two modules WaterCalc and GasCalc do have the same code line inside. So I guess they even should work well with that patch.
Do you think my spot testing of that particular case will be enough? Or are there some more special cases we should check by further tests?

It would would be excellent if all concerned modules could be patched officially (at least those three ones). But I'm not sure who feels actually responsible for that and when it could be done (are the module authors still on board and have the time to implement it?).
Well, the next clock change gives us a delay of almost 6 months - maybe not that urgent 

Best regards
rob

[Sailor]

Dear Nestor, dear Rob

@rob Can you test this patch?

After setting the sys-time back to 30.11. 22:20, I restarted FHEM and set the time to 22:59. No freeze happend as the time reached 23:00 

Thanks a lot for your suggestions!!! 

I am going to implement this patch as soon as I have the possibility.
Latest for Friday.
Still time enough till the next daylight saving 

Regards
    Sailor