Loading...

Type: Bug
Resolution: Done
Priority: Critical
Fix Version/s: 10.0.0.CR3
Affects Version/s: 10.0.0.Alpha5, 10.0.0.Alpha6, 10.0.0.Beta1, 10.0.0.CR2
Component/s: Clustering
Labels:
None

Git Pull Request:
https://github.com/wildfly/wildfly/pull/8244

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/

clones

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

Closed

is caused by

WFLY-5128 TimeoutException: Could not acquire lock: Waiting to complete tx

Closed

WFLY-5186 TimeoutException: Unable to acquire lock after 15 seconds

Closed

Details

Description

Attachments

Issue Links

Easy Agile Planning Poker

Activity

People

Dates