ignite-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Alexei Scherbakov (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (IGNITE-8863) Tx rollback can cause remote tx hang
Date Wed, 27 Jun 2018 14:53:00 GMT

    [ 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:52 PM:
--------------------------------------------------------------------

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}



was (Author: ascherbakov):
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)

Mime
View raw message