@On causes Job to run twice

[dirk]

There is a bug in the Jobs mechanism that causes jobs annotated with @On to sometimes run twice. This is causing emails in an application I have to be sent twice.

When the Job has finished running, the _finally method is invoked:
    @Override
    public void _finally() {
        super._finally();
        if (executor == JobsPlugin.executor) {
            JobsPlugin.scheduleForCRON(this);
        }
    }

This results in a call to scheduleForCRON(), which schedules the next invocation of the job by working out the difference in time between now and when it should next run using Time.parseCRONExpression(cron).

                    Date now = new Date();
                    cron = Expression.evaluate(cron, cron).toString();
                    Date nextDate = Time.parseCRONExpression(cron);
                    long delay = nextDate.getTime() - now.getTime();
                    executor.schedule((Callable<V>)job, delay, TimeUnit.MILLISECONDS);

A problem occurs if Time.parseCRONExpression returns a value that is a few milli-seconds less than it should be, or if the ScheduledThreadPoolExecutor runs the job slightly earlier than it should. Then when the job finishes, the job will be rescheduled for it's next invocation that is only a few milli-seconds later.

For example, the job is scheduled to run at 4:00am. ScheduledThreadPoolExecutor runs it at 3:00:59.543. When the job is complete, _finally() is called which in turn calls scheduleForCRON(), which works out the difference between now and 4:00am. If this happens fast enough, it is not yet 4:00 am, so the job is scheduled to run a few milli-seconds later, and runs again at 4:00:00.034

One solution would be to make sure that the variable delay is not less than one second:

    public static <V> void scheduleForCRON(Job<V> job) {
        if (job.getClass().isAnnotationPresent(On.class)) {
            String cron = job.getClass().getAnnotation(On.class).value();
            if (cron.startsWith("cron.")) {
                cron = Play.configuration.getProperty(cron);
            }
            if (cron != null && !cron.equals("")) {
                try {
                    cron = Expression.evaluate(cron, cron).toString();
                    Date nextDate = Time.parseCRONExpression(cron);
                    long delay = nextDate.getTime() - System.currentTimeMillis();
                    while(delay < 1000) {
                        Thread.sleep(delay);
                        delay = nextDate.getTime() - System.currentTimeMillis();
                    }
                    executor.schedule((Callable<V>)job, delay, TimeUnit.MILLISECONDS);
                    job.executor = executor;
                } catch (Exception ex) {
                    throw new UnexpectedException(ex);
                }
            } else {
                Logger.info("Skipping job %s, cron expression is not defined", job.getClass().getName());
            }
        }
    }

[dirk (australiandeveloper)]

An example of some logs from my server:
23:59:56,519 INFO ~ Sent rating emails from 7 days ago to 1 users.
23:59:56,519 INFO ~ Automatic sending of rating emails is enabled.
00:00:00,032 INFO ~ Sent rating emails from 7 days ago to 1 users.
00:00:00,032 INFO ~ Automatic sending of rating emails is enabled.

[dirk (australiandeveloper)]

Actually looking at the logs, it seems like the job is running a full 4 seconds early. So either the date calculation is a long way off or ScheduledThreadPoolExecutor is very inaccurate in my implementation of the JVM.

[Erwan Loisant (eloisant)]

which JVM are you using ?

[dirk (australiandeveloper)]

I think it's not that likely that this is a problem with the JVM otherwise
I'm sure it would have been fixed by now. My guess is that it's something to
do with the date calculation. But here are the details of my JVM and the box
that it's running on:

$ java -version
java version "1.6.0_12"
Java(TM) SE Runtime Environment (build 1.6.0_12-b04)
Java HotSpot(TM) Client VM (build 11.2-b01, mixed mode, sharing)

$ uname -a
Linux boludo 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 19:22:36 EST 2009
i686 GNU/Linux

$ cat /etc/debian_version
5.0.4

On Thu, Sep 9, 2010 at 10:12 AM, Erwan Loisant <email address hidden> wrote:

