WeekdayTimer - Nach Neuinstallation alles doppelt ausgeführt

Matze89 · 14 November 2021, 14:50:22

Aber ich bin wirklich etwas verunsichert, wo ich ansetzen soll. Aktuelles FHEM, aktuelles BS.
Wo kann ich da jetzt selber ansetzen? Also du siehst schon den Fehler? Ich sehe nicht, wo ich selber noch - auch rein persönlich für die Rollos, ansetzen kann. Womöglich ganz auf Weekdaytimer verzichten?

Sorry bin ratlos.

Beta-User · 14 November 2021, 15:00:29

Falls du warten kannst: ich werde das wohl fixen können, es wird aber vermutlich ein paar Tage dauern, weil der Code an einer zentralen Stelle umstrukturiert werden muss.
Tester sind dann willkommen

.

Matze89 · 14 November 2021, 15:49:29

Okay, werde ich machen und warten.

Vielen Dank.

Beta-User · 15 November 2021, 16:31:39

So, dann hier mal eine erste Iteration.
Damit konnte ich zumindest dieses seltsame delay nicht reproduzieren:

Zitat2021.11.14 11:00:00.003 4: [timer_rollo_sz] time={sunset_abs('REAL',-1500,"10:59","11:00")}/1636884000 delay=-1, nextDelay=60, nextRetry=1636884060

Die Codestruktur gefällt mir jetzt insgesamt besser, allerdings besteht bei solchen größeren Eingriffen immer das Risiko, dass was in die Hose geht... Test im Hauptsystem steht auch noch aus, auf dem Testsystem hatte ich jedenfalls bis dato keine Crashes => Testen auf eigene Gefahr.

Matze89 · 15 November 2021, 20:59:13

ok, auf gehts:

Code Auswählen

# $Id: 98_WeekdayTimer.pm 25110 2021-11-15 restructured Beta-User $

doif.js                    24438 2021-05-14 18:08:18Z Ellert
f18.js                     24575 2021-06-03 09:52:42Z rudolfkoenig
fhemweb.js                 25022 2021-09-27 07:11:18Z rudolfkoenig
fhemweb_readingsGroup.js   15189 2017-10-03 17:53:27Z justme1968

Code Auswählen

2021.11.15 20:56:20.009 4: ROLLO (rollo_sz) updating state to closed
2021.11.15 20:56:20.009 4: ROLLO (rollo_sz) drives to end pct and autostop is enabled. No stop command executed
2021.11.15 20:56:20.009 4: ROLLO (rollo_sz) stops from drive-down at pct 100
2021.11.15 20:56:20.009 5: ROLLO (rollo_sz) >> Stop
2021.11.15 20:56:20.000 5: ROLLO (rollo_sz) >> Timer
2021.11.15 20:56:00.141 4: [timer_rollo_sz] command: 'set $NAME $EVENT' executed with %EVENT=>closed,%NAME=>rollo_sz
2021.11.15 20:56:00.140 4: ROLLO (rollo_sz) stop in 20 seconds.
2021.11.15 20:56:00.135 3: MQTT2_DEVICE set mqtt_rollo_sz down
2021.11.15 20:56:00.126 4: ROLLO (rollo_sz) execute following commands: set mqtt_rollo_sz down; ; 
2021.11.15 20:56:00.114 4: ROLLO (rollo_sz) calculateDriveTime: oldpos=0,newpos=100,direction=down,time=19,steps=100,drivetime=20
2021.11.15 20:56:00.113 5: ROLLO (rollo_sz) netto drive time = 19
2021.11.15 20:56:00.113 5: ROLLO (rollo_sz) >> calculateDriveTime | going down: from 0 to 100
2021.11.15 20:56:00.112 4: ROLLO (rollo_sz) pct: 0 -> 100 / direction: down
2021.11.15 20:56:00.112 4: ROLLO (rollo_sz) drive from 0 to 100. command: closed. state: drive-down
2021.11.15 20:56:00.112 5: ROLLO (rollo_sz) >> Start
2021.11.15 20:56:00.074 4: ROLLO (rollo_sz) calculated pct is 100; rest drivetime is 19
2021.11.15 20:56:00.074 5: ROLLO (rollo_sz) >> calculatepct
2021.11.15 20:56:00.074 5: ROLLO (rollo_sz) DesiredPos now 100, closed
2021.11.15 20:56:00.074 5: ROLLO (rollo_sz) DesiredPos set to closed, () 
2021.11.15 20:56:00.074 5: ROLLO (rollo_sz) >> Set (closed,)
2021.11.15 20:56:00.073 4: [timer_rollo_sz] aktParam: newParam:closed - is not disabled
2021.11.15 20:56:00.069 4: [timer_rollo_sz] Update   - timer seems to be active today: 0123456|{sunset_abs('REAL',-1500,"20:56","20:57")}|closed
2021.11.15 20:56:00.069 4: [timer_rollo_sz] list of window sensors found: 'timer_rollo_sz'
2021.11.15 20:56:00.068 4: [timer_rollo_sz] time={sunset_abs('REAL',-1500,"20:56","20:57")}/1637006160 delay=0, nextDelay=60, nextRetry=1637006220
2021.11.15 20:56:00.062 4: [timer_rollo_sz] command: 'set $NAME $EVENT' executed with %NAME=>rollo_sz,%EVENT=>closed
2021.11.15 20:56:00.062 4: ROLLO (rollo_sz) stop in 20 seconds.
2021.11.15 20:56:00.055 3: MQTT2_DEVICE set mqtt_rollo_sz down
2021.11.15 20:56:00.040 4: ROLLO (rollo_sz) execute following commands: set mqtt_rollo_sz down; ; 
2021.11.15 20:56:00.027 4: ROLLO (rollo_sz) calculateDriveTime: oldpos=100,newpos=100,direction=down,time=19,steps=100,drivetime=20
2021.11.15 20:56:00.027 5: ROLLO (rollo_sz) netto drive time = 19
2021.11.15 20:56:00.027 4: ROLLO (rollo_sz): forceDrive set, driving down
2021.11.15 20:56:00.027 4: ROLLO (rollo_sz) already at position!
2021.11.15 20:56:00.027 5: ROLLO (rollo_sz) >> calculateDriveTime | going down: from 100 to 100
2021.11.15 20:56:00.026 4: ROLLO (rollo_sz) pct: 100 -> 100 / direction: down
2021.11.15 20:56:00.026 4: ROLLO (rollo_sz) drive from 100 to 100. command: closed. state: closed
2021.11.15 20:56:00.025 5: ROLLO (rollo_sz) >> Start
2021.11.15 20:56:00.012 5: ROLLO (rollo_sz) DesiredPos now 100, closed
2021.11.15 20:56:00.012 5: ROLLO (rollo_sz) DesiredPos set to closed, () 
2021.11.15 20:56:00.012 5: ROLLO (rollo_sz) >> Set (closed,)
2021.11.15 20:56:00.011 4: [timer_rollo_sz] aktParam: newParam:closed - is not disabled
2021.11.15 20:56:00.005 5: [timer_rollo_sz] removing Timer: timer_rollo_sz_4
2021.11.15 20:56:00.005 4: [timer_rollo_sz] Update   - timer seems to be active today: 0123456|{sunset_abs('REAL',-1500,"20:56","20:57")}|closed
2021.11.15 20:56:00.004 5: [timer_rollo_sz] resetting Timer: timer_rollo_sz_4
2021.11.15 20:56:00.003 4: [timer_rollo_sz] list of window sensors found: 'timer_rollo_sz'
2021.11.15 20:56:00.001 4: [timer_rollo_sz] time={sunset_abs('REAL',-1500,"20:56","20:57")}/1637006160 delay=-1, nextDelay=60, nextRetry=1637006220

