4 Replies Latest reply on Jan 29, 2007 6:25 PM by Manik Surtani

    Read Locks not released broken between 1.4.1.beta and 1.4.1.

    youngm Novice

      I have an app that worked fine with 1.4.1.beta but with the upgrade to 1.4.1.GA it appears my read locks are no longer being released. I get the following error frequently with 1.4.1.GA but never with 1.4.1.beta:

      14:55:04,218 ERROR IdentityLock: write lock for / could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<null>:2]
      Write lock owner: null
       (caller=Thread[main,5,main], lock info: read owners=[GlobalTransaction:<null>:2] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
      14:55:04,218 ERROR IdentityLock: write lock for / could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<null>:2]
      Write lock owner: null
       (caller=Thread[main,5,main], lock info: read owners=[GlobalTransaction:<null>:2] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
      14:55:04,218 ERROR IdentityLock: write lock for / could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<null>:2]
      Write lock owner: null
       (caller=Thread[main,5,main], lock info: read owners=[GlobalTransaction:<null>:2] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
      14:55:04,296 ERROR IdentityLock: write lock for / could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<null>:2]
      Write lock owner: null
       (caller=Thread[main,5,main], lock info: read owners=[GlobalTransaction:<null>:2] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
      14:55:04,296 ERROR IdentityLock: write lock for / could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<null>:2]
      Write lock owner: null
       (caller=Thread[main,5,main], lock info: read owners=[GlobalTransaction:<null>:2] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))


      I'm using JBossCache with Spring 2.0.2+Hibernate EntityManager 3.2.1+JoTM for JTA.

      JBossCache is correctly getting my JoTM transaction manager and Spring is starting a transaction.

      And again this worked fine with 1.4.1.beta.

      Any ideas about what could be the problem?

      For good measure I've included my cacheService file:

      <?xml version="1.0" encoding="UTF-8"?>
      <!-- ===================================================================== -->
      <!-- JBossCache Configuration File: test or dev -->
      <!-- ===================================================================== -->
      <server>
       <mbean code="org.jboss.cache.TreeCache" name="$jmxDomain$:service=TreeCache">
       <attribute name="TransactionManagerLookupClass">
       org.lds.stack.spring.jpa.jbosscache.JBossCacheConfigurableTransactionLookup
       </attribute>
       <attribute name="NodeLockingScheme">PESSIMISTIC</attribute>
       <attribute name="IsolationLevel">REPEATABLE_READ</attribute>
       <attribute name="CacheMode">LOCAL</attribute>
       <attribute name="UseReplQueue">false</attribute>
       <attribute name="ReplQueueInterval">0</attribute>
       <attribute name="ReplQueueMaxElements">0</attribute>
       <attribute name="ClusterName">org.lds.stack.$jmxDomain$</attribute>
       <attribute name="FetchInMemoryState">false</attribute>
       <attribute name="SyncReplTimeout">20000</attribute>
       <attribute name="LockAcquisitionTimeout">15000</attribute>
       <attribute name="InitialStateRetrievalTimeout">20000</attribute>
       <attribute name="EvictionPolicyClass">org.jboss.cache.eviction.LRUPolicy</attribute>
       <attribute name="EvictionPolicyConfig">
       <config>
       <attribute name="wakeUpIntervalSeconds">5</attribute>
       <region name="/_default_">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">1000</attribute>
       </region>
       <region name="/org/lds/stack/petstore/model/Animal">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">1000</attribute>
       </region>
       <region name="/org/lds/stack/petstore/model/Classification">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">0</attribute>
       </region>
       <region name="/org/lds/stack/petstore/model/Country">
       <attribute name="maxNodes">10000</attribute>
       <attribute name="timeToLiveSeconds">0</attribute>
       </region>
       </config>
       </attribute>
       <attribute name="UseRegionBasedMarshalling">false</attribute>
       </mbean>
      </server>
      


        • 1. Re: Read Locks not released broken between 1.4.1.beta and 1.
          Manik Surtani Master

          Are there any stack traces that depict an error? Perhaps if you increase your log level to TRACE?

          And can you consistently reproduce this, perhaps in a unit test?

          • 2. Re: Read Locks not released broken between 1.4.1.beta and 1.
            youngm Novice

            It happens consistently with 1.4.1.GA and never happenned with 1.4.1.beta. Here is a log with both Hibernate and JBossCache on trace. Below this I've included a log of hibernate and jbossCache on trace with everything the same except using 1.4.1.beta instead of 1.4.1.GA.

            I would think it was something wrong with how I was setting up my transaction lookups between hibernate, spring, and JBossCache except it appears to work perfectly with 1.4.1.beta and to create the problem I simply have to swap out the jar.

            I wish I could provide a unit test but it would be quite the task bundling all these frameworks and and the integration of them into a unit test. I could provide a war for you if that would help To duplicate you would just have to start the server.

            Here are the logs.

            JBossCache 1.4.1.GA

            09:46:51,609 DEBUG SessionImpl: opened session at timestamp: 11700892115
            09:46:51,609 DEBUG JDBCContext: TransactionFactory reported no active transaction; Synchronization not registered
            09:46:51,609 DEBUG AbstractEntityManagerImpl: Looking for a JTA transaction to join
            09:46:51,625 DEBUG JDBCContext: successfully registered Synchronization
            09:46:51,625 DEBUG AbstractEntityManagerImpl: Adding flush() and close() synchronization
            09:46:51,671 DEBUG QueryPlanCache: unable to locate HQL query plan in cache; generating (select e from org.lds.stack.petstore.model.ApplicationProperty e)
            09:46:51,671 DEBUG QueryTranslatorImpl: parse() - HQL: select e from org.lds.stack.petstore.model.ApplicationProperty e
            09:46:51,671 DEBUG AST: --- HQL AST ---
             \-[QUERY] 'query'
             \-[SELECT_FROM] 'SELECT_FROM'
             +-[FROM] 'from'
             | \-[RANGE] 'RANGE'
             | +-[DOT] '.'
             | | +-[DOT] '.'
             | | | +-[DOT] '.'
             | | | | +-[DOT] '.'
             | | | | | +-[DOT] '.'
             | | | | | | +-[IDENT] 'org'
             | | | | | | \-[IDENT] 'lds'
             | | | | | \-[IDENT] 'stack'
             | | | | \-[IDENT] 'petstore'
             | | | \-[IDENT] 'model'
             | | \-[IDENT] 'ApplicationProperty'
             | \-[ALIAS] 'e'
             \-[SELECT] 'select'
             \-[IDENT] 'e'
            
            09:46:51,703 DEBUG ErrorCounter: throwQueryException() : no errors
            09:46:51,703 DEBUG HqlSqlBaseWalker: select << begin [level=1, statement=select]
            09:46:51,703 DEBUG FromElement: FromClause{level=1} : org.lds.stack.petstore.model.ApplicationProperty (e) -> applicatio0_
            09:46:51,703 DEBUG FromReferenceNode: Resolved : e -> applicatio0_.name
            09:46:51,703 DEBUG HqlSqlBaseWalker: select : finishing up [level=1, statement=select]
            09:46:51,703 DEBUG HqlSqlWalker: processQuery() : ( SELECT ( {select clause} applicatio0_.name ) ( FromClause{level=1} APP_PROPERTIES applicatio0_ ) )
            09:46:51,703 DEBUG JoinProcessor: Using FROM fragment [APP_PROPERTIES applicatio0_]
            09:46:51,703 DEBUG HqlSqlBaseWalker: select >> end [level=1, statement=select]
            09:46:51,703 DEBUG AST: --- SQL AST ---
             \-[SELECT] QueryNode: 'SELECT' querySpaces (APP_PROPERTIES)
             +-[SELECT_CLAUSE] SelectClause: '{select clause}'
             | +-[ALIAS_REF] IdentNode: 'applicatio0_.name as name0_' {alias=e, className=org.lds.stack.petstore.model.ApplicationProperty, tableAlias=applicatio0_}
             | \-[SQL_TOKEN] SqlFragment: 'applicatio0_.prop_value as prop2_0_'
             \-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[e], fromElementByTableAlias=[applicatio0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
             \-[FROM_FRAGMENT] FromElement: 'APP_PROPERTIES applicatio0_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=e,role=null,tableName=APP_PROPERTIES,tableAlias=applicatio0_,origin=null,colums={,className=org.lds.stack.petstore.model.ApplicationProperty}}
            
            09:46:51,703 DEBUG ErrorCounter: throwQueryException() : no errors
            09:46:51,703 DEBUG QueryTranslatorImpl: HQL: select e from org.lds.stack.petstore.model.ApplicationProperty e
            09:46:51,703 DEBUG QueryTranslatorImpl: SQL: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_
            09:46:51,703 DEBUG ErrorCounter: throwQueryException() : no errors
            09:46:51,703 DEBUG HQLQueryPlan: HQL param location recognition took 0 mills (select e from org.lds.stack.petstore.model.ApplicationProperty e)
            09:46:51,703 DEBUG QueryPlanCache: located HQL query plan in cache (select e from org.lds.stack.petstore.model.ApplicationProperty e)
            09:46:51,703 DEBUG HQLQueryPlan: find: select e from org.lds.stack.petstore.model.ApplicationProperty e
            09:46:51,703 DEBUG QueryParameters: named parameters: {}
            09:46:51,718 DEBUG StandardQueryCache: checking cached query results in region: org.hibernate.cache.StandardQueryCache
            09:46:51,718 DEBUG TxInterceptor: (null) call on method [_get; id:26(/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, item, true)]
            09:46:51,718 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _get; id:26(/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, item, true)
            09:46:51,718 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {} for owner Thread[main,5,main]
            09:46:51,718 DEBUG Node: acquiring RL: fqn=/, caller=Thread[main,5,main], lock=<unlocked>
            09:46:51,718 DEBUG Node: acquired RL: fqn=/, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            09:46:51,734 DEBUG PessimisticLockInterceptor: failed to find or create child org of node /
            09:46:51,734 DEBUG CallInterceptor: Invoking method _get; id:26(/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, item, true) on cache.
            09:46:51,734 DEBUG TreeCache: _get("/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}", item, "true")
            09:46:51,734 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
            09:46:51,734 DEBUG EvictionInterceptor: Updating node/element events with no tx
            09:46:51,734 DEBUG EvictionInterceptor: No event added. Element does not exist
            09:46:51,734 DEBUG EvictionInterceptor: No node modifications
            09:46:51,734 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
            09:46:51,734 DEBUG UnlockInterceptor: Attempting to release locks on current thread. Lock table is {Thread[main,5,main]=[read owners=[Thread[main,5,main]]]}
            09:46:51,734 DEBUG UnlockInterceptor: releasing lock for /: read owners=[Thread[main,5,main]]
            09:46:51,734 DEBUG StandardQueryCache: query results were not found in cache
            09:46:51,734 DEBUG AbstractBatcher: about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            09:46:51,734 DEBUG ConnectionManager: opening JDBC connection
            09:46:51,734 DEBUG SQL:
             /* select
             e
             from
             org.lds.stack.petstore.model.ApplicationProperty e */ select
             applicatio0_.name as name0_,
             applicatio0_.prop_value as prop2_0_
             from
             APP_PROPERTIES applicatio0_
            Hibernate:
             /* select
             e
             from
             org.lds.stack.petstore.model.ApplicationProperty e */ select
             applicatio0_.name as name0_,
             applicatio0_.prop_value as prop2_0_
             from
             APP_PROPERTIES applicatio0_
            09:46:51,734 DEBUG AbstractBatcher: preparing statement
            09:46:51,765 DEBUG AbstractBatcher: about to open ResultSet (open ResultSets: 0, globally: 0)
            09:46:51,765 DEBUG Loader: processing result set
            09:46:51,765 DEBUG Loader: result set row: 0
            09:46:51,765 DEBUG StringType: returning 'ldap.url' as column: name0_
            09:46:51,781 DEBUG Loader: result row: EntityKey[org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:46:51,781 DEBUG Loader: Initializing object from ResultSet: [org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:46:51,781 DEBUG AbstractEntityPersister: Hydrating entity: [org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:46:51,781 DEBUG StringType: returning 'ldap://10.51.95.193' as column: prop2_0_
            09:46:51,781 DEBUG Loader: result set row: 1
            09:46:51,781 DEBUG StringType: returning 'ldap.manager.dn' as column: name0_
            09:46:51,781 DEBUG Loader: result row: EntityKey[org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
            09:46:51,781 DEBUG Loader: Initializing object from ResultSet: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
            09:46:51,781 DEBUG AbstractEntityPersister: Hydrating entity: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
            09:46:51,781 DEBUG StringType: returning 'cn=hansenbk,ou=People,o=WH' as column: prop2_0_
            09:46:51,781 DEBUG Loader: result set row: 2
            09:46:51,781 DEBUG StringType: returning 'ldap.manager.password' as column: name0_
            09:46:51,781 DEBUG Loader: result row: EntityKey[org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
            09:46:51,781 DEBUG Loader: Initializing object from ResultSet: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
            09:46:51,781 DEBUG AbstractEntityPersister: Hydrating entity: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
            09:46:51,781 DEBUG StringType: returning 'password' as column: prop2_0_
            09:46:51,781 DEBUG Loader: result set row: 3
            09:46:51,781 DEBUG StringType: returning 'smtp.host.name' as column: name0_
            09:46:51,781 DEBUG Loader: result row: EntityKey[org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name]
            09:46:51,781 DEBUG Loader: Initializing object from ResultSet: [org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name]
            09:46:51,781 DEBUG AbstractEntityPersister: Hydrating entity: [org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name]
            09:46:51,781 DEBUG StringType: returning 'smtp-relay.wh.ldsglobal.net' as column: prop2_0_
            09:46:51,796 DEBUG Loader: done processing result set (4 rows)
            09:46:51,796 DEBUG AbstractBatcher: about to close ResultSet (open ResultSets: 1, globally: 1)
            09:46:51,796 DEBUG AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            09:46:51,796 DEBUG AbstractBatcher: closing statement
            09:46:51,796 DEBUG ConnectionManager: aggressively releasing JDBC connection
            09:46:51,796 DEBUG ConnectionManager: releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            09:46:51,796 DEBUG Loader: total objects hydrated: 4
            09:46:51,796 DEBUG TwoPhaseLoad: resolving associations for [org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:46:51,796 DEBUG TwoPhaseLoad: adding entity to second-level cache: [org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:46:51,812 DEBUG TxInterceptor: (null) call on method [_get; id:26(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url, item, true)]
            09:46:51,812 DEBUG TxInterceptor: local transaction exists - registering global tx if not present for Thread[main,5,main]
            09:46:51,812 DEBUG TxInterceptor: Associated gtx in txTable is null
            09:46:51,812 DEBUG TreeCache: created new GTX: GlobalTransaction:<null>:1, local TX=bb14:38:0:01ddc3011eba1aaba6...d93001:
            09:46:51,812 DEBUG TxInterceptor: Registering sync handler for tx bb14:38:0:01ddc3011eba1aaba6...d93001:, gtx GlobalTransaction:<null>:1
            09:46:51,812 DEBUG TxInterceptor: registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:1, tx=bb14:38:0:01ddc3011eba1aaba6...d93001:))
            09:46:51,812 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _get; id:26(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url, item, true)
            09:46:51,812 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url for owner GlobalTransaction:<null>:1
            09:46:51,875 DEBUG Node: acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=<unlocked>
            09:46:51,875 DEBUG Node: acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            09:46:51,875 DEBUG PessimisticLockInterceptor: failed to find or create child org of node /
            09:46:51,875 DEBUG CallInterceptor: Invoking method _get; id:26(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url, item, true) on cache.
            09:46:51,875 DEBUG TreeCache: _get("/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url", item, "true")
            09:46:51,875 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
            09:46:51,875 DEBUG EvictionInterceptor: Updating node/element events with no tx
            09:46:51,875 DEBUG EvictionInterceptor: No event added. Element does not exist
            09:46:51,875 DEBUG EvictionInterceptor: No node modifications
            09:46:51,875 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
            09:46:51,875 DEBUG TransactionalCache: caching: org.lds.stack.petstore.model.ApplicationProperty#ldap.url
            09:46:51,875 DEBUG TxInterceptor: (null) call on method [_put; id:4(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=ldap://10.51.95.193, _version=null, _lazyPropertiesUnfetched=true}, true, 0)]
            09:46:51,875 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _put; id:4(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=ldap://10.51.95.193, _version=null, _lazyPropertiesUnfetched=true}, true, 0)
            09:46:51,875 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url for owner Thread[main,5,main]
            09:46:51,875 DEBUG Node: acquiring WL: fqn=/, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
            09:46:51,875 ERROR IdentityLock: write lock for / could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<null>:1]
            Write lock owner: null
             (caller=Thread[main,5,main], lock info: read owners=[GlobalTransaction:<null>:1] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
            09:46:51,875 DEBUG Node: failure acquiring lock: fqn=/, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
            09:46:51,875 DEBUG UnlockInterceptor: Attempting to release locks on current thread. Lock table is {}
            09:46:51,875 INFO TxInterceptor: There was a problem handling this request
            org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
             at org.jboss.cache.Node.acquire(Node.java:500)
             at org.jboss.cache.interceptors.PessimisticLockInterceptor.acquireNodeLock(PessimisticLockInterceptor.java:342)
             at org.jboss.cache.interceptors.PessimisticLockInterceptor.lock(PessimisticLockInterceptor.java:287)
             at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:172)
             at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
             at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:32)
             at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
             at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:364)
             at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:160)
             at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
             at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:157)
             at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:5710)
             at org.jboss.cache.TreeCache.putFailFast(TreeCache.java:3747)
             at org.hibernate.cache.TreeCache.put(TreeCache.java:74)
             at org.hibernate.cache.TransactionalCache.put(TransactionalCache.java:58)
             at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:156)
             at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:842)
             at org.hibernate.loader.Loader.doQuery(Loader.java:717)
             at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
             at org.hibernate.loader.Loader.doList(Loader.java:2211)
             at org.hibernate.loader.Loader.listUsingQueryCache(Loader.java:2127)
             at org.hibernate.loader.Loader.list(Loader.java:2087)
             at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:375)
             at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
             at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
             at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
             at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
             at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:64)
             at org.lds.stack.serviceproxy.jpa.hibernate.FindAllFindExecutor.executeQuery(FindAllFindExecutor.java:31)
             at org.lds.stack.serviceproxy.jpa.hibernate.EntityFindExecutor.executeQuery(EntityFindExecutor.java:15)
             at org.lds.stack.serviceproxy.jpa.FindInterceptor$1.doInJpa(FindInterceptor.java:43)
             at org.springframework.orm.jpa.JpaTemplate.execute(JpaTemplate.java:191)
             at org.springframework.orm.jpa.JpaTemplate.execute(JpaTemplate.java:154)
             at org.lds.stack.serviceproxy.jpa.FindInterceptor.invoke(FindInterceptor.java:39)
             at org.lds.stack.serviceproxy.ServiceProxyCglibInterceptor.intercept(ServiceProxyCglibInterceptor.java:48)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c.findAllProperties(<generated>)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService.entrySet(AbstractApplicationPropertyService.java:194)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c.CGLIB$entrySet$11(<generated>)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c$$FastClassByCGLIB$$299f1a43.invoke(<generated>)
             at net.sf.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:187)
             at org.lds.stack.serviceproxy.ServiceProxyCglibInterceptor.intercept(ServiceProxyCglibInterceptor.java:43)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c.entrySet(<generated>)
             at java.util.AbstractMap.size(AbstractMap.java:68)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c.CGLIB$size$25(<generated>)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c$$FastClassByCGLIB$$299f1a43.invoke(<generated>)
             at net.sf.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:187)
             at org.lds.stack.serviceproxy.ServiceProxyCglibInterceptor.intercept(ServiceProxyCglibInterceptor.java:43)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c.size(<generated>)
             at $java.util.AbstractMap$$FastClassByCGLIB$$6ee8901a.invoke(<generated>)
             at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:163)
             at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:675)
             at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:154)
             at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:107)
             at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
             at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:616)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$46274020.size(<generated>)
             at org.springframework.beans.TypeConverterDelegate.convertToTypedMap(TypeConverterDelegate.java:363)
             at org.springframework.beans.TypeConverterDelegate.convertIfNecessary(TypeConverterDelegate.java:205)
             at org.springframework.beans.TypeConverterDelegate.convertIfNecessary(TypeConverterDelegate.java:139)
             at org.springframework.beans.BeanWrapperImpl.setPropertyValue(BeanWrapperImpl.java:772)
             at org.springframework.beans.BeanWrapperImpl.setPropertyValue(BeanWrapperImpl.java:606)
             at org.springframework.beans.AbstractPropertyAccessor.setPropertyValue(AbstractPropertyAccessor.java:49)
             at org.springframework.beans.AbstractPropertyAccessor.setPropertyValues(AbstractPropertyAccessor.java:74)
             at org.springframework.beans.AbstractPropertyAccessor.setPropertyValues(AbstractPropertyAccessor.java:57)
             at org.springframework.beans.factory.support.AbstractBeanFactory.applyPropertyValues(AbstractBeanFactory.java:840)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1026)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:809)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:425)
             at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:250)
             at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:141)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:247)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:161)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:245)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:124)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveManagedMap(BeanDefinitionValueResolver.java:298)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:136)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1019)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:809)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:425)
             at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:250)
             at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:141)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:247)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:161)
             at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:273)
             at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:346)
             at org.springframework.web.context.support.AbstractRefreshableWebApplicationContext.refresh(AbstractRefreshableWebApplicationContext.java:156)
             at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
             at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
             at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
             at java.lang.reflect.Method.invoke(Method.java:585)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1160)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1122)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1085)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:429)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveInnerBeanDefinition(BeanDefinitionValueResolver.java:197)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:107)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1019)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:809)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:425)
             at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:250)
             at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:141)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:247)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:161)
             at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:642)
             at org.springframework.beans.factory.access.SingletonBeanFactoryLocator.useBeanFactory(SingletonBeanFactoryLocator.java:393)
             at org.lds.stack.spring.context.WebContextSingletonBeanFactoryLocator.useBeanFactory(WebContextSingletonBeanFactoryLocator.java:38)
             at org.lds.stack.spring.context.BootstrapContextLoader.createWebApplicationContext(BootstrapContextLoader.java:29)
             at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:184)
             at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:49)
             at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3763)
             at org.apache.catalina.core.StandardContext.start(StandardContext.java:4211)
             at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1013)
             at org.apache.catalina.core.StandardHost.start(StandardHost.java:718)
             at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1013)
             at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:442)
             at org.apache.catalina.core.StandardService.start(StandardService.java:450)
             at org.apache.catalina.core.StandardServer.start(StandardServer.java:709)
             at org.apache.catalina.startup.Catalina.start(Catalina.java:551)
             at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
             at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
             at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
             at java.lang.reflect.Method.invoke(Method.java:585)
             at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:294)
             at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:432)
            Caused by: org.jboss.cache.lock.TimeoutException: write lock for / could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<null>:1]
            Write lock owner: null
             (caller=Thread[main,5,main], lock info: read owners=[GlobalTransaction:<null>:1] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
             at org.jboss.cache.lock.IdentityLock.acquireWriteLock(IdentityLock.java:206)
             at org.jboss.cache.Node.acquireWriteLock(Node.java:529)
             at org.jboss.cache.Node.acquire(Node.java:476)
             ... 123 more
            09:46:51,875 DEBUG TreeCache: ignoring write lock acquisition failure
            09:46:51,875 DEBUG TwoPhaseLoad: done materializing entity [org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:46:51,875 DEBUG TwoPhaseLoad: resolving associations for [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
            09:46:51,875 DEBUG TwoPhaseLoad: adding entity to second-level cache: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
            09:46:51,875 DEBUG TxInterceptor: (null) call on method [_get; id:26(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, true)]
            09:46:51,875 DEBUG TxInterceptor: local transaction exists - registering global tx if not present for Thread[main,5,main]
            09:46:51,875 DEBUG TxInterceptor: Associated gtx in txTable is GlobalTransaction:<null>:1
            09:46:51,875 DEBUG TxInterceptor: Transaction bb14:38:0:01ddc3011eba1aaba6...d93001: is already registered.
            09:46:51,875 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _get; id:26(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, true)
            09:46:51,875 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn for owner GlobalTransaction:<null>:1
            09:46:51,875 DEBUG Node: acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            09:46:51,875 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /
            09:46:51,875 DEBUG Node: acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            09:46:51,875 DEBUG PessimisticLockInterceptor: failed to find or create child org of node /
            09:46:51,875 DEBUG CallInterceptor: Invoking method _get; id:26(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, true) on cache.
            09:46:51,875 DEBUG TreeCache: _get("/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn", item, "true")
            09:46:51,875 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
            09:46:51,875 DEBUG EvictionInterceptor: Updating node/element events with no tx
            09:46:51,875 DEBUG EvictionInterceptor: No event added. Element does not exist
            09:46:51,875 DEBUG EvictionInterceptor: No node modifications
            09:46:51,875 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
            09:46:51,875 DEBUG TransactionalCache: caching: org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn
            09:46:51,875 DEBUG TxInterceptor: (null) call on method [_put; id:4(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=cn=hansenbk,ou=People,o=WH, _version=null, _lazyPropertiesUnfetched=true}, true, 0)]
            09:46:51,875 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _put; id:4(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=cn=hansenbk,ou=People,o=WH, _version=null, _lazyPropertiesUnfetched=true}, true, 0)
            09:46:51,875 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn for owner Thread[main,5,main]
            09:46:51,875 DEBUG Node: acquiring WL: fqn=/, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
            09:46:51,875 ERROR IdentityLock: write lock for / could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<null>:1]
            Write lock owner: null
             (caller=Thread[main,5,main], lock info: read owners=[GlobalTransaction:<null>:1] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
            09:46:51,875 DEBUG Node: failure acquiring lock: fqn=/, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
            09:46:51,875 DEBUG UnlockInterceptor: Attempting to release locks on current thread. Lock table is {}
            09:46:51,875 INFO TxInterceptor: There was a problem handling this request
            org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
             at org.jboss.cache.Node.acquire(Node.java:500)
             at org.jboss.cache.interceptors.PessimisticLockInterceptor.acquireNodeLock(PessimisticLockInterceptor.java:342)
             at org.jboss.cache.interceptors.PessimisticLockInterceptor.lock(PessimisticLockInterceptor.java:287)
             at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:172)
             at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
             at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:32)
             at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
             at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:364)
             at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:160)
             at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
             at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:157)
             at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:5710)
             at org.jboss.cache.TreeCache.putFailFast(TreeCache.java:3747)
             at org.hibernate.cache.TreeCache.put(TreeCache.java:74)
             at org.hibernate.cache.TransactionalCache.put(TransactionalCache.java:58)
             at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:156)
             at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:842)
             at org.hibernate.loader.Loader.doQuery(Loader.java:717)
             at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
             at org.hibernate.loader.Loader.doList(Loader.java:2211)
             at org.hibernate.loader.Loader.listUsingQueryCache(Loader.java:2127)
             at org.hibernate.loader.Loader.list(Loader.java:2087)
             at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:375)
             at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
             at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
             at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
             at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
             at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:64)
             at org.lds.stack.serviceproxy.jpa.hibernate.FindAllFindExecutor.executeQuery(FindAllFindExecutor.java:31)
             at org.lds.stack.serviceproxy.jpa.hibernate.EntityFindExecutor.executeQuery(EntityFindExecutor.java:15)
             at org.lds.stack.serviceproxy.jpa.FindInterceptor$1.doInJpa(FindInterceptor.java:43)
             at org.springframework.orm.jpa.JpaTemplate.execute(JpaTemplate.java:191)
             at org.springframework.orm.jpa.JpaTemplate.execute(JpaTemplate.java:154)
             at org.lds.stack.serviceproxy.jpa.FindInterceptor.invoke(FindInterceptor.java:39)
             at org.lds.stack.serviceproxy.ServiceProxyCglibInterceptor.intercept(ServiceProxyCglibInterceptor.java:48)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c.findAllProperties(<generated>)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService.entrySet(AbstractApplicationPropertyService.java:194)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c.CGLIB$entrySet$11(<generated>)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c$$FastClassByCGLIB$$299f1a43.invoke(<generated>)
             at net.sf.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:187)
             at org.lds.stack.serviceproxy.ServiceProxyCglibInterceptor.intercept(ServiceProxyCglibInterceptor.java:43)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c.entrySet(<generated>)
             at java.util.AbstractMap.size(AbstractMap.java:68)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c.CGLIB$size$25(<generated>)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c$$FastClassByCGLIB$$299f1a43.invoke(<generated>)
             at net.sf.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:187)
             at org.lds.stack.serviceproxy.ServiceProxyCglibInterceptor.intercept(ServiceProxyCglibInterceptor.java:43)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$7beb109c.size(<generated>)
             at $java.util.AbstractMap$$FastClassByCGLIB$$6ee8901a.invoke(<generated>)
             at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:163)
             at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:675)
             at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:154)
             at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:107)
             at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
             at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:616)
             at org.lds.stack.petstore.service.AbstractApplicationPropertyService$$EnhancerByCGLIB$$46274020.size(<generated>)
             at org.springframework.beans.TypeConverterDelegate.convertToTypedMap(TypeConverterDelegate.java:363)
             at org.springframework.beans.TypeConverterDelegate.convertIfNecessary(TypeConverterDelegate.java:205)
             at org.springframework.beans.TypeConverterDelegate.convertIfNecessary(TypeConverterDelegate.java:139)
             at org.springframework.beans.BeanWrapperImpl.setPropertyValue(BeanWrapperImpl.java:772)
             at org.springframework.beans.BeanWrapperImpl.setPropertyValue(BeanWrapperImpl.java:606)
             at org.springframework.beans.AbstractPropertyAccessor.setPropertyValue(AbstractPropertyAccessor.java:49)
             at org.springframework.beans.AbstractPropertyAccessor.setPropertyValues(AbstractPropertyAccessor.java:74)
             at org.springframework.beans.AbstractPropertyAccessor.setPropertyValues(AbstractPropertyAccessor.java:57)
             at org.springframework.beans.factory.support.AbstractBeanFactory.applyPropertyValues(AbstractBeanFactory.java:840)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1026)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:809)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:425)
             at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:250)
             at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:141)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:247)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:161)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:245)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:124)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveManagedMap(BeanDefinitionValueResolver.java:298)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:136)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1019)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:809)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:425)
             at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:250)
             at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:141)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:247)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:161)
             at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:273)
             at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:346)
             at org.springframework.web.context.support.AbstractRefreshableWebApplicationContext.refresh(AbstractRefreshableWebApplicationContext.java:156)
             at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
             at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
             at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
             at java.lang.reflect.Method.invoke(Method.java:585)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1160)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1122)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1085)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:429)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveInnerBeanDefinition(BeanDefinitionValueResolver.java:197)
             at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:107)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1019)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:809)
             at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:425)
             at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:250)
             at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:141)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:247)
             at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:161)
             at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:642)
             at org.springframework.beans.factory.access.SingletonBeanFactoryLocator.useBeanFactory(SingletonBeanFactoryLocator.java:393)
             at org.lds.stack.spring.context.WebContextSingletonBeanFactoryLocator.useBeanFactory(WebContextSingletonBeanFactoryLocator.java:38)
             at org.lds.stack.spring.context.BootstrapContextLoader.createWebApplicationContext(BootstrapContextLoader.java:29)
             at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:184)
             at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:49)
             at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3763)
             at org.apache.catalina.core.StandardContext.start(StandardContext.java:4211)
             at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1013)
             at org.apache.catalina.core.StandardHost.start(StandardHost.java:718)
             at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1013)
             at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:442)
             at org.apache.catalina.core.StandardService.start(StandardService.java:450)
             at org.apache.catalina.core.StandardServer.start(StandardServer.java:709)
             at org.apache.catalina.startup.Catalina.start(Catalina.java:551)
             at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
             at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
             at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
             at java.lang.reflect.Method.invoke(Method.java:585)
             at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:294)
             at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:432)
            Caused by: org.jboss.cache.lock.TimeoutException: write lock for / could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<null>:1]
            Write lock owner: null
             (caller=Thread[main,5,main], lock info: read owners=[GlobalTransaction:<null>:1] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
             at org.jboss.cache.lock.IdentityLock.acquireWriteLock(IdentityLock.java:206)
             at org.jboss.cache.Node.acquireWriteLock(Node.java:529)
             at org.jboss.cache.Node.acquire(Node.java:476)
             ... 123 more
            09:46:51,890 DEBUG TreeCache: ignoring write lock acquisition failure
            09:46:51,890 DEBUG TwoPhaseLoad: done materializing entity [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
            09:46:51,890 DEBUG TwoPhaseLoad: resolving associations for [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
            09:46:51,890 DEBUG TwoPhaseLoad: adding entity to second-level cache: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
            09:46:51,890 DEBUG TxInterceptor: (null) call on method [_get; id:26(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, true)]
            09:46:51,890 DEBUG TxInterceptor: local transaction exists - registering global tx if not present for Thread[main,5,main]
            09:46:51,890 DEBUG TxInterceptor: Associated gtx in txTable is GlobalTransaction:<null>:1
            09:46:51,890 DEBUG TxInterceptor: Transaction bb14:38:0:01ddc3011eba1aaba6...d93001: is already registered.
            09:46:51,890 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _get; id:26(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, true)
            09:46:51,890 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password for owner GlobalTransaction:<null>:1
            09:46:51,890 DEBUG Node: acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            09:46:51,890 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /
            09:46:51,890 DEBUG Node: acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            09:46:51,890 DEBUG PessimisticLockInterceptor: failed to find or create child org of node /
            09:46:51,890 DEBUG CallInterceptor: Invoking method _get; id:26(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, true) on cache.
            09:46:51,890 DEBUG TreeCache: _get("/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password", item, "true")
            09:46:51,890 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
            09:46:51,890 DEBUG EvictionInterceptor: Updating node/element events with no tx
            09:46:51,890 DEBUG EvictionInterceptor: No event added. Element does not exist
            09:46:51,890 DEBUG EvictionInterceptor: No node modifications
            09:46:51,890 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
            09:46:51,890 DEBUG TransactionalCache: caching: org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password
            09:46:51,890 DEBUG TxInterceptor: (null) call on method [_put; id:4(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=password, _version=null, _lazyPropertiesUnfetched=true}, true, 0)]
            09:46:51,890 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _put; id:4(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=password, _version=null, _lazyPropertiesUnfetched=true}, true, 0)
            09:46:51,890 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password for owner Thread[main,5,main]
            09:46:51,890 DEBUG Node: acquiring WL: fqn=/, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
            09:46:51,890 ERROR IdentityLock: write lock for / could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<null>:1]
            Write lock owner: null
             (caller=Thread[main,5,main], lock info: read owners=[GlobalTransaction:<null>:1] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
            09:46:51,890 DEBUG Node: failure acquiring lock: fqn=/, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
            09:46:51,890 DEBUG UnlockInterceptor: Attempting to release locks on current thread. Lock table is {}
            09:46:51,890 INFO TxInterceptor: There was a problem handling this request
            


            JBossCache 1.4.1.beta
            09:55:31,593 DEBUG SessionImpl: opened session at timestamp: 11700897315
            09:55:31,593 DEBUG JDBCContext: TransactionFactory reported no active transaction; Synchronization not registered
            09:55:31,593 DEBUG AbstractEntityManagerImpl: Looking for a JTA transaction to join
            09:55:31,593 DEBUG JDBCContext: successfully registered Synchronization
            09:55:31,593 DEBUG AbstractEntityManagerImpl: Adding flush() and close() synchronization
            09:55:31,640 DEBUG QueryPlanCache: unable to locate HQL query plan in cache; generating (select e from org.lds.stack.petstore.model.ApplicationProperty e)
            09:55:31,640 DEBUG QueryTranslatorImpl: parse() - HQL: select e from org.lds.stack.petstore.model.ApplicationProperty e
            09:55:31,640 DEBUG AST: --- HQL AST ---
             \-[QUERY] 'query'
             \-[SELECT_FROM] 'SELECT_FROM'
             +-[FROM] 'from'
             | \-[RANGE] 'RANGE'
             | +-[DOT] '.'
             | | +-[DOT] '.'
             | | | +-[DOT] '.'
             | | | | +-[DOT] '.'
             | | | | | +-[DOT] '.'
             | | | | | | +-[IDENT] 'org'
             | | | | | | \-[IDENT] 'lds'
             | | | | | \-[IDENT] 'stack'
             | | | | \-[IDENT] 'petstore'
             | | | \-[IDENT] 'model'
             | | \-[IDENT] 'ApplicationProperty'
             | \-[ALIAS] 'e'
             \-[SELECT] 'select'
             \-[IDENT] 'e'
            
            09:55:31,640 DEBUG ErrorCounter: throwQueryException() : no errors
            09:55:31,640 DEBUG HqlSqlBaseWalker: select << begin [level=1, statement=select]
            09:55:31,640 DEBUG FromElement: FromClause{level=1} : org.lds.stack.petstore.model.ApplicationProperty (e) -> applicatio0_
            09:55:31,640 DEBUG FromReferenceNode: Resolved : e -> applicatio0_.name
            09:55:31,640 DEBUG HqlSqlBaseWalker: select : finishing up [level=1, statement=select]
            09:55:31,640 DEBUG HqlSqlWalker: processQuery() : ( SELECT ( {select clause} applicatio0_.name ) ( FromClause{level=1} APP_PROPERTIES applicatio0_ ) )
            09:55:31,640 DEBUG JoinProcessor: Using FROM fragment [APP_PROPERTIES applicatio0_]
            09:55:31,640 DEBUG HqlSqlBaseWalker: select >> end [level=1, statement=select]
            09:55:31,640 DEBUG AST: --- SQL AST ---
             \-[SELECT] QueryNode: 'SELECT' querySpaces (APP_PROPERTIES)
             +-[SELECT_CLAUSE] SelectClause: '{select clause}'
             | +-[ALIAS_REF] IdentNode: 'applicatio0_.name as name0_' {alias=e, className=org.lds.stack.petstore.model.ApplicationProperty, tableAlias=applicatio0_}
             | \-[SQL_TOKEN] SqlFragment: 'applicatio0_.prop_value as prop2_0_'
             \-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[e], fromElementByTableAlias=[applicatio0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
             \-[FROM_FRAGMENT] FromElement: 'APP_PROPERTIES applicatio0_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=e,role=null,tableName=APP_PROPERTIES,tableAlias=applicatio0_,origin=null,colums={,className=org.lds.stack.petstore.model.ApplicationProperty}}
            
            09:55:31,640 DEBUG ErrorCounter: throwQueryException() : no errors
            09:55:31,640 DEBUG QueryTranslatorImpl: HQL: select e from org.lds.stack.petstore.model.ApplicationProperty e
            09:55:31,640 DEBUG QueryTranslatorImpl: SQL: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_
            09:55:31,640 DEBUG ErrorCounter: throwQueryException() : no errors
            09:55:31,640 DEBUG HQLQueryPlan: HQL param location recognition took 0 mills (select e from org.lds.stack.petstore.model.ApplicationProperty e)
            09:55:31,640 DEBUG QueryPlanCache: located HQL query plan in cache (select e from org.lds.stack.petstore.model.ApplicationProperty e)
            09:55:31,640 DEBUG HQLQueryPlan: find: select e from org.lds.stack.petstore.model.ApplicationProperty e
            09:55:31,640 DEBUG QueryParameters: named parameters: {}
            09:55:31,656 DEBUG StandardQueryCache: checking cached query results in region: org.hibernate.cache.StandardQueryCache
            09:55:31,656 DEBUG TxInterceptor: (null) call on method [_get(/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, item, true)]
            09:55:31,656 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _get(/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, item, true)
            09:55:31,656 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {} for owner Thread[main,5,main]
            09:55:31,656 DEBUG PessimisticLockInterceptor: failed to find or create child org of node /
            09:55:31,656 DEBUG CallInterceptor: Invoking method _get(/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, item, true) on cache.
            09:55:31,656 DEBUG TreeCache: _get("/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}", item, "true")
            09:55:31,656 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
            09:55:31,656 DEBUG EvictionInterceptor: Updating node/element events with no tx
            09:55:31,656 DEBUG EvictionInterceptor: No event added. Element does not exist
            09:55:31,656 DEBUG EvictionInterceptor: No node modifications
            09:55:31,656 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
            09:55:31,656 DEBUG UnlockInterceptor: Attempting to release locks on current thread. Lock table is {}
            09:55:31,656 DEBUG StandardQueryCache: query results were not found in cache
            09:55:31,656 DEBUG AbstractBatcher: about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            09:55:31,656 DEBUG ConnectionManager: opening JDBC connection
            09:55:31,656 DEBUG SQL:
             /* select
             e
             from
             org.lds.stack.petstore.model.ApplicationProperty e */ select
             applicatio0_.name as name0_,
             applicatio0_.prop_value as prop2_0_
             from
             APP_PROPERTIES applicatio0_
            Hibernate:
             /* select
             e
             from
             org.lds.stack.petstore.model.ApplicationProperty e */ select
             applicatio0_.name as name0_,
             applicatio0_.prop_value as prop2_0_
             from
             APP_PROPERTIES applicatio0_
            09:55:31,656 DEBUG AbstractBatcher: preparing statement
            09:55:31,687 DEBUG AbstractBatcher: about to open ResultSet (open ResultSets: 0, globally: 0)
            09:55:31,687 DEBUG Loader: processing result set
            09:55:31,687 DEBUG Loader: result set row: 0
            09:55:31,687 DEBUG StringType: returning 'ldap.url' as column: name0_
            09:55:31,687 DEBUG Loader: result row: EntityKey[org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:55:31,687 DEBUG Loader: Initializing object from ResultSet: [org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:55:31,703 DEBUG AbstractEntityPersister: Hydrating entity: [org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:55:31,703 DEBUG StringType: returning 'ldap://10.51.95.193' as column: prop2_0_
            09:55:31,703 DEBUG Loader: result set row: 1
            09:55:31,703 DEBUG StringType: returning 'ldap.manager.dn' as column: name0_
            09:55:31,703 DEBUG Loader: result row: EntityKey[org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
            09:55:31,703 DEBUG Loader: Initializing object from ResultSet: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
            09:55:31,703 DEBUG AbstractEntityPersister: Hydrating entity: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
            09:55:31,703 DEBUG StringType: returning 'cn=hansenbk,ou=People,o=WH' as column: prop2_0_
            09:55:31,703 DEBUG Loader: result set row: 2
            09:55:31,703 DEBUG StringType: returning 'ldap.manager.password' as column: name0_
            09:55:31,703 DEBUG Loader: result row: EntityKey[org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
            09:55:31,703 DEBUG Loader: Initializing object from ResultSet: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
            09:55:31,703 DEBUG AbstractEntityPersister: Hydrating entity: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
            09:55:31,703 DEBUG StringType: returning 'password' as column: prop2_0_
            09:55:31,703 DEBUG Loader: result set row: 3
            09:55:31,703 DEBUG StringType: returning 'smtp.host.name' as column: name0_
            09:55:31,703 DEBUG Loader: result row: EntityKey[org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name]
            09:55:31,703 DEBUG Loader: Initializing object from ResultSet: [org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name]
            09:55:31,703 DEBUG AbstractEntityPersister: Hydrating entity: [org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name]
            09:55:31,703 DEBUG StringType: returning 'smtp-relay.wh.ldsglobal.net' as column: prop2_0_
            09:55:31,703 DEBUG Loader: done processing result set (4 rows)
            09:55:31,703 DEBUG AbstractBatcher: about to close ResultSet (open ResultSets: 1, globally: 1)
            09:55:31,703 DEBUG AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            09:55:31,718 DEBUG AbstractBatcher: closing statement
            09:55:31,718 DEBUG ConnectionManager: aggressively releasing JDBC connection
            09:55:31,718 DEBUG ConnectionManager: releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            09:55:31,718 DEBUG Loader: total objects hydrated: 4
            09:55:31,718 DEBUG TwoPhaseLoad: resolving associations for [org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:55:31,718 DEBUG TwoPhaseLoad: adding entity to second-level cache: [org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
            09:55:31,718 DEBUG TxInterceptor: (null) call on method [_get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url, item, true)]
            09:55:31,718 DEBUG TxInterceptor: local transaction exists - registering global tx if not present for Thread[main,5,main]
            09:55:31,718 DEBUG TxInterceptor: Associated gtx in txTable is null
            09:55:31,718 DEBUG TreeCache: created new GTX: GlobalTransaction:<null>:1, local TX=bb14:38:0:01e39ddc3f61455084...967001:
            09:55:31,718 DEBUG TxInterceptor: Registering sync handler for tx bb14:38:0:01e39ddc3f61455084...967001:, gtx GlobalTransaction:<null>:1
            09:55:31,718 DEBUG TxInterceptor: registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:1, tx=bb14:38:0:01e39ddc3f61455084...967001:))
            09:55:31,718 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url, item, true)
            09:55:31,718 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url for owner GlobalTransaction:<null>:1
            09:55:31,718 DEBUG PessimisticLockInterceptor: failed to find or create child org of node /
            09:55:31,718 DEBUG CallInterceptor: Invoking method _get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url, item, true) on cache.
            09:55:31,718 DEBUG TreeCache: _get("/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url", item, "true")
            09:55:31,718 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
            09:55:31,718 DEBUG EvictionInterceptor: Updating node/element events with no tx
            09:55:31,718 DEBUG EvictionInterceptor: No event added. Element does not exist
            09:55:31,718 DEBUG EvictionInterceptor: No node modifications
            09:55:31,718 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
            09:55:31,718 DEBUG TransactionalCache: caching: org.lds.stack.petstore.model.ApplicationProperty#ldap.url
            09:55:31,718 DEBUG TxInterceptor: (null) call on method [_put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=ldap://10.51.95.193, _version=null, _lazyPropertiesUnfetched=true}, true, 0)]
            09:55:31,718 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=ldap://10.51.95.193, _version=null, _lazyPropertiesUnfetched=true}, true, 0)
            09:55:31,718 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.url for owner Thread[main,5,main]
            09:55:31,718 DEBUG Node: created child: fqn=/org
            09:55:31,734 DEBUG Node: acquiring RL: fqn=/org, caller=Thread[main,5,main], lock=<unlocked>
            09:55:31,734 DEBUG Node: acquired RL: fqn=/org, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            09:55:31,734 DEBUG Node: created child: fqn=/org/lds
            09:55:31,734 DEBUG Node: acquiring RL: fqn=/org/lds, caller=Thread[main,5,main], lock=<unlocked>
            09:55:31,734 DEBUG Node: acquired RL: fqn=/org/lds, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            09:55:31,734 DEBUG Node: created child: fqn=/org/lds/stack
            09:55:31,734 DEBUG Node: acquiring RL: fqn=/org/lds/stack, caller=Thread[main,5,main], lock=<unlocked>
            09:55:31,734 DEBUG Node: acquired RL: fqn=/org/lds/stack, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            09:55:31,734 DEBUG Node: created child: fqn=/org/lds/stack/petstore
            09:55:31,734 DEBUG Node: acquiring RL: fqn=/org/lds/stack/p


            • 3. Re: Read Locks not released broken between 1.4.1.beta and 1.
              youngm Novice

              I just realized I may not have provided enough of the 1.4.1.beta log. So here is a bit more:


              09:55:31,734 DEBUG TwoPhaseLoad: done materializing entity [org.lds.stack.petstore.model.ApplicationProperty#ldap.url]
              09:55:31,750 DEBUG TwoPhaseLoad: resolving associations for [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
              09:55:31,750 DEBUG TwoPhaseLoad: adding entity to second-level cache: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
              09:55:31,750 DEBUG TxInterceptor: (null) call on method [_get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, true)]
              09:55:31,750 DEBUG TxInterceptor: local transaction exists - registering global tx if not present for Thread[main,5,main]
              09:55:31,750 DEBUG TxInterceptor: Associated gtx in txTable is GlobalTransaction:<null>:1
              09:55:31,750 DEBUG TxInterceptor: Transaction bb14:38:0:01e39ddc3f61455084...967001: is already registered.
              09:55:31,750 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, true)
              09:55:31,750 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn for owner GlobalTransaction:<null>:1
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org, caller=GlobalTransaction:<null>:1, lock=<unlocked>
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds, caller=GlobalTransaction:<null>:1, lock=<unlocked>
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack, caller=GlobalTransaction:<null>:1, lock=<unlocked>
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore, caller=GlobalTransaction:<null>:1, lock=<unlocked>
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model, caller=GlobalTransaction:<null>:1, lock=<unlocked>
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=GlobalTransaction:<null>:1, lock=<unlocked>
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG PessimisticLockInterceptor: failed to find or create child org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn of node /org/lds/stack/petstore/model/ApplicationProperty
              09:55:31,750 DEBUG CallInterceptor: Invoking method _get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, true) on cache.
              09:55:31,750 DEBUG TreeCache: _get("/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn", item, "true")
              09:55:31,750 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
              09:55:31,750 DEBUG EvictionInterceptor: Updating node/element events with no tx
              09:55:31,750 DEBUG EvictionInterceptor: No event added. Element does not exist
              09:55:31,750 DEBUG EvictionInterceptor: No node modifications
              09:55:31,750 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
              09:55:31,750 DEBUG TransactionalCache: caching: org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn
              09:55:31,750 DEBUG TxInterceptor: (null) call on method [_put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=cn=hansenbk,ou=People,o=WH, _version=null, _lazyPropertiesUnfetched=true}, true, 0)]
              09:55:31,750 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=cn=hansenbk,ou=People,o=WH, _version=null, _lazyPropertiesUnfetched=true}, true, 0)
              09:55:31,750 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn for owner Thread[main,5,main]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: created child: fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn
              09:55:31,750 DEBUG Node: acquiring WL: fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, caller=Thread[main,5,main], lock=<unlocked>
              09:55:31,750 DEBUG Node: acquired WL: fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, caller=Thread[main,5,main], lock=write owner=Thread[main,5,main]
              09:55:31,750 DEBUG CallInterceptor: Invoking method _put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=cn=hansenbk,ou=People,o=WH, _version=null, _lazyPropertiesUnfetched=true}, true, 0) on cache.
              09:55:31,750 DEBUG TreeCache: _put(null, "/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn", item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=cn=hansenbk,ou=People,o=WH, _version=null, _lazyPropertiesUnfetched=true})
              09:55:31,750 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
              09:55:31,750 DEBUG EvictionInterceptor: Updating node/element events with no tx
              09:55:31,750 DEBUG RegionManager: getRegion(): user-specified region not found: / will use the global default region
              09:55:31,750 DEBUG RegionManager: getRegion(): user-specified region not found: / will use the global default region
              09:55:31,750 DEBUG EvictionInterceptor: Adding event EvictedEN[fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn event=3 diff=1] to region at /_default_/
              09:55:31,750 DEBUG EvictionInterceptor: Finished updating node
              09:55:31,750 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
              09:55:31,750 DEBUG UnlockInterceptor: Attempting to release locks on current thread. Lock table is {Thread[main,5,main]=[read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], write owner=Thread[main,5,main]]}
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn: write owner=Thread[main,5,main]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore/model/ApplicationProperty: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore/model: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG TwoPhaseLoad: done materializing entity [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.dn]
              09:55:31,750 DEBUG TwoPhaseLoad: resolving associations for [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
              09:55:31,750 DEBUG TwoPhaseLoad: adding entity to second-level cache: [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
              09:55:31,750 DEBUG TxInterceptor: (null) call on method [_get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, true)]
              09:55:31,750 DEBUG TxInterceptor: local transaction exists - registering global tx if not present for Thread[main,5,main]
              09:55:31,750 DEBUG TxInterceptor: Associated gtx in txTable is GlobalTransaction:<null>:1
              09:55:31,750 DEBUG TxInterceptor: Transaction bb14:38:0:01e39ddc3f61455084...967001: is already registered.
              09:55:31,750 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, true)
              09:55:31,750 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password for owner GlobalTransaction:<null>:1
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org/lds
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org/lds/stack
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org/lds/stack/petstore
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org/lds/stack/petstore/model
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org/lds/stack/petstore/model/ApplicationProperty
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG PessimisticLockInterceptor: failed to find or create child org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password of node /org/lds/stack/petstore/model/ApplicationProperty
              09:55:31,750 DEBUG CallInterceptor: Invoking method _get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, true) on cache.
              09:55:31,750 DEBUG TreeCache: _get("/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password", item, "true")
              09:55:31,750 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
              09:55:31,750 DEBUG EvictionInterceptor: Updating node/element events with no tx
              09:55:31,750 DEBUG EvictionInterceptor: No event added. Element does not exist
              09:55:31,750 DEBUG EvictionInterceptor: No node modifications
              09:55:31,750 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
              09:55:31,750 DEBUG TransactionalCache: caching: org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password
              09:55:31,750 DEBUG TxInterceptor: (null) call on method [_put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=password, _version=null, _lazyPropertiesUnfetched=true}, true, 0)]
              09:55:31,750 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=password, _version=null, _lazyPropertiesUnfetched=true}, true, 0)
              09:55:31,750 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password for owner Thread[main,5,main]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: created child: fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password
              09:55:31,750 DEBUG Node: acquiring WL: fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, caller=Thread[main,5,main], lock=<unlocked>
              09:55:31,750 DEBUG Node: acquired WL: fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, caller=Thread[main,5,main], lock=write owner=Thread[main,5,main]
              09:55:31,750 DEBUG CallInterceptor: Invoking method _put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=password, _version=null, _lazyPropertiesUnfetched=true}, true, 0) on cache.
              09:55:31,750 DEBUG TreeCache: _put(null, "/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password", item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=password, _version=null, _lazyPropertiesUnfetched=true})
              09:55:31,750 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
              09:55:31,750 DEBUG EvictionInterceptor: Updating node/element events with no tx
              09:55:31,750 DEBUG RegionManager: getRegion(): user-specified region not found: / will use the global default region
              09:55:31,750 DEBUG RegionManager: getRegion(): user-specified region not found: / will use the global default region
              09:55:31,750 DEBUG EvictionInterceptor: Adding event EvictedEN[fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password event=3 diff=1] to region at /_default_/
              09:55:31,750 DEBUG EvictionInterceptor: Finished updating node
              09:55:31,750 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
              09:55:31,750 DEBUG UnlockInterceptor: Attempting to release locks on current thread. Lock table is {Thread[main,5,main]=[read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], write owner=Thread[main,5,main]]}
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password: write owner=Thread[main,5,main]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore/model/ApplicationProperty: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore/model: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org/lds: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG UnlockInterceptor: releasing lock for /org: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG TwoPhaseLoad: done materializing entity [org.lds.stack.petstore.model.ApplicationProperty#ldap.manager.password]
              09:55:31,750 DEBUG TwoPhaseLoad: resolving associations for [org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name]
              09:55:31,750 DEBUG TwoPhaseLoad: adding entity to second-level cache: [org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name]
              09:55:31,750 DEBUG TxInterceptor: (null) call on method [_get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name, item, true)]
              09:55:31,750 DEBUG TxInterceptor: local transaction exists - registering global tx if not present for Thread[main,5,main]
              09:55:31,750 DEBUG TxInterceptor: Associated gtx in txTable is GlobalTransaction:<null>:1
              09:55:31,750 DEBUG TxInterceptor: Transaction bb14:38:0:01e39ddc3f61455084...967001: is already registered.
              09:55:31,750 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name, item, true)
              09:55:31,750 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name for owner GlobalTransaction:<null>:1
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org/lds
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org/lds/stack
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org/lds/stack/petstore
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org/lds/stack/petstore/model
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG IdentityLock: acquireReadLock(): caller GlobalTransaction:<null>:1 already owns lock for /org/lds/stack/petstore/model/ApplicationProperty
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG PessimisticLockInterceptor: failed to find or create child org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name of node /org/lds/stack/petstore/model/ApplicationProperty
              09:55:31,750 DEBUG CallInterceptor: Invoking method _get(/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name, item, true) on cache.
              09:55:31,750 DEBUG TreeCache: _get("/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name", item, "true")
              09:55:31,750 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
              09:55:31,750 DEBUG EvictionInterceptor: Updating node/element events with no tx
              09:55:31,750 DEBUG EvictionInterceptor: No event added. Element does not exist
              09:55:31,750 DEBUG EvictionInterceptor: No node modifications
              09:55:31,750 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
              09:55:31,750 DEBUG TransactionalCache: caching: org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name
              09:55:31,750 DEBUG TxInterceptor: (null) call on method [_put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=smtp-relay.wh.ldsglobal.net, _version=null, _lazyPropertiesUnfetched=true}, true, 0)]
              09:55:31,750 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=smtp-relay.wh.ldsglobal.net, _version=null, _lazyPropertiesUnfetched=true}, true, 0)
              09:55:31,750 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name for owner Thread[main,5,main]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: acquiring RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,750 DEBUG Node: acquired RL: fqn=/org/lds/stack/petstore/model/ApplicationProperty, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,750 DEBUG Node: created child: fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name
              09:55:31,750 DEBUG Node: acquiring WL: fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name, caller=Thread[main,5,main], lock=<unlocked>
              09:55:31,750 DEBUG Node: acquired WL: fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name, caller=Thread[main,5,main], lock=write owner=Thread[main,5,main]
              09:55:31,765 DEBUG CallInterceptor: Invoking method _put(null, /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name, item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=smtp-relay.wh.ldsglobal.net, _version=null, _lazyPropertiesUnfetched=true}, true, 0) on cache.
              09:55:31,765 DEBUG TreeCache: _put(null, "/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name", item, {_subclass=org.lds.stack.petstore.model.ApplicationProperty, value=smtp-relay.wh.ldsglobal.net, _version=null, _lazyPropertiesUnfetched=true})
              09:55:31,765 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
              09:55:31,765 DEBUG EvictionInterceptor: Updating node/element events with no tx
              09:55:31,765 DEBUG RegionManager: getRegion(): user-specified region not found: / will use the global default region
              09:55:31,765 DEBUG RegionManager: getRegion(): user-specified region not found: / will use the global default region
              09:55:31,765 DEBUG EvictionInterceptor: Adding event EvictedEN[fqn=/org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name event=3 diff=1] to region at /_default_/
              09:55:31,765 DEBUG EvictionInterceptor: Finished updating node
              09:55:31,765 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
              09:55:31,765 DEBUG UnlockInterceptor: Attempting to release locks on current thread. Lock table is {Thread[main,5,main]=[read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], write owner=Thread[main,5,main]]}
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore/model/ApplicationProperty/org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name: write owner=Thread[main,5,main]
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore/model/ApplicationProperty: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore/model: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack/petstore: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org/lds/stack: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org/lds: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,765 DEBUG TwoPhaseLoad: done materializing entity [org.lds.stack.petstore.model.ApplicationProperty#smtp.host.name]
              09:55:31,765 DEBUG StatefulPersistenceContext: initializing non-lazy collections
              09:55:31,765 DEBUG StandardQueryCache: caching query results in region: org.hibernate.cache.StandardQueryCache; timestamp=11700897315
              09:55:31,765 DEBUG TxInterceptor: (null) call on method [_put(null, /org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, item, [11700897315, ldap.url, ldap.manager.dn, ldap.manager.password, smtp.host.name], true, 0)]
              09:55:31,765 DEBUG PessimisticLockInterceptor: PessimisticLockInterceptor invoked for method _put(null, /org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, item, [11700897315, ldap.url, ldap.manager.dn, ldap.manager.password, smtp.host.name], true, 0)
              09:55:31,765 DEBUG PessimisticLockInterceptor: Attempting to lock node /org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {} for owner Thread[main,5,main]
              09:55:31,765 DEBUG Node: acquiring RL: fqn=/org, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1]
              09:55:31,765 DEBUG Node: acquired RL: fqn=/org, caller=Thread[main,5,main], lock=read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,765 DEBUG Node: created child: fqn=/org/hibernate
              09:55:31,765 DEBUG Node: acquiring RL: fqn=/org/hibernate, caller=Thread[main,5,main], lock=<unlocked>
              09:55:31,765 DEBUG Node: acquired RL: fqn=/org/hibernate, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
              09:55:31,765 DEBUG Node: created child: fqn=/org/hibernate/cache
              09:55:31,765 DEBUG Node: acquiring RL: fqn=/org/hibernate/cache, caller=Thread[main,5,main], lock=<unlocked>
              09:55:31,765 DEBUG Node: acquired RL: fqn=/org/hibernate/cache, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
              09:55:31,765 DEBUG Node: created child: fqn=/org/hibernate/cache/StandardQueryCache
              09:55:31,765 DEBUG Node: acquiring RL: fqn=/org/hibernate/cache/StandardQueryCache, caller=Thread[main,5,main], lock=<unlocked>
              09:55:31,765 DEBUG Node: acquired RL: fqn=/org/hibernate/cache/StandardQueryCache, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
              09:55:31,765 DEBUG Node: created child: fqn=/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}
              09:55:31,765 DEBUG Node: acquiring WL: fqn=/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, caller=Thread[main,5,main], lock=<unlocked>
              09:55:31,765 DEBUG Node: acquired WL: fqn=/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, caller=Thread[main,5,main], lock=write owner=Thread[main,5,main]
              09:55:31,765 DEBUG CallInterceptor: Invoking method _put(null, /org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}, item, [11700897315, ldap.url, ldap.manager.dn, ldap.manager.password, smtp.host.name], true, 0) on cache.
              09:55:31,765 DEBUG TreeCache: _put(null, "/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}", item, [11700897315, ldap.url, ldap.manager.dn, ldap.manager.password, smtp.host.name])
              09:55:31,765 DEBUG EvictionInterceptor: Invoking EvictionInterceptor
              09:55:31,765 DEBUG EvictionInterceptor: Updating node/element events with no tx
              09:55:31,765 DEBUG RegionManager: getRegion(): user-specified region not found: / will use the global default region
              09:55:31,765 DEBUG RegionManager: getRegion(): user-specified region not found: / will use the global default region
              09:55:31,765 DEBUG EvictionInterceptor: Adding event EvictedEN[fqn=/org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {} event=3 diff=1] to region at /_default_/
              09:55:31,765 DEBUG EvictionInterceptor: Finished updating node
              09:55:31,765 DEBUG EvictionInterceptor: Finished invoking EvictionInterceptor
              09:55:31,765 DEBUG UnlockInterceptor: Attempting to release locks on current thread. Lock table is {Thread[main,5,main]=[read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], write owner=Thread[main,5,main]]}
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org/hibernate/cache/StandardQueryCache/sql: select applicatio0_.name as name0_, applicatio0_.prop_value as prop2_0_ from APP_PROPERTIES applicatio0_; parameters: ; named parameters: {}: write owner=Thread[main,5,main]
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org/hibernate/cache/StandardQueryCache: read owners=[Thread[main,5,main]]
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org/hibernate/cache: read owners=[Thread[main,5,main]]
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org/hibernate: read owners=[Thread[main,5,main]]
              09:55:31,765 DEBUG UnlockInterceptor: releasing lock for /org: read owners=[GlobalTransaction:<null>:1, Thread[main,5,main]]
              09:55:31,781 DEBUG AbstractApplicationPropertyService: Adding db property to entrySet: org.lds.stack.petstore.model.ApplicationProperty@54f169[key=ldap.url,value=ldap://10.51.95.193]
              09:55:31,796 DEBUG AbstractApplicationPropertyService: Adding db property to entrySet: org.lds.stack.petstore.model.ApplicationProperty@7a3a30[key=ldap.manager.dn,value=cn=hansenbk,ou=People,o=WH]
              09:55:31,796 DEBUG AbstractApplicationPropertyService: Adding db property to entrySet: org.lds.stack.petstore.model.ApplicationProperty@825cf3[key=ldap.manager.password,value=password]
              09:55:31,796 DEBUG AbstractApplicationPropertyService: Adding db property to entrySet: org.lds.stack.petstore.model.ApplicationProperty@a47cc3[key=smtp.host.name,value=smtp-relay.wh.ldsglobal.net]
              09:55:31,796 DEBUG CacheSynchronization: transaction before completion callback
              09:55:31,796 DEBUG JDBCContext: before transaction completion
              09:55:31,796 DEBUG SessionImpl: before transaction completion
              09:55:31,796 DEBUG AbstractEntityManagerImpl: automatically flushing session
              09:55:31,796 DEBUG SessionImpl: automatically flushing session
              09:55:31,796 DEBUG AbstractFlushingEventListener: flushing session
              09:55:31,796 DEBUG AbstractFlushingEventListener: processing flush-time cascades
              09:55:31,796 DEBUG Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: org.lds.stack.petstore.model.ApplicationProperty
              09:55:31,796 DEBUG Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: org.lds.stack.petstore.model.ApplicationProperty
              09:55:31,796 DEBUG Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: org.lds.stack.petstore.model.ApplicationProperty
              09:55:31,796 DEBUG Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: org.lds.stack.petstore.model.ApplicationProperty
              09:55:31,796 DEBUG Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: org.lds.stack.petstore.model.ApplicationProperty
              09:55:31,796 DEBUG Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: org.lds.stack.petstore.model.ApplicationProperty
              09:55:31,796 DEBUG Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: org.lds.stack.petstore.model.ApplicationProperty
              09:55:31,796 DEBUG Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: org.lds.stack.petstore.model.ApplicationProperty