RESIDENTS wakeuptimer weckt zur defaultZeit, auch wenn andere angegeben ist

[Torsten-]

Hi zusammen,

seit letzter Woche weckt mich mein "Wochentags" Wecker jeden Morgen um 6:00 Uhr, obwohl ich ihn manuell auf eine andere Uhrzeit gestellt habe.
6:00 Uhr ist meine default Weckzeit. Den Resetswitch habe ich mittlerweile ausgeschaltet. Seitdem steht der Wecker permanent auf 7:00 Uhr und auch nextRun zeigt 7:00 Uhr an, es wird aber trotzdem pünktlich zu 6 Uhr geweckt. (Gleiches Problem mit 8:00 Uhr - Systemzeit ist korrekt).

Ich habe letzte Woche zwei Dinge getan: ein FHEM Update und einen Cronjob eingerichtet, der FHEM um 1 Uhr durchstartet.

Zum FHEM Update: Meine aktuellen *RESIDENTS*.pm files kommen vom 8.8. (Tag des Updates). Davor war das letzte Update am 9.7. - im SVN konnte ich keine wirklichen Änderungen am Code finden die relevant wären.

Zum Cronjob: Ich habe ihn für heute Nacht deaktiviert und kann morgen wieder berichten. Aber trotzdem dürfte das den Wecker nicht interessieren. Ich habe schon von Problemen mit Restarts im Zusammenhang mit der wakeupWaitPeriod gesehen, das würde aber eher gegen das zu frühe Wecken sprechen.

Hier ein list meines Weckers:

Code Auswählen Erweitern

Internals:
   NAME       dummy_Torsten_wakeuptimer_weekday
   NR         117
   STATE      07:00
   TYPE       dummy
   Readings:
     2016-08-16 05:40:00   lastRun         06:00
     2016-08-13 19:25:40   nextRun         07:00
     2016-08-16 06:00:01   running         0
     2016-08-16 06:40:00   state           07:00
Attributes:
   alias      Wake-up Timer Wochentags
   comment    Auto-created by ROOMMATE module for use with RESIDENTS Toolkit
   devStateIcon OFF:general_aus@red:reset running:general_an@blue:stop .*:general_an@green:nextRun%20OFF
   group      0.Torsten
   icon       time_timer
   room       Torsten
   setList    nextRun:OFF,00:00,00:15,00:30,00:45,01:00,01:15,01:30,01:45,02:00,02:15,02:30,02:45,03:00,03:15,03:30,03:45,04:00,04:15,04:30,04:45,05:00,05:15,05:30,05:45,06:00,06:15,06:30,06:45,07:00,07:15,07:30,07:45,08:00,08:15,08:30,08:45,09:00,09:15,09:30,09:45,10:00,10:15,10:30,10:45,11:00,11:15,11:30,11:45,12:00,12:15,12:30,12:45,13:00,13:15,13:30,13:45,14:00,14:15,14:30,14:45,15:00,15:15,15:30,15:45,16:00,16:15,16:30,16:45,17:00,17:15,17:30,17:45,18:00,18:15,18:30,18:45,19:00,19:15,19:30,19:45,20:00,20:15,20:30,20:45,21:00,21:15,21:30,21:45,22:00,22:15,22:30,22:45,23:00,23:15,23:30,23:45 reset:noArg trigger:noArg start:noArg stop:noArg end:noArg
   sortby     2
   userattr   wakeupOffset:slider,0,1,120 wakeupDefaultTime:OFF,00:00,00:15,00:30,00:45,01:00,01:15,01:30,01:45,02:00,02:15,02:30,02:45,03:00,03:15,03:30,03:45,04:00,04:15,04:30,04:45,05:00,05:15,05:30,05:45,06:00,06:15,06:30,06:45,07:00,07:15,07:30,07:45,08:00,08:15,08:30,08:45,09:00,09:15,09:30,09:45,10:00,10:15,10:30,10:45,11:00,11:15,11:30,11:45,12:00,12:15,12:30,12:45,13:00,13:15,13:30,13:45,14:00,14:15,14:30,14:45,15:00,15:15,15:30,15:45,16:00,16:15,16:30,16:45,17:00,17:15,17:30,17:45,18:00,18:15,18:30,18:45,19:00,19:15,19:30,19:45,20:00,20:15,20:30,20:45,21:00,21:15,21:30,21:45,22:00,22:15,22:30,22:45,23:00,23:15,23:30,23:45 wakeupMacro wakeupUserdevice wakeupAtdevice wakeupResetSwitcher wakeupResetdays:multiple-strict,0,1,2,3,4,5,6 wakeupDays:multiple-strict,0,1,2,3,4,5,6 wakeupHolidays:andHoliday,orHoliday,andNoHoliday,orNoHoliday wakeupEnforced:0,1,2 wakeupWaitPeriod:slider,0,1,360
   verbose    5
   wakeupAtdevice at_Torsten_wakeuptimer_weekday
   wakeupDays 1,2,3,4,5
   wakeupDefaultTime 06:00
   wakeupEnforced 1
   wakeupHolidays andNoHoliday
   wakeupMacro notify_Torsten_wakeuptimer
   wakeupOffset 20
   wakeupResetSwitcher dummy_Torsten_wakeuptimer_resetswitcher
   wakeupResetdays 1,2,3,4,5
   wakeupUserdevice ROOMMATE_Torsten
   webCmd     nextRun



Und hier das entsprechende Log von heute morgen:

Code Auswählen Erweitern

2016.08.16 05:40:00 4: dummy set dummy_Torsten_wakeuptimer_weekday trigger
2016.08.16 05:40:00 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: lastRun != nextRun = 06:00
2016.08.16 05:40:00 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: trigger notify_Torsten_wakeuptimer (running=1)
2016.08.16 05:40:00 3: notify_Torsten_wakeuptimer: Wake-up program started for ROOMMATE_Torsten with target time 06:00. Current state: asleep
2016.08.16 05:40:00 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: created at-device at_Torsten_wakeuptimer_weekday_stop to stop wake-up program in 20 minutes
2016.08.16 05:40:00 5: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: received unspecified notify 'lastRun:' - nothing to do
2016.08.16 05:40:00 5: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: received unspecified notify 'running:' - nothing to do
2016.08.16 05:40:00 5: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: received unspecified notify 'running' - nothing to do
2016.08.16 05:40:00 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: wakeupGetBegin source: nextRun
2016.08.16 05:40:00 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: wakeupGetBegin result: 07:00 = 24000 s - 20 m = 06:40:00
2016.08.16 06:00:01 4: dummy set dummy_Torsten_wakeuptimer_weekday stop triggerpost
2016.08.16 06:00:01 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: stopping wake-up program
2016.08.16 06:00:01 4: dummy set dummy_Torsten_wakeuptimer_weekday nextRun 07:00
2016.08.16 06:00:01 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: trigger notify_Torsten_wakeuptimer stop 06:00 20 1 ROOMMATE_Torsten asleep
2016.08.16 06:00:01 3: notify_Torsten_wakeuptimer: Wake-up program ended for ROOMMATE_Torsten with target time 06:00. Current state: asleep
2016.08.16 06:00:01 5: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: received unspecified notify 'running:' - nothing to do
2016.08.16 06:05:01 2: ROOMMATE set ROOMMATE_Torsten awoken
...
2016.08.16 06:40:00 4: dummy set dummy_Torsten_wakeuptimer_weekday trigger
2016.08.16 06:40:00 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: lastRun = nextRun = 07:00
2016.08.16 06:40:00 3: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: won't trigger wake-up program due to non-expired wakeupWaitPeriod threshold since lastWakeup (expLastWakeup=1471341599 > nowRunSec=1471323600)
2016.08.16 06:40:00 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: wakeupGetBegin source: nextRun
2016.08.16 06:40:00 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: wakeupGetBegin result: 07:00 = 24000 s - 20 m = 06:40:00

Interessant finde ich auch, das er es um 7 Uhr noch mal probiert. Ich habe es die Tage beobachtet, der Wakeuptimer stand immer in dem Status den ihr oben seht (stat 7:00 Uhr, nextRun 7:00 Uhr). Sowohl vor als auch nach dem FHEM restart.

Habt ihr noch eine Idee woran es liegen könnte? Hatte leider noch keine Zeit mir das Modul selbst anzugucken.

Gruß
  Torsten

PS: Der Wecker lief genau in der Konfiguration seit ca. einem Jahr ohne dieses Problem.

[Loredo]

Ich vermute das verlinkte at-Device unter dem Attribut wakeupAtdevice stimmt nicht (mehr). Das ist der eigentliche Taktgeber wann wirklich das nächste Mal geweckt wird.
Im Zweifel einmal das at-Device löschen und den Wecker neu stellen, dann sollte es neu angelegt werden.


