[
https://issues.apache.org/jira/browse/IGNITE-2529?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Semen Boikov updated IGNITE-2529:
---------------------------------
Fix Version/s: (was: 1.6)
> 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
> Labels: important
>
> 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)
