GridCacheStore operations are not eligible to join JTA transaction with write-behind disabled

[markathomas]

From testing I have found that by the time the methods in my GridCacheStore implementation are invoked by GridGain the JTA TX is already in the COMMITTING state thus changes made through my cache store (JPA operations w/ Hibernate) fail to actually commit to the database. For reference I am using GridGain 6.1.6 with Spring 4.0.5 and Hibernate 4.3.5 (JPA 2.1). TX Manager is Narayana (JBoss) 5.0.2 using JTA 1.2. I have a debug log I'd be happy to share but github won't allow me to upload a text file. Here's the relevant part:

[testng:testng] 2014-06-21 10:54:39,525 [main] [DEBUG] [org.gridgain.grid.logger.log4j.GridLog4jLogger.debug(GridLog4jLogger.java:465)] Changed transaction state [prev=PREPARED, new=COMMITTING, tx=GridNearTxLocal [prepFut=GridNearTxPrepareFuture [futId=b29722fb641-a85171e5-b74f-4a73-b07b-b1ac7b686542, trackable=true, txMapping=null, super=GridCompoundIdentityFuture [super=GridCompoundFuture [lsnrCalls=0, finished=false, rdc=org.gridgain.grid.kernal.processors.cache.distributed.near.GridNearTxPrepareFuture$1@4ea11eff, init=false, res=java.util.concurrent.atomic.AtomicMarkableReference@33fa1fad, err=null, done=true, cancelled=false, err=null, futs=[]]]], commitFut=GridNearTxFinishFuture [futId=c29722fb641-a85171e5-b74f-4a73-b07b-b1ac7b686542, commit=true, err=null, trackable=true, super=GridCompoundIdentityFuture [super=GridCompoundFuture [lsnrCalls=0, finished=false, rdc=org.gridgain.grid.util.lang.GridFunc$58@6a35b183, init=false, res=java.util.concurrent.atomic.AtomicMarkableReference@6b1945ee, err=null, done=false, cancelled=false, err=null, futs=[]]]], rollbackFut=null, topSnapshot=GridDiscoveryTopologySnapshot [topVer=1, topNodes=[GridTcpDiscoveryNode [id=12760c5c-5536-41a3-bbde-a71158355bb7, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47500], discPort=47500, order=1, loc=true, ver=GridProductVersion [major=6, minor=1, maintenance=6, revTs=1401960823]]]], syncCommit=true, syncRollback=true, mappings=[12760c5c-5536-41a3-bbde-a71158355bb7], super=GridCacheTxLocalAdapter [completedBase=null, partLock=false, sndTransformedVals=false, super=GridCacheTxAdapter [xidVer=GridCacheVersion [topVer=14846047, nodeOrderDrId=1, globalTime=0, order=1403366046302], writeVer=null, implicit=false, implicitSingle=false, loc=true, threadId=1, startTime=1403366079404, nodeId=12760c5c-5536-41a3-bbde-a71158355bb7, startVer=GridCacheVersion [topVer=14846047, nodeOrderDrId=1, globalTime=0, order=1403366046302], endVer=null, isolation=REPEATABLE_READ, concurrency=PESSIMISTIC, timeout=30000, sysInvalidate=false, commitVer=null, finalizing=NONE, preparing=false, state=COMMITTING, timedOut=false, topVer=1, duration=121ms, grpLock=false, onePhaseCommit=false], size=1]]]
[testng:testng] 2014-06-21 10:54:39,525 [main] [DEBUG] [org.gridgain.grid.logger.log4j.GridLog4jLogger.debug(GridLog4jLogger.java:465)] <realtime> Added transaction to committed version set: GridCacheVersion [topVer=14846047, nodeOrderDrId=1, globalTime=0, order=1403366046302]
[testng:testng] 2014-06-21 10:54:39,526 [main] [DEBUG] [org.gridgain.grid.logger.log4j.GridLog4jLogger.debug(GridLog4jLogger.java:465)] <realtime> Storing value in cache store [key=6dbb13c9-5d04-4472-9d98-ed49f4a377c7, val=com.clj2.business.model.realtime.RealtimeCall@6d41eb4d[
[testng:testng]   uuid=6dbb13c9-5d04-4472-9d98-ed49f4a377c7
[testng:testng] ]]
[testng:testng] 2014-06-21 10:54:39,579 [main] [DEBUG] [com.clj2.business.lib.grid.storage.MySQLBasedGridCacheStore.put(MySQLBasedGridCacheStore.java:174)] MySQLBasedGridCacheStore: saving object of type `com.clj2.business.model.realtime.RealtimeCall' with id `6dbb13c9-5d04-4472-9d98-ed49f4a377c7'
[testng:testng] 2014-06-21 10:54:39,579 [main] [DEBUG] [org.springframework.orm.jpa.EntityManagerFactoryUtils.doGetTransactionalEntityManager(EntityManagerFactoryUtils.java:272)] Opening JPA EntityManager
[testng:testng] 2014-06-21 10:54:39,579 [main] [DEBUG] [org.springframework.orm.jpa.EntityManagerFactoryUtils.doGetTransactionalEntityManager(EntityManagerFactoryUtils.java:290)] Registering transaction synchronization for JPA EntityManager
[testng:testng] 2014-06-21 10:54:39,580 [main] [TRACE] [org.springframework.transaction.support.TransactionSynchronizationManager.bindResource(TransactionSynchronizationManager.java:193)] Bound value [org.springframework.orm.jpa.EntityManagerHolder@76cdc9fb] for key [com.clj2.business.dao.impl.HibernateEntityManagerFactoryBean@3a71a6d6] to thread [main]
[testng:testng] 2014-06-21 10:54:39,593 [main] [DEBUG] [org.gridgain.grid.logger.log4j.GridLog4jLogger.debug(GridLog4jLogger.java:465)] <realtime> Stored value in cache store [key=6dbb13c9-5d04-4472-9d98-ed49f4a377c7, val=com.clj2.business.model.realtime.RealtimeCall@6d41eb4d[
[testng:testng]   uuid=6dbb13c9-5d04-4472-9d98-ed49f4a377c7
[testng:testng] ]]
[testng:testng] 2014-06-21 10:54:39,593 [main] [DEBUG] [com.clj2.business.lib.grid.storage.MySQLBasedGridCacheStore.txEnd(MySQLBasedGridCacheStore.java:222)] MySQLBasedGridCacheStore: TX was successful
[testng:testng] 2014-06-21 10:54:39,594 [main] [DEBUG] [org.gridgain.grid.logger.log4j.GridLog4jLogger.debug(GridLog4jLogger.java:465)] Evicting dht-local entry from near cache [entry=GridNearCacheEntry [primaryNodeId=12760c5c-5536-41a3-bbde-a71158355bb7, dhtVer=GridCacheVersion [topVer=14846047, nodeOrderDrId=1, globalTime=0, order=1403366046304], part=5509, super=GridDistributedCacheEntry [super=GridCacheMapEntry [key=6dbb13c9-5d04-4472-9d98-ed49f4a377c7, val=null, startVer=1403366046303, ver=GridCacheVersion [topVer=14846047, nodeOrderDrId=1, globalTime=0, order=1403366046302], hash=1556302946, valPtr=0, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=12760c5c-5536-41a3-bbde-a71158355bb7, ver=GridCacheVersion [topVer=14846047, nodeOrderDrId=1, globalTime=0, order=1403366046302], timeout=29990, ts=1403366079414, threadId=1, id=5, topVer=1, reentry=null, otherNodeId=12760c5c-5536-41a3-bbde-a71158355bb7, otherVer=GridCacheVersion [topVer=14846047, nodeOrderDrId=1, globalTime=0, order=1403366046305], mappedNodeIds=null, ownerVer=null, key=6dbb13c9-5d04-4472-9d98-ed49f4a377c7, masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=1|removed=0, prevVer=null, nextVer=null]], rmts=null]], flags=0]]], tx=GridNearTxLocal [prepFut=GridNearTxPrepareFuture [futId=b29722fb641-a85171e5-b74f-4a73-b07b-b1ac7b686542, trackable=true, txMapping=null, super=GridCompoundIdentityFuture [super=GridCompoundFuture [lsnrCalls=0, finished=false, rdc=org.gridgain.grid.kernal.processors.cache.distributed.near.GridNearTxPrepareFuture$1@4ea11eff, init=false, res=java.util.concurrent.atomic.AtomicMarkableReference@33fa1fad, err=null, done=true, cancelled=false, err=null, futs=[]]]], commitFut=GridNearTxFinishFuture [futId=c29722fb641-a85171e5-b74f-4a73-b07b-b1ac7b686542, commit=true, err=null, trackable=true, super=GridCompoundIdentityFuture [super=GridCompoundFuture [lsnrCalls=0, finished=false, rdc=org.gridgain.grid.util.lang.GridFunc$58@6a35b183, init=false, res=java.util.concurrent.atomic.AtomicMarkableReference@6b1945ee, err=null, done=false, cancelled=false, err=null, futs=[]]]], rollbackFut=null, topSnapshot=GridDiscoveryTopologySnapshot [topVer=1, topNodes=[GridTcpDiscoveryNode [id=12760c5c-5536-41a3-bbde-a71158355bb7, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47500], discPort=47500, order=1, loc=true, ver=GridProductVersion [major=6, minor=1, maintenance=6, revTs=1401960823]]]], syncCommit=true, syncRollback=true, mappings=[12760c5c-5536-41a3-bbde-a71158355bb7], super=GridCacheTxLocalAdapter [completedBase=null, partLock=false, sndTransformedVals=false, super=GridCacheTxAdapter [xidVer=GridCacheVersion [topVer=14846047, nodeOrderDrId=1, globalTime=0, order=1403366046302], writeVer=GridCacheVersion [topVer=14846047, nodeOrderDrId=1, globalTime=0, order=1403366046306], implicit=false, implicitSingle=false, loc=true, threadId=1, startTime=1403366079404, nodeId=12760c5c-5536-41a3-bbde-a71158355bb7, startVer=GridCacheVersion [topVer=14846047, nodeOrderDrId=1, globalTime=0, order=1403366046302], endVer=null, isolation=REPEATABLE_READ, concurrency=PESSIMISTIC, timeout=30000, sysInvalidate=false, commitVer=null, finalizing=NONE, preparing=false, state=COMMITTING, timedOut=false, topVer=1, duration=181ms, grpLock=false, onePhaseCommit=false], size=1]]]

[dsetrakyan]

Can we move this discussion to StackOverflow? Please provide the code and configuration. You can use http://pastebin.com/ to paste code or logs.

[markathomas]

http://stackoverflow.com/questions/24346973/gridcachestore-operations-are-not-eligible-to-join-jta-transaction-with-write-be

Relevant code and config at: http://pastebin.com/jzvZyi11
Relevant log at: http://pastebin.com/KCaXkAZc

[dsetrakyan]

I have responded on StackOverflow. Any reason you are not using GridGain Hibernate L2 Cache integration here?

[markathomas]

I have responded on SO. Regardless of whether or not I use the GridGain L2 cache implementation it doesn't address the issue I've brought up here with JTA and GridCacheStore.

[dsetrakyan]

Just one more question. Do you have more than one data source? If yes, can you tell us what they are?

[markathomas]

Yes, I have a MysqlXADataSource for JTA in REPEATABLE_READ and a BoneCPDataSource for reporting in READ_UNCOMMITTED

[markathomas]

JPA uses MysqlXADataSource

[dsetrakyan]

We have reproduced the issue and are fixing it. I will update this issue with GridGain version that will contain the fix.

[markathomas]

Awesome. Thanks.