Uploaded image for project: 'JBeret'
  1. JBeret
  2. JBERET-146

Chunk commit can cause errors that can't be handled / JDBC job repository can cause deadlock

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major Major
    • 1.1.0.Final
    • 1.0.0.Final
    • jberet-core
    • None
    • Hide

      With one batch running a lot of inserts on a table, we start a second batch doing different work but using the table, too. We get a deadlock exception we can't handle with one of our retry or skip exception classes and the batch just fails directly after a bulk insert chunk completes. With just the in memory job repository we don't have any problem. Using two separate datasources for the processing and the job repository will result in a more obfusicated stack trace but the same problem source.

      Show
      With one batch running a lot of inserts on a table, we start a second batch doing different work but using the table, too. We get a deadlock exception we can't handle with one of our retry or skip exception classes and the batch just fails directly after a bulk insert chunk completes. With just the in memory job repository we don't have any problem. Using two separate datasources for the processing and the job repository will result in a more obfusicated stack trace but the same problem source.

      We have several separate batches and the errors during a commit seem to be unable to be handled. We stumbled upon this problem using a JDBC job repository and a deadlock during commit caused by it. An in memory repository will "fix" the deadlock but won't prevent the underlying problem.

      Expected behavior:

      • Errors during the commit of a chunk can be handled with a retry or skip and not only a failed batch.
      • The type of batch job repository has no impact on the batches. (e.g. no deadlocks) The job repository handling should be done in its own transaction or deadlocks will ensue.

      Actual behavior:
      Switching from in memory to a database repository can cause deadlocks. Even more worrying: The commit of a chunk is outside of the error handling of a writer. Deadlocks or other errors that can occur during a commit may stop a batch without allowing any kind of error or retry handling.

      Details

      The source of the problem seems to be the commit after the chunk has been processed in ChunkRunner.readProcessWriteItems(). There is no retry or skip handling there. The job repository handling isn't separated from the chunk handling itself.

      Stack trace for a MySQL datasource:

      2015-03-18 17:16:31,318 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Batch Thread - 5) SQL Error: 1213, SQLState: 40001
2015-03-18 17:16:31,319 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Batch Thread - 5) Deadlock found when trying to get lock; try restarting transaction
2015-03-18 17:16:31,320 INFO  [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (Batch Thread - 5) HHH000010: On release of batch it still contained JDBC statements
2015-03-18 17:16:31,322 WARN  [com.arjuna.ats.arjuna] (Batch Thread - 5) ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffff0abcb73a:-55bd6993:5509a424:180c, org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@1300a97c >: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
	at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1683) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.jpa.spi.AbstractEntityManagerImpl$CallbackExceptionMapperImpl.mapManagedFlushFailure(AbstractEntityManagerImpl.java:1882) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:119) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:50) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:358) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:91) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1166) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
	at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:323) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:191) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:205) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:138) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:164) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.CompositeExecutionRunner.runJobElement(CompositeExecutionRunner.java:128) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:184) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:164) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:58) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.wildfly.jberet.services.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:144) [wildfly-jberet-8.2.0.Final.jar:8.2.0.Final]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_31]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_31]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_31]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_31]
	at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_31]
	at org.jboss.threads.JBossThread.run(JBossThread.java:122)
Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
	at org.hibernate.dialect.MySQLDialect$1.convert(MySQLDialect.java:451) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:211) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:62) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3124) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3581) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:104) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1222) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:425) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:114) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	... 25 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) [rt.jar:1.8.0_31]
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) [rt.jar:1.8.0_31]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.8.0_31]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:408) [rt.jar:1.8.0_31]
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:377)
	at com.mysql.jdbc.Util.getInstance(Util.java:360)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:985)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3887)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3823)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2435)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2582)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2530)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1907)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2141)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2077)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2062)
	at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:493)
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:208) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	... 36 more

      Stack trace for a H2 datasource:

      2015-03-18 15:07:57,244 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Batch Thread - 8) SQL Error: 40001, SQLState: 40001
2015-03-18 15:07:57,248 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Batch Thread - 8) Eine Verklemmung (Deadlock) ist aufgetreten. Die aktuelle Transaktion wurde rückgängig gemacht. Details: "
Session #32 (user: SYS) is waiting to lock PUBLIC.STEP_EXECUTION while locking PUBLIC.TAB_XXX_XXXXXXXXXX (exclusive).
Session #30 (user: SYS) is waiting to lock PUBLIC.TAB_XXX_XXXXXXXXXX while locking PUBLIC.STEP_EXECUTION (exclusive)."
Deadlock detected. The current transaction was rolled back. Details: "
Session #32 (user: SYS) is waiting to lock PUBLIC.STEP_EXECUTION while locking PUBLIC.TAB_XXX_XXXXXXXXXX (exclusive).
Session #30 (user: SYS) is waiting to lock PUBLIC.TAB_XXX_XXXXXXXXXX while locking PUBLIC.STEP_EXECUTION (exclusive)."; SQL statement:
insert into TAB_XXX_XXXXXXXXXX (XXX_XXXXXXXX_XXXX, XXX_XXXXXXX_XXX_XX, XXX_XXXXXXXXXXXX_XXXX, XXX_XXXXXXXX_XXX_XX, XXX_XXXXXXX, XXX_XXXXXX, XXX_XXXXX_XXXXX, XXX_XXXX_XXXXXXXXXX, XXX_XXXXXXX_XXXXXXXXXX, XXX_XXXXX_XXXXXXXX, XXX_XXXXX_XXXX_XXXXXXXXXX, XXX_XXXXX_XXXXXXX_XXXXXXXXXX, XXX_XXXXX_XXXX, XXX_XXXXX_XXXX, XXX_XXXX_XXXXX_XXXXXX, XXX_XXX_XX, XXX_XXXX, XXX_XXX_XX, XXX_XXXXXXXXXX_XXXXX, XXX_XXXXXXXXX, XXX_XX) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [40001-173]
2015-03-18 15:07:57,248 INFO  [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (Batch Thread - 8) HHH000010: On release of batch it still contained JDBC statements
2015-03-18 15:07:57,253 WARN  [com.arjuna.ats.arjuna] (Batch Thread - 8) ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffff0abcb73a:7443bb9d:55096d96:16180, org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@99a22d5 >: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
	at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1683) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.jpa.spi.AbstractEntityManagerImpl$CallbackExceptionMapperImpl.mapManagedFlushFailure(AbstractEntityManagerImpl.java:1882) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:119) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:50) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:358) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:91) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1166) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
	at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
	at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:323) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:191) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:205) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:138) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:164) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.CompositeExecutionRunner.runJobElement(CompositeExecutionRunner.java:128) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:184) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:164) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:58) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.wildfly.jberet.services.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:144) [wildfly-jberet-8.2.0.Final.jar:8.2.0.Final]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_31]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_31]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_31]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_31]
	at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_31]
	at org.jboss.threads.JBossThread.run(JBossThread.java:122)
Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
	at org.hibernate.dialect.H2Dialect$2.convert(H2Dialect.java:337) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:211) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:62) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3124) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3581) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:104) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1222) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:425) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:114) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	... 25 more
Caused by: org.h2.jdbc.JdbcSQLException: Eine Verklemmung (Deadlock) ist aufgetreten. Die aktuelle Transaktion wurde rückgängig gemacht. Details: "
Session #32 (user: SYS) is waiting to lock PUBLIC.STEP_EXECUTION while locking PUBLIC.XXX_XXX_XXXXXXXXXX (exclusive).
Session #30 (user: SYS) is waiting to lock PUBLIC.XXX_XXX_XXXXXXXXXX while locking PUBLIC.STEP_EXECUTION (exclusive)."
Deadlock detected. The current transaction was rolled back. Details: "
Session #32 (user: SYS) is waiting to lock PUBLIC.STEP_EXECUTION while locking PUBLIC.XXX_XXX_XXXXXXXXXX (exclusive).
Session #30 (user: SYS) is waiting to lock PUBLIC.XXX_XXX_XXXXXXXXXX while locking PUBLIC.STEP_EXECUTION (exclusive)."; SQL statement:
insert into TAB_XXX_XXXXXXXXXX (XXX_XXXXXXXX_XXXX, XXX_XXXXXXX_XXX_XX, XXX_XXXXXXXXXXXX_XXXX, XXX_XXXXXXXX_XXX_XX, XXX_XXXXXXX, XXX_XXXXXX, XXX_XXXXX_XXXXX, XXX_XXXX_XXXXXXXXXX, XXX_XXXXXXX_XXXXXXXXXX, XXX_XXXXX_XXXXXXXX, XXX_XXXXX_XXXX_XXXXXXXXXX, XXX_XXXXX_XXXXXXX_XXXXXXXXXX, XXX_XXXXX_XXXX, XXX_XXXXX_XXXX, XXX_XXXX_XXXXX_XXXXXX, XXX_XXX_XX, XXX_XXXX, XXX_XXX_XX, XXX_XXXXXXXXXX_XXXXX, XXX_XXXXXXXXX, XXX_XX) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [40001-173]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:331)
	at org.h2.message.DbException.get(DbException.java:171)
	at org.h2.message.DbException.get(DbException.java:148)
	at org.h2.table.RegularTable.doLock(RegularTable.java:509)
	at org.h2.table.RegularTable.lock(RegularTable.java:455)
	at org.h2.command.dml.Insert.insertRows(Insert.java:126)
	at org.h2.command.dml.Insert.update(Insert.java:86)
	at org.h2.command.CommandContainer.update(CommandContainer.java:79)
	at org.h2.command.Command.executeUpdate(Command.java:235)
	at org.h2.server.TcpServerThread.process(TcpServerThread.java:335)
	at org.h2.server.TcpServerThread.run(TcpServerThread.java:151)
	at java.lang.Thread.run(Unknown Source)

	at org.h2.engine.SessionRemote.done(SessionRemote.java:579)
	at org.h2.command.CommandRemote.executeUpdate(CommandRemote.java:186)
	at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:154)
	at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:140)
	at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:493)
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:208) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
	... 36 more

      Mixed datasources (H2 for the repository and MySQL for the application):

      2015-03-19 08:09:55,212 WARN  [com.arjuna.ats.arjuna] (Batch Thread - 6) ARJUNA012140: Adding multiple last resources is disallowed. Trying to add LastResourceRecord(XAOnePhaseResource(LocalXAResourceImpl@3cfdc287[connectionListener=ab44ff4 connectionManager=33a85e42 warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0abcb73a:4b6d6d02:550a757e:535, node_name=1, branch_uid=0:ffff0abcb73a:4b6d6d02:550a757e:9ea, subordinatenodename=null, eis_name=java:jboss/datasources/H2DS > productName=H2 productVersion=1.3.173 (2013-07-28) jndiName=java:jboss/datasources/H2DS])), but already have LastResourceRecord(XAOnePhaseResource(LocalXAResourceImpl@32e30d75[connectionListener=88fc823 connectionManager=51a632c5 warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0abcb73a:4b6d6d02:550a757e:535, node_name=1, branch_uid=0:ffff0abcb73a:4b6d6d02:550a757e:539, subordinatenodename=null, eis_name=java:jboss/datasources/ExampleDS > productName=MySQL productVersion=5.6.16-log jndiName=java:jboss/datasources/ExampleDS]))
2015-03-19 08:09:55,215 ERROR [org.jberet] (Batch Thread - 6) JBERET000007: Failed to run job measurementPairingAssignment, unassignStep, org.jberet.job.model.Chunk@7687953c: javax.batch.operations.BatchRuntimeException: JBERET000622: Failed to obtain connection from org.jboss.jca.adapters.jdbc.WrapperDataSource@6a44732b, java:jboss/datasources/H2DS
	at org.jberet.repository.JdbcRepository.getConnection(JdbcRepository.java:802) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.repository.JdbcRepository.updateStepExecution(JdbcRepository.java:546) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.repository.JdbcRepository.savePersistentData(JdbcRepository.java:583) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.context.StepContextImpl.savePersistentData(StepContextImpl.java:165) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.ChunkRunner.doCheckpoint(ChunkRunner.java:519) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:303) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:191) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:205) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:138) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:164) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:58) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	at org.wildfly.jberet.services.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:144) [wildfly-jberet-8.2.0.Final.jar:8.2.0.Final]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_31]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_31]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_31]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_31]
	at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_31]
	at org.jboss.threads.JBossThread.run(JBossThread.java:122)
Caused by: java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@ab44ff4[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@66774c99 connection handles=0 lastUse=1426748995213 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@b88a4ec mcp=SemaphoreArrayListManagedConnectionPool@5888e642[pool=H2DS] xaResource=LocalXAResourceImpl@3cfdc287[connectionListener=ab44ff4 connectionManager=33a85e42 warned=false currentXid=null productName=H2 productVersion=1.3.173 (2013-07-28) jndiName=java:jboss/datasources/H2DS] txSync=null]
	at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:154)
	at org.jberet.repository.JdbcRepository.getConnection(JdbcRepository.java:800) [jberet-core-1.0.2.Final.jar:1.0.2.Final]
	... 18 more
Caused by: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@ab44ff4[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@66774c99 connection handles=0 lastUse=1426748995213 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@b88a4ec mcp=SemaphoreArrayListManagedConnectionPool@5888e642[pool=H2DS] xaResource=LocalXAResourceImpl@3cfdc287[connectionListener=ab44ff4 connectionManager=33a85e42 warned=false currentXid=null productName=H2 productVersion=1.3.173 (2013-07-28) jndiName=java:jboss/datasources/H2DS] txSync=null]
	at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:780)
	at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:518)
	at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:146)
	... 19 more
Caused by: javax.resource.ResourceException: IJ000461: Could not enlist in transaction on entering meta-aware object
	at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:551)
	at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:775)
	... 21 more
Caused by: javax.transaction.SystemException: IJ000356: Failed to enlist: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: 0:ffff0abcb73a:4b6d6d02:550a757e:535 status: ActionStatus.ABORT_ONLY >
	at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.checkEnlisted(TxConnectionListener.java:848)
	at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:383)
	at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:544)
	... 22 more

        1. ChunkRunner.java
          36 kB
        2. ChunkRunner.java
          35 kB
        3. jberet-core-1.0.2.Final-patched.jar
          208 kB
        4. jberet-core-1.0.2.Final-patchedV2.jar
          208 kB
        5. jBeretTransactionTest.zip
          13 kB
        6. jBeretTransactionTestRetryError.zip
          7 kB

            cfang@redhat.com Cheng Fang
            oescher Ortwin Escher (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: