[ https://issues.apache.org/jira/browse/IGNITE-8863?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16525170#comment-16525170 ]
Alexei Scherbakov commented on IGNITE-8863: ------------------------------------------- There is suspicious failure in CacheSerializableTransactionsTest#testReadWriteTransactionsNoDeadlock leading to Cache5 suite hang: I see hanging transaction: {noformat} [00:23:01]W: [org.apache.ignite:ignite-core] [2018-06-26 21:23:01,176][WARN ][grid-timeout-worker-#55%cache.CacheSerializableTransactionsTest0%][diagnostic] Found long running transaction [startTime=21:21:27.406, curTime=21:23:01.174, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=false, lb=null, thread=test-thread-22, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=[1544803905], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=27, val=27, hasValBytes=false], cacheId=1544803905, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=27, val=27, hasValBytes=false], cacheId=1544803905], val=[op=READ, val=null], prevVal=[op=READ, val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=null, filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=27, val=27, hasValBytes=false], val=null, ver=GridCacheVersion [topVer=0, order=0, nodeOrder=0], hash=27, extras=null, flags=0]]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=GridCacheVersion [topVer=0, order=0, nodeOrder=0], xidVer=GridCacheVersion [topVer=141525768, order=1530052929764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=8, val=8, hasValBytes=false], cacheId=1544803905, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=8, val=8, hasValBytes=false], cacheId=1544803905], val=[op=CREATE, val=UserCacheObjectImpl [val=8, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=8, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=8, val=8, hasValBytes=false], val=null, ver=GridCacheVersion [topVer=0, order=0, nodeOrder=0], hash=8, extras=null, flags=0]]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=141525768, order=1530052929764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=24, val=24, hasValBytes=false], cacheId=1544803905, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=24, val=24, hasValBytes=false], cacheId=1544803905], val=[op=READ, val=null], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=null, filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=24, val=24, hasValBytes=false], val=null, ver=GridCacheVersion [topVer=0, order=0, nodeOrder=0], hash=24, extras=null, flags=0]]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=141525768, order=1530052929764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=29, val=29, hasValBytes=false], cacheId=1544803905, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=29, val=29, hasValBytes=false], cacheId=1544803905], val=[op=READ, val=null], prevVal=[op=READ, val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=null, filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=29, val=29, hasValBytes=false], val=null, ver=GridCacheVersion [topVer=0, order=0, nodeOrder=0], hash=29, extras=null, flags=0]]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=GridCacheVersion [topVer=0, order=0, nodeOrder=0], xidVer=GridCacheVersion [topVer=141525768, order=1530052929764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=21, val=21, hasValBytes=false], cacheId=1544803905, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=21, val=21, hasValBytes=false], cacheId=1544803905], val=[op=CREATE, val=UserCacheObjectImpl [val=21, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=21, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=21, val=21, hasValBytes=false], val=null, ver=GridCacheVersion [topVer=0, order=0, nodeOrder=0], hash=21, extras=null, flags=0]]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=141525768, order=1530052929764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=5, val=5, hasValBytes=false], cacheId=1544803905, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=5, val=5, hasValBytes=false], cacheId=1544803905], val=[op=READ, val=null], prevVal=[op=READ, val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=null, filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=5, val=5, hasValBytes=false], val=null, ver=GridCacheVersion [topVer=0, order=0, nodeOrder=0], hash=5, extras=null, flags=0]]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=GridCacheVersion [topVer=0, order=0, nodeOrder=0], xidVer=GridCacheVersion [topVer=141525768, order=1530052929764, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=141525768, order=1530052929764, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=66969, startTime=1530048087406, nodeId=5c5201aa-093a-475c-96b9-90273f800000, startVer=GridCacheVersion [topVer=141525768, order=1530052929764, nodeOrder=1], endVer=null, isolation=SERIALIZABLE, concurrency=OPTIMISTIC, timeout=0, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=ACTIVE, timedOut=false, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], duration=93768ms, onePhaseCommit=false], size=6]]]] {noformat} and cache future {noformat} [00:23:01]W: [org.apache.ignite:ignite-core] [2018-06-26 21:23:01,187][WARN ][grid-timeout-worker-#55%cache.CacheSerializableTransactionsTest0%][diagnostic] Found long running cache future [startTime=21:21:27.426, curTime=21:23:01.174, fut=GridPartitionedSingleGetFuture [topVer=AffinityTopologyVersion [topVer=529, minorTopVer=40], key=UserKeyCacheObjectImpl [part=24, val=24, hasValBytes=true], readThrough=true, forcePrimary=true, futId=bcca6a24461-2a102386-4d04-437c-a368-0f918b8525e8, trackable=true, subjId=5c5201aa-093a-475c-96b9-90273f800000, taskName=null, deserializeBinary=false, skipVals=false, expiryPlc=null, canRemap=true, needVer=true, keepCacheObjects=true, recovery=false, node=TcpDiscoveryNode [id=4945f35a-b862-4657-9838-1371f6d00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=3, intOrder=3, lastExchangeTime=1530045240352, loc=false, ver=2.6.0#20180626-sha1:cf01e782, isClient=false], postProcessingClos=null]] [00:23:01] : [Step 3/4] [2018-06-26 21:23:01,213][INFO ][sys-#31692%cache.CacheSerializableTransactionsTest0%][diagnostic] GridPartitionedSingleGetFuture waiting for response [node=4945f35a-b862-4657-9838-1371f6d00002, key=UserKeyCacheObjectImpl [part=24, val=24, hasValBytes=true], futId=bcca6a24461-2a102386-4d04-437c-a368-0f918b8525e8, topVer=AffinityTopologyVersion [topVer=529, minorTopVer=40]] {noformat} caused by Assertion: {noformat} [00:21:27]W: [org.apache.ignite:ignite-core] [2018-06-26 21:21:27,446][ERROR][sys-#25415%cache.CacheSerializableTransactionsTest2%][GridClosureProcessor] Closure execution failed with error. [00:21:27]W: [org.apache.ignite:ignite-core] java.lang.AssertionError: GridDhtCacheEntry [rdrs=[], part=24, super=GridDistributedCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=24, val=24, hasValBytes=true], val=null, ver=GridCacheVersion [t opVer=0, order=0, nodeOrder=0], hash=24, extras=null, flags=0]]] [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheMapEntry.clearReserveForLoad(GridCacheMapEntry.java:2902) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheAdapter.clearReservationsIfNeeded(GridCacheAdapter.java:2286) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheAdapter.access$400(GridCacheAdapter.java:162) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheAdapter$18.call(GridCacheAdapter.java:2178) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheAdapter$18.call(GridCacheAdapter.java:2100) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:6710) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.closure.GridClosureProcessor$2.body(GridClosureProcessor.java:967) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110) [00:21:27]W: [org.apache.ignite:ignite-core] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [00:21:27]W: [org.apache.ignite:ignite-core] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [00:21:27]W: [org.apache.ignite:ignite-core] at java.lang.Thread.run(Thread.java:745) [00:21:27]W: [org.apache.ignite:ignite-core] [2018-06-26 21:21:27,453][ERROR][sys-#25415%cache.CacheSerializableTransactionsTest2%][GridClosureProcessor] Runtime error caught during grid runnable execution: GridWorker [name=closure-proc-worker, igniteInstanceName=cache.CacheSerializableTransactionsTest2, finished=false, hashCode=1670420442, interrupted=false, runner=sys-#25415%cache.CacheSerializableTransactionsTest2%] [00:21:27]W: [org.apache.ignite:ignite-core] java.lang.AssertionError: GridDhtCacheEntry [rdrs=[], part=24, super=GridDistributedCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=24, val=24, hasValBytes=true], val=null, ver=GridCacheVersion [topVer=0, order=0, nodeOrder=0], hash=24, extras=null, flags=0]]] [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheMapEntry.clearReserveForLoad(GridCacheMapEntry.java:2902) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheAdapter.clearReservationsIfNeeded(GridCacheAdapter.java:2286) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheAdapter.access$400(GridCacheAdapter.java:162) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheAdapter$18.call(GridCacheAdapter.java:2178) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheAdapter$18.call(GridCacheAdapter.java:2100) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:6710) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.closure.GridClosureProcessor$2.body(GridClosureProcessor.java:967) [00:21:27]W: [org.apache.ignite:ignite-core] at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110) [00:21:27]W: [org.apache.ignite:ignite-core] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [00:21:27]W: [org.apache.ignite:ignite-core] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [00:21:27]W: [org.apache.ignite:ignite-core] at java.lang.Thread.run(Thread.java:745) {noformat} > Tx rollback can cause remote tx hang > ------------------------------------ > > Key: IGNITE-8863 > URL: https://issues.apache.org/jira/browse/IGNITE-8863 > Project: Ignite > Issue Type: Bug > Reporter: Alexei Scherbakov > Assignee: Alexei Scherbakov > Priority: Major > Fix For: 2.7 > > > {noformat} > [16:33:56]W: [org.apache.ignite:ignite-core] [2018-06-08 > 13:33:56,931][WARN ][sys-#66696%client%][GridNearTxLocal] The transaction was > forcibly rolled back because a timeout is reached: > GridNearTxLocal[xid=e198a9fd361-00000000-0857-6387-0000-000000000004, > xidVersion=GridCacheVersion [topVer=139944839, order=1528464836894, > nodeOrder=4], concurrency=PESSIMISTIC, isolation=REPEATABLE_READ, > state=MARKED_ROLLBACK, invalidate=false, rollbackOnly=true, > nodeId=3c8d85b2-4eb9-46b2-8bd1-6f18f542fc7a, timeout=1, duration=11] > [16:35:55]W: [org.apache.ignite:ignite-core] [2018-06-08 > 13:35:55,056][WARN > ][grid-timeout-worker-#66394%transactions.TxRollbackOnTimeoutTest0%][diagnostic] > Found long running transaction [startTime=13:33:56.931, > curTime=13:35:55.054, tx=GridDhtTxRemote > [nearNodeId=3c8d85b2-4eb9-46b2-8bd1-6f18f542fc7a, > rmtFutId=af940d0e361-79c59341-3292-46e4-92ce-5c4ef4eddef8, > nearXidVer=GridCacheVersion [topVer=139944839, order=1528464836894, > nodeOrder=4], storeWriteThrough=false, super=GridDistributedTxRemoteAdapter > [explicitVers=null, started=true, commitAllowed=0, > txState=IgniteTxRemoteSingleStateImpl [entry=IgniteTxEntry > [key=KeyCacheObjectImpl [part=1, val=1, hasValBytes=true], cacheId=3556498, > txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=1, val=1, hasValBytes=true], > cacheId=3556498], val=[op=CREATE, val=CacheObjectImpl [val=null, > hasValBytes=true]], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null], > entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, > explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, > filtersSet=false, entry=GridDhtCacheEntry [rdrs=[], part=1, > super=GridDistributedCacheEntry [super=GridCacheMapEntry > [key=KeyCacheObjectImpl [part=1, val=1, hasValBytes=true], > val=CacheObjectImpl [val=null, hasValBytes=true], startVer=1528464836879, > ver=GridCacheVersion [topVer=139944839, order=1528464836863, nodeOrder=2], > hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=null, > rmts=[GridCacheMvccCandidate [nodeId=97ee44cd-73c9-4e79-95df-e1a034800001, > ver=GridCacheVersion [topVer=139944839, order=1528464836897, nodeOrder=2], > threadId=75880, id=2310313, topVer=AffinityTopologyVersion [topVer=-1, > minorTopVer=0], reentry=null, > otherNodeId=3c8d85b2-4eb9-46b2-8bd1-6f18f542fc7a, otherVer=null, > mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, > key=KeyCacheObjectImpl [part=1, val=1, hasValBytes=true], > masks=local=0|owner=0|ready=0|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, > prevVer=null, nextVer=null], GridCacheMvccCandidate > [nodeId=97ee44cd-73c9-4e79-95df-e1a034800001, ver=GridCacheVersion > [topVer=139944839, order=1528464836900, nodeOrder=2], threadId=75875, > id=2310317, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], > reentry=null, otherNodeId=3c8d85b2-4eb9-46b2-8bd1-6f18f542fc7a, > otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, > serOrder=null, key=KeyCacheObjectImpl [part=1, val=1, hasValBytes=true], > masks=local=0|owner=1|ready=0|reentry=0|used=1|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, > prevVer=null, nextVer=null]]]], flags=2]]], prepared=1, locked=false, > nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, > flags=0, partUpdateCntr=0, serReadVer=null, xidVer=null]], > skipCompletedVers=false, super=IgniteTxAdapter [xidVer=GridCacheVersion > [topVer=139944839, order=1528464836897, nodeOrder=2], > writeVer=GridCacheVersion [topVer=139944839, order=1528464836898, > nodeOrder=2], implicit=false, loc=false, threadId=75880, > startTime=1528464836931, nodeId=97ee44cd-73c9-4e79-95df-e1a034800001, > startVer=GridCacheVersion [topVer=139944839, order=1528464836864, > nodeOrder=1], endVer=null, isolation=REPEATABLE_READ, > concurrency=PESSIMISTIC, timeout=1, sysInvalidate=false, sys=false, plc=2, > commitVer=null, finalizing=NONE, invalidParts=null, state=PREPARED, > timedOut=false, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=0], > duration=118123ms, onePhaseCommit=false]]]] > {noformat} -- This message was sent by Atlassian JIRA (v7.6.3#76005)