datanucleus level 2 cache returning stale value

Question

appengine 1.6.4 datanucleus-appengine-2.0.0 datanucleus cache 3.0.1

hi all

i am getting stale data returned from a read query using the datanucleus level 2 cache.

my persistent config has NO cache setting so from the docs it is using a default setting.

problem

step 1: in TX1 do a simple merge on entity MerchantPromotion(5).

result 1: datastore viewer shows the entity has been updated correctly.

step 2: in TX2 do a read of entity MerchantPromotion(5).

result 2: the data returned is the pre merged data NOT the changed data.

It seems to be related to the level 2 cache because when the level 2 cache is set to NONE the operations work successfully.

the DN trace is attached.

any help appreciated.

-lp

<persistence-unit name="transactions-optional">
    <provider>org.datanucleus.api.jpa.PersistenceProviderImpl</provider>
    <properties>
        <property name="datanucleus.ConnectionURL" value="appengine"/>
        <property name="datanucleus.metadata.allowLoadAtRuntime" value="true"/>
        <property name="datanucleus.appengine.ignorableMetaDataBehavior" value="ERROR"/>
        <property name="datanucleus.DetachAllOnCommit" value="true" />
        <property name="datanucleus.DetachOnClose" value="true" />
        <property name="datanucleus.appengine.datastoreEnableXGTransactions" value="true"/>           

    </properties>
</persistence-unit>

merge existing entity

07/05/2012 11:00:43 PM com.asteriski.mingle.venueportal.managedbeans.PromotionBackingBean saveAction
INFO: saveSun May 06 00:00:00 UTC 2012
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl initialiseLevel1Cache
FINE: Level 1 Cache of type "soft" initialised
07/05/2012 11:00:43 PM     com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection <init>
FINE: Created ManagedConnection using DatastoreService = com.google.appengine.api.datastore.DatastoreServiceImpl@136fb9fd
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl allocateConnection
FINE: Connection added to the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@47d77d9e for key=org.datanucleus.ObjectManagerImpl@1f4790be in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM com.asteriski.mingle.venueportal.service.PromotionService save
INFO: com.asteriski.mingle.venueportal.beans.PromotionBean@147834eb
07/05/2012 11:00:43 PM com.asteriski.mingle.venueportal.dao.PromotionDAO save
INFO: content:another one here11
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl putObjectIntoCache
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@6ac1abcf" (id="org.datanucleus.identity.IdentityReference@20e74663") added to Level 1 cache (loadedFlags="[YYYYYYYYYY]")
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl allocateConnection
FINE: Connection found in the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@47d77d9e for key=org.datanucleus.ObjectManagerImpl@1f4790be in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl allocateConnection
FINE: Connection found in the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@47d77d9e for key=org.datanucleus.ObjectManagerImpl@1f4790be in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl allocateConnection
FINE: Connection found in the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@47d77d9e for key=org.datanucleus.ObjectManagerImpl@1f4790be in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl allocateConnection
FINE: Connection found in the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@47d77d9e for key=org.datanucleus.ObjectManagerImpl@1f4790be in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl allocateConnection
FINE: Connection found in the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@47d77d9e for key=org.datanucleus.ObjectManagerImpl@1f4790be in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl replaceObjectId
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@6ac1abcf" (id="org.datanucleus.identity.IdentityReference@20e74663") being changed to be referenced by id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)" in Level 1 cache
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl putObjectIntoCache
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@6ac1abcf" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)") added to Level 1 cache (loadedFlags="[YYYYYYYYYY]")
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl allocateConnection
FINE: Connection found in the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@47d77d9e for key=org.datanucleus.ObjectManagerImpl@1f4790be in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl performLevel2CacheUpdateAtCommit
FINE: Object with id="org.datanucleus.identity.IdentityReference@20e74663" removed from Level 2 cache since was updated yet object has been GCed
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl$1 managedConnectionPostClose
FINE: Connection removed from the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@47d77d9e for key=org.datanucleus.ObjectManagerImpl@1f4790be in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM org.datanucleus.state.LifeCycleState changeState
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@6ac1abcf" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)") has a lifecycle change : "P_NEW"->"DETACHED_CLEAN"
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl removeObjectFromCache
FINE: Object with id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)" being removed from Level 1 cache [current cache size = 1]
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl disconnectSMCache
FINE: Level 1 Cache cleared

read entity

