ignite-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Denis Magda (JIRA)" <j...@apache.org>
Subject [jira] [Created] (IGNITE-2529) Confusing messages in the log when transaction is being rollbacked
Date Tue, 02 Feb 2016 07:38:39 GMT
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)

Mime
View raw message