You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@ignite.apache.org by "Semen Boikov (JIRA)" <ji...@apache.org> on 2016/05/12 08:26:12 UTC
[jira] [Updated] (IGNITE-2529) Confusing messages in the log when
transaction is being rollbacked
[ 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)