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

[Brian Stansberry (JIRA)]

    [ http://jira.jboss.com/jira/browse/JBCACHE-1251?page=comments#action_12393314 ] 
            
Brian Stansberry commented on JBCACHE-1251:
-------------------------------------------

InvalidationInterceptorTest.testPessimisticNodeResurrection2() shows the problem.  I should probably move this test elsewhere, since it's not really a test of the InvalidationInterceptor.  But, that's where it is for now. :)

> 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
>
> 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.

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira