Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-8635

Recovery doesn't work when transaction is propagated thru EJB remoting

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Blocker Blocker
    • 7.1.0.ER2
    • 7.1.0.DR11
    • EJB, Transactions
    • None
    • Hide
      git clone http://git.app.eng.bos.redhat.com/git/jbossqe-eap-tests-transactions.gitexport JBOSS_HOME=... (downloadable at http://download.eng.brq.redhat.com/devel/candidates/JBEAP/)
      
      DS_PROPS="-Dds0.db=postgresql -Dds0.jdbc.driver.url=http://www.qa.jboss.com/jdbc-drivers-products/EAP/7.1.0/postgresql94/jdbc4/postgresql-9.4.1209.jar -Dds0.jdbc.xa-class=org.postgresql.xa.PGXADataSource -Dds0.jdbc.url=jdbc:postgresql://gen-vm006.mw.lab.eng.bos.redhat.com:5432/crashrec -Dds0.db.name=crashrec -Dds0.user=crashrec -Dds0.pass=crashrec -Dds0.jdbc.driver.jar=postgresql-driver.jar -Dds1.db=postgresql -Dds1.jdbc.driver.url=http://www.qa.jboss.com/jdbc-drivers-products/EAP/7.1.0/postgresql94/jdbc4/postgresql-9.4.1209.jar -Dds1.jdbc.xa-class=org.postgresql.xa.PGXADataSource -Dds1.jdbc.url=jdbc:postgresql://gen-vm006.mw.lab.eng.bos.redhat.com:5432/crashrec -Dds1.db.name=crashrec2 -Dds1.user=crashrec2 -Dds1.pass=crashrec2 -Dds1.jdbc.driver.jar=postgresql-driver.jar"
      
      mvn clean verify -am -pl jbossts -fn -Djbossts.noJTS $DS_PROPS -Dtest=TxPropagationJPACrashRecoveryTestCase#commitHaltServer
      
      Show
      git clone http: //git.app.eng.bos.redhat.com/git/jbossqe-eap-tests-transactions.gitexport JBOSS_HOME=... (downloadable at http://download.eng.brq.redhat.com/devel/candidates/JBEAP/) DS_PROPS= "-Dds0.db=postgresql -Dds0.jdbc.driver.url=http: //www.qa.jboss.com/jdbc-drivers-products/EAP/7.1.0/postgresql94/jdbc4/postgresql-9.4.1209.jar -Dds0.jdbc.xa-class=org.postgresql.xa.PGXADataSource -Dds0.jdbc.url=jdbc:postgresql://gen-vm006.mw.lab.eng.bos.redhat.com:5432/crashrec -Dds0.db.name=crashrec -Dds0.user=crashrec -Dds0.pass=crashrec -Dds0.jdbc.driver.jar=postgresql-driver.jar -Dds1.db=postgresql -Dds1.jdbc.driver.url=http://www.qa.jboss.com/jdbc-drivers-products/EAP/7.1.0/postgresql94/jdbc4/postgresql-9.4.1209.jar -Dds1.jdbc.xa-class=org.postgresql.xa.PGXADataSource -Dds1.jdbc.url=jdbc:postgresql://gen-vm006.mw.lab.eng.bos.redhat.com:5432/crashrec -Dds1.db.name=crashrec2 -Dds1.user=crashrec2 -Dds1.pass=crashrec2 -Dds1.jdbc.driver.jar=postgresql-driver.jar" mvn clean verify -am -pl jbossts -fn -Djbossts.noJTS $DS_PROPS -Dtest=TxPropagationJPACrashRecoveryTestCase#commitHaltServer

      We have test where tx is propagated (thru EJB remoting) from one server to another. We halt second server during 2PC and then start it again. The transaction should be recovered by TM. The scenario is like:

      1. enlist and use 2 XA resources on server 1
      2. call an ejb on server 2
      3. enlist and use 2 XA resources on server 2
      4. prepare phase - preparing all 4 resources on both servers
      5. commit phase starts
      6. crash JVM of server 2
      7. start server 2 once again
      8. run recovery

      Recovery ends on NPE.

      First server log:

      2017-02-02 15:17:33,802 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::phase2Commit() for action-id 0:ffff7f000001:1ef56039:58933eec:21
      2017-02-02 15:17:33,802 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) BasicAction::doCommit (XAResourceRecord < resource:RecoveryOnlySerializedEJBXAResource{ejbReceiverNodeName='jbossts2'}, txid:< formatId=131077, gtrid_length=32, bqual_length=36, tx_uid=0:ffff7f000001:1ef56039:58933eec:21, node_name=PJrQ, branch_uid=0:ffff7f000001:1ef56039:58933eec:23, subordinatenodename=null, eis_name=unknown eis name >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@e7bfebe >)
      2017-02-02 15:17:33,802 TRACE [com.arjuna.ats.jta] (Periodic Recovery) XAResourceRecord.topLevelCommit for XAResourceRecord < resource:RecoveryOnlySerializedEJBXAResource{ejbReceiverNodeName='jbossts2'}, txid:< formatId=131077, gtrid_length=32, bqual_length=36, tx_uid=0:ffff7f000001:1ef56039:58933eec:21, node_name=PJrQ, branch_uid=0:ffff7f000001:1ef56039:58933eec:23, subordinatenodename=null, eis_name=unknown eis name >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@e7bfebe >, record id=0:ffff7f000001:1ef56039:58933eec:24
      2017-02-02 15:17:33,802 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) RecoveryOnlySerializedEJBXAResource{ejbReceiverNodeName='jbossts2'} sending commit request for Xid < formatId=131077, gtrid_length=32, bqual_length=36, tx_uid=0:ffff7f000001:1ef56039:58933eec:21, node_name=PJrQ, branch_uid=0:ffff7f000001:1ef56039:58933eec:23, subordinatenodename=null, eis_name=unknown eis name > to EJB receiver with node name jbossts2 during recovery. One phase? false
      2017-02-02 15:17:36,834 TRACE [org.jboss.ejb.client.remoting.ChannelAssociation] (default task-44) Received message with header 0x6
      2017-02-02 15:17:36,983 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016036: commit on < formatId=131077, gtrid_length=32, bqual_length=36, tx_uid=0:ffff7f000001:1ef56039:58933eec:21, node_name=PJrQ, branch_uid=0:ffff7f000001:1ef56039:58933eec:23, subordinatenodename=null, eis_name=unknown eis name > (RecoveryOnlySerializedEJBXAResource{ejbReceiverNodeName='jbossts2'}) failed with exception $XAException.XAER_RMFAIL: javax.transaction.xa.XAException
      	at org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver.sendCommit(RemotingConnectionEJBReceiver.java:507)
      	at org.jboss.ejb.client.RecoveryOnlySerializedEJBXAResource.commit(RecoveryOnlySerializedEJBXAResource.java:63)
      	at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit(XAResourceRecord.java:514)
      	at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2890)
      	at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2806)
      	at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1871)
      	at com.arjuna.ats.arjuna.recovery.RecoverAtomicAction.replayPhase2(RecoverAtomicAction.java:71)
      	at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.doRecoverTransaction(AtomicActionRecoveryModule.java:152)
      	at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactionsStatus(AtomicActionRecoveryModule.java:253)
      	at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass(AtomicActionRecoveryModule.java:109)
      	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811)
      	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377)
      Caused by: java.lang.NullPointerException
      	at org.jboss.as.ejb3.remote.protocol.versionone.XidTransactionCommitTask.manageTransaction(XidTransactionCommitTask.java:73)
      	at org.jboss.as.ejb3.remote.protocol.versionone.XidTransactionManagementTask.run(XidTransactionManagementTask.java:68)
      	at org.jboss.as.ejb3.remote.protocol.versionone.TransactionRequestHandler.processMessage(TransactionRequestHandler.java:139)
      	at org.jboss.as.ejb3.remote.protocol.versionone.VersionOneProtocolChannelReceiver.processMessage(VersionOneProtocolChannelReceiver.java:212)
      	at org.jboss.as.ejb3.remote.protocol.versiontwo.VersionTwoProtocolChannelReceiver.processMessage(VersionTwoProtocolChannelReceiver.java:77)
      	at org.jboss.as.ejb3.remote.protocol.versionone.VersionOneProtocolChannelReceiver.handleMessage(VersionOneProtocolChannelReceiver.java:158)
      	at org.jboss.remoting3.remote.RemoteConnectionChannel.lambda$handleMessageData$3(RemoteConnectionChannel.java:434)
      	at org.jboss.remoting3.EndpointImpl$TrackingExecutor.lambda$execute$0(EndpointImpl.java:789)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      	at java.lang.Thread.run(Thread.java:745)
      	at ...asynchronous invocation...(Unknown Source)
      	at org.jboss.ejb.client.remoting.InvocationExceptionResponseHandler$MethodInvocationExceptionResultProducer.getResult(InvocationExceptionResponseHandler.java:96)
      	at org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver.sendCommit(RemotingConnectionEJBReceiver.java:503)
      	... 11 more
      

      Server 2:

      2017-02-02 15:17:36,696 TRACE [com.arjuna.ats.arjuna] (default task-7)  Restored heuristic decision of TwoPhaseOutcome.PREPARE_OK 0
      2017-02-02 15:17:36,696 TRACE [com.arjuna.ats.jta] (default task-7) TransactionImple.getStatus: javax.transaction.Status.STATUS_UNKNOWN
      2017-02-02 15:17:36,696 TRACE [com.arjuna.ats.jta] (default task-7) TransactionImpleManager.suspend
      2017-02-02 15:17:36,696 TRACE [com.arjuna.ats.jta] (default task-7) TransactionImpleManager.suspend
      2017-02-02 15:17:36,696 ERROR [org.jboss.as.ejb3.remote] (default task-7) WFLYEJB0155: Error during transaction management of transaction id XidTransactionID [485048484850484848535048484848484848484848484848484848484848484870707070557048484848484949697053544851575356575151696967484848484848504953485265555053495052484848484848484848484848484848484848484870707070557048484848484949697053544851575356575151696967484848484848505148484848484848484848484848484848]: java.lang.NullPointerException
      	at org.jboss.as.ejb3.remote.protocol.versionone.XidTransactionCommitTask.manageTransaction(XidTransactionCommitTask.java:73)
      	at org.jboss.as.ejb3.remote.protocol.versionone.XidTransactionManagementTask.run(XidTransactionManagementTask.java:68)
      	at org.jboss.as.ejb3.remote.protocol.versionone.TransactionRequestHandler.processMessage(TransactionRequestHandler.java:139)
      	at org.jboss.as.ejb3.remote.protocol.versionone.VersionOneProtocolChannelReceiver.processMessage(VersionOneProtocolChannelReceiver.java:212)
      	at org.jboss.as.ejb3.remote.protocol.versiontwo.VersionTwoProtocolChannelReceiver.processMessage(VersionTwoProtocolChannelReceiver.java:77)
      	at org.jboss.as.ejb3.remote.protocol.versionone.VersionOneProtocolChannelReceiver.handleMessage(VersionOneProtocolChannelReceiver.java:158)
      	at org.jboss.remoting3.remote.RemoteConnectionChannel.lambda$handleMessageData$3(RemoteConnectionChannel.java:434)
      	at org.jboss.remoting3.EndpointImpl$TrackingExecutor.lambda$execute$0(EndpointImpl.java:789)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      	at java.lang.Thread.run(Thread.java:745)
      
      2017-02-02 15:17:37,300 TRACE [com.arjuna.ats.arjuna] (default task-8) InputObjectState::InputObjectState()
      

      It seems to me that regression was caused by this commit: https://github.com/wildfly/wildfly/commit/32afade7748d158c9b91502d86af85d9054d936c

        1. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server1.log
          891 kB
        2. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server2.log
          1.32 MB
        3. server1.log
          329 kB
        4. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server.log
          384 kB
        5. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server.log
          468 kB
        6. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server-jbossts2.log
          126 kB
        7. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server.log
          405 kB
        8. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server2.log
          450 kB
        9. org.jboss.as.test.jbossts.crashrec.txpropagation.test.TxPropagationJPACrashRecoveryTestCase-jta.txt
          12 kB
        10. org.jboss.as.test.jbossts.crashrec.txpropagation.test.TxPropagationJPACrashRecoveryTestCase-jta-output.txt
          379 kB
        11. org.jboss.as.test.jbossts.crashrec.txpropagation.test.TxPropagationJPACrashRecoveryTestCase-jta.txt
          12 kB
        12. org.jboss.as.test.jbossts.crashrec.txpropagation.test.TxPropagationJPACrashRecoveryTestCase-jta-output.txt
          379 kB
        13. TEST-org.jboss.as.test.jbossts.crashrec.txpropagation.test.TxPropagationJPACrashRecoveryTestCase-jta.xml
          399 kB
        14. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server.log
          406 kB
        15. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server2.log
          451 kB
        16. TxPropagationJPACrashRecoveryTestCase_commitHaltServer-postgres-ochaloup-passing.zip
          104 kB

              flaviarnn Flavia Rainone
              dsimko Daniel Simko (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

                Created:
                Updated:
                Resolved: