[infinispan-issues] [JBoss JIRA] (ISPN-5245) org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock

Wed Feb 25 01:47:49 EST 2015

Alexandr Sokolov created ISPN-5245:
--------------------------------------

             Summary: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock
                 Key: ISPN-5245
                 URL: https://issues.jboss.org/browse/ISPN-5245
             Project: Infinispan
          Issue Type: Bug
    Affects Versions: 6.0.2.Final
         Environment: The Wildfly 8.2.0.Final application server,
Linux,
java -version
java version "1.8.0_25"
Java(TM) SE Runtime Environment (build 1.8.0_25-b17)
Java HotSpot(TM) 64-Bit Server VM (build 25.25-b02, mixed mode)
            Reporter: Alexandr Sokolov
            Priority: Critical

We get the following exception:
{code}
10:36:58,480 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-29) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [spuXxNa9Wehy5MaWTArHzWgO] for requestor [GlobalTransaction:<null>:8707:local]! Lock held by [GlobalTransaction:<null>:8695:local]
    at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:198) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:171) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:169) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitGetKeyValueCommand(PessimisticLockingInterceptor.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:74) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:226) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:221) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.CacheMgmtInterceptor.visitGetKeyValueCommand(CacheMgmtInterceptor.java:92) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:73) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:74) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:79) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:74) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:333) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.CacheImpl.get(CacheImpl.java:377) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.DecoratedCache.get(DecoratedCache.java:396) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.infinispan.AbstractDelegatingCache.get(AbstractDelegatingCache.java:271) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]
    at org.jboss.as.clustering.infinispan.invoker.Locator$FindOperation.invoke(Locator.java:54)
    at org.jboss.as.clustering.infinispan.invoker.Locator$LockingFindOperation.invoke(Locator.java:71)
    at org.jboss.as.clustering.infinispan.invoker.SimpleCacheInvoker.invoke(SimpleCacheInvoker.java:34)
    at org.jboss.as.clustering.infinispan.invoker.RetryingCacheInvoker.invoke(RetryingCacheInvoker.java:87)
    at org.wildfly.clustering.web.infinispan.session.coarse.CoarseSessionFactory.findValue(CoarseSessionFactory.java:109)
    at org.wildfly.clustering.web.infinispan.session.coarse.CoarseSessionFactory.findValue(CoarseSessionFactory.java:55)
    at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager.findSession(InfinispanSessionManager.java:148)
    at org.wildfly.clustering.web.undertow.session.DistributableSessionManager.getSession(DistributableSessionManager.java:115)
    at io.undertow.servlet.spec.ServletContextImpl.getSession(ServletContextImpl.java:688) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
    at io.undertow.servlet.spec.HttpServletRequestImpl.getSession(HttpServletRequestImpl.java:364) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
    at org.jboss.weld.servlet.SessionHolder.requestInitialized(SessionHolder.java:47) [weld-core-impl-2.2.6.Final.jar:2014-10-03 10:05]
    at org.jboss.weld.servlet.HttpContextLifecycle.requestInitialized(HttpContextLifecycle.java:212) [weld-core-impl-2.2.6.Final.jar:2014-10-03 10:05]
    at org.jboss.weld.servlet.WeldInitialListener.requestInitialized(WeldInitialListener.java:160) [weld-core-impl-2.2.6.Final.jar:2014-10-03 10:05]
    at io.undertow.servlet.core.ApplicationListeners.requestInitialized(ApplicationListeners.java:216) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
    at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:260) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
    at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:247) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
    at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:76) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
    at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:166) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
    at io.undertow.server.Connectors.executeRootHandler(Connectors.java:197) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
    at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:759) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_25]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_25]
    at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_25]
{/code}

I cannot say right now, how infinispan cache is used, to reproduce it.
We get it when we perform different actions on different pages. Maybe you have already met the same problem.

Is there a way to apply logging to infispan cache operations only? Like jdbc/hibernate logging. I've read documentation but could not find such option. 

--
This message was sent by Atlassian JIRA
(v6.3.11#6341)