AT mit Perl Code in der Zeitangabe verusacht doppeltes Logging

[Rampler]

Hallo zusammen,
folgender AT wird ausgeführt:

Code Auswählen Erweitern

*{sunset_abs("REAL",1200)} {if (sunset_abs("REAL",1200) lt "20:30:00") { fhem('set FL.AZ.pm.sw on-till 23:00:00')}};

Dieser führt zu folgenden LOG Einträgen:

Code Auswählen Erweitern


2015.12.15 19:45:36 3: CUL_HM set FL.AZ.pm.sw on-till 23:00:00
2015.12.15 19:45:45 3: CUL_HM set FL.AZ.pm.sw on-till 23:00:00


Laut Log wird der Befehl also zweimal gesendet, lt. Event Monitor sehe ich nur einen Befehl.
Wenn ich stattdessen einen AT mit absoluter Zeitangabe (*19:30 {if...) auf den Weg schicke passt alles, also nur einen LOG-Eintrag.
Bei dem Device  FL.AZ.pm.sw handelt es sich um die Funk Schaltsteckdose von Homematic.
Das muss mit irgendeinem Update gekommen sein, bei älteren LOG's passt noch alles

Gruß Klaus

[betateilchen]

Zwischen den beiden Logeinträgen liegen fast 10 Sekunden Differenz - das muss eine andere Ursache haben.

[Rampler]

Sorry, aber der Fehler ist astrein nachvollziehbar..   
Habe mal in den Log's geblättert, der Fehler tritt ab dem 13.12.2015 auf, nach dem update am 13.12 kommt die Meldung doppelt ...

[Puschel74]

Mit 9 Sekunden Differenz??
Was sagt Apptime und stactrace?
ggf. mal das Log auf verbose 5 drehen.
Also die üblichen Verdächtigen mal einschalten und posten.

[Rampler]

@Puschel74
werde ich machen ..

Habe aber erstmal den AT auf mein Flurlicht gesendet, selbes Ergebniss..
2015.12.15 20:47:16 3: CUL_HM set FL.EG.licht on-till 23:00:00
2015.12.15 20:47:25 3: CUL_HM set FL.EG.licht on-till 23:00:00

Der Befehl kommt definitiv zweimal, da ich auf das Flurlicht eine Sequenze gesetzt habe (FL.EG.licht:on 10 FL.EG.licht:on), welche auch bei dem AT anspringt..

[Rampler]

Ok, beim stacktrace sehe ich nichts.
Beim Verbose 5:

Code Auswählen Erweitern

2015.12.15 21:08:48 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0384784 d:29A083 O:29A083 t:25255A97 IDcnt:002F L:26 %
2015.12.15 21:08:50 5: HMLAN_Send:  HMLAN3 I:K
2015.12.15 21:08:50 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0641421,2CD6E2,29A083,633996DE,0003,03

2015.12.15 21:08:50 5: HMLAN_Parse: HMLAN3 V:03C4 sNo:LEQ0641421 d:2CD6E2 O:29A083 t:633996DE IDcnt:0003 L:3 %
2015.12.15 21:08:55 5: HMLAN/RAW: /E2BBFE8,0000,25257480,FF,FFC0,3686702BBFE800000000385C

2015.12.15 21:08:55 5: HMLAN_Parse: HMLAN1 R:E2BBFE8   stat:0000 t:25257480 d:FF r:FFC0     m:36 8670 2BBFE8 000000 00385C
2015.12.15 21:08:55 5: HMLAN1 dispatch A0C3686702BBFE800000000385C::-64:HMLAN1
2015.12.15 21:08:55 5: HMLAN/RAW: /E2BBFE8,0000,633B6455,FF,FFA2,3686702BBFE800000000385C

2015.12.15 21:08:55 5: HMLAN_Parse: HMLAN2 R:E2BBFE8   stat:0000 t:633B6455 d:FF r:FFA2     m:36 8670 2BBFE8 000000 00385C
2015.12.15 21:08:55 5: HMLAN2 dispatch A0C3686702BBFE800000000385C::-94:HMLAN2
2015.12.15 21:08:55 4: CUL_HM Wetterstation dupe: dont process
2015.12.15 21:08:55 5: HMLAN/RAW: /E2BBFE8,0000,6339A976,FF,FF9C,3686702BBFE800000000385C

2015.12.15 21:08:55 5: HMLAN_Parse: HMLAN3 R:E2BBFE8   stat:0000 t:6339A976 d:FF r:FF9C     m:36 8670 2BBFE8 000000 00385C
2015.12.15 21:08:55 5: HMLAN3 dispatch A0C3686702BBFE800000000385C::-100:HMLAN3
2015.12.15 21:08:55 4: CUL_HM Wetterstation dupe: dont process
2015.12.15 21:08:56 5: exec at command test
2015.12.15 21:08:56 5: Cmd: >{if (sunset_abs("REAL",1200) lt "20:30:00") { fhem('set FL.EG.licht on-till 23:00:00')}}<
2015.12.15 21:08:56 5: Compute sunrise/sunset for latitude 50.0712 , longitude 10.207
2015.12.15 21:08:56 5: Cmd: >set FL.EG.licht on-till 23:00:00<
2015.12.15 21:08:56 5: CUL_HM FL.EG.licht protEvent:CMDs_pending pending:1
2015.12.15 21:08:56 5: Triggering FL.EG.licht (1 changes)
2015.12.15 21:08:56 5: Notify loop for FL.EG.licht set_on-till 23:00:00
2015.12.15 21:08:56 5: Update structure 'Alarm_licht_all' to off because device FL.EG.licht has changed
2015.12.15 21:08:56 3: CUL_HM set FL.EG.licht on-till 23:00:00
2015.12.15 21:08:56 5: HMLAN_Send:  HMLAN1 S:SA7429168 stat:  00 t:00000000 d:01 r:A7429168 m:09 A011 29A083 2DAA03 0201C800008226
2015.12.15 21:08:56 5: CUL_HM FL.EG.licht protEvent:CMDs_processing... pending:0
2015.12.15 21:08:56 5: redefine at command test as *{sunset_abs("REAL",17900)} {if (sunset_abs("REAL",1200) lt "20:30:00") { fhem('set FL.EG.licht on-till 23:00:00')}};
2015.12.15 21:08:56 5: Cmd: >{sunset_abs("REAL",17900)}<
2015.12.15 21:08:56 5: Compute sunrise/sunset for latitude 50.0712 , longitude 10.207
2015.12.15 21:08:56 5: Triggering test (1 changes)
2015.12.15 21:08:56 5: Notify loop for test Next: 21:09:05
2015.12.15 21:08:56 5: HMLAN/RAW: /E29A083,0000,633B6793,FF,FFB0,09A01129A0832DAA030201C800008226

2015.12.15 21:08:56 5: HMLAN_Parse: HMLAN2 R:E29A083   stat:0000 t:633B6793 d:FF r:FFB0     m:09 A011 29A083 2DAA03 0201C800008226
2015.12.15 21:08:56 5: HMLAN2 dispatch A1009A01129A0832DAA030201C800008226::-80:HMLAN2
2015.12.15 21:08:56 5: HMLAN/RAW: /E29A083,0000,6339ACB4,FF,FFB2,09A01129A0832DAA030201C800008226

2015.12.15 21:08:56 5: HMLAN_Parse: HMLAN3 R:E29A083   stat:0000 t:6339ACB4 d:FF r:FFB2     m:09 A011 29A083 2DAA03 0201C800008226
2015.12.15 21:08:56 5: HMLAN3 dispatch A1009A01129A0832DAA030201C800008226::-78:HMLAN3
2015.12.15 21:08:56 4: CUL_HM vccu dupe: dont process
2015.12.15 21:08:56 5: HMLAN/RAW: /RA7429168,0001,2525783F,FF,FFC1,0980022DAA0329A0830101C84040

2015.12.15 21:08:56 5: HMLAN_Parse: HMLAN1 R:RA7429168 stat:0001 t:2525783F d:FF r:FFC1     m:09 8002 2DAA03 29A083 0101C84040
2015.12.15 21:08:56 5: HMLAN1 dispatch A0E0980022DAA0329A0830101C84040::-63:HMLAN1
2015.12.15 21:08:56 5: CUL_HM FL.EG.licht protEvent:CMDs_done
2015.12.15 21:08:56 5: Triggering FL.EG.licht (1 changes)
2015.12.15 21:08:56 5: Notify loop for FL.EG.licht on
2015.12.15 21:08:56 5: Update structure 'Alarm_licht_all' to off because device FL.EG.licht has changed
2015.12.15 21:08:56 5: sequence FL.EG.gong.mp3.muteswitch_doublepress_sequence matched 2
2015.12.15 21:08:56 5: HMLAN/RAW: /E2DAA03,0000,633B680F,FF,FFBC,0980022DAA0329A0830101C84040

2015.12.15 21:08:56 5: HMLAN_Parse: HMLAN2 R:E2DAA03   stat:0000 t:633B680F d:FF r:FFBC     m:09 8002 2DAA03 29A083 0101C84040
2015.12.15 21:08:56 5: HMLAN2 dispatch A0E0980022DAA0329A0830101C84040::-68:HMLAN2
2015.12.15 21:08:56 4: CUL_HM FL.EG.licht dupe: dont process
2015.12.15 21:08:56 5: HMLAN/RAW: /E2DAA03,0000,6339AD2F,FF,FFA1,0980022DAA0329A0830101C84040

2015.12.15 21:08:56 5: HMLAN_Parse: HMLAN3 R:E2DAA03   stat:0000 t:6339AD2F d:FF r:FFA1     m:09 8002 2DAA03 29A083 0101C84040
2015.12.15 21:08:56 5: HMLAN3 dispatch A0E0980022DAA0329A0830101C84040::-95:HMLAN3
2015.12.15 21:08:56 4: CUL_HM FL.EG.licht dupe: dont process
2015.12.15 21:09:02 5: redefine at command SZ.timer as +*00:00:15 set FL.EG.gong.mp3 playTone 1,1
2015.12.15 21:09:02 5: redefine at command BD.timer as +*00:00:15 set FL.EG.gong.mp3 playTone 2,2
2015.12.15 21:09:02 5: redefine at command FL.UG.tk.timer as +*00:00:15 set FL.EG.gong.mp3 playTone 3,3
2015.12.15 21:09:02 5: redefine at command GA.timer as +*00:00:15 set FL.EG.gong.mp3 playTone 4,4
2015.12.15 21:09:05 5: exec at command test
2015.12.15 21:09:05 5: Cmd: >{if (sunset_abs("REAL",1200) lt "20:30:00") { fhem('set FL.EG.licht on-till 23:00:00')}}<
2015.12.15 21:09:05 5: Compute sunrise/sunset for latitude 50.0712 , longitude 10.207
2015.12.15 21:09:05 5: [b]Cmd: >set FL.EG.licht on-till 23:00:00<
[/b]2015.12.15 21:09:05 5: CUL_HM FL.EG.licht protEvent:CMDs_pending pending:1
2015.12.15 21:09:05 5: Triggering FL.EG.licht (1 changes)
2015.12.15 21:09:05 5: Notify loop for FL.EG.licht set_on-till 23:00:00
2015.12.15 21:09:05 5: Update structure 'Alarm_licht_all' to off because device FL.EG.licht has changed
2015.12.15 21:09:05 3: CUL_HM set FL.EG.licht on-till 23:00:00
2015.12.15 21:09:05 5: HMLAN_Send:  HMLAN1 S:SA742B472 stat:  00 t:00000000 d:01 r:A742B472 m:0A A011 29A083 2DAA03 0201C8000081E6
2015.12.15 21:09:05 5: CUL_HM FL.EG.licht protEvent:CMDs_processing... pending:0
2015.12.15 21:09:05 5: redefine at command test as *{sunset_abs("REAL",17900)} {if (sunset_abs("REAL",1200) lt "20:30:00") { fhem('set FL.EG.licht on-till 23:00:00')}};
2015.12.15 21:09:05 5: Cmd: >{sunset_abs("REAL",17900)}<
2015.12.15 21:09:05 5: Compute sunrise/sunset for latitude 50.0712 , longitude 10.207
2015.12.15 21:09:05 5: HMLAN/RAW: /E29A083,0000,633B8A9E,FF,FFAF,0AA01129A0832DAA030201C8000081E6

2015.12.15 21:09:05 5: HMLAN_Parse: HMLAN2 R:E29A083   stat:0000 t:633B8A9E d:FF r:FFAF     m:0A A011 29A083 2DAA03 0201C8000081E6
2015.12.15 21:09:05 5: HMLAN2 dispatch A100AA01129A0832DAA030201C8000081E6::-81:HMLAN2
2015.12.15 21:09:05 5: HMLAN/RAW: /E29A083,0000,6339CFBF,FF,FFB2,0AA01129A0832DAA030201C8000081E6

2015.12.15 21:09:05 5: HMLAN_Parse: HMLAN3 R:E29A083   stat:0000 t:6339CFBF d:FF r:FFB2     m:0A A011 29A083 2DAA03 0201C8000081E6
2015.12.15 21:09:05 5: HMLAN3 dispatch A100AA01129A0832DAA030201C8000081E6::-78:HMLAN3
2015.12.15 21:09:05 4: CUL_HM vccu dupe: dont process
2015.12.15 21:09:05 5: HMLAN/RAW: /RA742B472,0001,25259B4A,FF,FFC0,0A80022DAA0329A0830101C84041

2015.12.15 21:09:05 5: HMLAN_Parse: HMLAN1 R:RA742B472 stat:0001 t:25259B4A d:FF r:FFC0     m:0A 8002 2DAA03 29A083 0101C84041
2015.12.15 21:09:05 5: HMLAN1 dispatch A0E0A80022DAA0329A0830101C84041::-64:HMLAN1
2015.12.15 21:09:05 5: CUL_HM FL.EG.licht protEvent:CMDs_done
2015.12.15 21:09:05 5: Triggering FL.EG.licht (1 changes)
2015.12.15 21:09:05 5: Notify loop for FL.EG.licht on
2015.12.15 21:09:05 5: Update structure 'Alarm_licht_all' to off because device FL.EG.licht has changed
2015.12.15 21:09:05 5: sequence FL.EG.gong.mp3.muteswitch_doublepress_sequence matched 4
2015.12.15 21:09:05 5: sequence FL.EG.gong.mp3.muteswitch_doublepress_sequence trigger
2015.12.15 21:09:05 5: Triggering FL.EG.gong.mp3.muteswitch_doublepress_sequence (1 changes)
2015.12.15 21:09:05 5: Notify loop for FL.EG.gong.mp3.muteswitch_doublepress_sequence trigger
2015.12.15 21:09:05 5: Cmd: >set FL.EG.gong.mp3 playTone 26<
2015.12.15 21:09:05 5: CUL_HM FL.EG.gong protEvent:CMDs_pending pending:1
2015.12.15 21:09:05 5: Triggering FL.EG.gong.mp3 (1 changes)
2015.12.15 21:09:05 5: Notify loop for FL.EG.gong.mp3 set_playTone 26
2015.12.15 21:09:05 5: HMLAN_Send:  HMLAN1 S:SA742B563 stat:  00 t:00000000 d:01 r:A742B563 m:12 A011 29A083 322BFA 8002C8011A
2015.12.15 21:09:05 5: CUL_HM FL.EG.gong protEvent:CMDs_processing... pending:0
2015.12.15 21:09:05 5: Cmd: >set FL.EG.anzeige.led11 led red<
2015.12.15 21:09:05 5: CUL_HM FL.EG.anzeige protEvent:CMDs_pending pending:1
2015.12.15 21:09:05 5: Cmd: >set FL.EG.gong.mp3.muteswitch on<
2015.12.15 21:09:05 4: dummy set FL.EG.gong.mp3.muteswitch on
2015.12.15 21:09:05 5: Triggering FL.EG.gong.mp3.muteswitch (1 changes)
2015.12.15 21:09:05 5: Notify loop for FL.EG.gong.mp3.muteswitch on
2015.12.15 21:09:05 5: HMLAN/RAW: /E2DAA03,0000,633B8B1A,FF,FFBC,0A80022DAA0329A0830101C84041
E29A083,0000,633B8B8D,FF,FFAF,12A01129A083322BFA8002C8011A

2015.12.15 21:09:05 5: HMLAN_Parse: HMLAN2 R:E2DAA03   stat:0000 t:633B8B1A d:FF r:FFBC     m:0A 8002 2DAA03 29A083 0101C84041
2015.12.15 21:09:05 5: HMLAN2 dispatch A0E0A80022DAA0329A0830101C84041::-68:HMLAN2
2015.12.15 21:09:05 4: CUL_HM FL.EG.licht dupe: dont process
2015.12.15 21:09:05 5: HMLAN_Parse: HMLAN2 R:E29A083   stat:0000 t:633B8B8D d:FF r:FFAF     m:12 A011 29A083 322BFA 8002C8011A
2015.12.15 21:09:05 5: HMLAN2 dispatch A0E12A01129A083322BFA8002C8011A::-81:HMLAN2
2015.12.15 21:09:05 5: HMLAN/RAW: /E2DAA03,0000,6339D03A,FF,FF9E,0A80022DAA0329A0830101C84041
E29A083,0000,6339D0AE,FF,FFB1,12A01129A083322BFA8002C8011A

2015.12.15 21:09:05 5: HMLAN_Parse: HMLAN3 R:E2DAA03   stat:0000 t:6339D03A d:FF r:FF9E     m:0A 8002 2DAA03 29A083 0101C84041
2015.12.15 21:09:05 5: HMLAN3 dispatch A0E0A80022DAA0329A0830101C84041::-98:HMLAN3
2015.12.15 21:09:05 4: CUL_HM FL.EG.licht dupe: dont process
2015.12.15 21:09:05 5: HMLAN_Parse: HMLAN3 R:E29A083   stat:0000 t:6339D0AE d:FF r:FFB1     m:12 A011 29A083 322BFA 8002C8011A
2015.12.15 21:09:05 5: HMLAN3 dispatch A0E12A01129A083322BFA8002C8011A::-79:HMLAN3


Aus diesen LOG Auszug ist zumindest ersichtlich, dass das Command doppelt gesendet wird...
Mehr sehe ich aber auch nicht ...

[rudolfkoenig]

Entweder verstehe ich das Problem nicht, oder ihr habt den Unterschied zwischen sunset_abs und sunset nicht verstanden. Entweder, weil der commandref Eintrag unverstaendlich ist, oder weil ihr es nicht gelesen habt.

Koennt ihr mir sagen, welcher der vielen Moeglichkeiten hier zutrifft?

[Rampler]

@Rudolf
Der AT Befehl:

Code Auswählen Erweitern

*{sunset_abs("REAL",17900)} {if (sunset_abs("REAL",1200) lt "20:30:00") { fhem('set FL.EG.licht on-till 23:00:00')}};

wird doppelt im Abstand kleiner 10 Sekunden ausgeführt. Tritt seit dem 13.12 auf...
Im obigen SYSLOG Auszug wird  um 21:08:56 und um 21:09:05 jeweils ein "set FL.EG.licht on-till 23:00:00" ausgegeben, obwohl es laut dem AT Befehl nur einmal erfolgen soll.
Bei Angabe ohne sunset(), also *{21:00} {if....} wird der "set" einmalig pro Tag ausgeführt, so wie es sein soll..
Kann auch jederzeit nachvollzogen werden...
Gruß Klaus
PS: Ich hoffe, wir reden nicht aneinander vorbei ...

[rudolfkoenig]

DAS habe ich gelesen, ich vermute, du hast meine Saetze nicht ganz ernst genommen.
Ich versuchs mal mit vielen Worten, vielleicht werde ich dann ernst genommen:

Die von FHEM berechneten Sonnenuntergaenge erfolgen z.Zt. immer spaeter, wie man das anhand von

fhem> { sunset_abs_dat(time()-86400) }
17:01:31
fhem> { sunset_abs_dat(time()) }
17:01:42

sehen kann. Die Tage werden trotzdem immer kuerzer, aber das ist eine andere Baustelle.

at berechnet die naechste Ausfuehrungszeit nachdem die Aktuelle ausgefuehrt wurde. Wenn diese Zeit kleiner gleich die aktuelle Uhrzeit ist, dann wird die Ausfuehrungszeit auf morgen verschoben. D.h. du kriegst heute eine Ausfuehrung um 17:01:31 (gestern eingeplant), eins um 17:01:42, und eins morgen um 17:01:42.

Da dieses Problem seit 10 Jahren bekannt ist, gibt es seitdem ein sunset()/sunset_rel()/sunset_abs(). Im commandref wird mAn klar gesagt, dass mit at sunset zu verwenden ist:

sunrise()/sunset() returns the absolute time of the next sunrise/sunset, adding 24 hours if the next event is tomorrow, to use it in the timespec of an at device or for the on-till command for FS20 devices.

[Rampler]

Jetzt habe ich es auch schon kapiert 
Danke für Deine Geduld... und Deine ausführliche Erklärung ...
Gruß Klaus

[Rampler]

Hallo zusammen,
möchte meiner Begeisterung für den FHEM Support hier nochmal zum Ausdruck bringen...
DANKE !!

Gruß Klaus