3 Replies Latest reply on Nov 20, 2006 5:01 AM by Panagiotis Korros

    TimeoutException: Response timed out errors with jboss/hiber

    Panagiotis Korros Newbie

      I am using hibernate 3.2.GA, JBoss Cache 1.4.0sp1 configured with pessimistic locking.

      I am getting errors like the following upon transaction completion.

      16:50:46,984 ERROR [StdServerSession] failed to commit/rollback
      org.jboss.tm.JBossRollbackException: Unable to commit, tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=pkor/28, BranchQual=, localId=28] status=STATUS_NO_TRANSACTION; - nested throwable: (java.lang.RuntimeException: )
      at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:372)
      at org.jboss.tm.TxManager.commit(TxManager.java:240)
      at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:351)
      at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:905)
      at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:170)
      at org.jboss.mq.SpySession.run(SpySession.java:323)
      at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:194)
      at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748)
      at java.lang.Thread.run(Thread.java:595)
      Caused by: java.lang.RuntimeException:
      at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1091)
      at org.jboss.cache.interceptors.OrderedSynchronizationHandler.beforeCompletion(OrderedSynchronizationHandler.java:75)
      at org.jboss.tm.TransactionImpl.doBeforeCompletion(TransactionImpl.java:1491)
      at org.jboss.tm.TransactionImpl.beforePrepare(TransactionImpl.java:1110)
      at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:324)
      ... 8 more
      Caused by: org.jboss.cache.ReplicationException: rsp=sender=192.168.1.157:2483, retval=null, received=false, suspected=false
      at org.jboss.cache.TreeCache.callRemoteMethods(TreeCache.java:4191)
      at org.jboss.cache.TreeCache.callRemoteMethods(TreeCache.java:4114)
      at org.jboss.cache.TreeCache.callRemoteMethods(TreeCache.java:4215)
      at org.jboss.cache.interceptors.BaseRpcInterceptor.replicateCall(BaseRpcInterceptor.java:110)
      at org.jboss.cache.interceptors.BaseRpcInterceptor.replicateCall(BaseRpcInterceptor.java:88)
      at org.jboss.cache.interceptors.ReplicationInterceptor.runPreparePhase(ReplicationInterceptor.java:147)
      at org.jboss.cache.interceptors.ReplicationInterceptor.invoke(ReplicationInterceptor.java:64)
      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
      at org.jboss.cache.interceptors.TxInterceptor.runPreparePhase(TxInterceptor.java:804)
      at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1069)
      ... 12 more
      Caused by: org.jboss.cache.lock.TimeoutException: Response timed out: sender=192.168.1.157:2483, retval=null, received=false, suspected=false
      at org.jboss.cache.TreeCache.callRemoteMethods(TreeCache.java:4189)
      ... 21 more

      Any ideas on what causes this?

        • 1. Re: TimeoutException: Response timed out errors with jboss/h
          Panagiotis Korros Newbie

          This is happening only when I have two jboss nodes in the cluster. With only one node everything works as expected.

          • 2. Re: TimeoutException: Response timed out errors with jboss/h
            Manik Surtani Master

            Could you try 1.4.1.BETA? A bunch of things related to hibernate interop were fixed in this release.

            http://labs.jboss.com/portal/jbosscache/download/index.html

            • 3. Re: TimeoutException: Response timed out errors with jboss/h
              Panagiotis Korros Newbie

              In my test scenario JBoss Cache 1.4.1.BETA seems to work much better than 1.4.0.SP1.

              The test scenario is to repeat a specific request 60 times. Previously my test scenario didn't work at all. The server was being locked on the first request and I had to leave only 1 active node for the test to continue.
              The errors were like this:
              Caused by: org.jboss.cache.lock.TimeoutException: Response timed out: sender=192.168.1.157:2483, retval=null, received=false, suspected=false
              at org.jboss.cache.TreeCache.callRemoteMethods(TreeCache.java:4189)

              Now I am getting some errors but the test continues and the system manages to complete 54 out of 60 requests successfully.

              I get 6 errors like this:
              2006-11-20 10:36:02,883 ERROR [org.jboss.cache.lock.IdentityLock] (UpHandler (STATE_TRANSFER)) write lock for /com/oakgrovesystems/reactor/processMediation/hibernate/HibProcess/currentStatuses/com.oakgrovesystems.reactor.processMediation.hibernate.HibProcess.currentStatuses#165199 could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<192.168.1.147:1270>:1153]
              Write lock owner: null
              (caller=Thread[UpHandler (STATE_TRANSFER),5,JGroups threads], lock info: read owners=[GlobalTransaction:<192.168.1.147:1270>:1153] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
              2006-11-20 10:36:02,898 INFO [org.jboss.cache.interceptors.TxInterceptor] (UpHandler (STATE_TRANSFER)) There was a problem handling this request
              org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/com/oakgrovesystems/reactor/processMediation/hibernate/HibProcess/currentStatuses/com.oakgrovesystems.reactor.processMediation.hibernate.HibProcess.currentStatuses#165199, caller=Thread[UpHandler (STATE_TRANSFER),5,JGroups threads], lock=read owners=[GlobalTransaction:<192.168.1.147:1270>:1153] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
              at org.jboss.cache.Node.acquire(Node.java:475)
              at org.jboss.cache.interceptors.PessimisticLockInterceptor.lock(PessimisticLockInterceptor.java:244)
              at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:168)
              at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
              at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:32)
              at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
              at org.jboss.cache.interceptors.ReplicationInterceptor.invoke(ReplicationInterceptor.java:39)
              at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
              at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:364)
              at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:160)
              at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
              at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:157)
              at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:5611)
              at org.jboss.cache.TreeCache._replicate(TreeCache.java:4957)
              at sun.reflect.GeneratedMethodAccessor337.invoke(Unknown Source)
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
              at java.lang.reflect.Method.invoke(Method.java:585)
              at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:330)
              at org.jgroups.blocks.RpcDispatcher.handle(RpcDispatcher.java:267)
              at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:623)
              at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:508)
              at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:331)
              at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:769)
              at org.jgroups.JChannel.up(JChannel.java:1091)
              at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:377)
              at org.jgroups.stack.ProtocolStack.receiveUpEvent(ProtocolStack.java:393)
              at org.jgroups.stack.Protocol.passUp(Protocol.java:538)
              at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:162)
              at org.jgroups.stack.UpHandler.run(Protocol.java:60)
              Caused by: org.jboss.cache.lock.TimeoutException: write lock for /com/oakgrovesystems/reactor/processMediation/hibernate/HibProcess/currentStatuses/com.oakgrovesystems.reactor.processMediation.hibernate.HibProcess.currentStatuses#165199 could not be acquired after 0 ms. Locks: Read lock owners: [GlobalTransaction:<192.168.1.147:1270>:1153]
              Write lock owner: null
              (caller=Thread[UpHandler (STATE_TRANSFER),5,JGroups threads], lock info: read owners=[GlobalTransaction:<192.168.1.147:1270>:1153] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
              at org.jboss.cache.lock.IdentityLock.acquireWriteLock(IdentityLock.java:202)
              at org.jboss.cache.Node.acquireWriteLock(Node.java:504)
              at org.jboss.cache.Node.acquire(Node.java:451)
              ... 28 more


              Notice that by using another (commercial) replicated cache I manage to successfully complete all 60 requests.