[JBossCache] - Re: Timeout/Lock exception in single user/single thread envi - jboss-user

Wednesday, 23 January 2008

Hi Manik,

enclosed is a big log which hopefully gives you a clue what's going in there when
using isolation level REPEATABLE_READ

That's what it says in the end...

Caused by: org.jboss.cache.lock.TimeoutException: write lock for
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 could not be acquired after 10000 ms.
Locks: Read lock owners: [GlobalTransaction::2]
Write lock owner: null
 (caller=Thread[http-0.0.0.0-8080-2,5,jboss], lock info: read
owners=[GlobalTransaction::2] (activeReaders=1, activeWriter=null, waitingReaders=0,
waitingWriters=0, waitingUpgrader=0))
	at org.jboss.cache.lock.IdentityLock.acquireWriteLock(IdentityLock.java:206)
	at org.jboss.cache.Node.acquireWriteLock(Node.java:529)
	at org.jboss.cache.Node.acquire(Node.java:476)
	... 257 more

nearly complete log till excpetion ...

16:18:04,977 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, valueMap, true)]
16:18:04,977 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, valueMap, true)
16:18:04,977 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:05,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=
16:18:05,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:05,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] failed to find or create child portalSession of node /
16:18:05,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, valueMap, true) on cache.
16:18:05,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", valueMap,
"true")
16:18:05,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:05,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read
owners=[Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:05,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: valueMap returned:null
16:18:05,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] no valueMap found, creating new one
16:18:05,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] set: valueMap to: {} for session [D44653CF8598B06D8CA8AC86E0619A01]
16:18:11,618 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_put; id:3(null,
/portalSession/D44653CF8598B06D8CA8AC86E0619A01, valueMap, {}, true)]
16:18:11,618 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _put;
id:3(null, /portalSession/D44653CF8598B06D8CA8AC86E0619A01, valueMap, {}, true)
16:18:11,618 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:11,618 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=
16:18:11,618 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:11,618 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node] created
child: fqn=/portalSession
16:18:11,618 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=
16:18:11,633 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:11,649 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node] created
child: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01
16:18:11,649 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring WL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=
16:18:11,649 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired WL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=write
owner=Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:18,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _put; id:3(null,
/portalSession/D44653CF8598B06D8CA8AC86E0619A01, valueMap, {}, true) on cache.
16:18:18,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_put(null, "/portalSession/D44653CF8598B06D8CA8AC86E0619A01", valueMap, {})
16:18:18,899 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[Thread[http-0.0.0.0-8080-1,5,jboss]],
read owners=[Thread[http-0.0.0.0-8080-1,5,jboss]], write
owner=Thread[http-0.0.0.0-8080-1,5,jboss]]}
16:18:18,899 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
write owner=Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:18,915 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read
owners=[Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:18,930 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read
owners=[Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:20,008 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT,
NAVIGATION_CONTEXT, true)]
16:18:20,008 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor]  local transaction exists - registering global tx if not present for
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:20,008 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] Associated gtx in txTable is null
16:18:20,008 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
created new GTX: GlobalTransaction::1, local TX=TransactionImpl:XidImpl[FormatId=257,
GlobalId=dbn3f84/193, BranchQual=, localId=193]
16:18:20,024 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] Registering sync handler for tx TransactionImpl:XidImpl[FormatId=257,
GlobalId=dbn3f84/193, BranchQual=, localId=193], gtx GlobalTransaction::1
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] registering for TX completion:
SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction::1,
tx=org.jboss.tm.TransactionImpl@24841074))
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT,
NAVIGATION_CONTEXT, true)
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT for owner
GlobalTransaction::1
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=GlobalTransaction::1, lock=
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=GlobalTransaction::1, lock=read owners=[GlobalTransaction::1]
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=GlobalTransaction::1, lock=
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=GlobalTransaction::1, lock=read
owners=[GlobalTransaction::1]
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=GlobalTransaction::1, lock=
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=GlobalTransaction::1, lock=read owners=[GlobalTransaction::1]
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] failed to find or create child NAVIGATION_CONTEXT of node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT,
NAVIGATION_CONTEXT, true) on cache.
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT",
NAVIGATION_CONTEXT, "true")
16:18:20,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: NAVIGATION_CONTEXT returned:null
16:18:23,836 [http-0.0.0.0-8080-1] INFO  (D44653CF8598B06D8CA8AC86E0619A01)
[BspPortalCommandFactory] creating navigation context in global session
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] set: NAVIGATION_CONTEXT to: DefaultNavigationContext[[]] for session
[D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT]
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_put; id:3(GlobalTransaction::1,
/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT, NAVIGATION_CONTEXT,
DefaultNavigationContext[[]], true)]
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor]  local transaction exists - registering global tx if not present for
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] Associated gtx in txTable is GlobalTransaction::1
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=dbn3f84/193,
BranchQual=, localId=193] is already registered.
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _put;
id:3(GlobalTransaction::1,
/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT, NAVIGATION_CONTEXT,
DefaultNavigationContext[[]], true)
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT for owner
GlobalTransaction::1
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=GlobalTransaction::1, lock=read owners=[GlobalTransaction::1]
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [IdentityLock]
acquireReadLock(): caller GlobalTransaction::1 already owns lock for /
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=GlobalTransaction::1, lock=read owners=[GlobalTransaction::1]
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=GlobalTransaction::1, lock=read
owners=[GlobalTransaction::1]
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [IdentityLock]
acquireReadLock(): caller GlobalTransaction::1 already owns lock for /portalSession
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=GlobalTransaction::1, lock=read
owners=[GlobalTransaction::1]
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=GlobalTransaction::1, lock=read owners=[GlobalTransaction::1]
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [IdentityLock]
acquireReadLock(): caller GlobalTransaction::1 already owns lock for
/portalSession/D44653CF8598B06D8CA8AC86E0619A01
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=GlobalTransaction::1, lock=read owners=[GlobalTransaction::1]
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node] created
child: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring WL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT,
caller=GlobalTransaction::1, lock=
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired WL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT,
caller=GlobalTransaction::1, lock=write owner=GlobalTransaction::1
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _put; id:3(GlobalTransaction::1,
/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT, NAVIGATION_CONTEXT,
DefaultNavigationContext[[]], true) on cache.
16:18:23,883 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_put(GlobalTransaction::1,
"/portalSession/D44653CF8598B06D8CA8AC86E0619A01/NAVIGATION_CONTEXT",
NAVIGATION_CONTEXT, DefaultNavigationContext[[]])
16:18:23,883 [http-0.0.0.0-8080-1] INFO  (D44653CF8598B06D8CA8AC86E0619A01)
[BspPortalCommandFactory] Sending Command to Prozess 0.
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true)]
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true)
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true) on cache.
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", navigationEvent,
"true")
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,493 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,524 [http-0.0.0.0-8080-1] INFO  (D44653CF8598B06D8CA8AC86E0619A01)
[RvpSessionListener] sessionCreated
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true)]
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true)
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true) on cache.
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", navigationEvent,
"true")
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:24,571 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,165 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationPath, true)]
16:18:27,165 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationPath, true)
16:18:27,165 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:27,165 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationPath, true) on cache.
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", navigationPath,
"true")
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,196 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: navigationPath returned:null
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, MEA_EXCEPTION, true)]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, MEA_EXCEPTION, true)
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, MEA_EXCEPTION, true) on cache.
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", MEA_EXCEPTION,
"true")
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,368 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: MEA_EXCEPTION returned:null
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true)]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true)
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true) on cache.
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", navigationEvent,
"true")
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true)]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true)
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, navigationEvent, true) on cache.
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", navigationEvent,
"true")
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,477 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true) on cache.
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", preview,
"true")
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: preview returned:null
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true) on cache.
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", preview,
"true")
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:27,680 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: preview returned:null
16:18:29,258 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)]
16:18:29,258 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)
16:18:29,258 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:29,258 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:29,258 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,274 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:29,274 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true) on cache.
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", preview,
"true")
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: preview returned:null
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true) on cache.
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", preview,
"true")
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:29,290 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: preview returned:null
16:18:29,352 [http-0.0.0.0-8080-1] INFO  (D44653CF8598B06D8CA8AC86E0619A01)
[RvpRefreshBean] startRefresh
16:18:29,352 [http-0.0.0.0-8080-1] INFO  (D44653CF8598B06D8CA8AC86E0619A01)
[RvpRefreshBean] first call, trying to schedule RVP refresh
16:18:29,352 [http-0.0.0.0-8080-1] INFO  (D44653CF8598B06D8CA8AC86E0619A01)
[RvpRefreshBean] account is federated, RVP refresh needed
16:18:29,368 [http-0.0.0.0-8080-1] INFO  (D44653CF8598B06D8CA8AC86E0619A01)
[RvpRefreshBean] RVP-Refresher scheduled. First callTime=2008-01-23 16:32:29.352+0100
interval=14min
16:18:30,399 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)]
16:18:30,399 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)
16:18:30,399 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:30,399 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:30,415 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true) on cache.
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", preview,
"true")
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: preview returned:null
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true) on cache.
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", preview,
"true")
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:30,430 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: preview returned:null
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true) on cache.
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", preview,
"true")
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /: read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:31,040 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[GlobalSession] get: preview returned:null
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[TxInterceptor] (null) call on method [_get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)]
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true)
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[PessimisticLockInterceptor] Attempting to lock node
/portalSession/D44653CF8598B06D8CA8AC86E0619A01 for owner
Thread[http-0.0.0.0-8080-1,5,jboss]
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1]
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession, caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read
owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquiring RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1]
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [Node]
acquired RL: fqn=/portalSession/D44653CF8598B06D8CA8AC86E0619A01,
caller=Thread[http-0.0.0.0-8080-1,5,jboss], lock=read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[CallInterceptor] Invoking method _get;
id:26(/portalSession/D44653CF8598B06D8CA8AC86E0619A01, preview, true) on cache.
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01) [TreeCache]
_get("/portalSession/D44653CF8598B06D8CA8AC86E0619A01", preview,
"true")
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] Attempting to release locks on current thread.  Lock table is
{Thread[http-0.0.0.0-8080-1,5,jboss]=[read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]], read owners=[GlobalTransaction::1,
Thread[http-0.0.0.0-8080-1,5,jboss]]]}
16:18:31,055 [http-0.0.0.0-8080-1] DEBUG (D44653CF8598B06D8CA8AC86E0619A01)
[UnlockInterceptor] releasing lock for /portalSession/D44653CF8598B06D8CA8AC86E0619A01:
read owners=[GlobalTransaction::1, Thread[http-0.0.0.0-8080-1,5,jboss]]
16:18:31,055

View the original post :
http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4122672#...

Reply to the post :
http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&a...

2026

2025

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

[JBossCache] - Re: Timeout/Lock exception in single user/single thread envi