Jboss 4.2.0CR1 - "Unabled to enlist resource" problem
omerlin Mar 21, 2007 5:43 AMHello,
We have really a blocking problem with JTA / Hibernate JDBC Transaction.
We are doing in a SSB a simple findByXXX method and we get systematically a javax.transaction.SystemException : Unabled to enlist resource
Context & problem analysis
-----------------------------------
* We checked several time the datasource - the message at the head of the stack " Cannot open connection [???]" is not related to a database problem
* In the same servlet session & context - we did previously some findByXXX calls that use the same datasource
* We only do SELECT jdbc call in the servlet session
* To help analysis we activate the full trace on ARJUNA
Hypothesis
--------------
We suspect an Hibernate EntityManager side effect in the transaction
NOTE : in the trace you can see a JDBC transaction that was successfully enlisted by the Transaction Manager and then the failling transaction
TRACE
----------
2007-03-20 13:50:11,941 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@468fa3 )
2007-03-20 13:50:11,941 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:11,942 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 0:0:0:1 )
2007-03-20 13:50:11,942 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (0:0:0:1)
2007-03-20 13:50:11,942 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord()
2007-03-20 13:50:11,942 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/LastResourceRecord for 0:0:0:1
2007-03-20 13:50:11,944 DEBUG [org.hibernate.SQL] select operatione0_.ID as ID0_, operatione0_.TIMESTAMP as TIMESTAMP0_, operatione0_.MSISDN as MSISDN0_, operatione0_.ICCID as ICCID0_, operatione0_.COMMAND_NAME as COMMAND5_0_, operatione0_.COMMAND_PARAMETERS as COMMAND6_0_, operatione0_.PRODUCT_TYPE as PRODUCT7_0_, operatione0_.MONITORING_ID as MONITORING8_0_, operatione0_.REQUESTER as REQUESTER0_, operatione0_.RESULT_CODE as RESULT10_0_, operatione0_.RESULT_DETAIL as RESULT11_0_, operatione0_.TERMINATED as TERMINATED0_ from OCP_HISTORY operatione0_ where operatione0_.ICCID=? and operatione0_.TERMINATED='F' order by operatione0_.TIMESTAMP
2007-03-20 13:50:11,944 INFO [STDOUT] Hibernate: select operatione0_.ID as ID0_, operatione0_.TIMESTAMP as TIMESTAMP0_, operatione0_.MSISDN as MSISDN0_, operatione0_.ICCID as ICCID0_, operatione0_.COMMAND_NAME as COMMAND5_0_, operatione0_.COMMAND_PARAMETERS as COMMAND6_0_, operatione0_.PRODUCT_TYPE as PRODUCT7_0_, operatione0_.MONITORING_ID as MONITORING8_0_, operatione0_.REQUESTER as REQUESTER0_, operatione0_.RESULT_CODE as RESULT10_0_, operatione0_.RESULT_DETAIL as RESULT11_0_, operatione0_.TERMINATED as TERMINATED0_ from OCP_HISTORY operatione0_ where operatione0_.ICCID=? and operatione0_.TERMINATED='F' order by operatione0_.TIMESTAMP
2007-03-20 13:50:12,142 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2007-03-20 13:50:12,144 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2007-03-20 13:50:12,144 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-03-20 13:50:12,144 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-03-20 13:50:12,144 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-03-20 13:50:12,144 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,144 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,146 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
2007-03-20 13:50:12,146 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,147 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,154 INFO [com.gemalto.mmserver.infra.services.impl.JobControllerBean] No job in process for the iccid : 200000004
2007-03-20 13:50:12,155 INFO [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Job completed :true
2007-03-20 13:50:12,155 INFO [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Getting next business command
2007-03-20 13:50:12,155 DEBUG [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Called : JobControllerBean.lookForNextBusinessCommand
2007-03-20 13:50:12,155 INFO [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Product type not yet defined
2007-03-20 13:50:12,155 DEBUG [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Called : JobControllerBean.getNextProduct
2007-03-20 13:50:12,155 DEBUG [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Called : JobControllerBean.getNextProductType
2007-03-20 13:50:12,155 DEBUG [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Called : JobControllerBean.getProductTypeList
2007-03-20 13:50:12,156 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.suspend
2007-03-20 13:50:12,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:49 removing TSThread:4
2007-03-20 13:50:12,156 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:49 removing TSThread:4 result = true
2007-03-20 13:50:12,156 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.begin
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 2 )
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::BasicAction()
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::Begin() for action-id a0aa44a:cf61:45ffd85c:51
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::actionInitialise() for action-id a0aa44a:cf61:45ffd85c:51
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ActionHierarchy::ActionHierarchy(5)
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ActionHierarchy::add(a0aa44a:cf61:45ffd85c:51, 1)
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:51 adding Thread[ajp-0.0.0.0-8010-1,5,jboss]
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:51 adding Thread[ajp-0.0.0.0-8010-1,5,jboss] result = true
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::create ( 120000 )
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::insert ( BasicAction: a0aa44a:cf61:45ffd85c:51 status: ActionStatus.RUNNING, 300 )
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement::ReaperElement ( BasicAction: a0aa44a:cf61:45ffd85c:51 status: ActionStatus.RUNNING, 300 )
2007-03-20 13:50:12,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement.greaterThan ()
2007-03-20 13:50:12,174 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@1fbaf73 )
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 0:0:0:1 )
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (0:0:0:1)
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord()
2007-03-20 13:50:12,175 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/LastResourceRecord for 0:0:0:1
2007-03-20 13:50:12,178 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,178 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,182 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,182 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.commit
2007-03-20 13:50:12,182 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.commitAndDisassociate
2007-03-20 13:50:12,182 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion
2007-03-20 13:50:12,182 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion
2007-03-20 13:50:12,182 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::End() for action-id a0aa44a:cf61:45ffd85c:51
2007-03-20 13:50:12,182 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::onePhaseCommit() for action-id a0aa44a:cf61:45ffd85c:51
2007-03-20 13:50:12,182 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord::topLevelPrepare() for 0:0:0:1
2007-03-20 13:50:12,182 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord::topLevelCommit() for 0:0:0:1
2007-03-20 13:50:12,182 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,183 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,183 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:51 removing TSThread:4
2007-03-20 13:50:12,183 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:51 removing TSThread:4 result = true
2007-03-20 13:50:12,183 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::create ( 120000 )
2007-03-20 13:50:12,183 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::remove ( BasicAction: a0aa44a:cf61:45ffd85c:51 status: ActionStatus.COMMITTED )
2007-03-20 13:50:12,183 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.resume
2007-03-20 13:50:12,183 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:49 adding Thread[ajp-0.0.0.0-8010-1,5,jboss]
2007-03-20 13:50:12,183 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:49 adding Thread[ajp-0.0.0.0-8010-1,5,jboss] result = true
2007-03-20 13:50:12,183 DEBUG [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Product list : [OCP]
2007-03-20 13:50:12,183 INFO [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Get next product type :OCP
2007-03-20 13:50:12,183 INFO [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Next product type :OCP
2007-03-20 13:50:12,183 DEBUG [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Called : JobControllerBean.getProduct
2007-03-20 13:50:12,183 DEBUG [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Called : JobControllerBean.getProductName
2007-03-20 13:50:12,184 DEBUG [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Called : JobControllerBean.getProductsAccessType
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.suspend
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:49 removing TSThread:4
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:49 removing TSThread:4 result = true
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.begin
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 2 )
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::BasicAction()
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::Begin() for action-id a0aa44a:cf61:45ffd85c:55
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::actionInitialise() for action-id a0aa44a:cf61:45ffd85c:55
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ActionHierarchy::ActionHierarchy(5)
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ActionHierarchy::add(a0aa44a:cf61:45ffd85c:55, 1)
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:55 adding Thread[ajp-0.0.0.0-8010-1,5,jboss]
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:55 adding Thread[ajp-0.0.0.0-8010-1,5,jboss] result = true
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::create ( 120000 )
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::insert ( BasicAction: a0aa44a:cf61:45ffd85c:55 status: ActionStatus.RUNNING, 300 )
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement::ReaperElement ( BasicAction: a0aa44a:cf61:45ffd85c:55 status: ActionStatus.RUNNING, 300 )
2007-03-20 13:50:12,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement.greaterThan ()
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement.greaterThan ()
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@1fbaf73 )
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 0:0:0:1 )
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (0:0:0:1)
2007-03-20 13:50:12,185 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord()
2007-03-20 13:50:12,186 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/LastResourceRecord for 0:0:0:1
2007-03-20 13:50:12,187 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,187 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,187 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,187 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.commit
2007-03-20 13:50:12,187 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.commitAndDisassociate
2007-03-20 13:50:12,187 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion
2007-03-20 13:50:12,187 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion
2007-03-20 13:50:12,187 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::End() for action-id a0aa44a:cf61:45ffd85c:55
2007-03-20 13:50:12,187 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::onePhaseCommit() for action-id a0aa44a:cf61:45ffd85c:55
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord::topLevelPrepare() for 0:0:0:1
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord::topLevelCommit() for 0:0:0:1
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:55 removing TSThread:4
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:55 removing TSThread:4 result = true
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::create ( 120000 )
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::remove ( BasicAction: a0aa44a:cf61:45ffd85c:55 status: ActionStatus.COMMITTED )
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.resume
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:49 adding Thread[ajp-0.0.0.0-8010-1,5,jboss]
2007-03-20 13:50:12,188 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:49 adding Thread[ajp-0.0.0.0-8010-1,5,jboss] result = true
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.suspend
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:49 removing TSThread:4
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:49 removing TSThread:4 result = true
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.begin
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 2 )
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::BasicAction()
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::Begin() for action-id a0aa44a:cf61:45ffd85c:59
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::actionInitialise() for action-id a0aa44a:cf61:45ffd85c:59
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ActionHierarchy::ActionHierarchy(5)
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ActionHierarchy::add(a0aa44a:cf61:45ffd85c:59, 1)
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:59 adding Thread[ajp-0.0.0.0-8010-1,5,jboss]
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:59 adding Thread[ajp-0.0.0.0-8010-1,5,jboss] result = true
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::create ( 120000 )
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::insert ( BasicAction: a0aa44a:cf61:45ffd85c:59 status: ActionStatus.RUNNING, 300 )
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement::ReaperElement ( BasicAction: a0aa44a:cf61:45ffd85c:59 status: ActionStatus.RUNNING, 300 )
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement.greaterThan ()
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement.greaterThan ()
2007-03-20 13:50:12,189 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement.greaterThan ()
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@1fbaf73 )
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 0:0:0:1 )
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (0:0:0:1)
2007-03-20 13:50:12,190 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord()
2007-03-20 13:50:12,191 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/LastResourceRecord for 0:0:0:1
2007-03-20 13:50:12,192 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,192 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,192 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,192 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.commit
2007-03-20 13:50:12,192 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.commitAndDisassociate
2007-03-20 13:50:12,192 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion
2007-03-20 13:50:12,192 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion
2007-03-20 13:50:12,192 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::End() for action-id a0aa44a:cf61:45ffd85c:59
2007-03-20 13:50:12,192 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::onePhaseCommit() for action-id a0aa44a:cf61:45ffd85c:59
2007-03-20 13:50:12,192 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord::topLevelPrepare() for 0:0:0:1
2007-03-20 13:50:12,193 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord::topLevelCommit() for 0:0:0:1
2007-03-20 13:50:12,193 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,193 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,193 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:59 removing TSThread:4
2007-03-20 13:50:12,193 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action a0aa44a:cf61:45ffd85c:59 removing TSThread:4 result = true
2007-03-20 13:50:12,193 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::create ( 120000 )
2007-03-20 13:50:12,193 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::remove ( BasicAction: a0aa44a:cf61:45ffd85c:59 status: ActionStatus.COMMITTED )
2007-03-20 13:50:12,193 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.resume
2007-03-20 13:50:12,193 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:49 adding Thread[ajp-0.0.0.0-8010-1,5,jboss]
2007-03-20 13:50:12,193 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action a0aa44a:cf61:45ffd85c:49 adding Thread[ajp-0.0.0.0-8010-1,5,jboss] result = true
2007-03-20 13:50:12,194 INFO [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Calling getNextBusinessCommand on OCP
2007-03-20 13:50:12,194 DEBUG [com.gemalto.mmserver.infra.services.impl.JobControllerBean] Called : JobControllerBean.getNextBusinessCommand
2007-03-20 13:50:12,201 DEBUG [com.gemalto.mmserver.ocp.interceptors.impl.MethodInterceptor] Method [17750771] OcpBusinessCommandControllerSpiBean.getNextBusinessCommand() called with 2 parameters
2007-03-20 13:50:12,201 DEBUG [com.gemalto.mmserver.ocp.interceptors.impl.MethodInterceptor] Method [17750771] parameter #0 type = String; value = 200000004
2007-03-20 13:50:12,201 DEBUG [com.gemalto.mmserver.ocp.interceptors.impl.MethodInterceptor] Method [17750771] parameter #1 type = CardCommunicationContext; value = [CardCommunicationContext [productType:OCP][jobId:-1][httpRequestSetId:null][currentUrl:http://signes:1793/CEH/cehocp][fragmentPolicyId:null][monitoringEnabled:true][requester:null][queryParameters:]]
2007-03-20 13:50:12,205 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,205 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,205 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4810321969991680
2007-03-20 13:50:12,205 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
2007-03-20 13:50:12,205 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,205 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,205 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,205 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,205 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,205 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization
2007-03-20 13:50:12,205 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.registerSynchronization
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
2007-03-20 13:50:12,206 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Transaction already joined
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-03-20 13:50:12,206 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@185477d )
2007-03-20 13:50:12,206 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,207 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 0:0:0:1 )
2007-03-20 13:50:12,207 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (0:0:0:1)
2007-03-20 13:50:12,207 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord()
2007-03-20 13:50:12,210 DEBUG [org.hibernate.util.JDBCExceptionReporter] Cannot open connection [???]
org.jboss.util.NestedSQLException: Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: a0aa44a:cf61:45ffd85c:49 status: ActionStatus.ABORT_ONLY >); - nested throwable: (org.jboss.resource.JBossResourceException: Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: a0aa44a:cf61:45ffd85c:49 status: ActionStatus.ABORT_ONLY >))
at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:94)
at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:47)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1538)
at org.hibernate.loader.Loader.doQuery(Loader.java:661)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
at org.hibernate.loader.Loader.doList(Loader.java:2211)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2095)
at org.hibernate.loader.Loader.list(Loader.java:2090)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:388)
at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
at org.hibernate.ejb.QueryImpl.getSingleResult(QueryImpl.java:80)
at com.gemalto.mmserver.ocp.services.impl.subscriptions.CardPersistenceServiceBean.findCardByIccid(CardPersistenceServiceBean.java:274)
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:585)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.tx.TxPolicy.invokeInCallerTx(TxPolicy.java:126)
at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:195)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:105)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessContainer.dynamicInvoke(StatelessContainer.java:274)
at org.jboss.ejb3.remoting.IsLocalInterceptor.invoke(IsLocalInterceptor.java:65)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessRemoteProxy.invoke(StatelessRemoteProxy.java:103)
at $Proxy161.findCardByIccid(Unknown Source)
at com.gemalto.mmserver.ocp.services.impl.otainfra.dispatcher.BusinessCommandDispatcherBean.getNextBusinessCommand(BusinessCommandDispatcherBean.java:82)
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:585)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.tx.TxPolicy.invokeInCallerTx(TxPolicy.java:126)
at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:195)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:105)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:210)
at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:180)
at org.jboss.ejb3.stateless.StatelessLocalProxy.invoke(StatelessLocalProxy.java:81)
at $Proxy173.getNextBusinessCommand(Unknown Source)
at com.gemalto.mmserver.ocp.services.impl.otainfra.spi.OcpBusinessCommandControllerSpiBean.getNextBusinessCommand(OcpBusinessCommandControllerSpiBean.java:79)
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:585)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
at com.gemalto.mmserver.ocp.interceptors.impl.ProfilingInterceptor.audit(ProfilingInterceptor.java:32)
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:585)
at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118)
at com.gemalto.mmserver.ocp.interceptors.impl.MethodInterceptor.traceCall(MethodInterceptor.java:52)
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:585)
at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118)
at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.tx.TxPolicy.invokeInCallerTx(TxPolicy.java:126)
at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:195)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:105)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessContainer.dynamicInvoke(StatelessContainer.java:274)
at org.jboss.ejb3.remoting.IsLocalInterceptor.invoke(IsLocalInterceptor.java:65)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessRemoteProxy.invoke(StatelessRemoteProxy.java:103)
at $Proxy176.getNextBusinessCommand(Unknown Source)
at com.gemalto.mmserver.infra.services.impl.JobControllerBean.getNextBusinessCommand(JobControllerBean.java:410)
at com.gemalto.mmserver.infra.services.impl.JobControllerBean.lookForNextBusinessCommand(JobControllerBean.java:795)
at com.gemalto.mmserver.infra.services.impl.JobControllerBean.getNextHttpRequestSetDirective(JobControllerBean.java:224)
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:585)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:79)
at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:191)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:105)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessContainer.dynamicInvoke(StatelessContainer.java:274)
at org.jboss.ejb3.remoting.IsLocalInterceptor.invoke(IsLocalInterceptor.java:65)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessRemoteProxy.invoke(StatelessRemoteProxy.java:103)
at $Proxy200.getNextHttpRequestSetDirective(Unknown Source)
at com.gemalto.mmserver.infra.comm.servlet.CardEventHandlerServlet.getNextHttpRequestSetDirective(CardEventHandlerServlet.java:526)
at com.gemalto.mmserver.infra.comm.servlet.CardEventHandlerServlet.doPost(CardEventHandlerServlet.java:793)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:228)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:175)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:156)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:216)
at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:437)
at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:447)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:445)
at java.lang.Thread.run(Thread.java:595)
Caused by: org.jboss.resource.JBossResourceException: Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: a0aa44a:cf61:45ffd85c:49 status: ActionStatus.ABORT_ONLY >)
at org.jboss.resource.connectionmanager.TxConnectionManager.managedConnectionReconnected(TxConnectionManager.java:343)
at org.jboss.resource.connectionmanager.BaseConnectionManager2.reconnectManagedConnection(BaseConnectionManager2.java:518)
at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:399)
at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:842)
at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:88)
... 179 more
Caused by: javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: a0aa44a:cf61:45ffd85c:49 status: ActionStatus.ABORT_ONLY >
at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener$TransactionSynchronization.checkEnlisted(TxConnectionManager.java:744)
at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener.enlist(TxConnectionManager.java:577)
at org.jboss.resource.connectionmanager.TxConnectionManager.managedConnectionReconnected(TxConnectionManager.java:337)
... 183 more
2007-03-20 13:50:12,215 WARN [org.hibernate.util.JDBCExceptionReporter] SQL Error: 0, SQLState: null
2007-03-20 13:50:12,215 ERROR [org.hibernate.util.JDBCExceptionReporter] Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: a0aa44a:cf61:45ffd85c:49 status: ActionStatus.ABORT_ONLY >); - nested throwable: (org.jboss.resource.JBossResourceException: Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: a0aa44a:cf61:45ffd85c:49 status: ActionStatus.ABORT_ONLY >))
2007-03-20 13:50:12,216 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,216 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,216 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] mark transaction for rollback
2007-03-20 13:50:12,217 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.setRollbackOnly
2007-03-20 13:50:12,217 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.setRollbackOnly
2007-03-20 13:50:12,217 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.setRollbackOnly
2007-03-20 13:50:12,324 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.setRollbackOnly
2007-03-20 13:50:12,324 DEBUG [com.gemalto.mmserver.ocp.interceptors.impl.ProfilingInterceptor] Method OcpBusinessCommandControllerSpiBean.getNextBusinessCommand() took 123 ms
2007-03-20 13:50:12,324 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.setRollbackOnly
2007-03-20 13:50:12,375 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.setRollbackOnly
2007-03-20 13:50:12,375 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,375 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.rollback
2007-03-20 13:50:12,375 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.rollbackAndDisassociate
2007-03-20 13:50:12,375 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::Abort() for action-id a0aa44a:cf61:45ffd85c:49
2007-03-20 13:50:12,375 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::doAbort (com.arjuna.ats.arjuna.LastResourceRecord@302f39)
2007-03-20 13:50:12,375 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] LastResourceRecord::topLevelAbort() for 0:0:0:1
2007-03-20 13:50:12,376 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,376 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] ************** closing entity managersession **************
2007-03-20 13:50:12,376 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
2007-03-20 13:50:12,376 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,376 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,376 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,376 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,376 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion
2007-03-20 13:50:12,377 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] ************** closing entity managersession **************