[jbossts-issues] [JBoss JIRA] Commented: (JBTM-751) Dirty transaction remains if rollback failed

Pieter Delmee (JIRA) jira-events at lists.jboss.org
Mon Sep 19 09:34:27 EDT 2011


    [ https://issues.jboss.org/browse/JBTM-751?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12629130#comment-12629130 ] 

Pieter Delmee commented on JBTM-751:
------------------------------------

The real problem appears to be that in the XAManagedConnection.end() method unlock is called. After the lock has been reinstantiated in the BaseWrapperManagedConnection.cleanup method. To demonstrate I modified the cleanup method by adding this lock.isLocked() if clause:

      // I'm recreating the lock object when we return to the pool
      // because it looks too nasty to expect the connection handle
      // to unlock properly in certain race conditions
      // where the dissociation of the managed connection is "random".
      if (lock.isLocked()) 
      	 try {
    	    throw new IllegalStateException("Lock is still being held by " 
    	    		+ (lock.isHeldByCurrentThread() ? "current thread" : "another thread")
    	    		+ (lock.hasQueuedThreads() ? ", and has queued threads!" : "")); 
      	 } catch (Exception e) {
      	    getLog().warn("Lock should not be renewed", e);
      	 }
      lock = new ReentrantLock();

It results in the following warning in the log:

2011-09-19 15:06:22,234 WARN  [org.jboss.resource.adapter.jdbc.xa.XAManagedConnectionFactory] (WorkManager(2)-99) Lock should not be renewed
java.lang.IllegalStateException: Lock is still being held by current thread
        at org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.cleanup(BaseWrapperManagedConnection.java:250)
        at org.jboss.resource.connectionmanager.InternalManagedConnectionPool.returnConnection(InternalManagedConnectionPool.java:341)
        at org.jboss.resource.connectionmanager.JBossManagedConnectionPool$BasePool.returnConnection(JBossManagedConnectionPool.java:724)
        at org.jboss.resource.connectionmanager.BaseConnectionManager2.returnManagedConnection(BaseConnectionManager2.java:463)
        at org.jboss.resource.connectionmanager.BaseConnectionManager2$BaseConnectionEventListener.connectionErrorOccurred(BaseConnectionManager2.java:854)
        at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener.connectionErrorOccurred(TxConnectionManager.java:792)
        at org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.broadcastConnectionError(BaseWrapperManagedConnection.java:429)
        at org.jboss.resource.adapter.jdbc.xa.XAManagedConnection.end(XAManagedConnection.java:253)
        at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:396)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3270)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3248)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1933)
        at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:114)
        at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:201)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1497)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:165)
        at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.rollback(BaseTransactionManagerDelegate.java:114)
        at org.jboss.resource.adapter.jms.inflow.JmsServerSession$XATransactionDemarcationStrategy.end(JmsServerSession.java:636)
        at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:243)
        at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)
        at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)


> Dirty transaction remains if rollback failed
> --------------------------------------------
>
>                 Key: JBTM-751
>                 URL: https://issues.jboss.org/browse/JBTM-751
>             Project: JBoss Transaction Manager
>          Issue Type: Bug
>      Security Level: Public(Everyone can see) 
>          Components: JTA
>    Affects Versions: 4.6.1
>         Environment: Jboss 5.1.0GA
>            Reporter: Teofilis Martisius
>            Assignee: Jonathan Halliday
>            Priority: Minor
>              Labels: Arjuna, JTA, dirty, rollback, thread, transaction
>             Fix For: 4.14.0
>
>         Attachments: patch1, patch2
>
>
> Hi,
> I noticed that in some cases when transaction rollback fails, remaining dirty transaction is left associated with the thread when it gets returned to thread pool. Same thread gets used again producing errors. I have attached a patch I have used successfully for a while in my deployment. This patch is applicable to v4.6.1GA, but I think other versions are also affected.
> This issue gets triggered by exception like this one:
> ERROR [org.hibernate.event.def.AbstractFlushingEventListener] (WorkManager(2)-17) Could not synchronize database state with
>  session
> org.hibernate.exception.LockAcquisitionException: could not update: [org.jbpm.graph.exe.Token#15022]
>         at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:105)
>         at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
>         at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2453)
>         at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2335)
>         at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2635)
>         at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:115)
>         at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
>         at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
>         at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
>         at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
>         at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
>         at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
>         at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:365)
>         at org.hibernate.transaction.CacheSynchronization.beforeCompletion(CacheSynchronization.java:88)
>         at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:101)
>         at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:269)
>         at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:89)
>         at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
>         at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1475)
>         at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)
>         at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
>         at org.jboss.resource.adapter.jms.inflow.JmsServerSession$XATransactionDemarcationStrategy.end(JmsServerSession.java:657)
>         at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:243)
>         at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)
>         at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>         at java.lang.Thread.run(Thread.java:619)
> Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
>         at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
>         at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
>         at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
>         at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
>         at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
>         at com.mysql.jdbc.Util.getInstance(Util.java:381)
>         at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1045)
>         at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:956)
>         at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3515)
>         at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3447)
>         at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1951)
>         at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2101)
>         at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2554)
>         at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1761)
>         at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2046)
>         at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1964)
>         at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1949)
>         at com.mysql.jdbc.jdbc2.optional.PreparedStatementWrapper.executeUpdate(PreparedStatementWrapper.java:874)
>         at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:365)
>         at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2435)
>         ... 25 more
> When same thread gets reused later, it produces following exception:
> ERROR [org.jboss.resource.adapter.jms.inflow.JmsServerSession] (WorkManager(2)-90) org.jboss.resource.adapter.jms.inflow.Jm
> sServerSession$DemarcationStrategyFactory at 42bae587 error creating transaction demarcation
> javax.transaction.NotSupportedException: BaseTransaction.checkTransactionState - [com.arjuna.ats.internal.jta.transaction.arjunacore.alreadyassocia
> ted] [com.arjuna.ats.internal.jta.transaction.arjunacore.alreadyassociated] thread is already associated with a transaction!
>         at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.begin(BaseTransaction.java:80)
>         at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.begin(BaseTransactionManagerDelegate.java:65)
>         at org.jboss.resource.adapter.jms.inflow.JmsServerSession$XATransactionDemarcationStrategy.<init>(JmsServerSession.java:560)
>         at org.jboss.resource.adapter.jms.inflow.JmsServerSession$DemarcationStrategyFactory.getStrategy(JmsServerSession.java:295)
>         at org.jboss.resource.adapter.jms.inflow.JmsServerSession.createTransactionDemarcation(JmsServerSession.java:252)
>         at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:224)
>         at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)
>         at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>         at java.lang.Thread.run(Thread.java:619)
> If you need any help or information, feel free to contact me.
> Sincerely,
> Teofilis Martisius

--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira

        


More information about the jbossts-issues mailing list