Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-505

TimeoutException: Could not acquire lock during server startup causes operation ("deploy") to fail

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Blocker
    • 7.0.0.DR13 (Alpha)
    • 7.0.0.DR5, 7.0.0.DR6, 7.0.0.DR8, 7.0.0.DR9, 7.0.0.DR11
    • Clustering
    • None

    Description

      Seen regularly in these scenarios of failover tests:
      ejb-ejbservlet-jvmkill-dist-sync
      ejb-ejbservlet-shutdown-dist-async

      The error is present in EAP 7.0.0.DR5, EAP 7.0.0.DR6. We did not see it in EAP 7.0.0.DR4.

      This error happens every time for the specified scenarios and is seen on one of the nodes in a 4-nodes cluster - usually it is the second node to fail, perf19.

      When the affected server is restarting after failover, it logs these error messages, ending up with Operation ("deploy") failed:

      [JBossINF] [0m[0m03:49:26,594 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 64) WFLYCLINF0002: Started clusterbench-ee7.ear.clusterbench-ee7-web-passivating.war cache from web container
      [JBossINF] [0m[0m03:49:26,666 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 62) WFLYCLINF0002: Started clusterbench-ee7.ear.clusterbench-ee7-web-default.war cache from web container
      [JBossINF] [0m[0m03:49:26,667 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 63) WFLYCLINF0002: Started dist cache from web container
      [JBossINF] [0m[0m03:49:27,364 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 65) WFLYCLINF0002: Started dist cache from ejb container
      [JBossINF] [0m[0m03:49:27,409 INFO  [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (ServerService Thread Pool -- 65) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
      [JBossINF] [0m[0m03:49:27,410 INFO  [org.infinispan.configuration.cache.EvictionConfigurationBuilder] (ServerService Thread Pool -- 65) ISPN000152: Passivation configured without an eviction policy being selected. Only manually evicted entities will be passivated.
      [JBossINF] [0m[0m03:49:27,487 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 65) WFLYCLINF0002: Started clusterbench-ee7.ear/clusterbench-ee7-ejb.jar cache from ejb container
      [JBossINF] [0m[0m03:49:28,506 INFO  [javax.enterprise.resource.webcontainer.jsf.config] (ServerService Thread Pool -- 67) Initializing Mojarra 2.2.11-jbossorg-1 20150505-1501 for context '/clusterbench'
      [JBossINF] [0m[0m03:49:28,506 INFO  [javax.enterprise.resource.webcontainer.jsf.config] (ServerService Thread Pool -- 69) Initializing Mojarra 2.2.11-jbossorg-1 20150505-1501 for context '/clusterbench-passivating'
      [JBossINF] [0m[0m03:49:29,435 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 69) WFLYUT0021: Registered web context: /clusterbench-passivating
      [JBossINF] [0m[31m03:49:44,489 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (ServerService Thread Pool -- 67) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Could not acquire lock on 1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF on behalf of transaction GlobalTransaction:<perf19>:203:local. Waiting to complete tx: RemoteTransaction{modifications=[ReplaceCommand{key=1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF, oldValue=null, newValue=[B@2b5a5fb2, metadata=EmbeddedMetadata{version=null}, flags=[IGNORE_RETURN_VALUES], successful=true, valueMatcher=MATCH_ALWAYS}], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=[1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF], lookedUpEntriesTopology=15, isMarkedForRollback=false, tx=GlobalTransaction:<perf21>:3605:remote, state=null}.
      [JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.newTimeoutException(AbstractTxLockingInterceptor.java:219)
      [JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.waitForTransactionsToComplete(AbstractTxLockingInterceptor.java:207)
      [JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:171)
      [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:346)
      [JBossINF] 	at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:318)
      [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:364)
      [JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.handleDefault(StateTransferInterceptor.java:349)
      [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:363)
      [JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager.start(InfinispanSessionManager.java:156)
      [JBossINF] 	at org.wildfly.clustering.web.undertow.session.DistributableSessionManager.start(DistributableSessionManager.java:69)
      [JBossINF] 	at io.undertow.servlet.core.DeploymentManagerImpl.start(DeploymentManagerImpl.java:485)
      [JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService.startContext(UndertowDeploymentService.java:101)
      [JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:82)
      [JBossINF] 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      [JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      [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] 	at org.jboss.threads.JBossThread.run(JBossThread.java:320)
      [JBossINF] 
      [JBossINF] [0m[31m03:49:44,492 ERROR [org.jboss.msc.service.fail] (ServerService Thread Pool -- 67) MSC000001: Failed to start service jboss.undertow.deployment.default-server.default-host./clusterbench: org.jboss.msc.service.StartException in service jboss.undertow.deployment.default-server.default-host./clusterbench: org.infinispan.util.concurrent.TimeoutException: Could not acquire lock on 1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF on behalf of transaction GlobalTransaction:<perf19>:203:local. Waiting to complete tx: RemoteTransaction{modifications=[ReplaceCommand{key=1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF, oldValue=null, newValue=[B@2b5a5fb2, metadata=EmbeddedMetadata{version=null}, flags=[IGNORE_RETURN_VALUES], successful=true, valueMatcher=MATCH_ALWAYS}], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=[1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF], lookedUpEntriesTopology=15, isMarkedForRollback=false, tx=GlobalTransaction:<perf21>:3605:remote, state=null}.
      [JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:85)
      [JBossINF] 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      [JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      [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] 	at org.jboss.threads.JBossThread.run(JBossThread.java:320)
      [JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: Could not acquire lock on 1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF on behalf of transaction GlobalTransaction:<perf19>:203:local. Waiting to complete tx: RemoteTransaction{modifications=[ReplaceCommand{key=1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF, oldValue=null, newValue=[B@2b5a5fb2, metadata=EmbeddedMetadata{version=null}, flags=[IGNORE_RETURN_VALUES], successful=true, valueMatcher=MATCH_ALWAYS}], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=[1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF], lookedUpEntriesTopology=15, isMarkedForRollback=false, tx=GlobalTransaction:<perf21>:3605:remote, state=null}.
      [JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.newTimeoutException(AbstractTxLockingInterceptor.java:219)
      [JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.waitForTransactionsToComplete(AbstractTxLockingInterceptor.java:207)
      [JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:171)
      [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:346)
      [JBossINF] 	at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:318)
      [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:364)
      [JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.handleDefault(StateTransferInterceptor.java:349)
      [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:363)
      [JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager.start(InfinispanSessionManager.java:156)
      [JBossINF] 	at org.wildfly.clustering.web.undertow.session.DistributableSessionManager.start(DistributableSessionManager.java:69)
      [JBossINF] 	at io.undertow.servlet.core.DeploymentManagerImpl.start(DeploymentManagerImpl.java:485)
      [JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService.startContext(UndertowDeploymentService.java:101)
      [JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:82)
      [JBossINF] 	... 6 more
      [JBossINF] 
      [JBossINF] [0m[31m03:49:44,503 ERROR [org.jboss.as.controller.management-operation] (Controller Boot Thread) WFLYCTL0013: Operation ("deploy") failed - address: ([("deployment" => "clusterbench-ee7.ear")]) - failure description: {"WFLYCTL0080: Failed services" => {"jboss.undertow.deployment.default-server.default-host./clusterbench" => "org.jboss.msc.service.StartException in service jboss.undertow.deployment.default-server.default-host./clusterbench: org.infinispan.util.concurrent.TimeoutException: Could not acquire lock on 1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF on behalf of transaction GlobalTransaction:<perf19>:203:local. Waiting to complete tx: RemoteTransaction{modifications=[ReplaceCommand{key=1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF, oldValue=null, newValue=[B@2b5a5fb2, metadata=EmbeddedMetadata{version=null}, flags=[IGNORE_RETURN_VALUES], successful=true, valueMatcher=MATCH_ALWAYS}], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=[1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF], lookedUpEntriesTopology=15, isMarkedForRollback=false, tx=GlobalTransaction:<perf21>:3605:remote, state=null}.
      [JBossINF]     Caused by: org.infinispan.util.concurrent.TimeoutException: Could not acquire lock on 1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF on behalf of transaction GlobalTransaction:<perf19>:203:local. Waiting to complete tx: RemoteTransaction{modifications=[ReplaceCommand{key=1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF, oldValue=null, newValue=[B@2b5a5fb2, metadata=EmbeddedMetadata{version=null}, flags=[IGNORE_RETURN_VALUES], successful=true, valueMatcher=MATCH_ALWAYS}], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=[1tlWOZAPqztbiLjjrJHTL_6OK7fRTPBhVvyB4BLF], lookedUpEntriesTopology=15, isMarkedForRollback=false, tx=GlobalTransaction:<perf21>:3605:remote, state=null}."}}
      

      Server log (failover-ejb-ejbservlet-jvmkill-dist-sync):
      http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/mvinkler_eap-7x-failover-ejb-ejbservlet-jvmkill-dist-sync/1/console-perf19/

      Server log (failover-ejb-ejbservlet-shutdown-dist-async):
      http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/mvinkler_eap-7x-failover-ejb-ejbservlet-shutdown-dist-async/1/console-perf20/

      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: