8 Replies Latest reply on Sep 2, 2008 7:01 AM by manik

    Endless loop trying to obtain lock in 1.4.1.SP9

    bradleydouglas

      Hi,

      I've been trying to work around this problem but nothing I do seems to fix it. We're using jboss cache as hibernate's second level cache and have problems where in predicatble behaviours in our application, the cache appears to go into an infinate loop trying to lock an entity it already has a lock on.

      I can provide full logging output, but it's quite large, and I can't attach it as a file - however I've included two samples from the logs. The first is a grep through our logs for the key of that seems to be causing the problem "PeerOrgCode#4". The second is a full sample of the endless loop that is repeated in our logs forever.

      Please, if anyone can suggest a solution or work around, I really need to get this working. Thanks.



      2008-08-14 11:33:26,948 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:26,948 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:26,948 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:27,010 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:27,057 DEBUG [org.hibernate.engine.TwoPhaseLoad] adding entity to second-level cache: [com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:27,057 TRACE [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [_get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, true)]
      2008-08-14 11:33:27,057 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, true)
      2008-08-14 11:33:27,057 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner GlobalTransaction:<null>:12
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] failed to find or create child com.synyati.spurwing.security.entity.PeerOrgCode#4 of node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.interceptors.CallInterceptor] Invoking method _get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, true) on cache.
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.TreeCache] _get("/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4", item, "true")
      2008-08-14 11:33:27,073 DEBUG [org.hibernate.cache.TransactionalCache] caching: com.synyati.spurwing.security.entity.PeerOrgCode#4
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [_put; id:4(null, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, CacheEntry(com.synyati.spurwing.security.entity.PeerOrgCode)[1,true,2006-01-01 00:00:00.0,1,null,null,NTH,5,4,0], true, 0)]
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _put; id:4(null, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, CacheEntry(com.synyati.spurwing.security.entity.PeerOrgCode)[1,true,2006-01-01 00:00:00.0,1,null,null,NTH,5,4,0], true, 0)
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.Node] created child: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=<unlocked>
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.interceptors.CallInterceptor] Invoking method _put; id:4(null, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, CacheEntry(com.synyati.spurwing.security.entity.PeerOrgCode)[1,true,2006-01-01 00:00:00.0,1,null,null,NTH,5,4,0], true, 0) on cache.
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.TreeCache] _put(null, "/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4", item, CacheEntry(com.synyati.spurwing.security.entity.PeerOrgCode)[1,true,2006-01-01 00:00:00.0,1,null,null,NTH,5,4,0])
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] Adding event EvictedEN[fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 event=3 diff=1] to region at /_default_/
      2008-08-14 11:33:27,073 TRACE [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4: write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:27,073 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:28,291 DEBUG [org.jboss.cache.eviction.BaseEvictionAlgorithm] Adding element /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for a node that doesn't exist yet. Process as an add.
      2008-08-14 11:33:28,291 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] Adding node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 with 1 elements to eviction queue
      2008-08-14 11:33:28,291 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 added successfully to eviction queue
      2008-08-14 11:33:39,604 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=GlobalTransaction:<null>:14, lock=<unlocked>
      2008-08-14 11:33:39,604 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=GlobalTransaction:<null>:14, lock=write owner=GlobalTransaction:<null>:14
      2008-08-14 11:33:39,729 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=GlobalTransaction:<null>:14, lock=write owner=GlobalTransaction:<null>:14
      2008-08-14 11:33:39,729 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 (caller=GlobalTransaction:<null>:14)
      2008-08-14 11:33:39,729 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=GlobalTransaction:<null>:14, lock=write owner=GlobalTransaction:<null>:14
      2008-08-14 11:33:40,604 TRACE [org.jboss.cache.TransactionEntry] releasing lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 (write owner=GlobalTransaction:<null>:14)
      2008-08-14 11:33:49,620 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:49,620 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:49,620 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:49,698 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:49,745 DEBUG [org.hibernate.engine.TwoPhaseLoad] adding entity to second-level cache: [com.synyati.spurwing.security.entity.PeerOrgCode#4]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [_get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, true)]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, true)
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner GlobalTransaction:<null>:15
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=GlobalTransaction:<null>:15, lock=<unlocked>
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=GlobalTransaction:<null>:15, lock=read owners=[GlobalTransaction:<null>:15]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.CallInterceptor] Invoking method _get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, true) on cache.
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.TreeCache] _get("/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4", item, "true")
      2008-08-14 11:33:49,745 DEBUG [org.hibernate.cache.TransactionalCache] caching: com.synyati.spurwing.security.entity.PeerOrgCode#4
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [_put; id:4(null, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, CacheEntry(com.synyati.spurwing.security.entity.PeerOrgCode)[1,true,2006-01-01 00:00:00.0,1,null,null,NTH,5,4,0], true, 0)]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _put; id:4(null, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, item, CacheEntry(com.synyati.spurwing.security.entity.PeerOrgCode)[1,true,2006-01-01 00:00:00.0,1,null,null,NTH,5,4,0], true, 0)
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 (caller=Thread[http-127.0.0.1-8080-1,5,jboss])
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 (caller=Thread[http-127.0.0.1-8080-1,5,jboss])
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 (caller=Thread[http-127.0.0.1-8080-1,5,jboss])
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 (caller=Thread[http-127.0.0.1-8080-1,5,jboss])
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 (caller=Thread[http-127.0.0.1-8080-1,5,jboss])
      2008-08-14 11:33:49,745 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]



      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode (caller=Thread[http-127.0.0.1-8080-1,5,jboss])
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 (caller=Thread[http-127.0.0.1-8080-1,5,jboss])
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode/com.synyati.spurwing.security.entity.PeerOrgCode#4 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jboss]]
      2008-08-14 11:33:51,760 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:15, Thread[http-127.0.0.1-8080-1,5,jbo


        • 1. Re: Endless loop trying to obtain lock in 1.4.1.SP9
          mircea.markus

          This is a known issue: https://jira.jboss.org/jira/browse/JBCACHE-1235.
          It was fixed in 2.1, take a look at the suggested workaround here: https://jira.jboss.org/jira/browse/JBCACHE-1165, or upgrade to a newer version

          • 2. Re: Endless loop trying to obtain lock in 1.4.1.SP9
            bradleydouglas

            Thanks for replying - but I've got two things to clear up.

            Firstly, is there a way to tell which version of the cache is being used? The reason I ask is that I've upgraded out app & jboss app server to use the core cahce version 2.2.1 and still appear to have the same problem with it endlessly looping trying to lock a node that is already locked by the user.

            I've attached the new logs below, and would really appreciate some help, as I've had to disable 2nd level cacheing in hibernate as this is taking our production environment off the air when it goes awry. The first logs are a grep for "ReconciliationBatch#2" showing the life of the node that is being locked when things go bad. The second is a snippet of all the jboss.cache logs around where the endless loop starts.

            Please - any help or hints about how resolve this would be really appreciated, and if more details are needed I'm happy to provide them.

            Thanks,


            2008-08-25 16:12:34,953 TRACE [org.hibernate.event.def.DefaultFlushEntityEventListener] Updating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,015 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Updating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,015 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Dehydrating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,015 DEBUG [org.hibernate.cache.TransactionalCache] updating: com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2
            2008-08-25 16:12:35,015 TRACE [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [_put; id:3(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,Mon Aug 25 16:12:33 EST 2008,3,Mon Aug 25 16:12:33 EST 2008,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv], true)]
            2008-08-25 16:12:35,015 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _put; id:3(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,Mon Aug 25 16:12:33 EST 2008,3,Mon Aug 25 16:12:33 EST 2008,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv], true)
            2008-08-25 16:12:35,015 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 for owner GlobalTransaction:<null>:10
            2008-08-25 16:12:35,015 TRACE [org.jboss.cache.Node] created child: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2
            2008-08-25 16:12:35,015 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:10, lock=<unlocked>
            2008-08-25 16:12:35,015 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:10, lock=write owner=GlobalTransaction:<null>:10
            2008-08-25 16:12:35,015 TRACE [org.jboss.cache.interceptors.CallInterceptor] Invoking method _put; id:3(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,Mon Aug 25 16:12:33 EST 2008,3,Mon Aug 25 16:12:33 EST 2008,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv], true) on cache.
            2008-08-25 16:12:35,015 TRACE [org.jboss.cache.TreeCache] _put(GlobalTransaction:<null>:10, "/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2", item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,Mon Aug 25 16:12:33 EST 2008,3,Mon Aug 25 16:12:33 EST 2008,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv])
            2008-08-25 16:12:35,015 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] Adding event EvictedEN[fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 event=3 diff=1] to region at /_default_/
            2008-08-25 16:12:35,125 TRACE [org.hibernate.engine.QueryParameters] named parameters: {batch=com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2}
            2008-08-25 16:12:35,171 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:10, lock=write owner=GlobalTransaction:<null>:10
            2008-08-25 16:12:35,171 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 (caller=GlobalTransaction:<null>:10)
            2008-08-25 16:12:35,171 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:10, lock=write owner=GlobalTransaction:<null>:10
            2008-08-25 16:12:35,531 DEBUG [org.jboss.cache.eviction.BaseEvictionAlgorithm] Adding element /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 for a node that doesn't exist yet. Process as an add.
            2008-08-25 16:12:35,531 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] Adding node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 with 1 elements to eviction queue
            2008-08-25 16:12:35,531 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 added successfully to eviction queue
            2008-08-25 16:12:35,531 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:10, lock=write owner=GlobalTransaction:<null>:10
            2008-08-25 16:12:35,531 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 (caller=GlobalTransaction:<null>:10)
            2008-08-25 16:12:35,531 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:10, lock=write owner=GlobalTransaction:<null>:10
            2008-08-25 16:12:35,718 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,718 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,718 TRACE [org.hibernate.event.def.DefaultLoadEventListener] object not resolved in any cache: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,718 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Fetching entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,718 DEBUG [org.hibernate.loader.Loader] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,734 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8765], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,734 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,734 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,734 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8766], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,734 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8767], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,734 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,734 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,734 TRACE [org.hibernate.engine.QueryParameters] named parameters: {batch=com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2}
            2008-08-25 16:12:35,828 TRACE [org.hibernate.engine.QueryParameters] named parameters: {batch=com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2}
            2008-08-25 16:12:35,828 TRACE [org.hibernate.engine.QueryParameters] named parameters: {batch=com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2}
            2008-08-25 16:12:35,828 TRACE [org.hibernate.engine.QueryParameters] named parameters: {batch=com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2}
            2008-08-25 16:12:35,828 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,828 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,828 TRACE [org.hibernate.event.def.DefaultLoadEventListener] object not resolved in any cache: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,828 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Fetching entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,828 DEBUG [org.hibernate.loader.Loader] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,843 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8765], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,843 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,843 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,843 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8766], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,843 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8767], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,843 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:35,843 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:40,406 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method prepare; id:10(GlobalTransaction:<null>:10, [_put; id:3(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,Mon Aug 25 16:12:33 EST 2008,3,Mon Aug 25 16:12:33 EST 2008,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv], true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/TransactionMapping, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatchDataMatch, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationSummary, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Transaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/User, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/SecurityGroupTransaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Menu, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reservation/segment/entity/SegmentStatus, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/UserRole, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationErrorData, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/UserSecurityGroup, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/money/entity/CardType, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Module, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/SecurityGroup, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Organisation, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/DomainRestriction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reservation/segment/entity/SegmentType, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Domain, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/OrganisationSynonym, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/money/entity/CurrencyDescription, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/i18n/entity/Message, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/ModuleTransaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatchData, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/TransactionMapping, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatchDataMatch, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationSummary, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Transaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/User, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/SecurityGroupTransaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Menu, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reservation/segment/entity/SegmentStatus, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/UserRole, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationErrorData, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/UserSecurityGroup, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/money/entity/CardType, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Module, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/SecurityGroup, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Organisation, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/DomainRestriction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reservation/segment/entity/SegmentType, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Domain, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/OrganisationSynonym, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/money/entity/CurrencyDescription, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/i18n/entity/Message, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/ModuleTransaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatchData, true)], null, false)
            2008-08-25 16:12:40,406 TRACE [org.jboss.cache.interceptors.CallInterceptor] Suppressing invocation of method prepare; id:10(GlobalTransaction:<null>:10, [_put; id:3(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,Mon Aug 25 16:12:33 EST 2008,3,Mon Aug 25 16:12:33 EST 2008,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv], true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/TransactionMapping, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatchDataMatch, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationSummary, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Transaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/User, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/SecurityGroupTransaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Menu, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reservation/segment/entity/SegmentStatus, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/UserRole, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationErrorData, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/UserSecurityGroup, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/money/entity/CardType, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Module, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/SecurityGroup, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Organisation, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/DomainRestriction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reservation/segment/entity/SegmentType, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Domain, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/OrganisationSynonym, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/money/entity/CurrencyDescription, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/i18n/entity/Message, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/ModuleTransaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatchData, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/TransactionMapping, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatchDataMatch, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationSummary, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Transaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/User, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/SecurityGroupTransaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/PeerOrgCode, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Menu, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reservation/segment/entity/SegmentStatus, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/UserRole, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationErrorData, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/UserSecurityGroup, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/money/entity/CardType, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Module, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/SecurityGroup, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Organisation, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/DomainRestriction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reservation/segment/entity/SegmentType, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/Domain, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/OrganisationSynonym, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/money/entity/CurrencyDescription, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/i18n/entity/Message, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/security/entity/ModuleTransaction, true), _remove; id:5(GlobalTransaction:<null>:10, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatchData, true)], null, false) on cache.
            2008-08-25 16:12:40,468 TRACE [org.jboss.cache.TransactionEntry] releasing lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 (write owner=GlobalTransaction:<null>:10)
            2008-08-25 16:12:41,312 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,312 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,312 TRACE [org.hibernate.event.def.DefaultLoadEventListener] object not resolved in any cache: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,312 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Fetching entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,312 DEBUG [org.hibernate.loader.Loader] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,312 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8765], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,312 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,312 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,328 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8766], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,328 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8767], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,328 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,328 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,328 TRACE [org.hibernate.engine.QueryParameters] named parameters: {batch=com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2}
            2008-08-25 16:12:41,359 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,359 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,359 TRACE [org.hibernate.event.def.DefaultLoadEventListener] object not resolved in any cache: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,359 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Fetching entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,359 DEBUG [org.hibernate.loader.Loader] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,359 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8765], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,359 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,359 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,359 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8766], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,359 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8767], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,375 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,375 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,484 TRACE [org.hibernate.engine.QueryParameters] named parameters: {batch=com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2}
            2008-08-25 16:12:41,500 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 TRACE [org.hibernate.event.def.DefaultLoadEventListener] object not resolved in any cache: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Fetching entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 DEBUG [org.hibernate.loader.Loader] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8765], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8766], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8767], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,500 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,625 TRACE [org.hibernate.engine.QueryParameters] named parameters: {batch=com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2}
            2008-08-25 16:12:41,640 TRACE [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,640 TRACE [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,640 TRACE [org.hibernate.event.def.DefaultLoadEventListener] object not resolved in any cache: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,640 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Fetching entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,640 DEBUG [org.hibernate.loader.Loader] loading entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,656 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8765], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,656 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,656 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,656 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8766], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,656 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.security.entity.Organisation#3], EntityKey[com.synyati.spurwing.i18n.entity.Message#8767], null, null, EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,656 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:41,656 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:55,906 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:55,906 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:55,906 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:55,906 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:55,937 DEBUG [org.hibernate.engine.TwoPhaseLoad] adding entity to second-level cache: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [_get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, true)]
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, true)
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 for owner GlobalTransaction:<null>:11
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.interceptors.CallInterceptor] Invoking method _get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, true) on cache.
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.TreeCache] _get("/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2", item, "true")
            2008-08-25 16:12:55,937 DEBUG [org.hibernate.cache.TransactionalCache] caching: com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [_put; id:4(null, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,2008-08-25 16:12:33.0,3,2008-08-25 16:12:33.0,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv], true, 0)]
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _put; id:4(null, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,2008-08-25 16:12:33.0,3,2008-08-25 16:12:33.0,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv], true, 0)
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.Node] created child: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=<unlocked>
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.interceptors.CallInterceptor] Invoking method _put; id:4(null, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,2008-08-25 16:12:33.0,3,2008-08-25 16:12:33.0,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv], true, 0) on cache.
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.TreeCache] _put(null, "/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2", item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,2008-08-25 16:12:33.0,3,2008-08-25 16:12:33.0,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv])
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] Adding event EvictedEN[fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 event=3 diff=1] to region at /_default_/
            2008-08-25 16:12:55,937 TRACE [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2: write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
            2008-08-25 16:12:55,937 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:13:15,093 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:12, lock=<unlocked>
            2008-08-25 16:13:15,093 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:12, lock=write owner=GlobalTransaction:<null>:12
            2008-08-25 16:13:15,140 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:12, lock=write owner=GlobalTransaction:<null>:12
            2008-08-25 16:13:15,140 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 (caller=GlobalTransaction:<null>:12)
            2008-08-25 16:13:15,140 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:12, lock=write owner=GlobalTransaction:<null>:12
            2008-08-25 16:13:17,281 TRACE [org.jboss.cache.TransactionEntry] releasing lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 (write owner=GlobalTransaction:<null>:12)
            2008-08-25 16:13:43,453 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:13, lock=<unlocked>
            2008-08-25 16:13:43,453 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:13, lock=write owner=GlobalTransaction:<null>:13
            2008-08-25 16:13:43,953 TRACE [org.jboss.cache.TransactionEntry] releasing lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 (write owner=GlobalTransaction:<null>:13)
            2008-08-25 16:14:15,828 TRACE [org.jboss.cache.eviction.LRUAlgorithm] Node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 has been idle for 75344ms
            2008-08-25 16:14:15,828 TRACE [org.jboss.cache.eviction.LRUAlgorithm] Node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 has been alive for 100297ms
            2008-08-25 16:14:15,828 TRACE [org.jboss.cache.eviction.LRUAlgorithm] Node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 should not be evicted
            2008-08-25 16:14:20,812 TRACE [org.jboss.cache.eviction.LRUAlgorithm] Node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 has been idle for 80328ms
            2008-08-25 16:14:20,812 TRACE [org.jboss.cache.eviction.LRUAlgorithm] Node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 has been alive for 105281ms
            2008-08-25 16:14:20,812 TRACE [org.jboss.cache.eviction.LRUAlgorithm] Node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 should not be evicted
            2008-08-25 16:14:23,921 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:14:23,921 TRACE [org.hibernate.loader.Loader] Initializing object from ResultSet: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:14:23,921 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:14:23,953 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:14:23,953 DEBUG [org.hibernate.engine.TwoPhaseLoad] adding entity to second-level cache: [com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [_get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, true)]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, true)
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 for owner GlobalTransaction:<null>:14
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:14, lock=<unlocked>
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.CallInterceptor] Invoking method _get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, true) on cache.
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.TreeCache] _get("/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2", item, "true")
            2008-08-25 16:14:23,953 DEBUG [org.hibernate.cache.TransactionalCache] caching: com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [_put; id:4(null, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,2008-08-25 16:12:33.0,3,2008-08-25 16:12:33.0,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv], true, 0)]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _put; id:4(null, /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, CacheEntry(com.synyati.spurwing.reconciliation.entity.ReconciliationBatch)[1,true,2008-08-25 16:12:33.0,3,2008-08-25 16:12:33.0,3,CONTRIBUTED,2,3,2,null,0,null,BGD100_payer.csv], true, 0)
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:14], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 for owner Thread[http-127.0.0.1-8080-1,5,jboss]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:14], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 (caller=Thread[http-127.0.0.1-8080-1,5,jboss])
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired WL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=Thread[http-127.0.0.1-8080-1,5,jboss], lock=read owners=[GlobalTransaction:<null>:14], write owner=Thread[http-127.0.0.1-8080-1,5,jboss]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 for owner Thread[http-127.0.0.1-8080-1,5,jboss]




            2008-08-25 16:14:20,812 TRACE [org.jboss.cache.eviction.LRUAlgorithm] Node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 has been idle for 80328ms
            2008-08-25 16:14:20,812 TRACE [org.jboss.cache.eviction.LRUAlgorithm] Node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 has been alive for 105281ms
            2008-08-25 16:14:20,812 TRACE [org.jboss.cache.eviction.LRUAlgorithm] Node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 should not be evicted
            ...
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] Invoking EvictionInterceptor
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] Updating node/element events with no tx
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.eviction.RegionManager] getRegion(): user-specified region not found: / will use the global default region
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.eviction.RegionManager] getRegion(): user-specified region not found: / will use the global default region
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] Adding event EvictedEN[fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#3 event=2 diff=0] to region at /_default_/
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] Finished updating node
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] Finished invoking EvictionInterceptor
            2008-08-25 16:14:23,953 DEBUG [org.hibernate.cache.TransactionalCache] item already cached: com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#3
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [_get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, true)]
            2008-08-25 16:14:23,953 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[http-127.0.0.1-8080-1,5,jboss]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:14
            2008-08-25 16:14:23,953 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Transaction TransactionImple < ac, BasicAction: -3f57fe3d:1215:48b24c98:263 status: ActionStatus.RUNNING > is already registered.
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method _get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, true)
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2 for owner GlobalTransaction:<null>:14
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired RL: fqn=/, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquiring RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:14, lock=<unlocked>
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.Node] acquired RL: fqn=/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, caller=GlobalTransaction:<null>:14, lock=read owners=[GlobalTransaction:<null>:14]
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.CallInterceptor] Invoking method _get; id:26(/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2, item, true) on cache.
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.TreeCache] _get("/spurwing_ear,spurwing-ejb_jar,SpurwingEM/com/synyati/spurwing/reconciliation/entity/ReconciliationBatch/com.synyati.spurwing.reconciliation.entity.ReconciliationBatch#2", item, "true")
            2008-08-25 16:14:23,953 TRACE [org.jboss.cache.interceptors.EvictionInterceptor


            • 3. Re: Endless loop trying to obtain lock in 1.4.1.SP9
              manik

               

              "BradleyDouglas" wrote:

              Firstly, is there a way to tell which version of the cache is being used? The reason I ask is that I've upgraded out app & jboss app server to use the core cahce version 2.2.1 and still appear to have the same problem with it endlessly looping trying to lock a node that is already locked by the user.


              There is no version 2.2.1. To tell which version you have, do this:

              
               $ java -jar /path/to/jbosscache-core.jar
              
              


              • 4. Re: Endless loop trying to obtain lock in 1.4.1.SP9
                manik

                Also, what lock level do you use, and which cache provider implementation have you configured Hibernate to use?

                • 5. Re: Endless loop trying to obtain lock in 1.4.1.SP9
                  bradleydouglas

                  Hey - thanks for the quick response.

                  Bah! typo, I've upgraded us to 2.1.1.GA:


                  C:\synyati\workspace\spurwing_jboss\lib\runtime\cache>java -jar jbosscache-core-2.1.1.GA.jar

                  Version: 2.1.1.GA
                  Codename: Alegrias
                  History: (see http://jira.jboss.com/jira/browse/JBCACHE for details)


                  It would be very cool if the version # was output in the logs (as many tools do) so it was 100% certain to be picking up the right version. anyway, I've nuked all the other jboss cache jars out of our app srever & ear.

                  From our persistence.xml:
                  <property name="hibernate.cache.provider_class" value="org.hibernate.cache.TreeCacheProvider"/>
                  


                  Our cache config:
                  <?xml version="1.0" encoding="UTF-8" ?>
                  <server>
                   <classpath codebase="./lib" archives="jboss-cache.jar, jgroups.jar" />
                  
                   <!-- ==================================================================== -->
                   <!-- Defines TreeCache configuration -->
                   <!-- ==================================================================== -->
                   <mbean code="org.jboss.cache.TreeCache" name="jboss.cache:service=SpurwingTreeCache">
                   <depends>jboss:service=Naming</depends>
                   <depends>jboss:service=TransactionManager</depends>
                  
                  
                   <!-- Configure the TransactionManager -->
                   <attribute name="TransactionManagerLookupClass">org.jboss.cache.JBossTransactionManagerLookup</attribute>
                  
                   <!--
                   Node locking scheme :
                   PESSIMISTIC (default)
                   OPTIMISTIC
                   -->
                   <attribute name="NodeLockingScheme">PESSIMISTIC</attribute>
                  
                   <!--
                   Node locking isolation level :
                   SERIALIZABLE
                   REPEATABLE_READ (default)
                   READ_COMMITTED
                   READ_UNCOMMITTED
                   NONE
                  
                   (ignored if NodeLockingScheme is OPTIMISTIC)
                   -->
                   <attribute name="IsolationLevel">READ_COMMITTED</attribute>
                  
                   <!-- Lock parent before doing node additions/removes -->
                   <attribute name="LockParentForChildInsertRemove">true</attribute>
                  
                   <!-- Valid modes are LOCAL
                   REPL_ASYNC
                   REPL_SYNC
                   INVALIDATION_ASYNC
                   INVALIDATION_SYNC
                   -->
                   <attribute name="CacheMode">LOCAL</attribute>
                  
                   <!-- Whether each interceptor should have an mbean
                   registered to capture and display its statistics. -->
                   <attribute name="UseInterceptorMbeans">true</attribute>
                  
                   <!-- Name of cluster. Needs to be the same for all TreeCache nodes in a
                   cluster, in order to find each other -->
                   <attribute name="ClusterName">Spurwing-PojoCache-Cluster</attribute>
                  
                   <!-- Uncomment next three statements to enable JGroups multiplexer.
                   This configuration is dependent on the JGroups multiplexer being
                   registered in an MBean server such as JBossAS. -->
                   <!--
                   <depends>jgroups.mux:name=Multiplexer</depends>
                   <attribute name="MultiplexerService">jgroups.mux:name=Multiplexer</attribute>
                   <attribute name="MultiplexerStack">udp</attribute>
                   -->
                  
                   <!-- JGroups protocol stack properties. ClusterConfig isn't used if the
                   multiplexer is enabled and successfully initialized. -->
                  <!-- <attribute name="ClusterConfig">
                   <config> -->
                   <!-- UDP: if you have a multihomed machine,
                   set the bind_addr attribute to the appropriate NIC IP address
                   -->
                  
                   <!-- UDP: On Windows machines, because of the media sense feature
                   being broken with multicast (even after disabling media sense)
                   set the loopback attribute to true
                   -->
                  <!-- <UDP mcast_port="45566" ip_ttl="64" ip_mcast="true"
                   mcast_send_buf_size="150000" mcast_recv_buf_size="80000" ucast_send_buf_size="150000"
                   ucast_recv_buf_size="80000" loopback="false" />
                   <PING timeout="2000" num_initial_members="3" up_thread="false" down_thread="false" />
                   <MERGE2 min_interval="10000" max_interval="20000" />
                   <FD shun="true" up_thread="true" down_thread="true" />
                   <VERIFY_SUSPECT timeout="1500" up_thread="false" down_thread="false" />
                   <pbcast.NAKACK gc_lag="50" max_xmit_size="8192" retransmit_timeout="600,1200,2400,4800" up_thread="false"
                   down_thread="false" />
                   <UNICAST timeout="600,1200,2400" window_size="100" min_threshold="10" down_thread="false" />
                   <pbcast.STABLE desired_avg_gossip="20000" up_thread="false" down_thread="false" />
                   <FRAG frag_size="8192" down_thread="false" up_thread="false" />
                   <pbcast.GMS join_timeout="5000" join_retry_timeout="2000" shun="true" print_local_addr="true" />
                   <pbcast.STATE_TRANSFER up_thread="false" down_thread="false" />
                   </config>
                   </attribute> -->
                  
                   <!-- The max amount of time (in milliseconds) we wait until the
                   initial state (ie. the contents of the cache) are retrieved from
                   existing members in a clustered environment
                   -->
                   <attribute name="InitialStateRetrievalTimeout">5000</attribute>
                  
                   <!-- Number of milliseconds to wait until all responses for a
                   synchronous call have been received.
                   -->
                   <attribute name="SyncReplTimeout">10000</attribute>
                  
                   <!-- Max number of milliseconds to wait for a lock acquisition -->
                   <attribute name="LockAcquisitionTimeout">15000</attribute>
                  
                   <!-- Name of the eviction policy class. -->
                   <attribute name="EvictionPolicyClass">org.jboss.cache.aop.eviction.AopLRUPolicy</attribute>
                  
                   <!-- Specific eviction policy configurations. This is LRU -->
                   <attribute name="EvictionPolicyConfig">
                   <config>
                   <attribute name="wakeUpIntervalSeconds">5</attribute>
                   <!-- Cache wide default -->
                   <region name="/_default_">
                   <attribute name="maxNodes">5000</attribute>
                   <attribute name="timeToLiveSeconds">1000</attribute>
                   <!-- Maximum time an object is kept in cache regardless of idle time -->
                   <attribute name="maxAgeSeconds">120</attribute>
                   </region>
                  
                   <region name="forgotPasswordRequest">
                   <attribute name="maxNodes">1000</attribute>
                   <attribute name="maxAgeSeconds">3600</attribute>
                   <attribute name="timeToLiveSeconds">0</attribute>
                   </region>
                  
                   <region name="ReconciliationOrgCodeLookup">
                   <attribute name="maxNodes">1000</attribute>
                   <attribute name="maxAgeSeconds">3600</attribute>
                   <attribute name="timeToLiveSeconds">0</attribute>
                   </region>
                  
                   <region name="ReservationStatusQuery">
                   <attribute name="maxNodes">1000</attribute>
                   <attribute name="maxAgeSeconds">3600</attribute>
                   <attribute name="timeToLiveSeconds">0</attribute>
                   </region>
                  
                   <region name="getModuleByName">
                   <attribute name="maxNodes">15</attribute>
                   <attribute name="maxAgeSeconds">3600</attribute>
                   <attribute name="timeToLiveSeconds">0</attribute>
                   </region>
                  
                   <region name="getTransactionByName">
                   <attribute name="maxNodes">15</attribute>
                   <attribute name="maxAgeSeconds">3600</attribute>
                   <attribute name="timeToLiveSeconds">0</attribute>
                   </region>
                  
                   </config>
                   </attribute>
                  
                   </mbean>
                  </server>
                  




                  • 6. Re: Endless loop trying to obtain lock in 1.4.1.SP9
                    manik

                    Version info is printed to the log file on startup. Just set your log level to INFO. :-)

                    • 7. Re: Endless loop trying to obtain lock in 1.4.1.SP9
                      bradleydouglas

                      Hi again,

                      Well I think I'm not going to be able to fix this. I've just looked at the compatability section of the jboss cache web site and saw that 2.1.1 isn't compatible with the jboss app server - which is what all our stuff run in.

                      I've also looked in the jxm console, and confirmed that our cache is still picking up an old version: JBossCache 'Cayenne' 1.4.1.SP3. I don't know where it's getting that from though as I've removed every old cache jar I could find.

                      Do you have any suggestions? If you look at our config you'll see that we're already running on READ_COMMITTED isolation level - which is what I beleive the work around you first pointed me to suggested.

                      At the moment I've disabled 2nd level caching - but would really like to get it working if possible.

                      PS - I'm guessing the version logging wasn't in that old version as I'm not seeing it and have set the priority to "ALL".

                      Life wasn't meant to be easy eh?

                      • 8. Re: Endless loop trying to obtain lock in 1.4.1.SP9
                        manik