07/05/2012 11:00:43 PM com.google.appengine.datanucleus.query.JPQLQuery performExecute
FINE: JPQL Query : Execution Time = 6 ms
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl getObjectFromCache
FINE: Object with id "com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(3)" not found in Level 1 cache [cache size = 0]
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl getObjectFromCache
FINE: Object with id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(3)" taken from Level 2 cache (loadedFlags="[YYYYYYYYYY]", relationFields="null") - extracting into managed persistable object
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl putObjectIntoCache
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@1aa3c177" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(3)") added to Level 1 cache (loadedFlags="[NNNYNNNNNN]")
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl getObjectFromCache
FINE: Object with id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(3)" taken from Level 2 cache represented as "com.asteriski.mingle.venueportal.entity.MerchantPromotion@1aa3c177" 
07/05/2012 11:00:43 PM org.datanucleus.state.LifeCycleState changeState
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@1aa3c177" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(3)") has a lifecycle change : "P_CLEAN"->"P_NONTRANS"
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl allocateConnection
FINE: Connection found in the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@230cc23b for key=org.datanucleus.ObjectManagerImpl@2db1d931 in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM com.asteriski.mingle.venueportal.service.PromotionService find
INFO: published:MerchantLocation does not exist
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl getObjectFromCache
FINE: Object with id "com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(4)" not found in Level 1 cache [cache size = 1]
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl getObjectFromCache
FINE: Object with id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(4)" taken from Level 2 cache (loadedFlags="[YYYYYYYYYY]", relationFields="null") - extracting into managed persistable object
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl putObjectIntoCache
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@74f2794a" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(4)") added to Level 1 cache (loadedFlags="[NNNYNNNNNN]")
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl getObjectFromCache
FINE: Object with id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(4)" taken from Level 2 cache represented as "com.asteriski.mingle.venueportal.entity.MerchantPromotion@74f2794a" 
07/05/2012 11:00:43 PM org.datanucleus.state.LifeCycleState changeState
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@74f2794a" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(4)") has a lifecycle change : "P_CLEAN"->"P_NONTRANS"
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl allocateConnection
FINE: Connection found in the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@230cc23b for key=org.datanucleus.ObjectManagerImpl@2db1d931 in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM com.asteriski.mingle.venueportal.service.PromotionService find
INFO: published:MerchantLocation does not exist
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl getObjectFromCache
FINE: Object with id "com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)" not found in Level 1 cache [cache size = 2]
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl getObjectFromCache
FINE: Object with id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)" taken from Level 2 cache (loadedFlags="[YYYYYYYYYY]", relationFields="null") - extracting into managed persistable object
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl putObjectIntoCache
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@574a3347" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)") added to Level 1 cache (loadedFlags="[NNNYNNNNNN]")
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl getObjectFromCache
FINE: Object with id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)" taken from Level 2 cache represented as "com.asteriski.mingle.venueportal.entity.MerchantPromotion@574a3347" 
07/05/2012 11:00:43 PM org.datanucleus.state.LifeCycleState changeState
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@574a3347" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)") has a lifecycle change : "P_CLEAN"->"P_NONTRANS"
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl allocateConnection
FINE: Connection found in the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@230cc23b for key=org.datanucleus.ObjectManagerImpl@2db1d931 in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM com.asteriski.mingle.venueportal.service.PromotionService find
INFO: published:null
07/05/2012 11:00:43 PM org.datanucleus.store.connection.ConnectionManagerImpl$1 managedConnectionPostClose
FINE: Connection removed from the pool : com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl$DatastoreManagedConnection@230cc23b for key=org.datanucleus.ObjectManagerImpl@2db1d931 in factory=ConnectionFactory:tx[com.google.appengine.datanucleus.DatastoreConnectionFactoryImpl@7fac4f3e]
07/05/2012 11:00:43 PM org.datanucleus.state.LifeCycleState changeState
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@574a3347" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)") has a lifecycle change : "P_NONTRANS"->"DETACHED_CLEAN"
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl removeObjectFromCache
FINE: Object with id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(5)" being removed from Level 1 cache [current cache size = 3]
07/05/2012 11:00:43 PM org.datanucleus.state.LifeCycleState changeState
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@74f2794a" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(4)") has a lifecycle change : "P_NONTRANS"->"DETACHED_CLEAN"
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl removeObjectFromCache
FINE: Object with id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(4)" being removed from Level 1 cache [current cache size = 2]
07/05/2012 11:00:43 PM org.datanucleus.state.LifeCycleState changeState
FINE: Object "com.asteriski.mingle.venueportal.entity.MerchantPromotion@1aa3c177" (id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(3)") has a lifecycle change : "P_NONTRANS"->"DETACHED_CLEAN"
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl removeObjectFromCache
FINE: Object with id="com.asteriski.mingle.venueportal.entity.MerchantPromotion:MerchantPromotion(3)" being removed from Level 1 cache [current cache size = 1]
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl disconnectSMCache
FINE: Level 1 Cache cleared
07/05/2012 11:00:43 PM org.datanucleus.ObjectManagerImpl initialiseLevel1Cache
FINE: Level 1 Cache of type "soft" initialised

Justin Justin · Accepted Answer · 2012-12-05T12:43:39

I am using jpa with datanucleus on app engine. If i run the query "DELETE FROM SOMETABLENAME a", and later fetch the object by it's id, the cache still returns it!

Adding to my persistance.xml file fixed the issue.

Current library versions are

datanucleus-api-jdo-3.1.1 
datanucleus-api-jpa-3.1.1
datanucleus-core-3.1.1

Part of the stack trace

ObjectManagerImpl.getObjectFromCache(Object) line: 5030 
ObjectManagerImpl.findObject(Object, boolean, boolean, String) line: 3282   
JPAEntityManager.find(Class<T>, Object, LockModeType, Map<String,Object>) line: 358 
JPAEntityManager.find(Class, Object) line: 256

Is this a update that occurred within the past 6 months? All unit tests were fine before updating to this version. Everything checks out again after disabling cache. Will app engine respect the new setting?

datanucleus level 2 cache returning stale value

1 Answers