[jboss-jira] [JBoss JIRA] Commented: (JBCACHE-1251) Re-adding invalidated node fails with invalidation + pessimistic locking

Re-adding invalidated node fails with invalidation + pessimistic locking ------------------------------------------------------------------------ Key: JBCACHE-1251 URL: http://jira.jboss.com/jira/browse/JBCACHE-1251 Project: JBoss Cache Issue Type: Bug Security Level: Public(Everyone can see) Affects Versions: 2.1.0.CR2 Reporter: Brian Stansberry Assigned To: Manik Surtani Fix For: 2.1.0.GA Scenario is one where a parent node represents a structural node, and then child nodes represent different data elements. Such data structures are set up on both caches, and then the parent node is removed (globally, via INVALIDATION) and re-added (locally) on one cache. This represents an attempt to clear the region -- removing a node and re-adding is one of the only ways to do this. On the second cache, the fact that the structural node is missing is detected, and an attempt is made to re-add it locally. This fails with pessimistic locking: 18:50:34,821 TRACE PessimisticLockInterceptor:71 - PessimisticLockInterceptor invoked for method MethodName: _put; MethodIdInteger: 1; Args: (null, /test/com/foo/test/ENTITY, null, true) 18:50:34,821 TRACE PessimisticLockInterceptor:292 - Attempting to lock node /test/com/foo/test/ENTITY for owner Thread[main,5,main] 18:50:34,822 TRACE PessimisticLockInterceptor:334 - Directly got child node null 18:50:34,822 TRACE IdentityLock:264 - acquiring RL: fqn=/, caller=Thread[main,5,main], lock=<unlocked> 18:50:34,823 TRACE IdentityLock:270 - acquired RL: fqn=/, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,823 TRACE PessimisticLockInterceptor:334 - Directly got child node test 18:50:34,824 TRACE IdentityLock:264 - acquiring RL: fqn=/test, caller=Thread[main,5,main], lock=<unlocked> 18:50:34,824 TRACE IdentityLock:270 - acquired RL: fqn=/test, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,825 TRACE PessimisticLockInterceptor:334 - Directly got child node com 18:50:34,825 TRACE IdentityLock:264 - acquiring RL: fqn=/test/com, caller=Thread[main,5,main], lock=<unlocked> 18:50:34,826 TRACE IdentityLock:270 - acquired RL: fqn=/test/com, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,826 TRACE PessimisticLockInterceptor:334 - Directly got child node foo 18:50:34,827 TRACE IdentityLock:264 - acquiring RL: fqn=/test/com/foo, caller=Thread[main,5,main], lock=<unlocked> 18:50:34,827 TRACE IdentityLock:270 - acquired RL: fqn=/test/com/foo, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,828 TRACE PessimisticLockInterceptor:334 - Directly got child node test 18:50:34,828 TRACE IdentityLock:264 - acquiring RL: fqn=/test/com/foo/test, caller=Thread[main,5,main], lock=<unlocked> 18:50:34,829 TRACE IdentityLock:270 - acquired RL: fqn=/test/com/foo/test, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,829 TRACE PessimisticLockInterceptor:334 - Directly got child node ENTITY 18:50:34,830 TRACE IdentityLock:164 - acquiring WL: fqn=/test/com/foo/test/ENTITY, caller=Thread[main,5,main], lock=<unlocked> 18:50:34,830 TRACE IdentityLock:170 - acquired WL: fqn=/test/com/foo/test/ENTITY, caller=Thread[main,5,main], lock=write owner=Thread[main,5,main] 18:50:34,831 TRACE PessimisticLockInterceptor:292 - Attempting to lock node /test/com/foo/test/ENTITY for owner Thread[main,5,main] 18:50:34,831 TRACE PessimisticLockInterceptor:334 - Directly got child node null 18:50:34,832 TRACE IdentityLock:264 - acquiring RL: fqn=/, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,832 TRACE IdentityLock:307 - acquireReadLock(): caller Thread[main,5,main] already owns lock for / 18:50:34,833 TRACE IdentityLock:270 - acquired RL: fqn=/, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,833 TRACE PessimisticLockInterceptor:334 - Directly got child node test 18:50:34,834 TRACE IdentityLock:264 - acquiring RL: fqn=/test, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,834 TRACE IdentityLock:307 - acquireReadLock(): caller Thread[main,5,main] already owns lock for /test 18:50:34,835 TRACE IdentityLock:270 - acquired RL: fqn=/test, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,835 TRACE PessimisticLockInterceptor:334 - Directly got child node com 18:50:34,836 TRACE IdentityLock:264 - acquiring RL: fqn=/test/com, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,836 TRACE IdentityLock:307 - acquireReadLock(): caller Thread[main,5,main] already owns lock for /test/com 18:50:34,837 TRACE IdentityLock:270 - acquired RL: fqn=/test/com, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,837 TRACE PessimisticLockInterceptor:334 - Directly got child node foo 18:50:34,838 TRACE IdentityLock:264 - acquiring RL: fqn=/test/com/foo, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,838 TRACE IdentityLock:307 - acquireReadLock(): caller Thread[main,5,main] already owns lock for /test/com/foo 18:50:34,839 TRACE IdentityLock:270 - acquired RL: fqn=/test/com/foo, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,839 TRACE PessimisticLockInterceptor:334 - Directly got child node test 18:50:34,840 TRACE IdentityLock:264 - acquiring RL: fqn=/test/com/foo/test, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,840 TRACE IdentityLock:307 - acquireReadLock(): caller Thread[main,5,main] already owns lock for /test/com/foo/test 18:50:34,841 TRACE IdentityLock:270 - acquired RL: fqn=/test/com/foo/test, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]] 18:50:34,841 TRACE PessimisticLockInterceptor:334 - Directly got child node ENTITY 18:50:34,842 TRACE IdentityLock:164 - acquiring WL: fqn=/test/com/foo/test/ENTITY, caller=Thread[main,5,main], lock=write owner=Thread[main,5,main] 18:50:34,842 TRACE IdentityLock:187 - acquireWriteLock(): caller already owns lock for /test/com/foo/test/ENTITY (caller=Thread[main,5,main]) 18:50:34,843 TRACE IdentityLock:170 - acquired WL: fqn=/test/com/foo/test/ENTITY, caller=Thread[main,5,main], lock=write owner=Thread[main,5,main] 18:50:34,843 TRACE PessimisticLockInterceptor:292 - Attempting to lock node /test/com/foo/test/ENTITY for owner Thread[main,5,main] 18:50:34,844 TRACE PessimisticLockInterceptor:334 - Directly got child node null ..... continues looping through the hierarchy until the timeout kicks in and a TimeoutException is thrown The above described scenario describes what happens with the "region clearing" operations in the Hibernate/JBC integration.