Endlosschleife in Astro bei NewDay-Trigger & Zeitumstellung

xenos1984 · 25 Oktober 2020, 00:10:13

Gerade habe ich die Feststellung gemacht, dass sich mein FHEM bei 100% CPU-Last aufgehängt hat. Mit globalem verbose=5 kam folgende Meldung in endloser Wiederholung im Log:

Code Auswählen

2020.10.25 00:27:57.619 5: Starting notify loop for astro, 1 event(s), first is Updated
2020.10.25 00:27:57.621 5: End notify loop for astro

Da lag der Verdacht nahe, dass es an der Zeitumstellung liegt. Der Verdacht erhärtet sich bei einem Blick in die 95_Astro.pm:

Code Auswählen

2517	  {
2518	    if ( $comp eq 'NewDay' ) {
2519	        push @next,
2520	          _timelocal_modern( 0, 0, 0, (localtime($now + 86400.))[3,4], (localtime($now + 86400.))[5]+1900. );
2521	        next;
2522	    }
2523	    my $k = ".$comp";
2524	    next unless ( defined( $Astro{$k} ) && $Astro{$k} =~ /^\d+(?:\.\d+)?$/ );
2525	    my $t =
2526	      _timelocal_modern( 0, 0, 0, (localtime($now))[3,4], (localtime($now))[5]+1900. ) + $Astro{$k} * 3600.;
2527	    $t += 86400. if ( $t < $now );    # that is for tomorrow
2528	    push @next, $t;
2529	  }

Wenn ich das richtig sehe, schaut Zeile 2526 welcher Tag in 24 Stunden ist und setzt einen Timer auf Mitternacht an dem gefundenen Tag. Dummerweise ist in 24 Stunden immer noch heute und nicht morgen, wenn man die Uhr eine Stunde zurückstellt und es zwischen Mitternacht und 1 Uhr ist. Damit wird scheinbar ein Timer in der Vergangenheit gesetzt und auch prompt aufgerufen, was dann zu einer Endlosschleife führt.

Erwartungsgemäß geht es jetzt nach 1 Uhr (Ortszeit hier in Estland) jetzt wieder, da in 24 Stunden morgen ist und der NewDay Trigger erst um Mitternacht wieder zuschlägt.

rakete123 · 25 Oktober 2020, 00:35:40

Kann ich bestätigen. Habe das Astro device eben mal aus der Config rausgenommen und neugestartet. Jetzt gehts wieder.

Prof. Dr. Peter Henning · 26 Oktober 2020, 19:29:42

Kann ich bei mir nicht bestätigen. Ich habe 2 Astro-Devices auf 2 verschiedenen FHEM-Servern. Kann sein, dass das mit dem genauen Termin der Zeitumstellung zusammenhängt. Etwas schwer zu testen...

LG

pah

rakete123 · 26 Oktober 2020, 19:58:19

In meiner zweiten Instanz konnte ich es durch mein Monitoring gut beobachten. Port 8083 war ab 00:00 Uhr nicht mehr erreichbar und ab Punkt 01:00 lief wieder alles. Wenn man in der Zeit sowieso nicht viel von FHEM erwartet hat, bekam man es vermutlich gar nicht mit.

Prof. Dr. Peter Henning · 26 Oktober 2020, 20:53:01

Aber die Zeitumstellung passiert doch um 03:00 - genau wegen solcher Effekte.

LG

pah

xenos1984 · 26 Oktober 2020, 21:01:29

Zitat von: Prof. Dr. Peter Henning am 26 Oktober 2020, 20:53:01
Aber die Zeitumstellung passiert doch um 03:00 - genau wegen solcher Effekte.

Anscheinend spielt der Zeitpunkt der Umstellung dafür keine Rolle, jedenfalls so wie Perl / POSIX die Zeit angibt:

25. 10. 2020, 0 Uhr Sommerzeit (oder kurz danach): NewDay wird getriggert. Mit localtime($now + 86400) wird der Zeitpunkt 24 Stunden später in lokaler Zeit formatiert. Dann gilt aber schon die Normalzeit - Perl liefert dann den 25. 10. 2020 um 23 Uhr zurück (oder kurz danach), also das in Normalzeit formatierte Datum. Daraus macht FHEM / Astro dann als neuen Triggerzeitpunkt den 25. 10. 2020 um Mitternacht. Das ist dann aber nicht der nächste Tag.

rakete123 · 31 Oktober 2021, 00:26:59

Hab wieder das gleiche Problem :-D

MadMax-FHEM · 31 Oktober 2021, 00:46:44

Bin hier ja nur durch Zufall gelandet...
...aber eben wollte ich mal auf mein fhem System: nix...

Dann top -> fhem 100%

Gut service fhem stop / service fhem start -> wieder 100%

Dann service fhem stop / per nano dann attr Astro disable 1 -> service fhem start -> alles wieder i.O.

Und: ab 00:00 keine Logs etc. mehr. Also scheint das so gegen 00:00 gewesen zu sein. Ja ich weiß (wurde ja schon genannt) Zeitumstellung kommt erst noch...
...aber es ist halt jetzt aufgetreten...

Wollte ich nur hier hinterlassen...

Gruß, Joachim

Nobbynews · 31 Oktober 2021, 01:30:37

Zitat von: MadMax-FHEM am 31 Oktober 2021, 00:46:44
Und: ab 00:00 keine Logs etc. mehr. Also scheint das so gegen 00:00 gewesen zu sein.

Dito hier bei mir.
Fhem ab 0:00 Uhr bis 1:00 Uhr nicht ansprechbar.
Im Logffile dann

Code Auswählen

2021.10.31 01:00:03 1: [Freezemon] myFreezemon: possible freeze starting at 00:00:01, delay is 3602.073 possibly caused by: tmr-FHEM::Astro::Update(myAstro) tmr-FileLog_dailySwitch(FileLog)

Norbert

Edit:
Außerdem habe ich noch festgestellt, dass die Zeiten für z.B. CivilTwilightMorning und SunRise mit dem Stand von Timesstamp 00:00:00 noch ohne die Zeitverschiebung berechnet waren. Leider habe ich ein

Code Auswählen

set myAstro update vor Sicherung des "alten" list ausgeführt und kann daher keinen Belege dafür liefern.

xenos1984 · 31 Oktober 2021, 07:24:23

Bei mir ebenfalls wieder der gleiche Effekt, um 0:00 bis 1:00. Es beginnt, wenn um 0:00 NewDay ausgelöst wird und der Zeitpunkt für das nächste NewDay (fehlerhaft) berechnet wird. Und es endet, wenn NewDay wieder korrekt ist.

Zitat von: xenos1984 am 26 Oktober 2020, 21:01:29
Anscheinend spielt der Zeitpunkt der Umstellung dafür keine Rolle, jedenfalls so wie Perl / POSIX die Zeit angibt:

25. 10. 2020, 0 Uhr Sommerzeit (oder kurz danach): NewDay wird getriggert. Mit localtime($now + 86400) wird der Zeitpunkt 24 Stunden später in lokaler Zeit formatiert. Dann gilt aber schon die Normalzeit - Perl liefert dann den 25. 10. 2020 um 23 Uhr zurück (oder kurz danach), also das in Normalzeit formatierte Datum. Daraus macht FHEM / Astro dann als neuen Triggerzeitpunkt den 25. 10. 2020 um Mitternacht. Das ist dann aber nicht der nächste Tag.

erwin · 31 Oktober 2021, 08:27:35

Bin auch dabei, und vermutlich hat das auch DbLog blockiert, siehe:

Code Auswählen

https://forum.fhem.de/index.php/topic,123788.0.html
l.g. erwin

