Scheduled tasks seem to run twice [SPR-6859]

[spring-projects-issues]

Matt Young opened SPR-6859 and commented

I posted this on the forum, but with no response... I wondered if you all could look into it.

I was stubbing out some code that I'd like to run on a schedule, and just to test it, I have it running once every 60 seconds. I noticed that in my logging, the method seems to be executed twice. To make sure it wasn't a logging issue, I put a static int counter into the class and have it increment on each call. So I can confirm the method is actually being run twice.

I suspect that this is something like doing a context:component-scan twice-over and resulting in double execution, but can't seem to locate the problem. I thought I would check first if there were any pointers.

The class Code: /**

• Date: Feb 15, 2010

• Time: 10:54:36 AM */ @Component public class DataHarvestingServiceImpl implements DataHarvestingService { private static final Logger logger = Logger.getLogger(DataHarvestingServiceImpl.class);

  private static int count = 0;

  @Override // Every night at 1 AM // @Scheduled(cron = " 1 ?")

  @Scheduled(cron = "0 ?") public void collectSocialMediaData() { logger.info("Starting data retrieval at " + new Date(System.currentTimeMillis()));

  logger.info("Finished media data retrieval at " + new Date(System.currentTimeMillis())); System.out.println("count is " + count++);

  }

} The configuration

Code:

\<?xml version="1.0" encoding="UTF-8"?>

\<beans xmlns="http://www.springframework.org/schema/beans" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:task="http://www.springframework.org/schema/task" xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd http://www.springframework.org/schema/task http://www.springframework.org/schema/task/spring-task-3.0.xsd">

<!--  This is the bit of configuration that allows spring to search for annotations
      that indicate that particular methods should be run at particular times.  -->

<task:scheduler id="searchScheduler"/>

<task:executor id="searchExecutor" pool-size="1"/>

<task:annotation-driven executor="searchExecutor" scheduler="searchScheduler"/>

\ The output I see: Code: 11316 [searchScheduler-1] INFO com.vodori.cms.feature.socialMedia.service.impl.DataHarvestingServiceImpl - Starting data retrieval at Mon Feb 15 14:56:00 CST 2010 11321 [searchScheduler-1] INFO com.vodori.cms.feature.socialMedia.service.impl.DataHarvestingServiceImpl - Finished media data retrieval at Mon Feb 15 14:56:00 CST 2010 count is 0 11321 [searchScheduler-1] INFO com.vodori.cms.feature.socialMedia.service.impl.DataHarvestingServiceImpl - Starting data retrieval at Mon Feb 15 14:56:00 CST 2010 11321 [searchScheduler-1] INFO com.vodori.cms.feature.socialMedia.service.impl.DataHarvestingServiceImpl - Finished media data retrieval at Mon Feb 15 14:56:00 CST 2010 count is 1 71318 [searchScheduler-1] INFO xxx.service.impl.DataHarvestingServiceImpl - Starting data retrieval at Mon Feb 15 14:57:00 CST 2010 71318 [searchScheduler-1] INFO xxx.service.impl.DataHarvestingServiceImpl - Finished media data retrieval at Mon Feb 15 14:57:00 CST 2010 count is 2 71318 [searchScheduler-1] INFO xxx.service.impl.DataHarvestingServiceImpl - Starting data retrieval at Mon Feb 15 14:57:00 CST 2010 71318 [searchScheduler-1] INFO xxx.service.impl.DataHarvestingServiceImpl - Finished media data retrieval at Mon Feb 15 14:57:00 CST 2010 count is 3 Any insight very much appreciated.

---

Affects: 3.0 GA

Reference URL: http://forum.springsource.org/showthread.php?t=84747

Issue Links:

• 11322 ScheduledAnnotationBeanPostProcessor registers schedules twice in web application ("duplicates")

• 14094 CronSequenceGenerator fails to accurately compute earliest next date when using second expression

• 11669 CronTrigger is not triggered at correct time

5 votes, 21 watchers

[spring-projects-issues]

Daniel Hodan commented

Hello,

I have still same problem with 3.0.1.RELEASE using @Scheduled annotation.

The workaround for now is to avoid annotation and use XML-based configuration with declaration of scheduled method which works correctly - runs method only once.

[spring-projects-issues]

Rafis Ismagilov commented

The problem still occurs in 3.0.1 for short-running tasks. No annotations, only XML.

<task:scheduler id="scheduler" pool-size="1"/>

<task:scheduled-tasks scheduler="scheduler">
    <task:scheduled ref="DateFilterFactory" method="updateDateFilters" cron="0 * * * * ?"/>
</task:scheduled-tasks>

Sometimes task starts a little earlier than a next scheduled time (at 14:31:00,000):

2010-06-02 14:30:59,998 [scheduler-1] DEBUG com.agi.apollo.search.filter.DateFilterFactory  - start
2010-06-02 14:30:59,999 [scheduler-1] DEBUG com.agi.apollo.search.filter.DateFilterFactory  - finish

The task is finished earlier than the scheduled time, and it rescheduled again at the same time according to code in CronTrigger.nextExecutionTime(TriggerContext triggerContext):

2010-06-02 14:31:00,001 [scheduler-1] DEBUG com.agi.apollo.search.filter.DateFilterFactory  - start
2010-06-02 14:31:00,002 [scheduler-1] DEBUG com.agi.apollo.search.filter.DateFilterFactory  - finish

It seems the source of the problem is accuracy of method System.currentTimeMillis() used in ReschedulingRunnable.schedule() and in java.util.Date default constructor.

I executed the following code on my Windows Vista x64:

for (int i = 0; i < 10000; i++) {
     System.out.println(System.currentTimeMillis());
}

and received the output:

1275478646948
...
1275478646948
1275478646964
...
1275478646964
1275478646979
...
1275478646979
...
1275478646979
1275478646995
...
1275478646995
1275478647010
...
1275478647010
1275478647026
...

Time was updated in 5-16 milliseconds.

I suggest to use in CronTrigger.nextExecutionTime(TriggerContext triggerContext) the latest of TriggerContext.lastCompletionTime() and TriggerContext.lastCompletionTime(). It helps to avoid double execution at the same time.

[spring-projects-issues]

Juergen Hoeller commented

See #11669: Fortunately, this should be fixed in the latest 3.0.3 snapshots already.

Juergen

[spring-projects-issues]

Rafis Ismagilov commented

Cool! Thanks.

[spring-projects-issues]

Paul Zolnierczyk commented

So I'm experiencing this issue on 3.0.5 . I have a task that is scheduled to run every ten minutes (I'm still in development). All it does is query the database for users that meet a specific criteria and then I send them an e-mail reminder. All I did to enable this was add in my XML

<context:component-scan base-package="my base package is in here" />

<task:annotation-driven/>

and then I annotated like this:

@Scheduled(fixedDelay = 1000 * 60 * 10)

I'm also on JDK 1.6 and developing on windows XP. For some reason I wonder if it's a dual core issue?

[spring-projects-issues]

Paul Zolnierczyk commented

Silly me, I was loading the application context twice!

[spring-projects-issues]

Bahman Kalali commented

I am experiencing the same the same problem where the methods that are scheduled to run every 2 and 1 minutes respectively are invoked twice at specified fixed rate.

Here is the xml fragment of my spring app context ( the XML app context is called edgeServerContext.xml)

<task:scheduled-tasks>
    <task:scheduled ref="IEdgeDeviceStatePollerService"
        method="process" fixed-rate="120000" />
    <task:scheduled ref="IEdgeDeviceResultsPollerService"
        method="process" fixed-rate="60000" />
</task:scheduled-tasks>