2021.11.15 20:56:00.135 3: MQTT2_DEVICE set mqtt_rollo_sz down
2021.11.15 20:56:00.055 3: MQTT2_DEVICE set mqtt_rollo_sz down

und die letzte Zeile beinhaltet deine delay=-1 darin. Kann es wirklich nicht am aktuellen Raspbian liegen?
Ich update jetzt das System bei meinen Eltern auf die aktuellste FHEM Version. Darauf läuft das vorherige Raspbian. Ansonsten ist vieles identisch, natürlich nur andere Module/Aufgaben im Einsatz. Ich bastle dort die gleichen Befehle wie hier ein. Ich poste daraufhin die Werte vom Raspbian Bulleye und dem Raspbian Buster.

Gruß Matthias

Matze89 · 16 November 2021, 09:41:20

Raspberry Buster - Da funktioniert es - alles aktuell.

Code Auswählen


File               Rev   Last Change

98_WeekdayTimer.pm 25110 2021-10-24 06:11:37Z Beta-User

f18.js                     24575 2021-06-03 09:52:42Z rudolfkoenig
fhemweb.js                 25022 2021-09-27 07:11:18Z rudolfkoenig

Version

Code Auswählen


Latest Revision: 25232

File               Rev   Last Change

fhem.pl            25197 2021-11-07 14:07:23Z rudolfkoenig
39_alexa.pm        23820 2021-02-24 19:29:15Z justme1968
98_autocreate.pm   23727 2021-02-12 20:31:37Z rudolfkoenig
91_eventTypes.pm   23471 2021-01-04 19:24:21Z rudolfkoenig
01_FHEMWEB.pm      25189 2021-11-06 10:25:54Z rudolfkoenig
92_FileLog.pm      24967 2021-09-13 16:09:40Z rudolfkoenig
88_HMCCU.pm        25221 2021-11-13 17:37:14Z zap
88_HMCCUDEV.pm     25221 2021-11-13 17:37:14Z zap
88_HMCCURPCPROC.pm 25221 2021-11-13 17:37:14Z zap
98_JsonList2.pm    23727 2021-02-12 20:31:37Z rudolfkoenig
82_LGTV_WebOS.pm   22008 2020-05-22 19:47:25Z CoolTux
10_MQTT2_DEVICE.pm 24861 2021-08-20 09:04:35Z rudolfkoenig
91_notify.pm       25231 2021-11-15 17:34:18Z rudolfkoenig
44_ROLLO.pm        18436 2019-01-27 20:46:04Z KernSani
99_SUNRISE_EL.pm   24249 2021-04-14 05:45:49Z rudolfkoenig
99_Utils.pm        24128 2021-04-02 16:29:11Z rudolfkoenig
98_version.pm      15140 2017-09-26 09:20:09Z markusbloch
98_WeekdayTimer.pm 25110 2021-10-24 06:11:37Z Beta-User

AttrTemplate.pm    25155 2021-10-30 12:48:21Z rudolfkoenig
Blocking.pm        23268 2020-12-01 11:48:48Z rudolfkoenig
CoProcess.pm       24043 2021-03-21 16:21:46Z justme1968
DevIo.pm           24800 2021-07-26 11:42:33Z rudolfkoenig
GPUtils.pm         19666 2019-06-20 11:17:29Z CoolTux
HMCCUConf.pm       25212 2021-11-10 17:51:58Z zap
HttpUtils.pm       25103 2021-10-22 12:00:39Z rudolfkoenig
Meta.pm            21008 2020-01-18 10:22:10Z loredo
RTypes.pm          10476 2016-01-12 21:03:33Z borisneubert
SetExtensions.pm   23300 2020-12-06 11:36:24Z rudolfkoenig
TcpServerUtils.pm  23472 2021-01-04 19:56:38Z rudolfkoenig

f18.js                     24575 2021-06-03 09:52:42Z rudolfkoenig
fhemweb.js                 25022 2021-09-27 07:11:18Z rudolfkoenig

Code Auswählen

