JTS works incorrectly for JMS connection being interrupted at commit phase -------------------------------------------------------------------------- Key: JBTM-2771 URL: https://issues.jboss.org/browse/JBTM-2771 Project: JBoss Transaction Manager Issue Type: Bug Components: JTS Affects Versions: 5.3.5.Final Reporter: Ondra Chaloupka Assignee: Tom Jenkinson Priority: Blocker Attachments: JMSProxyMessagingServerCrashRecoveryTestCase_prepareHalt_jts_server.log I do experience regression against DR5 (Narayana 5.3.3.Final) with current DR6 (Narayana 5.3.5.Final) release. The following scenario fails when JTS is used {quote} * prepare jms XA * stop connection to jms broker * prepare test XA * call commit on jms XA as connection is down we can experience {{XAException.XA_RETRY}} * commit test XA (the test XA is committed as XA_RETRY commands to finish the commit later which is made by recovery) * recovery: commit jms XA {quote} in 7.1.0.DR6 version the recovery does not {{commit}} but {{rollback}} which can cause data integrity failure. {code} 2016-10-11 17:03:32,194 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( getStatus ) nodeId=1 requestId=135 2016-10-11 17:03:32,194 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( getStatus ) nodeId=1 requestId=135 2016-10-11 17:03:32,194 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( getStatus ) nodeId=1 requestId=132 2016-10-11 17:03:32,194 DEBUG [com.arjuna.ats.jts] (Periodic Recovery) StatusChecker.getStatus(0:ffff7f000001:-687fd072:57fcfee8:4f) - stored status = CosTransactions::StatusNoTransaction 2016-10-11 17:03:32,195 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::send_reply ( replay_completion ) nodeId=1 requestId=133 2016-10-11 17:03:32,195 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionServerRequestInterceptorImpl::suspendContext ( replay_completion ) nodeId=1 requestId=133 2016-10-11 17:03:32,195 DEBUG [com.arjuna.ats.jts] (Thread-276) ResourceCompletor.rollback() 2016-10-11 17:03:32,195 TRACE [com.arjuna.ats.jts] (Periodic Recovery) InterpositionClientRequestInterceptorImpl::receive_reply ( replay_completion ) nodeId=1 requestId=130 2016-10-11 17:03:32,196 TRACE [com.arjuna.ats.jts] (Thread-276) InterpositionClientRequestInterceptorImpl::send_request ( rollback ) nodeId=1 requestId=133 2016-10-11 17:03:32,196 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.recover got status: CosTransactions::StatusRolledBack 2016-10-11 17:03:32,196 TRACE [com.arjuna.ats.jts] (Thread-276) ContextManager::current () 2016-10-11 17:03:32,196 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.doRecovery ( false ) 2016-10-11 17:03:32,196 INFO [com.arjuna.ats.jtax] (Periodic Recovery) ARJUNA024002: XA recovery rolling back < 131072, 29, 36, 0000000000-1-1127001-105-12847-11487-4-2-240007949, 0000000000-1-1127001-105-12847-11487-4-2-240008400000000 > 2016-10-11 17:03:32,196 TRACE [com.arjuna.ats.jtax] (Periodic Recovery) XAResourceRecord.rollback for < 131072, 29, 36, 0000000000-1-1127001-105-12847-11487-4-2-240007949, 0000000000-1-1127001-105-12847-11487-4-2-240008400000000 > 2016-10-11 17:03:32,196 TRACE [com.arjuna.ats.jts] (Thread-276) InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( rollback ) nodeId=1 requestId=136 2016-10-11 17:03:32,196 TRACE [com.arjuna.ats.jts] (Thread-276) InterpositionServerRequestInterceptorImpl::receive_request ( rollback ) nodeId=1 requestId=136 2016-10-11 17:03:32,196 TRACE [org.apache.activemq.artemis.core.client.impl.ClientSessionImpl] (Periodic Recovery) Calling rollback:: xid=XidImpl (948004762 bq:0.0.0.0.0.0.0.0.0.0.-1.-1.127.0.0.1.-105.-128.47.-114.87.-4.-2.-24.0.0.0.84.0.0.0.0.0.0.0.0 formatID:131072 gtxid:0.0.0.0.0.0.0.0.0.0.-1.-1.127.0.0.1.-105.-128.47.-114.87.-4.-2.-24.0.0.0.79.49 base64:AAAAAAAAAAAAAP__fwAAAZeAL45X_P7oAAAAVAAAAAAAAAAAAAAAAAAAAAAAAP__fwAAAZeAL45X_P7oAAAATzECAgIA,clientXID=< 131072, 29, 36, 0000000000-1-1127001-105-12847-11487-4-2-240007949, 0000000000-1-1127001-105-12847-11487-4-2-240008400000000 > 2016-10-11 17:03:32,196 TRACE [com.arjuna.ats.jtax] (Thread-276) XAResourceRecord.rollback for < 131072, 29, 36, 0000000000-1-1127001-105-12847-11487-4-2-240007949, 0000000000-1-1127001-105-12847-11487-4-2-240008400000000 > 2016-10-11 17:03:32,196 TRACE [org.apache.activemq.artemis.core.client.impl.ClientSessionImpl] (Thread-276) Calling rollback:: xid=XidImpl (1942398309 bq:0.0.0.0.0.0.0.0.0.0.-1.-1.127.0.0.1.-105.-128.47.-114.87.-4.-2.-24.0.0.0.84.0.0.0.0.0.0.0.0 formatID:131072 gtxid:0.0.0.0.0.0.0.0.0.0.-1.-1.127.0.0.1.-105.-128.47.-114.87.-4.-2.-24.0.0.0.79.49 base64:AAAAAAAAAAAAAP__fwAAAZeAL45X_P7oAAAAVAAAAAAAAAAAAAAAAAAAAAAAAP__fwAAAZeAL45X_P7oAAAATzECAgIA,clientXID=< 131072, 29, 36, 0000000000-1-1127001-105-12847-11487-4-2-240007949, 0000000000-1-1127001-105-12847-11487-4-2-240008400000000 > 2016-10-11 17:03:32,197 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl] (Periodic Recovery) Sending blocking PACKET(SessionXARollbackMessage)[type=56, channelID=10, packetObject=SessionXARollbackMessage] 2016-10-11 17:03:32,240 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.RemotingConnectionImpl] (Thread-3 (ActiveMQ-client-netty-threads-2140185711)) handling packet PACKET(SessionXAResponseMessage)[type=55, channelID=10, packetObject=SessionXAResponseMessage] 2016-10-11 17:03:32,241 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) HornetqObjectStore.remove_committed(0:ffff7f000001:-687fd072:57fcfee8:55, /CosTransactions/XAResourceRecord) 2016-10-11 17:03:32,241 TRACE [org.apache.activemq.artemis.core.journal.impl.JournalImpl] (Periodic Recovery) appendDeleteRecord::id=1, usedFile = JournalFileImpl: (jbossts-1.txlog id = 1, recordID = 1) 2016-10-11 17:03:32,241 TRACE [org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl] (Thread-276) Sending blocking PACKET(SessionXARollbackMessage)[type=56, channelID=10, packetObject=SessionXARollbackMessage] 2016-10-11 17:03:32,247 TRACE [com.arjuna.orbportability] (Periodic Recovery) RootOA::shutdownObject (Servant) 2016-10-11 17:03:32,248 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@4b366010, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5db75d15}, transactionOriginNodeIdentifier='1'} 1476198202113 1476198212248 false 2016-10-11 17:03:32,251 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check TestXAResourceRecovered(TestXAResourceCommon(id:473, xid:null, timeout:0, prepareReturn:0)) 1476198162076 1476198212248 true 2016-10-11 17:03:32,251 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@16b79fd1 1476198161776 1476198212251 true 2016-10-11 17:03:32,251 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) RecoveryXids isStale Check org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@130c1cb1 1476198202161 1476198212251 false 2016-10-11 17:03:32,251 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) JTS XARecoveryModule.resourceInitiatedRecovery completed {code}