[jboss-jira] [JBoss JIRA] (WFLY-5009) TimeoutException: Could not acquire lock during server startup causes operation ("deploy") to fail

TimeoutException: Could not acquire lock during server startup causes operation ("deploy") to fail -------------------------------------------------------------------------------------------------- Key: WFLY-5009 URL: https://issues.jboss.org/browse/WFLY-5009 Project: WildFly Issue Type: Bug Components: Clustering Affects Versions: 10.0.0.Alpha5, 10.0.0.Alpha6, 10.0.0.Beta1 Reporter: Michal Vinkler Assignee: Paul Ferraro Priority: Critical 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*: {code} [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}."}} {code} Server log (failover-ejb-ejbservlet-jvmkill-dist-sync): http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/mvinkler_eap-7x-failo... Server log (failover-ejb-ejbservlet-shutdown-dist-async): http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/mvinkler_eap-7x-failo...