What the post that I linked suggests is linking with a profile. That’s what I did, but the item stays undefined after the channel triggered. Does it work for other people to link a Switch item via a profile to the, e.g., sunrise range trigger channel with a profile? I would have expected that the Switch item receives a state when sunrise starts (switching to ON) and that it switches to OFF when sunrise ends.
Which profile habe you configured?
The only one that is offered (i.e., not greyed out) in the GUI: Toggle Switch.
I get those three offered when trying to link a switch item to an Astro trigger channel on 5.1.0:
- Generic Command
- Generic Toggle Switch
- Toggle Switch
The first two are configurable, the last one only toggles on PRESSED event.
Unfortunately the linked docs contain no „mapping“ to the names the UI displays.
Interesting. This is what it looks like for me, also on 5.1.0. No much choice here, and not much to configure…
I think I am starting to understand a bit better where the problems I am seeing are coming from, at least in some cases. My astro triggers remain erratic - sometimes it still seems that rules simply don’t get triggered at all. But for a few of the rules additional logging pointed me to an issue that explains some of my problems, one that’s more easy to pin-point.
These rules follow a design pattern like the following:
rule “…”
when
Channel ‘astro:sun:sun:set#event’ triggered END or
Channel ‘astro:sun:sun:civilDusk#event’ triggered END or
Item Something_else changed
then
val sunset = (Sunset.state as DateTimeType).getZonedDateTime(ZoneId.systemDefault)
val dusk = (Civil_Dusk.state as DateTimeType).getZonedDateTime(ZoneId.systemDefault)
if ((now.isAfter(sunset) && Something_else.state==ON) ||
now.isAfter(dusk)) {
do_something
}
end
The intention is to perform an action earlier (namely at the end of sunset) if Something_else is ON, or to wait until the end of civil dusk if Something_else is OFF. Sunset and Civil_Dusk are DateTime items linked to the respective #end time channels in the astro binding. The performed action do_something is idempotent (i.e., it doesn’t matter if it’s executed multiple times on the same day), so I didn’t need to worry about the possibility of multiple executions in case Something_else is ON or changes.
For a long time, I used to get the desired effect: the first execution of do_something takes place after sunset when the switch item is ON, or otherwise at the latest when civil dusk ended. Recently (and likely related to the 5.1.0 upgrade) however, do_something never happened if the Something_else switch remained OFF. I now understood why.
Additional logging of the values of now, sunset and dusk in one of these rules gave me this when the rule was triggered through astro:sun:sun:civilDusk#event END:
2026-01-01 17:16:05.002 [INFO ] […] -
now: 2026-01-01T17:16:05.002812514+01:00[Europe/Berlin],
sunset: 2026-01-01T16:38:14.521+01:00[Europe/Berlin],
dusk: 2026-01-01T17:16:05.936+01:00[Europe/Berlin]
The catch here can be seen by comparing the now and dusk timestamps, i.e., the time when the rule got triggered and Astro’s civilDusk#end time: They are very close together - but actually, dusk is still more than 900 milliseconds in the future when the rule triggers.
That is, the civilDusk#event END rule trigger actually triggers a tiny little bit (less than 1s) too early, namely before the time given by the civilDusk#end channel. This is enough, though, that now.isAfter(dusk) is false. Therefore the condition in my rule never evaluates to true if the switch is OFF, and do_something is never executed.
I believe that this behavior is new, because in many years with OpenHAB my rules of this form worked reliably. It seems unplausible that a rule triggered by an astro #event END trigger is executed before the time in the respective astro #end channel has actually passed. At the very least this is unintuitive, and quite likely it is unintended.
I successfully worked around this bug by substituting now.isAfter(…) by now.plusSeconds(1).isAfter(…). But that’s…well…ugly.
That’s an interesting finding. I won’t claim to understand all the details (yet at least), the reason for this should be found, but my initial thought is that this can be caused by rounding/truncation. There’s quite a lot of truncation of e.g. milliseconds in different places in the binding, and some of this has been redesigned to remove other bugs, perhaps we have ended up with a situation where the trigger actually triggers on a milliseconds-truncated value, thus happening slightly before the actual event.
Yes, that sounds very plausible, and I actually had a similar suspicion. Indeed it appears that the #begin/#end channels are filled with sub-second resolution, but the #event triggers happen at full seconds (with millisecond truncated).
If that’s the reason, then an easy solution would be to always work with full second precision, i.e., to also truncate milliseconds in the calculation of times for #begin/#end channel.
…or to change the binding to not truncate the events - making it simpler for everybody to use 
…or to change the binding to not truncate the events - making it simpler for everybody to use
Yes, sure - but that comes at the risk that tiny numerical differences with the involved floating point values might cause similar trouble then, again, in the future. That’s why my gut feeling tends towards a well-known, fixed precision that shouldn’t be affected by floating point precision.
I’m not arguing that managing precision isn’t “safer” in any case, merely that I think it would also be better to make sure that the events don’t trigger too early. They will never trigger exactly anyway, because a task is scheduled for a thread when the event happens, and that thread must be picked up and executed. But, that will normally be quick, and it should be possible to ensure that this is always slightly after the event, not perhaps a bit before or perhaps a bit after. That makes it easier for people to make correct assumptions.
Yes, sure, I got you. I was just pointing out that “very briefly after” could well turn into “very, very briefly before” in rare instances if different computation paths or some forth and back between different floating point precisions comes into play. And who knows what future versions of Java’s time -related classes or the scheduler behind the rule triggering might decide to do with the floating point parts of the DateTime values. I’d find it hard to decide how much of a “bit after” is really safe and future-proof, whereas we can be sure that “full seconds everywhere” is safe.
Seconds in DateTime are integers, and therefore “safe” in that regard. In the sub-second range wild things can happen, and if things go wrong with a sufficiently fast (future) CPU, when this thread will long be forgotten, this might turn into a hell to trace down.
It depends. If you check “after”, it should be safe. But, if you check “equals” it might not. There’s no guarantee that a thread will be available promptly, and depending on what other parts of the system are doing, it could be severely delayed.
I don’t think that there are floating points involved here, at least not at the Java side. Calendar works entirely with integers, shorter variants for partial fields (like “hours” or “minutes”), and long in milliseconds precision when as a combined value.
I’m not sure that a situation exists where it can actually trigger too early, unless it is scheduled to run too early because of truncation.
Okay, I might have been on the wrong track then regarding Java’s time classes. My fault.
In any case, one should never check for equality with now, regardless of the context, because as you say obviously time will pass between rule triggering and whatever point during the execution calls now. (And yes, I am also aware that my rule design is suboptimal because it calls now more than once within the same rule, and the values will slightly differ; I did better in that regard in other rules, when it might make a difference). But if you want to check for equality between two DateTime instances, you want to avoid that tiny differences mess it up, so it’s about precision again.
I trust you guys will know best how to fix your binding. I am looking forward to what’s coming up, and hope that I will be able to remove my ugly workarounds soon. And I will keep some extra logging in my rules to spot weird things going on without growing too much additional gray hair.
1 Like
I’ve been trying to debug this now, and there is one problem: As far as I can tell, the events are scheduled with millisecond precision. So, that kind of ruins that whole theory.
I see in the code, that if you enable DEBUG logging for org.openhab.binding.astro, it should be logged when events are created. Maybe that can shed some light?
Please note that the events are created shortly after midnight, so you might not want to wait for that. I’ve found that disabling the Thing (e.g “Sun”) in the UI and then enabling it again is enough for the schedules to be recreated though.
edit: I’m now wondering if now() in DSL can be trusted to be accurate. I have no reason to think it shouldn’t, because I assume it comes pretty straight from Java, but if the events have milliseconds precision, I’m a bit out of ideas.
Making further logs from the rule as above, might also give an indication, if “now” is always just after the full second, or if that was just a coincidence.
The DEBUG-Log during stopping and re-starting the Thing doesn’t reveal much (besides some error messages about missing deactivate methods), at least not at this time of day:
2026-01-01 22:08:23.655 [DEBUG] [o.internal.handler.AstroThingHandler] - Disposing thing astro:sun:sun
2026-01-01 22:08:23.655 [DEBUG] [o.internal.handler.AstroThingHandler] - Stopping scheduled jobs for thing astro:sun:sun
2026-01-01 22:08:23.655 [DEBUG] [o.internal.handler.AstroThingHandler] - Thing astro:sun:sun disposed
2026-01-01 22:08:23.659 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : ServiceFactory.ungetService()
2026-01-01 22:08:23.659 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : getting deactivate: deactivate
2026-01-01 22:08:23.659 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : Locating method deactivate in class org.openhab.binding.astro.internal.action.AstroActions
2026-01-01 22:08:23.660 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : Declared Method org.openhab.binding.astro.internal.action.AstroActions.deactivate([interface org.osgi.service.component.ComponentContext]) not found
2026-01-01 22:08:23.660 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : Locating method deactivate in class java.lang.Object
2026-01-01 22:08:23.660 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : Declared Method java.lang.Object.deactivate([interface org.osgi.service.component.ComponentContext]) not found
2026-01-01 22:08:23.660 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : deactivate method [deactivate] not found, ignoring
2026-01-01 22:08:23.660 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : DependencyManager: osgi.ds.satisfying.condition close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@74f41f2a at tracking count 1 refpairs: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2026-01-01 22:08:25.095 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : ServiceFactory.getService()
2026-01-01 22:08:25.096 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : This thread collected dependencies
2026-01-01 22:08:25.097 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : getService (ServiceFactory) dependencies collected.
2026-01-01 22:08:25.097 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : Querying state active
2026-01-01 22:08:25.097 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2026-01-01 22:08:25.098 [DEBUG] [g.astro.internal.action.AstroActions] - Astro actions service instanciated
2026-01-01 22:08:25.099 [DEBUG] [g.astro.internal.action.AstroActions] - bundle org.openhab.binding.astro:5.1.0 (291)[org.openhab.binding.astro.internal.action.AstroActions(354)] : Changed state from active to active
2026-01-01 22:08:25.116 [DEBUG] [o.internal.handler.AstroThingHandler] - Initializing thing astro:sun:sun
2026-01-01 22:08:25.117 [DEBUG] [o.internal.handler.AstroThingHandler] - org.openhab.binding.astro.internal.config.AstroThingConfig@66e4ebd2
2026-01-01 22:08:25.118 [DEBUG] [o.internal.handler.AstroThingHandler] - Restarting jobs for thing astro:sun:sun
2026-01-01 22:08:25.119 [DEBUG] [o.internal.handler.AstroThingHandler] - Stopping scheduled jobs for thing astro:sun:sun
2026-01-01 22:08:25.121 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled org.openhab.core.internal.scheduler.SchedulerImpl$ScheduledCompletableFutureRecurring@43d21390[Not completed, 2 dependents] at midnight
2026-01-01 22:08:25.127 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:sun
2026-01-01 22:08:25.129 [DEBUG] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:sun
2026-01-01 22:08:25.130 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:sun every 300 seconds
2026-01-01 22:08:25.134 [DEBUG] [o.internal.handler.AstroThingHandler] - Thing astro:sun:sun initialized ONLINE
2026-01-01 22:08:25.136 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:sun
2026-01-01 22:09:19.601 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:moon
Maybe we’ll see something more enlightening tomorrow.
Past log entries from my rules definitely tend to occur right after full seconds when the trigger event was from Astro. I don’t have many log entries of that sort, but the ones that I do have don’t look like a mere coincidence:
2025-12-30 17:55:25.004 [INFO ] [...] - now: 2025-12-30T17:55:25.004662452+01:00[Europe/Berlin], sunset: 2025-12-30T16:36:23.305+01:00[Europe/Berlin], dusk: 2025-12-30T17:14:21.036+01:00[Europe/Berlin]
2025-12-31 16:37:17.008 [INFO ] [...] - now: 2025-12-31T16:37:17.008665840+01:00[Europe/Berlin], sunset: 2025-12-31T16:37:17.611+01:00[Europe/Berlin], dusk: 2025-12-31T17:15:12.339+01:00[Europe/Berlin]
2025-12-31 17:15:12.004 [INFO ] [...] - now: 2025-12-31T17:15:12.004543249+01:00[Europe/Berlin], sunset: 2025-12-31T16:37:17.611+01:00[Europe/Berlin], dusk: 2025-12-31T17:15:12.339+01:00[Europe/Berlin]
That isn’t really an error - if there’s no deactivate method, there’s no specific “deactivating” code. It’s just that in debug, you see how this process “resolves”.
Yeah, that’s a bit impractical for debugging - it doesn’t schedule events that are in the past. You’re probably on your production system, so that’s probably not an option, but I sat my time zone and location to Vietnam to get some events. I did this on a test system though.
I agree that it doesn’t look coincidental, I just can’t quite figure out where this truncation takes place - if that’s what happens. But, there are lots of places to check, and it takes just one place to make it so, so I’m not saying it’s not the case. It would be helpful to have the suspicion reinforced before trying to dig really deep though.
No, sorry, it’s indeed way too “production” for that. I don’t even want to start thinking about how many different things I might mess up when I do this, because my zoo of scripts and services around OH are for sure not all timezone-safe. 
I will need to catch up on sleep a bit, so don’t expect a live update right after midnight. But I’ll check the logs tomorrow and will let you know.
1 Like
Good morning. 
Okay, this is getting more and more interesting…
The night brought these messages from Astro in my openhab.log:
2026-01-02 00:00:30.131 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/rise#event/START in 30298873ms (at 2026-01-02T08:25:29)
2026-01-02 00:00:30.131 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/rise#event/END in 30542869ms (at 2026-01-02T08:29:33)
2026-01-02 00:00:30.131 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/set#event/START in 59679869ms (at 2026-01-02T16:35:10)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/set#event/END in 59922868ms (at 2026-01-02T16:39:13)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/noon#event/START in 45110868ms (at 2026-01-02T12:32:21)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/noon#event/END in 45170868ms (at 2026-01-02T12:33:21)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/night#event/START in 66987868ms (at 2026-01-02T18:36:58)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/morningNight#event/START in -30132ms (at 2026-01-02T00:00:00)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/morningNight#event/END in 23234868ms (at 2026-01-02T06:27:45)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/astroDawn#event/START in 23234868ms (at 2026-01-02T06:27:45)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/astroDawn#event/END in 25573868ms (at 2026-01-02T07:06:44)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/nauticDawn#event/START in 25573868ms (at 2026-01-02T07:06:44)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/nauticDawn#event/END in 28031868ms (at 2026-01-02T07:47:42)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/civilDawn#event/START in 28031868ms (at 2026-01-02T07:47:42)
2026-01-02 00:00:30.132 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/civilDawn#event/END in 30298868ms (at 2026-01-02T08:25:29)
2026-01-02 00:00:30.133 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/astroDusk#event/START in 64648867ms (at 2026-01-02T17:57:59)
2026-01-02 00:00:30.133 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/astroDusk#event/END in 66987867ms (at 2026-01-02T18:36:58)
2026-01-02 00:00:30.133 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/nauticDusk#event/START in 62190867ms (at 2026-01-02T17:17:01)
2026-01-02 00:00:30.133 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/nauticDusk#event/END in 64648867ms (at 2026-01-02T17:57:59)
2026-01-02 00:00:30.133 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/civilDusk#event/START in 59922867ms (at 2026-01-02T16:39:13)
2026-01-02 00:00:30.133 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/civilDusk#event/END in 62190867ms (at 2026-01-02T17:17:01)
2026-01-02 00:00:30.133 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/eveningNight#event/START in 66987867ms (at 2026-01-02T18:36:58)
2026-01-02 00:00:30.133 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/daylight#event/START in 30542867ms (at 2026-01-02T08:29:33)
2026-01-02 00:00:30.133 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:sun/daylight#event/END in 59679867ms (at 2026-01-02T16:35:10)
2026-01-02 00:00:30.134 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:sun/SUN_RISE in 30299731ms (at 2026-01-02T08:25:29)
2026-01-02 00:00:30.134 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:sun/SUN_SET in 59680445ms (at 2026-01-02T16:35:10)
2026-01-02 00:00:30.134 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:sun/NIGHT in 66988236ms (at 2026-01-02T18:36:58)
2026-01-02 00:00:30.135 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:sun/DAYLIGHT in 30543122ms (at 2026-01-02T08:29:33)
2026-01-02 00:00:30.135 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:sun/ASTRO_DAWN in 23235331ms (at 2026-01-02T06:27:45)
2026-01-02 00:00:30.135 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:sun/NAUTIC_DAWN in 25574619ms (at 2026-01-02T07:06:44)
2026-01-02 00:00:30.135 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:sun/CIVIL_DAWN in 28031925ms (at 2026-01-02T07:47:42)
2026-01-02 00:00:30.135 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:sun/ASTRO_DUSK in 64648947ms (at 2026-01-02T17:57:59)
2026-01-02 00:00:30.135 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:sun/NAUTIC_DUSK in 62191641ms (at 2026-01-02T17:17:01)
2026-01-02 00:00:30.135 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:sun/CIVIL_DUSK in 59923837ms (at 2026-01-02T16:39:13)
Before I went to bed I added eight test rules, which fire (only) at the beginning/end of astro/nautic/civil dawn and sunrise and do nothing but writing a log entry. Those rules gave me the following:
2026-01-02 06:27:45.005 [INFO ] [openhab.core.model.script.astro test] - astro dawn start
2026-01-02 07:06:44.003 [INFO ] [openhab.core.model.script.astro test] - nautic dawn start
2026-01-02 07:06:44.003 [INFO ] [openhab.core.model.script.astro test] - astro dawn end
2026-01-02 07:47:42.004 [INFO ] [openhab.core.model.script.astro test] - nautic dawn end
2026-01-02 07:47:42.004 [INFO ] [openhab.core.model.script.astro test] - civil dawn start
2026-01-02 08:25:29.003 [INFO ] [openhab.core.model.script.astro test] - sunrise start
2026-01-02 08:25:29.003 [INFO ] [openhab.core.model.script.astro test] - civil dawn end
2026-01-02 08:29:33.002 [INFO ] [openhab.core.model.script.astro test] - sunrise end
And finally a collection of channel trigger logs from my events.log:
2026-01-01 16:34:10.000 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:set#event triggered START
2026-01-01 16:34:10.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:daylight#event triggered END
2026-01-01 16:38:14.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:set#event triggered END
2026-01-01 16:38:14.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:civilDusk#event triggered START
2026-01-01 17:16:05.003 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:nauticDusk#event triggered START
2026-01-01 17:16:05.003 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:civilDusk#event triggered END
2026-01-01 17:57:05.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:astroDusk#event triggered START
2026-01-01 17:57:05.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:nauticDusk#event triggered END
2026-01-01 18:36:07.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:night#event triggered START
2026-01-01 18:36:07.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:astroDusk#event triggered END
2026-01-01 18:36:07.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:eveningNight#event triggered START
2026-01-02 06:27:45.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:morningNight#event triggered END
2026-01-02 06:27:45.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:astroDawn#event triggered START
2026-01-02 07:06:44.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:nauticDawn#event triggered START
2026-01-02 07:06:44.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:astroDawn#event triggered END
2026-01-02 07:47:42.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:nauticDawn#event triggered END
2026-01-02 07:47:42.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:civilDawn#event triggered START
2026-01-02 07:56:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:moon:moon:set#event triggered END
2026-01-02 08:25:29.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:rise#event triggered START
2026-01-02 08:25:29.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:civilDawn#event triggered END
2026-01-02 08:29:33.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:daylight#event triggered START
2026-01-02 08:29:33.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:sun:rise#event triggered END
A number of observations:
- The scheduled times in the Astro debug log show only full second precision. It might be worth to change that if the decision is to schedule at (sub-?)millisecond accuracy.
- One event,
morningNight#event/START, is scheduled into the past. - According to the scheduled events,
nightnever ends.
eveningNightalso doesn’t. (Don’t rely on my events.log for comparison, it might be incomplete around midnight. My OH installation processes so many events that events.log rolls over very, very quickly. The worrysome part is that these events are missing in the list of what’s being scheduled.) - The Astro log entries also give the (rounded? truncated? exact?) number of milliseconds into the future, though. If you add the respective number of milliseconds to the log timestamps, you end up (1) anywhere for the phase job log entries (which might mean sub-second scheduling accuracy in these cases?), (2) very close to a full second for the first log entry,
rise#event/START(4ms off, might be a processing delay before or during the generation of the log entry?), and (3) on the spot on full seconds for all other START/END schedulings. - This matches the log timestamps of my test rules - all of them triggered on full seconds, as it seems.
- It also matches the log timestamps in the events.log, which are all a very short (processing) delay after a full second. (This, by the way, will be easy to verify on other systems, because virtually everyone should have those ChannelTriggerEvent INFO entries in their events.log anyway.)
Regarding your comment on the accuracy of now:
I had another look at the log output of my rules over the past few days. Here are examples (reduced to the relevant parts for clarity):
2025-12-30 17:55:25.004 - now: 2025-12-30T17:55:25.004662452
2025-12-30 23:58:28.647 - now: 2025-12-30T23:58:28.647482428
2026-01-01 01:43:16.033 - now: 2026-01-01T01:43:16.032859897
2026-01-01 23:30:45.764 - now: 2026-01-01T23:30:45.763617307
As expected, the now timestamps are always (very, very) briefly earlier than the respective (truncated-to-ms) log timestamps: now is called first, and then the return value is passed to logInfo. This holds for instances where the rules were triggered by Astro (like in the first case here), and also when the rule was triggered by other events (in the other examples). So, if we assume that the log timestamp generation is accurate (and why shouldn’t we?), then now seems at least as accurate.
tl;dr: I wouldn’t be worried about the accuracy of now.
Interesting choice of words…
The “minus schedule” is interesting, I must admit, because there is code there that excludes those. So, I don’t know how it managed to slip through.
I also can’t help but notice that the milliseconds delay have a tendency to and at around 867. That doesn’t sound like a coincidence. When I debugged this, there was no such system, but that probably just means that the debugging itself interferes with the result - so that pauses in debugging make the delay appear “more random”. I looked specifically for any “pattern” there, and couldn’t find one.
I can take a quick look, but I think the formatting as caused by what format is easily available for logging. Time with milliseconds is a somewhat obscure and unusual format, and it’s not worth constructing something just for the log. But, the delay is logged in milliseconds from the current time-stamp (which has milliseconds), so you can figure it out exactly if you want to.
Yes, very peculiar and must be investigated.
I might be missing something here, is night supposed to end at midnight, or when exactly? The way this works means that we can’t have events that happen between 00:00:00 and 00:00:30 (or whenever the job runs), because those take place before the events have been created. This is the reason why there is no “midnight” event, could this be the cause of this as well?
Neither rounded not truncated. Milliseconds is the precision used for scheduling (and many other things). We also have nanoseconds to work with in many areas, but it just gets a whole lot more difficult to work with. Nanoseconds don’t have a fixed epoch, because they are also stored in longs, and these would easily overflow. Therefore, the epoch is “arbitrary” when working with nanoseconds, and every value must be considered relative only. Which should explain why it isn’t used for things like this
Yeah, I don’t pay much attention to those 4ms, they can be from the logging framework or from thread other sources, when they are this close, it’s pretty clear that they are “second-aligned” for some strange reason.
I agree, it seems that now is on the ball, and that the explanation for what we see must exist in the scheduling.