Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-5809

TimeoutException: Unable to acquire lock after 15 seconds. Lock is held by GlobalTransaction:local

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 20.0.0.Final
    • 10.0.0.CR5
    • Clustering
    • None

    Description

      Seen in these scenarios:
      ejb-ejbservlet-shutdown-dist-async
      http-session-shutdown-dist-sync
      http-session-shutdown-dist-async

      After perf18 received new view (perf19 left the cluster gracefully), it logged this error:

      [JBossINF] [0m[31m15:25:11,994 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-50) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key perf18 and requestor GlobalTransaction:<perf18>:17121:local. Lock is held by GlobalTransaction:<perf18>:17120:local
[JBossINF] 	at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAndRecord(AbstractLockingInterceptor.java:189)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockKey(AbstractTxLockingInterceptor.java:192)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockOrRegisterBackupLock(AbstractTxLockingInterceptor.java:115)
[JBossINF] 	at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitDataWriteCommand(PessimisticLockingInterceptor.java:121)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.visitPutKeyValueCommand(AbstractTxLockingInterceptor.java:61)
[JBossINF] 	at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:73)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:43)
[JBossINF] 	at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:73)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:366)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:220)
[JBossINF] 	at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:73)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:43)
[JBossINF] 	at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:73)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.handleTxWriteCommand(StateTransferInterceptor.java:304)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.handleWriteCommand(StateTransferInterceptor.java:286)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.visitPutKeyValueCommand(StateTransferInterceptor.java:108)
[JBossINF] 	at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:73)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:102)
[JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:71)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:43)
[JBossINF] 	at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:73)
[JBossINF] 	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
[JBossINF] 	at org.infinispan.cache.impl.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1634)
[JBossINF] 	at org.infinispan.cache.impl.CacheImpl.putInternal(CacheImpl.java:1094)
[JBossINF] 	at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1083)
[JBossINF] 	at org.infinispan.cache.impl.DecoratedCache.put(DecoratedCache.java:447)
[JBossINF] 	at org.infinispan.cache.impl.AbstractDelegatingCache.put(AbstractDelegatingCache.java:291)
[JBossINF] 	at org.wildfly.clustering.server.registry.CacheRegistry.getLocalEntry(CacheRegistry.java:139)
[JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanRouteLocator.locate(InfinispanRouteLocator.java:62)
[JBossINF] 	at org.wildfly.clustering.web.undertow.session.DistributableSessionIdentifierCodec.encode(DistributableSessionIdentifierCodec.java:48)
[JBossINF] 	at org.wildfly.extension.undertow.session.CodecSessionConfig.findSessionId(CodecSessionConfig.java:60)
[JBossINF] 	at io.undertow.servlet.spec.ServletContextImpl$IgnoreInvalidatedSessionConfig.findSessionId(ServletContextImpl.java:990)
[JBossINF] 	at org.wildfly.clustering.web.undertow.session.DistributableSessionManager.getSession(DistributableSessionManager.java:134)
[JBossINF] 	at io.undertow.servlet.spec.ServletContextImpl.getSession(ServletContextImpl.java:725)
[JBossINF] 	at io.undertow.servlet.spec.HttpServletRequestImpl.getSession(HttpServletRequestImpl.java:370)
[JBossINF] 	at org.jboss.weld.servlet.SessionHolder.requestInitialized(SessionHolder.java:47)
[JBossINF] 	at org.jboss.weld.servlet.HttpContextLifecycle.requestInitialized(HttpContextLifecycle.java:231)
[JBossINF] 	at org.jboss.weld.servlet.WeldInitialListener.requestInitialized(WeldInitialListener.java:152)
[JBossINF] 	at io.undertow.servlet.core.ApplicationListeners.requestInitialized(ApplicationListeners.java:245)
[JBossINF] 	at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:283)
[JBossINF] 	at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
[JBossINF] 	at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
[JBossINF] 	at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
[JBossINF] 	at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
[JBossINF] 	at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
[JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[JBossINF] 	at java.lang.Thread.run(Thread.java:745)

      Other nodes logged the error during the test as well - approx. 500 times in total.

      Client log: as the perf19 is shut down, sampling error immediately start to occur (so the TimeoutException does seem to cause sampling errors):

      2015/11/27 15:25:07:758 EST [INFO ][TestController] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Node 1 (perf19) is down.
2015/11/27 15:25:07:758 EST [INFO ][TestController] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Cluster state: [UP, DOWN, UP, UP].
2015/11/27 15:25:11:999 EST [WARN ][Runner - 421] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Invalid response code: 500 Content: <html><head><title>Error</title></head><body>Internal Server Error</body></html>>
        org.jboss.smartfrog.loaddriver.RequestProcessingException: Invalid response code: 500 Content: <html><head><title>Error</title></head><body>Internal Server Error</body></html>
	at org.jboss.smartfrog.loaddriver.http.HttpRequestProcessorFactoryImpl$HttpRequestProcessor.processRequest(HttpRequestProcessorFactoryImpl.java:163)
	at org.jboss.smartfrog.loaddriver.CompoundRequestProcessorFactoryImpl$CompoundRequestProcessor.processRequest(CompoundRequestProcessorFactoryImpl.java:52)
	at org.jboss.smartfrog.loaddriver.Runner.run(Runner.java:103)
	at java.lang.Thread.run(Thread.java:745)

      In the same run, these TimeoutExcpetions were also logged:

      [JBossINF] [0m[31m15:25:22,306 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread--p8-t31) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Could not acquire lock on perf20 in behalf of transaction GlobalTransaction:<perf20>:79029:remote. Current owner GlobalTransaction:<perf20>:36201:remote.
[JBossINF] 	at org.infinispan.util.concurrent.locks.impl.DefaultPendingLockManager.timeout(DefaultPendingLockManager.java:224)
[JBossINF] 	at org.infinispan.util.concurrent.locks.impl.DefaultPendingLockManager.awaitPendingTransactionsForAllKeys(DefaultPendingLockManager.java:131)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:197)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
[JBossINF] 	at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitLockControlCommand(PessimisticLockingInterceptor.java:184)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:163)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.visitLockControlCommand(TxInterceptor.java:215)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:163)
[JBossINF] 	at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitLockControlCommand(TransactionSynchronizerInterceptor.java:75)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:239)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.visitLockControlCommand(StateTransferInterceptor.java:103)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:102)
[JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.visitLockControlCommand(InvocationContextInterceptor.java:76)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.perform(LockControlCommand.java:122)
[JBossINF] 	at org.infinispan.remoting.inboundhandler.BasePerCacheInboundInvocationHandler.invokePerform(BasePerCacheInboundInvocationHandler.java:92)
[JBossINF] 	at org.infinispan.remoting.inboundhandler.BaseBlockingRunnable.run(BaseBlockingRunnable.java:34)
[JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[JBossINF] 	at java.lang.Thread.run(Thread.java:745)

      Are they related?

      Link:
      http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-failover-http-session-shutdown-dist-async/13/console-perf18/

      Attachments

        Issue Links

          clones

          Bug - A problem that impairs or prevents the functions of the product. JBEAP-2273 TimeoutException: Unable to acquire lock after 15 seconds. Lock is held by GlobalTransaction:local

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Verified
          is related to

          Bug - A problem that impairs or prevents the functions of the product. WFLY-5186 TimeoutException: Unable to acquire lock after 15 seconds

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed
          Mentioned in

          [Trello] Card Micro team GREEN: Clustering BUGs revalidation

          Activity

            People

              pferraro@redhat.com Paul Ferraro
              mvinkler1@redhat.com Michal Vinkler
              Tommaso Borgato Tommaso Borgato
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: