search

jensrossbach / node-red-contrib-chronos

Time-based Node-RED scheduling, repeating, queueing, routing, filtering and manipulating nodes
https://jensrossbach.github.io/node-red-contrib-chronos
MIT License
28 stars 1 forks source link

scheduler node do not consistently apply offset #77

Closed JanickGers85 closed 2 years ago

JanickGers85 commented 2 years ago

Describe the bug scheduler node do not consistently apply offset (Sunset (end) schedule)

To reproduce Steps to reproduce the behavior:

  1. Add a scheduler node
  2. Set an offset (tried only positive)
  3. Deploy node
  4. Offset is considered only a first run of the schedule; the next run are executed with an offset of 0.

Expected behavior Offset correctly used.

Screenshots The schedule image Next execution without offset (thrust me, it's true 😆) image

Context information Please complete the following information.

jensrossbach commented 2 years ago

Hi, I tried it on my side but I cannot reproduce it. I used a fixed time instead of a sun time to better compare the values because sun times change from one day to the next. I also reviewed the code and couldn't find any problem there. Please also try with a fixed time and if you can reproduce, send me the logs on "trace" level. Thanks!

JanickGers85 commented 2 years ago

@jensrossbach With fixed time it works correctly

chrome_2022-01-19_20-30-48

19 Jan 20:29:50 - [trace] [flow:a7f95c7992bacc92] ------------------|--------------|-----------------
19 Jan 20:29:50 - [trace] [flow:f2a13030edb1c6f5] start flow [f2a13030edb1c6f5]
19 Jan 20:29:50 - [debug] [chronos-scheduler:92c48233a95f1e8a] Starting node with configuration 'Casa' (latitude ***, longitude ***)
19 Jan 20:29:50 - [debug] [chronos-scheduler:92c48233a95f1e8a] Starting timers
19 Jan 20:29:50 - [debug] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Set up timer
19 Jan 20:29:50 - [trace] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Timer specification: {"trigger":{"type":"time","value":"20:31","offset":0,"random":false},"output":{"type":"msg","property":{"name":"payload","type":"str","value":"Hello world!"}}}
19 Jan 20:29:50 - [debug] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Starting timer for trigger at 2022-01-19 20:31:00
19 Jan 20:29:50 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:29:50 - [trace] [flow:f2a13030edb1c6f5]  id               | type         | alias
19 Jan 20:29:50 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:29:50 - [trace] [flow:f2a13030edb1c6f5]  92c48233a95f1e8a | chronos-scheduler |
19 Jan 20:29:50 - [trace] [flow:f2a13030edb1c6f5]  b354df5c80f0c724 | debug        |
19 Jan 20:29:50 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:29:50 - [trace] runtime event: {"id":"runtime-state","retain":true}
19 Jan 20:29:50 - [info] Started modified nodes
19 Jan 20:29:50 - [trace] runtime event: {"id":"runtime-deploy","payload":{"revision":"b04641781f7fdc19635066051d5e3869"},"retain":true}
19 Jan 20:29:54 - [debug] Flushing localfilesystem context scope global
19 Jan 20:30:24 - [debug] Flushing localfilesystem context scope global
19 Jan 20:30:56 - [debug] Flushing localfilesystem context scope global
19 Jan 20:31:00 - [debug] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Timer expired
19 Jan 20:31:00 - [debug] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Set up timer (repeating)
19 Jan 20:31:00 - [trace] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Timer specification: {"trigger":{"type":"time","value":"20:31","offset":0,"random":false},"output":{"type":"msg","property":{"name":"payload","type":"str","value":"Hello world!"}}}
19 Jan 20:31:00 - [debug] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Starting timer for trigger at 2022-01-20 20:31:00

Then added offset of 4 minutes

chrome_2022-01-19_20-35-18

19 Jan 20:33:47 - [trace] [flow:a7f95c7992bacc92] ------------------|--------------|-----------------
19 Jan 20:33:47 - [trace] [flow:f2a13030edb1c6f5] start flow [f2a13030edb1c6f5]
19 Jan 20:33:47 - [debug] [chronos-scheduler:92c48233a95f1e8a] Starting node with configuration 'Casa' (latitude ***, longitude ***)
19 Jan 20:33:47 - [debug] [chronos-scheduler:92c48233a95f1e8a] Starting timers
19 Jan 20:33:47 - [debug] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Set up timer
19 Jan 20:33:47 - [trace] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Timer specification: {"trigger":{"type":"time","value":"20:31","offset":4,"random":false},"output":{"type":"msg","property":{"name":"payload","type":"str","value":"Hello world!"}}}
19 Jan 20:33:47 - [debug] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Starting timer for trigger at 2022-01-19 20:35:00
19 Jan 20:33:47 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:33:47 - [trace] [flow:f2a13030edb1c6f5]  id               | type         | alias
19 Jan 20:33:47 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:33:47 - [trace] [flow:f2a13030edb1c6f5]  b354df5c80f0c724 | debug        |
19 Jan 20:33:47 - [trace] [flow:f2a13030edb1c6f5]  92c48233a95f1e8a | chronos-scheduler |
19 Jan 20:33:47 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:33:47 - [trace] runtime event: {"id":"runtime-state","retain":true}
19 Jan 20:33:47 - [info] Started modified nodes
19 Jan 20:33:47 - [trace] runtime event: {"id":"runtime-deploy","payload":{"revision":"8c394eaac948d2e60b5f4ac55d5aaf40"},"retain":true}
19 Jan 20:33:59 - [debug] Flushing localfilesystem context scope global
19 Jan 20:34:29 - [debug] Flushing localfilesystem context scope global
19 Jan 20:34:59 - [debug] Flushing localfilesystem context scope global
19 Jan 20:35:00 - [debug] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Timer expired
19 Jan 20:35:00 - [debug] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Set up timer (repeating)
19 Jan 20:35:00 - [trace] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Timer specification: {"trigger":{"type":"time","value":"20:31","offset":4,"random":false},"output":{"type":"msg","property":{"name":"payload","type":"str","value":"Hello world!"}}}
19 Jan 20:35:00 - [debug] [chronos-scheduler:92c48233a95f1e8a] [Timer:1] Starting timer for trigger at 2022-01-20 20:35:00

But with sun events it's still problematic, here a GIF

chrome_2022-01-19_20-48-04

and here the logs; in bold the "offset":15 which is not considered in time calculation and trigger time is 2022-01-20 17:07:50 as before.

19 Jan 20:47:06 - [trace] [flow:a7f95c7992bacc92] ------------------|--------------|-----------------
19 Jan 20:47:06 - [trace] [flow:f2a13030edb1c6f5] start flow [f2a13030edb1c6f5]
19 Jan 20:47:06 - [debug] [chronos-scheduler:d0907f940cedf596] Starting node with configuration 'Casa' (latitude ***, longitude ***)
19 Jan 20:47:06 - [debug] [chronos-scheduler:d0907f940cedf596] Starting timers
19 Jan 20:47:06 - [debug] [chronos-scheduler:d0907f940cedf596] [Timer:1] Set up timer
19 Jan 20:47:06 - [trace] [chronos-scheduler:d0907f940cedf596] [Timer:1] Timer specification: {"trigger":{"type":"sun","value":"sunset","offset":0,"random":false},"output":{"type":"msg","property":{"name":"payload","type":"str","value":"Hello world!"}}}
19 Jan 20:47:06 - [debug] [chronos-scheduler:d0907f940cedf596] [Timer:1] Trigger time before current time, adding one day
19 Jan 20:47:06 - [debug] [chronos-scheduler:d0907f940cedf596] [Timer:1] Starting timer for trigger at 2022-01-20 17:07:50
19 Jan 20:47:06 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:47:06 - [trace] [flow:f2a13030edb1c6f5]  id               | type         | alias
19 Jan 20:47:06 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:47:06 - [trace] [flow:f2a13030edb1c6f5]  d0907f940cedf596 | chronos-scheduler |
19 Jan 20:47:06 - [trace] [flow:f2a13030edb1c6f5]  b9f48151b8d9d993 | debug        |
19 Jan 20:47:06 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:47:06 - [trace] runtime event: {"id":"runtime-state","retain":true}
19 Jan 20:47:06 - [info] Started modified nodes
19 Jan 20:47:06 - [trace] runtime event: {"id":"runtime-deploy","payload":{"revision":"73027f074400d53419d7139cbba151ef"},"retain":true}
...
19 Jan 20:48:01 - [trace] [flow:a7f95c7992bacc92] ------------------|--------------|-----------------
19 Jan 20:48:01 - [trace] [flow:f2a13030edb1c6f5] start flow [f2a13030edb1c6f5]
19 Jan 20:48:01 - [debug] [chronos-scheduler:d0907f940cedf596] Starting node with configuration 'Casa' (latitude ***, longitude ***)
19 Jan 20:48:01 - [debug] [chronos-scheduler:d0907f940cedf596] Starting timers
19 Jan 20:48:01 - [debug] [chronos-scheduler:d0907f940cedf596] [Timer:1] Set up timer
19 Jan 20:48:01 - [trace] [chronos-scheduler:d0907f940cedf596] [Timer:1] Timer specification: {"trigger":{"type":"sun","value":"sunset","offset":15,"random":false},"output":{"type":"msg","property":{"name":"payload","type":"str","value":"Hello world!"}}}
19 Jan 20:48:01 - [debug] [chronos-scheduler:d0907f940cedf596] [Timer:1] Trigger time before current time, adding one day
19 Jan 20:48:01 - [debug] [chronos-scheduler:d0907f940cedf596] [Timer:1] Starting timer for trigger at 2022-01-20 17:07:50
19 Jan 20:48:01 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:48:01 - [trace] [flow:f2a13030edb1c6f5]  id               | type         | alias
19 Jan 20:48:01 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:48:01 - [trace] [flow:f2a13030edb1c6f5]  b9f48151b8d9d993 | debug        |
19 Jan 20:48:01 - [trace] [flow:f2a13030edb1c6f5]  d0907f940cedf596 | chronos-scheduler |
19 Jan 20:48:01 - [trace] [flow:f2a13030edb1c6f5] ------------------|--------------|-----------------
19 Jan 20:48:01 - [trace] runtime event: {"id":"runtime-state","retain":true}
19 Jan 20:48:01 - [info] Started modified nodes
19 Jan 20:48:01 - [trace] runtime event: {"id":"runtime-deploy","payload":{"revision":"ea5917f6d73c596b1a7a82832a2740cd"},"retain":true}
jensrossbach commented 2 years ago

ok, now I got your usecase and I was able to reproduce the problem. The problem only occurs after flow deployment (or any other re-scheduling occurance) when the calculated sun time has already been passed and the scheduled time is shifted to the next day.

The fix will come in the next release.

jensrossbach commented 2 years ago

Fixed in release v1.17.0.