Außerdem hast du über die Festlegung von wakeupDefaultTime gewählt, dass eine veränderte Weckzeit nur ein einziges Mal greift und danach wieder auf die dort eingestellte Zeit zurückgestellt wird, jedoch nur an den unter wakeupResetDays definierten Tagen (entspricht hier ohnehin allen Wecktagen und könnte ggf. auch weg gelassen werden glaube ich). Dadurch, dass wakeupResetSwitcher gesetzt ist, wird das dort hinterlegte Dummy Device zusätzlich geprüft, ob ein Reset stattfinden soll. Wenn das Device nicht existiert, wird es angelegt. Wenn du also den wakeupResetSwitcher deaktivieren willst, musst du tatsächlich auch das Attribut löschen.

[Torsten-]

Hi Loredo,

danke für die Erklärung. Das at-Device muss ich mir dann mal genauer angucken.
Heute durfte ich tatsächlich bis 7 Uhr schlafen - ich habe gestern in FHEM nichts gemacht, ich habe nur den Cronjob zum Restarten deaktiviert, d.h. der Restart von FHEM um 1 Uhr morgens ist der Auslöser für das Problem.
Ich komme die Tage erst wieder dazu, aber dann werde ich mir mal das state-File zu dem at-Device angucken. Meine Vermutung war, das die Weckzeit-Einstellung den FHEM Neustart nicht überlebt, ich hatte aber bisher nur nach dem wakeuptimer geguckt.

Den wakeupResetSwitcher habe ich nur deaktiviert um die Fehlerursache herauszufinden. Der wird zukünftig wieder aktiviert, d.h. komplett entfernen möchte ich den nicht. Ich wollte nur ausschließen, das er die Ursache für die frühe Weckzeit ist.

Gruß
  Torsten

[Torsten-]

Ich habe es ein wenig eingrenzen können:

Beim Restart von FHEM wird wie erwartet vom at-Device die Funktion "RESIDENTStk_wakeupGetBegin" aufgerufen. Laut Log benutzt er dann aber die DefaultTime, nicht die nextRun Zeit.

Code Auswählen Erweitern

2016.08.19 17:08:09 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: wakeupGetBegin source: wakeupDefaultTime
2016.08.19 17:08:09 4: RESIDENTStk dummy_Torsten_wakeuptimer_weekday: wakeupGetBegin result: 06:00 = 20400 s - 20 m = 05:40:00

Laut Code sollte aber nextRun genommen werden:

Code Auswählen Erweitern

    # use nextRun value if not OFF
    if ( $nextRun && lc($nextRun) ne "off" ) {
        $wakeupTime = $nextRun;
        Log3 $NAME, 4, "RESIDENTStk $NAME: wakeupGetBegin source: nextRun";
    }

    # use wakeupDefaultTime if present and not OFF
    elsif ( $wakeupDefaultTime && lc($wakeupDefaultTime) ne "off" ) {
        $wakeupTime = $wakeupDefaultTime;
        Log3 $NAME, 4,
          "RESIDENTStk $NAME: wakeupGetBegin source: wakeupDefaultTime";
    }

Wenn ich mir $nextRun ausgeben lasse während des FHEM-Start, ist der Wert "0". (Vermutlich der default-Wert aus dem ReadingsVal)

Das Device hat aber ein nextRun gesetzt - das wird auch vom Statefile über den Neustart hinweg mitgenommen.

Ich vermute hier gibt es ein timing-Problem - evtl. wird der nextRun-Status erst später wiederhergestellt, wenn die Funktion schon lief?! Dafür kenne ich die fhem.pl zu schlecht.

[Loredo]

Danke für die prima Untersuchung! Es ist schön zu sehen, dass jemand mit dem ausführlichen Logging umzugehen weiß 

Das sieht mir ganz danach aus, dass das at-Device-Modul beim initialen Laden nicht berücksichtigt, dass die Readings anderer Module noch nicht verfügbar sind und per {} gesetzte Perl Befehle wie den für den Wakeuptimer einfach neu ausführt, um seine Timerwerte neu zu berechnen, statt die vor dem Neustart berechneten Werte aus den eigenen Readings wiederherzustellen. Ich sehe da drei Möglichkeiten:

1. das at-Modul wartet ab, bis die Readings aller Devices eingelesen worden sind
2. das at-Modul nutzt nach einem Neustart seine eigenen Readings für das starten der internen Timer, statt diese neu zu berechnen
3. Du hilfst einmal zu evaluieren, wie man DOIF statt dem at-Modul einsetzen kann bzw. ob und wie DOIF aus dem Perl-Befehl seine Aktivierungszeit beziehen kann. Ob dort die Neuberechnung beim Neustart besser implementiert ist, weiß ich nicht.