> which JVM are you using ?
>
> --
> @On causes Job to run twice
> https://bugs.launchpad.net/bugs/632427
> You received this bug notification because you are a direct subscriber
> of the bug.
>
> Status in play framework: New
>
> Bug description:
> There is a bug in the Jobs mechanism that causes jobs annotated with @On to
> sometimes run twice. This is causing emails in an application I have to be
> sent twice.
>
> When the Job has finished running, the _finally method is invoked:
> @Override
> public void _finally() {
> super._finally();
> if (executor == JobsPlugin.executor) {
> JobsPlugin.scheduleForCRON(this);
> }
> }
>
> This results in a call to scheduleForCRON(), which schedules the next
> invocation of the job by working out the difference in time between now and
> when it should next run using Time.parseCRONExpression(cron).
>
> Date now = new Date();
> cron = Expression.evaluate(cron, cron).toString();
> Date nextDate = Time.parseCRONExpression(cron);
> long delay = nextDate.getTime() - now.getTime();
> executor.schedule((Callable<V>)job, delay,
> TimeUnit.MILLISECONDS);
>
> A problem occurs if Time.parseCRONExpression returns a value that is a few
> milli-seconds less than it should be, or if the ScheduledThreadPoolExecutor
> runs the job slightly earlier than it should. Then when the job finishes,
> the job will be rescheduled for it's next invocation that is only a few
> milli-seconds later.
>
> For example, the job is scheduled to run at 4:00am.
> ScheduledThreadPoolExecutor runs it at 3:00:59.543. When the job is
> complete, _finally() is called which in turn calls scheduleForCRON(), which
> works out the difference between now and 4:00am. If this happens fast
> enough, it is not yet 4:00 am, so the job is scheduled to run a few
> milli-seconds later, and runs again at 4:00:00.034
>
> One solution would be to make sure that the variable delay is not less than
> one second:
>
> public static <V> void scheduleForCRON(Job<V> job) {
> if (job.getClass().isAnnotationPresent(On.class)) {
> String cron = job.getClass().getAnnotation(On.class).value();
> if (cron.startsWith("cron.")) {
> cron = Play.configuration.getProperty(cron);
> }
> if (cron != null && !cron.equals("")) {
> try {
> cron = Expression.evaluate(cron, cron).toString();
> Date nextDate = Time.parseCRON...

[dirk (australiandeveloper)]

These are the two cron expressions:
cron.ratingmailer.send = 0 0 0 * * ?
cron.sitemap.ping = 0 0 1 * * ?

Both of them are running 3 or 4 seconds early:
23:59:57,131 INFO ~ Sent rating emails from 7 days ago to 0 users.
00:00:00,011 INFO ~ Sent rating emails from 7 days ago to 0 users.
00:59:56,742 INFO ~ Pinging 3 sites with site map url
01:00:00,007 INFO ~ Pinging 3 sites with site map url

[Sébastien Crème (sebastien-creme)]

Seen the implementation and i think it's hardly because:
in your case, @On is calculate 24 hours before execution.
So it's scheduling for a pure 24 hours delay, but on a vitual machine, it's common that clocks drift and are synchronized with NTP or other mecanism.
So at the end of the day drift is 4 seconds but the delay of the scheduled does not take account of drift and execute the job with as reference the time it was when it calculate the duration.
Just after that, it's reshedule the job in 4 seconds for executing the job at the new Midnight.

In a few words, the actual implementation of job scheduling cannot deal with clock drift and we will consider using quartz scheduler if at least they can handle this kind of problems (and i think quartz can).

[dirk (australiandeveloper)]

I posted a message to the play group about quartz with some links that I
will also include here:
I've been reading about ScheduledThreadPoolExecutor and it seems like it's
not very accurate, especially for times further in the future and for
processes that run on virtual hosts (which is almost all VPS these days,
including amazon ec2):
http://stackoverflow.com/questions/2745839/scheduledthreadpoolexecutor-executing-a-wrong-time-because-of-cpu-time-discrepanc
http://www.velocityreviews.com/forums/t729513-scheduledexecutorservice-very-inaccurate.html

Instead, people seem to recommend using Quartz. I see that play.libs.Time
already includes some code form the Quartz library to parse the cron
expression:
http://bazaar.launchpad.net/~play-developers/play/1.1-unstable/annotate/head%3A/framework/src/play/libs/Time.java#L61<http://bazaar.launchpad.net/%7Eplay-developers/play/1.1-unstable/annotate/head%3A/framework/src/play/libs/Time.java#L61>

Why not just use the Quartz library to do the scheduling directly? It
includes a mechanism that will schedule based on a cron expression already:
http://www.quartz-scheduler.org/docs/cookbook/DailyTrigger.html

Trigger trigger = new CronTrigger("trigger1", "group1");
trigger.setCronExpression("0 0 15 * * ?");

2010/9/12 Sébastien Crème <email address hidden>

> Seen the implementation and i think it's hardly because:
> in your case, @On is calculate 24 hours before execution.
> So it's scheduling for a pure 24 hours delay, but on a vitual machine, it's
> common that clocks drift and are synchronized with NTP or other mecanism.
> So at the end of the day drift is 4 seconds but the delay of the scheduled
> does not take account of drift and execute the job with as reference the
> time it was when it calculate the duration.
> Just after that, it's reshedule the job in 4 seconds for executing the job
> at the new Midnight.
>
> In a few words, the actual implementation of job scheduling cannot deal
> with clock drift and we will consider using quartz scheduler if at least
> they can handle this kind of problems (and i think quartz can).
>
>
> ** Changed in: play
> Status: New => Confirmed
>
> --
> @On causes Job to run twice
> https://bugs.launchpad.net/bugs/632427
> You received this bug notification because you are a direct subscriber
> of the bug.
>
> Status in play framework: Confirmed
>
> Bug description:
> There is a bug in the Jobs mechanism that causes jobs annotated with @On to
> sometimes run twice. This is causing emails in an application I have to be
> sent twice.
>
> When the Job has finished running, the _finally method is invoked:
> @Override
> public void _finally() {
> super._finally();
> if (executor == JobsPlugin.executor) {
> JobsPlugin.scheduleForCRON(this);
> }
> }
>
> This results in a call to scheduleForCRON(), which schedules the next
> invocation of the job by working out the difference in time between now and
> when it should next run using Time.parseCRONExpression(cron).
>
> Date now = new Date();
> cron = Expression.evaluate(cron, cron).toString();
> Date nextDate = Time.parseC...