Ephemeris ToD: Troubleshooting

james_2_roberts · September 3, 2020, 7:02pm

Platform information:
- Hardware: RPi 3
- OS: Raspbian GNU/Linux 8 (jessie)
- JRE: OpenJDK Runtime Environment (Zulu 8.31.1.122-linux_aarch32hf) (build 1.8.0_181-b122)
- OH: 2.5.6 (Build)

I’ve configured the ephemeris according to the details on github. The script runs without any errors, configures the timers, and sets the ToD to the correct ToD, but the timers to triggers the state changes don’t happen.

Items:

DateTime Default_Dawn       { channel="astro:sun:local:civilDawn#start", etod="DAWN"[type="default"] }
DateTime Default_Morning    { init="06:30:00", etod="MORNING"[type="default"] } 
DateTime Default_Day        { channel="astro:sun:local:rise#end", etod="DAY"[type="default"] }
DateTime Default_Dusk       { channel="astro:sun:local:civilDusk#start", etod="DUSK"[type="default"] }
DateTime Default_Evening    { channel="astro:sun:local:set#start", etod="EVENING"[type="default"] }
DateTime Default_Night      { init="22:10:00", etod="NIGHT"[type="default"] }

DateTime Weekend_Morning    { init="07:30:00", etod="MORNING"[type="weekend"] }
DateTime Weekend_Day        { channel="astro:sun:set120:set#start", etod="DAY"[type="weekend"] }
DateTime Weekend_Night      { init="22:45:00", etod="NIGHT"[type="weekend"] }

openhab.log:

2020-09-03 06:09:43.050 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day

2020-09-03 06:11:16.062 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 6 time periods today.

2020-09-03 06:11:16.172 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-03T06:30:00.000+01:00

2020-09-03 06:11:16.265 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-03T22:10:00.000+01:00

2020-09-03 06:11:16.368 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-03T18:40:00.000+01:00

2020-09-03 06:11:16.462 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-03T08:00:00.000+01:00

2020-09-03 06:11:16.557 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - NOW:    DAWN start time 2020-09-03T05:37:00.000+01:00 is in the past but after 2020-09-02T06:11:16.075+01:00

2020-09-03 06:11:16.712 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-03T19:37:00.000+01:00

2020-09-03 06:11:16.742 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 1 timers.

2020-09-03 06:11:16.777 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is DAWN

2020-09-03 06:11:16.839 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-04T00:02:00.000+01:00

console @ 20:00 in the evening:

openhab> smarthome:items list | grep -i timeof
TimeOfDay (Type=StringItem, State=DAWN, Label=null, Category=null)
openhab>

Cheers
James

rlkoshak · September 3, 2020, 10:22pm

Are those the only log from the rule for the whole day?

There are no log statements indicating a transition and/or no errors or warnings around the transition times?

The only thing that stands out there is that it only created one Timer when I would have expected five. The line immediately after those that start with FUTURE is scheduling the timer. Unfortunately I can’t know which one it created.

Change the log level for the “Ephemeris Time of Day” logger to debug which will generate a lot more information about what the Rule does when it runs.

When did you download and install the library? If it was two weeks ago or more, there have been some updates since then. Maybe you need to update.

james_2_roberts · September 4, 2020, 5:39am

Thanks @rlkoshak, updating the openhab-rules-tools has done the trick:

2020-09-04 06:02:21.905 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Deleting rule 3f111a67-42b2-474c-820f-4e74b635f67a

2020-09-04 06:02:22.059 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Deleting rule f2c3dd6d-ddd9-4721-9282-8d236d6f4b5a

2020-09-04 06:02:39.862 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Successfully created rule Reload Ephemeris Time of Day

2020-09-04 06:02:39.891 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating Ephemeris Time of Day rule...

2020-09-04 06:02:58.115 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Successfully created rule Ephemeris Time of Day

2020-09-04 06:02:58.142 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day

2020-09-04 06:04:23.236 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 6 time periods today.