[2021.11.16 09:28:20 4: ROLLO (rollo_sz) updating state to closed
2021.11.16 09:28:20 4: ROLLO (rollo_sz) drives to end pct and autostop is enabled. No stop command executed
2021.11.16 09:28:20 4: ROLLO (rollo_sz) stops from drive-down at pct 100
2021.11.16 09:28:20 5: ROLLO (rollo_sz) >> Stop
2021.11.16 09:28:20 1: Rollo Schlafzimmer wurde geschlossen.
2021.11.16 09:28:20 5: ROLLO (rollo_sz) >> Timer
2021.11.16 09:28:00 4: ROLLO (rollo_sz) stop in 20 seconds.
2021.11.16 09:28:00 3: MQTT2_DEVICE set mqtt_rollo_sz down
2021.11.16 09:28:00 4: ROLLO (rollo_sz) execute following commands: set mqtt_rollo_sz down; ; 
2021.11.16 09:28:00 4: ROLLO (rollo_sz) calculateDriveTime: oldpos=100,newpos=100,direction=down,time=19,steps=100,drivetime=20
2021.11.16 09:28:00 5: ROLLO (rollo_sz) netto drive time = 19
2021.11.16 09:28:00 4: ROLLO (rollo_sz): forceDrive set, driving down
2021.11.16 09:28:00 4: ROLLO (rollo_sz) already at position!
2021.11.16 09:28:00 5: ROLLO (rollo_sz) >> calculateDriveTime | going down: from 100 to 100
2021.11.16 09:28:00 4: ROLLO (rollo_sz) pct: 100 -> 100 / direction: down
2021.11.16 09:28:00 4: ROLLO (rollo_sz) drive from 100 to 100. command: closed. state: closed
2021.11.16 09:28:00 5: ROLLO (rollo_sz) >> Start
2021.11.16 09:28:00 5: ROLLO (rollo_sz) DesiredPos now 100, closed
2021.11.16 09:28:00 5: ROLLO (rollo_sz) DesiredPos set to closed, () 
2021.11.16 09:28:00 5: ROLLO (rollo_sz) >> Set (closed,)
2021.11.16 09:28:00 4: [timer_rollo_sz] command: 'set $NAME $EVENT' executed with %NAME=>rollo_sz,%EVENT=>closed
2021.11.16 09:28:00 4: [timer_rollo_sz] aktParam: newParam:closed - is not disabled
2021.11.16 09:28:00 5: [timer_rollo_sz] removing Timer: timer_rollo_sz_4
2021.11.16 09:28:00 4: [timer_rollo_sz] Update   - timer seems to be active today: 0123456|{sunset_abs('REAL',-1500,"09:27","09:28")}|closed
2021.11.16 09:28:00 5: [timer_rollo_sz] result of condition: 1
2021.11.16 09:28:00 5: [timer_rollo_sz] condition: { my $days={};;map{$days->{$_}=1}(0,1,2,3,4,5,6) ;;;; ( 1 && (defined $days->{$wday})) }
2021.11.16 09:28:00 4: [timer_rollo_sz] condition: - Tage:0,1,2,3,4,5,6
2021.11.16 09:28:00 4: [timer_rollo_sz] list of window sensors found: 'timer_rollo_sz'
2021.11.16 09:28:00 4: [timer_rollo_sz] result of delayedExecutionCond: 0
2021.11.16 09:28:00 4: [timer_rollo_sz] delayedExecutionCond:0
2021.11.16 09:28:00 4: [timer_rollo_sz] time={sunset_abs('REAL',-1500,"09:27","09:28")}/1637051280 delay=0, nextDelay=60, nextRetry=1637051340

Beta-User · 16 November 2021, 10:19:47

Hmm, strange...

Hatte es auf Strawberryperl 5.32.1 getestet, und da verhält es sich wie dein Buster (5.28.1). Das komische Verhalten scheint daran zu liegen, dass der Aufruf des "mach jetzt den Check, ob geschaltet werden kann" _zu früh_ erfolgt, delay=-1" ist das Ergebnis von "my $delay = int(time) - $epoch;" wobei $epoch dem Wert entspricht, der für das Setzen des InternalTimer mal verwendet wurde.
Kurz gesagt: eigentlich dürfte es diesen Fall nicht geben...
Ich hatte eben aber auch den Fall, dass der Timer auf (vermutlich) "eine Sekunde zu früh" gesetzt wurde, also (im Profil) "09:22:59 open" für '12345|{sunrise_abs('REAL',+180,"09:23","10:30")}|open', was auch etwas seltsam ist.

Na ja, jedenfalls habe ich jetzt mal noch eine Ausnahme in die Prüfung des Timer-Resets reingeknödelt, von der ich hoffe, dass sie nebenwirkungsfrei ist.

Matze89 · 16 November 2021, 13:17:03

Hallo,
vielen Dank weiterhin für die Mithilfe.

Noch ein paar Daten:
Raspberry mit raspbian Bullseye:

Code Auswählen


apt show perl
Package: perl
Version: 5.32.1-4+deb11u2

apt show fhem
Package: fhem
Version: 6.0.24833
Status: install ok installed

Raspberry mit raspbian Buster:

Code Auswählen


apt show perl
Package: perl
Version: 5.28.1-6

apt show fhem
Package: fhem
Version: 6.1.25205
Status: install ok installed

Also Betriebssysteme sind anders, aber auch Perl und FHEM?

---

Soeben deine geänderte WeekdayTimer eingebaut:

Code Auswählen

File               Rev   Last Change

# $Id: 98_WeekdayTimer.pm 25110 2021-11-16 restructured Beta-User $

doif.js                    24438 2021-05-14 18:08:18Z Ellert
f18.js                     24575 2021-06-03 09:52:42Z rudolfkoenig
fhemweb.js                 25022 2021-09-27 07:11:18Z rudolfkoenig
fhemweb_readingsGroup.js   15189 2017-10-03 17:53:27Z justme1968

Ergebnis:

Code Auswählen


021.11.16 13:10:18.014 4: ROLLO (rollo_sz) updating state to open
2021.11.16 13:10:18.014 4: ROLLO (rollo_sz) drives to end pct and autostop is enabled. No stop command executed
2021.11.16 13:10:18.014 4: ROLLO (rollo_sz) stops from drive-up at pct 0
2021.11.16 13:10:18.013 5: ROLLO (rollo_sz) >> Stop
2021.11.16 13:10:18.006 1: Rollo Schlafzimmer wurde geöffnet.
2021.11.16 13:10:18.000 5: ROLLO (rollo_sz) >> Timer
2021.11.16 13:09:59.035 4: [timer_rollo_sz] command: 'set $NAME $EVENT' executed with %EVENT=>open,%NAME=>rollo_sz
2021.11.16 13:09:59.035 4: ROLLO (rollo_sz) stop in 19 seconds.
2021.11.16 13:09:59.029 3: MQTT2_DEVICE set mqtt_rollo_sz up
2021.11.16 13:09:59.022 4: ROLLO (rollo_sz) execute following commands: set mqtt_rollo_sz up; sleep 10; set RaspBee_SZ off; 
2021.11.16 13:09:59.012 4: ROLLO (rollo_sz) calculateDriveTime: oldpos=0,newpos=0,direction=up,time=18,steps=100,drivetime=19
2021.11.16 13:09:59.012 5: ROLLO (rollo_sz) netto drive time = 18
2021.11.16 13:09:59.012 4: ROLLO (rollo_sz): forceDrive set, driving up
2021.11.16 13:09:59.012 4: ROLLO (rollo_sz) already at position!
2021.11.16 13:09:59.012 5: ROLLO (rollo_sz) >> calculateDriveTime | going up: from 0 to 0
2021.11.16 13:09:59.011 4: ROLLO (rollo_sz) pct: 0 -> 0 / direction: up
2021.11.16 13:09:59.011 4: ROLLO (rollo_sz) drive from 0 to 0. command: open. state: open
2021.11.16 13:09:59.011 5: ROLLO (rollo_sz) >> Start
2021.11.16 13:09:59.005 5: ROLLO (rollo_sz) DesiredPos now 0, open
2021.11.16 13:09:59.005 5: ROLLO (rollo_sz) DesiredPos set to open, () 
2021.11.16 13:09:59.005 5: ROLLO (rollo_sz) >> Set (open,)
2021.11.16 13:09:59.005 4: [timer_rollo_sz] aktParam: newParam:open - is not disabled
2021.11.16 13:09:59.002 5: [timer_rollo_sz] removing Timer: timer_rollo_sz_4
2021.11.16 13:09:59.002 4: [timer_rollo_sz] Update   - timer seems to be active today: 0123456|{sunset_abs('REAL',-1500,"13:09","13:10")}|open
2021.11.16 13:09:59.002 4: [timer_rollo_sz] list of window sensors found: 'timer_rollo_sz'
2021.11.16 13:09:59.001 4: [timer_rollo_sz] time={sunset_abs('REAL',-1500,"13:09","13:10")}/1637064599 delay=-1, nextDelay=60, nextRetry=1637064659

Löst nur einmal aus.

Perfekt!
Aber ist das jetzt nur eine Notlösung? Irgendwo wird da der Fehler sein.

Beta-User · 16 November 2021, 13:41:21

Zitat von: Matze89 am 16 November 2021, 13:17:03
Aber ist das jetzt nur eine Notlösung? Irgendwo wird da der Fehler sein.

Es ist ein Würgaround, weil es einen Fall abfängt, den es eigentlich nicht geben dürfte. Er hat aber einen eher beschränkten Wirkungsbereich, so dass ich - wie schon geschrieben - nicht davon ausgehe, dass das groß Nebenwirkungen hat. Werde es also erst mal selbst testen (mit den paar wenigen WDT, die ich habe), und hoffen, dass hier der eine oder andere mitliest, der auch Mittesten will.

Die neue Version bringt übrigens auch wieder ein etwas anderes Verhalten für CONDITION - die wird nämlich jetzt (wieder?) zur Laufzeit geprüft, der WDT wird nicht mehr für den ganzen Tag deaktiviert. Ich finde dieses Verhalten intuitiver und werde wohl auch noch den einen oder anderen "Perl-oneliner" dahingehend umschreiben.

Zitat
Noch ein paar Daten:
Raspberry mit Buster:
Code Auswählen Erweitern
apt show fhem Package: fhem Version: 6.0.24833 Status: install ok installed

Diese "Sichtweise" ist bezogen auf FHEM irreführend. Was man im Einsatz hat, zeigt "fheminfo" sehr viel besser, der apt-Stand ist mit dem ersten update innerhalb FHEM "kalter Kaffee".

Wenn überhaupt, spielt allenfalls was FHEM-internes und/oder die Perl-Version mit rein.
Da du aber dasselbe Grundverhalten ("-1") auch auf dem System deiner Eltern hattest mit der alten WDT-Fassung, mag ich nicht so recht an ein Perl-Problem glauben, das sieht eher danach aus, als würden "time" und "gettimeofday()" (leicht) unterschiedliche Ergebnisse liefern (letzteres wird in HandleTimeout() in fhem.pl verwendet).
Stochern im Nebel ginge mit (FHEM-Kommandozeile):

Code Auswählen

{gettimeofday() . " " . time}

Vielleicht ersetze ich die "time"-Anweisungen bei Gelegenheit mal durch gettimeofday()...?

Beta-User · 20 November 2021, 07:04:25

Habe hier bisher keine Nebenwirkungen festgestellt, ist daher jetzt eingecheckt...

Matze89 · 20 November 2021, 08:23:41

Korrekt. Danke. Funktioniert bei mir auch einwandfrei.