8 Replies Latest reply on Jan 29, 2011 11:58 AM by sannegrinovero

    InfinispanDirectory: Timeout while merging indexes

    nadirx

      Dear all (Sanne in particular ),

       

      using InfinispanDirectory I am getting Timeout Exceptions during the index merges. At the bottom of this post I have pasted an excerpt of the exception. I have since switched to using STREAMING_STATE_TRANSFER instead of STATE_TRANSFER, but I don't know if this would make a difference.

       

      Please note that this is with a single Infinispan node with only one IndexWriter.

       

      Thanks for any help you may be able to provide.

       

      Tristan

       

      2010-11-24 13:18:32,770 INFO  [STDOUT] (http-0.0.0.0-8080-8) 20101124 131832 WARN  [Persistence] (http-0.0.0.0-8080-8) getBean conn time  of (in nanos) : 150349804000
      2010-11-24 13:18:50,590 INFO  [STDOUT] (Lucene Merge Thread #423) 20101124 131850 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (Lucene Merge Thread #423) Execution error:
      org.infinispan.util.concurrent.TimeoutException: Replication timeout for innrab03-7151
         at org.infinispan.remoting.transport.AbstractTransport.parseResponseAndAddToResponseList(AbstractTransport.java:49)
         at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:418)
         at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:101)
         at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:125)
         at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:230)
         at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:217)
         at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:213)
         at org.infinispan.interceptors.DistributionInterceptor.visitPrepareCommand(DistributionInterceptor.java:268)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.LockingInterceptor.visitPrepareCommand(LockingInterceptor.java:114)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.CacheStoreInterceptor.visitPrepareCommand(CacheStoreInterceptor.java:177)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
         at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:48)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:91)
         at org.infinispan.interceptors.DistTxInterceptor.visitPrepareCommand(DistTxInterceptor.java:59)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:87)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:58)
         at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76)
         at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
         at org.infinispan.transaction.xa.TransactionXaAdapter.prepare(TransactionXaAdapter.java:96)
         at org.infinispan.transaction.tm.DummyTransaction.runPrepare(DummyTransaction.java:255)
         at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:82)
         at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:96)
         at org.infinispan.batch.BatchContainer.resolveTransaction(BatchContainer.java:130)
         at org.infinispan.batch.BatchContainer.endBatch(BatchContainer.java:107)
         at org.infinispan.batch.BatchContainer.endBatch(BatchContainer.java:92)
         at org.infinispan.CacheDelegate.endBatch(CacheDelegate.java:389)
         at org.infinispan.lucene.InfinispanIndexOutput.storeCurrentBuffer(InfinispanIndexOutput.java:172)
         at org.infinispan.lucene.InfinispanIndexOutput.close(InfinispanIndexOutput.java:190)
         at org.apache.lucene.index.FormatPostingsPositionsWriter.close(FormatPostingsPositionsWriter.java:87)
         at org.apache.lucene.index.FormatPostingsDocsWriter.close(FormatPostingsDocsWriter.java:127)
         at org.apache.lucene.index.FormatPostingsTermsWriter.close(FormatPostingsTermsWriter.java:71)
         at org.apache.lucene.index.FormatPostingsFieldsWriter.finish(FormatPostingsFieldsWriter.java:73)
         at org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:570)
         at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:154)
         at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4359)
         at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3965)
         at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:231)
         at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:288)
      2010-11-24 13:18:50,614 INFO  [STDOUT] (Lucene Merge Thread #423) 20101124 131850 ERROR [org.infinispan.transaction.xa.TransactionXaAdapter] (Lucene Merge Thread #423) Error while processing PrepareCommand
      org.infinispan.util.concurrent.TimeoutException: Replication timeout for innrab03-7151
         at org.infinispan.remoting.transport.AbstractTransport.parseResponseAndAddToResponseList(AbstractTransport.java:49)
         at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:418)
         at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:101)
         at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:125)
         at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:230)
         at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:217)
         at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:213)
         at org.infinispan.interceptors.DistributionInterceptor.visitPrepareCommand(DistributionInterceptor.java:268)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.LockingInterceptor.visitPrepareCommand(LockingInterceptor.java:114)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.CacheStoreInterceptor.visitPrepareCommand(CacheStoreInterceptor.java:177)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
         at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:48)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:91)
         at org.infinispan.interceptors.DistTxInterceptor.visitPrepareCommand(DistTxInterceptor.java:59)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:87)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:58)
         at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76)
         at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
         at org.infinispan.transaction.xa.TransactionXaAdapter.prepare(TransactionXaAdapter.java:96)
         at org.infinispan.transaction.tm.DummyTransaction.runPrepare(DummyTransaction.java:255)
         at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:82)
         at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:96)
         at org.infinispan.batch.BatchContainer.resolveTransaction(BatchContainer.java:130)
         at org.infinispan.batch.BatchContainer.endBatch(BatchContainer.java:107)
         at org.infinispan.batch.BatchContainer.endBatch(BatchContainer.java:92)
         at org.infinispan.CacheDelegate.endBatch(CacheDelegate.java:389)
         at org.infinispan.lucene.InfinispanIndexOutput.storeCurrentBuffer(InfinispanIndexOutput.java:172)
         at org.infinispan.lucene.InfinispanIndexOutput.close(InfinispanIndexOutput.java:190)
         at org.apache.lucene.index.FormatPostingsPositionsWriter.close(FormatPostingsPositionsWriter.java:87)
         at org.apache.lucene.index.FormatPostingsDocsWriter.close(FormatPostingsDocsWriter.java:127)
         at org.apache.lucene.index.FormatPostingsTermsWriter.close(FormatPostingsTermsWriter.java:71)
         at org.apache.lucene.index.FormatPostingsFieldsWriter.finish(FormatPostingsFieldsWriter.java:73)
         at org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:570)
         at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:154)
         at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4359)
         at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3965)
         at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:231)
         at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:288)
      2010-11-24 13:19:21,998 INFO  [STDOUT] (Lucene Merge Thread #423) 20101124 131921 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (Lucene Merge Thread #423) Execution error:
      org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [_3sz.prx|M|METACONTENT] for requestor [Thread[OOB-77,ngs-infinispan-preprod_3,innrab03-7151,5,Thread Pools]]! Lock held by [GlobalTransaction:<innrab06-20774>:57039:remote]
         at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:218)
         at org.infinispan.interceptors.CacheLoaderInterceptor.loadIfNeeded(CacheLoaderInterceptor.java:132)
         at org.infinispan.interceptors.CacheLoaderInterceptor.loadIfNeededAndUpdateStats(CacheLoaderInterceptor.java:217)
         at org.infinispan.interceptors.CacheLoaderInterceptor.visitRemoveCommand(CacheLoaderInterceptor.java:109)
         at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
         at org.infinispan.commands.AbstractVisitor.visitRemoveCommand(AbstractVisitor.java:61)
         at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:172)
         at org.infinispan.interceptors.TxInterceptor.visitRemoveCommand(TxInterceptor.java:125)
         at org.infinispan.interceptors.DistTxInterceptor.visitRemoveCommand(DistTxInterceptor.java:83)
         at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:87)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:58)
         at org.infinispan.commands.AbstractVisitor.visitRemoveCommand(AbstractVisitor.java:61)
         at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:60)
         at org.infinispan.commands.AbstractVisitor.visitRemoveCommand(AbstractVisitor.java:61)
         at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
         at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
         at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:42)
         at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:44)
         at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:94)
         at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:176)
         at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:148)
         at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
         at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
         at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
         at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
         at org.jgroups.JChannel.up(JChannel.java:1453)
         at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
         at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
         at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
         at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
         at org.jgroups.protocols.FC.up(FC.java:494)
         at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
         at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
         at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
         at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
         at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
         at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
         at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
         at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
         at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
         at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
         at org.jgroups.protocols.Discovery.up(Discovery.java:283)
         at org.jgroups.protocols.PING.up(PING.java:67)
         at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
         at org.jgroups.protocols.TP.access$100(TP.java:56)
         at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
         at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
         at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
         at java.lang.Thread.run(Thread.java:619)
      2010-11-24 13:19:22,293 ERROR [STDERR] (Lucene Merge Thread #423) Exception in thread "Lucene Merge Thread #423"
      2010-11-24 13:19:22,293 ERROR [STDERR] (Lucene Merge Thread #423) org.apache.lucene.index.MergePolicy$MergeException: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [_3sz.prx|M|METACONTENT] for requestor [Thread[OOB-77,ngs-infinispan-preprod_3,innrab03-7151,5,Thread Pools]]! Lock held by [GlobalTransaction:<innrab06-20774>:57039:remote]
      2010-11-24 13:19:22,293 ERROR [STDERR] (Lucene Merge Thread #423)     at org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:347)
      2010-11-24 13:19:22,293 ERROR [STDERR] (Lucene Merge Thread #423)     at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:312)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423) Caused by: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [_3sz.prx|M|METACONTENT] for requestor [Thread[OOB-77,ngs-infinispan-preprod_3,innrab03-7151,5,Thread Pools]]! Lock held by [GlobalTransaction:<innrab06-20774>:57039:remote]
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:218)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.CacheLoaderInterceptor.loadIfNeeded(CacheLoaderInterceptor.java:132)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.CacheLoaderInterceptor.loadIfNeededAndUpdateStats(CacheLoaderInterceptor.java:217)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.CacheLoaderInterceptor.visitRemoveCommand(CacheLoaderInterceptor.java:109)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.commands.AbstractVisitor.visitRemoveCommand(AbstractVisitor.java:61)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:172)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.TxInterceptor.visitRemoveCommand(TxInterceptor.java:125)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.DistTxInterceptor.visitRemoveCommand(DistTxInterceptor.java:83)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:87)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:58)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.commands.AbstractVisitor.visitRemoveCommand(AbstractVisitor.java:61)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
      2010-11-24 13:19:22,294 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:60)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.commands.AbstractVisitor.visitRemoveCommand(AbstractVisitor.java:61)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:42)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:44)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:94)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:176)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:148)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.JChannel.up(JChannel.java:1453)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.FC.up(FC.java:494)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.Discovery.up(Discovery.java:283)
      2010-11-24 13:19:22,295 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.PING.up(PING.java:67)
      2010-11-24 13:19:22,296 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
      2010-11-24 13:19:22,296 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.TP.access$100(TP.java:56)
      2010-11-24 13:19:22,296 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
      2010-11-24 13:19:22,296 ERROR [STDERR] (Lucene Merge Thread #423)     at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
      2010-11-24 13:19:22,296 ERROR [STDERR] (Lucene Merge Thread #423)     at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      2010-11-24 13:19:22,296 ERROR [STDERR] (Lucene Merge Thread #423)     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      2010-11-24 13:19:22,296 ERROR [STDERR] (Lucene Merge Thread #423)     at java.lang.Thread.run(Thread.java:619)
      2010-11-24 13:19:39,102 INFO  [STDOUT] (http-0.0.0.0-8080-8) 20101124 131939 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (http-0.0.0.0-8080-8) Execution error:
      org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [*|METACONTENT] for requestor [GlobalTransaction:<innrab06-20774>:57040:remote]! Lock held by [GlobalTransaction:<innrab06-20774>:57039:remote]
         at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:218)
         at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:121)
         at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:106)
         at org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:245)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.DistCacheStoreInterceptor.visitPutKeyValueCommand(DistCacheStoreInterceptor.java:77)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.CacheLoaderInterceptor.visitPutKeyValueCommand(CacheLoaderInterceptor.java:81)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
         at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:82)
         at org.infinispan.interceptors.DistTxInterceptor.visitPrepareCommand(DistTxInterceptor.java:59)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:87)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:58)
         at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:60)
         at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
         at org.infinispan.commands.tx.PrepareCommand.perform(PrepareCommand.java:111)
         at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:94)
         at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:176)
         at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:148)
         at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
         at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
         at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
         at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
         at org.jgroups.JChannel.up(JChannel.java:1453)
         at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
         at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
         at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
         at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
         at org.jgroups.protocols.FC.up(FC.java:494)
         at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
         at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
         at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
         at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
         at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
         at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
         at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
         at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
         at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
         at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
         at org.jgroups.protocols.Discovery.up(Discovery.java:283)
         at org.jgroups.protocols.PING.up(PING.java:67)
         at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
         at org.jgroups.protocols.TP.access$100(TP.java:56)
         at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
         at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
         at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
         at java.lang.Thread.run(Thread.java:619)
      2010-11-24 13:19:39,183 INFO  [STDOUT] (http-0.0.0.0-8080-8) 20101124 131939 ERROR [org.infinispan.transaction.xa.TransactionXaAdapter] (http-0.0.0.0-8080-8) Error while processing PrepareCommand
      org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [*|METACONTENT] for requestor [GlobalTransaction:<innrab06-20774>:57040:remote]! Lock held by [GlobalTransaction:<innrab06-20774>:57039:remote]
         at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:218)
         at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:121)
         at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:106)
         at org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:245)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.DistCacheStoreInterceptor.visitPutKeyValueCommand(DistCacheStoreInterceptor.java:77)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.CacheLoaderInterceptor.visitPutKeyValueCommand(CacheLoaderInterceptor.java:81)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
         at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:82)
         at org.infinispan.interceptors.DistTxInterceptor.visitPrepareCommand(DistTxInterceptor.java:59)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:87)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:58)
         at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:60)
         at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
         at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
         at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
         at org.infinispan.commands.tx.PrepareCommand.perform(PrepareCommand.java:111)
         at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:94)
         at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:176)
         at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:148)
         at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
         at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
         at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
         at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
         at org.jgroups.JChannel.up(JChannel.java:1453)
         at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
         at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
         at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
         at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
         at org.jgroups.protocols.FC.up(FC.java:494)
         at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
         at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
         at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
         at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
         at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
         at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
         at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
         at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
         at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
         at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
         at org.jgroups.protocols.Discovery.up(Discovery.java:283)
         at org.jgroups.protocols.PING.up(PING.java:67)
         at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
         at org.jgroups.protocols.TP.access$100(TP.java:56)
         at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
         at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
         at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
         at java.lang.Thread.run(Thread.java:619)
      2010-11-24 13:19:52,181 INFO  [STDOUT] (http-0.0.0.0-8080-8) 20101124 131952 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (http-0.0.0.0-8080-8) Execution error:
      org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [*|METACONTENT] for requestor [Thread[OOB-77,ngs-infinispan-preprod_3,innrab03-7151,5,Thread Pools]]! Lock held by [GlobalTransaction:<innrab06-20774>:57039:remote]
         at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:218)
         at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:121)
         at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:106)
         at org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:245)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.DistCacheStoreInterceptor.visitPutKeyValueCommand(DistCacheStoreInterceptor.java:77)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.CacheLoaderInterceptor.visitPutKeyValueCommand(CacheLoaderInterceptor.java:81)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
         at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:172)
         at org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:120)
         at org.infinispan.interceptors.DistTxInterceptor.visitPutKeyValueCommand(DistTxInterceptor.java:76)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:87)
         at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:58)
         at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
         at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:60)
         at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
         at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
         at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
         at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:42)
         at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:44)
         at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:94)
         at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:176)
         at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:148)
         at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
         at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
         at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
         at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
         at org.jgroups.JChannel.up(JChannel.java:1453)
         at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
         at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
         at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
         at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
         at org.jgroups.protocols.FC.up(FC.java:494)
         at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
         at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
         at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
         at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
         at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
         at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
         at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
         at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
         at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
         at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
         at org.jgroups.protocols.Discovery.up(Discovery.java:283)
         at org.jgroups.protocols.PING.up(PING.java:67)
         at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
         at org.jgroups.protocols.TP.access$100(TP.java:56)
         at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
         at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
         at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
         at java.lang.Thread.run(Thread.java:619)
      2010-11-24 13:19:52,218 INFO  [STDOUT] (http-0.0.0.0-8080-8) 20101124 131952 ERROR [com.buongiorno.rabbit.dss.logic.BasicManager] (http-0.0.0.0-8080-8) Warning : the metacontent with rowKey 'PhysicalId [id=7Digital-Albums:4ced02988f513: 0]' was persisted but not indexed in the Meta Content Indexing System. The cause was : Unable to end batch
      org.infinispan.CacheException: Unable to end batch
         at org.infinispan.batch.BatchContainer.endBatch(BatchContainer.java:110)
         at org.infinispan.batch.BatchContainer.endBatch(BatchContainer.java:92)
         at org.infinispan.CacheDelegate.endBatch(CacheDelegate.java:389)
         at org.infinispan.lucene.InfinispanIndexOutput.storeCurrentBuffer(InfinispanIndexOutput.java:172)
         at org.infinispan.lucene.InfinispanIndexOutput.flush(InfinispanIndexOutput.java:141)
         at org.apache.lucene.store.ChecksumIndexOutput.prepareCommit(ChecksumIndexOutput.java:86)
         at org.apache.lucene.index.SegmentInfos.write(SegmentInfos.java:347)
         at org.apache.lucene.index.SegmentInfos.prepareCommit(SegmentInfos.java:782)
         at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:4793)
         at org.apache.lucene.index.IndexWriter.prepareCommit(IndexWriter.java:3433)
         at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3506)
         at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3477)
         at com.buongiorno.rabbit.dss.indexing.IndexWriterAdapter.commit(IndexWriterAdapter.java:48)
         at com.buongiorno.rabbit.dss.indexing.MCIndexingSystemManager.finalize(MCIndexingSystemManager.java:614)
         at com.buongiorno.rabbit.dss.indexing.MCIndexingSystemManager.addDocument(MCIndexingSystemManager.java:610)
         at com.buongiorno.rabbit.dss.indexing.MCIndexingSystemManager.writeMetaContent(MCIndexingSystemManager.java:537)
         at com.buongiorno.rabbit.dss.indexing.MCIndexingSystemManager.indexMetaContent(MCIndexingSystemManager.java:126)
         at com.buongiorno.rabbit.dss.logic.MetaContentManager.insertNode(MetaContentManager.java:672)
         at com.buongiorno.rabbit.dss.logic.MetaContentManager.insertNewMetaContent(MetaContentManager.java:215)
         at com.buongiorno.rabbit.dss.service.DIFPersistenceService.doExecution(DIFPersistenceService.java:80)
         at com.buongiorno.rabbit.dss.service.DIFPersistenceService.doExecution(DIFPersistenceService.java:46)
         at com.buongiorno.rabbit.dss.service.BasicService.execute(BasicService.java:51)
         at com.buongiorno.rabbit.dss.service.BasicService.execute(BasicService.java:26)
         at com.buongiorno.rabbit.dss.service.DIFPersistenceService.persistDIF(DIFPersistenceService.java:66)
         at sun.reflect.GeneratedMethodAccessor292.invoke(Unknown Source)
         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
         at java.lang.reflect.Method.invoke(Method.java:597)
         at org.jboss.wsf.container.jboss50.invocation.InvocationHandlerJSE.invoke(InvocationHandlerJSE.java:108)
         at org.jboss.ws.core.server.ServiceEndpointInvoker.invoke(ServiceEndpointInvoker.java:222)
         at org.jboss.wsf.stack.jbws.RequestHandlerImpl.processRequest(RequestHandlerImpl.java:474)
         at org.jboss.wsf.stack.jbws.RequestHandlerImpl.handleRequest(RequestHandlerImpl.java:295)
         at org.jboss.wsf.stack.jbws.RequestHandlerImpl.doPost(RequestHandlerImpl.java:205)
         at org.jboss.wsf.stack.jbws.RequestHandlerImpl.handleHttpRequest(RequestHandlerImpl.java:131)
         at org.jboss.wsf.common.servlet.AbstractEndpointServlet.service(AbstractEndpointServlet.java:85)
         at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
         at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
         at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
         at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
         at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)
         at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)
         at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
         at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
         at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
         at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
         at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
         at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
         at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
         at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
         at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)
         at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
         at java.lang.Thread.run(Thread.java:619)
      Caused by: javax.transaction.RollbackException: Exception rolled back, status is: 9
         at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
         at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:96)
         at org.infinispan.batch.BatchContainer.resolveTransaction(BatchContainer.java:130)
         at org.infinispan.batch.BatchContainer.endBatch(BatchContainer.java:107)
         ... 54 more

        • 1. Re: InfinispanDirectory: Timeout while merging indexes
          sannegrinovero

          Hi Tristan,

          You might want to check about what you state this is a single node system, as this stacktrace has remove invocations and clearly shows signs of using JGroups.

          Still even ignoring the remote parts, the Lucene Directory is explicitly asking to avoid locking as they are not needed and data integrity is mantained at an higher level, so I have something to check in Infinispan core.

          I've been discussing this with manik and I got some pointers about what to check, I'll keep you updated.

          • 2. Re: InfinispanDirectory: Timeout while merging indexes
            sannegrinovero

            Tristan, any update on this?

            • 3. Re: InfinispanDirectory: Timeout while merging indexes
              nadirx

              It has not happened again. But that is not a confirmation that everything is fine. A similar issue was caused by the fact that Cassandra's compaction (the store for these caches) caused timeouts when doing bulk loading, but that showed up as timeouts in my own cachestore code. This is solved by telling Cassandra not to do compaction during these bulk loads I'll let you know if it happens again.

              • 4. Re: InfinispanDirectory: Timeout while merging indexes
                sannegrinovero

                thanks, and make sure to understand why you're having remote invocations in a single node.

                • 5. Re: InfinispanDirectory: Timeout while merging indexes
                  nadirx

                  Sanne,

                  we're still getting failures on acquiring locks during merges. Here is the configuration:

                   

                  Infinispan: 3 caches: lockCache (replicated, volatile, no eviction), metadataCache (replicated, persisted, no eviction), dataCache (distributed, persisted, eviction).

                  Node 1: coordinator, IndexWriter open constantly and writing a stream of documents

                  Node 2: opens a read-only IndexReader to perform queries.

                   

                  Occasionally when performing queries on node 2 we get the following

                   

                  Node1:

                  20110127 133353 ERROR [org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:94)] (OOB-185,ngs-infinispan-ss_cluster,rabbit-1-1658) Execution error:

                  org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [_64.fdt|RL|METACONTENT] for requestor [Thread[OOB-185,ngs-infinispan-ss_cluster,rabbit-1-1658,5,Thread Pools]

                  ]! Lock held by [merge thread: _64:C199 _65:c1 _66:c1 _67:c1 _68:c1 _69:c1 _6a:c1 _6b:c1 _6c:c1 _6d:c1 into _6e [mergeDocStores]]

                          at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:228)

                          at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:155)

                          at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:107)

                          at org.infinispan.interceptors.LockingInterceptor.visitReplaceCommand(LockingInterceptor.java:337)

                  <snip>

                  20110127 133353 ERROR [org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:94)] (Lucene Merge Thread #22) Execution error:

                  org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [_64.fdt|RL|METACONTENT] for requestor [Thread[OOB-129,ngs-infinispan-ss_cluster,rabbit-2-52029,5,Thread Pools

                  ]]! Lock held by [Thread[http-192.168.10.221-8080-1,5,jboss]]

                          at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:228)

                          at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:155)

                          at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:107)

                          at org.infinispan.interceptors.LockingInterceptor.visitReplaceCommand(LockingInterceptor.java:337)

                  <snip>

                   

                  Node 2:

                  20110127 133353 ERROR [org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationCont

                  extInterceptor.java:94)] (OOB-129,ngs-infinispan-ss_cluster,rabbit-2-52029) Execution error:

                  org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [_64.f

                  dt|RL|METACONTENT] for requestor [Thread[OOB-129,ngs-infinispan-ss_cluster,rabbit-2-52029,5,Thread Pools

                  ]]! Lock held by [Thread[http-192.168.10.221-8080-1,5,jboss]]

                          at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:228)

                          at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:155)

                          at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:107)

                          at org.infinispan.interceptors.LockingInterceptor.visitReplaceCommand(LockingInterceptor.java:337)

                  <snip>

                  20110127 133353 ERROR [org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:94)] (http-192.168.10.221-8080-1) Execution error:

                  org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [_64.fdt|RL|METACONTENT] for requestor [Thread[OOB-185,ngs-infinispan-ss_cluster,rabbit-1-1658,5,Thread Pools]]! Lock held by [merge thread: _64:C199 _65:c1 _66:c1 _67:c1 _68:c1 _69:c1 _6a:c1 _6b:c1 _6c:c1 _6d:c1 into _6e [mergeDocStores]]

                          at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:228)

                          at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:155)

                          at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:107)

                          at org.infinispan.interceptors.LockingInterceptor.visitReplaceCommand(LockingInterceptor.java:337)

                   

                  As you can see, it is related to index merging, i.e. while Node 1 is merging indices, Node 2 runs a query, hangs for 10 seconds and both nodes log the above. Note that each node gets two exceptions each for the same problem at the same moment.


                  Any suggestions ?

                   

                  Tristan

                  • 6. Re: InfinispanDirectory: Timeout while merging indexes
                    sannegrinovero

                    Hi Tristan, could you open a JIRA issue and assign it to me, please attach full stacktraces. I'm not sure why replaceCommand would need to lock the ReadLock.  Also from this stack I guess that you're using one of the ReadLock implementations in org.infinispan.lucene.readlocks, which one? DistributedSegmentReadLocker is the default, still for optimal performance the application could "guess" when an IndexReader is needed or not, and so plugin it's own implementation.  If you are sure that no IndexReader lives for longer than X seconds, you could implement a clever ReadLocker which, instead of deleting segments, sets them to have a time-to live as 2X seconds or similar. If you can, you avoid some network roundtrips and locks.

                    • 7. Re: InfinispanDirectory: Timeout while merging indexes
                      nadirx

                      Hi Sanne,

                       

                      I guess the ideal implementation would use some kind of MVCC mechanism, where readers see a previous "snapshot" of all the "files", without locking. Can it be done ?

                      • 8. Re: InfinispanDirectory: Timeout while merging indexes
                        sannegrinovero

                        No, you can't get a "fully frozen" read view via infinispan, you would have to lock all keys atomically, while you actually want to avoid any kind of locking. Getting global MVCC would require some form of garbage collection, not good for scalability as some form of registry of keys should be maintained.

                         

                        The problem is segment fragmentation, my recommendation would be to avoid segment fragmentation. If you can tune the merge policy of Lucene and the "chunkSize" parameter of InfinispanDirectory to guarantee the segments won't ever split, then you don't need locking at all.

                         

                        You'll still need to implement a custom SegmentReadLocker as the NoopSegmentReadLocker implementation doesn't delete the segments (just delete them); this could have some effect on search performance.

                         

                        Lucene can recover easily from a disappearing segment, it can not recover from a disappearing/missing fragment of an open segment.

                         

                        You can still have a fragmented index implementing a proper SRL, time limited IndexReaders should not be hard.

                         

                        Also if you really have this amount of contention, I think you are opening an unneeded high amount of readers. Don't you have an IndexReader pool? don't you open IRs via reopen()? See org.hibernate.search.reader.SharingBufferReaderProvider to know how Hibernate Search does it.

                         

                        Anyway whatever you're doing or solution you choose, please open a JIRA and attach stacktraces; I might find an easy solution providing a new SRLocker using deltas instead of locking. I just need your stack