LockTimeoutException
Hi!
We set up a cluster of two JBoss/Tomcat Nodes (4.0.1sp1) and regularly there's the following exception in our log files:
06:49:37,340 ERROR [IdentityLock] read lock for /JSESSION//Qxf+cksX3P2Y2BFZvkYGhw** could not be acquired after 15000 ms. Lock map ownership Read lock
owners: []
Write lock owner: <trial-1:32860>:105
(caller=Thread[TP-Processor7,5,jboss])
06:49:37,341 INFO [STDOUT] org.jboss.cache.lock.TimeoutException: lock for /JSESSION//Qxf+cksX3P2Y2BFZvkYGhw** could not be acquired after 15000ms. L
ock map ownership Read lock owners: []
Write lock owner: <trial-1:32860>:105
06:49:37,342 INFO [STDOUT] at org.jboss.cache.lock.IdentityLock.acquireReadLock(IdentityLock.java:227)
06:49:37,342 INFO [STDOUT] at org.jboss.cache.Node.acquireReadLock(Node.java:418)
06:49:37,342 INFO [STDOUT] at org.jboss.cache.Node.acquire(Node.java:399)
06:49:37,342 INFO [STDOUT] at org.jboss.cache.interceptors.LockInterceptor.lock(LockInterceptor.java:187)
06:49:37,342 INFO [STDOUT] at org.jboss.cache.interceptors.LockInterceptor.invoke(LockInterceptor.java:134)
06:49:37,342 INFO [STDOUT] at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:40)
06:49:37,342 INFO [STDOUT] at org.jboss.cache.interceptors.CreateIfNotExistsInterceptor.invoke(CreateIfNotExistsInterceptor.java:47)
06:49:37,343 INFO [STDOUT] at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:40)
06:49:37,343 INFO [STDOUT] at org.jboss.cache.interceptors.ReplicationInterceptor.invoke(ReplicationInterceptor.java:51)
06:49:37,343 INFO [STDOUT] at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:3132)
06:49:37,343 INFO [STDOUT] at org.jboss.cache.TreeCache.get(TreeCache.java:1664)
06:49:37,343 INFO [STDOUT] at org.jboss.cache.TreeCache.get(TreeCache.java:1648)
06:49:37,343 INFO [STDOUT] at sun.reflect.GeneratedMethodAccessor95.invoke(Unknown Source)
06:49:37,343 INFO [STDOUT] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
06:49:37,343 INFO [STDOUT] at java.lang.reflect.Method.invoke(Method.java:324)
06:49:37,343 INFO [STDOUT] at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:144)
06:49:37,343 INFO [STDOUT] at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80)
06:49:37,343 INFO [STDOUT] at org.jboss.mx.server.Invocation.invoke(Invocation.java:72)
06:49:37,344 INFO [STDOUT] at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:249)
06:49:37,344 INFO [STDOUT] at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:642)
06:49:37,344 INFO [STDOUT] at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:177)
06:49:37,344 INFO [STDOUT] at $Proxy48.get(Unknown Source)
06:49:37,344 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheService._get(JBossCacheService.java:304)
06:49:37,344 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheService.nodeDirty(JBossCacheService.java:576)
06:49:37,344 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheService.nodeModified(JBossCacheService.java:570)
06:49:37,344 INFO [STDOUT] at org.jboss.cache.TreeCache.notifyNodeModified(TreeCache.java:3203)
06:49:37,344 INFO [STDOUT] at org.jboss.cache.TreeCache._put(TreeCache.java:2442)
06:49:37,344 INFO [STDOUT] at sun.reflect.GeneratedMethodAccessor98.invoke(Unknown Source)
06:49:37,344 INFO [STDOUT] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
06:49:37,344 INFO [STDOUT] at java.lang.reflect.Method.invoke(Method.java:324)
06:49:37,345 INFO [STDOUT] at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:236)
06:49:37,345 INFO [STDOUT] at org.jboss.cache.interceptors.LockInterceptor.rollback(LockInterceptor.java:285)
06:49:37,345 INFO [STDOUT] at org.jboss.cache.interceptors.LockInterceptor.access$200(LockInterceptor.java:23)
06:49:37,345 INFO [STDOUT] at org.jboss.cache.interceptors.LockInterceptor$SynchronizationHandler.afterCompletion(LockInterceptor.java:366)
06:49:37,345 INFO [STDOUT] at org.jboss.cache.interceptors.OrderedSynchronizationHandler.afterCompletion(OrderedSynchronizationHandler.java:79)
06:49:37,345 INFO [STDOUT] at org.jboss.tm.TransactionImpl.doAfterCompletion(TransactionImpl.java:1418)
06:49:37,345 INFO [STDOUT] at org.jboss.tm.TransactionImpl.completeTransaction(TransactionImpl.java:1090)
06:49:37,345 INFO [STDOUT] at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:341)
06:49:37,345 INFO [STDOUT] at org.jboss.tm.TxManager.commit(TxManager.java:200)
06:49:37,345 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheManager.processSessionRepl(JBossCacheManager.java:466)
06:49:37,345 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheManager.storeSession(JBossCacheManager.java:248)
06:49:37,346 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:37)
06:49:37,346 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91)
06:49:37,346 INFO [STDOUT] at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
06:49:37,346 INFO [STDOUT] at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:54)
06:49:37,346 INFO [STDOUT] at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
06:49:37,346 INFO [STDOUT] at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
06:49:37,346 INFO [STDOUT] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
06:49:37,346 INFO [STDOUT] at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
06:49:37,346 INFO [STDOUT] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:118)
06:49:37,346 INFO [STDOUT] at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
06:49:37,347 INFO [STDOUT] at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
06:49:37,347 INFO [STDOUT] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
06:49:37,347 INFO [STDOUT] at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
06:49:37,347 INFO [STDOUT] at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
06:49:37,347 INFO [STDOUT] at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:929)
06:49:37,347 INFO [STDOUT] at org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:160)
06:49:37,347 INFO [STDOUT] at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:300)
06:49:37,347 INFO [STDOUT] at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:374)
06:49:37,347 INFO [STDOUT] at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:743)
06:49:37,347 INFO [STDOUT] at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:675)
06:49:37,347 INFO [STDOUT] at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:866)
06:49:37,348 INFO [STDOUT] at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
06:49:37,348 INFO [STDOUT] at java.lang.Thread.run(Thread.java:534)
The strange thing is that the node itself is trial-1:32860 and there's only this one active session on the whole cluster.
Has anyone an idea how to solve the problem?
Thanks in advance!
Dirk
