Yes. Channels only exist as a part of a Thing. They do not exist on their own.
On 2.4 Stable I’m having the same always ‘afternoon’ issue.
Before on M8 it was okay, even after restart/midnight.
Now it seems that after midnight this problem is still there…
Since this is still not really fixed for you a few questions:
- You are calling it “afternoon” issue. It would be good to go through the rule logic and logs to see whether this is caused by astro things not updating (or whether there is something else going on). If it is only because of astro things not updating it is rather a scheduling issue for astro things than an afternoon issue.
- You are writing that this occurred not only after midnight but you also get afternoon directly after restart at some times. Again, in case this is only related to an issue with astro scheduling that would mean that there are also schedules missed directly after restart - you should be able to see that in the logs as well.
- Last thing: When the “afternoon” issue is really only about astro scheduling then it is a first good finding. Then it might be interesting why you are experiencing these problems. What is special about your setup - hardware, installation, rules, etc. However this might then be better discussed in the related issue for scheduling.
I’m still having the same problem with this set of rules (using the example at the beginning of the thread). I’ve upgraded to the latest release and it seems that the Val are all populating correctly but the start triggers do not always seem to fire. For example yesterday the variable all updated but the DAY and EVENING starts did not update correctly.
2019-01-10 00:00:29.884 [vent.ItemStateChangedEvent] - vEvening_Time changed from 2019-01-09T17:10:00.000+0100 to 2019-01-10T17:11:00.000+0100
2019-01-10 00:00:29.924 [vent.ChannelTriggeredEvent] - astro:sun:minus90:morningNight#event triggered START
2019-01-10 00:00:29.951 [vent.ItemStateChangedEvent] - MoonDistance changed from 405847.64242036606 km to 405847.6061119282 km
2019-01-10 00:00:29.981 [vent.ItemStateChangedEvent] - Sunrise_Time changed from 2019-01-10T08:06:00.000+0100 to 2019-01-10T09:13:00.000+0100
2019-01-10 00:00:29.985 [vent.ItemStateChangedEvent] - Sunset_Time changed from 2019-01-10T17:11:00.000+0100 to 2019-01-10T17:09:00.000+0100
2019-01-10 00:00:29.988 [vent.ItemStateChangedEvent] - LocalSun_Position_Azimuth changed from 326.987334665386 to 328.5859313352662
2019-01-10 00:00:29.990 [vent.ItemStateChangedEvent] - LocalSun_Position_Elevation changed from -56.400929156650065 to -56.731067768795384
2019-01-10 00:00:30.001 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered START
2019-01-10 00:00:30.035 [vent.ItemStateChangedEvent] - Sunrise_Time changed from 2019-01-10T09:13:00.000+0100 to 2019-01-10T08:06:00.000+0100
2019-01-10 00:00:30.036 [vent.ChannelTriggeredEvent] - astro:sun:home:morningNight#event triggered START
2019-01-10 00:00:30.037 [vent.ItemStateChangedEvent] - Sunset_Time changed from 2019-01-10T17:09:00.000+0100 to 2019-01-10T17:11:00.000+0100
2019-01-10 00:01:00.243 [vent.ItemStateChangedEvent] - vMorning_Time changed from 2019-01-09T06:00:00.000+0100 to 2019-01-10T06:00:00.000+0100
2019-01-10 00:01:00.245 [vent.ItemStateChangedEvent] - vNight_Time changed from 2019-01-09T23:00:00.000+0100 to 2019-01-10T23:00:00.000+0100
2019-01-10 00:01:00.247 [vent.ItemStateChangedEvent] - vBed_Time changed from 2019-01-09T00:00:00.000+0100 to 2019-01-10T00:00:00.000+0100
2019-01-10 00:01:00.259 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command BED
2019-01-10 00:01:00.261 [vent.ItemStateChangedEvent] - vTimeOfDay changed from NIGHT to BED
Then at 06:00 as expected it converts to Morning
2019-01-10 06:00:00.066 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command MORNING
2019-01-10 06:00:00.067 [vent.ItemStateChangedEvent] - vTimeOfDay changed from BED to MORNING
But after this is does not seem to trigger Day until much later than expected at 17:10
2019-01-10 08:05:59.939 [vent.ChannelTriggeredEvent] - astro:sun:minus90:civilDawn#event triggered END
2019-01-10 08:05:59.939 [vent.ChannelTriggeredEvent] - astro:sun:minus90:rise#event triggered START
2019-01-10 08:05:59.939 [vent.ChannelTriggeredEvent] - astro:sun:home:rise#event triggered START
2019-01-10 08:05:59.940 [vent.ChannelTriggeredEvent] - astro:sun:home:civilDawn#event triggered END
2019-01-10 08:05:59.951 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command MORNING
2019-01-10 08:08:59.939 [vent.ChannelTriggeredEvent] - astro:sun:home:daylight#event triggered START
2019-01-10 08:08:59.939 [vent.ChannelTriggeredEvent] - astro:sun:minus90:rise#event triggered END
2019-01-10 08:08:59.940 [vent.ChannelTriggeredEvent] - astro:sun:home:rise#event triggered END
2019-01-10 08:08:59.940 [vent.ChannelTriggeredEvent] - astro:sun:minus90:daylight#event triggered START
2019-01-10 17:08:59.872 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
2019-01-10 17:08:59.873 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered END
2019-01-10 17:10:59.872 [vent.ChannelTriggeredEvent] - astro:sun:home:daylight#event triggered END
2019-01-10 17:10:59.874 [vent.ChannelTriggeredEvent] - astro:sun:minus90:set#event triggered START
2019-01-10 17:10:59.875 [vent.ChannelTriggeredEvent] - astro:sun:minus90:daylight#event triggered END
2019-01-10 17:10:59.875 [vent.ChannelTriggeredEvent] - astro:sun:home:set#event triggered START
2019-01-10 17:10:59.900 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command DAY
2019-01-10 17:10:59.900 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command DAY
2019-01-10 17:10:59.901 [vent.ItemStateChangedEvent] - vTimeOfDay changed from MORNING to DAY
It worked fine the previous day but something stopped it triggering.
This morning it seems to have worked again
2019-01-11 08:04:59.939 [vent.ChannelTriggeredEvent] - astro:sun:home:civilDawn#event triggered END
2019-01-11 08:04:59.940 [vent.ChannelTriggeredEvent] - astro:sun:minus90:civilDawn#event triggered END
2019-01-11 08:04:59.940 [vent.ChannelTriggeredEvent] - astro:sun:minus90:rise#event triggered START
2019-01-11 08:04:59.940 [vent.ChannelTriggeredEvent] - astro:sun:home:rise#event triggered START
2019-01-11 08:05:00.018 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command DAY
could it be trying to trigger too many things at once?
Do you see around midnight in the logs the Astro events being rescheduled?
Yes it seems to run just after midnight.
2019-01-10 00:00:29.884 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:minus90
2019-01-10 00:00:29.927 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:home
2019-01-10 00:00:29.931 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2019-01-10 00:00:29.996 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
2019-01-10 00:00:30.023 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home
Is it possible that if I am making changes to Openhab during the day it somehow loses the variables, so that the events get out of sync. I’m not touching the rules or items for this and I am not restarting the System.
Just seems strange that it the vTimeofDay change to DAY happened at the EVENING event.
So still actiing strange:
This morning the MORNING event worked but the DAY event has just stayed as a MORNING = compare the log of yesterday with today:
2019-01-11 08:04:59.939 [vent.ChannelTriggeredEvent] - astro:sun:home:civilDawn#event triggered END
2019-01-11 08:04:59.940 [vent.ChannelTriggeredEvent] - astro:sun:minus90:civilDawn#event triggered END
2019-01-11 08:04:59.940 [vent.ChannelTriggeredEvent] - astro:sun:minus90:rise#event triggered START
2019-01-11 08:04:59.940 [vent.ChannelTriggeredEvent] - astro:sun:home:rise#event triggered START
2019-01-11 08:05:00.018 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command DAY
2019-01-12 08:04:59.962 [vent.ChannelTriggeredEvent] - astro:sun:home:rise#event triggered START
2019-01-12 08:04:59.963 [vent.ChannelTriggeredEvent] - astro:sun:minus90:civilDawn#event triggered END
2019-01-12 08:04:59.963 [vent.ChannelTriggeredEvent] - astro:sun:home:civilDawn#event triggered END
2019-01-12 08:04:59.964 [vent.ChannelTriggeredEvent] - astro:sun:minus90:rise#event triggered START
2019-01-12 08:04:59.993 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command MORNINGlog out all the time variables. then build a table that matches the case statements and make sure they are no overlaps and no gaps.
Basically, log out al the data and do the steps of the rule by hand.
finally, check that for every time variable used in the switch statement there is a corresponding rule trigger.
HI Ric - so I put some logging in and the issue is that the values Now and Astro events are sometimes getting calculated a fraction of a second before the actual start events. This means the case rule is out of sync.
For example this morning it ran the morning start at 06:20:59 when in fact it should have been 06:21. So it still thinks it is LATE NiGHT.
No sure this qualifies as a bug but it definitely needs a workaround.
For the moment I have added a new Val
val now_5= new DateTime(now.plusSeconds(5))
I then use this in the CASE statement instead of now which should fix it.
What do you think?
Here is the log file
2019-01-18 06:20:59.899 [INFO ] [smarthome.model.script.startup.rules] - Calculating time of day...
2019-01-18 06:20:59.924 [INFO ] [.eclipse.smarthome.model.script.test] - morning start 2019-01-18T06:21:00.000+01:00
2019-01-18 06:20:59.925 [INFO ] [.eclipse.smarthome.model.script.test] - day start 2019-01-18T08:06:00.000+01:00
2019-01-18 06:20:59.926 [INFO ] [.eclipse.smarthome.model.script.test] - afternoon start 2019-01-18T12:43:00.000+01:00
2019-01-18 06:20:59.927 [INFO ] [.eclipse.smarthome.model.script.test] - evening start 2019-01-18T17:21:00.000+01:00
2019-01-18 06:20:59.928 [INFO ] [.eclipse.smarthome.model.script.test] - night start 2019-01-18T18:31:00.000+01:00
2019-01-18 06:20:59.928 [INFO ] [.eclipse.smarthome.model.script.test] - latenight start 2019-01-18T00:00:00.000+01:00
2019-01-18 06:20:59.930 [INFO ] [eclipse.smarthome.model.script.test1] - Now is 2019-01-18T06:20:59.929+01:00
2019-01-18 06:20:59.937 [INFO ] [smarthome.model.script.startup.rules] - Calculated time of day is LATE NIGHT
Here is the events file
2019-01-18 06:20:59.885 [vent.ChannelTriggeredEvent] - astro:sun:home:morningNight#event triggered END
2019-01-18 06:20:59.886 [vent.ChannelTriggeredEvent] - astro:sun:home:astroDawn#event triggered START
2019-01-18 06:20:59.941 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command LATE NIGHT
1 Like
I will try this, because I also have problems with this.
Very good debugging and analysis but it still isn’t totally clear.
The Rule is triggering before it should? That would account for now being off. Is it only the Astro events or is this also a problem with the cron triggered events?
Your work around is a good one but if this is ever going to be fixed we need to narrow the problem down just a bit so we know where to file the issue.
cron seems ok I have the rule set to run at 00:05 and it ran 15 seconds after that time. So it seems to be the Astro events which run a fraction of a second earlier than scheduled.
That does not seem OK to me. It should run at or a few milliseconds after 00:05, not 15 seconds after. Do you have a lot of cron triggered or Astro triggered Rules or lots of Timers?
Hi I’ve checked a few of my cron jobs for timing and they all happen less than 1 second after scheduled, with the exception of that one which for some reason took 15 seconds, despite nothing else happening at that time. Last night it ran fine. I mostly use expire now for timers but these only operate when there is movement and this cron job was in the middle of the night…so a mystery for now!
The good news is that my fix of adding 5 seconds to the now value seems to be working fine. It seems that over half the astro jobs are starting a fraction of a second before they should.
it might be worth filing an issue on the binding at the openhab2-addons repo. The event shouldn’t occur before the time.
Hi,
I’m using the “Simple Example” at the top of this DP. I get an error at this line:
// Convert the Astro Items to Joda DateTime
val day_start = new DateTime(vSunrise_Time.state.toString)
The error I get:
2019-01-20 20:02:47.752 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'Calculate time of day state': Invalid format: "NULL"
Can anybody help my out?
vSunrise_Time is uninitialised. Do you have the Astro binding installed?
I think that i am experiencing the same issue after openHAB startup. (At least the same error message appears)
But didn’t invest time yet.
Astro binding installed.
Check the logs. After startup and a little after midnight you should see logs from Astro saying it’s scheduling events. If you don’t that means Astro is failing to calculate the times for the new day.
If those logs are present, then something new I’ve never seen before is going on.
Mine is calculating every day, normally, but the rule fail to run automatically usually.