Atomikos Forum
stacktrace on rollback |
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)
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>
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
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
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
Hi,
This looks OK. This is a warning that happens if you reuse a connection after its transaction has rolled back. Afterwards, Spring should refresh the connection and you should be fine.
HTH
This looks OK. This is a warning that happens if you reuse a connection after its transaction has rolled back. Afterwards, Spring should refresh the connection and you should be fine.
HTH
Guy Pardon 
Wednesday, September 16, 2009
Wednesday, September 16, 2009
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.
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.
Other recent topics