Quartz jobs scheduled twice

[davidkarlsen]

Hi - I'm expiriencing jobs getting executed twice by Quartz.

Environment: spring 2.0.2, quartz 1.6.0, websphere 6.1, using a WorkManager referenc eas thread-backing:


My context config:

<bean id="schedulerFactoryBean"
class="org.springframework.scheduling.quartz.Sched ulerFactoryBean">
<!-- TODO - use the common taskExecutor for now - a dedicated one later on -->
<property name="taskExecutor" ref="taskExecutor" />
<property name="triggers">
<list>
<bean
class="org.springframework.scheduling.quartz.CronT riggerBean">
<property name="jobDetail" ref="delayedMessagesJob" />
<!-- flush every whole hour -->
<property name="cronExpression" value="0 0 0-23 * * ?" />
</bean>
</list>
</property>
</bean>


I'd expect this to run once each hour, but the job is submitted twice (on two different threads):

2007-04-05 17:00:00,019 [WorkManager.DefaultWorkManager : 44] DEBUG org.quartz.core.JobRunShell - Calling execute on job DEFAULT.delayedMessagesJob (JobRunShell.java:201)
2007-04-05 17:00:00,022 [WorkManager.DefaultWorkManager : 46] DEBUG org.quartz.core.JobRunShell - Calling execute on job DEFAULT.delayedMessagesJob (JobRunShell.java:201)

[karldmoore]

There have a been a few posts in the past with people having a similar problem. Are there actually two instances of Spring running and thus two schedulers?

[davidkarlsen]

No - it's only this instance.

[karldmoore]

I'm not really sure what to suggest. You could print a stacktrace out in the log to see where the job is getting invoked from, maybe print out some of the scheduler details as well. Turn up the logging to ensure nothing strange is going on.

[Sara_Mitchell]

Possibly a threading issue as quoted from this developerWorks article->
http://www-128.ibm.com/developerwork...09_alcott.html

"Spring provides or integrates with a number of scheduling packages. The only Spring scheduling package that works with threads managed by WebSphere Application Server is the CommonJ WorkManager scheduling package. Other packages, such as quartz and the JDK Timer, start unmanaged threads and should be avoided."

[adam_jh]

I also have been experiencing my tasks executing twice - its been going on for some time but have only recently found out. Here's my environment and the logs.

spring: 2.0.3
quartz: 1.6.0

<bean name="jobDetail" class="org.springframework.scheduling.quartz.JobDetailBean">
	<property name="jobClass" value="com.service.threads.TaskJob"/>
	<property name="jobDataAsMap">
		<map>
			<entry key="taskService"><ref bean="taskServiceTarget"/></entry>
		</map>
	</property>
</bean>

<bean name="expiryJobDetail" class="org.springframework.scheduling.quartz.JobDetailBean">
	<property name="jobClass" value="com.service.threads.ExpiryJob"/>
	<property name="jobDataAsMap">
		<map>
			<entry key="userService"><ref bean="userService"/></entry>
			<entry key="contactService"><ref bean="contactService"/></entry>
		</map>
	</property>
</bean>

<bean id="cronTrigger" class="org.springframework.scheduling.quartz.CronTriggerBean">
	<property name="jobDetail" ref="jobDetail"/>
	<property name="cronExpression" value="0 0/5 * * * ?"/>
</bean>

<bean id="expiryCronTrigger" class="org.springframework.scheduling.quartz.CronTriggerBean">
	<property name="jobDetail" ref="expiryJobDetail"/>
	<property name="cronExpression" value="0 0 11 * * ?"/>
</bean>

<bean class="org.springframework.scheduling.quartz.SchedulerFactoryBean">
	<property name="configLocation">
		<value>/WEB-INF/quartz.properties</value>
	</property>
	<property name="triggers">
		<list>
			<ref bean="cronTrigger"/>
			<ref bean="expiryCronTrigger"/>
		</list>
	</property>
</bean>

quartz.properties

org.quartz.threadPool.class=org.quartz.simpl.SimpleThreadPool
org.quartz.threadPool.ThreadCount=1
org.quartz.threadPool.threadPriority=4

org.quartz.plugin.triggHistory.class = org.quartz.plugins.history.LoggingTriggerHistoryPlugin
org.quartz.plugin.triggHistory.triggerFiredMessage = Trigger {1}.{0} fired job {6}.{5} at: {4, date, HH:mm:ss dd/MMM/yyyy}
org.quartz.plugin.triggHistory.triggerCompleteMessage = Trigger {1}.{0} completed firing job {6}.{5} at {4, date, HH:mm:ss dd/MMM/yyyy} with resulting trigger instruction code: {9}

and the logs...

2007-04-23 14:50:00,012 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger fired job DEFAULT.jobDetail at:  14:50:00 23/Apr/2007
2007-04-23 14:50:00,016 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger fired job DEFAULT.jobDetail at:  14:50:00 23/Apr/2007
2007-04-23 14:50:00,024 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger completed firing job DEFAULT.jobDetail at  14:50:00 23/Apr/2007 with resulting trigger instruction code: DO NOTHING
2007-04-23 14:50:00,068 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger completed firing job DEFAULT.jobDetail at  14:50:00 23/Apr/2007 with resulting trigger instruction code: DO NOTHING
2007-04-23 14:55:00,014 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger fired job DEFAULT.jobDetail at:  14:55:00 23/Apr/2007
2007-04-23 14:55:00,018 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger fired job DEFAULT.jobDetail at:  14:55:00 23/Apr/2007
2007-04-23 14:55:00,028 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger completed firing job DEFAULT.jobDetail at  14:55:00 23/Apr/2007 with resulting trigger instruction code: DO NOTHING
2007-04-23 14:55:00,076 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger completed firing job DEFAULT.jobDetail at  14:55:00 23/Apr/2007 with resulting trigger instruction code: DO NOTHING

As you can see at each 5 minute intervals 2 jobs are fired. Although the logs don't show it - the other job (ExpiryJob) also repeats when its due - 11am.

Can anyone suggest a starting point to unravel this?

Regards,
adam

[karldmoore]

There are a few things common to this problem. The first is, is the job actually executing twice or are you simply seeing two log messages? The second is are you somehow starting two schedulers. A common theme here is simply randomly creating new ApplicationContext's within the application. If not either of these, it would be useful to know what you are running this on (e.g. Tomcat) and how you are starting Spring (e.g. ContextLoaderListener).

[davidkarlsen]

There are a few things common to this problem. The first is, is the job actually executing twice or are you simply seeing two log messages? The second is are you somehow starting two schedulers. A common theme here is simply randomly creating new ApplicationContext's within the application. If not either of these, it would be useful to know what you are running this on (e.g. Tomcat) and how you are starting Spring (e.g. ContextLoaderListener).

It's executing twice.

I'm using org.springframework.web.context.ContextLoaderListe ner to load a beanRefContext.xml holding all the contexts - but I've also got some EJB's (message driven). Good point about the applications getting initialized twice - I'll try to retrieve the applicationContext inside the job and print the address of the object.

Thanks

[davidkarlsen]

Possibly a threading issue as quoted from this developerWorks article->
http://www-128.ibm.com/developerwork...09_alcott.html

"Spring provides or integrates with a number of scheduling packages. The only Spring scheduling package that works with threads managed by WebSphere Application Server is the CommonJ WorkManager scheduling package. Other packages, such as quartz and the JDK Timer, start unmanaged threads and should be avoided."

But in this case we're using a workmanager

[adam_jh]

There are a few things common to this problem. The first is, is the job actually executing twice or are you simply seeing two log messages? The second is are you somehow starting two schedulers. A common theme here is simply randomly creating new ApplicationContext's within the application. If not either of these, it would be useful to know what you are running this on (e.g. Tomcat) and how you are starting Spring (e.g. ContextLoaderListener).

Thanks Karl.

I don't try to create the ApplicationContext myself, I simply have the following in the web.xml and let spring manage things.

<context-param>
	<param-name>contextConfigLocation</param-name>
	<!-- tiles put in the deploy-... so not loaded for junit tests since tiles require a container instance to work causing problems for junit tests loading the container -->
	<param-value>/WEB-INF/deploy-development.xml, /WEB-INF/applicationContext-dao.xml, /WEB-INF/applicationContext-service.xml, /WEB-INF/applicationContext-web.xml, /WEB-INF/applicationContext-threads.xml</param-value>
</context-param>

<!-- latest servlet versions allows this to execute before the load-on-startup=1 -->
<listener>
	<!-- this loads the spring via an ApplicationContext (don't use the BeanFactory) -->
        <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
</listener>

I start tomcat using its startup command. All very standard. I can't have two tomcats running else I'd get the 'port in use' exception.

More environment info:
tomcat5-5.5.17
linux RHEL4

What steps would you try next? How do I determine if its 2 logs or 2 jobs? Perhaps show from the JobExecutionContext ctx its memory address - how do I do that? I doubt its 2 logs though since changing the code to send an email - it sends 2 identical emails!


adam