Well, yes, but that’s a logical consequence of if all the target times are full seconds, and all the log entries are generated within almost the same millisecond, right?
Did you check your own events.log, to see if the ChannelTriggeredEvent entries also align with full seconds?
Yes, sure. But since the log timestamps themselves come with milliseconds, I assumed there was a formatting method or format string directive for this. Just guessing, though - Java is not my usual home ground.
Well, you’re the expert for the binding. But I assume that night ends at the start of sunrise, because night starts after sunset. And since morningNight starts at midnight, eveningNight will very likely be expected to end at midnight (and I suppose the DateTime channels will say exactly that, without having verified it). An average user would certainly expect trigger events at these times.
So, for night/END this cannot be the cause. For eveningNight/END it could. But sending triggers for start, but not for END just because END is at midnight is certainly not what users would expect to happen.
Exactly - it’s a “pattern” that indicates that there’s some system that shouldn’t be there. The events shouldn’t be “aligned” in this way, and it strongly indicates some kind of alignment with full seconds.
I didn’t look, because my test environment is pretty different that a real system, and instead of looking in the logs, I debug execution as it happens, following every step. Except for the fact that debugging changes the timing of things itself, it gives a much better insight into what happens than reading logs do. But, I’m pretty sure that I would see the same if I tested this in a “normal environment”.
There might be something somewhere, but in this case, the class already has a formatter defined:
private final SimpleDateFormat isoFormatter = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss", Locale.ROOT);
This formatter is then simply reused for logging, instead of creating a new one just for logging purposes:
final String formattedDate = this.isoFormatter.format(eventAt.getTime());
logger.debug("Scheduled {} in {}ms (at {})", job, sleepTime, formattedDate);
The log timestamps are created by the logging framework, which is a whole other matter.
It’s absolutely possible to change this, the question is just: When this issue is resolved, is there any point? Is it worth the extra object creation, that won’t even be used unless DEBUG logging is enabled?
Actually, I’m not. I just did some bug fixes to it, and now suddenly I seem to be involved in all kind of matters for this binding. But, there are still large parts of it I know very little about
Someone™ will have to figure out why then..
This follows the design of how jobs and events are done. I guess it could be set to happen at 23:59:59.999 or something like that as a workaround. I’m really not well enough informed about why these decisions are what they are. @lsiepel do you have anything to add to this?
Well then - an ever bigger thank you for your efforts.
Yes, that’s better than nothing. Though technically I don’t really see why at 00:00:30.000 on day x one cannot schedule an event for 00:00:00.000 on day x+1. The scheduler certainly won’t complain, and the next round of scheduling won’t happen until 30s later, so it won’t interfere in the sense of scheduling new times exactly when the old events trigger. I share the intuition that this doesn’t feel right. But shifting the scheduling to 30s after midnight is done anyway, and that seems to be exactly the solution that allows to safely schedule events at (next) midnight.
This could be solved differently. But, this binding has been around for a very long time, and a lot of people rely on it for their automation. Changing “fundamental logic” is thus very scary. The reason it “can’t be done” as the logic is at the moment, is that events are just generated, and then all those that belong to a different date are filtered out. I assume that this is a way to protect against “double events”, and without this protection, a much more rigorous scheme would have to be implemented to protect against double events. Moving it to 00:00:30 is something that has been done after the initial design I think, probably because too much was happening at 00:00.
It’s absolutely possible to redesign this to work also just after midnight - the question is if anybody dares to
edit: Remember that just shifting the “window” that is unavailable won’t solve that much. It could run at any other time, the “filtering” would be a bit more complicated, but not much. But, no matter where you put it, it will always collide with something (astronomical and nautical will keep moving around). So, a fundamentally different logic would have to exist, where you can handle if the same even already exists.
I’ve determined that this is a red herring here. I was getting all worked up now, because the cron scheduler only supports seconds resolution. But, it’s not the scheduler used for these events. It is what’s used to schedule the job that runs at 00:30, but the timing of that job isn’t the problem.
Actually, this is quite tricky. I haven’t yet found whatever seems to align it to the nearest second, but I’ve found another issue that could make the event happen slightly too soon:
This is the schedule function for Instant based schedules:
public void schedule(Job job, Instant eventAt) {
long sleepTime = Instant.now().until(eventAt, ChronoUnit.MILLIS);
schedule(job, sleepTime);
logger.debug("Scheduled {} in {}ms (at {})", job, sleepTime, eventAt);
}
The until() method says in its documentation that it returns the number of full “selected units” that exist between the two - in other words, the result is truncated. This could mean that it could be scheduled to run 1 millisecond too early, which could mean at the wrong second, minute, hour, day, month, year etc. if the point in time is just before “rollover”. We would want it “the other way”, where it was “ceiled” instead of “flored”, but that’s not an option in these implementations. The only rememdy I can see is to use microseconds instead, and then handle the “rounding” ourselves. But, that’s a bit pointless too, because the precision of the system timer might not be good enough. According to the JavaDocs, some OSes has a system timer with 10 milliseconds precision only. So, what do we do to make sure that it’s never too early? Add 10 milliseconds to everything? I just don’t know…
As I said: This is getting more and more interesting.
Would it make sense to check what changed between 5.0.x and 5.1.0 in that specific regard, and if anything? I fully agree that this all sounds like a more fundamental solution will make sense, and ideally sometime soon. But I have been using those rules that are - as it now turned out - so sensitive to early triggering since 2.x, before the trouble started with 5.1.0. Therefore, I dare to say that if the schedule() method looked the same in 5.0.x, then this specific cause of potentially early triggers was at least not something that (often) caused problems in practice.
Again: yes, should be solved. But apparently there are more pressing reasons for too early triggers, since this one is about <1ms.
You are focused on your exact use case, I’m focused on not having to revisit it
I think I have a good idea of what changed in the Astro binding, I think I did most of it, and none of it was supposed to really “change” anything except for bugs. Fundamentally, it was about proper handling of locale and time zones. There was also an “upgrade” to the null handling, and other minor issues. Nothing that should affect this - but that doesn’t always mean that it doesn’t. There can be some subtle consequence that has led to a change.
Another possibility is that 5.1 is just quicker, so the chance of this manifesting has increased. There has been done various things with threads and thread pools that could affect that. I’m not leaving heavily into this possibility, but it is there.
But, as I try to track down the details of the scheduling, I’m pretty sure that I will stumble over the cause of this “seconds alignment” eventually.
The problem with running 1ms too early is that it still fails “equals or later” tests, and it still fails “rollover tests”, e.g. for 19:59.999, hour is < 20.
I am totally with you. I am just saying that I don’t think this is the biggest bug in the collection.
The previous versions were not slow enough to “compensate” for (up to) a full second early.
Yes. As I said: should be fixed. I and understand the difficulty of finding a solution that doesn’t come at significant risks to break other things, or of simply being ugly. Like adding 10ms and hoping that this will always be enough also on any future system.
I think I found it. In adjustRangeToConfig(), we have:
return new Range(truncateToSecond(applyConfig(start, config)), truncateToSecond(applyConfig(end, config)));
There was a reason for this, which I cannot remember at this time of course. I’ll have to try to figure out which bug was solved by doing this, and then how to not reintroduce that bug while getting rid of the truncation.
It’s easy to see why it is in the past when the events are generated, but it shouldn’t be scheduled. I’ve yet to figure out why it seems to be scheduled despite this.
I’ve looked at this now. They both end, but there is no event for the end of eveningNight and the start of morningNight, because events are only scheduled for the current day, and only for events that haven’t already passed. The end of eveningNight is excluded because it falls to the next date, the start of morningNight is never scheduled because the time has passed when the scheduling occurs. The end of the night should be there, but it will be the event for the “previous night”.
edit: I’ve researched further, and the truncation to seconds wasn’t done by me (so I was thinking of something else that was done to fix a bug where things could end up in the wrong date). It was done here:
..and there’s not really any explanation. The reason this has started happening now must be more complicated, something else that lead to a delay that’s no longer there. I’m pretty confident that it is this truncation that leads the events to be scheduled too soon, and the code has been like that since 2021 - so something else must have “compensated”/delayed it.
When it comes to the night#end event, I just realized that it’s missing and why: If you look at the channels in the binding, under “Night”, you will see that it’s always “next night”. The things are registered as “ranges”, so it’s impossible for the end to be before the start. Thus, the “previous night” isn’t in the picture, and that’s where the “night end” would have to come from.
When events are scheduled, only those that fall within the same date is included - so the “night end” is excluded because it belongs to the next date. So, there is no “night end” event. Some holes in the logic yes, but that’s how it is.
When it comes to the negative scheduling for the one event that had passed, I was sure that there was code that ignored events in the past - but I just can’t find it. If in fact it doesn’t exist, I think the rationale must be something like this: If you schedule something with a negative delay, it will be interpreted as zero, and thus the event will fire right away. Normally, when the job runs 30 seconds past midnight, the only events that would be in the past must have happened in those 30 seconds. Thus, it’s “better” that the event runs there and then, 30 seconds to late, than not run at all. But, this also means that if you restart OH later, all the past events will fire during startup. I’m still not 100% sure that the “past cutoff code” doesn’t exist, but I don’t understand why I can’t find it. It could also allow “some slack”, let’s say 5 minutes back in time or so.
A suggestion: If it’s the plan to have certain trigger channels send only END (or only START), then it will at least make sense to mention that in the channel description (in the GUI channel description text and in the docs). By now I understand where it’s coming from, but as a user I would never have expected that behavior - especially not for the one single point in time in the whole of Astro that’s by far easiest to compute, namely midnight. IMHO, this needs a big red warning sign that events at or very shortly after midnight will not trigger.
Don’t get me wrong, but that sounds like an excellent way to cause erratic, inconsistent (aka race condition) behavior in the future. Then rather make morningNight/START not trigger at all, which will at least be consistent with the never-ending eveningNight. Users who intend to use it will soon notice that it doesn’t work, also without reading the docs - but only if it consistently doesn’t work. They will then likely use a “Time is midnight” trigger instead (which is also more accurate than +30s or “+up-to-5min or maybe not at all”). If it works most of the time, but (sometimes) fires to late, or (possibly sometimes) not at all, then this will be a cause of frustration.
I agree that ideally there should be no “event hole”, and if there has to be, it should be documented. I also agree that the “night” behavior is unintuitive and that something better should be figured out. But, this isn’t the right place to address that, this is a forum thread trying to figure out a problem.
You should create a new issue with your suggestions, I’m very much on-board, it’s just that I can’t just start redesigning this from here. I’d just have to create an issue and discuss it “on your behalf”, so it’s better if you do it. If you do create an issue, please tag me (my github username is the same as here) and I’ll take part in the discussion.
I think it’s you that got me wrong: I was trying to explain what might have happened, not suggest a modification of the logic. I finally tracked down where the “filtering” of events take place:
So, events that either aren’t of the same date, or that isn’t of “greater or equal” time, are silently dropped. As I thought I remembered. That means that I simply cannot explain how you got one event scheduled in the past - it shouldn’t be possible.
But I assume that night ends at the start of sunrise, because night starts after sunset. And since morningNight starts at midnight, eveningNight will very likely be expected to end at midnight (and I suppose the DateTime channels will say exactly that, without having verified it). An average user would certainly expect trigger events at these times.
