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

    Timeout/Lock exception in single user/single thread environm

    Mark Doppelfeld Newbie

      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 Surtani Master

          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.

          • 2. Re: Timeout/Lock exception in single user/single thread envi
            Mark Doppelfeld Newbie

            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]

            • 3. Re: Timeout/Lock exception in single user/single thread envi
              Manik Surtani Master

              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.

              • 4. Re: Timeout/Lock exception in single user/single thread envi
                Mark Doppelfeld Newbie

                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

                • 5. Re: Timeout/Lock exception in single user/single thread envi
                  Manik Surtani Master

                  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?

                  • 6. Re: Timeout/Lock exception in single user/single thread envi
                    Mark Doppelfeld Newbie

                    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

                    • 7. Re: Timeout/Lock exception in single user/single thread envi
                      Manik Surtani Master

                      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.

                      • 8. Re: Timeout/Lock exception in single user/single thread envi
                        Mark Doppelfeld Newbie

                        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

                        • 9. Re: Timeout/Lock exception in single user/single thread envi
                          Manik Surtani Master

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