"Lock obtain timed out" is thrown while querying using Infinispan directory_provider with jdbc cache store ---------------------------------------------------------------------------------------------------------- Key: ISPN-3090 URL: https://issues.jboss.org/browse/ISPN-3090 Project: Infinispan Issue Type: Bug Components: Lucene Directory, Querying Affects Versions: 5.2.4.Final Reporter: Anna Manukyan Assignee: Sanne Grinovero Fix For: 6.0.0.Final Attachments: clustered-config.xml Pre-requisites: You can find the used configuration attached (clustered-config.xml). The main cache is configured so that, the default.directory_provider is set to infinispan. The index caches are redefined and jdbc string based cache store is declared for them. The test which is run for this configuration is a performance test. The point is to start a several nodes, make sure that the replication takes place, then put indexed entries into the cache and perform queries on that cache. All these actions are done in parallel. Problem 1: Configuration: JDBC cache store - shared=false, indexLocalOnly=false a) When starting 2 nodes which perform puts in parallel into the cache (putting indexed entries), everything goes smoothly no problem appears. b) As soon as the number of nodes is increased to 3, the following exception is thrown while trying to put data into the cache (see below). Please note, that in case of 3 nodes, this exception is thrown just in the beginning while verifying that the cluster is formed, i.e. put is done into the cache and then it is expected that the data is replicated to the rest nodes. The exception is thrown during the put, but it doesn't harm the further work of the test and the next steps described above succeed properly: {code} 14:45:50,190 ERROR [InvocationContextInterceptor] ISPN000136: Execution error org.hibernate.search.SearchException: HSEARCH000103: Unable to initialize IndexManager query at org.hibernate.search.indexes.impl.IndexManagerHolder.createIndexManager(IndexManagerHolder.java:230) at org.hibernate.search.indexes.impl.IndexManagerHolder.buildEntityIndexBinding(IndexManagerHolder.java:102) at org.hibernate.search.spi.SearchFactoryBuilder.initDocumentBuilders(SearchFactoryBuilder.java:414) at org.hibernate.search.spi.SearchFactoryBuilder.buildIncrementalSearchFactory(SearchFactoryBuilder.java:169) at org.hibernate.search.spi.SearchFactoryBuilder.buildSearchFactory(SearchFactoryBuilder.java:149) at org.hibernate.search.impl.MutableSearchFactory.addClasses(MutableSearchFactory.java:194) at org.infinispan.query.backend.QueryInterceptor.enableClassesIncrementally(QueryInterceptor.java:225) at org.infinispan.query.backend.QueryInterceptor.updateKnownTypesIfNeeded(QueryInterceptor.java:250) at org.infinispan.query.backend.QueryInterceptor.processPutKeyValueCommand(QueryInterceptor.java:426) at org.infinispan.query.backend.QueryInterceptor.visitPutKeyValueCommand(QueryInterceptor.java:128) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutKeyValueCommand(NonTransactionalLockingInterceptor.java:73) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) 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:62) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) 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:62) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:216) at org.infinispan.statetransfer.StateTransferInterceptor.handleWriteCommand(StateTransferInterceptor.java:194) at org.infinispan.statetransfer.StateTransferInterceptor.visitPutKeyValueCommand(StateTransferInterceptor.java:136) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:92) at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:62) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343) at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61) at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:70) at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:101) at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:122) at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:86) at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommandFromLocalCluster(CommandAwareRpcDispatcher.java:247) at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:220) at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:484) at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:391) at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:249) at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:598) at org.jgroups.JChannel.up(JChannel.java:707) at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1020) at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:504) at org.jgroups.protocols.FRAG2.up(FRAG2.java:181) at org.jgroups.protocols.FlowControl.up(FlowControl.java:400) at org.jgroups.protocols.FlowControl.up(FlowControl.java:418) at org.jgroups.protocols.pbcast.GMS.up(GMS.java:896) at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:245) at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:453) at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:751) at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:609) at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:143) at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288) at org.jgroups.protocols.MERGE2.up(MERGE2.java:205) at org.jgroups.protocols.Discovery.up(Discovery.java:359) at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2616) at org.jgroups.protocols.TP.passMessageUp(TP.java:1263) at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1825) at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1798) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:722) Caused by: org.hibernate.search.SearchException: Could not initialize index at org.hibernate.search.store.impl.DirectoryProviderHelper.initializeIndexIfNeeded(DirectoryProviderHelper.java:162) at org.hibernate.search.infinispan.impl.InfinispanDirectoryProvider.start(InfinispanDirectoryProvider.java:103) at org.hibernate.search.indexes.impl.DirectoryBasedIndexManager.initialize(DirectoryBasedIndexManager.java:104) at org.hibernate.search.indexes.impl.IndexManagerHolder.createIndexManager(IndexManagerHolder.java:227) ... 65 more Caused by: org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: org.infinispan.lucene.locking.BaseLuceneLock@98f624d at org.apache.lucene.store.Lock.obtain(Lock.java:84) at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1098) at org.hibernate.search.store.impl.DirectoryProviderHelper.initializeIndexIfNeeded(DirectoryProviderHelper.java:157) ... 68 more {code} c) If the number of nodes is increased to 4, then the exception described above is thrown always not only during cluster verification, but also during writing indexed data into the cache. Problem 2: Configuration: JDBC cache store - shared=true, indexLocalOnly=true In this case for both 3 and 4 nodes happens the case described in Problem 1.b . Problem 3: Configuration: JDBC cache store - shared=true, indexLocalOnly=false In this case for 3 node configuration, the Problem 1.b happens. For the 4 node configuration, the picture is a little bit different. First during cluster validation the exception is thrown given above. As soon as the test comes to the stage of writing indexed data into the cache, the following exception is continuously thrown: {code} 17:20:27,445 ERROR [InvocationContextInterceptor] ISPN000136: Execution error org.infinispan.util.concurrent.TimeoutException: Replication timeout for amanukyan-2185 at org.infinispan.remoting.transport.AbstractTransport.parseResponseAndAddToResponseList(AbstractTransport.java:113) at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:541) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:169) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:190) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:247) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:234) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:229) at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:208) at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:200) at org.infinispan.interceptors.ReplicationInterceptor.handleCrudMethod(ReplicationInterceptor.java:297) at org.infinispan.interceptors.ReplicationInterceptor.visitPutKeyValueCommand(ReplicationInterceptor.java:248) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.EntryWrappingInterceptor.invokeNextAndApplyChanges(EntryWrappingInterceptor.java:275) at org.infinispan.interceptors.EntryWrappingInterceptor.visitPutKeyValueCommand(EntryWrappingInterceptor.java:166) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.query.backend.QueryInterceptor.visitPutKeyValueCommand(QueryInterceptor.java:127) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutKeyValueCommand(NonTransactionalLockingInterceptor.java:71) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) 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:62) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) 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:62) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:216) at org.infinispan.statetransfer.StateTransferInterceptor.handleWriteCommand(StateTransferInterceptor.java:194) at org.infinispan.statetransfer.StateTransferInterceptor.visitPutKeyValueCommand(StateTransferInterceptor.java:136) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:92) at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:62) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343) at org.infinispan.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1186) at org.infinispan.CacheImpl.putInternal(CacheImpl.java:783) at org.infinispan.CacheImpl.put(CacheImpl.java:777) at org.infinispan.CacheImpl.put(CacheImpl.java:771) at org.infinispan.CacheSupport.put(CacheSupport.java:53) at org.radargun.cachewrappers.InfinispanWrapper.put(InfinispanWrapper.java:244) at org.radargun.cachewrappers.InfinispanExplicitLockingWrapper.put(InfinispanExplicitLockingWrapper.java:72) at org.radargun.cachewrappers.InfinispanQueryWrapper.put(InfinispanQueryWrapper.java:79) at org.radargun.stressors.StressTestStressor$FixedSetPerThreadOperationLogic.init(StressTestStressor.java:313) at org.radargun.stressors.StressTestStressor$Stressor.run(StressTestStressor.java:541) 17:20:27,448 ERROR [InvocationContextInterceptor] ISPN000136: Execution error org.infinispan.util.concurrent.TimeoutException: Replication timeout for amanukyan-2185 at org.infinispan.remoting.transport.AbstractTransport.parseResponseAndAddToResponseList(AbstractTransport.java:113) at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:541) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:169) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:190) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:247) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:234) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:229) at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:208) at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:200) at org.infinispan.interceptors.ReplicationInterceptor.handleCrudMethod(ReplicationInterceptor.java:297) at org.infinispan.interceptors.ReplicationInterceptor.visitPutKeyValueCommand(ReplicationInterceptor.java:248) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.EntryWrappingInterceptor.invokeNextAndApplyChanges(EntryWrappingInterceptor.java:275) at org.infinispan.interceptors.EntryWrappingInterceptor.visitPutKeyValueCommand(EntryWrappingInterceptor.java:166) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.query.backend.QueryInterceptor.visitPutKeyValueCommand(QueryInterceptor.java:127) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutKeyValueCommand(NonTransactionalLockingInterceptor.java:71) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) 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:62) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) 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:62) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:216) at org.infinispan.statetransfer.StateTransferInterceptor.handleWriteCommand(StateTransferInterceptor.java:194) at org.infinispan.statetransfer.StateTransferInterceptor.visitPutKeyValueCommand(StateTransferInterceptor.java:136) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:92) at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:62) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343) at org.infinispan.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1186) at org.infinispan.CacheImpl.putInternal(CacheImpl.java:783) at org.infinispan.CacheImpl.put(CacheImpl.java:777) at org.infinispan.CacheImpl.put(CacheImpl.java:771) at org.infinispan.CacheSupport.put(CacheSupport.java:53) at org.radargun.cachewrappers.InfinispanWrapper.put(InfinispanWrapper.java:244) at org.radargun.cachewrappers.InfinispanExplicitLockingWrapper.put(InfinispanExplicitLockingWrapper.java:72) at org.radargun.cachewrappers.InfinispanQueryWrapper.put(InfinispanQueryWrapper.java:79) at org.radargun.stressors.StressTestStressor$FixedSetPerThreadOperationLogic.init(StressTestStressor.java:313) at org.radargun.stressors.StressTestStressor$Stressor.run(StressTestStressor.java:541) ..... and so on {code} Problem 4: Configuration: JDBC cache store - shared=false, indexLocalOnly=true In this case for both 3 and 4 nodes happens the case described in Problem 1.b .