1 Reply Latest reply on Mar 2, 2005 9:41 AM by Ben Wang

    LockTimeoutException

    Dirk Müller Newbie

      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