2020-09-04 06:04:23.328 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-04T06:30:00.000+01:00

2020-09-04 06:04:23.423 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-04T22:10:00.000+01:00

2020-09-04 06:04:23.518 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-04T18:38:00.000+01:00

2020-09-04 06:04:23.613 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-04T08:00:00.000+01:00

2020-09-04 06:04:23.720 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - NOW:    DAWN start time 2020-09-04T05:39:00.000+01:00 is in the past but after 2020-09-03T06:04:23.240+01:00

2020-09-04 06:04:23.914 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-04T19:34:00.000+01:00

2020-09-04 06:04:23.948 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 5 timers.

2020-09-04 06:04:23.979 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is DAWN

2020-09-04 06:04:24.050 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-05T00:02:00.000+01:00

2020-09-04 06:30:00.217 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Transitioning Time of Day from DAWN to MORNING

Out of interest, how do I change the log level of a specific module? The relevant log levels I have are:

openhab> log:get
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
jsr223                                             │ DEBUG
jsr223.jython.core                                 │ DEBUG
org.openhab.core.automation                        │ INFO

Cheers
James

rlkoshak · September 4, 2020, 2:13pm

The logging config is in /var/lib/openhab2/etc/org.ops4j.pax.logging.cfg. The zwave and zigbee bindings have good instructions for how to configure that. The “name” of the logger will be “Ephemeris Time of Day” which, now that I look at it might be a problem. I don’t know of the config allows spaces. I’ll have to test it out and figure out if that is a problem. Regardless I should probably change it to ephem_tod anyway. There are additional instructions in the main docs at Logging | openHAB

You can also do it through the karaf console Logging | openHAB

james_2_roberts · September 10, 2020, 4:18am

Thanks @rlkoshak,

I’ll take a look at defining a separate file for this as it’s still giving me a few issues, looking at the last couple of days, TimeOfDay hasn’t changed as expected. The reload timer kicks off as expected, but it runs a few times, sets ToD to Day, but then never executes the remaining timers.

2020-09-09 00:00:31.176 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-09 00:02:08.257 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 6 time periods today.
2020-09-09 00:02:08.291 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - Item Default_Morning is yesterday, updating to today
2020-09-09 00:02:08.393 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-09T06:30:00.000+01:00
2020-09-09 00:02:08.427 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - Item Default_Night is yesterday, updating to today
2020-09-09 00:02:08.524 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-09T22:10:00.000+01:00
2020-09-09 00:02:08.626 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-09T18:26:00.000+01:00
2020-09-09 00:02:08.724 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-09T08:00:00.000+01:00
2020-09-09 00:02:08.833 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-09T05:47:00.000+01:00
2020-09-09 00:02:08.931 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-09T19:23:00.000+01:00
2020-09-09 00:02:08.970 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 6 timers.
2020-09-09 00:02:09.064 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is DAY
2020-09-09 00:02:09.134 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-10T00:02:00.000+01:00
2020-09-09 00:02:09.162 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-09 00:03:45.228 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 6 time periods today.
2020-09-09 00:03:45.343 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-09T06:30:00.000+01:00
2020-09-09 00:03:45.439 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-09T22:10:00.000+01:00
2020-09-09 00:03:45.536 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-09T18:26:00.000+01:00
2020-09-09 00:03:45.632 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-09T08:00:00.000+01:00
2020-09-09 00:03:45.728 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-09T05:47:00.000+01:00
2020-09-09 00:03:45.825 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-09T19:23:00.000+01:00
2020-09-09 00:03:45.853 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 1 timers.
2020-09-09 00:03:45.880 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is DAY
2020-09-09 00:03:45.948 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-10T00:02:00.000+01:00
2020-09-09 00:03:45.972 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-09 00:05:23.570 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 6 time periods today.
2020-09-09 00:05:23.734 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-09T06:30:00.000+01:00
2020-09-09 00:05:23.863 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-09T22:10:00.000+01:00
2020-09-09 00:05:23.979 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-09T18:26:00.000+01:00
2020-09-09 00:05:24.098 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-09T08:00:00.000+01:00
2020-09-09 00:05:24.217 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-09T05:47:00.000+01:00
2020-09-09 00:05:24.326 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-09T19:23:00.000+01:00
2020-09-09 00:05:24.360 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 6 timers.
2020-09-09 00:05:24.391 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is DAY
2020-09-09 00:05:24.468 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-10T00:02:00.000+01:00
2020-09-09 00:05:24.497 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-09 00:07:03.340 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 6 time periods today.
2020-09-09 00:07:03.458 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-09T06:30:00.000+01:00
2020-09-09 00:07:03.570 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-09T22:10:00.000+01:00
2020-09-09 00:07:03.674 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-09T18:26:00.000+01:00
2020-09-09 00:07:03.788 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-09T08:00:00.000+01:00
2020-09-09 00:07:03.902 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-09T05:47:00.000+01:00
2020-09-09 00:07:04.009 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-09T19:23:00.000+01:00
2020-09-09 00:07:04.039 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 1 timers.
2020-09-09 00:07:04.072 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is DAY
2020-09-09 00:07:04.144 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-10T00:02:00.000+01:00
2020-09-09 00:07:04.169 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-09 00:08:44.851 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 6 time periods today.
2020-09-09 00:08:44.954 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-09T06:30:00.000+01:00
2020-09-09 00:08:45.059 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-09T22:10:00.000+01:00
2020-09-09 00:08:45.173 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-09T18:26:00.000+01:00
2020-09-09 00:08:45.275 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-09T08:00:00.000+01:00
2020-09-09 00:08:45.377 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-09T05:47:00.000+01:00
2020-09-09 00:08:45.479 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-09T19:23:00.000+01:00
2020-09-09 00:08:45.510 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 6 timers.
2020-09-09 00:08:45.539 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is DAY
2020-09-09 00:08:45.623 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-10T00:02:00.000+01:00
2020-09-09 00:08:45.656 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-09 00:10:25.566 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 6 time periods today.
2020-09-09 00:10:25.697 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-09T06:30:00.000+01:00
2020-09-09 00:10:25.818 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-09T22:10:00.000+01:00
2020-09-09 00:10:25.937 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-09T18:26:00.000+01:00
2020-09-09 00:10:26.055 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-09T08:00:00.000+01:00
2020-09-09 00:10:26.171 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-09T05:47:00.000+01:00
2020-09-09 00:10:26.291 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-09T19:23:00.000+01:00
2020-09-09 00:10:26.335 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 1 timers.
2020-09-09 00:10:26.369 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is DAY
2020-09-09 00:10:26.446 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-10T00:02:00.000+01:00

James

rlkoshak · September 10, 2020, 2:15pm

The first thing I see odd is at two minutes after midnight it decides that the current time of day is DAY. It should be NIGHT. There appears to be an edge case here when the time carries over from one day to the next.

For the short term you can work around that problem by adding a time period that starts a little after 00:02:00. That should help with that some. Though not totally. I would have expected it to switch over to MORNING, not DAY so I need to look at the code very closely. But this does indicate a bug, just not the one you are reporting.

Even though it sets the time of day to DAY it still creates the timers for all the other times of day and there is no reason why those would not be going off at the right times. Looking further I see that the rule ran multiple times, which is expected as it will run each time Astro updates the Items and the Time of Day Rule itself changes the time Items. And it looks like that works just fine until the very last time it runs in which case it only creates one timer instead of the six it’s supposed to, and managed to do so the previous times it ran through the rule.

I’d be very interested to see if you see the same behavior if you have a time of day that starts at say 00:05:00. If not that might be a clue as to what is going on.

james_2_roberts · September 10, 2020, 7:19pm

Thanks Rich,