Bei den Möglichkeiten 1+2 kann wohl nur Rudi als Modul-Maintainer weiterhelfen.

[rudolfkoenig]

Bin nicht sicher, ob ich es richtig verstehe, ich vermute Folgendes: "define X at {function()} Befehl" wird beim Initialisieren ausgefuehrt, damit function() aufgerufen, der aber mangels gesetzten Readings falsche Zeiten zurueckliefert.
Loesungsvorschlaege:
- {function()}  liefert etwas in der Zukunft zurueck, falls die Werte nicht gesetzt sind. Irgendwer (nicht at) reagiert auf global:INITIALIZED, und ruft "modify X {function()}" auf, um die Zeit korrekt zu setzen.
- Die Definition wird modifiziert in "define X *ZEIT Befehl", und Befehl setzt ZEIT erneut, falls das ander ist.

Die vorgeschlagene Loesung, function() in at nach dem einlesen aller Befehle zu setzen hat fuer mich erstmal zu viele Nebeneffekte.
Bitte korrigiert mich, falls ich es falsch verstanden habe

[Loredo]

Hallo Rudi,

danke, dass du dich meldest 

Das ist nicht ganz korrekt: Das at-Device kalkuliert über die Define-Funktion jedes Mal seinen internen Timerstatus neu. Wenn allerdings über {} eine Perl Funktion dafür gesetzt ist und diese Perl Funktion sich für die Berechnung auf vorhandene Readings von Devices verlässt, dann stehen diese Readings während des FHEM Bootvorgangs noch nicht zur Verfügung, weil fhem.save erst danach eingelesen wird. Deshalb kann zu dem Zeitpunkt aus Modulsicht noch nichts unternommen werden (auch kein InternalTimer() für später, da dieser zu dem Zeitpunkt noch blockierend ist).

Als Lösung käme folgende kleine NotifyFn für 90_at.pm in Frage:

Code Auswählen Erweitern


sub
at_Notify($$)
{
  my ( $hash, $dev ) = @_;
  my $name = $hash->{NAME};

  if (   $dev->{NAME} eq "global"
      && grep( m/^INITIALIZED$/, @{ $dev->{CHANGED} } )
      && $hash->{TIMESPEC} =~ m/^{.*}$/ )
  {
      Log3 $name, 4, "$name: Triggered recalculation via Perl function after reboot";
      my $command;
      ( $command, undef ) = split( "[ \t]+", $hash->{DEF}, 2 );
      $command =~ s/^[*+]//;
      return at_Set ($hash, ($name, "modifyTimeSpec", $command) );
  }

  return undef;
}


Allerdings scheint das INITIALIZED Event doppelt zu kommen und die Neukalkulation daher auch doppelt durchgeführt werden (zusätzlich dazu, dass sie vor dem einlesen der fhem.save natürlich auch nochmals durchgeführt wird, dort dann aber wie gesagt wegen der noch fehlenden Readings falsch berechnet).

Eine eigene Notify-Funktion kann ich woanders nicht einbauen, da es sich hierbei um eine Erweiterung von Außerhalb des Dummy-Moduls handelt und eine Erweiterung dort somit keinen Sinn macht.
Auch möchte ich in der at-Definition keine fixe Zeit drin haben, da in FHEMWEB ansonsten natürlich immer ungespeicherte Devices angezeigt werden und ohne ein "save" dann auch bei einem Absturz der letzte Wert verloren geht und auch wieder manuell über einen globalen Eventtrigger korrigiert werden müsste. Das ist alles eher Flickschusterwerk 

Ich habe den Patch mit der fhem.cfg.demo getestet. Du kannst es dort auch selbst wie folgt ausprobieren und vergleichen:

   
• set rr_Son create wakeuptimer
• set rr_Son_wakeuptimer1 08:00
• attr rr_Son_wakeuptimer1,at_rr_Son_wakeuptimer1 verbose 4
• save
• shutdown restart

Ohne den Patch steht das Device at_rr_Son_wakeuptimer1 auf 05:00 und unterscheidet sich somit von gesetzten Wert in rr_Son_wakeuptimer1. Mit dem Patch werden die beiden Devices korrekt nach :INITIALIZED wieder synchronisiert.



Gruß
Julian

[rudolfkoenig]

Das ist nicht ganz korrekt:...

