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

TimeoutException: Could not acquire lock: Waiting to complete tx

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 11.0.0.Alpha1
    • 10.0.0.Alpha6, 10.0.0.Beta1, 10.0.0.CR2
    • Clustering
    • None

    Description

      Seen in these scenarios:
      ejbservlet - shutdown/undeploy
      http session - shutdown/undeploy

      Setup: 4 node cluster, one node at time is shutdown, while standalone clients keep calling the application.
      Approx. 30 seconds after failing one node, one or more nodes intermittently log this error:

      [JBossINF] �[0m�[31m16:32:07,395 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (transport-thread--p7-t21) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Could not acquire lock on la5hJBZTPNMkBJCXILk9IzqA36rlEU-rSIUIwB-x on behalf of transaction GlobalTransaction:<perf19>:3179:local. Waiting to complete tx: RemoteTransaction{modifications=[], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=[la5hJBZTPNMkBJCXILk9IzqA36rlEU-rSIUIwB-x, la5hJBZTPNMkBJCXILk9IzqA36rlEU-rSIUIwB-x], lookedUpEntriesTopology=2147483647, isMarkedForRollback=false, tx=GlobalTransaction:<perf18>:31071:remote, state=null}.
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.newTimeoutException(AbstractTxLockingInterceptor.java:217)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.waitForTransactionsToComplete(AbstractTxLockingInterceptor.java:209)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:173)
[JBossINF] 	at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitDataReadCommand(PessimisticLockingInterceptor.java:68)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitGetKeyValueCommand(AbstractLockingInterceptor.java:70)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:86)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:287)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:259)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:86)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:360)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.handleDefault(StateTransferInterceptor.java:345)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:86)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.CacheMgmtInterceptor.visitDataReadCommand(CacheMgmtInterceptor.java:103)
[JBossINF] 	at org.infinispan.interceptors.CacheMgmtInterceptor.visitGetKeyValueCommand(CacheMgmtInterceptor.java:91)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[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.visitGetKeyValueCommand(AbstractVisitor.java:86)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
[JBossINF] 	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
[JBossINF] 	at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:430)
[JBossINF] 	at org.infinispan.cache.impl.DecoratedCache.get(DecoratedCache.java:427)
[JBossINF] 	at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:287)
[JBossINF] 	at org.wildfly.clustering.web.infinispan.session.coarse.CoarseSessionFactory.findValue(CoarseSessionFactory.java:120)
[JBossINF] 	at org.wildfly.clustering.web.infinispan.session.coarse.CoarseSessionFactory.findValue(CoarseSessionFactory.java:56)
[JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager.schedule(InfinispanSessionManager.java:384)
[JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager.dataRehashed(InfinispanSessionManager.java:369)
[JBossINF] 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[JBossINF] 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[JBossINF] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[JBossINF] 	at java.lang.reflect.Method.invoke(Method.java:497)
[JBossINF] 	at org.infinispan.notifications.impl.AbstractListenerImpl$ListenerInvocationImpl$1.run(AbstractListenerImpl.java:286)
[JBossINF] 	at org.infinispan.util.concurrent.WithinThreadExecutor.execute(WithinThreadExecutor.java:22)
[JBossINF] 	at org.infinispan.notifications.impl.AbstractListenerImpl$ListenerInvocationImpl.invoke(AbstractListenerImpl.java:309)
[JBossINF] 	at org.infinispan.notifications.cachelistener.CacheNotifierImpl$BaseCacheEntryListenerInvocation.doRealInvocation(CacheNotifierImpl.java:1212)
[JBossINF] 	at org.infinispan.notifications.cachelistener.CacheNotifierImpl$BaseCacheEntryListenerInvocation.invoke(CacheNotifierImpl.java:1170)
[JBossINF] 	at org.infinispan.notifications.cachelistener.CacheNotifierImpl$BaseCacheEntryListenerInvocation.invoke(CacheNotifierImpl.java:1135)
[JBossINF] 	at org.infinispan.notifications.cachelistener.CacheNotifierImpl.notifyDataRehashed(CacheNotifierImpl.java:576)
[JBossINF] 	at org.infinispan.statetransfer.StateConsumerImpl.onTopologyUpdate(StateConsumerImpl.java:385)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferManagerImpl.doTopologyUpdate(StateTransferManagerImpl.java:200)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferManagerImpl.access$000(StateTransferManagerImpl.java:47)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferManagerImpl$1.updateConsistentHash(StateTransferManagerImpl.java:115)
[JBossINF] 	at org.infinispan.topology.LocalTopologyManagerImpl.doHandleTopologyUpdate(LocalTopologyManagerImpl.java:282)
[JBossINF] 	at org.infinispan.topology.LocalTopologyManagerImpl$1.run(LocalTopologyManagerImpl.java:217)
[JBossINF] 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[JBossINF] 	at org.infinispan.executors.SemaphoreCompletionService$QueueingTask.runInternal(SemaphoreCompletionService.java:173)
[JBossINF] 	at org.infinispan.executors.SemaphoreCompletionService$QueueingTask.run(SemaphoreCompletionService.java:151)
[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)

      This error may be the root cause of https://issues.jboss.org/browse/JBEAP-505 (server ends up with Operation ("deploy") failed when restarted after failover).

      The following error (and matching warning), occurring just before the above mentioned TimeoutException, is most likely also related:

       
[JBossINF] �[0m�[31m16:31:56,503 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread--p3-t41) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key perf21 and requestor GlobalTransaction:<perf21>:78599:remote. Lock is held by GlobalTransaction:<perf21>:78433:remote, while request came from perf21
[JBossINF] 	at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:198)
[JBossINF] 	at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:171)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:185)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:118)
[JBossINF] 	at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitLockControlCommand(PessimisticLockingInterceptor.java:200)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:174)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:141)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.visitLockControlCommand(TxInterceptor.java:199)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:174)
[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:97)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:196)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.visitLockControlCommand(StateTransferInterceptor.java:99)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:174)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[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:129)
[JBossINF] 	at org.infinispan.remoting.inboundhandler.BasePerCacheInboundInvocationHandler.invokePerform(BasePerCacheInboundInvocationHandler.java:85)
[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)
[JBossINF] 
[JBossINF] �[0m�[33m16:31:56,504 WARN  [org.infinispan.remoting.inboundhandler.NonTotalOrderPerCacheInboundInvocationHandler] (remote-thread--p3-t41) ISPN000071: Caught exception when handling command LockControlCommand{cache=dist, keys=[perf21], flags=[IGNORE_RETURN_VALUES], unlock=false, gtx=GlobalTransaction:<perf21>:78599:remote}: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key perf21 and requestor GlobalTransaction:<perf21>:78599:remote. Lock is held by GlobalTransaction:<perf21>:78433:remote, while request came from perf21
[JBossINF] 	at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:198)
[JBossINF] 	at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:171)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:185)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:118)
[JBossINF] 	at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitLockControlCommand(PessimisticLockingInterceptor.java:200)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:174)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:141)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.visitLockControlCommand(TxInterceptor.java:199)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:174)
[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:97)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:196)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.visitLockControlCommand(StateTransferInterceptor.java:99)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:174)
[JBossINF] 	at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)
[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:129)
[JBossINF] 	at org.infinispan.remoting.inboundhandler.BasePerCacheInboundInvocationHandler.invokePerform(BasePerCacheInboundInvocationHandler.java:85)
[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)

      Server log:
      http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-failover-http-session-shutdown-dist-sync/4/console-perf19/

      Attachments

        Issue Links

          causes

          Bug - A problem that impairs or prevents the functions of the product. WFLY-5009 TimeoutException: Could not acquire lock during server startup causes operation ("deploy") to fail

          • Critical - To be worked on immediately following BLOCKER issues.
          • Closed
          clones

          Bug - A problem that impairs or prevents the functions of the product. JBEAP-742 TimeoutException: Could not acquire lock: Waiting to complete tx

          • 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

          Activity

            People

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

              Dates

                Created:
                Updated:
                Resolved: