[jboss-jira] [JBoss JIRA] (AS7-4813) Shutdown in REPL SYNC results in TimeoutException: Unable to acquire lock after
Dan Berindei (JIRA)
jira-events at lists.jboss.org
Thu May 17 12:43:18 EDT 2012
[ https://issues.jboss.org/browse/AS7-4813?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12693742#comment-12693742 ]
Dan Berindei commented on AS7-4813:
-----------------------------------
Richard, I might be wrong, but I think the errors only start appearing AFTER perf19 re-joined the cluster. This is what I've seen in the server logs:
{noformat}
11:45:29,369 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-14,null) ISPN000094: Received new cluster view: [perf21/web|6] [perf21/web, perf20/web, perf18/web]
11:46:34,639 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-10,null) ISPN000094: Received new cluster view: [perf21/ejb|7] [perf21/ejb, perf20/ejb, perf18/ejb, perf19/ejb]
11:46:54,112 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (ajp-perf18/10.16.90.54:8009-97) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [sgalNLPm8jvqZzLyQjwt4oZ3] for requestor [GlobalTransaction:<perf18/web>:3840:remote]! Lock held by [GlobalTransaction:<perf18/web>:3617:remote]
{noformat}
Richard, could it be that the client is only reporting the jvm route change if the request was successful? That may explain why the client logs show the jvm route change so long after the node re-joined... (Assuming I got the right logs.)
A possible reason may be that we only remove the tx from the TransactionTable in XaTransactionAdapter.commit, after we have already released the shared StateTransferLock.
So it's possible for state transfer to acquire the exclusive StateTransferLock and start sending the tx information to the new owner before all the already-committed txs have been removed from the table. The tx being committed already, the joiner won't receive any other commit command and will keep the key locked until it loses ownership of the key.
> Shutdown in REPL SYNC results in TimeoutException: Unable to acquire lock after
> -------------------------------------------------------------------------------
>
> Key: AS7-4813
> URL: https://issues.jboss.org/browse/AS7-4813
> Project: Application Server 7
> Issue Type: Bug
> Components: Clustering
> Affects Versions: 7.1.2.Final (EAP)
> Reporter: Radoslav Husar
> Assignee: Paul Ferraro
> Fix For: 7.1.3.Final (EAP)
>
>
> Similar to what we had before, but this time in failover tests.
> Whole logs
> http://hudson.qa.jboss.com/hudson/view/EAP6/view/EAP6-Failover/job/eap-6x-failover-http-session-shutdown-repl-sync/35/
> {noformat}
> 11:46:54,106 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (OOB-1720,null) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [sgalNLPm8jvqZzLyQjwt4oZ3] for requestor [GlobalTransaction:<perf18/web>:3840:remote]! Lock held by [GlobalTransaction:<perf18/web>:3617:remote]
> at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:216)
> at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:189)
> at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:179)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:209)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:136)
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitPutKeyValueCommand(OptimisticLockingInterceptor.java:243)
> at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.acquireLocksVisitingCommands(OptimisticLockingInterceptor.java:318)
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:119)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
> at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:58)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
> at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:106)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
> at org.infinispan.interceptors.StateTransferLockInterceptor.handleWithRetries(StateTransferLockInterceptor.java:213)
> at org.infinispan.interceptors.StateTransferLockInterceptor.visitPrepareCommand(StateTransferLockInterceptor.java:85)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:131)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:90)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
> at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:70)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
> at org.infinispan.commands.tx.PrepareCommand.perform(PrepareCommand.java:128)
> at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:127)
> at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:136)
> at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithRetry(InboundInvocationHandlerImpl.java:162)
> at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:114)
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:221)
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:201)
> at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:130) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.JChannel.up(JChannel.java:716) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.RSVP.up(RSVP.java:192) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.FRAG2.up(FRAG2.java:181) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.FlowControl.up(FlowControl.java:400) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.FlowControl.up(FlowControl.java:418) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.pbcast.GMS.up(GMS.java:889) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:383) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:706) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:566) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.BARRIER.up(BARRIER.java:126) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:143) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.FD.up(FD.java:273) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.MERGE2.up(MERGE2.java:205) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.Discovery.up(Discovery.java:359) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.stack.Protocol.up(Protocol.java:363) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.TP.passMessageUp(TP.java:1180) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1728) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1710) [jgroups-3.0.9.Final.jar:3.0.9.Final]
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_30]
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_30]
> at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_30]
> {noformat}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.jboss.org/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the jboss-jira
mailing list