[jboss-jira] [JBoss JIRA] (WFLY-5009) TimeoutException: Could not acquire lock during server startup causes operation ("deploy") to fail
Michal Vinkler (JIRA)
issues at jboss.org
Mon Jul 27 05:03:03 EDT 2015
Michal Vinkler created WFLY-5009:
------------------------------------
Summary: 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
Reporter: Michal Vinkler
Assignee: Paul Ferraro
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 at 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 at 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 at 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 at 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 at 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-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/
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
More information about the jboss-jira
mailing list