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)