I’ve added a time of day starting at 00:05:00 as suggested:
DateTime Default_Late { init="00:05:00", etod="LATE"[type="default"] }

I’ll check and post the logs in the morning.

Cheers
James

james_2_roberts · September 11, 2020, 8:07pm

Interestingly, it seems to be working today, seems to run multiple times, picking up setting to DAY first time around:

2020-09-11 00:00:30.488 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-11 00:01:59.749 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 7 time periods today.
2020-09-11 00:01:59.772 [WARN ] [jsr223.jython.Ephemeris Time of Day ] - The following Items are are NULL/UNDEF, kicking off initialization using item_init: [u'Default_Late']
2020-09-11 00:02:04.818 [ERROR] [jsr223.jython.Ephemeris Time of Day ] - The following Items are still NULL/UNDEF, cannot create Time of Day timers: [u'Default_Late']
2020-09-11 00:02:04.859 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-11 00:03:38.155 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 7 time periods today.
2020-09-11 00:03:38.192 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - Item Default_Morning is yesterday, updating to today
2020-09-11 00:03:38.306 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-11T06:30:00.000+01:00
2020-09-11 00:03:38.351 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - Item Default_Night is yesterday, updating to today
2020-09-11 00:03:38.452 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-11T22:10:00.000+01:00
2020-09-11 00:03:38.490 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - Item Default_Late is yesterday, updating to today
2020-09-11 00:03:38.603 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: LATE Scheduleing Timer for 2020-09-11T00:05:00.000+01:00
2020-09-11 00:03:38.700 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-11T18:21:00.000+01:00
2020-09-11 00:03:38.804 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-11T08:00:00.000+01:00
2020-09-11 00:03:38.900 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-11T05:51:00.000+01:00
2020-09-11 00:03:38.998 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-11T19:18:00.000+01:00
2020-09-11 00:03:39.031 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 7 timers.
2020-09-11 00:03:39.063 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is DAY
2020-09-11 00:03:39.146 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-12T00:02:00.000+01:00
2020-09-11 00:03:39.172 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-11 00:05:03.201 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Transitioning Time of Day from DAY to LATE
2020-09-11 00:05:12.768 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 7 time periods today.
2020-09-11 00:05:12.880 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-11T06:30:00.000+01:00
2020-09-11 00:05:12.984 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-11T22:10:00.000+01:00
2020-09-11 00:05:13.082 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - NOW:    LATE start time 2020-09-11T00:05:00.000+01:00 is in the past but after 2020-09-10T00:05:12.779+01:00
2020-09-11 00:05:13.255 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-11T18:21:00.000+01:00
2020-09-11 00:05:13.354 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-11T08:00:00.000+01:00
2020-09-11 00:05:13.458 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-11T05:51:00.000+01:00
2020-09-11 00:05:13.558 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-11T19:18:00.000+01:00
2020-09-11 00:05:13.589 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 1 timers.
2020-09-11 00:05:13.621 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is LATE
2020-09-11 00:05:13.704 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-12T00:02:00.000+01:00
2020-09-11 00:05:13.731 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-11 00:06:46.745 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 7 time periods today.
2020-09-11 00:06:46.850 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-11T06:30:00.000+01:00
2020-09-11 00:06:47.012 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-11T22:10:00.000+01:00
2020-09-11 00:06:47.120 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - NOW:    LATE start time 2020-09-11T00:05:00.000+01:00 is in the past but after 2020-09-10T00:06:46.750+01:00
2020-09-11 00:06:47.287 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-11T18:21:00.000+01:00
2020-09-11 00:06:47.391 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-11T08:00:00.000+01:00
2020-09-11 00:06:47.495 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-11T05:51:00.000+01:00
2020-09-11 00:06:47.614 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-11T19:18:00.000+01:00
2020-09-11 00:06:47.651 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 6 timers.
2020-09-11 00:06:47.682 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is LATE
2020-09-11 00:06:47.757 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-12T00:02:00.000+01:00
2020-09-11 00:06:47.788 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-11 00:08:20.624 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 7 time periods today.
2020-09-11 00:08:20.802 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-11T06:30:00.000+01:00
2020-09-11 00:08:20.983 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-11T22:10:00.000+01:00
2020-09-11 00:08:21.108 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - NOW:    LATE start time 2020-09-11T00:05:00.000+01:00 is in the past but after 2020-09-10T00:08:20.641+01:00
2020-09-11 00:08:21.276 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-11T18:21:00.000+01:00
2020-09-11 00:08:21.391 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-11T08:00:00.000+01:00
2020-09-11 00:08:21.499 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-11T05:51:00.000+01:00
2020-09-11 00:08:21.600 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-11T19:18:00.000+01:00
2020-09-11 00:08:21.631 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 1 timers.
2020-09-11 00:08:21.662 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is LATE
2020-09-11 00:08:21.740 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-12T00:02:00.000+01:00
2020-09-11 00:08:21.767 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Recalculating time of day
2020-09-11 00:09:53.997 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Today is a default day, there are 7 time periods today.
2020-09-11 00:09:54.093 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: MORNING Scheduleing Timer for 2020-09-11T06:30:00.000+01:00
2020-09-11 00:09:54.192 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: NIGHT Scheduleing Timer for 2020-09-11T22:10:00.000+01:00
2020-09-11 00:09:54.290 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - NOW:    LATE start time 2020-09-11T00:05:00.000+01:00 is in the past but after 2020-09-10T00:09:54.001+01:00
2020-09-11 00:09:54.470 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DUSK Scheduleing Timer for 2020-09-11T18:21:00.000+01:00
2020-09-11 00:09:54.577 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAY Scheduleing Timer for 2020-09-11T08:00:00.000+01:00
2020-09-11 00:09:54.686 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: DAWN Scheduleing Timer for 2020-09-11T05:51:00.000+01:00
2020-09-11 00:09:54.795 [DEBUG] [jsr223.jython.Ephemeris Time of Day ] - FUTURE: EVENING Scheduleing Timer for 2020-09-11T19:18:00.000+01:00
2020-09-11 00:09:54.837 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Created 6 timers.
2020-09-11 00:09:54.868 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - The current time of day is LATE
2020-09-11 00:09:54.956 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Creating reload timer for 2020-09-12T00:02:00.000+01:00
2020-09-11 05:51:00.269 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Transitioning Time of Day from LATE to DAWN
2020-09-11 06:30:00.146 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Transitioning Time of Day from DAWN to MORNING
2020-09-11 08:00:00.151 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Transitioning Time of Day from MORNING to DAY
2020-09-11 18:21:00.258 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Transitioning Time of Day from DAY to DUSK
2020-09-11 19:18:00.187 [INFO ] [jsr223.jython.Ephemeris Time of Day ] - Transitioning Time of Day from DUSK to EVENING

rlkoshak · September 14, 2020, 3:31pm

It shouldn’t use DAY the first time around. That is probably a separate bug. I’ve created an issue on github and will try to figure out what is going wrong as soon as I have a free moment.

There appears to be two bugs here.

Why is it calculating the current time of day as DAY?
At midnight(ish) when the rule runs again, it should use the current time of day as the default. I think what’s happening is it changes the times’ dates to today and then it calculates the current time of day. When it does that, it advances the time for the current period (NIGHT) to the current day making it no longer in the past. Consequently it misses that the current time of day is still NIGHT.

I think I have an approach to 2. I’ve no idea about 1. It gets corrected after the first run of the Rule and unfortunately the rule ends up running multiple times around midnight as Astro updates the Items and the rule itself updates the items to the current day. I have it on my list of todos to figure out how to avoid the multiple executions and still reschedule the Timers when the user/binding changes the state of one of the Items.

Keeping that LATE Item should serve as a workaround for now. I’ll come back here and post when I have made the changes to fix the problem. Hopefully in the next day or so.