[JBoss JIRA] (ISPN-4840) LockControlCommand timeouts can cause orphaned locks
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-4840?page=com.atlassian.jira.plugin.... ]
Dan Berindei updated ISPN-4840:
-------------------------------
Summary: LockControlCommand timeouts can cause orphaned locks (was: LockControlCommand timeouts can cause orphaned locks.)
> LockControlCommand timeouts can cause orphaned locks
> ----------------------------------------------------
>
> Key: ISPN-4840
> URL: https://issues.jboss.org/browse/ISPN-4840
> Project: Infinispan
> Issue Type: Bug
> Components: Core, Transactions
> Affects Versions: 7.0.0.CR1
> Reporter: Erik Salter
> Assignee: Dan Berindei
>
> If an originator times out on sending a pessimistic LockControlCommand, the receiver may still get the message. In this case, the originator will send a TxCompletionCommand. Because of this, the receiver will remove the registered remote transaction from its transaction table. If, however, another thread is processing the remote LCC command, it could acquire the lock(s) after the referencing remoteTx is removed. Thus, the affected keys will remain locked indefinitely.
> A simple solution would be to add a check to see if there's a remote transaction when the LCC thread verifies the remote transaction. This would be in addition to checking if the transaction is completed.
> See the following TRACE messages:
> -- Local TX created
> 2014-10-10 11:27:28,899 TRACE [org.infinispan.transaction.TransactionTable] (OOB-1353,session-resource-cluster,240-east-dht2.comcast.net-46326(CMC-Denver-CO)) Created a new local transaction: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, isFromStateTransfer=false} globalTx=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:local, topologyId=64, age(ms)=0
> -- Remote TX created
> 2014-10-10 11:27:28,525 TRACE [org.infinispan.transaction.TransactionTable] (OOB-2850,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Created and registered remote transaction RemoteTransaction{modifications=[], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=null, missingLookedUpEntries=false, isMarkedForRollback=false} globalTx=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:remote, topologyId=63, age(ms)=0
> -- Originator times out on LCC
> 2014-10-10 11:27:36,902 WARN [org.infinispan.remoting.rpc.RpcManagerImpl] (OOB-1353,session-resource-cluster,240-east-dht2.comcast.net-46326(CMC-Denver-CO)) ISPN000071: Caught exception when handling command LockControlCommand{cache=eigAllocation, keys=[EdgeResourceCacheKey[edgeDeviceId=2878,resourceId=11130]], flags=null, unlock=false}
> org.infinispan.CacheException: org.jgroups.TimeoutException: timeout sending message to 240-west-dht2.comcast.net-30190(CH2-Chicago-IL)
> at org.infinispan.util.Util.rewrapAsCacheException(Util.java:542)
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:188)
> ...
> at org.infinispan.interceptors.distribution.TxDistributionInterceptor.visitLockControlCommand(TxDistributionInterceptor.java:204)
> at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:134)
> at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:177)
> at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
> at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitLockControlCommand(PessimisticLockingInterceptor.java:235)
> at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:134)
> at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:177)
> at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
> at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:116)
> ...
> at org.infinispan.CacheImpl.lock(CacheImpl.java:565)
> at org.infinispan.CacheImpl.lock(CacheImpl.java:548)
> ...
> Caused by: org.jgroups.TimeoutException: timeout sending message to 240-west-dht2.comcast.net-30190(CH2-Chicago-IL)
> at org.jgroups.blocks.MessageDispatcher.sendMessage(MessageDispatcher.java:390)
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processSingleCall(CommandAwareRpcDispatcher.java:303)
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:181)
> ... 91 more
> 2014-10-10 11:27:36,936 TRACE [org.infinispan.interceptors.TxInterceptor] (OOB-1353,session-resource-cluster,240-east-dht2.comcast.net-46326(CMC-Denver-CO)) invokeNextInterceptorAndVerifyTransaction :: originatorMissing=false, alreadyCompleted=false
> 2014-10-10 11:27:36,937 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (OOB-1353,session-resource-cluster,240-east-dht2.comcast.net-46326(CMC-Denver-CO)) ISPN000136: Execution error
> org.infinispan.CacheException: org.jgroups.TimeoutException: timeout sending message to 240-west-dht2.comcast.net-30190(CH2-Chicago-IL)
> at org.infinispan.util.Util.rewrapAsCacheException(Util.java:542)
> ...
> -- Same stack trace
> -- Remote TX removed -- must be from TxCompletionMessage since isMarkedForRollback == false
> 2014-10-10 11:27:36,530 TRACE [org.infinispan.transaction.TransactionTable] (OOB-2963,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Removed remote transaction GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:local ? RemoteTransaction{modifications=[], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=null, missingLookedUpEntries=false, isMarkedForRollback=false} globalTx=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:remote, topologyId=63, age(ms)=8004
> 2014-10-10 11:27:36,530 TRACE [org.infinispan.transaction.TransactionTable] (OOB-2963,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Removed RemoteTransaction{modifications=[], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=null, missingLookedUpEntries=false, isMarkedForRollback=false} globalTx=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:remote, topologyId=63, age(ms)=8004 from transaction table.
> -- Local TX removed
> 2014-10-10 11:27:36,937 TRACE [org.infinispan.transaction.TransactionTable] (OOB-1353,session-resource-cluster,240-east-dht2.comcast.net-46326(CMC-Denver-CO)) Removed LocalTransaction{remoteLockedNodes=[240-east-dht2.comcast.net-46326(CMC-Denver-CO), 240-west-dht2.comcast.net-30190(CH2-Chicago-IL)], isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, isFromStateTransfer=false} globalTx=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:local, topologyId=64, age(ms)=8038 from transaction table.
> -- Lock acquisition completes!
> 2014-10-10 11:27:39,195 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (OOB-2850,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Attempting to lock EdgeResourceCacheKey[edgeDeviceId=2878,resourceId=11130] with acquisition timeout of 5000 millis
> 2014-10-10 11:27:39,198 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (OOB-2850,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Successfully acquired lock EdgeResourceCacheKey[edgeDeviceId=2878,resourceId=11130]!
> 2014-10-10 11:27:39,202 TRACE [org.infinispan.transaction.TransactionTable] (OOB-2850,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Transaction=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:remote, nodeMaxPrunedTxId=858439
> -- Not in completion map since transaction was removed without commit or rollback. Lock never releases
> 2014-10-10 11:27:39,203 TRACE [org.infinispan.interceptors.TxInterceptor] (OOB-2850,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) invokeNextInterceptorAndVerifyTransaction :: originatorMissing=false, alreadyCompleted=false
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years, 5 months
[JBoss JIRA] (ISPN-4887) Stale locks in non-tx cache after merge
by Dan Berindei (JIRA)
Dan Berindei created ISPN-4887:
----------------------------------
Summary: Stale locks in non-tx cache after merge
Key: ISPN-4887
URL: https://issues.jboss.org/browse/ISPN-4887
Project: Infinispan
Issue Type: Bug
Components: Core, Test Suite - Core
Affects Versions: 7.0.0.CR2
Reporter: Dan Berindei
Priority: Blocker
Fix For: 7.0.0.Final
It appears to cause random failures in {{ThreeNodesReplicatedSplitAndMergeTest.testSplitAndMerge0}}:
{noformat}
org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 10 seconds for key MagicKey#null{74043ff7@ThreeNodesReplicatedSplitAndMergeTest-NodeC-12710/9} and requestor Thread[testng-ThreeNodesReplicatedSplitAndMergeTest,5,main]. Lock is held by Thread[remote-thread-ThreeNodesReplicatedSplitAndMergeTest-NodeC-p5654-t5,5,main], while request came from null
at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:198)
at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:181)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:127)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:123)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitPutKeyValueCommand(AbstractLockingInterceptor.java:47)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112)
at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:33)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112)
at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:33)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)
at org.infinispan.statetransfer.StateTransferInterceptor.handleNonTxWriteCommand(StateTransferInterceptor.java:172)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPutKeyValueCommand(StateTransferInterceptor.java:95)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)
at org.infinispan.interceptors.CacheMgmtInterceptor.updateStoreStatistics(CacheMgmtInterceptor.java:148)
at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:134)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112)
at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:33)
at org.infinispan.partionhandling.impl.PartitionHandlingInterceptor.visitPutKeyValueCommand(PartitionHandlingInterceptor.java:34)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:102)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:71)
at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:33)
at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:333)
at org.infinispan.cache.impl.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1512)
at org.infinispan.cache.impl.CacheImpl.putInternal(CacheImpl.java:990)
at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:982)
at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1582)
at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:235)
at org.infinispan.partitionhandling.ThreeNodesReplicatedSplitAndMergeTest.testSplitAndMerge(ThreeNodesReplicatedSplitAndMergeTest.java:132)
at org.infinispan.partitionhandling.ThreeNodesReplicatedSplitAndMergeTest.testSplitAndMerge0(ThreeNodesReplicatedSplitAndMergeTest.java:27)
{noformat}
http://ci.infinispan.org/viewLog.html?buildId=13499&tab=buildResultsDiv&b...
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years, 5 months
[JBoss JIRA] (ISPN-4872) During state transfer, a pessimistic transaction can fail due to a ClusteredGetCommand forcing a lock command
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-4872?page=com.atlassian.jira.plugin.... ]
Dan Berindei updated ISPN-4872:
-------------------------------
Status: Resolved (was: Pull Request Sent)
Fix Version/s: 7.04
Resolution: Done
> During state transfer, a pessimistic transaction can fail due to a ClusteredGetCommand forcing a lock command
> -------------------------------------------------------------------------------------------------------------
>
> Key: ISPN-4872
> URL: https://issues.jboss.org/browse/ISPN-4872
> Project: Infinispan
> Issue Type: Bug
> Components: Core
> Affects Versions: 5.2.7.Final, 6.0.2.Final, 7.0.0.CR2
> Reporter: Erik Salter
> Assignee: Dan Berindei
> Fix For: 7.04
>
>
> This is a strange one:
> A pessimistic transaction started on the primary owner during state transfer can fail because a backup owner issues a ClusteredGetCommand to the primary while processing the write command. This can happen if the backup needs to perform a remote get (due to a DELTA_WRITE, conditional, or reliable return values). In this case, it's a DELTA_WRITE.
> In this chain of events, state transfer is ongoing, and the union CH is (east-dht5, west-dht5, east-dht6) In this case, the pessimistic transaction originated on east-dht5 must be invoked on west-dht5 and east-dht6:
> {code}
> 2014-10-21 02:15:01,309 TRACE [org.infinispan.transaction.TransactionTable] (OOB-1713,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Created a new local transaction: LocalXaTransaction{xid=null} LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, isFromStateTransfer=false} globalTx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local, topologyId=33, age(ms)=0
> 2014-10-21 02:15:01,309 TRACE [org.infinispan.util.concurrent.locks.containers.OwnableReentrantPerEntryLockContainer] (OOB-1713,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Creating and acquiring new lock instance for key EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831]
> 2014-10-21 02:15:01,345 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-1713,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Replication task sending PrepareCommand {modifications=[PutKeyValueCommand{key=EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], value=QamResource [qamId=431831, currentBandwidth=3750000, maxBandwidth=38810000, maxPrograms=255, currentPrograms=1], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE], putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1, successful=true, ignorePreviousValue=false}], onePhaseCommit=true, gtx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local, cacheName='qamAllocation', topologyId=33} to addresses [240-west-dht5.comcast.net-35898(CH2-Chicago-IL), 240-east-dht6.comcast.net-47049(CMC-Denver-CO)] with response mode GET_ALL
> {code}
> Let's examine east-dht6. It gets the write request. It needs to perform a remote get to pull the full key context, since it receives only the delta.
> {code}
> 2014-10-21 02:15:01,362 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-2149,session-resource-cluster,240-east-dht6.comcast.net-47049(CMC-Denver-CO)) Attempting to execute command: PrepareCommand {modifications=[PutKeyValueCommand{key=EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], value=QamResourceDelta [qamId=431831, basePort=2049, currentBandwidth=3750000, maxBandwidth=38810000, maxPrograms=255, currentPrograms=1, baseProgramNumber=1, portStep=1, program=Program [portNumber=2053, programNumber=5, status=UNUSED, sessionToken=, lastUpdatedTime=1413872101310, bandwidth=0, inputId=-1]], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE], putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1, successful=true, ignorePreviousValue=false}], onePhaseCommit=true, gtx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local, cacheName='qamAllocation', topologyId=33} [sender=240-east-dht5.comcast.net-26106(CMC-Denver-CO)]
> ...
> 2014-10-21 02:15:01,362 TRACE [org.infinispan.transaction.TransactionTable] (OOB-2149,session-resource-cluster,240-east-dht6.comcast.net-47049(CMC-Denver-CO)) Created and registered remote transaction RemoteTransaction{modifications=...
> globalTx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:remote, topologyId=33, age(ms)=0
> 2014-10-21 02:15:01,362 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-2149,session-resource-cluster,240-east-dht6.comcast.net-47049(CMC-Denver-CO)) Replication task sending ClusteredGetCommand{key=EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE]} to addresses [240-east-dht5.comcast.net-26106(CMC-Denver-CO), 240-west-dht5.comcast.net-35898(CH2-Chicago-IL)] with response mode GET_FIRST
> {code}
> east-dht5 receives the ClusteredGetCommand request. Because TxDistributionInterceptor::line 325 is true, the acquireRemoteLock flag is set to true.
> {code}
> boolean acquireRemoteLock = false;
> if (ctx.isInTxScope()) {
> TxInvocationContext txContext = (TxInvocationContext) ctx;
> acquireRemoteLock = isWrite && isPessimisticCache && !txContext.getAffectedKeys().contains(key);
> }
> {code}
> Thus, when east-dht5 runs the ClusteredGetCommand. it will create and invoke a LockControlCommand. Because the LCC is created inline, it will not have its origin set. But the LCC will create a RemoteTxInvocationContext. When the LCC runs through the interceptor chain, TxInterceptor::invokeNextInterceptorAndVerifyTransaction will check the originator (because of the remote context). When it doesn't find it, it will force a rollback.
> {code}
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Calling perform() on ClusteredGetCommand{key=EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE]}
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.transaction.TransactionTable] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Created and registered remote transaction RemoteTransaction{modifications=[], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=null, missingLookedUpEntries=false, isMarkedForRollback=false} globalTx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local, topologyId=33, age(ms)=0
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.statetransfer.StateTransferInterceptor] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) handleTopologyAffectedCommand for command LockControlCommand{cache=qamAllocation, keys=[EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831]], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE], unlock=false}
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.interceptors.locking.PessimisticLockingInterceptor] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Locking key EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], no need to check for pending locks.
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.interceptors.TxInterceptor] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) invokeNextInterceptorAndVerifyTransaction :: originatorMissing=true, alreadyCompleted=false
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.interceptors.TxInterceptor] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Rolling back remote transaction GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local because either already completed(false) or originator(null) no longer in the cluster(true).
>
> // ROLLBACK HAPPENS HERE
> {code}
> When the transaction attempts to commit, it fails due to the spurious rollback. For instance:
> {code}
> 2014-10-21 02:15:01,384 WARN [org.infinispan.remoting.rpc.RpcManagerImpl] (OOB-1713,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) ISPN000071: Caught exception when handling command PrepareCommand {modifications=[PutKeyValueCommand{key=EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], value=QamResource [qamId=431831, currentBandwidth=3750000, maxBandwidth=38810000, maxPrograms=255, currentPrograms=1], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE], putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1, successful=true, ignorePreviousValue=false}], onePhaseCommit=true, gtx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local, cacheName='qamAllocation', topologyId=33}
> org.infinispan.remoting.RemoteException: ISPN000217: Received exception from 240-west-dht5.comcast.net-35898(CH2-Chicago-IL), see cause for remote stack trace
> ...
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
> at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:175)
> at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:122)
> ...
> com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:636)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2619)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1779)
> at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:88)
> at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
> Caused by: org.infinispan.transaction.xa.InvalidTransactionException: This remote transaction GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local is already rolled back
> at org.infinispan.transaction.RemoteTransaction.checkIfRolledBack(RemoteTransaction.java:137)
> at org.infinispan.transaction.RemoteTransaction.putLookedUpEntry(RemoteTransaction.java:73)
> at org.infinispan.context.impl.RemoteTxInvocationContext.putLookedUpEntry(RemoteTxInvocationContext.java:99)
> at org.infinispan.container.EntryFactoryImpl.wrapInternalCacheEntryForPut(EntryFactoryImpl.java:242)
> at org.infinispan.container.EntryFactoryImpl.wrapEntryForPut(EntryFactoryImpl.java:166)
> ...
> {code}
> So it looks like there's a couple ways to handle this. One would be to only acquire a remote lock in TxDistributionInterceptor if the current node was the originator. Another -- possibly less intrusive -- would be to set the origin of the invoked LCC command to that of the ClusteredGetCommand. The former should be preferable, but this code tends to be a bit labyrinthine with the various pessimistic use cases out there.
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years, 5 months
[JBoss JIRA] (ISPN-4872) During state transfer, a pessimistic transaction can fail due to a ClusteredGetCommand forcing a lock command
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-4872?page=com.atlassian.jira.plugin.... ]
Dan Berindei updated ISPN-4872:
-------------------------------
Status: Pull Request Sent (was: Open)
Git Pull Request: https://github.com/infinispan/infinispan/pull/2978
> During state transfer, a pessimistic transaction can fail due to a ClusteredGetCommand forcing a lock command
> -------------------------------------------------------------------------------------------------------------
>
> Key: ISPN-4872
> URL: https://issues.jboss.org/browse/ISPN-4872
> Project: Infinispan
> Issue Type: Bug
> Components: Core
> Affects Versions: 5.2.7.Final, 6.0.2.Final, 7.0.0.CR2
> Reporter: Erik Salter
> Assignee: Dan Berindei
> Fix For: 7.04
>
>
> This is a strange one:
> A pessimistic transaction started on the primary owner during state transfer can fail because a backup owner issues a ClusteredGetCommand to the primary while processing the write command. This can happen if the backup needs to perform a remote get (due to a DELTA_WRITE, conditional, or reliable return values). In this case, it's a DELTA_WRITE.
> In this chain of events, state transfer is ongoing, and the union CH is (east-dht5, west-dht5, east-dht6) In this case, the pessimistic transaction originated on east-dht5 must be invoked on west-dht5 and east-dht6:
> {code}
> 2014-10-21 02:15:01,309 TRACE [org.infinispan.transaction.TransactionTable] (OOB-1713,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Created a new local transaction: LocalXaTransaction{xid=null} LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, isFromStateTransfer=false} globalTx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local, topologyId=33, age(ms)=0
> 2014-10-21 02:15:01,309 TRACE [org.infinispan.util.concurrent.locks.containers.OwnableReentrantPerEntryLockContainer] (OOB-1713,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Creating and acquiring new lock instance for key EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831]
> 2014-10-21 02:15:01,345 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-1713,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Replication task sending PrepareCommand {modifications=[PutKeyValueCommand{key=EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], value=QamResource [qamId=431831, currentBandwidth=3750000, maxBandwidth=38810000, maxPrograms=255, currentPrograms=1], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE], putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1, successful=true, ignorePreviousValue=false}], onePhaseCommit=true, gtx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local, cacheName='qamAllocation', topologyId=33} to addresses [240-west-dht5.comcast.net-35898(CH2-Chicago-IL), 240-east-dht6.comcast.net-47049(CMC-Denver-CO)] with response mode GET_ALL
> {code}
> Let's examine east-dht6. It gets the write request. It needs to perform a remote get to pull the full key context, since it receives only the delta.
> {code}
> 2014-10-21 02:15:01,362 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-2149,session-resource-cluster,240-east-dht6.comcast.net-47049(CMC-Denver-CO)) Attempting to execute command: PrepareCommand {modifications=[PutKeyValueCommand{key=EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], value=QamResourceDelta [qamId=431831, basePort=2049, currentBandwidth=3750000, maxBandwidth=38810000, maxPrograms=255, currentPrograms=1, baseProgramNumber=1, portStep=1, program=Program [portNumber=2053, programNumber=5, status=UNUSED, sessionToken=, lastUpdatedTime=1413872101310, bandwidth=0, inputId=-1]], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE], putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1, successful=true, ignorePreviousValue=false}], onePhaseCommit=true, gtx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local, cacheName='qamAllocation', topologyId=33} [sender=240-east-dht5.comcast.net-26106(CMC-Denver-CO)]
> ...
> 2014-10-21 02:15:01,362 TRACE [org.infinispan.transaction.TransactionTable] (OOB-2149,session-resource-cluster,240-east-dht6.comcast.net-47049(CMC-Denver-CO)) Created and registered remote transaction RemoteTransaction{modifications=...
> globalTx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:remote, topologyId=33, age(ms)=0
> 2014-10-21 02:15:01,362 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-2149,session-resource-cluster,240-east-dht6.comcast.net-47049(CMC-Denver-CO)) Replication task sending ClusteredGetCommand{key=EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE]} to addresses [240-east-dht5.comcast.net-26106(CMC-Denver-CO), 240-west-dht5.comcast.net-35898(CH2-Chicago-IL)] with response mode GET_FIRST
> {code}
> east-dht5 receives the ClusteredGetCommand request. Because TxDistributionInterceptor::line 325 is true, the acquireRemoteLock flag is set to true.
> {code}
> boolean acquireRemoteLock = false;
> if (ctx.isInTxScope()) {
> TxInvocationContext txContext = (TxInvocationContext) ctx;
> acquireRemoteLock = isWrite && isPessimisticCache && !txContext.getAffectedKeys().contains(key);
> }
> {code}
> Thus, when east-dht5 runs the ClusteredGetCommand. it will create and invoke a LockControlCommand. Because the LCC is created inline, it will not have its origin set. But the LCC will create a RemoteTxInvocationContext. When the LCC runs through the interceptor chain, TxInterceptor::invokeNextInterceptorAndVerifyTransaction will check the originator (because of the remote context). When it doesn't find it, it will force a rollback.
> {code}
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Calling perform() on ClusteredGetCommand{key=EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE]}
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.transaction.TransactionTable] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Created and registered remote transaction RemoteTransaction{modifications=[], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=null, missingLookedUpEntries=false, isMarkedForRollback=false} globalTx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local, topologyId=33, age(ms)=0
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.statetransfer.StateTransferInterceptor] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) handleTopologyAffectedCommand for command LockControlCommand{cache=qamAllocation, keys=[EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831]], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE], unlock=false}
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.interceptors.locking.PessimisticLockingInterceptor] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Locking key EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], no need to check for pending locks.
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.interceptors.TxInterceptor] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) invokeNextInterceptorAndVerifyTransaction :: originatorMissing=true, alreadyCompleted=false
> 2014-10-21 02:15:01,347 TRACE [org.infinispan.interceptors.TxInterceptor] (OOB-1721,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) Rolling back remote transaction GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local because either already completed(false) or originator(null) no longer in the cluster(true).
>
> // ROLLBACK HAPPENS HERE
> {code}
> When the transaction attempts to commit, it fails due to the spurious rollback. For instance:
> {code}
> 2014-10-21 02:15:01,384 WARN [org.infinispan.remoting.rpc.RpcManagerImpl] (OOB-1713,session-resource-cluster,240-east-dht5.comcast.net-26106(CMC-Denver-CO)) ISPN000071: Caught exception when handling command PrepareCommand {modifications=[PutKeyValueCommand{key=EdgeResourceCacheKey[edgeDeviceId=4211,resourceId=431831], value=QamResource [qamId=431831, currentBandwidth=3750000, maxBandwidth=38810000, maxPrograms=255, currentPrograms=1], flags=[SKIP_REMOTE_LOOKUP, DELTA_WRITE], putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1, successful=true, ignorePreviousValue=false}], onePhaseCommit=true, gtx=GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local, cacheName='qamAllocation', topologyId=33}
> org.infinispan.remoting.RemoteException: ISPN000217: Received exception from 240-west-dht5.comcast.net-35898(CH2-Chicago-IL), see cause for remote stack trace
> ...
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
> at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:175)
> at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:122)
> ...
> com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:636)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2619)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1779)
> at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:88)
> at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
> Caused by: org.infinispan.transaction.xa.InvalidTransactionException: This remote transaction GlobalTransaction:<240-east-dht5.comcast.net-26106(CMC-Denver-CO)>:1575124:local is already rolled back
> at org.infinispan.transaction.RemoteTransaction.checkIfRolledBack(RemoteTransaction.java:137)
> at org.infinispan.transaction.RemoteTransaction.putLookedUpEntry(RemoteTransaction.java:73)
> at org.infinispan.context.impl.RemoteTxInvocationContext.putLookedUpEntry(RemoteTxInvocationContext.java:99)
> at org.infinispan.container.EntryFactoryImpl.wrapInternalCacheEntryForPut(EntryFactoryImpl.java:242)
> at org.infinispan.container.EntryFactoryImpl.wrapEntryForPut(EntryFactoryImpl.java:166)
> ...
> {code}
> So it looks like there's a couple ways to handle this. One would be to only acquire a remote lock in TxDistributionInterceptor if the current node was the originator. Another -- possibly less intrusive -- would be to set the origin of the invoked LCC command to that of the ClusteredGetCommand. The former should be preferable, but this code tends to be a bit labyrinthine with the various pessimistic use cases out there.
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years, 5 months
[JBoss JIRA] (ISPN-3450) Jon plugin - failing RebuildIndex operation on [MassIndexer] component
by William Burns (JIRA)
[ https://issues.jboss.org/browse/ISPN-3450?page=com.atlassian.jira.plugin.... ]
William Burns updated ISPN-3450:
--------------------------------
Status: Resolved (was: Pull Request Sent)
Resolution: Done
> Jon plugin - failing RebuildIndex operation on [MassIndexer] component
> ----------------------------------------------------------------------
>
> Key: ISPN-3450
> URL: https://issues.jboss.org/browse/ISPN-3450
> Project: Infinispan
> Issue Type: Bug
> Components: JMX, reporting and management
> Reporter: Tomas Sykora
> Assignee: Adrian Nistor
> Fix For: 7.0.0.Final
>
>
> RebuildIndex operation on [MassIndexer] component is failing while issuing in JON with this error:
> java.lang.NullPointerException
> at org.infinispan.rhq.CacheComponent.invokeOperation(CacheComponent.java:157)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:601)
> at org.rhq.core.pc.inventory.ResourceContainer$ComponentInvocationThread.call(ResourceContainer.java:634)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:722)
> I reused configuration from ISPN test suite + I was able to issue this operation successfully via jconsole tool. That's why I suspect that problems are somewhere in JON-ISPN interaction or plugin.
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years, 5 months
[JBoss JIRA] (ISPN-4463) AsyncAPITest.testAsyncMethodWithLifespanAndMaxIdle fails randomly
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-4463?page=com.atlassian.jira.plugin.... ]
Dan Berindei commented on ISPN-4463:
------------------------------------
The test is wrong: it saves the {{nanoTime()}} after it called {{putAsync()}} and assumes that it's more or less the timestamp of the created entry. It should save two timestamps, one before calling {{putAsync()}}, the other after the future returned by {{putAsync()}} is done, and check that {{nanoTime_before_the_entry_expired - nanoTime_after_putAsync <= lifespan}} and {{nanoTime_after_the_entry_expired - nanoTime_before_putAsync >= lifespan}}. Using a mock {{TimeService}} should also help...
> AsyncAPITest.testAsyncMethodWithLifespanAndMaxIdle fails randomly
> -----------------------------------------------------------------
>
> Key: ISPN-4463
> URL: https://issues.jboss.org/browse/ISPN-4463
> Project: Infinispan
> Issue Type: Bug
> Components: Core
> Affects Versions: 7.0.0.Alpha4
> Reporter: Vitalii Chepeliuk
> Priority: Blocker
> Labels: testsuite_stability
> Fix For: 7.0.0.Final
>
> Attachments: AsyncAPITest.log
>
>
> {noformat}
> java.lang.AssertionError: Entry evicted too soon!
> at org.junit.Assert.fail(Assert.java:88)
> at org.junit.Assert.assertTrue(Assert.java:41)
> at org.infinispan.api.AsyncAPITest.verifyEviction(AsyncAPITest.java:356)
> at org.infinispan.api.AsyncAPITest.testAsyncMethodWithLifespanAndMaxIdle(AsyncAPITest.java:279)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:94)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
> at java.lang.reflect.Method.invoke(Method.java:619)
> at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:80)
> at org.testng.internal.Invoker.invokeMethod(Invoker.java:714)
> at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901)
> at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231)
> at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
> at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
> at org.testng.TestRunner.privateRun(TestRunner.java:767)
> at org.testng.TestRunner.run(TestRunner.java:617)
> at org.testng.SuiteRunner.runTest(SuiteRunner.java:334)
> at org.testng.SuiteRunner.access$000(SuiteRunner.java:37)
> at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:368)
> at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64)
> at java.util.concurrent.FutureTask.run(FutureTask.java:273)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
> at java.lang.Thread.run(Thread.java:853)
> {noformat}
> Jenkins failer here
> https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/JDG/view/FUNC/job/e...
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years, 5 months
[JBoss JIRA] (ISPN-4566) ManualIndexingTest.testManualIndexing random failures
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-4566?page=com.atlassian.jira.plugin.... ]
Dan Berindei commented on ISPN-4566:
------------------------------------
A new error appeared without TRACE logging enabled:
{noformat}
javax.management.MBeanException: null
at org.infinispan.jmx.ResourceDMBean.invoke(ResourceDMBean.java:271)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801)
at org.jboss.as.jmx.PluggableMBeanServerImpl$TcclMBeanServer.invoke(PluggableMBeanServerImpl.java:1456)
at org.jboss.as.jmx.PluggableMBeanServerImpl.invoke(PluggableMBeanServerImpl.java:732)
at org.jboss.remotingjmx.protocol.v2.ServerProxy$InvokeHandler.handle(ServerProxy.java:952)
at org.jboss.remotingjmx.protocol.v2.ServerCommon$MessageReciever$1$1.run(ServerCommon.java:153)
at org.jboss.as.jmx.ServerInterceptorFactory$Interceptor$1.run(ServerInterceptorFactory.java:75)
at org.jboss.as.jmx.ServerInterceptorFactory$Interceptor$1.run(ServerInterceptorFactory.java:70)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:415)
at org.jboss.as.controller.AccessAuditContext.doAs(AccessAuditContext.java:94)
at org.jboss.as.jmx.ServerInterceptorFactory$Interceptor.handleEvent(ServerInterceptorFactory.java:70)
at org.jboss.remotingjmx.protocol.v2.ServerCommon$MessageReciever$1.run(ServerCommon.java:149)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.Exception: java.lang.NullPointerException
at org.infinispan.jmx.ResourceDMBean.invoke(ResourceDMBean.java:271)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801)
at org.jboss.as.jmx.PluggableMBeanServerImpl$TcclMBeanServer.invoke(PluggableMBeanServerImpl.java:1456)
at org.jboss.as.jmx.PluggableMBeanServerImpl.invoke(PluggableMBeanServerImpl.java:732)
at org.jboss.remotingjmx.protocol.v2.ServerProxy$InvokeHandler.handle(ServerProxy.java:952)
at org.jboss.remotingjmx.protocol.v2.ServerCommon$MessageReciever$1$1.run(ServerCommon.java:153)
at org.jboss.as.jmx.ServerInterceptorFactory$Interceptor$1.run(ServerInterceptorFactory.java:75)
at org.jboss.as.jmx.ServerInterceptorFactory$Interceptor$1.run(ServerInterceptorFactory.java:70)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:415)
at org.jboss.as.controller.AccessAuditContext.doAs(AccessAuditContext.java:94)
at org.jboss.as.jmx.ServerInterceptorFactory$Interceptor.handleEvent(ServerInterceptorFactory.java:70)
at org.jboss.remotingjmx.protocol.v2.ServerCommon$MessageReciever$1.run(ServerCommon.java:149)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException: null
at org.infinispan.query.impl.massindex.IndexingMapper.map(IndexingMapper.java:43)
at org.infinispan.distexec.mapreduce.MapReduceManagerImpl$2.apply(MapReduceManagerImpl.java:205)
at org.infinispan.distexec.mapreduce.MapReduceManagerImpl$2.apply(MapReduceManagerImpl.java:200)
at org.infinispan.container.DefaultDataContainer$1.apply(DefaultDataContainer.java:397)
at org.infinispan.container.DefaultDataContainer$1.apply(DefaultDataContainer.java:393)
at org.infinispan.commons.util.concurrent.jdk8backported.ConcurrentParallelHashMapV8$1.apply(ConcurrentParallelHashMapV8.java:48)
at org.infinispan.commons.util.concurrent.jdk8backported.EquivalentConcurrentHashMapV8$ForEachMappingTask.compute(EquivalentConcurrentHashMapV8.java:4894)
at org.infinispan.commons.util.concurrent.jdk8backported.CountedCompleter.exec(CountedCompleter.java:681)
at org.infinispan.commons.util.concurrent.jdk8backported.ForkJoinTask.doExec(ForkJoinTask.java:264)
at org.infinispan.commons.util.concurrent.jdk8backported.ForkJoinTask.doInvoke(ForkJoinTask.java:360)
at org.infinispan.commons.util.concurrent.jdk8backported.ForkJoinTask.invoke(ForkJoinTask.java:692)
at org.infinispan.commons.util.concurrent.jdk8backported.EquivalentConcurrentHashMapV8.forEach(EquivalentConcurrentHashMapV8.java:3592)
at org.infinispan.commons.util.concurrent.jdk8backported.ConcurrentParallelHashMapV8.forEach(ConcurrentParallelHashMapV8.java:44)
at org.infinispan.container.DefaultDataContainer.executeTask(DefaultDataContainer.java:393)
at org.infinispan.distexec.mapreduce.MapReduceManagerImpl.map(MapReduceManagerImpl.java:200)
at org.infinispan.distexec.mapreduce.MapReduceManagerImpl.mapAndCombineForLocalReduction(MapReduceManagerImpl.java:94)
at org.infinispan.distexec.mapreduce.MapReduceTask$MapTaskPart.invokeMapCombineLocallyForLocalReduction(MapReduceTask.java:1162)
at org.infinispan.distexec.mapreduce.MapReduceTask$MapTaskPart.access$400(MapReduceTask.java:1101)
at org.infinispan.distexec.mapreduce.MapReduceTask$MapTaskPart$2.call(MapReduceTask.java:1133)
at org.infinispan.distexec.mapreduce.MapReduceTask$MapTaskPart$2.call(MapReduceTask.java:1129)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
at org.jboss.threads.JBossThread.run(JBossThread.java:122)
{noformat}
http://ci.infinispan.org/viewLog.html?buildId=13486&tab=buildResultsDiv&b...
> ManualIndexingTest.testManualIndexing random failures
> -----------------------------------------------------
>
> Key: ISPN-4566
> URL: https://issues.jboss.org/browse/ISPN-4566
> Project: Infinispan
> Issue Type: Bug
> Components: Test Suite - Query
> Affects Versions: 7.0.0.Alpha5
> Reporter: Dan Berindei
> Priority: Blocker
> Labels: testsuite_stability
> Fix For: 7.0.0.Final
>
>
> Random timeouts when TRACE logging is enabled:
> {noformat}
> 04:58:33,679 ERROR (testng-ManualIndexingTest:) [UnitTestTestNGListener] Test testManualIndexing(org.infinispan.query.api.ManualIndexingTest) failed.
> org.infinispan.commons.CacheException: java.util.concurrent.ExecutionException: Map phase executing at ManualIndexingTest-NodeA-44176 did not complete within 20 sec timeout
> at org.infinispan.distexec.mapreduce.MapReduceTask.executeHelper(MapReduceTask.java:506)
> at org.infinispan.distexec.mapreduce.MapReduceTask.execute(MapReduceTask.java:407)
> at org.infinispan.query.impl.massindex.MapReduceMassIndexer.start(MapReduceMassIndexer.java:25)
> at org.infinispan.query.api.ManualIndexingTest.testManualIndexing(ManualIndexingTest.java:52)
> {noformat}
> Trace log here: http://ci.infinispan.org/viewLog.html?buildId=9816&buildTypeId=Infinispan...
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years, 5 months