Scheduler does not work after many redeployments ------------------------------------------------ Key: JBESB-1415 URL: http://jira.jboss.com/jira/browse/JBESB-1415 Project: JBoss ESB Issue Type: Bug Security Level: Public (Everyone can see) Components: Adapters, Rosetta Affects Versions: 4.2.1 Environment: FC7, MySQL, dual core Reporter: Jiri Pechanec Priority: Critical When I run QE test suite (lot of redpeloyments) then in cca 5 % will Scheduler stop scheduling events in that way that all scheduled services are not triggered (including FTP etc.) Bug is extremly difficult to reproduce and I did not identified any pattern that can trigger it. This is sample of log - service was not triggered after deployment 2007-12-17 17:38:21,187 DEBUG [org.jboss.deployment.MainDeployer] Starting deployment of package: file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb 2007-12-17 17:38:21,187 DEBUG [org.jboss.deployment.MainDeployer] Starting deployment (init step) of package at: file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb 2007-12-17 17:38:21,187 DEBUG [org.jboss.deployment.MainDeployer] Copying file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb -> /home/jpechane/pokus/IR8AS/server/mysql/tmp/deploy/tmp42805Quickstart_scheduled_services.esb 2007-12-17 17:38:21,188 DEBUG [org.jboss.deployment.MainDeployer] using deployer org.jboss.soa.esb.listeners.config.JBoss4ESBDeployer@51f3eab7 2007-12-17 17:38:21,190 DEBUG [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployer] looking for nested deployments in : file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb 2007-12-17 17:38:21,191 DEBUG [org.jboss.deployment.DeploymentInfo] createLoaderRepository from config: LoaderRepositoryConfig(repositoryName: JMImplementation:service=LoaderRepository,name=Default, repositoryClassName: null, configParserClassName: null, repositoryConfig: null) 2007-12-17 17:38:21,191 DEBUG [org.jboss.mx.loading.RepositoryClassLoader] setRepository, repository=org.jboss.mx.loading.UnifiedLoaderRepository3@2911a3a4, cl=org.jboss.mx.loading.UnifiedClassLoader3@16da5c5a{ url=file:/home/jpechane/pokus/IR8AS/server/mysql/tmp/deploy/tmp42805Quickstart_scheduled_services.esb ,addedOrder=0} 2007-12-17 17:38:21,191 DEBUG [org.jboss.mx.loading.RepositoryClassLoader] setRepository, repository=org.jboss.mx.loading.UnifiedLoaderRepository3@2911a3a4, cl=org.jboss.mx.loading.UnifiedClassLoader3@16da5c5a{ url=file:/home/jpechane/pokus/IR8AS/server/mysql/tmp/deploy/tmp42805Quickstart_scheduled_services.esb ,addedOrder=0} 2007-12-17 17:38:21,191 DEBUG [org.jboss.mx.loading.UnifiedLoaderRepository3] Adding org.jboss.mx.loading.UnifiedClassLoader3@16da5c5a{ url=file:/home/jpechane/pokus/IR8AS/server/mysql/tmp/deploy/tmp42805Quickstart_scheduled_services.esb ,addedOrder=0} 2007-12-17 17:38:21,191 DEBUG [org.jboss.mx.loading.ClassLoaderUtils] Multiple class loaders found for pkg: org.jboss.soa.esb.samples.quickstart.scheduler 2007-12-17 17:38:21,192 DEBUG [org.jboss.deployment.MainDeployer] found 0 subpackages of file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb 2007-12-17 17:38:21,192 DEBUG [org.jboss.deployment.MainDeployer] Watching new file: file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb 2007-12-17 17:38:21,192 DEBUG [org.jboss.deployment.MainDeployer] create step for deployment file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb 2007-12-17 17:38:21,192 INFO [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployer] create esb service, Quickstart_scheduled_services.esb 2007-12-17 17:38:21,200 DEBUG [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployer] Deploying: file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb 2007-12-17 17:38:21,200 DEBUG [org.jboss.system.ServiceController] Creating service jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:38:21,200 DEBUG [org.jboss.system.ServiceController] adding depends in ServiceController.register: [jboss.esb:deployment=jbossesb.esb] 2007-12-17 17:38:21,200 DEBUG [org.jboss.system.ServiceController] recording that jboss.esb:deployment=Quickstart_scheduled_services.esb depends on jboss.esb:deployment=jbossesb.esb 2007-12-17 17:38:21,200 DEBUG [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployment] Creating jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:38:21,200 DEBUG [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployment] Created jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:38:21,200 DEBUG [org.jboss.system.ServiceController] Creating dependent components for: jboss.esb:deployment=Quickstart_scheduled_services.esb dependents are: [] 2007-12-17 17:38:21,200 DEBUG [org.jboss.deployment.MainDeployer] Done with create step of deploying Quickstart_scheduled_services.esb 2007-12-17 17:38:21,200 DEBUG [org.jboss.deployment.MainDeployer] Begin deployment start file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb 2007-12-17 17:38:21,201 DEBUG [org.jboss.system.ServiceController] starting service jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:38:21,201 DEBUG [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployment] Starting jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:38:21,201 DEBUG [org.jboss.soa.esb.lifecycle.LifecycleResourceManager] Associating deploymentName Quickstart_scheduled_services.esb with identity: ID-60 2007-12-17 17:38:21,229 DEBUG [org.jboss.soa.esb.listeners.lifecycle.AbstractManagedLifecycle] terminationPeriod value 60000 2007-12-17 17:38:21,234 INFO [STDOUT] ** initialize: <my_scheduled_listener event-processor="org.jboss.soa.esb.samples.quickstart.scheduler.MyScheduledActionMsgComposer" listenerClass="org.jboss.soa.esb.listeners.ScheduleListener" mep="OneWay" scheduleidref="10-sec-trigger"> <action action="first" class="org.jboss.soa.esb.samples.quickstart.scheduler.MyBasicAction" exceptionMethod="exceptionHandler" process="displayMessage2"/> <action action="groovy" class="org.jboss.soa.esb.actions.scripting.GroovyActionProcessor" script="/scripts/iTunesTop5.groovy"/> <action action="testReport" class="org.jboss.soa.esb.qa.framework.ReportAction" jaasConfig="client-login" jaasLogin="admin" jaasPassword="admin" jaasSecure="true"/> </my_scheduled_listener> 2007-12-17 17:38:21,234 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] Using mep: OneWay, oneWay: true, defaultProcessing: false 2007-12-17 17:38:21,234 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] Registering action class org.jboss.soa.esb.samples.quickstart.scheduler.MyBasicAction 2007-12-17 17:38:21,236 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] Using overridden action lifecycle processor for org.jboss.soa.esb.samples.quickstart.scheduler.MyBasicAction 2007-12-17 17:38:21,236 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] Registering action class org.jboss.soa.esb.actions.scripting.GroovyActionProcessor 2007-12-17 17:38:21,236 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] Using normal action pipeline processor for org.jboss.soa.esb.actions.scripting.GroovyActionProcessor 2007-12-17 17:38:21,237 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] Registering action class org.jboss.soa.esb.qa.framework.ReportAction 2007-12-17 17:38:21,237 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] Using bean configured action processor for org.jboss.soa.esb.qa.framework.ReportAction 2007-12-17 17:38:21,242 INFO [org.quartz.core.QuartzScheduler] Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED started. 2007-12-17 17:38:21,242 DEBUG [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployment] Started jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:38:21,242 DEBUG [org.jboss.system.ServiceController] Starting dependent components for: jboss.esb:deployment=Quickstart_scheduled_services.esb dependent components: [] 2007-12-17 17:38:21,242 DEBUG [org.jboss.deployment.MainDeployer] End deployment start on package: Quickstart_scheduled_services.esb 2007-12-17 17:38:21,242 DEBUG [org.jboss.deployment.MainDeployer] Deployed package: file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb 2007-12-17 17:39:40,710 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - first pass <Mon, 17 Dec 2007 17:39:40> 2007-12-17 17:39:40,710 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule: first pass 2007-12-17 17:39:40,710 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass 2007-12-17 17:39:40,710 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass 2007-12-17 17:39:50,711 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - second pass <Mon, 17 Dec 2007 17:39:50> 2007-12-17 17:39:50,711 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AtomicActionRecoveryModule: Second pass 2007-12-17 17:39:50,712 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass 2007-12-17 17:39:50,712 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass 2007-12-17 17:40:21,403 INFO [org.jboss.soa.esb.qa.framework.ESBCallback] Cleaning message store 2007-12-17 17:40:21,403 DEBUG [org.jboss.soa.esb.qa.framework.ESBCallback] Cleaning classification: RDLVR 2007-12-17 17:40:21,403 DEBUG [org.jboss.internal.soa.esb.persistence.format.db.DBMessageStoreImpl] retrieved 0 RDLVR messages 2007-12-17 17:40:21,403 DEBUG [org.jboss.soa.esb.qa.framework.ESBCallback] Cleaning classification: DLQ 2007-12-17 17:40:21,403 DEBUG [org.jboss.internal.soa.esb.persistence.format.db.DBMessageStoreImpl] retrieved 0 DLQ messages 2007-12-17 17:40:21,403 DEBUG [org.jboss.soa.esb.qa.framework.ESBCallback] Cleaning classification: STORE 2007-12-17 17:40:21,404 DEBUG [org.jboss.internal.soa.esb.persistence.format.db.DBMessageStoreImpl] retrieved 0 STORE messages 2007-12-17 17:40:21,404 DEBUG [org.jboss.soa.esb.qa.framework.ESBCallback] Cleaning classification: null 2007-12-17 17:40:21,404 DEBUG [org.jboss.internal.soa.esb.persistence.format.db.DBMessageStoreImpl] retrieved 0 null messages 2007-12-17 17:40:21,404 DEBUG [org.jboss.soa.esb.qa.framework.ESBCallback] Cleaning classification: test 2007-12-17 17:40:21,404 DEBUG [org.jboss.internal.soa.esb.persistence.format.db.DBMessageStoreImpl] retrieved 0 test messages 2007-12-17 17:40:21,407 DEBUG [org.jboss.deployment.MainDeployer] Undeploying file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb, isShutdown=false 2007-12-17 17:40:21,407 DEBUG [org.jboss.system.ServiceController] stopping service: jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:40:21,407 DEBUG [org.jboss.system.ServiceController] stopping dependent services for: jboss.esb:deployment=Quickstart_scheduled_services.esb dependent services are: [] 2007-12-17 17:40:21,407 DEBUG [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployment] Stopping jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:40:21,407 INFO [STDOUT] uninitialize ** 2007-12-17 17:40:21,407 DEBUG [org.jboss.soa.esb.lifecycle.LifecycleResourceManager] Disassociating deploymentName Quickstart_scheduled_services.esb from identity: ID-60 2007-12-17 17:40:21,407 DEBUG [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployment] Stopped jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:40:21,407 DEBUG [org.jboss.system.ServiceController] destroying service: jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:40:21,407 DEBUG [org.jboss.system.ServiceController] destroying dependent services for: jboss.esb:deployment=Quickstart_scheduled_services.esb dependent services are: [] 2007-12-17 17:40:21,407 DEBUG [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployment] Destroying jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:40:21,407 DEBUG [org.jboss.soa.esb.listeners.config.JBoss4ESBDeployment] Destroyed jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:40:21,407 DEBUG [org.jboss.system.ServiceController] removing service: jboss.esb:deployment=Quickstart_scheduled_services.esb 2007-12-17 17:40:21,407 DEBUG [org.jboss.system.ServiceController] removing already unregistered jboss.esb:deployment=Quickstart_scheduled_services.esb from server 2007-12-17 17:40:21,408 DEBUG [org.jboss.mx.loading.RepositoryClassLoader] Unregistering cl=org.jboss.mx.loading.UnifiedClassLoader3@16da5c5a{ url=file:/home/jpechane/pokus/IR8AS/server/mysql/tmp/deploy/tmp42805Quickstart_scheduled_services.esb ,addedOrder=114} 2007-12-17 17:40:21,408 DEBUG [org.jboss.mx.loading.UnifiedLoaderRepository3] UnifiedLoaderRepository removed(true) org.jboss.mx.loading.UnifiedClassLoader3@16da5c5a{ url=file:/home/jpechane/pokus/IR8AS/server/mysql/tmp/deploy/tmp42805Quickstart_scheduled_services.esb ,addedOrder=114} 2007-12-17 17:40:21,408 DEBUG [org.jboss.deployment.DeploymentInfo] Cleaned Deployment: file:/home/jpechane/pokus/IR8AS/server/mysql/tmp/deploy/tmp42805Quickstart_scheduled_services.esb 2007-12-17 17:40:21,408 DEBUG [org.jboss.deployment.MainDeployer] Undeployed file:/home/jpechane/testing/esbtests/tests/quickstarts/tests/output/lib/Quickstart_scheduled_services.esb -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.jboss.com/jira/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira