Lost locks after exception during rollback
We're running JBC 1.4.1SP9 under WebSphere Application Server 6.0. In our application, we're processing multiple file imports in parallel threads.
In this scenario we observe lost cache locks. In other words, the lock table contains locks from transactions that have been rolled back or commited. These locks block later transactions from modifying the nodes.
We've been able to reproduce this to some extent, here's what we know.
The following is a part of our logfile that I stripped down a bit. org.jboss.cache.interceptors.TxInterceptor is configured to trace. The transaction that interfers later is no. 199, so this is what it does:
2008-10-07 19:34:21 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_put; id:1; Args: ( arg[0] = GlobalTransaction:<null>:199 ...)];;;;;FINEST;; 2008-10-07 19:34:21 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:21 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:21 ;org.jboss.cache.interceptors.TxInterceptor;;;Registering sync handler for tx com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344, gtx GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:21 ;org.jboss.cache.interceptors.TxInterceptor;;;registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:199, tx=com.ibm.ws.Transaction.JTA.TransactionImpl@283072741));;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:31; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)])];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;acquireReadLock(): caller GlobalTransaction:<null>:199 already owns lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:31; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)])];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;acquireReadLock(): caller GlobalTransaction:<null>:199 already owns lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:31; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)])];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;acquireReadLock(): caller GlobalTransaction:<null>:199 already owns lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:201 ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:201;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Registering sync handler for tx com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344, gtx GlobalTransaction:<null>:201;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:201, tx=com.ibm.ws.Transaction.JTA.TransactionImpl@283072741));;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:199 ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:201 ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:201;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:199 ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:201 ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:201;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:26; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)] ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;acquireReadLock(): caller GlobalTransaction:<null>:199 already owns lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:26; Args: ( arg[0] = /values/BASELOAD/MIN_FTC/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,MIN_FTC,2008-05-29,2008-05-29)] ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:26; Args: ( arg[0] = /values/BASELOAD/MAX_FTC/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,MAX_FTC,2008-05-29,2008-05-29)] ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:26; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/200000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,200000,DUE_OUTPUT,2008-05-29,2008-05-29)] ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 1,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:26; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/200000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,200000,DUE_OUTPUT,2008-05-29,2008-05-29)] ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is null;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Registering sync handler for tx com.ibm.ws.Transaction.JTA.TransactionImpl@39ff58df#tid=1349, gtx GlobalTransaction:<null>:202;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@10df58e5#tid=1344 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:202, tx=com.ibm.ws.Transaction.JTA.TransactionImpl@973035743));;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_put; id:1; Args: ( arg[0] = GlobalTransaction:<null>:202 ...)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 1,5,main];;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:202;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@39ff58df#tid=1349 is already registered.;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;upgrading RL to WL for GlobalTransaction:<null>:202, timeout=15000, locks: Read lock owners: [GlobalTransaction:<null>:199, GlobalTransaction:<null>:202] Write lock owner: null ;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;upgrading lock for /values/BASELOAD/DUE_OUTPUT/200000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,200000,DUE_OUTPUT,2008-05-29,2008-05-29)];;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;calling aftercompletion for GlobalTransaction:<null>:199;;;;;FINEST;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Running rollback phase;;;;;FINE;; 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; running rollback for GlobalTransaction:<null>:199;;;;;FINEST;;
Obviously, #199 had a problem somewhere and is being rolled back. Nothing unusual so far, and I'd expect the rollback to continue with a "Finished local commit/rollback method" message. But there's nothing like that at this point of the log file.
Instead, this is the next time transaction #199 occurs in the log (15 seconds later):
2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:31; Args: ( arg[0] = /values/BASELOAD/MIN_FTC/313020100/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,313020100,MIN_FTC,2008-05-29,2008-05-29)])];;;;;FINEST;; 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 1,5,main];;;;;FINE;; 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:214;;;;;FINEST;; 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl@13a698dc#tid=1492 is already registered.;;;;;FINE;; 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;Identity;1;other ; ;;org.jboss.cache.lock.IdentityLock;;;acquireReadLock(): caller GlobalTransaction:<null>:214 already owns lock for /values/BASELOAD/MIN_FTC/313020100/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,313020100,MIN_FTC,2008-05-29,2008-05-29)];;;;;FINEST;; 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;Identity;1;other ; ;;org.jboss.cache.lock.IdentityLock;;;read lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)] could not be acquired by Thread[WebContainer : 0,5,main] after 15000 ms. Locks: Read lock owners: [] Write lock owner: GlobalTransaction:<null>:199 , lock info: write owner=GlobalTransaction:<null>:199 (org.jboss.cache.lock.LockStrategyReadCommitted@369798d2);;;;;FINEST;;
This is the next time transaction #199 occurs (again, 15 seconds later):
2008-10-07 19:34:52 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:224 ...)];;;;;FINEST;; 2008-10-07 19:34:52 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 1,5,main];;;;;FINE;; 2008-10-07 19:34:52 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:224;;;;;FINEST;; 2008-10-07 19:34:52 ;GMT+01:00 ;S83XB ;Identity;1;other ; ;;org.jboss.cache.lock.IdentityLock;;;read lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)] could not be acquired by Thread[WebContainer : 0,5,main] after 15000 ms. Locks: Read lock owners: [] Write lock owner: GlobalTransaction:<null>:199 , lock info: write owner=GlobalTransaction:<null>:199 (org.jboss.cache.lock.LockStrategyReadCommitted@369798d2);;;;;FINEST;;
These are the only two times a lock could not be obtained, and both times transaction #199 blocks them.
The following is the first time "Finished rollback phase" is logged after "Running rollback phase". Between there and here it's 45 seconds of time or 75,000 lines of log file. Note that the expected "Finished local commit/rollback method for GlobalTransaction::199" is never logged! I conclude from this that it's transaction #199 that has a problem with its rollback phase:
2008-10-07 19:35:07 ;org.jboss.cache.lock.IdentityLock;;;read lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)] could not be acquired by Thread[WebContainer : 0,5,main] after 15000 ms. Locks: Read lock owners: [] Write lock owner: GlobalTransaction:<null>:199 , lock info: write owner=GlobalTransaction:<null>:199 (org.jboss.cache.lock.LockStrategyReadCommitted@369798d2);;;;;FINEST;; 2008-10-07 19:35:07 ;org.jboss.cache.interceptors.TxInterceptor;;;Rollback had a problem;;;;;WARNING;; 2008-10-07 19:35:07 ;org.jboss.cache.interceptors.TxInterceptor;;;Finished rollback phase;;;;;FINE;; 2008-10-07 19:35:07 ;com.sdm.p69.fileadapter.internal.importer.TransportObjectProcessor;;UNCAUGHT; Stack Trace: javax.ejb.TransactionRolledbackLocalException: ; nested exception is: java.util.ConcurrentModificationException java.util.ConcurrentModificationException at java.util.AbstractList$Itr.checkForComodification(AbstractList.java(Inlined Compiled Code)) at java.util.AbstractList$Itr.next(AbstractList.java(Compiled Code)) at com.sdm.p32.clustertargetvalue.internal.ServiceTargetValueSet_NewCache.containsTargetValueData(ServiceTargetValueSet_NewCache.java(Compiled Code))
Of course we can fix the ConcurrentModificationException in our code, but such an error must not lead to lost locks.
Much later in the log, the lock by transaction #199 still persists and blocks any other locking attempts. Additionally, further locks seem to stack (tx #574):
2008-10-07 19:38:50 ;com.sdm.p69.fileadapter.internal.importer.TransportObjectProcessor;;UNCAUGHT; Stack Trace: javax.ejb.TransactionRolledbackLocalException: ; nested exception is: Cache "TargetValueCacheDistributed": failure acquiring lock: fqn=/values/BASELOAD/DUE_OUTPUT/260201020, caller=GlobalTransaction:<null>:592, lock=write owner=GlobalTransaction:<null>:574 (org.jboss.cache.lock.LockStrategyReadCommitted@2baa18c4) TargetValueCacheDistributed lock information follows: Own transaction: GlobalTransaction:<null>:592 Locking scheme: PESSIMISTIC, READ_COMMITTED Root lock: (read owners=[GlobalTransaction:<null>:199, GlobalTransaction:<null>:592, GlobalTransaction:<null>:593]) /values (read owners=[GlobalTransaction:<null>:199, GlobalTransaction:<null>:592, GlobalTransaction:<null>:593]) /BASELOAD (read owners=[GlobalTransaction:<null>:199, GlobalTransaction:<null>:592, GlobalTransaction:<null>:593]) /DUE_OUTPUT (read owners=[GlobalTransaction:<null>:199, GlobalTransaction:<null>:592, GlobalTransaction:<null>:593]) /491000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,491000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /550000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,550000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /300004100 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,300004100,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /90000014 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,90000014,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /313060100 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,313060100,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /540000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,540000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /262104000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,262104000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /303250 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,303250,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /530000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,530000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /360005405 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,360005405,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /260201010 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260201010,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /360002200 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,360002200,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /260102000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260102000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /520000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,520000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /312040000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,312040000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /510000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,510000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /313020100 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,313020100,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /312020000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,312020000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /260201020 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260201020,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /307990799 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,307990799,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /311100000 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,311100000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /300520 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,300520,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /410010100 (write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,410010100,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574) /260700000 (read owners=[GlobalTransaction:<null>:199], write owner=GlobalTransaction:<null>:574) /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:199) /300006000 /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,300006000,DUE_OUTPUT,2008-05-29,2008-05-29)] /112000 /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,112000,DUE_OUTPUT,2008-05-29,2008-05-29)] /311040000 /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,311040000,DUE_OUTPUT,2008-05-29,2008-05-29)] /313020210 /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,313020210,DUE_OUTPUT,2008-05-29,2008-05-29)]
Are these conclusions correct? Even if they're not, IMO this kind of situation shouldn't leave these locks in the lock table.
