Sup people,
just found out that it seem this
Channel 'astro:sun:local:rise#event' triggered START or
Channel 'astro:sun:local:set#event' triggered START
...
does not work in OH2.5.8
Is there a way how to debug it somehow?
I’ve tried to add cron trigger, which works, so rule is fine, just it is not triggered by astro binding.
(and yes, I have checked things/items and everthing is linked together)
Ideas?
thanks
ah … digged bit deeper into logs and strange things happening:
astro:sun:local:set#start
This holds 2020-09-10T19:25:00.000+0200
BUT Log for EVENT shows that this is triggered before “START”
2020-09-10 19:24:59.933 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
Is this correct behaviour?
Another strange thing is that offset sunset is triggering at same time as local
2020-09-10 19:24:59.933 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
2020-09-10 19:24:59.933 [vent.ChannelTriggeredEvent] - astro:sun:m90:set#event triggered START
The documentation shows double quotemarks. I have seen suggestions that is necessary, I do not know the truth of that.
Channel "astro:sun:local:rise#event" triggered
That appears to be 70mS “early”. Is that a problem for you? I suspect the state channels round to the nearest minute.
Did the rule trigger? Can’t see a direct connection but this thread may be of interest
Just checked my rule file. I have single quotes there and it works
Channel 'astro:sun:home:set#event' triggered START
while I use double quotes in the things file
astro:sun:home [ geolocation="53.316849, 9.863902,51", interval=60 ] {
Channels:
Type rangeEvent : set#event [
offset=-0,
latest="21:59"
]
}
seems like it is because of this inside the rule:
switch now {
case now.isAfter(morning_start) && now.isBefore(day_start): curr = "MORNING"
case now.isAfter(day_start) && now.isBefore(afternoon_start): curr = "DAY"
case now.isAfter(afternoon_start) && now.isBefore(evening_start): curr = "AFTERNOON"
case now.isAfter(evening_start) && now.isBefore(night_start): curr = "EVENING"
case now.isAfter(night_start): curr = "NIGHT"
case now.isAfter(bed_start) && now.isBefore(morning_start): curr = "BED"
}
for example
val evening_start = new DateTime(vSunset_Time.state.toString)
holds 19:25:000+000 and therefore RULE is triggered few mS EARLIER than evening starts, which means time of the day is not changed eventho rule is probably triggered.
Which is super strange.
yes it did, anyway rule can’t really work because of difference between event trigger and start
It was working on earlier versions for sure, not sure if related to 2.5.8 or some kind of system time sync
Yes, that’s a rule design issue. Half the time the rule trigger will be before the static Item instant, half the time after (assuming there is some rounding
going on).
Factor in some execution delays and it will usually work … change something, it will change your chances. Tricky to solve.
That’s a nasty little race condition been hiding there all along … I wonder how much trouble that’s given folk. @rlkoshak , for awareness.
I’m not sure of the exact mechanisms going on here…
The binding looks like it rounds static states to nearest second, I doubt it rounds to minute?
Then, using quartz scheduler in rules, you can only schedule for whole seconds, not milliseconds. I guess the same applies to use by bindings.
But - I have observed the scheduler fires by milliseconds on the clock e.g. if at 10:53:00.500 you schedule +10 seconds, it goes off at 10:53:10.500 (plus a couple mS for execution).
We must bear in mind Astro will be scheduling by “delay from now”, not by the clock. It might do that before or after calculating static values, so there will be more execution times thrown in.
I don’t think we need to figure this out really … just appreciate they’re never going to consistently match to the second.
question really is if there is a convenient way how to trigger it after START or shift start couple of seconds before actual start.
I can indeed subtrack few seconds from START constant, so my rule will work as trigger will be after shifted start, but not sure if that is the right way how to do it.
@rikoshak DP rules (which this is) works with isBefore isAfter START/END so basically what we are saying here is that these rules works half of the time right, and other half they are not … 
It triggered 77 msec before the START. For a system like openHAB with all that is going on in parallel I’d call that about as close as it can get.
But that 77 msec shouldn’t cause the events to not occur in the first place.
Which one was right? Did they both trigger at -90 or both trigger at local?
Indeed, and indeed this does show how that few msec could be a problem, especially on a fast machine that can handle the event and kick off the rule faster than that 77 msec.
So I’ve totally reworked the time of day DP in Jython to no longer rely on the events from Astro and manually written cron triggers so that might be why I’ve not seen this behavior. Unfortunately the approach it uses relies on Item metadata which is unavailable in Rules DSL. The good news is when/if you move in that direction all you have to do is define your Items and drop the library into /etc/openhab2/automation. 
As a work around one could add a 100-300 msec sleep at the start of the Rule, or even better add 100-300 msec to now for the comparisons. The amount of time just needs to be long enough to cover most if not all of the rounding error cases. That’s not really a satisfactory solution but it would work.
It seems odd that it would round at all IMO, and this must be something new as if this were happening before I imagine there would be more reports of problems before now with the ToD rule. If it didn’t work 50% of the time I would have expected to hear about this behavior before now.
Another source of the problem could be that Astro has been rounding all this time but something changed to make the rule kick off some 100 msec faster. But that would almost have to include changes from core and there have been none of those since 2.5.0.
See above, add a few msec to now before the switch statement. That will push the comparison past the rounding error. You’ll have to experiment to find the optimal number. Based on the logs above 100 should cover it, but that’s based on a sample of 1.
I don’t think there is any way to adjust this at the trigger short of changing the Thing definition. But that fees as awkward as just adding a few msec to now in the Rule.
yeah I’ve done this to be on safe side
val newnow = now.plusSeconds(10)
// Calculate the current time of day
var curr = "UNKNOWN"
switch newnow {
case newnow.isAfter(morning_start) && newnow.isBefore(day_start): curr = "MORNING"
case newnow.isAfter(day_start) && newnow.isBefore(afternoon_start): curr = "DAY"
case newnow.isAfter(afternoon_start) && newnow.isBefore(evening_start): curr = "AFTERNOON"
case newnow.isAfter(evening_start) && newnow.isBefore(night_start): curr = "EVENING"
case newnow.isAfter(night_start): curr = "NIGHT"
case newnow.isAfter(bed_start) && newnow.isBefore(morning_start): curr = "BED"
}
both triggered at local, so -90min have not been triggered at correct time
2020-09-10 19:24:59.933 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
2020-09-10 19:24:59.933 [vent.ChannelTriggeredEvent] - astro:sun:m90:set#event triggered START
And I was expecting rather something like this
2020-09-10 17:54:59.933 [vent.ChannelTriggeredEvent] - astro:sun:m90:set#event triggered START
2020-09-10 19:24:59.933 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
For the last issue with the events occurring at the same time I’d recommend filing an issue on the binding. That looks like a bug. Is it just the events or do Items linked to the DateTime Channels also show the error?
Items linked to -90 shows correct time which is 1.5hour before local time, so this seems to be ok.
It looks like just trigger does not count with offset value
just watching logs which I’m expecting to trigger -90 set#start at 17:52:00
which is value of this
DateTime vEvening_Time "Afternoon [%1$tH:%1$tM]" <sunset> { channel="astro:sun:home90:set#start" }
but nothing in logs so far (17:58 already)
Are you sure you have set the event channel to use offset 90, too? you have to set offset for every single channel…
pretty sure I have
astro:sun:home90 "Sys Sun -90" [ geolocation="xxx,xxx,xx", interval=300 ] {
Channels:
Type rangeEvent : set#event [
offset=-90
]
Type rangeEvent : set#start [
offset=-90
]
}
But to be on the safe side, I’ve restarted OH so let’s wait till today just in case OH haven’t picked things file correctly
so after OH restart it looks like problem with wrong -90min trigger is gone.
Anyway, it still triggers few milliseconds earlier than actual start - which is solvable by adding couple of seconds to whatever variable rule is using, but honestly I would expect trigger few millis after actual start 
Would you like to define “actual start” within milliseconds for the sunrise event? I suspect mine here varies a bit depending how much the grass has grown on the hill on the horizon.
Someone, somewhere will have a use case where they want the static time to become ‘true’ after the event has fired. (There is always a someone, somewhere with openHAB!).
The root point is that they simply can never be exactly matched or “simultaneous”. In fact, the closer the match, the more likely a race will result at the point of use. I would not support any effort to fudge this by having Astro binding "lie’ with faked static or event times.
There is just an inherent race condition, that we’ve all overlooked for years.
The ‘engineered’ fix is to make use of only one of your racing conditions. For example, you could trigger whatevers off the event and also set some variable “sun has risen” true. No delays required, no use made of static state.
Having said all that … yes this behaviour comes as a surprise.
I can’t imagine anyone anywhere who would use EVENT to start few milisecodns earlier than real START of given event … but indeed someone somewhere could be.