Announcement Announcement Module
Collapse
No announcement yet.
Quartz jobs scheduled twice Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Quartz jobs scheduled twice

    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)

  • #2
    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?

    Comment


    • #3
      No - it's only this instance.

      Comment


      • #4
        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.

        Comment


        • #5
          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."

          Comment


          • #6
            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

            Code:
            <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
            Code:
            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...
            Code:
            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

            Comment


            • #7
              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).

              Comment


              • #8
                Originally posted by karldmoore View Post
                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

                Comment


                • #9
                  Originally posted by Sara_Mitchell View Post
                  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

                  Comment


                  • #10
                    Originally posted by karldmoore View Post
                    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.
                    Code:
                    <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

                    Comment


                    • #11
                      I also have a TaskExecutor defined, but that shouldn't do anything to quartz?

                      Code:
                      <bean id="taskExecutor" class="org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor">
                      	  <property name="corePoolSize" value="5"/>
                      	  <property name="maxPoolSize" value="10"/>
                      </bean>

                      Comment


                      • #12
                        Interesting...

                        From the logs, the job fires ONCE on my development machine. My development machine is windows and has tomcat 5.5.17 installed. I start tomcat using sysdeo's plug in.

                        From the logs, the job fires TWICE on the production server. The production server is RHEL4 with the tomcat version 5.5.17.

                        I will have to investigate. The only difference off the top of my head is the production is set as the root context.

                        adam

                        Comment


                        • #13
                          Sorry I haven't posted back I missed the responses. I guess it must be something in the environment then. I'm still not sure what would cause this. If it's exactly the same web app you would expect it to behave in the same way. If you do make any headway on this it would be great if you could post back!

                          Comment


                          • #14
                            fixed itself?

                            Assuming the logs actually portray an accurate picture of what's going on, then it appears to have fixed itself!?

                            I certainly wasn't doing any work past 11 on this day...Note how the logs at the start show the job triggering twice at the same time, then at the end just once - from then on!

                            Code:
                            2007-04-24 23:05:00,015 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger fired job DEFAULT.jobDetail at:  23:05:00 24/Apr/2007
                            2007-04-24 23:05:00,017 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger fired job DEFAULT.jobDetail at:  23:05:00 24/Apr/2007
                            2007-04-24 23:05:00,072 INFO [com.service.threads.TaskJob] - handling task: user_event_type_utc_version_processing 2, 0, 3, 2007-04-23T13:30:00.000+01:00, 992, true
                            2007-04-24 23:05:00,080 INFO [com.service.threads.TaskJob] - handling task: user_event_type_utc_version_processing 2, 0, 3, 2007-04-23T13:30:00.000+01:00, 992, true
                            2007-04-24 23:05:00,088 INFO [com.service.threads.TaskJob] - failed completing task - last failed acknowledgment: responseCode_usersId ddf62a2ac0ba13845aa938ef8ca5a278, 2
                            2007-04-24 23:05:00,096 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger completed firing job DEFAULT.jobDetail at  23:05:00 24/Apr/2007 with resulting trigger instruction code: DO NOTHING
                            2007-04-24 23:05:00,101 INFO [com.service.threads.TaskJob] - failed completing task - last failed acknowledgment: responseCode_usersId ddf62a2ac0ba13845aa938ef8ca5a278, 2
                            2007-04-24 23:05:00,105 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger completed firing job DEFAULT.jobDetail at  23:05:00 24/Apr/2007 with resulting trigger instruction code: DO NOTHING
                            2007-04-24 23:10:00,012 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger fired job DEFAULT.jobDetail at:  23:10:00 24/Apr/2007
                            2007-04-24 23:10:00,070 INFO [com.service.threads.TaskJob] - handling task: user_event_type_utc_version_processing 2, 0, 3, 2007-04-23T13:30:00.000+01:00, 996, true
                            2007-04-24 23:10:00,090 INFO [com.service.threads.TaskJob] - failed completing task - last failed acknowledgment: responseCode_usersId ddf62a2ac0ba13845aa938ef8ca5a278, 2
                            2007-04-24 23:10:00,099 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger completed firing job DEFAULT.jobDetail at  23:10:00 24/Apr/2007 with resulting trigger instruction code: DO NOTHING
                            2007-04-24 23:15:00,021 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger fired job DEFAULT.jobDetail at:  23:15:00 24/Apr/2007
                            2007-04-24 23:15:00,027 INFO [org.quartz.plugins.history.LoggingTriggerHistoryPlugin] - Trigger DEFAULT.cronTrigger completed firing job DEFAULT.jobDetail at  23:15:00 24/Apr/2007 with resulting trigger instruction code: DO NOTHING

                            Comment


                            • #15
                              Interesting. I would presume it's fired twice because it was told to? Otherwise it would fire twice everytime. Just thinking out loud really.

                              Comment

                              Working...
                              X