9 Replies Latest reply on Jan 25, 2008 11:55 AM by manik

single thread environm

doubble Jan 23, 2008 4:40 AM

Hi together,

I'm new to JBossCache so probably this might have been asked before, but I couldn't find any directly related information in the forum or documentation.
We are running JBossCache in local mode with isolation level repeatable read and pessimistic locking. I'm facing Timeout exceptions on acquiring read or write locks on a node, claiming my thread already has a read/write lock on this node??? I completely do not understand what is going on there, that's the reason why I didn't put any configuration or code details here.
Could someone please shed some light on this?!?!

Thanks in advance
Mark

1. Re: Timeout/Lock exception in single user/single thread envi

manik Jan 23, 2008 7:50 AM (in response to doubble)

Do you mean an upgrade exception? I can't imagine why you'd get a lock timeout exception if you already hold the lock you need.
Actions
2. Re: Timeout/Lock exception in single user/single thread envi

doubble Jan 23, 2008 10:14 AM (in response to doubble)

Hi Manik,

I tried to set isolation level to NONE. Thsi works fine for a while, then I'm facing an infinte loop in PessimisticLockInterceptor. Below I'll paste snippets from my log files. In the next post I would like to give you some snippets of my log file in case of isolation level REPEATABLE_READ and READ_COMMITTED. Btw, I tried Ver. 1.2.4 SP2 (?) up to 1.4.1.SP8...

Best regards
Mark
last succesful put to cache here

15:42:32,086 [http-0.0.0.0-8080-1] INFO (7F0328D0587DFF513D9CC23EABAA6B4A) [BspPortalCommandFactory] creating navigation context in global session
15:42:32,086 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [GlobalSession] set: NAVIGATION_CONTEXT to: DefaultNavigationContext[[]] for session [7F0328D0587DFF513D9CC23EABAA6B4A/NAVIGATION_CONTEXT]
15:42:39,821 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] (null) call on method [_put; id:3(GlobalTransaction::6, /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A/NAVIGATION_CONTEXT, NAVIGATION_CONTEXT, DefaultNavigationContext[[]], true)]
15:42:39,821 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] local transaction exists - registering global tx if not present for Thread[http-0.0.0.0-8080-1,5,jboss]
15:42:39,821 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] Associated gtx in txTable is GlobalTransaction::6
15:42:39,821 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=dbn3f84/717, BranchQual=, localId=717] is already registered.
15:42:39,852 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _put; id:3(GlobalTransaction::6, /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A/NAVIGATION_CONTEXT, NAVIGATION_CONTEXT, DefaultNavigationContext[[]], true)
15:42:39,852 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A/NAVIGATION_CONTEXT for owner GlobalTransaction::6
15:42:39,852 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [Node] created child: fqn=/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A/NAVIGATION_CONTEXT
15:42:39,852 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [CallInterceptor] Invoking method _put; id:3(GlobalTransaction::6, /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A/NAVIGATION_CONTEXT, NAVIGATION_CONTEXT, DefaultNavigationContext[[]], true) on cache.
15:42:39,852 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TreeCache] _put(GlobalTransaction::6, "/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A/NAVIGATION_CONTEXT", NAVIGATION_CONTEXT, DefaultNavigationContext[[]])
15:42:52,368 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] (null) call on method [_remove; id:5(GlobalTransaction::6, /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, true)]
15:42:52,368 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] local transaction exists - registering global tx if not present for Thread[http-0.0.0.0-8080-1,5,jboss]
15:42:52,368 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] Associated gtx in txTable is GlobalTransaction::6
15:42:52,368 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=dbn3f84/717, BranchQual=, localId=717] is already registered.
15:42:52,368 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _remove; id:5(GlobalTransaction::6, /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, true)
15:42:52,368 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner GlobalTransaction::6
15:42:52,368 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [CallInterceptor] Invoking method _remove; id:5(GlobalTransaction::6, /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, true) on cache.
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TreeCache] _remove(GlobalTransaction::6, "/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A")
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] (null) call on method [_get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, navigationEvent, true)]
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, navigationEvent, true)
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [CallInterceptor] Invoking method _get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, navigationEvent, true) on cache.
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TreeCache] _get("/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A", navigationEvent, "true")
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [UnlockInterceptor] Attempting to release locks on current thread. Lock table is {}
15:42:52,415 [http-0.0.0.0-8080-1] INFO (7F0328D0587DFF513D9CC23EABAA6B4A) [RvpSessionListener] sessionCreated
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] (null) call on method [_get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, navigationEvent, true)]
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, navigationEvent, true)
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [CallInterceptor] Invoking method _get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, navigationEvent, true) on cache.
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TreeCache] _get("/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A", navigationEvent, "true")
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [UnlockInterceptor] Attempting to release locks on current thread. Lock table is {}
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] (null) call on method [_get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, navigationPath, true)]
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, navigationPath, true)
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [CallInterceptor] Invoking method _get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, navigationPath, true) on cache.
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TreeCache] _get("/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A", navigationPath, "true")
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [UnlockInterceptor] Attempting to release locks on current thread. Lock table is {}
15:42:52,415 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [GlobalSession] get: navigationPath returned:null
15:42:52,430 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] (null) call on method [_get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, MEA_EXCEPTION, true)]
15:42:52,430 [http-0.0.0.0-8080-1] DEBUG

omited loads of gets in between....

15:42:53,321 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:42:53,321 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [CallInterceptor] Invoking method _get; id:26(/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, navigationEvent, true) on cache.
15:42:53,321 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TreeCache] _get("/portalSession/7F0328D0587DFF513D9CC23EABAA6B4A", navigationEvent, "true")
15:42:53,321 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [UnlockInterceptor] Attempting to release locks on current thread. Lock table is {}
15:42:53,383 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [GlobalSession] set: preview to: false for session [7F0328D0587DFF513D9CC23EABAA6B4A]
15:43:01,211 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [TxInterceptor] (null) call on method [_put; id:3(null, /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, preview, false, true)]
15:43:01,211 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _put; id:3(null, /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A, preview, false, true)
15:43:01,211 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,211 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,211 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,211 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,211 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,227 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,227 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,227 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
15:43:01,243 [http-0.0.0.0-8080-1] DEBUG (7F0328D0587DFF513D9CC23EABAA6B4A) [PessimisticLockInterceptor] Attempting to lock node /portalSession/7F0328D0587DFF513D9CC23EABAA6B4A for owner Thread[http-0.0.0.0-8080-1,5,jboss]
Actions
3. Re: Timeout/Lock exception in single user/single thread envi

manik Jan 23, 2008 10:23 AM (in response to doubble)

Sounds like something related to JBCACHE-1165.

Isolation level of NONE always causes issues since there is no locking whatsoever between threads - not even read locks.

With REPEATABLE_READ you have timeout issues? I'd recommend focusing on R_R and the latest SP release from 1.4.1.
Actions
4. Re: Timeout/Lock exception in single user/single thread envi

doubble Jan 23, 2008 10:24 AM (in response to doubble)

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
Actions
5. Re: Timeout/Lock exception in single user/single thread envi

manik Jan 23, 2008 11:32 AM (in response to doubble)

This looks pretty normal to me. You have a reader (GlobalTransaction::2) which holds the lock on the node, and you have another thread (Thread[http-0.0.0.0-8080-2,5,jboss]) trying to get a hold of a write lock. Given R_R semantics, this thread will block until the reader completes and releases the read lock.

Have you tried increasing the lock acquisition timeout? Or using optimistic locking?
Actions
6. Re: Timeout/Lock exception in single user/single thread envi

doubble Jan 24, 2008 3:58 AM (in response to doubble)

Hi Malik,

I tried OptimisticLocking, it didn'T work either. I'm wondering why the reading Tx isn't committed or rolledback in my scenario? My test case consist of one client using the system, so I would expect the Tx to be ended at least when the Http response was written. Do I have to manually commit or rollback the Tx? How could I achieve this?
I'll try to increase lock acquisition timeout... and post my results here.
Regards
Mark
Actions
7. Re: Timeout/Lock exception in single user/single thread envi

manik Jan 24, 2008 5:41 AM (in response to doubble)
Try
Context ctx=new InitialContext(...); UserTranscation utx=(UserTransaction) ctx.lookup("java:comp/UserTransaction");

to get a hold of a UserTransaction, which you can then use to begin() and commit() your work.
Actions
8. Re: Timeout/Lock exception in single user/single thread envi

doubble Jan 24, 2008 9:58 AM (in response to doubble)

Hi,

increasing the timeout didn't work either. I tried to start my own tx and do rollback/commit also on my own, but I'm still facing locks.
Interestingly there is sometimes an existing Tx which Jboss Cache joins(is this correct) in that case, and I assume the obe who startetd this Tx forgot to commit/rollback it (there is also DB access in this project...)
As I don't want to interfere with this Tx, is there a way to suspend this Tx and start a new one (I know we will have trouble with this Tx, but I would like to defer this...)
Or is my theory totally crazy????
Regards
Mark
Actions
9. Re: Timeout/Lock exception in single user/single thread envi

manik Jan 25, 2008 11:55 AM (in response to doubble)

You could check if a tx is already running, and if so, suspend it and resume it again in a finally block, yes.
Actions

Go to original post