[gelöst] WeekdayTimer profile damaged or incomplete

[persching]

Hallo zusammen,
ich hatte es in der letzten Woche 2x dass ein WDT als "damaged or incomplete" gelesen wird, was dazu führt, dass der FHEM Container in einer Endlosschleife wieder startet und sich beendet.

2020.07.08 08:58:00.475 3: From the FHEM_GLOBALATTR environment: attr global nofork 0
Can't use an undefined value as an ARRAY reference at ./FHEM/98_WeekdayTimer.pm line 1212.

2020.07.08 08:57:49.213 1: ERROR evaluating my $NAME='OG_KiZi_Lara_T';my $EVENT='';{my $days={};map{$days->{$_}=1}();;( 1 && )}: syntax error at (eval 2030) line 1, near "&& )"
2020.07.08 08:57:49.213 1: PERL WARNING: Use of uninitialized value $v in concatenation (.) or string at fhem.pl line 1142.
2020.07.08 08:57:49.213 1: PERL WARNING: Use of uninitialized value $v in substitution (s///) at fhem.pl line 1141.
2020.07.08 08:57:49.212 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_WeekdayTimer.pm line 1216.
2020.07.08 08:57:49.211 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_WeekdayTimer.pm line 1050.
2020.07.08 08:57:49.211 0: [WDT_Lara] profile WP_Thermostate:Off:Lara, item 20 seems to be somehow damaged or incomlete!

Man kann das dann lösen indem man ein

Code Auswählen Erweitern

set WP_Thermostate remove_profile Off:Lara

schnell genug ausführt und danach das Profil wieder von einem anderes Profil kopiert und ihm den alten Profilnamen vergibt. Komischerweise war es 2x das Profil meiner Tochter das diesen Fehler hervorruft. Ich habe die Configdatei in der ConfigDB importiert und kann sie deshalb auch nicht mal eben Offline bearbeiten.
Kann man den Fehler abfangen, dass nur eine Warnmeldung ausgegeben wird? Oder das Defaultprofil verwendet wird?

[Beta-User]

Hi, vorab mal sorry für den trouble...

Bei einem ersten Blick in den Code war ich erst mal ratlos, diese Prüfung habe ich vor einiger Zeit eingeführt, um in so einem Fall den direkten Absturz abzufangen. Das Modul ist aktuell, oder?

Hast du bitte mal ein list von dem WDT (gerne mit einem funktionierenden Profil) und dann noch die Ausgabe des getters für weekprofile von "WP_Thermostate" bzgl. "Off:Lara". Damit sollte sich das dann ggf. nachstellen lassen...

Und: Kannst du ggf. einen Zusammenhang mit dem Wechsel des Profils erkennen?

[persching]

Kein Problem mit dem Trouble, derzeit ist ja keine Heizphase und somit saß niemand im kalten! Und ich finde es ja super und bin dankbar, dass sich jemand die Mühe macht und das alles programmiert und allen zur Verfügung stellt.

Zur Version:

Code Auswählen Erweitern

CONFIGFILE ./log/weekprofile-WP_Thermostate.cfg
   FUUID      5e0887c5-f33f-b0f8-36c4-a188664da09a159b
   FVERSION   98_weekprofile.pm:v1.1.0-s21373/2020-03-07
   NAME       WP_Thermostate
   NR         252
   NTFY_ORDER 50-WP_Thermostate
   STATE      created
   TYPE       weekprofile
   Helper:
     DBLOG:
       profile_count:
         logdb:
           TIME       1594191558.45371
           VALUE      43
       state:
         logdb:
           TIME       1594191558.45022
           VALUE      PROFILES_SAVED
       topics:
         logdb:
           TIME       1594191558.45371
           VALUE      default:Arbeitstag:Nachtabsenkung:Abwesend:Ferien:Kachelofen:Minimal:Off

get WP_Thermostate profile_data Off:Lara (natürlich jetzt schon wieder die funktionierende Version):

Code Auswählen Erweitern


{"Fri":{"temp":["5.0"],"time":["24:00"]},"Sat":{"time":["24:00"],"temp":["5.0"]},"Thu":{"temp":["5.0"],"time":["24:00"]},"Tue":{"temp":["5.0"],"time":["24:00"]},"Wed":{"time":["24:00"],"temp":["5.0"]},"Sun":{"time":["24:00"],"temp":["5.0"]},"Mon":{"temp":["5.0"],"time":["24:00"]}}


Wenn der Fehler gerade aktuell ist, dann kommt ein JSON Fehler und die Tabelle mit den Temperaturen kann nicht dargestellt werden. Aber im Fehlerfall würde ich gar kein get hinbekommen, da dann sofort FHEM abstürzt.

list WDT_Lara:

Code Auswählen Erweitern

COMMAND   
   CONDITION 
   DEF        OG_KiZi_Lara_T weekprofile:WP_Thermostate
   DEVICE     OG_KiZi_Lara_T
   FUUID      5e0b0cb8-f33f-b0f8-126f-981f8e97d738f047
   FVERSION   98_WeekdayTimer.pm:0.222220/2020-06-21
   GlobalDaylistSpec
   LANGUAGE   de
   NAME       WDT_Lara
   NR         260
   Profil 0: Sonntag 00:10:00 19.5, 07:00:00 19.0, 20:00:00 19.5,
   Profil 1: Montag 00:10:00 19.5, 07:00:00 19.0, 20:00:00 19.5,
   Profil 2: Dienstag 00:10:00 19.5, 07:00:00 19.0, 20:00:00 19.5,
   Profil 3: Mittwoch 00:10:00 19.5, 07:00:00 19.0, 20:00:00 19.5,
   Profil 4: Donnerstag 00:10:00 19.5, 07:00:00 19.0, 20:00:00 19.5,
   Profil 5: Freitag 00:10:00 19.5, 07:00:00 19.0, 20:00:00 19.5,
   Profil 6: Samstag 00:10:00 19.5, 07:00:00 19.0, 20:00:00 19.5,
   STATE      open window
   STILLDONETIME 0
   TYPE       WeekdayTimer
   VERZOEGRUNG 1
   VERZOEGRUNG_IDX 20
   Helper:
     DBLOG:
       state:
         logdb:
           TIME       1594191513.81379
           VALUE      open window
   OLDREADINGS:
     2020-07-06 19:03:57   weekprofiles    WP_Thermostate:Abwesend:Lara
   READINGS:
     2020-07-08 08:58:30   currValue       19.0
     2020-07-08 08:58:30   nextUpdate      2020-07-08 20:00:00
     2020-07-08 08:58:30   nextValue       19.5
     2020-07-08 10:48:33   state           open window
     2020-07-08 08:58:32   weekprofiles    WP_Thermostate:Off:Lara
   SWITCHINGTIMES:
   TIMER:
     WDT_Lara_20:
       HASH       WDT_Lara
       MODIFIER   20
       NAME       WDT_Lara_20
     WDT_Lara_SetTimerOfDay:
       HASH       WDT_Lara
       MODIFIER   SetTimerOfDay
       NAME       WDT_Lara_SetTimerOfDay
       SETTIMERATMIDNIGHT 1
   helper:
     daysRegExp (so|mo|di|mi|do|fr|sa|\$we|\!\$we)
     daysRegExpMessage (so|mo|di|mi|do|fr|sa|$we|!$we)
     SWITCHINGTIME:
     WEDAYS:
       3          1
       4          1
   profil:
     20:
   profile_IDX:
     0:
       00:10:00   10
       07:00:00   11
       20:00:00   12
     1:
       00:10:00   4
       07:00:00   5
       20:00:00   6
     2:
       00:10:00   16
       07:00:00   17
       20:00:00   18
     3:
       00:10:00   19
       07:00:00   20
       20:00:00   21
     4:
       00:10:00   13
       07:00:00   14
       20:00:00   15
     5:
       00:10:00   1
       07:00:00   2
       20:00:00   3
     6:
       00:10:00   7
       07:00:00   8
       20:00:00   9
   weekprofiles:
     WP_Thermostate:
       PROFILE    Abwesend:Lara
       PROFILE_JSON {"Wed":{"time":["07:00","20:00","24:00"],"temp":["19.5","19.0","19.5"]},"Tue":{"time":["07:00","20:00","24:00"],"temp":["19.5","19.0","19.5"]},"Mon":{"time":["07:00","20:00","24:00"],"temp":["19.5","19.0","19.5"]},"Sun":{"temp":["19.5","19.0","19.5"],"time":["07:00","20:00","24:00"]},"Thu":{"time":["07:00","20:00","24:00"],"temp":["19.5","19.0","19.5"]},"Sat":{"temp":["19.5","19.0","19.5"],"time":["07:00","20:00","24:00"]},"Fri":{"temp":["19.5","19.0","19.5"],"time":["07:00","20:00","24:00"]}}
       SunAsWE    0
       PROFILE_DATA:
         Fri:
           temp:
             19.5
             19.0
             19.5
           time:
             07:00
             20:00
             24:00
         Mon:
           temp:
             19.5
             19.0
             19.5
           time:
             07:00
             20:00
             24:00
         Sat:
           temp:
             19.5
             19.0
             19.5
           time:
             07:00
             20:00
             24:00
         Sun:
           temp:
             19.5
             19.0
             19.5
           time:
             07:00
             20:00
             24:00
         Thu:
           temp:
             19.5
             19.0
             19.5
           time:
             07:00
             20:00
             24:00
         Tue:
           temp:
             19.5
             19.0
             19.5
           time:
             07:00
             20:00
             24:00
         Wed:
           temp:
             19.5
             19.0
             19.5
           time:
             07:00
             20:00
             24:00
Attributes:
   DbLogExclude .*
   DbLogInclude state
   WDT_Group  WDT_Group_Lara
   WDT_delayedExecutionDevices OG_KiZi_Lara_Fensterkontakt OG_KiZi_Lara_DF_Fensterkontakt
   commandTemplate set $NAME desiredTemperature $EVENT
   event-on-change-reading state,currValue
   group      Profile
   oldreadings weekprofiles
   room       Roomdetails->Lara
   switchInThePast 1
   userattr   weekprofile
   weekprofile Lara

Und ja, es könnte mit einem Profilwechsel zusammenhängen. Aber 100% konnte ich es noch nicht nachvollziehen. Eigentlich wäre jetzt derzeit gar kein Profilwechsel notwendig, denn es sind ja alle Heizkörper im Profil "Off" und somit auf 5°C eingestellt. Aber hier bin ich noch etwas hinten dran mit einer sinnvollen Umsetzung.

[Beta-User]

OK, jetzt habe ich wenigstens eine Idee. Das neue Profil scheint wirksam geworden zu sein, während das alte irgendwie in einem Delayed-Zustand war. In diesem Fall war dann  noch ein Timer übriggeblieben, der keinen Bezugspunkt mehr auf das aktuelle Profil hatte...

Kannst du mal bitte beigefügte Version testen, die sollte das (u.a. auch) an dieser Stelle berücksichtigen, wenn jemand das Fenster offen gelassen hatte.

[persching]

Ja werde ich testen. Aber ich weiß nicht, wie ich den Fehler jetzt provozieren soll, insofern kann es dauern bis ich sagen kann, ob alles IO ist.

[Beta-User]

Na ja, für's erste wäre mal wichtig, dass es keine neuen Abstürze gibt, also keine Regression.

Dann kannst du das vermutlich testen, indem du bei offenem Fenster das "kürzere" Off-Profil setzt und 10 Min. wartest. Ist danach weiter alles iO., sollte es das gewesen sein...

[Beta-User]

Was ich allerdings noch nicht ganz verstanden habe, ist das hier:

Wenn der Fehler gerade aktuell ist, dann kommt ein JSON Fehler und die Tabelle mit den Temperaturen kann nicht dargestellt werden. Aber im Fehlerfall würde ich gar kein get hinbekommen, da dann sofort FHEM abstürzt.

Das deutet darauf hin, dass das Profil selbst irgendwo im Hintergrund geändert wird?

An sich wäre das dem WDT egal, der ruft die Daten nur bei entsprechender Anweisung bzw. beim FHEM-Start ab. Kommt da was zurück, ist das so lange gültig, bis eine neue Anweisung kommt. Die Daten selbst werden intern verwaltet bzw. bei jedem Lesevorgang in das WDT-Format überführt.

[persching]

Was ich allerdings noch nicht ganz verstanden habe, ist das hier:Das deutet darauf hin, dass das Profil selbst irgendwo im Hintergrund geändert wird?

An sich wäre das dem WDT egal, der ruft die Daten nur bei entsprechender Anweisung bzw. beim FHEM-Start ab. Kommt da was zurück, ist das so lange gültig, bis eine neue Anweisung kommt.

Warum die Daten korrupt sind, weiß ich nicht. Ich hatte schon länger keine Änderungen mehr an den Profilen gemacht. Ich kann dir nur sagen, dass es so war.

Da sich der Docker Container immer wieder neu startete, wurden die Daten ja immer wieder abgerufen. Das hat wieder dazu geführt, dass der Container neu gestartet wurde... Ich vermute ja fast, dass das nicht abzufangen ist, weil es im Moment des Zugriffs zum Absturz kommt. Aber wenn doch, dann wäre es ja sinnvoll, dass man dann lieber auf Default:default geht oder wenn du sagst, dass die Daten geladen werden und dann im WDT verwaltet werden, dann eben besser nix tun.

[Beta-User]

Vielleicht zur Klarstellung:

Der log-Eintrag bedeutet nur, dass das Modul _denkt_, die Daten wären kaputt ("might"). Das ist aber bereits eine Interpretation und bedeutet mitnichten, dass es tatsächlich so war oder ist... Wenn du also nichts geändert hattest, und jetzt eine unkorrupte Rückmeldung auf "get" kommt, ist mit einiger Wahrscheinlichkeit lediglich diese Interpretation falsch .

Ob ein Rückgriff auf default:default sinnvoll wäre, ist eine andere Frage. Was deine Konstellation betrifft - vorausgesetzt, die Hypothese mit dem "offenen Fenster" ist zutreffend - ist dieser Rückgriff hier unnötig, es ist lediglich beim Tausch des Profils auch der verzögerte Timer zu löschen, wenn in diesem zusammenhang der WDT vollständig neu initialisiert wird.

Um die Hypothese zu erhärten wäre es allerdings ggf. hilfreich zu wissen, ob im Zusammenhang mit dem Neustart eventuell ein Profilwechsel veranlasst wurde? Dann müßte es irgendeinen Eventhandler geben, der auf einen Statuswechsel - vermutlich rund um den betreffenden Bewohner - reagiert und irgendwie noch keine bzw. alte Werte hat... Sowas kannst aber nur du wissen.

Unabhängig davon dürfte das Ergänzen dieser zwei Zeilen nicht schaden, von daher checke ich das bei nächster Gelegenheit ein .

[persching]

So, zwei Wochen ohne Fehler. Ich denke deine Änderung war hilfreich. Danke! 

[Beta-User]

Danke für die Rückmeldung.

Markierst du bitte noch als [gelöst]?