[mule-user] Mule shudown with jms and xa

1 view
Skip to first unread message

JURZAK Theotime

unread,
Oct 3, 2007, 10:56:12 AM10/3/07
to us...@mule.codehaus.org

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

 

Andrew Perepelytsya

unread,
Oct 3, 2007, 11:56:00 AM10/3/07
to us...@mule.codehaus.org
XA transacted receiver polls queue for new messages in transaction. When you shutdown the server those polling threads give you the message.

Andrew

JURZAK Theotime

unread,
Oct 4, 2007, 6:11:42 AM10/4/07
to us...@mule.codehaus.org

Hi Andrew,

 

Thanks to reply.

 

The problem is my transaction monitor (atomikos) is already shutdown. It has a shutdown hook and checking logs, i see that when rollback is called, it’s stopped.

I let you know if i find something.

 

Theotime

 


De : Andrew Perepelytsya [mailto:aper...@gmail.com]
Envoyé : mercredi 3 octobre 2007 17:56
À : us...@mule.codehaus.org
Objet : Re: [mule-user] Mule shudown with jms and xa

Holger Hoffstätte

unread,
Oct 4, 2007, 6:24:53 AM10/4/07
to us...@mule.codehaus.org
JURZAK Theotime wrote:
> The problem is my transaction monitor (atomikos) is already shutdown. It
> has a shutdown hook and checking logs, i see that when rollback is
> called, it’s stopped.

JVM shutdown hooks are essentially _completely useless_ for services that
depend on each other and their respective lifecycles, since they are
executed concurrently, which means random order. So you might see correct
shutdown at one time and some other random behaviour the next. Try
shutting down Mule first and then Atomikos.

-h

---------------------------------------------------------------------
To unsubscribe from this list please visit:

http://xircles.codehaus.org/manage_email

Andrew Perepelytsya

unread,
Oct 4, 2007, 8:48:25 AM10/4/07
to us...@mule.codehaus.org
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

JURZAK Theotime

unread,
Oct 5, 2007, 8:27:11 AM10/5/07
to us...@mule.codehaus.org

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

 

 

 


De : Andrew Perepelytsya [mailto:aper...@gmail.com]
Envoyé : jeudi 4 octobre 2007 14:48


À : us...@mule.codehaus.org
Objet : Re: [mule-user] Mule shudown with jms and xa

Andrew Perepelytsya

unread,
Oct 5, 2007, 8:36:19 AM10/5/07
to us...@mule.codehaus.org
Hi Theotime,

The fix ugliness just depends how we go about managing it. If it's a high-quality patch submission with a clear explanation, that's OSS in action :) For the time being you can drop a modified Atomikos class into $MULE_HOME/lib/user, it will be searched first in the classpath, thus no need to mess with repackaging.

BTW, do you know their issue id to track?

HTH,
Andrew

GuyPardon

unread,
Oct 5, 2007, 11:25:51 PM10/5/07
to us...@mule.codehaus.org

Hi,


Andrew Perepelytsya wrote:
>
>
> BTW, do you know their issue id to track?
>

Our (Atomikos) issue tracker is focused primarily on customer support and
ticketing, which (unfortunately) means that it doesn't allow 'community'
views of issues. However, for issues reported in our forums (i.e. community
feedback) we link the tracker issue to the forum post.

What I am saying: you can use the forum post URL as a substitute for the
issue ID: http://www.atomikos.org/forums/viewtopic.php?t=1273

Since we don't delete forum posts (with the exception of spam) this URL
should be stable.

We're evaluating how to improve the visibility of the issues - but for now
that is all we can offer.

Best
Guy


--
View this message in context: http://www.nabble.com/Mule-shudown-with-jms-and-xa-tf4562317.html#a13070420
Sent from the Mule - User mailing list archive at Nabble.com.

Reply all
Reply to author
Forward
0 new messages