Ich habs also richtig verstanden: ihr seid nicht die Ersten mit diesem Problem

auch kein InternalTimer() für später, da dieser zu dem Zeitpunkt noch blockierend ist

Das ist mAn falsch, man kann naemlich das notify auf "global:INITIALIZED" mit einem InternalTimer(1, ..., ..., 0) simulieren.
InternalTimer muesste so vom RESIDENTStk_wakeupGetBegin aufgerufen werden, falls !$init_done.

Ich werde aber auch ein at Attribut einbauen, damit at den Ausdruck nach einlesen der Readings nochmal ausfuehrt, es gab naemlich auch einen anderen Fall, mit gleicher Ursache.

[Loredo]

Ich habs also richtig verstanden:

Äh ja *räusper*
Mein Fehler, sorry 

Das ist mAn falsch, man kann naemlich das notify auf "global:INITIALIZED" mit einem InternalTimer(1, ..., ..., 0) simulieren.
InternalTimer muesste so vom RESIDENTStk_wakeupGetBegin aufgerufen werden, falls !$init_done.

Ah den letzten Parameter kannte ich noch nicht. Hatte es nur ohne versucht und das ging dann natürlich nicht. So geht es aber und hat dann den selben Effekt wie die NotifyFn in 90_at.pm.
Allerdings wird auch hier die Neuberechnung einmal mehr als nötig ausgeführt:
Leider funktioniert es so aber nicht: Ich setze zwar den InternalTimer, er wird aber offenbar nicht aufgerufen:

Code Auswählen Erweitern


    if ($wakeupAtdevice) {
        # let at-device recalculate after global:INITIALIZED event
        # as $nextRun can only be undef at that stage
        if ( !$init_done ) {
            Log3 $NAME, 4,
"RESIDENTStk $NAME: Waiting for FHEM initialization to recalculate Wakeuptime";
            InternalTimer( 1, RESIDENTStk_wakeupGetBegin,
                ( $NAME, $wakeupAtdevice ), 0 );
            return $wakeupInitTime;
        }
        else {
            Log3 $NAME, 4,
"RESIDENTStk $NAME: Wakeuptime recalculation triggered by at-device $wakeupAtdevice";
        }
    }


Ich vermute, dass der letzte Parameter 1 sein muss, nicht 0. Aber damit passiert dann auch nichts.
Setze ich den ersten Parameter auf eine Unixtime+5sec, dann blockiert FHEM diese 5 Sekunden und macht dann normal weiter. Die Funktion wird auch nicht aufgerufen.

Ich werde aber auch ein at Attribut einbauen, damit at den Ausdruck nach einlesen der Readings nochmal ausfuehrt, es gab naemlich auch einen anderen Fall, mit gleicher Ursache.

Ok! Da warte ich mal ab, wie es sich dann damit verhält. Bisher funktioniert es halt nur mit der neuen NotifyFn in 90_at.pm


Gruß
Julian

[Loredo]

Ich habe das Notify jetzt erstmal in ROOMMATE und GUEST aufgenommen:
https://sourceforge.net/p/fhem/code/12016/


@Torsten, damit ist dein Problem erstmal erledigt.

[rudolfkoenig]

Hab das Attribut computeAfterInit eingebaut:

If perlfunc() in the timespec relies on some other/dummy readings, then
it will return a wrong time upon FHEM start, as the at define is
processed before the readings are known. If computeAfterInit is set,
FHEM will recompute timespec after the initialization is finished.

[Loredo]

Vielen Dank Rudi, funktioniert.
Ich habe die Module entsprechend angepasst.


Vielleicht bei Gelegenheit noch das Logging in 90_at.pm korrigieren

Code Auswählen Erweitern



2016.08.21 14:01:32.740 1: IT


[rudolfkoenig]

Danke, habs entfernt.

[Torsten-]

Perfekt, das ging ja schnell mit dem Bugfix.
Danke an alle beteiligte!
Nächstes mal wenn ich ausschlafen will werde ich an euch denken 

[Damian]

3. Du hilfst einmal zu evaluieren, wie man DOIF statt dem at-Modul einsetzen kann bzw. ob und wie DOIF aus dem Perl-Befehl seine Aktivierungszeit beziehen kann. Ob dort die Neuberechnung beim Neustart besser implementiert ist, weiß ich nicht.

Nur mal zur Info: Beim DOIF werden die Timer erst nach der abgeschlossenen Initialisierungsphase gesetzt.

Gruß

Damian