Cron Scheduler: Job seems to be executed to early

[maggu2810]

It seems that a cron expression that for daily midnight ("0 0 0 * * ? *") could lead to an job execution on the "day before".

See comments here: #4131

IMHO the common behavior of a scheduled job is to be executed on the expected time or a little bit later, but not sooner.
That a cron job that should be executed on midnight has to add a delay just to be sure to be executed on the correct day seems to be wrong to me.

[kgoderis]

@maggu2810 I do agree that delaying the execution with an arbitrary amount of time is not ok. I was not able to reproduce the problem. Here is the test setup:

        CronExpression c = new CronExpression("0 4 20 * * ? *");
        Date now = new Date(2017 - 1900, 8, 07, 23, 59, 50);

        Runnable dummy = new Runnable() {

            @Override
            public void run() {
                System.out.println("Run. Forrest, Run!");
            }
        };

        ExpressionThreadPoolExecutor etpm = ExpressionThreadPoolManager.getExpressionScheduledPool("test");
        etpm.schedule(dummy, c);

I chose 20:04:00 instead of midnight because that about 1 minute in the future right now, but I the outcomes should be the same. This is the output I get

2017-09-07 20:03:26.569 [TRACE] [r$ExpressionThreadPoolExecutor:187 ] - Expression's '0 4 20 * * ? *' next execution time is 2017-09-07T20:04:00.000+0200
2017-09-07 20:03:26.569 [DEBUG] [r$ExpressionThreadPoolExecutor:223 ] - Scheduling the task 'org.eclipse.smarthome.core.scheduler.RunnableWrapper@563a4d4c' to execute in 33474 ms
2017-09-07 20:03:26.572 [TRACE] [r$ExpressionThreadPoolExecutor:227 ] - Task 'org.eclipse.smarthome.core.scheduler.RunnableWrapper@563a4d4c' has now 1 Futures
2017-09-07 20:03:26.573 [TRACE] [r$ExpressionThreadPoolExecutor:232 ] - Task org.eclipse.smarthome.core.scheduler.RunnableWrapper@563a4d4c (1461011708) will run in 33470 ms
2017-09-07 20:03:26.573 [TRACE] [r$ExpressionThreadPoolExecutor:267 ] - Putting the monitor thread 'ESH-test-Monitor-1' to sleep for 33427 ms
...
2017-09-07 20:04:00.001 [TRACE] [r$ExpressionThreadPoolExecutor:275 ] - Monitor thread woke again with false
2017-09-07 20:04:00.002 [TRACE] [r$ExpressionThreadPoolExecutor:177 ] - There are 1 scheduled expressions
2017-09-07 20:04:00.002 [TRACE] [r$ExpressionThreadPoolExecutor:179 ] - Runnable org.eclipse.smarthome.core.scheduler.RunnableWrapper@563a4d4c with org.eclipse.smarthome.core.scheduler.RunnableWrapper@563a4d4c
...
2017-09-07 20:04:00.021 [TRACE] [r$ExpressionThreadPoolExecutor:187 ] - Expression's '0 4 20 * * ? *' next execution time is 2017-09-08T20:04:00.000+0200
2017-09-07 20:04:00.021 [DEBUG] [r$ExpressionThreadPoolExecutor:223 ] - Scheduling the task 'org.eclipse.smarthome.core.scheduler.RunnableWrapper@563a4d4c' to execute in 86399998 ms
2017-09-07 20:04:00.021 [TRACE] [r$ExpressionThreadPoolExecutor:227 ] - Task 'org.eclipse.smarthome.core.scheduler.RunnableWrapper@563a4d4c' has now 2 Futures
2017-09-07 20:04:00.022 [TRACE] [r$ExpressionThreadPoolExecutor:232 ] - Task org.eclipse.smarthome.core.scheduler.RunnableWrapper@563a4d4c (1461011708) will run in 22 ms
2017-09-07 20:04:00.022 [TRACE] [r$ExpressionThreadPoolExecutor:232 ] - Task org.eclipse.smarthome.core.scheduler.RunnableWrapper@563a4d4c (1461011708) will run in 86399997 ms
2017-09-07 20:04:00.022 [TRACE] [r$ExpressionThreadPoolExecutor:267 ] - Putting the monitor thread 'ESH-test-Monitor-1' to sleep for 86399978 ms
Run. Forrest, Run!
2017-09-07 20:04:00.045 [TRACE] [r$ExpressionThreadPoolExecutor:111 ] - Cleaning up after the execution of 'java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@532aca41'

As you can see the monitor task woke up 1 ms after it is supposed to happen, and the scheduled task is finally executed 22 ms after the calculated cron expression. Those 22 ms seconds are partly spent by the CronExpression recalculating its next execution, and the ExpressionThreadPoolExecutor executing other code.

I am puzzled as how it could be that tasks execute before their scheduled execution. I can only explain that by something happening java.util.concurrent. wdyt?

[maggu2810]

@kgoderis I didn't analyze the cause myself. @triller-telekom reported that problem and explained me that this problem exists. Perhaps he can give more details what he analyzed.

[triller-telekom]

It didn't happen to me so I cannot reproduce it, also with an old version, but I saw the problem in the logoutput from @kaimahnke here. The scheduling happens slightly before midnight...

[kgoderis]

@maggu2810 cfr #4018 (comment), shall we close this issue then?

[maggu2810]

@kgoderis I don't think so. The root cause has not been found or fixed.
The workaround has been to change the cron expression from "0 0 0 * * ? *" to "30 0 0 * * ? *" to ensure that it is executed later in the timeline.
So, nothing has been changed to get "0 0 0 * * ? *" running.
Or do I miss something?

[kgoderis]

@maggu2810 You're right. Anyways, I am unable to reproduce this (outside of the Astro binding)

[Narasingha123]

@here Please send me a sample Scheduler in eclipse smarthome java file with below exression.
cronExpression c = new CronExpression("0 4 20 * * ? *");
Date now = new Date(2017 - 1900, 8, 07, 23, 59, 50);

Regards,
narasinghapattnayak@gmail.com