Cron triggered rules are executed twice

Tags: #<Tag:0x00007fc3ed367ca8> #<Tag:0x00007fc3ed367b40>

I think you should raise a Github issue for this, as it is repeatable. Need some expert advice on how/what to trace.

I would open an issue, but I am still not sure in which repository. The bug occurs only with Jython rules, but after a quick lock in the Jython library sources I am quite sure, that it is not in these sources.

Any advice would be appreciated!

It would be an issue for openhab-core, but if you’ll wait, I’ll take a look. I have not been able to reproduce this. I am wrapping up some major releases and should be done by this weekend.

1 Like

Thanks for your effort! If you need further details please let me know, especially because not all of my cron triggers are showing this behavior.

As a workaround I have written a small function, that checks the time since the rule was triggered last, so that is nor very pressing for me.

Thanks Scott for all you contribute!

1 Like

DSL uses quartz, jython uses new rule engine Cron trigger. Based on your examples it looks like the step part in the Cron expression could have a problem. Because all the ones with the step have the problem, the other not. I did some tests and from that it looks the calculation of the Cron expression is correct. Also for the steps. This seems also logical given the behavior. Because how it works is. When a Cron task is finished the next iteration is scheduled. It does this by calculating in how many seconds to schedule the next call. For some reason either this calculation goes wrong and it’s scheduled to early or the scheduler itself does something wrong. So because of this the task is run to earlier. But then it calculates the next task and that will be the time it should have actually run. Which results in the task run twice. The core schedule part doesn’t contain much logging options, so this doesn’t give us any options there. It could be the number of threads available for the scheduler is to low in this case. But this is just a wild guess. So one option might be to increase the number of threads. I don’t know out of my head where to configure this, but it might be worth a try. I’ll also will have a second look at the scheduler code itself, to see if I can find anything suspicious.

1 Like

Is there a possibility that your system clock is being updated? What hardware are you using?

I am using a PC Engines APU4 Board with the AMD GX-412TC CPU and Debian 10, with all updates installed. The system has been rebootet several times after I first noticed the bug

The system time is synced via a ntp server. I thought about that, but it seems very unlikly, that this causes the same step of several seconds every day at the same time.

The error occured after updating from 2.4 release to 2.5M2, bevore that it never occured.

I moved my code over to Jython and have this problem as well. I have rules set to run once a day at midnight, once a week on Monday at midnight, and once a month on the first at midnight.

They are all triggering roughly 15 to 30 seconds before midnight and then triggering again at midnight.

I have created a script to ignore the first one if it is not more than 12 hours away from midnight, and this has allowed me to use the correct one. But it is very odd that this is needed when it was not before I moved away from DSL to Jython.

from datetime import datetime

def MillisecondsUntilMidnight():
    n = datetime.now()
    return 86400000 - ((n.hour * 3600000) + (n.minute * 60000) + (n.second * 1000) + (n.microsecond / 1000))

@rule("Daily Cron")
@when("Time cron 0 0 0 ? * * *")
def DailyCron(event):
    if MillisecondsUntilMidnight() < 43200000: return
    # do something here

I am running it on a QNAP TS-251+ with 8GB RAM:

I am using openhab 2.4.

I very much like coding in Jython though. It is so very much better than coding in Xtend.

That does seem to be another confirmation that something is up with NGRE scheduler.

It might be helpful if you can narrow down more precisely the range of the “earliness” trigger. @juelicher is getting a fairly consistent 5 seconds - if you get something of a different order, it could be a clue.

From what @hilbrand says, the new scheduler is completely different, which I did not realize.

I have been logging the times when they execute, so that shouldn’t be an issue for me to get the times. The earliness does not seem to be consistent for me though. Although I suspect the longer interval schedules may trigger earlier then those with smaller intervals. But I’ll have to look at them again to be sure.

When I get around to it, I’ll post the times that they have been triggering.

Here are the numbers that I have gathered so far.

Daily: Time cron 0 0 0 ? * * *
2019-09-29 23:59:43.547
2019-09-30 00:00:00.017
2019-09-30 23:59:24.621
2019-10-01 00:00:00.014
2019-10-01 23:59:43.731
2019-10-02 00:00:00.011
2019-10-02 23:59:24.621
2019-10-03 00:00:00.109

Weekly: Time cron 0 0 0 ? * MON *
2019-09-29 23:59:43.551
2019-09-30 00:00:00.015

Monthly: Time cron 0 0 0 1 * ?
2019-09-30 23:59:08.145
2019-10-01 00:00:00.020

That is 16, 35, 16 and 16 seconds early for daily, 16 seconds early for weekly, and over 51 seconds early for monthly. The time stamps I am taking look like they are accurate within 200 milliseconds.

It never seems to not run early, at least with the three triggers I have set up.

1 Like

I’d recommend opening a github issue, you’ve got clear data and it seems repeatable.

1 Like