Denis Magda created IGNITE-2529:
-----------------------------------
Summary: Confusing messages in the log when transaction is being
rollbacked
Key: IGNITE-2529
URL: https://issues.apache.org/jira/browse/IGNITE-2529
Project: Ignite
Issue Type: Bug
Components: cache
Affects Versions: 1.5.0.final
Reporter: Denis Magda
Assignee: Semen Boikov
Fix For: 1.6
Here's the scenario:
1) there are two nodes N0 and N1 up and running in the cluster and there is a
replicated cache "cache1" started on both nodes.
2) each node registers a local event listener to track the discovery events.
3) node N1 gets stopped (gracefully).
4) N0 receives EVT_NODE_LEFT event and updates "cache1" using an async put
operation.
5) once in a while the put operation fails with following exceptions:
- the first one says that the commit has failed and transaction has been rolled
back on the backup nodes,
{noformat}
[topVer=65717610, nodeOrderDrId=1, globalTime=1454237609333,
order=1454237607894]
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.checkBackup(GridNearTxFinishFuture.java:425)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.finish(GridNearTxFinishFuture.java:321)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal$4.apply(GridNearTxLocal.java:838)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal$4.apply(GridNearTxLocal.java:830)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListener(GridFutureAdapter.java:262)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.listen(GridFutureAdapter.java:225)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal.commitAsync(GridNearTxLocal.java:830)
at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter.optimisticPutFuture(IgniteTxLocalAdapter.java:3230)
at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter.putAsync0(IgniteTxLocalAdapter.java:3017)
at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter.putAsync(IgniteTxLocalAdapter.java:1956)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter$31.op(GridCacheAdapter.java:2348)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter.asyncOp(GridCacheAdapter.java:4246)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter$AsyncOpRetryFuture.execute(GridCacheAdapter.java:4858)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter.asyncOp(GridCacheAdapter.java:4170)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter.putAsync0(GridCacheAdapter.java:2346)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter.putAsync(GridCacheAdapter.java:2323)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter.putAsync(GridCacheAdapter.java:2309)
at
org.apache.ignite.internal.processors.cache.IgniteCacheProxy.put(IgniteCacheProxy.java:1054)
... application stack frames ...
at java.lang.Thread.run(Thread.java:745)
{noformat}
- and the second one says that Ignite has failed to automatically rollback the
transaction and a whole bunch of other confusing messages
{noformat}
28395 [cluster-worker%N0.0] ERROR GridNearTxFinishFuture - Failed to
automatically rollback transaction: GridNearTxLocal
[mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl
[val=StateCoordinator.STATE_KEY, hasValBytes=true], cacheId=-1337668919,
txKey=null, val=[op=CREATE, val=UserCacheObjectImpl [val=OFFLINE,
hasValBytes=true]], prevVal=[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
[val=StateCoordinator.STATE_KEY, hasValBytes=true], val=null,
startVer=1454237607896, ver=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607896], hash=-1412496225, extras=null,
flags=0]]], prepared=false, locked=false,
nodeId=a680d5e4-0cb6-4ba8-9f5b-089b32a3ec8c, locMapped=false, expiryPlc=null,
transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null,
xidVer=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607894]]], explicitLock=false,
dhtVer=null, last=false, near=false, clientFirst=false,
node=a680d5e4-0cb6-4ba8-9f5b-089b32a3ec8c]], nearLocallyMapped=false,
colocatedLocallyMapped=false, needCheckBackup=false, hasRemoteLocks=false,
mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl
[val=StateCoordinator.STATE_KEY, hasValBytes=true], cacheId=-1337668919,
txKey=null, val=[op=CREATE, val=UserCacheObjectImpl [val=OFFLINE,
hasValBytes=true]], prevVal=[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
[val=StateCoordinator.STATE_KEY, hasValBytes=true], val=null,
startVer=1454237607896, ver=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607896], hash=-1412496225, extras=null,
flags=0]]], prepared=false, locked=false,
nodeId=a680d5e4-0cb6-4ba8-9f5b-089b32a3ec8c, locMapped=false, expiryPlc=null,
transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null,
xidVer=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607894]]], explicitLock=false,
dhtVer=null, last=false, near=false, clientFirst=false,
node=a680d5e4-0cb6-4ba8-9f5b-089b32a3ec8c]], super=GridDhtTxLocalAdapter
[nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false,
super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false,
depEnabled=false, txState=IgniteTxImplicitSingleStateImpl [entry=IgniteTxEntry
[key=KeyCacheObjectImpl [val=StateCoordinator.STATE_KEY, hasValBytes=true],
cacheId=-1337668919, txKey=null, val=[op=CREATE, val=UserCacheObjectImpl
[val=OFFLINE, hasValBytes=true]], prevVal=[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 [val=StateCoordinator.STATE_KEY, hasValBytes=true],
val=null, startVer=1454237607896, ver=GridCacheVersion [topVer=65717610,
nodeOrderDrId=1, globalTime=1454237609333, order=1454237607896],
hash=-1412496225, extras=null, flags=0]]], prepared=false, locked=false,
nodeId=a680d5e4-0cb6-4ba8-9f5b-089b32a3ec8c, locMapped=false, expiryPlc=null,
transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null,
xidVer=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607894]], init=true],
super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=65717610,
nodeOrderDrId=1, globalTime=1454237609333, order=1454237607894], writeVer=null,
implicit=true, loc=true, threadId=862, startTime=1454237609326,
nodeId=306ac330-41b7-46ab-98a5-81effd7309de, startVer=GridCacheVersion
[topVer=65717610, nodeOrderDrId=1, globalTime=1454237609333,
order=1454237607894], endVer=null, isolation=READ_COMMITTED,
concurrency=OPTIMISTIC, timeout=0, sysInvalidate=false, sys=false, plc=2,
commitVer=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607894], finalizing=NONE,
preparing=false, invalidParts=null, state=ROLLED_BACK, timedOut=false,
topVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], duration=10ms,
onePhaseCommit=true], size=1]]]
class org.apache.ignite.IgniteCheckedException: Invalid transaction state for
commit [state=ROLLED_BACK, tx=GridNearTxLocal
[mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl
[val=StateCoordinator.STATE_KEY, hasValBytes=true], cacheId=-1337668919,
txKey=null, val=[op=CREATE, val=UserCacheObjectImpl [val=OFFLINE,
hasValBytes=true]], prevVal=[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
[val=StateCoordinator.STATE_KEY, hasValBytes=true], val=null,
startVer=1454237607896, ver=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607896], hash=-1412496225, extras=null,
flags=0]]], prepared=false, locked=false,
nodeId=a680d5e4-0cb6-4ba8-9f5b-089b32a3ec8c, locMapped=false, expiryPlc=null,
transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null,
xidVer=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607894]]], explicitLock=false,
dhtVer=null, last=false, near=false, clientFirst=false,
node=a680d5e4-0cb6-4ba8-9f5b-089b32a3ec8c]], nearLocallyMapped=false,
colocatedLocallyMapped=false, needCheckBackup=false, hasRemoteLocks=false,
mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl
[val=StateCoordinator.STATE_KEY, hasValBytes=true], cacheId=-1337668919,
txKey=null, val=[op=CREATE, val=UserCacheObjectImpl [val=OFFLINE,
hasValBytes=true]], prevVal=[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
[val=StateCoordinator.STATE_KEY, hasValBytes=true], val=null,
startVer=1454237607896, ver=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607896], hash=-1412496225, extras=null,
flags=0]]], prepared=false, locked=false,
nodeId=a680d5e4-0cb6-4ba8-9f5b-089b32a3ec8c, locMapped=false, expiryPlc=null,
transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null,
xidVer=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607894]]], explicitLock=false,
dhtVer=null, last=false, near=false, clientFirst=false,
node=a680d5e4-0cb6-4ba8-9f5b-089b32a3ec8c]], super=GridDhtTxLocalAdapter
[nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false,
super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false,
depEnabled=false, txState=IgniteTxImplicitSingleStateImpl [entry=IgniteTxEntry
[key=KeyCacheObjectImpl [val=StateCoordinator.STATE_KEY, hasValBytes=true],
cacheId=-1337668919, txKey=null, val=[op=CREATE, val=UserCacheObjectImpl
[val=OFFLINE, hasValBytes=true]], prevVal=[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 [val=StateCoordinator.STATE_KEY, hasValBytes=true],
val=null, startVer=1454237607896, ver=GridCacheVersion [topVer=65717610,
nodeOrderDrId=1, globalTime=1454237609333, order=1454237607896],
hash=-1412496225, extras=null, flags=0]]], prepared=false, locked=false,
nodeId=a680d5e4-0cb6-4ba8-9f5b-089b32a3ec8c, locMapped=false, expiryPlc=null,
transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null,
xidVer=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607894]], init=true],
super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=65717610,
nodeOrderDrId=1, globalTime=1454237609333, order=1454237607894], writeVer=null,
implicit=true, loc=true, threadId=862, startTime=1454237609326,
nodeId=306ac330-41b7-46ab-98a5-81effd7309de, startVer=GridCacheVersion
[topVer=65717610, nodeOrderDrId=1, globalTime=1454237609333,
order=1454237607894], endVer=null, isolation=READ_COMMITTED,
concurrency=OPTIMISTIC, timeout=0, sysInvalidate=false, sys=false, plc=2,
commitVer=GridCacheVersion [topVer=65717610, nodeOrderDrId=1,
globalTime=1454237609333, order=1454237607894], finalizing=NONE,
preparing=false, invalidParts=null, state=ROLLED_BACK, timedOut=false,
topVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], duration=0ms,
onePhaseCommit=true], size=1]]]]
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal.finish(GridNearTxLocal.java:713)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.onDone(GridNearTxFinishFuture.java:238)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.onDone(GridNearTxFinishFuture.java:61)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:323)
at
org.apache.ignite.internal.util.future.GridCompoundFuture.checkComplete(GridCompoundFuture.java:301)
at
org.apache.ignite.internal.util.future.GridCompoundFuture.markInitialized(GridCompoundFuture.java:292)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.finish(GridNearTxFinishFuture.java:343)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal.rollbackAsync(GridNearTxLocal.java:886)
at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxLocalAdapter.rollback(GridDhtTxLocalAdapter.java:852)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.onDone(GridNearTxFinishFuture.java:213)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.onDone(GridNearTxFinishFuture.java:61)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:334)
at
org.apache.ignite.internal.util.future.GridCompoundFuture$Listener.apply(GridCompoundFuture.java:402)
at
org.apache.ignite.internal.util.future.GridCompoundFuture$Listener.apply(GridCompoundFuture.java:365)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListener(GridFutureAdapter.java:262)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListeners(GridFutureAdapter.java:250)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:380)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:346)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:334)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.checkBackup(GridNearTxFinishFuture.java:425)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.finish(GridNearTxFinishFuture.java:321)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal$4.apply(GridNearTxLocal.java:838)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal$4.apply(GridNearTxLocal.java:830)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListener(GridFutureAdapter.java:262)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.listen(GridFutureAdapter.java:225)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal.commitAsync(GridNearTxLocal.java:830)
at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter.optimisticPutFuture(IgniteTxLocalAdapter.java:3230)
at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter.putAsync0(IgniteTxLocalAdapter.java:3017)
at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter.putAsync(IgniteTxLocalAdapter.java:1956)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter$31.op(GridCacheAdapter.java:2348)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter.asyncOp(GridCacheAdapter.java:4246)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter$AsyncOpRetryFuture.execute(GridCacheAdapter.java:4858)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter.asyncOp(GridCacheAdapter.java:4170)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter.putAsync0(GridCacheAdapter.java:2346)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter.putAsync(GridCacheAdapter.java:2323)
at
org.apache.ignite.internal.processors.cache.GridCacheAdapter.putAsync(GridCacheAdapter.java:2309)
at
org.apache.ignite.internal.processors.cache.IgniteCacheProxy.put(IgniteCacheProxy.java:1054)
... application stack frames ...
at java.lang.Thread.run(Thread.java:745)
{noformat}
The second messages is really confusing because it leads to the feeling that
the transaction hasn't been rolled back.
This message should be reworked.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
