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

TimeoutException: Could not acquire lock: Waiting to complete tx

    XMLWordPrintable

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Done
    • 10.0.0.Alpha6, 10.0.0.Beta1, 10.0.0.CR2
    • 11.0.0.Alpha1
    • 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

          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: