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. org.jboss.as.test.jbossts.crashrec.txpropagation.test.TxPropagationJPACrashRecoveryTestCase-jta.txt
          12 kB
          Flavia Rainone
        2. org.jboss.as.test.jbossts.crashrec.txpropagation.test.TxPropagationJPACrashRecoveryTestCase-jta.txt
          12 kB
          Flavia Rainone
        3. org.jboss.as.test.jbossts.crashrec.txpropagation.test.TxPropagationJPACrashRecoveryTestCase-jta-output.txt
          379 kB
          Flavia Rainone
        4. org.jboss.as.test.jbossts.crashrec.txpropagation.test.TxPropagationJPACrashRecoveryTestCase-jta-output.txt
          379 kB
          Flavia Rainone
        5. server1.log
          329 kB
          Daniel Simko
        6. TEST-org.jboss.as.test.jbossts.crashrec.txpropagation.test.TxPropagationJPACrashRecoveryTestCase-jta.xml
          399 kB
          Flavia Rainone
        7. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server.log
          406 kB
          Flavia Rainone
        8. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server.log
          405 kB
          Flavia Rainone
        9. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server.log
          468 kB
          Flavia Rainone
        10. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server.log
          384 kB
          Flavia Rainone
        11. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server1.log
          891 kB
          Daniel Simko
        12. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server2.log
          451 kB
          Flavia Rainone
        13. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server2.log
          450 kB
          Flavia Rainone
        14. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server2.log
          1.32 MB
          Daniel Simko
        15. TxPropagationJPACrashRecoveryTestCase_commitHaltServer_jta_server-jbossts2.log
          126 kB
          Flavia Rainone

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

              Created:
              Updated:
              Resolved: