Problem with analysing transaction locks
jobame Aug 28, 2013 10:21 AMHello
We use JBoss-as-7.1.1.Final and do have transaction errors. It starts with the below log messages, continues through
- ARJUNA016063: The transaction is not active!
- java.sql.SQLException: pingDatabase failed status=-2
- ARJUNA016051: thread is already associated with a transaction!
- Lock owned during cleanup: java.lang.Throwable: Lock owned during cleanup
- Connection is not associated with a managed connection.org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@363f4446
- java.lang.OutOfMemoryError: Java heap space
and ends up with a "ORA-01591: lock held by in-doubt distributed transaction 9.17.233860" which is pretty bad. See attached log for full details.
How is it technically possibly to analyse where the error occurs? At the start of the problem log statements there is no link to the code of the application. How can we work on it?
22.08.2013 18:35:01,063 WARN [TransactionReaper.java:check:148] ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0a045150:-5eacabf6:5214c882:51f15f in state RUN
22.08.2013 18:35:02,789 WARN [TransactionReaper.java:check:148] ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0a045150:-5eacabf6:5214c882:51f15f in state CANCEL
22.08.2013 18:35:04,430 WARN [TransactionReaper.java:check:148] ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0a045150:-5eacabf6:5214c882:51f15f in state CANCEL_INTERRUPTED
22.08.2013 18:35:04,434 WARN [TransactionReaper.java:check:254] ARJUNA012120: TransactionReaper::check worker Thread[Transaction Reaper Worker 0,5,main] not responding to interrupt when cancelling TX 0:ffff0a045150:-5eacabf6:5214c882:51f15f -- worker marked as zombie and TX scheduled for mark-as-rollback
22.08.2013 18:35:04,435 WARN [TransactionReaper.java:check:270] ARJUNA012110: TransactionReaper::check successfuly marked TX 0:ffff0a045150:-5eacabf6:5214c882:51f15f as rollback only
22.08.2013 18:35:04,436 WARN [TransactionReaper.java:doCancellations:406] ARJUNA012113: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] missed interrupt when cancelling TX 0:ffff0a045150:-5eacabf6:5214c882:51f15f -- exiting as zombie (zombie count decremented to 0)
22.08.2013 18:35:04,435 INFO [ClusterGuard.java:ensureOneProcessInCluster:49] db - entry created ClusterControl [id=34275, owner=DebitPositionCalculation, startDate=22.08.2013 18:35:02, hostname=chetan001.unix.live.local]
22.08.2013 18:35:04,456 INFO [DebitPositionRunTrigger.java:triggerDebitPositions:63] ... starting DPC
22.08.2013 18:35:04,458 INFO [DebitPositionRunTrigger.java:calculateDebitPositions:90] Retrieved 0 AccountState candidates for calculation of debit positions from database.
22.08.2013 18:36:35,725 WARN [BasicAction.java:Abort:1588] ARJUNA012077: Abort called on already aborted atomic action 0:ffff0a045150:-5eacabf6:5214c882:51f15f
22.08.2013 18:36:35,728 ERROR [TimerTask.java:run:137] JBAS014120: Error invoking timeout for timer: [id=1b8444f9-0dd2-4bf0-b96c-49f5330256fe timedObjectId=ab23TurnerEAR.ab23TurnerEJB.AccountStateTimer auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@12efc0ee initialExpiration=Wed Aug 21 00:00:00 CEST 2013 intervalDuration(in milli sec)=0 nextExpiration=Thu Aug 22 18:40:00 CEST 2013 timerState=IN_TIMEOUT: javax.ejb.EJBTransactionRolledbackException: Transaction rolled back
at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleEndTransactionException(CMTTxInterceptor.java:115) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:95) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.TimerCMTTxInterceptor.endTransaction(TimerCMTTxInterceptor.java:66) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:232) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:304) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:190) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:43) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:101) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.timerservice.task.CalendarTimerTask.callTimeout(CalendarTimerTask.java:60) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.timerservice.task.TimerTask.run(TimerTask.java:132) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439) [rt.jar:1.6.0_37]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [rt.jar:1.6.0_37]
at java.util.concurrent.FutureTask.run(FutureTask.java:138) [rt.jar:1.6.0_37]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_37]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_37]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_37]
at org.jboss.threads.JBossThread.run(JBossThread.java:122) [jboss-threads-2.0.0.GA.jar:2.0.0.GA]
Caused by: javax.transaction.RollbackException: ARJUNA016063: The transaction is not active!
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1155) [jbossjts-4.16.2.Final.jar:]
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:117) [jbossjts-4.16.2.Final.jar:]
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
... 24 more
Edit: since we don't know when the problem does occur we can't set the log level to TRACE for a long time. The application was running without problems for weeks.
We use two timer triggered methods but we make sure only one of them can run at a time. So if one starts and the other has not finished yet then the other cannot start.
Regards,
Dominik
-
server_error.log.zip 25.2 KB