TimeoutException: Response timed out errors with jboss/hiber

[pkorros]

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?

[pkorros]

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

[manik]

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

[pkorros]

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.