BMT issue: EJBException Stateful instance org.jboss.as.ejb3.component.stateful.StatefulSessionComponentInstance is already associated with tx
guinotphil Sep 13, 2011 9:27 AMHello,
I’m currently having some issues with transaction management with BMT on JBoss AS 7.
This is in a Seam 2 application which is currently in production on JBoss AS 4. I’m not really sure about the origins of the problem, but I’ll try to give the maximum of details.
I’ve got an EJB with look something like that:
@Stateless(name="path/processManager")
@Name("path.processManager")
@AutoCreate
@TransactionManagement(TransactionManagementType.BEAN)
@JndiName("java:app/MyEjbProject/path/processManager")
public class ProcessManagerAction implements ProcessManager
{
@Logger
private Log log;
@Resource
private UserTransaction userTransaction;
@PersistenceContext(unitName="entityManagerFactory")
EntityManager em;
public static ProcessManager instance() {
return (ProcessManager) Component.getInstance(ProcessManagerAction.class);
}
static void beginTransaction(UserTransaction userTransaction, EntityManager em) {
try {
if (userTransaction.getStatus() == Status.STATUS_NO_TRANSACTION) {
userTransaction.begin();
em.joinTransaction();
}
} catch (Exception e) {
log.error("Cannot begin transaction", e);
throw new IllegalStateException("Cannot begin transaction", e);
}
}
static void commitTransaction (UserTransaction userTransaction, EntityManager em)
try {
if (userTransaction.getStatus() != javax.transaction.Status.STATUS_ACTIVE) {
throw new IllegalStateException("No transaction active");
}
em.flush();
userTransaction.commit();
} catch (OptimisticLockException e) {
throw e;
} catch (EntityNotFoundException e) {
throw e;
} catch (Exception e) {
log.error("Cannot commit transaction", e);
throw new IllegalStateException("Cannot commit transaction", e);
}
}
public Object process(Object param) {
beginTransaction(userTransaction, em);
<< some business code>>
commitTransaction(userTransaction, em);
return result;
}
}
When I enter into the process method, the userTransaction is an instance of com.arjuna.ats.internal.jta.transaction.arjunacore.UserTransactionImple
And before the following things were logged:
14:37:00,877 DEBUG [org.jboss.seam.transaction.UTTransaction] (http--127.0.0.1-80-3) beginning JTA transaction
14:37:00,877 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) BaseTransaction.begin
14:37:00,877 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) StateManager::StateManager( 2, 0 )
14:37:00,877 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::BasicAction()
14:37:00,877 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::Begin() for action-id 0:ffffc0a80a80:354a2ce5:4e6f491c:16f
14:37:00,877 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::actionInitialise() for action-id 0:ffffc0a80a80:354a2ce5:4e6f491c:16f
14:37:00,877 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) ActionHierarchy::ActionHierarchy(5)
14:37:00,877 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) ActionHierarchy::add(0:ffffc0a80a80:354a2ce5:4e6f491c:16f, 1)
14:37:00,877 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::addChildThread () action 0:ffffc0a80a80:354a2ce5:4e6f491c:16f adding Thread[http--127.0.0.1-80-3,5,main]
14:37:00,877 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::addChildThread () action 0:ffffc0a80a80:354a2ce5:4e6f491c:16f adding Thread[http--127.0.0.1-80-3,5,main] result = true
14:37:00,877 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) TransactionReaper::insert ( BasicAction: 0:ffffc0a80a80:354a2ce5:4e6f491c:16f status: ActionStatus.RUNNING, 300 )
14:37:00,877 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) ReaperElement::ReaperElement ( BasicAction: 0:ffffc0a80a80:354a2ce5:4e6f491c:16f status: ActionStatus.RUNNING, 300 )
14:37:00,877 DEBUG [org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor] (http--127.0.0.1-80-3) Looking for stateful component instance with session id: 5c4oa3k-jy8x0y-gsiuwg52-1-gsiv987n-1e
14:37:00,877 TRACE [org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor] (http--127.0.0.1-80-3) Trying to acquire lock: java.util.concurrent.locks.ReentrantLock@4f2a858f[Unlocked] for stateful component instance: org.jboss.as.ejb3.component.stateful.StatefulSessionComponentInstance@70a697e3 during invocation: org.jboss.invocation.InterceptorContext@589f393
14:37:00,877 TRACE [org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor] (http--127.0.0.1-80-3) Acquired lock: java.util.concurrent.locks.ReentrantLock@4f2a858f[Locked by thread http--127.0.0.1-80-3] for stateful component instance: org.jboss.as.ejb3.component.stateful.StatefulSessionComponentInstance@70a697e3 during invocation: org.jboss.invocation.InterceptorContext@589f393
14:37:00,877 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getTransactionKey
14:37:00,877 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.registerInterposedSynchronization
14:37:00,877 TRACE [org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor] (http--127.0.0.1-80-3) Registered tx synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@23d63abc for tx: 0:ffffc0a80a80:354a2ce5:4e6f491c:16f associated with stateful component instance: org.jboss.as.ejb3.component.stateful.StatefulSessionComponentInstance@70a697e3
14:37:00,877 DEBUG [org.jboss.seam.transaction.EjbSynchronizations] (http--127.0.0.1-80-3) afterBegin
14:37:00,878 DEBUG [org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor] (http--127.0.0.1-80-3) Looking for stateful component instance with session id: 5c4oa3k-jy8x0y-gsiuwg52-1-gsiv8hvw-z
14:37:00,878 TRACE [org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor] (http--127.0.0.1-80-3) Trying to acquire lock: java.util.concurrent.locks.ReentrantLock@3f2aebe4[Unlocked] for stateful component instance: org.jboss.as.ejb3.component.stateful.StatefulSessionComponentInstance@1ae4e622 during invocation: org.jboss.invocation.InterceptorContext@1b4235cc
14:37:00,878 TRACE [org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor] (http--127.0.0.1-80-3) Acquired lock: java.util.concurrent.locks.ReentrantLock@3f2aebe4[Locked by thread http--127.0.0.1-80-3] for stateful component instance: org.jboss.as.ejb3.component.stateful.StatefulSessionComponentInstance@1ae4e622 during invocation: org.jboss.invocation.InterceptorContext@1b4235cc
14:37:00,878 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getTransactionKey
14:37:00,878 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.registerInterposedSynchronization
14:37:00,878 TRACE [org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor] (http--127.0.0.1-80-3) Registered tx synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@17d9f20f for tx: 0:ffffc0a80a80:354a2ce5:4e6f491c:16f associated with stateful component instance: org.jboss.as.ejb3.component.stateful.StatefulSessionComponentInstance@1ae4e622
…
14:37:01,437 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (http--127.0.0.1-80-3) Looking for a JTA transaction to join
14:37:01,437 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (http--127.0.0.1-80-3) Transaction already joined
14:37:01,437 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) BaseTransaction.getStatus
14:37:01,437 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:01,438 DEBUG [org.jboss.jpa] (http--127.0.0.1-80-3) created new TransactionScopedEntityManager for unit name=My_EAR_Project.ear#entityManagerFactory
14:37:01,438 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImpleManager.suspend
14:37:01,438 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::removeChildThread () action 0:ffffc0a80a80:354a2ce5:4e6f491c:16f removing TSThread:3
14:37:01,438 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::removeChildThread () action 0:ffffc0a80a80:354a2ce5:4e6f491c:16f removing TSThread:3 result = true
Then, when I can start the transaction and inside the business code I got a javax.ejb.EJBException
14:37:17,269 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) BaseTransaction.getStatus
14:37:17,269 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) BaseTransaction.begin
14:37:17,269 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) StateManager::StateManager( 2, 0 )
14:37:17,269 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::BasicAction()
14:37:17,269 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::Begin() for action-id 0:ffffc0a80a80:354a2ce5:4e6f491c:175
14:37:17,269 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::actionInitialise() for action-id 0:ffffc0a80a80:354a2ce5:4e6f491c:175
14:37:17,269 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) ActionHierarchy::ActionHierarchy(5)
14:37:17,269 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) ActionHierarchy::add(0:ffffc0a80a80:354a2ce5:4e6f491c:175, 1)
14:37:17,269 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::addChildThread () action 0:ffffc0a80a80:354a2ce5:4e6f491c:175 adding Thread[http--127.0.0.1-80-3,5,main]
14:37:17,269 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) BasicAction::addChildThread () action 0:ffffc0a80a80:354a2ce5:4e6f491c:175 adding Thread[http--127.0.0.1-80-3,5,main] result = true
14:37:17,269 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) TransactionReaper::insert ( BasicAction: 0:ffffc0a80a80:354a2ce5:4e6f491c:175 status: ActionStatus.RUNNING, 300 )
14:37:17,269 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) ReaperElement::ReaperElement ( BasicAction: 0:ffffc0a80a80:354a2ce5:4e6f491c:175 status: ActionStatus.RUNNING, 300 )
14:37:17,269 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,269 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getResource
14:37:17,269 DEBUG [org.hibernate.impl.SessionImpl] (http--127.0.0.1-80-3) opened session at timestamp: 5389997823053824
14:37:17,269 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (http--127.0.0.1-80-3) Looking for a JTA transaction to join
14:37:17,269 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,269 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,269 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,269 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,269 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,269 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.registerSynchronization
14:37:17,269 DEBUG [org.hibernate.jdbc.JDBCContext] (http--127.0.0.1-80-3) successfully registered Synchronization
14:37:17,269 DEBUG [org.jboss.jpa] (http--127.0.0.1-80-3) http--127.0.0.1-80-3:: created entity manager session TransactionImple < ac, BasicAction: 0:ffffc0a80a80:354a2ce5:4e6f491c:175 status: ActionStatus.RUNNING >
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.registerSynchronization
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.putResource
14:37:17,270 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (http--127.0.0.1-80-3) Looking for a JTA transaction to join
14:37:17,270 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (http--127.0.0.1-80-3) Transaction already joined
14:37:17,270 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (http--127.0.0.1-80-3) Looking for a JTA transaction to join
14:37:17,270 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (http--127.0.0.1-80-3) Transaction already joined
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) BaseTransaction.getStatus
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) BaseTransaction.getStatus
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getTransactionKey
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getTransactionKey
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getResource
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getTransactionKey
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getResource
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.putResource
14:37:17,270 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getResource
14:37:17,295 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getTransactionKey
14:37:17,295 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getResource
14:37:17,295 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getResource
14:37:17,295 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.putResource
14:37:17,295 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) BaseTransaction.getStatus
14:37:17,295 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,295 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.registerInterposedSynchronization
14:37:17,295 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.equals
14:37:17,295 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.enlistResource ( org.jboss.jca.core.tx.jbossts.LocalXAResourceImpl@3f87323 )
14:37:17,295 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionImple.getStatus
14:37:17,295 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) StateManager::StateManager( 0:0:0:0:1 )
14:37:17,295 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) AbstractRecord::AbstractRecord (0:0:0:0:1)
14:37:17,296 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) LastResourceRecord()
14:37:17,296 TRACE [com.arjuna.ats.arjuna] (http--127.0.0.1-80-3) RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/LastResourceRecord for 0:0:0:0:1
14:37:17,296 DEBUG [org.hibernate.impl.SessionImpl] (http--127.0.0.1-80-3) opened session at timestamp: -9223372036854775808
14:37:17,296 DEBUG [org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor] (http--127.0.0.1-80-3) Looking for stateful component instance with session id: 5c4oa3k-jy8x0y-gsiuwg52-1-gsiv987n-1e
14:37:17,296 TRACE [org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor] (http--127.0.0.1-80-3) Trying to acquire lock: java.util.concurrent.locks.ReentrantLock@4f2a858f[Locked by thread http--127.0.0.1-80-3] for stateful component instance: org.jboss.as.ejb3.component.stateful.StatefulSessionComponentInstance@70a697e3 during invocation: org.jboss.invocation.InterceptorContext@76c2058b
14:37:17,296 TRACE [org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor] (http--127.0.0.1-80-3) Acquired lock: java.util.concurrent.locks.ReentrantLock@4f2a858f[Locked by thread http--127.0.0.1-80-3] for stateful component instance: org.jboss.as.ejb3.component.stateful.StatefulSessionComponentInstance@70a697e3 during invocation: org.jboss.invocation.InterceptorContext@76c2058b
14:37:17,296 TRACE [com.arjuna.ats.jta] (http--127.0.0.1-80-3) TransactionSynchronizationRegistryImple.getTransactionKey
14:37:17,296 TRACE [org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor] (http--127.0.0.1-80-3) Released lock: java.util.concurrent.locks.ReentrantLock@4f2a858f[Locked by thread http--127.0.0.1-80-3]
14:37:17,296 TRACE [org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor] (http--127.0.0.1-80-3) Removing bean 5c4oa3k-jy8x0y-gsiuwg52-1-gsiv987n-1e because of exception: javax.ejb.EJBException: EJB 3.1 FR 4.6 Stateful instance org.jboss.as.ejb3.component.stateful.StatefulSessionComponentInstance@70a697e3 is already associated with tx 0:ffffc0a80a80:354a2ce5:4e6f491c:16f (current tx 0:ffffc0a80a80:354a2ce5:4e6f491c:175)
(The trace-logged EJBException is then thrown)
As you can see, since I started running the process method, the only transaction logged is the current one : 0:ffffc0a80a80:354a2ce5:4e6f491c:175
The other transaction, 0:ffffc0a80a80:354a2ce5:4e6f491c:16f, is however still associated with the StatefulSessionComponentInstance but has been suspended as logged before.
Any idea on this? It is possible that it comes from a misconfiguration, the set up is very big (can’t attach the whole application sorry) as it use Seam 2, Hibernate 3 and also jBPM 3 (which I managed to patch to obtain the Hibernate SessionFactory from the EntityManagerFactory in JNDI), etc, etc.,
In a similar way, if I use Seam 2 to get the transaction instead of the injection:
public Object process(Object param) {
UserTransaction userTransaction = org.jboss.seam.transaction.Transaction.instance();
beginTransaction(userTransaction, em);
<< some business code>>
commitTransaction(userTransaction, em);
return result;
}
The UserTransaction is time is an instance of org.jboss.seam.transaction.UTTransaction
Then, I the same EJBException is thrown during the beginTransaction while I had the exception only during business code when I was using the injected UserTransaction instance.
Thank you very much for any help !