The only difference with my issue and the rest of other commentators is that my spring xml context is imported into mule-config.xml as follows:

\<?xml version="1.0" encoding="UTF-8"?>

<mule xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="http://www.mulesoft.org/schema/mule/core" xmlns:spring="http://www.springframework.org/schema/beans" xmlns:context="http://www.springframework.org/schema/context"

xsi:schemaLocation="
http://www.springframework.org/schema/context
      http://www.springframework.org/schema/context/spring-context-3.0.xsd
        http://www.mulesoft.org/schema/mule/core http://www.mulesoft.org/schema/mule/core/3.1/mule.xsd
        http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-3.0.xsd">

<spring:beans>
    <spring:import resource="classpath:edgeServerContext.xml" />
</spring:beans>

\

I am not sure this issue is related to mule or spring. It seems that schedulers are initialized twice when deployed two a mule server. I am using mule 3.1.2, spring 3.0.6.RELEASE, jdk1.6.0_25

I appreciated it any insight on this issue...

BR//Bahman

[spring-projects-issues]

Sidharth Kaushik commented

I am using Spring 3.0.5. Trying to schedule a simple job @Service public class HelloWorldScheduler2 { public void process() { System.out.println("################processing next########## at " + new Date()+ " SidddThe Milli time is : " + System.currentTimeMillis()); } } For Scheduling this the XML I am using is:

\<?xml version="1.0" encoding="UTF-8"?>

\<beans xmlns="http://www.springframework.org/schema/beans" xmlns:context="http://www.springframework.org/schema/context" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:util="http://www.springframework.org/schema/util" xmlns:task="http://www.springframework.org/schema/task" xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-3.0.xsd http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.0.xsd http://www.springframework.org/schema/util http://www.springframework.org/schema/util/spring-util-3.0.xsd http://www.springframework.org/schema/task http://www.springframework.org/schema/task/spring-task-3.0.xsd">

<context:spring-configured />

<context:annotation-config/>

<bean id="scheduler" class="com.mystudyweb.schedulers.HelloWorldScheduler2" />
<task:scheduled-tasks>
    <task:scheduled ref="scheduler" method="process" cron="${cron}"/>
</task:scheduled-tasks>

\

The cron expression is read from properties file as : 3/10 ?

On running the application on TOMCAT, the output in console is ################processing next########## at Tue Dec 13 13:10:43 IST 2011 SidddThe Milli time is : 1323762043001 ################processing next########## at Tue Dec 13 13:10:43 IST 2011 SidddThe Milli time is : 1323762043001

How can I stop the job from being called twice. When I run it as a simple standalone application, it works fine. Also, my context xml is being loaded correctly and only once.

Regards, Sidharth.

[spring-projects-issues]

Hoshiar Ravesh commented

Hi,

I am having the same problem that scheduled task is being executed twice with Spring 3.1.1 Release using both the XML configurations and Annotations.

My Dispatcher-servlet.xml:

\<?xml version="1.0" encoding="UTF-8"?>

\<beans xmlns="http://www.springframework.org/schema/beans" xmlns:context="http://www.springframework.org/schema/context" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:mvc="http://www.springframework.org/schema/mvc" xmlns:task="http://www.springframework.org/schema/task" xsi:schemaLocation=" http://www.springframework.org/schema/beans
http://www.springframework.org/schema/beans/spring-beans-3.0.xsd http://www.springframework.org/schema/mvc http://www.springframework.org/schema/mvc/spring-mvc-3.0.xsd http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.0.xsd http://www.springframework.org/schema/task
http://www.springframework.org/schema/task/spring-task-3.0.xsd">

<task:executor id="myExecutor" pool-size="1"/>      
<task:scheduler id="myScheduler" pool-size="1"/>

<task:scheduled-tasks scheduler="myScheduler">
    <task:scheduled ref="DateFilterFactory" method="sendEmail" cron="0 54 11 * * ?"/>
