Atomikos Forum |
|
I am testing out Atomikos with Spring tcServer and enlisting transactions with Oracle, DB2, & MQ. So far everything has been stellar. I am testing a rollback scenario and it appears to be working. However I'm getting a stacktrace that may be right or maybe not.
Only the MQ transaction throws this exception, none of the database transactions do. My question is, should I expect this stacktrace or do I have something setup wrong? Thanks John The interesting part of the stacktrace from atomikos is: Caused by: com.atomikos.jms.AtomikosJMSException: error during enlist: Transaction is marked for rollback only or has timed out at com.atomikos.jms.AtomikosJMSException.throwAtomikosJMSException(AtomikosJMSException.java:29) at com.atomikos.jms.ConsumerProducerSupport.enlist(ConsumerProducerSupport.java:71) at com.atomikos.jms.AtomikosJmsMessageProducerProxy.send(AtomikosJmsMessageProducerProxy.java:25) at com.atomikos.jms.AtomikosJmsMessageProducerProxy.send(AtomikosJmsMessageProducerProxy.java:106) at org.springframework.jms.core.JmsTemplate.doSend(JmsTemplate.java:584) at org.springframework.jms.core.JmsTemplate.doSend(JmsTemplate.java:561) at org.springframework.jms.core.JmsTemplate$3.doInJms(JmsTemplate.java:528) at org.springframework.jms.core.JmsTemplate.execute(JmsTemplate.java:459) ... 68 more Caused by: com.atomikos.datasource.xa.session.InvalidSessionHandleStateException: Transaction is marked for rollback only or has timed out at com.atomikos.datasource.xa.session.NotInBranchStateHandler.checkEnlistBeforeUse(NotInBranchStateHandler.java:34) at com.atomikos.datasource.xa.session.TransactionContext.checkEnlistBeforeUse(TransactionContext.java:60) at com.atomikos.datasource.xa.session.SessionHandleState.notifyBeforeUse(SessionHandleState.java:151) at com.atomikos.jms.ConsumerProducerSupport.enlist(ConsumerProducerSupport.java:67)
Adding some more details:
My server.xml for the QCF & queue look like this: <Resource CHAN="TO.MQAPPDEV" HOST="MQAPPDEV1" PORT="1414" QMGR="MQAPPDEV" TRAN="1" auth="Container" description="JMS Connection Factory for sending messages to notification service" factory="com.ibm.mq.jms.MQXAConnectionFactoryFactory" name="jms/notifServConnectionFactory" type="com.ibm.mq.jms.MQXAConnectionFactory" /> <Resource QU="AART.NOTIFY.MSGS.FROM.APPL" auth="Container" description="JMS Queue for sending messages to notification service" factory="com.ibm.mq.jms.MQQueueFactory" name="jms/notifServQueue" type="com.ibm.mq.jms.MQQueue" /> My context.xml has the transaction factory: <Transaction factory="com.atomikos.icatch.jta.UserTransactionFactory" /> My Spring config looks like this: <bean id="atomikosTransactionManager" class="com.atomikos.icatch.jta.UserTransactionManager" init-method="init" destroy-method="close"> <property name="forceShutdown" value="false" /> </bean> <bean id="txManager" class="org.springframework.transaction.jta.JtaTransactionManager" > <property name="transactionManager" ref="atomikosTransactionManager" /> </bean> <jee:jndi-lookup id="notifServConnectionFactory" jndi-name="jms/notifServConnectionFactory" lookup-on-startup="true" resource-ref="true"/> <jee:jndi-lookup id="notifServQueue" jndi-name="jms/notifServQueue" lookup-on-startup="true" resource-ref="true"/> <bean id="atomikosNotifServConnectionFactory" class="com.atomikos.jms.AtomikosConnectionFactoryBean"> <property name="xaConnectionFactory" ref="notifServConnectionFactory"/> <property name="uniqueResourceName" value="Bill_Notif_Serv_MQSeries_XA_RMI"/> </bean> <bean id="notifServJmsTemplate" class="org.springframework.jms.core.JmsTemplate"> <property name="connectionFactory" ref="atomikosNotifServConnectionFactory"/> <property name="defaultDestination" ref="notifServQueue"/> <property name="sessionTransacted" value="true"/> </bean> Finally my transaction settings for the bean that uses the JMS template looks like this: <tx:advice id="txAdvice" transaction-manager="txManager"> <!-- the transactional semantics... --> <tx:attributes> <!-- all methods starting with 'get' are read-only --> <tx:method name="get*" read-only="true" /> <!-- other methods use the default transaction settings (see below) --> <tx:method name="*" /> </tx:attributes> </tx:advice> and <aop:config> <aop:pointcut id="notifServOp" expression="execution(* com.railinc.tcServer.service.BillNotificationSenderImpl.*(..))" /> <aop:advisor advice-ref="txAdvice" pointcut-ref="notifServOp"/> </aop:config>
09-09-16 09:44:01,978 [tomcat-http--4] getCompositeTransaction() returning NULL!
09-09-16 09:44:01,978 [tomcat-http--4] getCompositeTransaction() returning NULL! 09-09-16 09:44:01,978 [tomcat-http--4] getCompositeTransaction() returning NULL! 09-09-16 09:44:01,978 [tomcat-http--4] Coordinator tcServer10000500002 entering state: ACTIVE 09-09-16 09:44:01,978 [tomcat-http--4] Coordinator tcServer10000500002 entered state: ACTIVE 09-09-16 09:44:01,978 [tomcat-http--4] (1.5) executing task: com.atomikos.timing.PooledAlarmTimer@1eb494e 09-09-16 09:44:01,978 [tomcat-http--4] Creating composite transaction: tcServer10000500002 09-09-16 09:44:01,978 [tomcat-http--4] createCompositeTransaction ( 10000 ): created new ROOT transaction with id tcServer10000500002 09-09-16 09:44:01,994 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:01,994 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:01,994 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:01,994 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:02,010 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:02,010 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:02,010 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:02,010 [tomcat-http--4] Coordinator tcServer10000500002 entering state: ACTIVE 09-09-16 09:44:02,010 [tomcat-http--4] Coordinator tcServer10000500002 entered state: ACTIVE 09-09-16 09:44:02,010 [tomcat-http--4] setRollbackOnly() called for transaction tcServer10000500002 09-09-16 09:44:02,025 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:02,025 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:02,025 [tomcat-http--4] AtomikosConnectionFactoryBean 'Bill_Notif_Serv_MQSeries_XA_RMI': createConnection()... 09-09-16 09:44:02,025 [tomcat-http--4] AtomikosConnectionFactoryBean 'Bill_Notif_Serv_MQSeries_XA_RMI': init... 09-09-16 09:44:02,025 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:02,025 [tomcat-http--4] atomikos connection pool 'Bill_Notif_Serv_MQSeries_XA_RMI': pool reached max size: 1 09-09-16 09:44:02,025 [tomcat-http--4] atomikos connection pool 'Bill_Notif_Serv_MQSeries_XA_RMI': current size: 1/1 09-09-16 09:44:02,025 [tomcat-http--4] atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI: updating last time acquired 09-09-16 09:44:02,025 [tomcat-http--4] atomikos connection pool 'Bill_Notif_Serv_MQSeries_XA_RMI': error creating proxy of connection atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI com.atomikos.datasource.pool.CreateConnectionException: atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI: connection is erroneous at com.atomikos.jms.AtomikosPooledJmsConnection.testUnderlyingConnection(AtomikosPooledJmsConnection.java:43) at com.atomikos.datasource.pool.AbstractXPooledConnection.createConnectionProxy(AbstractXPooledConnection.java:43) at com.atomikos.datasource.pool.ConnectionPool.borrowConnection(ConnectionPool.java:135) at com.atomikos.jms.AtomikosConnectionFactoryBean.createConnection(AtomikosConnectionFactoryBean.java:554) at org.springframework.jms.support.JmsAccessor.createConnection(JmsAccessor.java:184) at org.springframework.jms.core.JmsTemplate.access$400(JmsTemplate.java:90) at org.springframework.jms.core.JmsTemplate$JmsTemplateResourceFactory.createConnection(JmsTemplate.java:1035) at org.springframework.jms.connection.ConnectionFactoryUtils.doGetTransactionalSession(ConnectionFactoryUtils.java:279) at org.springframework.jms.core.JmsTemplate.execute(JmsTemplate.java:446) at org.springframework.jms.core.JmsTemplate.send(JmsTemplate.java:526) at org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:605) at org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:596) at com.railinc.notifserv.event.senders.NotificationServiceEventSender.sendEvent(NotificationServiceEventSender.java:44) at com.railinc.tcServer.service.BillNotificationSenderImpl.reallySend(BillNotificationSenderImpl.java:41) at com.railinc.tcServer.service.BillNotificationSenderImpl.sendNotification(BillNotificationSenderImpl.java:23) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:310) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at $Proxy33.sendNotification(Unknown Source) at com.railinc.tcServer.service.BillServiceController.saveBill(BillServiceController.java:44) at com.railinc.tcServer.service.BillServiceController$$FastClassByCGLIB$$dfe16f24.invoke(<generated>) at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:149) at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:700) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:635) at com.railinc.tcServer.service.BillServiceController$$EnhancerByCGLIB$$e39afa1e.saveBill(<generated>) at com.railinc.tcServer.bill.web.services.rest.BillLookupService.postBill(BillLookupService.java:83) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:166) at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:82) at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:117) at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:77) at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:57) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at org.apache.cxf.workqueue.SynchronousExecutor.execute(SynchronousExecutor.java:37) at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:95) at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:236) at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:89) at org.apache.cxf.transport.servlet.ServletDestination.invoke(ServletDestination.java:99) at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:368) at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:146) at org.apache.cxf.transport.servlet.AbstractCXFServlet.invoke(AbstractCXFServlet.java:163) at org.apache.cxf.transport.servlet.AbstractCXFServlet.doPost(AbstractCXFServlet.java:141) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:379) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619) 09-09-16 09:44:02,025 [tomcat-http--4] atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI: destroying connection... 09-09-16 09:44:02,025 [tomcat-http--4] atomikos connection pool 'Bill_Notif_Serv_MQSeries_XA_RMI': no connection found - waiting a bit... 09-09-16 09:44:03,026 [tomcat-http--4] atomikos connection pool 'Bill_Notif_Serv_MQSeries_XA_RMI': growing pool size to: 1 09-09-16 09:44:03,136 [tomcat-http--4] atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI: registering listener atomikos connection pool 'Bill_Notif_Serv_MQSeries_XA_RMI' 09-09-16 09:44:03,136 [tomcat-http--4] atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI: updating last time acquired 09-09-16 09:44:03,136 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: calling toString on JMS driver... 09-09-16 09:44:03,136 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: toString returning com.ibm.mq.jms.MQXAConnection@1e04a35 09-09-16 09:44:03,136 [tomcat-http--4] atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI: returning proxy com.ibm.mq.jms.MQXAConnection@1e04a35 09-09-16 09:44:03,136 [tomcat-http--4] atomikos connection pool 'Bill_Notif_Serv_MQSeries_XA_RMI': got connection from pool, new size: 0/1 09-09-16 09:44:03,136 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: calling toString on JMS driver... 09-09-16 09:44:03,136 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: toString returning com.ibm.mq.jms.MQXAConnection@1e04a35 09-09-16 09:44:03,136 [tomcat-http--4] AtomikosConnectionFactoryBean 'Bill_Notif_Serv_MQSeries_XA_RMI': createConnection() returning com.ibm.mq.jms.MQXAConnection@1e04a35 09-09-16 09:44:03,136 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,136 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: creating XA-capable session... 09-09-16 09:44:03,261 [tomcat-http--4] a SessionHandleState with 0 context(s): notifySessionBorrowed 09-09-16 09:44:03,261 [tomcat-http--4] a TransactionContext: changing to state com.atomikos.datasource.xa.session.NotInBranchStateHandler@1086036 09-09-16 09:44:03,261 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: calling toString on JMS driver session... 09-09-16 09:44:03,261 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: toString returning com.ibm.mq.jms.MQXASession@13887c2 09-09-16 09:44:03,261 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: returning com.ibm.mq.jms.MQXASession@13887c2 09-09-16 09:44:03,261 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: calling hashCode on JMS driver... 09-09-16 09:44:03,261 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: hashCode returning 31476277 09-09-16 09:44:03,261 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: calling hashCode on JMS driver... 09-09-16 09:44:03,261 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: hashCode returning 31476277 09-09-16 09:44:03,261 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: calling toString on JMS driver session... 09-09-16 09:44:03,261 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: toString returning com.ibm.mq.jms.MQXASession@13887c2 09-09-16 09:44:03,261 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: calling createProducer on JMS driver session com.ibm.mq.jms.MQXASession@13887c2 09-09-16 09:44:03,292 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: createProducer returning atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@e22632 09-09-16 09:44:03,292 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: calling createTextMessage on JMS driver session... 09-09-16 09:44:03,292 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: createTextMessage returning JMS Message class: jms_text JMSType: null JMSDeliveryMode: 2 JMSExpiration: 0 JMSPriority: 4 JMSMessageID: null JMSTimestamp: 0 JMSCorrelationID:null JMSDestination: null JMSReplyTo: null JMSRedelivered: false <?xml version="1.0" encoding="UTF-8" standalone="yes"?><event xmlns="http://events.notifserv.railinc Another 571 character(s) omitted 09-09-16 09:44:03,308 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@e22632: send ( message )... 09-09-16 09:44:03,308 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@e22632: send ( message , heuristicMessage )... 09-09-16 09:44:03,308 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,308 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@e22632: detected transaction com.atomikos.icatch.imp.CompositeTransactionImp@e0a3f2 09-09-16 09:44:03,308 [tomcat-http--4] Coordinator tcServer10000500002 entering state: ACTIVE 09-09-16 09:44:03,308 [tomcat-http--4] Coordinator tcServer10000500002 entered state: ACTIVE 09-09-16 09:44:03,308 [tomcat-http--4] a SessionHandleState with 1 context(s): checking XA context for transaction com.atomikos.icatch.imp.CompositeTransactionImp@e0a3f2 09-09-16 09:44:03,308 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@e22632: error during enlist: Transaction is marked for rollback only or has timed out 09-09-16 09:44:03,308 [tomcat-http--4] error during enlist: Transaction is marked for rollback only or has timed out com.atomikos.datasource.xa.session.InvalidSessionHandleStateException: Transaction is marked for rollback only or has timed out at com.atomikos.datasource.xa.session.NotInBranchStateHandler.checkEnlistBeforeUse(NotInBranchStateHandler.java:34) at com.atomikos.datasource.xa.session.TransactionContext.checkEnlistBeforeUse(TransactionContext.java:60) at com.atomikos.datasource.xa.session.SessionHandleState.notifyBeforeUse(SessionHandleState.java:151) at com.atomikos.jms.ConsumerProducerSupport.enlist(ConsumerProducerSupport.java:67) at com.atomikos.jms.AtomikosJmsMessageProducerProxy.send(AtomikosJmsMessageProducerProxy.java:25) at com.atomikos.jms.AtomikosJmsMessageProducerProxy.send(AtomikosJmsMessageProducerProxy.java:106) at org.springframework.jms.core.JmsTemplate.doSend(JmsTemplate.java:584) at org.springframework.jms.core.JmsTemplate.doSend(JmsTemplate.java:561) at org.springframework.jms.core.JmsTemplate$3.doInJms(JmsTemplate.java:528) at org.springframework.jms.core.JmsTemplate.execute(JmsTemplate.java:459) at org.springframework.jms.core.JmsTemplate.send(JmsTemplate.java:526) at org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:605) at org.springframework.jms.core.JmsTemplate.convertAndSend(JmsTemplate.java:596) at com.railinc.notifserv.event.senders.NotificationServiceEventSender.sendEvent(NotificationServiceEventSender.java:44) at com.railinc.tcServer.service.BillNotificationSenderImpl.reallySend(BillNotificationSenderImpl.java:41) at com.railinc.tcServer.service.BillNotificationSenderImpl.sendNotification(BillNotificationSenderImpl.java:23) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:310) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at $Proxy33.sendNotification(Unknown Source) at com.railinc.tcServer.service.BillServiceController.saveBill(BillServiceController.java:44) at com.railinc.tcServer.service.BillServiceController$$FastClassByCGLIB$$dfe16f24.invoke(<generated>) at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:149) at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:700) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:635) at com.railinc.tcServer.service.BillServiceController$$EnhancerByCGLIB$$e39afa1e.saveBill(<generated>) at com.railinc.tcServer.bill.web.services.rest.BillLookupService.postBill(BillLookupService.java:83) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:166) at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:82) at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:117) at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:77) at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:57) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at org.apache.cxf.workqueue.SynchronousExecutor.execute(SynchronousExecutor.java:37) at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:95) at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:236) at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:89) at org.apache.cxf.transport.servlet.ServletDestination.invoke(ServletDestination.java:99) at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:368) at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:146) at org.apache.cxf.transport.servlet.AbstractCXFServlet.invoke(AbstractCXFServlet.java:163) at org.apache.cxf.transport.servlet.AbstractCXFServlet.doPost(AbstractCXFServlet.java:141) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:379) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619) 09-09-16 09:44:03,308 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@e22632: close... 09-09-16 09:44:03,323 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@e22632: close done. 09-09-16 09:44:03,323 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,323 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,323 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,323 [tomcat-http--4] setRollbackOnly() called for transaction tcServer10000500002 09-09-16 09:44:03,323 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,323 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,323 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,323 [tomcat-http--4] suspend() for transaction tcServer10000500002 09-09-16 09:44:03,323 [tomcat-http--4] getCompositeTransaction() returning NULL! 09-09-16 09:44:03,323 [tomcat-http--4] Coordinator tcServer10000600002 entering state: ACTIVE 09-09-16 09:44:03,323 [tomcat-http--4] Coordinator tcServer10000600002 entered state: ACTIVE 09-09-16 09:44:03,323 [tomcat-http--4] (1.5) executing task: com.atomikos.timing.PooledAlarmTimer@1e64a3b 09-09-16 09:44:03,339 [tomcat-http--4] Creating composite transaction: tcServer10000600002 09-09-16 09:44:03,339 [tomcat-http--4] createCompositeTransaction ( 10000 ): created new ROOT transaction with id tcServer10000600002 09-09-16 09:44:03,339 [tomcat-http--4] AtomikosConnectionFactoryBean 'Bill_MQSeries_XA_RMI': createConnection()... 09-09-16 09:44:03,339 [tomcat-http--4] AtomikosConnectionFactoryBean 'Bill_MQSeries_XA_RMI': init... 09-09-16 09:44:03,339 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000600002 09-09-16 09:44:03,339 [tomcat-http--4] atomikos connection pool 'Bill_MQSeries_XA_RMI': pool reached max size: 1 09-09-16 09:44:03,339 [tomcat-http--4] atomikos connection pool 'Bill_MQSeries_XA_RMI': current size: 1/1 09-09-16 09:44:03,339 [tomcat-http--4] atomikos pooled connection for resource Bill_MQSeries_XA_RMI: updating last time acquired 09-09-16 09:44:03,339 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: calling toString on JMS driver... 09-09-16 09:44:03,339 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: toString returning com.ibm.mq.jms.MQXAConnection@26fbfc 09-09-16 09:44:03,339 [tomcat-http--4] atomikos pooled connection for resource Bill_MQSeries_XA_RMI: returning proxy com.ibm.mq.jms.MQXAConnection@26fbfc 09-09-16 09:44:03,339 [tomcat-http--4] atomikos connection pool 'Bill_MQSeries_XA_RMI': got connection from pool, new size: 0/1 09-09-16 09:44:03,339 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: calling toString on JMS driver... 09-09-16 09:44:03,339 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: toString returning com.ibm.mq.jms.MQXAConnection@26fbfc 09-09-16 09:44:03,339 [tomcat-http--4] AtomikosConnectionFactoryBean 'Bill_MQSeries_XA_RMI': createConnection() returning com.ibm.mq.jms.MQXAConnection@26fbfc 09-09-16 09:44:03,339 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000600002 09-09-16 09:44:03,339 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: creating XA-capable session... 09-09-16 09:44:03,526 [tomcat-http--4] a SessionHandleState with 0 context(s): notifySessionBorrowed 09-09-16 09:44:03,526 [tomcat-http--4] a TransactionContext: changing to state com.atomikos.datasource.xa.session.NotInBranchStateHandler@d593f7 09-09-16 09:44:03,526 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: calling toString on JMS driver session... 09-09-16 09:44:03,526 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: toString returning com.ibm.mq.jms.MQXASession@a4daa3 09-09-16 09:44:03,526 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: returning com.ibm.mq.jms.MQXASession@a4daa3 09-09-16 09:44:03,526 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: calling hashCode on JMS driver... 09-09-16 09:44:03,526 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: hashCode returning 2554876 09-09-16 09:44:03,526 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: calling hashCode on JMS driver... 09-09-16 09:44:03,526 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: hashCode returning 2554876 09-09-16 09:44:03,526 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: calling toString on JMS driver session... 09-09-16 09:44:03,526 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: toString returning com.ibm.mq.jms.MQXASession@a4daa3 09-09-16 09:44:03,526 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: calling createProducer on JMS driver session com.ibm.mq.jms.MQXASession@a4daa3 09-09-16 09:44:03,542 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: createProducer returning atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@104a681 09-09-16 09:44:03,542 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: calling createTextMessage on JMS driver session... 09-09-16 09:44:03,542 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: createTextMessage returning JMS Message class: jms_text JMSType: null JMSDeliveryMode: 2 JMSExpiration: 0 JMSPriority: 4 JMSMessageID: null JMSTimestamp: 0 JMSCorrelationID:null JMSDestination: null JMSReplyTo: null JMSRedelivered: false <?xml version="1.0" encoding="UTF-8" standalone="yes"?><billDocument xmlns="http://railinc.com/bill/ Another 236 character(s) omitted 09-09-16 09:44:03,542 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@104a681: send ( message )... 09-09-16 09:44:03,542 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@104a681: send ( message , heuristicMessage )... 09-09-16 09:44:03,542 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000600002 09-09-16 09:44:03,542 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@104a681: detected transaction com.atomikos.icatch.imp.CompositeTransactionImp@f87478 09-09-16 09:44:03,542 [tomcat-http--4] Coordinator tcServer10000600002 entering state: ACTIVE 09-09-16 09:44:03,542 [tomcat-http--4] Coordinator tcServer10000600002 entered state: ACTIVE 09-09-16 09:44:03,542 [tomcat-http--4] a SessionHandleState with 1 context(s): checking XA context for transaction com.atomikos.icatch.imp.CompositeTransactionImp@f87478 09-09-16 09:44:03,542 [tomcat-http--4] Coordinator tcServer10000600002 entering state: ACTIVE 09-09-16 09:44:03,542 [tomcat-http--4] Coordinator tcServer10000600002 entered state: ACTIVE 09-09-16 09:44:03,542 [tomcat-http--4] addParticipant ( XAResourceTransaction: 74635365727665723130303030363030303032:74635365727665723133 ) for transaction tcServer10000600002 09-09-16 09:44:03,542 [tomcat-http--4] XAResourceTransaction: 74635365727665723130303030363030303032:74635365727665723133: about to switch to XAResource com.ibm.mq.MQXAResource@988dd6 09-09-16 09:44:03,542 [tomcat-http--4] XAResourceTransaction tcServer10000600002tcServer13: switched to XAResource com.ibm.mq.MQXAResource@988dd6 09-09-16 09:44:03,542 [tomcat-http--4] XAResource.start ( 74635365727665723130303030363030303032:74635365727665723133 , XAResource.TMNOFLAGS ) on resource Bill_MQSeries_XA_RMI represented by XAResource instance com.ibm.mq.MQXAResource@988dd6 09-09-16 09:44:03,558 [tomcat-http--4] a TransactionContext: changing to state com.atomikos.datasource.xa.session.BranchEnlistedStateHandler@18806f7 09-09-16 09:44:03,573 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@104a681: send done. 09-09-16 09:44:03,573 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@104a681: send done. 09-09-16 09:44:03,573 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: calling getTransacted on JMS driver session... 09-09-16 09:44:03,573 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: getTransacted returning true 09-09-16 09:44:03,573 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: calling equals on JMS driver session... 09-09-16 09:44:03,573 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: equals returning false 09-09-16 09:44:03,573 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: Calling commit/rollback is not allowed on a managed session! 09-09-16 09:44:03,573 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@104a681: close... 09-09-16 09:44:03,589 [tomcat-http--4] atomikos MessageProducer proxy for com.ibm.mq.jms.MQMessageProducer@104a681: close done. 09-09-16 09:44:03,589 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000600002 09-09-16 09:44:03,589 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000600002 09-09-16 09:44:03,589 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000600002 09-09-16 09:44:03,589 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000600002 09-09-16 09:44:03,589 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000600002 09-09-16 09:44:03,589 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000600002 09-09-16 09:44:03,589 [tomcat-http--4] commit() done (by application) of transaction tcServer10000600002 09-09-16 09:44:03,589 [tomcat-http--4] Coordinator tcServer10000600002 entering state: PREPARING 09-09-16 09:44:03,589 [tomcat-http--4] Coordinator tcServer10000600002 entered state: PREPARING 09-09-16 09:44:03,589 [tomcat-http--4] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@dc420b 09-09-16 09:44:03,589 [tomcat-http--4] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@7413e8 09-09-16 09:44:03,605 [Atomikos:4] XAResource.end ( 74635365727665723130303030363030303032:74635365727665723133 , XAResource.TMSUCCESS ) on resource Bill_MQSeries_XA_RMI represented by XAResource instance com.ibm.mq.MQXAResource@988dd6 09-09-16 09:44:03,605 [Atomikos:4] About to call prepare on XAResource instance: com.ibm.mq.MQXAResource@988dd6 09-09-16 09:44:03,636 [Atomikos:4] XAResource.prepare ( 74635365727665723130303030363030303032:74635365727665723133 ) returning OK on resource Bill_MQSeries_XA_RMI represented by XAResource instance com.ibm.mq.MQXAResource@988dd6 09-09-16 09:44:03,636 [tomcat-http--4] Coordinator tcServer10000600002 entering state: IN_DOUBT 09-09-16 09:44:03,636 [tomcat-http--4] Coordinator tcServer10000600002 entered state: IN_DOUBT 09-09-16 09:44:03,636 [tomcat-http--4] prepare() of Coordinator tcServer10000600002 returning YES vote 09-09-16 09:44:03,636 [tomcat-http--4] Coordinator tcServer10000600002 entering state: COMMITTING 09-09-16 09:44:03,683 [tomcat-http--4] Coordinator tcServer10000600002 entered state: COMMITTING 09-09-16 09:44:03,683 [tomcat-http--4] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@1c5b828 09-09-16 09:44:03,683 [Atomikos:4] XAResource.commit ( 74635365727665723130303030363030303032:74635365727665723133 , false ) on resource Bill_MQSeries_XA_RMI represented by XAResource instance com.ibm.mq.MQXAResource@988dd6 09-09-16 09:44:03,698 [tomcat-http--4] Coordinator tcServer10000600002 entering state: TERMINATED 09-09-16 09:44:03,730 [tomcat-http--4] Coordinator tcServer10000600002 : stopping timer... 09-09-16 09:44:03,730 [tomcat-http--4] Coordinator tcServer10000600002 : disposing statehandler TERMINATED... 09-09-16 09:44:03,730 [tomcat-http--4] Coordinator tcServer10000600002 : disposed. 09-09-16 09:44:03,730 [tomcat-http--4] JmsRequeueSynchronization: detected termination of transaction com.atomikos.icatch.imp.CompositeTransactionImp@f87478 09-09-16 09:44:03,730 [tomcat-http--4] a TransactionContext: changing to state com.atomikos.datasource.xa.session.NotInBranchStateHandler@a53948 09-09-16 09:44:03,730 [tomcat-http--4] JmsRequeueSynchronization: is in terminated state ? false 09-09-16 09:44:03,730 [tomcat-http--4] Coordinator tcServer10000600002 entered state: TERMINATED 09-09-16 09:44:03,745 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: Calling commit/rollback is not allowed on a managed session! 09-09-16 09:44:03,745 [tomcat-http--4] a SessionHandleState with 1 context(s): entering notifySessionClosed 09-09-16 09:44:03,745 [tomcat-http--4] a SessionHandleState with 1 context(s): delegeting session close to a TransactionContext 09-09-16 09:44:03,745 [tomcat-http--4] a TransactionContext: changing state to com.atomikos.datasource.xa.session.TerminatedStateHandler@153d05b 09-09-16 09:44:03,745 [tomcat-http--4] a TransactionContext: changing to state com.atomikos.datasource.xa.session.TerminatedStateHandler@153d05b 09-09-16 09:44:03,745 [tomcat-http--4] a SessionHandleState with 0 context(s): all contexts terminated, firing TerminatedEvent 09-09-16 09:44:03,745 [tomcat-http--4] atomikos pooled connection for resource Bill_MQSeries_XA_RMI: a session has terminated, is connection now available ? false 09-09-16 09:44:03,745 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: destroying JMS session atomikos xa session proxy for resource Bill_MQSeries_XA_RMI 09-09-16 09:44:03,745 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: closing session atomikos xa session proxy for resource Bill_MQSeries_XA_RMI - is terminated ? true 09-09-16 09:44:03,745 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: destroying JMS session atomikos xa session proxy for resource Bill_MQSeries_XA_RMI 09-09-16 09:44:03,745 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: calling close on JMS driver session... 09-09-16 09:44:03,745 [tomcat-http--4] atomikos xa session proxy for resource Bill_MQSeries_XA_RMI: close returning null 09-09-16 09:44:03,745 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: intercepting call to close 09-09-16 09:44:03,745 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: closing 0 session(s) 09-09-16 09:44:03,745 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: is available ? true 09-09-16 09:44:03,745 [tomcat-http--4] atomikos pooled connection for resource Bill_MQSeries_XA_RMI: a session has terminated, is connection now available ? true 09-09-16 09:44:03,745 [tomcat-http--4] atomikos connection proxy for resource Bill_MQSeries_XA_RMI: closing connection and all 0 session(s) 09-09-16 09:44:03,745 [tomcat-http--4] atomikos pooled connection for resource Bill_MQSeries_XA_RMI: notifying listener: atomikos connection pool 'Bill_MQSeries_XA_RMI' 09-09-16 09:44:03,745 [tomcat-http--4] atomikos connection pool 'Bill_MQSeries_XA_RMI': connection atomikos pooled connection for resource Bill_MQSeries_XA_RMI became available, notifying potentially waiting threads 09-09-16 09:44:03,761 [tomcat-http--4] resume ( com.atomikos.icatch.imp.CompositeTransactionImp@e0a3f2 ) done for transaction tcServer10000500002 09-09-16 09:44:03,761 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,761 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,761 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,761 [tomcat-http--4] getCompositeTransaction() returning instance with id tcServer10000500002 09-09-16 09:44:03,761 [tomcat-http--4] Coordinator tcServer10000500002 entering state: ABORTING 09-09-16 09:44:03,761 [tomcat-http--4] Coordinator tcServer10000500002 entered state: ABORTING 09-09-16 09:44:03,761 [tomcat-http--4] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@19a8942 09-09-16 09:44:03,761 [tomcat-http--4] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@a96eba 09-09-16 09:44:03,761 [tomcat-http--4] Coordinator tcServer10000500002 entering state: TERMINATED 09-09-16 09:44:03,761 [tomcat-http--4] Coordinator tcServer10000500002 : stopping timer... 09-09-16 09:44:03,761 [tomcat-http--4] Coordinator tcServer10000500002 : disposing statehandler TERMINATED... 09-09-16 09:44:03,761 [tomcat-http--4] Coordinator tcServer10000500002 : disposed. 09-09-16 09:44:03,761 [tomcat-http--4] JmsRequeueSynchronization: detected termination of transaction com.atomikos.icatch.imp.CompositeTransactionImp@e0a3f2 09-09-16 09:44:03,761 [tomcat-http--4] a TransactionContext: changing to state null 09-09-16 09:44:03,761 [tomcat-http--4] JmsRequeueSynchronization: is in terminated state ? false 09-09-16 09:44:03,761 [tomcat-http--4] Coordinator tcServer10000500002 entered state: TERMINATED 09-09-16 09:44:03,761 [tomcat-http--4] rollback() done of transaction tcServer10000500002 09-09-16 09:44:03,777 [tomcat-http--4] a SessionHandleState with 1 context(s): entering notifySessionClosed 09-09-16 09:44:03,777 [tomcat-http--4] a SessionHandleState with 1 context(s): delegeting session close to a TransactionContext 09-09-16 09:44:03,777 [tomcat-http--4] a TransactionContext: changing state to com.atomikos.datasource.xa.session.TerminatedStateHandler@3e3c83 09-09-16 09:44:03,777 [tomcat-http--4] a TransactionContext: changing to state com.atomikos.datasource.xa.session.TerminatedStateHandler@3e3c83 09-09-16 09:44:03,777 [tomcat-http--4] a SessionHandleState with 0 context(s): all contexts terminated, firing TerminatedEvent 09-09-16 09:44:03,777 [tomcat-http--4] atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI: a session has terminated, is connection now available ? false 09-09-16 09:44:03,777 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: destroying JMS session atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI 09-09-16 09:44:03,777 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: closing session atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI - is terminated ? true 09-09-16 09:44:03,777 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: destroying JMS session atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI 09-09-16 09:44:03,777 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: calling close on JMS driver session... 09-09-16 09:44:03,777 [tomcat-http--4] atomikos xa session proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: close returning null 09-09-16 09:44:03,777 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: intercepting call to close 09-09-16 09:44:03,792 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: closing 0 session(s) 09-09-16 09:44:03,792 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: is available ? true 09-09-16 09:44:03,792 [tomcat-http--4] atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI: a session has terminated, is connection now available ? true 09-09-16 09:44:03,792 [tomcat-http--4] atomikos connection proxy for resource Bill_Notif_Serv_MQSeries_XA_RMI: closing connection and all 0 session(s) 09-09-16 09:44:03,792 [tomcat-http--4] atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI: notifying listener: atomikos connection pool 'Bill_Notif_Serv_MQSeries_XA_RMI' 09-09-16 09:44:03,792 [tomcat-http--4] atomikos connection pool 'Bill_Notif_Serv_MQSeries_XA_RMI': connection atomikos pooled connection for resource Bill_Notif_Serv_MQSeries_XA_RMI became available, notifying potentially waiting threads
A final point,
I'm simulating a rollback by sending in a certain value that throws a runtime exception. If I send in "valid" values that results in a commit everything looks fine. The actual physical rollback from the queue in question and both databases appears to be working fine. (I also have another queue I drop a message on, but it has a REQUIRES_NEW transaction on it, and it gets committed correctly). So to summarize I'm ok with the behavior, just curious about the stacktraces. Thanks
Excellent, thanks Guy,
I was playing around with my simulated rollback code and by changing its behavior this stacktrace went away. What I was doing was in one service class executing all 4 transactions and catching any exception it might throw. Then at the end of that service class throwing an exception if anything failed (this was so I could test out different commit/rollback scenarios with different transactional policies). I removed this catch & re-throw "hack" and let the first exception thrown just bubble on up and now I get the stacktraces I expect + the right behavior. |