Prof. Dr. Peter Henning · 31 Oktober 2021, 08:59:02

Hmmm, ich kanns nicht nachvollziehen...
Astro läuft in zwei meiner Systeme - allerdings nicht auf einem Raspberry Pi. Keine Blockade...

Könnte der Grund in der Hardware-Echtzeituhr liegen?

LG

pah

erwin · 31 Oktober 2021, 09:59:07

ZitatKönnte der Grund in der Hardware-Echtzeituhr liegen?

.. kann ich nicht sagen, jedenfalls hat der ntpd seinen job richtig gemacht, lt. meinem FHEM-log:

Code Auswählen

2021.10.31 02:56:59.125 3: Invalid response for /common/get_datetime: Can't connect to 192.168.x.y:80
2021.10.31 02:57:00.876 2: AC_Schlafzimmer HVAC_DaikinAC_Poll(): failed (HVAC_DaikinAC_Poll) - Timeout while attempting to poll 192.168.x.y (Timeout: process terminated)
2021.10.31 02:00:13.390 2: ......

(das WLAN der Klimaanlage spinnt.....)
ich hatte zufällig auch apptime am laufen, schaut so als ob alles was mit Internal timer zu tun hatte, in dieser zeit blockiert hat:

Code Auswählen

 name                                     function                               max    count      total  average   maxDly   avgDly TS Max call     param Max call
 tmr-FHEM::Astro::Update                  HASH(0x38508c8)                        134   298321 3595667.91    12.05 3600007.82 1798271.32 29.10. 18:11:11 HASH(myAstro)
 tmr-perfmon_ProcessTimer                 HASH_unnamed                             1   248456   34226.51     0.14 3599251.63    17.58 28.10. 11:46:26 HASH(0xa88ed0)
 tmr-freezemon_ProcessTimer               HASH(0x34ebbe8)                         36   248456  111554.90     0.45 3599235.53    17.01 28.10. 11:46:26 HASH(myfreezemon)
 tmr-FileLog_dailySwitch                  HASH_unnamed                            11        3      29.04     9.68 3599228.50 1199743.56 29.10. 00:00:01 HASH(0x1244e40)
 tmr-DOIFtoolsCounterReset                myDOIFtools                              0        3       1.56     0.52 3596819.15 1198940.48 29.10. 00:00:03 myDOIFtools
 tmr-at_Exec                              HASH(0x2be21b8)                         28        3      79.75    26.58 3595252.99 1198418.05 29.10. 00:00:05 HASH(after_midnight)
 tmr-FW_closeInactiveClients              0                                        7     4142    9880.86     2.39 3583277.93   869.01 31.10. 01:55:00 0
 tmr-HVAC_DaikinAC_StartPoll              HASH(0x38ea230)                         26      824   15932.03    19.33 3581804.81  4348.56 31.10. 02:11:10 HASH(AC_Schlafzimmer)
 tmr-ENIGMA2_GetStatus                    HASH(0x2ecfcd0)                          2     5521    3717.29     0.67 3573941.16   649.16 30.10. 09:46:53 HASH(myVUzero)
 tmr-CustomReadings_OnTimer               HASH(0x1bb90f8)                          6     4141   12198.37     2.95 3568449.56   874.89 30.10. 22:44:30 HASH(mySPCMQTTCheck)
 tmr-MQTT2_CLIENT_keepalive               HASH(0x37f3a28)                          1     4140    1785.22     0.43 3568446.65   879.09 31.10. 01:56:03 HASH(Mosquitto_CL_RPI_3)
 tmr-SamsungAV_Init                       HASH(0x3a81bd0)                         12     4141   15060.61     3.64 3568445.29   872.06 30.10. 01:57:54 HASH(newTV)
 tmr-KNXIO_keepAlive                      HASH(0x3b96598)                         16     4139    7954.26     1.92 3566199.16   868.15 31.10. 07:27:17 HASH(myKNXIO)
 tmr-PRESENCE_StartLocalScan              HASH(0x2acd828)                         31      820   15953.21    19.46 3430449.78  4185.48 30.10. 13:26:11 HASH(VPN_PRESENCE)
 tmr-HVAC_DaikinAC_StartPoll              HASH(0x38f4b20)                         31      827   15898.14    19.22 3348373.12  4050.44 31.10. 03:40:33 HASH(AC_Wohnzimmer)
 tmr-HVAC_DaikinAC_StartPoll              HASH(0x39998a8)                         27      827   15938.04    19.27 3318024.39  4014.28 31.10. 07:26:05 HASH(AC_Kinderzimmer)
 tmr-SYSSTAT_GetUpdate                    HASH(0x23ae368)                        118      829   22495.93    27.14 3316862.89  4002.66 29.10. 12:04:42 HASH(mySYSSTAT)
 tmr-FRITZBOX_Readout_Start               myFritzbox.Readout                      39      829   16098.92    19.42 3311355.59  3996.12 29.10. 17:59:48 myFritzbox.Readout
 tmr-at_Exec                              HASH(0x384c1e8)                         75      420   21546.12    51.30 3000461.64 21471.17 28.10. 22:50:00 HASH(get_ebus_updates)
 tmr-at_Exec                              HASH(0x2def588)                        153      280   26692.62    95.33 3000398.77 23581.64 30.10. 23:40:00 HASH(EnergyPoll)
 tmr-KOSTALPIKO_StatusTimer               myKostal.STATUS                         27       69    1546.34    22.41 921706.75 13359.87 31.10. 07:00:00 myKostal.STATUS
 tmr-PROPLANTA_Start                      HASH(0x27abab0)                         29       69    1393.96    20.20 901970.85 13076.03 31.10. 08:00:00 HASH(myPROPLANTA)
 tmr-statistics_PeriodChange              HASH(0x2df1438)                        116       70    3379.26    48.28  5838.51   133.55 29.10. 23:59:55 HASH(Stromzaehler_stats)

und nach 01:00:00 läuft wieder alles!
Edit: Hardware: raspberry 3B - Linux CL-RPI-2 4.9.35-v7+ #1014
l.g. erwin

Prof. Dr. Peter Henning · 31 Oktober 2021, 10:00:08

Welche Hardware?

LG

pah

xenos1984 · 31 Oktober 2021, 10:09:39

Bei mir ist es ein RPi 4. Aber ich denke nicht, dass es an der Hardware-Echtzeituhr liegt, sondern an der Zeitberechnung

Code Auswählen


2518	    if ( $comp eq 'NewDay' ) {
2519	        push @next,
2520	          _timelocal_modern( 0, 0, 0, (localtime($now + 86400.))[3,4], (localtime($now + 86400.))[5]+1900. );
2521	        next;
2522	    }

"Setze den nächsten Trigger an dem Tag (gemäß lokaler Uhrzeit) um 00:00, der in 86400 Sekunden ist." In 86400 Sekunden ist aber, gemessen in lokaler Zeit, immer noch der gleiche Tag, weil die Uhr ja zwischenzeitlich zurückgestellt wird. Also wird der Trigger nicht für 00:00 am nächsten, sondern am selben Tag gesetzt, und sofort ausgelöst, weil der Zeitpunkt ja bereits erreicht ist. Erst ab 01:00 fällt (jetzt + 86400 Sekunden) auf den nächsten Kalendertag.

Vielleicht könntest du zum testen ein Testsystem aufsetzen und dessen Uhrzeit auf 23:55 am Tag vor der Zeitumstellung setzen? Dann sollte das Phänomen eigentlich auftreten.

Abhilfe schaffen würde statt 86400 Sekunden in die Zukunft eine Stunde weiter zu projizieren. Das funktioniert dann sowohl an normalen Tagen, als auch zur Zeitumstellung.