</task:scheduled-tasks>

<bean id="DateFilterFactory" class="com.MailService"/>

\

[spring-projects-issues]

Hoshiar Ravesh commented

The issue is still reproducing in 3.1.1 Release

[spring-projects-issues]

Paul Boonyarungsrit commented

I had this issue and found a solution for it. In my case, one of my applicationContext*.xml that I have was loaded by both root application context (contextConfigLocation in web.xml) and by web application context (via DispatcherServlet). Putting in the config that is loaded by both contexts causes 2 scheduler threads to be created, one for each context.

Making sure that is loaded by the root application context only fixes my issue. It would be nice if Spring can detect that, but at least you can avoid this issue yourself.

[spring-projects-issues]

suresh m commented

This issue is coming in Spring 3.1.0 RELEASE, any workaround

[spring-projects-issues]

Juergen Hoeller commented

As of 3.2.2, we've done everything we can do to avoid a repeat of the current execution time as next scheduled time: CronTrigger uses the later of lastCompletionTime and lastScheduledExecutionTime to calculate from, and CronSequenceGenerator explicitly recalculates from the next second if it ends up computing the same time as the original timestamp.

In other words, if you're still running into double execution with only one scheduler set up (please always double-check that), then we have no idea how that could happen. I'll mark this issue as resolved for that reason. If you happen to be able to reproduce this under proper circumstances against 3.2.2, please create a more specific issue as a follow-up.

Juergen

[spring-projects-issues]

Assaf commented

I have just tried this on 3.2.2 and it still does not work. My configuration is as follows:

\

and the class: @Service public class RankingEngine {

.....

@Scheduled(cron="0 10 18 *") public void calculateRankings(){

The method is being called twice

[spring-projects-issues]

James Hunvanich commented

I also have 3.2.2, and this is still a problem.

Similar configs as users above. I tripled-check to make sure context was not being loaded more than once.

Trying to use java.util.Timer also gets run twice if initiated from @PostConstruct:

... @PostConstruct public void init() { log.trace("Initializing"); //This is verified to be called only once.

Timer timer = new Timer(); timer.schedule(new TimerTask() { @Override public void run() { log.trace("Timer task running..."); } }, 60 1000, 60 1000); } ...

Result: 03-21 14:37:55,249 INFO [ Timer-0] Timer task running... 03-21 14:38:02,414 INFO [ Timer-1] Timer task running...

[spring-projects-issues]

Assaf commented

I retract my issue. Apparently, spring was loading my configuration twice and hence the code being triggered twice. Thanks guys for helping!

Assaf

[spring-projects-issues]

Kirill Kadyrko commented

Confirm the issue still exists. I'm sure my application context is loaded only once. Another interesting thing is that the task is not always executed twice, still, I don't understand the pattern. I have no issues when running the app on Tomcat from within Eclipse. But it's exposed after deploying the app to GlassFish.

[spring-projects-issues]

Kirill Kadyrko commented

Well, I'm taking my words back. Seems the new jar wasn't in the repository when I did the check. So far so good with 3.2.2 :) Thanks!

[spring-projects-issues]

Hasnain Javed commented

Hi All,

I ran into the same problem even after upgrading to Spring 3.2.2 and was able to solve the problem by removing the \ element inside the \ element in tomcat's server.xml file (I'm running tomcat 7)

Snippet: \

\ \

I guess the IDE (STS in my case) modified the server.xml file while configuring tomcat within it. If that is not the case, manually remove or comment the \ tag and hopefully it should work fine. The reason was that the application was deployed twice by tomcat.

Hope this helps.

Kind Regards.

[spring-projects-issues]

Juergen Hoeller commented

To the best of our knowledge, this is caused by accidental duplicate deployment of your application - in one form or the other. The comments above seem to confirm this. You might otherwise not notice that your app is being deployed twice since only one of those instances will actually serve requests...

Juergen

[spring-projects-issues]

Salano commented

The job context is loaded twice. I am not sure what's causing this. I do see app deployed once only. This is still an issue with 3.2.2 release. Any help

[spring-projects-issues]

Salano commented

App is deployed only once, but contexts are loaded twice. Not sure what's causing this

[spring-projects-issues]

Juergen Hoeller commented

This issue was just about double execution when the context was only loaded once. If your context is being loaded twice, it's not really a scheduling bug; you're rather initializing the context twice in some place - a different issue.

Juergen

[kaleeswaran35]

@spring-issuemaster : Hi, This problem still does exist job runs twice. spring-batch-demo.tar.gz Any idea or suggestion is highly appreciated

2020-11-16 17:00:12.150 INFO 7754 --- [ main] com.concretepage.Main : Starting Main on kalees-desktop with PID 7754 (/home/kalees/Downloads/spring-batch-demo/target/classes started by kalees in /home/kalees/Downloads/spring-batch-demo) 2020-11-16 17:00:12.155 INFO 7754 --- [ main] com.concretepage.Main : No active profile set, falling back to default profiles: default 2020-11-16 17:00:13.427 INFO 7754 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting... 2020-11-16 17:00:13.571 INFO 7754 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed. 2020-11-16 17:00:13.586 INFO 7754 --- [ main] o.s.b.c.r.s.JobRepositoryFactoryBean : No database type set, using meta data indicating: H2 2020-11-16 17:00:13.803 INFO 7754 --- [ main] o.s.b.c.l.support.SimpleJobLauncher : No TaskExecutor has been set, defaulting to synchronous executor. 2020-11-16 17:00:14.028 INFO 7754 --- [ main] com.concretepage.Main : Started Main in 2.284 seconds (JVM running for 2.601) 2020-11-16 17:00:14.030 INFO 7754 --- [ main] o.s.b.a.b.JobLauncherCommandLineRunner : Running default command line with: [] 2020-11-16 17:00:14.173 INFO 7754 --- [ main] o.s.b.c.l.support.SimpleJobLauncher : Job: [SimpleJob: [name=createEmployeeJob]] launched with the following parameters: [{jobId=1605099316695, run.id=221}] Executing job id 473 2020-11-16 17:00:14.193 INFO 7754 --- [ main] o.s.batch.core.job.SimpleStepHandler : Executing step: [step1] Emp Code: 111, Emp Name: Mahesh, Profile Name:Developer Emp Code: 112, Emp Name: Krishna, Profile Name:Team Lead Emp Code: 113, Emp Name: Rama, Profile Name:Manager Emp Code: 114, Emp Name: Shiva, Profile Name:Developer Number of Records:20 2020-11-16 17:00:14.283 INFO 7754 --- [ main] o.s.b.c.l.support.SimpleJobLauncher : Job: [SimpleJob: [name=createEmployeeJob]] completed with the following parameters: [{jobId=1605099316695, run.id=221}] and the following status: [COMPLETED] 2020-11-16 17:00:14.303 INFO 7754 --- [ main] o.s.b.c.l.support.SimpleJobLauncher : Job: [FlowJob: [name=UpdateEmployeeJob]] launched with the following parameters: [{run.id=192}] step job id update474 2020-11-16 17:00:14.318 INFO 7754 --- [ main] o.s.batch.core.job.SimpleStepHandler : Executing step: [step2] Inside Update Item processor 5updated 5updated 2020-11-16 17:00:14.344 INFO 7754 --- [ main] o.s.b.c.l.support.SimpleJobLauncher : Job: [FlowJob: [name=UpdateEmployeeJob]] completed with the following parameters: [{run.id=192}] and the following status: [COMPLETED] 2020-11-16 17:00:14.349 INFO 7754 --- [ Thread-2] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown initiated... 2020-11-16 17:00:14.356 INFO 7754 --- [ Thread-2] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown completed.