We are using JBoss 5.1 w/ MDB backed by ActiveMQ RAR. When a message on a
queue is consumed and performs some database operations which then result
in a deadlock, the deadlock is essentially hosing the entire instance of
JBoss until it is restarted. By hosed, any subsequent messages consumed on
that queue all fail with the follow exception:
Caused by: javax.persistence.PersistenceException:
org.hibernate.exception.GenericJDBCException: Cannot open connection
The deadlock exception never references my code, which in turn make it very
difficult for me to catch and handle.
See sample exception at the bottom of this message...
On subsequent messages to the queue I'm able to catch the GenericJDBCException:
Cannot open connection, but I'm not even sure what to do with it, maybe I
can get a new EntityManager that isn't hosed, but I'm getting via Injection
to begin with... The only way I know to fix this error is to restart.
I assume that the initial Deadlock is happening as part of ending the
transaction in the Queue which is why it's not happening in my code, but
does any idea of a way I can handle this gracefully?
Thanks.
----
2012-06-18 18:52:19,848 WARN [JDBCExceptionReporter] : SQL Error:
1213, SQLState: 40001
2012-06-18 18:52:19,848 ERROR [JDBCExceptionReporter] : Deadlock found
when trying to get lock; try restarting transaction
2012-06-18 18:52:19,850 ERROR [AbstractFlushingEventListener] : Could
not synchronize database state with session
org.hibernate.exception.LockAcquisitionException: Could not execute
JDBC batch update
at
org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:105)
at
org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
at
org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:275)
at
org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
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.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:504)
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:1423)
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.ejb3.mdb.inflow.MessageInflowLocalProxy.endTransaction(MessageInflowLocalProxy.java:435)
at
org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.finish(MessageInflowLocalProxy.java:314)
at
org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:230)
at
org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:136)
at $Proxy677.afterDelivery(Unknown Source)
at
org.apache.activemq.ra.MessageEndpointProxy$MessageEndpointAlive.afterDelivery(MessageEndpointProxy.java:128)
at
org.apache.activemq.ra.MessageEndpointProxy.afterDelivery(MessageEndpointProxy.java:69)
at
org.apache.activemq.ra.ServerSessionImpl.afterDelivery(ServerSessionImpl.java:224)
at
org.apache.activemq.ActiveMQSession.run(ActiveMQSession.java:897)
at
org.apache.activemq.ra.ServerSessionImpl.run(ServerSessionImpl.java:169)
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: java.sql.BatchUpdateException: Deadlock found when trying to
get lock; try restarting transaction
at
com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2013)
at
com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1449)
at
com.mysql.jdbc.jdbc2.optional.StatementWrapper.executeBatch(StatementWrapper.java:721)
at
org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:774)
at
org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
at
org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
... 29 more
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:407)
at com.mysql.jdbc.Util.getInstance(Util.java:382)
at
com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1064)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3603)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3535)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1989)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2150)
at
com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2626)
at
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2415)
at
com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1976)
... 34 more
2012-06-18 18:52:19,851 WARN [arjLoggerI18N] :
[com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_2]
TwoPhaseCoordinator.beforeCompletion - failed for
com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@480671ab
javax.persistence.PersistenceException:
org.hibernate.exception.LockAcquisitionException: Could not execute JDBC
batch update
at
org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:614)
at
org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:513)
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:1423)
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.ejb3.mdb.inflow.MessageInflowLocalProxy.endTransaction(MessageInflowLocalProxy.java:435)
at
org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.finish(MessageInflowLocalProxy.java:314)
at
org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:230)
at
org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:136)
at $Proxy677.afterDelivery(Unknown Source)
at
org.apache.activemq.ra.MessageEndpointProxy$MessageEndpointAlive.afterDelivery(MessageEndpointProxy.java:128)
at
org.apache.activemq.ra.MessageEndpointProxy.afterDelivery(MessageEndpointProxy.java:69)
at
org.apache.activemq.ra.ServerSessionImpl.afterDelivery(ServerSessionImpl.java:224)
at
org.apache.activemq.ActiveMQSession.run(ActiveMQSession.java:897)
at
org.apache.activemq.ra.ServerSessionImpl.run(ServerSessionImpl.java:169)
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: org.hibernate.exception.LockAcquisitionException: Could not
execute JDBC batch update
at
org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:105)
at
org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
at
org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:275)
at
org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
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.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:504)
... 22 more
Caused by: java.sql.BatchUpdateException: Deadlock found when trying to
get lock; try restarting transaction
at
com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2013)
at
com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1449)
at
com.mysql.jdbc.jdbc2.optional.StatementWrapper.executeBatch(StatementWrapper.java:721)
at
org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:774)
at
org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
at
org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
... 29 more
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:407)
at com.mysql.jdbc.Util.getInstance(Util.java:382)
at
com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1064)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3603)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3535)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1989)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2150)
at
com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2626)
at
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2415)
at
com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1976)
... 34 more
2012-06-18 18:52:19,912 WARN [TxConnectionManager] : Connection error
occured:
org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@6acc2da9[state=NORMAL
mc=org.jboss.resource.adapter.jdbc.xa.XAManagedConnection@2c9e906 handles=0
lastUse=1340059939649 permit=true trackByTx=true
mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@10015060context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@4643d6d5xaResource=org.jboss.resource.adapter.jdbc.xa.XAManagedConnection@2c9e906txSync=null]
com.mysql.jdbc.jdbc2.optional.MysqlXAException: XA_RBDEADLOCK:
Transaction branch was rolled back: deadlock was detected
at
com.mysql.jdbc.jdbc2.optional.MysqlXAConnection.mapXAExceptionFromSQLException(MysqlXAConnection.java:605)
at
com.mysql.jdbc.jdbc2.optional.MysqlXAConnection.dispatchCommand(MysqlXAConnection.java:584)
at
com.mysql.jdbc.jdbc2.optional.MysqlXAConnection.end(MysqlXAConnection.java:479)
at
org.jboss.resource.adapter.jdbc.xa.XAManagedConnection.end(XAManagedConnection.java:246)
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.end(TwoPhaseCoordinator.java:97)
at
com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1423)
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.ejb3.mdb.inflow.MessageInflowLocalProxy.endTransaction(MessageInflowLocalProxy.java:435)
at
org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.finish(MessageInflowLocalProxy.java:314)
at
org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:230)
at
org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:136)
at $Proxy677.afterDelivery(Unknown Source)
at
org.apache.activemq.ra.MessageEndpointProxy$MessageEndpointAlive.afterDelivery(MessageEndpointProxy.java:128)
at
org.apache.activemq.ra.MessageEndpointProxy.afterDelivery(MessageEndpointProxy.java:69)
at
org.apache.activemq.ra.ServerSessionImpl.afterDelivery(ServerSessionImpl.java:224)
at
org.apache.activemq.ActiveMQSession.run(ActiveMQSession.java:897)
at
org.apache.activemq.ra.ServerSessionImpl.run(ServerSessionImpl.java:169)
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)
2012-06-18 18:52:19,914 INFO [ServerSessionImpl:153] : Endpoint
failed to process message. Reason: Endpoint after delivery notification
failure
|