How to fix "Unable to acquire lock after 15 seconds" errors in Wildfly

Question

I have a web application that is <distributable/>, but also deployed to stand alone instances of Wildfly for local development work. Sometimes we have calls to the backend that can stall for a few seconds, which often leads to exceptions like the one shown below.

How can I fix this given that I have no control over long running backend requests?

14:55:04,808 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-6) ISPN000136: Error executing command LockControlCommand, writing keys []: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key LA6Q5r9L1q-VF2tyKE9Pc_bO9yYtzXu8dYt8l-BQ and requestor GlobalTransaction:<null>:37:local. Lock is held by GlobalTransaction:<null>:36:local
    at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
    at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
    at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
    at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
    at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitLockControlCommand(PessimisticLockingInterceptor.java:184)
    at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
    at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
    at org.infinispan.interceptors.TxInterceptor.visitLockControlCommand(TxInterceptor.java:215)
    at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
    at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
    at org.infinispan.interceptors.InvocationContextInterceptor.visitLockControlCommand(InvocationContextInterceptor.java:81)
    at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:110)
    at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
    at org.infinispan.cache.impl.CacheImpl.lock(CacheImpl.java:828)
    at org.infinispan.cache.impl.CacheImpl.lock(CacheImpl.java:810)
    at org.infinispan.cache.impl.AbstractDelegatingAdvancedCache.lock(AbstractDelegatingAdvancedCache.java:177)
    at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.getValue(InfinispanSessionMetaDataFactory.java:84)
    at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.findValue(InfinispanSessionMetaDataFactory.java:69)
    at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.findValue(InfinispanSessionMetaDataFactory.java:39)
    at org.wildfly.clustering.web.infinispan.session.InfinispanSessionFactory.findValue(InfinispanSessionFactory.java:61)
    at org.wildfly.clustering.web.infinispan.session.InfinispanSessionFactory.findValue(InfinispanSessionFactory.java:40)
    at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager.findSession(InfinispanSessionManager.java:234)
    at org.wildfly.clustering.web.undertow.session.DistributableSessionManager.getSession(DistributableSessionManager.java:140)
    at io.undertow.servlet.spec.ServletContextImpl.getSession(ServletContextImpl.java:726)
    at io.undertow.servlet.spec.HttpServletRequestImpl.getSession(HttpServletRequestImpl.java:370)
    at au.com.agic.settings.listener.SessionInvalidatorListener.clearSession(SessionInvalidatorListener.java:57)
    at au.com.agic.settings.listener.SessionInvalidatorListener.requestInitialized(SessionInvalidatorListener.java:52)
    at io.undertow.servlet.core.ApplicationListeners.requestInitialized(ApplicationListeners.java:245)
    at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:283)
    at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
    at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
    at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
    at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
    at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

Solution

I believe the answer is to update the infinispan configuration like this, which increases the lock timeout to 60 seconds.

<cache-container name="web" default-cache="passivation" module="org.wildfly.clustering.web.infinispan">
                <local-cache name="passivation">
                    <locking isolation="REPEATABLE_READ" striping="false" acquire-timeout="60000"/>
                    <transaction mode="BATCH"/>
                    <file-store passivation="true" purge="false"/>
                </local-cache>
                <local-cache name="persistent">
                    <locking isolation="REPEATABLE_READ" striping="false" acquire-timeout="60000"/>
                    <transaction mode="BATCH"/>
                    <file-store passivation="false" purge="false"/>
                </local-cache>
            </cache-container>

Comments

[Stijn de Witt]

I found that setting locking="OPTIMISTIC" on the <transaction mode="batch" /> element helps as well.

[garykwwong]

@Phyxx Could you help to explain why setting the timeout to 60 seconds could resolve the problem? what would happen when timeout after 60 seconds?

[thierryler]

I would think that increasing the timeout is a short term solution that will make the problem bigger finally

[Carlos Lacerda]

this maybe also can help access.redhat.com/solutions/2776221

[Aguid]

Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 60 seconds for key i369vnLfx8pZ9Oj5 and requestor CommandInvocation. It is not working for 60 seconds also :(