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

[youngm]

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>

[manik]

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?

[youngm]

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

[youngm]

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

[manik]

This is related to http://jira.jboss.com/jira/browse/JBCACHE-955

I hope to release an SP1 very soon.