[
https://issues.apache.org/jira/browse/IGNITE-8863?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16525170#comment-16525170
]
Alexei Scherbakov edited comment on IGNITE-8863 at 6/27/18 2:53 PM:
--------------------------------------------------------------------
A suspicious failure has occured in
CacheSerializableTransactionsTest#testReadWriteTransactionsNoDeadlock causing
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}
was (Author: ascherbakov):
A suspicious failure has occured 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)
