Mule shudown with jms and xa

Hi mule team,

I’m currently using mule 1.4.3 with XA transactions.

When i shutdown (properly) my application server (jboss 4), i get some errors.

It seems that after my jms connector is stopped, some XATransactedJmsMessageReceiver are always active and call rollback  on transaction. So, i get a TransactionRollbackException…

16:21:58,846 INFO  [Server] LifeThread.run exits!

16:21:58,846 INFO  [Server] Shutting down the JVM now!

16:21:58,862 INFO  [QuartzConnector] Stopping: QuartzConnector{this=10bd71c, started=true, initialised=true, name='connector.quartz.0', disposed=false, numberOfConcurrentTransactedReceivers=4, createMultipleTransactedReceivers=true, connected=true, supportedProtocols=[quartz], serviceOverrides=null}

16:21:58,862 INFO  [QuartzScheduler] Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED shutting down.

16:21:58,862 INFO  [QuartzScheduler] Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED paused.

16:21:58,893 INFO  [Server] Runtime shutdown hook called, forceHalt: true

16:21:58,893 INFO  [Server] JBoss SHUTDOWN: Undeploying all packages

16:21:58,893 INFO  [QuartzScheduler] Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED shutdown complete.

16:21:58,909 INFO  [TomcatDeployer] undeploy, ctxPath=/jmx-console, warUrl=.../deploy/jmx-console.war/

16:21:58,909 INFO  [QuartzMessageReceiver] Disconnected: QuartzMessageReceiver{this=279c88, receiverKey=/receiveNotificationStarter, endpoint=quartz:/receiveNotificationStarter}

16:21:58,909 INFO  [QuartzConnector] Stopped: QuartzConnector{this=10bd71c, started=false, initialised=true, name='connector.quartz.0', disposed=false, numberOfConcurrentTransactedReceivers=4, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[quartz], serviceOverrides=null}

16:21:58,925 INFO  [QuartzConnector] Disconnected: QuartzConnector{this=10bd71c, started=false, initialised=true, name='connector.quartz.0', disposed=false, numberOfConcurrentTransactedReceivers=4, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[quartz], serviceOverrides=null}

16:21:58,925 INFO  [QuartzConnector] Stopped: QuartzConnector{this=10bd71c, started=false, initialised=true, name='connector.quartz.0', disposed=false, numberOfConcurrentTransactedReceivers=4, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[quartz], serviceOverrides=null}

16:21:58,925 INFO  [ActiveMqJmsConnector] Stopping: ActiveMqJmsConnector{this=1e7d8b1, started=true, initialised=true, name='ReceiveJmsConnector', disposed=false, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=true, supportedProtocols=[jms], serviceOverrides=null}

16:21:59,003 INFO  [TomcatDeployer] undeploy, ctxPath=/jamon, warUrl=.../tmp/deploy/tmp18858jamon-exp.war/

16:21:59,034 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=397d4e, receiverKey=ReceiveDispatcherUMO~fromMtaTo, endpoint=jms://fromMtaTo}

16:21:59,050 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=312c50, receiverKey=ReceiveErrorManagerUMO~-receive-exception-notification-queue, endpoint=jms://-receive-exception-notification-queue}

16:21:59,050 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=129dda, receiverKey=ReceiveDispatcherUMO~fromPop3To, endpoint=jms://fromPop3To}

16:21:59,112 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=1871f70, receiverKey=ReceiveUMO~receive.default, endpoint=jms://receive.default}

16:21:59,112 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=2423e2, receiverKey=ReceiveDispatcherUMO~fromRvaTo, endpoint=jms://fromRvaTo}

16:21:59,112 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=109f28b, receiverKey=ReceiveDispatcherUMO~fromMoveItTo, endpoint=jms://fromMoveItTo}

16:21:59,112 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=d4aaf6, receiverKey=ReceiveDispatcherUMO~fromAs2To, endpoint=jms://fromAs2To}

16:21:59,112 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=afd9e3, receiverKey=ReceiveDispatcherUMO~fromSshTo, endpoint=jms://fromSshTo}

16:21:59,112 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=1254e59, receiverKey=ReceiveLadUMO~receive.lad, endpoint=jms://receive.lad}

16:21:59,112 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=1a1ed04, receiverKey=ReceiveCatalogUMO~receive.catalog, endpoint=jms://receive.catalog}

16:21:59,112 INFO  [XaTransactedJmsMessageReceiver] Disconnected: XaTransactedJmsMessageReceiver{this=1f2caf4, receiverKey=ReceiveForwardBasicUMO~receive.forward.basic, endpoint=jms://receive.forward.basic}

16:21:59,128 INFO  [TomcatDeployer] undeploy, ctxPath=/-flow-receive-war, warUrl=.../deploy/-flow-receive-war.war/

16:21:59,143 INFO  [ActiveMqJmsConnector] Stopped: ActiveMqJmsConnector{this=1e7d8b1, started=false, initialised=true, name='ReceiveJmsConnector', disposed=false, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[jms], serviceOverrides=null}

16:21:59,143 INFO  [ActiveMqJmsConnector] Disconnected: ActiveMqJmsConnector{this=1e7d8b1, started=false, initialised=true, name='ReceiveJmsConnector', disposed=false, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[jms], serviceOverrides=null}

16:21:59,143 INFO  [ActiveMqJmsConnector] Stopped: ActiveMqJmsConnector{this=1e7d8b1, started=false, initialised=true, name='ReceiveJmsConnector', disposed=false, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[jms], serviceOverrides=null}

16:21:59,159 INFO  [MuleManager] Connectors have been stopped successfully

16:21:59,159 INFO  [MuleManager] Stopping agents...

16:21:59,159 INFO  [MuleManager] Agents Successfully Stopped

16:21:59,159 INFO  [TransactionalQueueManager] Stopping ResourceManager

16:21:59,159 INFO  [TransactionalQueueManager] Stopped ResourceManager

16:21:59,175 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://fromAs2To

16:21:59,175 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://fromRvaTo

16:21:59,175 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://fromSshTo

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [TransactionTemplate] Exception Caught in Transaction template.  Handing off to exception handler: com.mycomp.flow.common.mule.ExceptionStrategy@46d485

16:21:59,190 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://fromMoveItTo

16:21:59,206 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://fromPop3To

16:21:59,206 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://fromMtaTo

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [SedaModel] Component ReceiveDispatcherUMO has been stopped successfully

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [ExceptionStrategy] There is no current event available, routing Null message with the exception

16:21:59,206 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://receive.catalog

16:21:59,221 INFO  [SedaModel] Component ReceiveCatalogUMO has been stopped successfully

16:21:59,221 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://-receive-exception-notification-queue

16:21:59,221 INFO  [SedaModel] Component ReceiveErrorManagerUMO has been stopped successfully

16:21:59,221 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://receive.forward.basic

16:21:59,221 INFO  [SedaModel] Component ReceiveForwardBasicUMO has been stopped successfully

16:21:59,221 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://receive.lad

16:21:59,221 INFO  [SedaModel] Component ReceiveLadUMO has been stopped successfully

16:21:59,221 INFO  [QuartzConnector] Removing listener on endpointUri: quartz:/receiveNotificationStarter

16:21:59,221 INFO  [SedaModel] Component ReceiveSchedulerNotificationUMO has been stopped successfully

16:21:59,221 INFO  [ActiveMqJmsConnector] Removing listener on endpointUri: jms://receive.default

16:21:59,237 INFO  [SedaModel] Component ReceiveUMO has been stopped successfully

16:21:59,237 INFO  [QuartzConnector] Disposing: QuartzConnector{this=10bd71c, started=false, initialised=true, name='connector.quartz.0', disposed=false, numberOfConcurrentTransactedReceivers=4, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[quartz], serviceOverrides=null}

16:21:59,237 INFO  [QuartzConnector] Stopped: QuartzConnector{this=10bd71c, started=false, initialised=true, name='connector.quartz.0', disposed=false, numberOfConcurrentTransactedReceivers=4, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[quartz], serviceOverrides=null}

16:21:59,237 INFO  [QuartzConnector] Disposed: QuartzConnector{this=10bd71c, started=false, initialised=true, name='connector.quartz.0', disposed=true, numberOfConcurrentTransactedReceivers=4, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[quartz], serviceOverrides=null}

16:21:59,237 INFO  [ActiveMqJmsConnector] Disposing: ActiveMqJmsConnector{this=1e7d8b1, started=false, initialised=true, name='ReceiveJmsConnector', disposed=false, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[jms], serviceOverrides=null}

16:21:59,237 INFO  [ActiveMqJmsConnector] Stopped: ActiveMqJmsConnector{this=1e7d8b1, started=false, initialised=true, name='ReceiveJmsConnector', disposed=false, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[jms], serviceOverrides=null}

16:21:59,237 INFO  [ActiveMqJmsConnector] Disposed: ActiveMqJmsConnector{this=1e7d8b1, started=false, initialised=true, name='ReceiveJmsConnector', disposed=true, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[jms], serviceOverrides=null}

16:21:59,237 INFO  [SedaModel] ReceiveDispatcherUMO has been destroyed successfully

16:21:59,237 INFO  [SedaModel] ReceiveCatalogUMO has been destroyed successfully

16:21:59,237 INFO  [SedaModel] ReceiveErrorManagerUMO has been destroyed successfully

16:21:59,237 INFO  [SedaModel] ReceiveForwardBasicUMO has been destroyed successfully

16:21:59,237 INFO  [SedaModel] ReceiveLadUMO has been destroyed successfully

16:21:59,237 INFO  [SedaModel] ReceiveSchedulerNotificationUMO has been destroyed successfully

16:21:59,237 INFO  [SedaModel] ReceiveUMO has been destroyed successfully

16:21:59,237 INFO  [MuleManager] disposing agents...

16:21:59,253 ERROR [ExceptionStrategy]

********************************************************************************

Message               : Transaction rollback failed

Type                  : org.mule.transaction.TransactionRollbackException

Code                  : MULE_ERROR-92098

JavaDoc               : http://mule.mulesource.org/docs/apidocs/org/mule/transaction/TransactionRollbackException.html

********************************************************************************

Exception stack is:

1. Error in rollback: null (com.atomikos.icatch.jta.ExtendedSystemException)

  com.atomikos.icatch.jta.TransactionImp:-1 (null)

2. Transaction rollback failed (org.mule.transaction.TransactionRollbackException)

  org.mule.transaction.XaTransaction:107 (http://mule.mulesource.org/docs/apidocs/org/mule/transaction/TransactionRollbackException.html)

********************************************************************************

Root Exception stack trace:

com.atomikos.icatch.jta.ExtendedSystemException: Error in rollback: null

            at com.atomikos.icatch.jta.TransactionImp.rollback(Unknown Source)

            at org.mule.transaction.XaTransaction.doRollback(XaTransaction.java:102)

            at org.mule.transaction.AbstractTransaction.rollback(AbstractTransaction.java:120)

            at org.mule.transaction.TransactionTemplate.execute(TransactionTemplate.java:98)

            at org.mule.providers.TransactedPollingMessageReceiver.poll(TransactedPollingMessageReceiver.java:131)

            at org.mule.providers.jms.XaTransactedJmsMessageReceiver.poll(XaTransactedJmsMessageReceiver.java:171)

            at org.mule.providers.PollingReceiverWorker.run(PollingReceiverWorker.java:47)

            at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310)

            at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)

            at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)

            at java.lang.Thread.run(Thread.java:595)

…

Do you have an idea why i get this behaviour ?

Thanks

Hi Andrew,

I did like you said to plug my transaction manager with Mule’s lifecycle.

The problem is that atomikos shutdown hook cannot be disabled so it works with a ‘badly’ hack of atomikos removing this shutdown hook.

I informed atomikos about this and they have filled a feature request for 3.3 release J.

See http://www.atomikos-support.com/forums/viewtopic.php?p=2369

Theotime

Instead of a shutdown hook I would recommend using Mule's lifecycle, as at least there's a better control of the shutdown order (nothing is guaranteed for runtime JVM hooks).

I think this topic emerged before, so I filed a http://mule.mulesource.org/jira/browse/MULE-2479 , you can put a watch on it. Note, however, I'm reluctant to change the API in 1.4.x for backwards compatibility, so for now it'll be in 2.x.

For the time being you can achieve the same by registering a proper listener on the MuleManager, e.g. on 'models stopped' events.

Andrew