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

NPE when trying delete heuristic transaction (with CMR resource) from JDBC tx log-store

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Critical Critical
    • 7.1.0.DR9
    • 7.1.0.DR6
    • Transactions
    • None
    • Regression
    • Hide

      git clone http://git.app.eng.bos.redhat.com/git/jbossqe-eap-tests-transactions.git

      export JBOSS_HOME=... (downloadable at http://download.eng.brq.redhat.com/devel/candidates/JBEAP/)

      DS_PROPS="-Dds0.db=oracle -Dds0.jdbc.driver.url=http://www.qa.jboss.com/jdbc-drivers-products/EAP/7.1.0/oracle12c/jdbc4/ojdbc7.jar -Dds0.jdbc.xa-class=oracle.jdbc.xa.client.OracleXADataSource -Dds0.jdbc.url=jdbc:oracle:thin:@dev151.mw.lab.eng.bos.redhat.com:1521:qaora12 -Dds0.db.name=qaora12 -Dds0.user=crashrec -Dds0.pass=crashrec -Dds0.jdbc.driver.jar=dsdriver-oracle.jar"

      mvn clean verify -am -pl jbossts -DfailIfNoTests=false -Djbossts.noJTS -Djbossts.objectstore.type=jdbc -Dtest=ToolingCMRTestCase#haltCMRHeuristicMix $DS_PROPS

      Show
      git clone http://git.app.eng.bos.redhat.com/git/jbossqe-eap-tests-transactions.git export JBOSS_HOME=... (downloadable at http://download.eng.brq.redhat.com/devel/candidates/JBEAP/ ) DS_PROPS="-Dds0.db=oracle -Dds0.jdbc.driver.url= http://www.qa.jboss.com/jdbc-drivers-products/EAP/7.1.0/oracle12c/jdbc4/ojdbc7.jar -Dds0.jdbc.xa-class=oracle.jdbc.xa.client.OracleXADataSource -Dds0.jdbc.url=jdbc:oracle:thin:@dev151.mw.lab.eng.bos.redhat.com:1521:qaora12 -Dds0.db.name=qaora12 -Dds0.user=crashrec -Dds0.pass=crashrec -Dds0.jdbc.driver.jar=dsdriver-oracle.jar" mvn clean verify -am -pl jbossts -DfailIfNoTests=false -Djbossts.noJTS -Djbossts.objectstore.type=jdbc -Dtest=ToolingCMRTestCase#haltCMRHeuristicMix $DS_PROPS

      Part of the test is cleaning tx log-store:

      14:36:46,747 ERROR [org.jboss.as.test.jbossts.base.setup.operations.TMOperations] (main) Management operation {
          "operation" => "delete",
          "address" => [
              ("subsystem" => "transactions"),
              ("log-store" => "log-store"),
              ("transactions" => "0:ffff7f000001:-475b5c9c:5804af44:31")
          ]
      } failed: {
          "outcome" => "failed",
          "failure-description" => "java.lang.NullPointerException",
          "rolled-back" => true
      }
      

      but fails with NPE. Server log:

      2016-10-17 14:36:42,798 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) InputObjectState::InputObjectState()
      2016-10-17 14:36:42,798 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) OutputObjectState::OutputObjectState()
      2016-10-17 14:36:43,140 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) StateManager::StateManager( 0:ffff7f000001:-475b5c9c:5804af44:31 )
      2016-10-17 14:36:43,140 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) BasicAction::BasicAction(0:ffff7f000001:-475b5c9c:5804af44:31)
      2016-10-17 14:36:43,141 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) BasicAction::activate() for action-id 0:ffff7f000001:-475b5c9c:5804af44:31
      2016-10-17 14:36:43,308 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) InputObjectState::InputObjectState(0:ffff7f000001:-475b5c9c:5804af44:31, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
      2016-10-17 14:36:43,474 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) BasicAction::restore_state ()
      2016-10-17 14:36:43,475 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) StateManager.unpackHeader for object-id 0:ffff7f000001:-475b5c9c:5804af44:31 birth-date 1476707800081
      2016-10-17 14:36:43,475 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) Unpacked a 463 record
      2016-10-17 14:36:43,475 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) HeuristicList - Unpacked heuristic list size of 1
      2016-10-17 14:36:43,475 WARN  [com.arjuna.ats.arjuna] (management-handler-thread - 4) Transaction 0:ffff7f000001:-475b5c9c:5804af44:31 has 1 heuristic participant(s)!
      2016-10-17 14:36:43,475 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) HeuristicList - Unpacked a 50 record
      2016-10-17 14:36:43,475 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) StateManager::StateManager( 0:0:0:0:0 )
      2016-10-17 14:36:43,475 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) AbstractRecord::AbstractRecord () - crash recovery constructor
      2016-10-17 14:36:43,475 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) CommitMarkableResourceRecord.CommitMarkableResourceRecord (), record id=-8000000000000000:-8000000000000000:-80000000:-80000000:-80000000
      2016-10-17 14:36:43,475 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) unpack: java:jboss/xa-datasources/CrashRecoveryDS
      2016-10-17 14:36:43,475 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) unpack: < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-475b5c9c:5804af44:31, node_name=1, branch_uid=0:ffff7f000001:-475b5c9c:5804af44:37, subordinatenodename=null, eis_name=java:jboss/xa-datasources/CrashRecoveryDS >
      2016-10-17 14:36:43,476 TRACE [com.arjuna.ats.jta] (management-handler-thread - 4) TransactionSynchronizationRegistryImple.getTransactionKey
      2016-10-17 14:36:43,476 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) Attempting to delete number of entries: 2
      2016-10-17 14:36:43,991 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) CommitMarkableResourceRecordRecoveryModule::periodicWorkFirstPass
      2016-10-17 14:36:43,991 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) CommitMarkableResourceRecordRecoveryModule::connecting to: java:jboss/xa-datasources/CrashRecoveryDS
      2016-10-17 14:36:43,991 TRACE [com.arjuna.ats.jta] (management-handler-thread - 4) TransactionSynchronizationRegistryImple.getTransactionKey
      2016-10-17 14:36:44,334 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) InputObjectState::InputObjectState()
      2016-10-17 14:36:44,335 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) OutputObjectState::OutputObjectState()
      2016-10-17 14:36:44,669 DEBUG [com.arjuna.ats.arjuna] (management-handler-thread - 4) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
      2016-10-17 14:36:44,669 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) InputObjectState::InputObjectState()
      2016-10-17 14:36:44,669 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) OutputObjectState::OutputObjectState()
      2016-10-17 14:36:45,002 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) InputObjectState::InputObjectState()
      2016-10-17 14:36:45,002 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) OutputObjectState::OutputObjectState()
      2016-10-17 14:36:45,838 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) InputObjectState::InputObjectState(0:ffff7f000001:-475b5c9c:5804af44:31, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
      2016-10-17 14:36:46,004 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) StateManager::StateManager( 0:ffff7f000001:-475b5c9c:5804af44:31 )
      2016-10-17 14:36:46,004 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) BasicAction::BasicAction(0:ffff7f000001:-475b5c9c:5804af44:31)
      2016-10-17 14:36:46,005 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) StateManager.unpackHeader for object-id 0:ffff7f000001:-475b5c9c:5804af44:31 birth-date 1476707800081
      2016-10-17 14:36:46,005 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) wasCommitted< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-475b5c9c:5804af44:31, node_name=1, branch_uid=0:ffff7f000001:-475b5c9c:5804af44:37, subordinatenodename=null, eis_name=java:jboss/xa-datasources/CrashRecoveryDS > null
      2016-10-17 14:36:46,005 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/CommitMarkableResourceRecord for -8000000000000000:-8000000000000000:-80000000:-80000000:-80000000
      2016-10-17 14:36:46,005 WARN  [com.arjuna.ats.arjuna] (management-handler-thread - 4) Transaction 0:ffff7f000001:-475b5c9c:5804af44:31 restored heuristic participant com.arjuna.ats.internal.jta.resources.arjunacore.CommitMarkableResourceRecord@2493dae0
      2016-10-17 14:36:46,005 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) HeuristicList - Unpacked a 463 record
      2016-10-17 14:36:46,005 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) Restored action status of ActionStatus.COMMITTED 7
      2016-10-17 14:36:46,005 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) Restored action type Top-level 0
      2016-10-17 14:36:46,005 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4)  Restored heuristic decision of TwoPhaseOutcome.HEURISTIC_ROLLBACK 3
      2016-10-17 14:36:46,005 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) StateManager::StateManager( 0:ffff7f000001:-475b5c9c:5804af44:31 )
      2016-10-17 14:36:46,174 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) InputObjectState::InputObjectState(0:ffff7f000001:-475b5c9c:5804af44:31, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
      2016-10-17 14:36:46,344 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) StateManager::activate( null) for object-id 0:0:0:0:0
      2016-10-17 14:36:46,345 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) StateManager::setupStore ( null )
      2016-10-17 14:36:46,682 WARN  [com.arjuna.ats.arjuna] (management-handler-thread - 4) ARJUNA012035: Activate of object with id = 0:0:0:0:0 and type /StateManager/AbstractRecord/CommitMarkableResourceRecord unexpectedly failed
      2016-10-17 14:36:46,682 TRACE [com.arjuna.ats.arjuna] (management-handler-thread - 4) Registering: jboss.jta:type=ObjectStore,itype=StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction,uid=0_ffff7f000001_-475b5c9c_5804af44_31
      2016-10-17 14:36:46,682 DEBUG [com.arjuna.ats.arjuna] (management-handler-thread - 4) registering bean jboss.jta:type=ObjectStore,itype=StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction,uid=0_ffff7f000001_-475b5c9c_5804af44_31
      2016-10-17 14:36:46,683 DEBUG [com.arjuna.ats.arjuna] (management-handler-thread - 4) registering bean jboss.jta:type=ObjectStore,itype=StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction,uid=0_ffff7f000001_-475b5c9c_5804af44_31,puid=-8000000000000000_-8000000000000000_-80000000_-80000000_-80000000
      

      Test passed for EAP 7.1.0.DR5 but failed for EAP 7.1.0.DR6. For another types of log-store (standard file based, activemq artemis journal) test passed.

              thjenkin@redhat.com Tom Jenkinson
              dsimko Daniel Simko (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated:
                Resolved: