Data put to index enabled cache with Infinispan Directory provider using Async. JDBC StringBased CacheStore fails ----------------------------------------------------------------------------------------------------------------- Key: ISPN-3432 URL: https://issues.jboss.org/browse/ISPN-3432 Project: Infinispan Issue Type: Bug Components: Querying Affects Versions: 6.0.0.Alpha1 Reporter: Anna Manukyan Assignee: Sanne Grinovero Attachments: async-config.xml Hi, this issue is related to the ISPN-3090, but I thought to specify this case separately for bringing detailed explanation for the configuration and thrown exceptions. The issue relates to the performance tests for Index enabled Infinispan cache, with configured Infinispan directory and Async JDBC. String Based Cache store. The tests are running on 4 nodes and performing puts/gets on all nodes with many threads. The problem is that, during data put, the following exceptions are thrown: {code} org.infinispan.commons.CacheException: Received invalid rebalance confirmation from edg-perf12-2810 for cache LuceneIndexesData_custom, we don't have a rebalance in progress at org.infinispan.topology.ClusterTopologyManagerImpl.handleRebalanceCompleted(ClusterTopologyManagerImpl.java:189) at org.infinispan.topology.CacheTopologyControlCommand.doPerform(CacheTopologyControlCommand.java:147) at org.infinispan.topology.CacheTopologyControlCommand.perform(CacheTopologyControlCommand.java:124) at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher$4.run(CommandAwareRpcDispatcher.java:270) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724) 04:03:54,470 INFO [org.radargun.Slave] (pool-1-thread-1) Executing stage: ClusterValidation {exitBenchmarkOnSlaveFailure=false, partialReplication=false, replicationTimeSleep=2000, replicationTryCount=60, runOnAllSlaves=false, slaves=null, useSmartClassLoading=true } 04:04:05,365 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread-0) ISPN000136: Execution error org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [segments.gen|M|query] for requestor [GlobalTransaction:<edg-perf11-6046>:2:remote]! Lock held by [GlobalTransaction:<edg-perf10-45266>:2:local] at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:192) at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:165) at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:184) at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:113) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.acquireAllLocks(OptimisticLockingInterceptor.java:262) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:84) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:36) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:115) at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:102) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:39) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:192) at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:165) at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:70) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:106) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:70) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:321) at org.infinispan.commands.tx.PrepareCommand.perform(PrepareCommand.java:115) at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:100) at org.infinispan.remoting.InboundInvocationHandlerImpl.access$000(InboundInvocationHandlerImpl.java:46) at org.infinispan.remoting.InboundInvocationHandlerImpl$2.run(InboundInvocationHandlerImpl.java:172) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724) 04:04:05,367 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread-1) ISPN000136: Execution error org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [segments.gen|M|query] for requestor [GlobalTransaction:<edg-perf13-31800>:2:remote]! Lock held by [GlobalTransaction:<edg-perf10-45266>:2:local] at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:192) at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:165) at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:184) at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:113) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.acquireAllLocks(OptimisticLockingInterceptor.java:262) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:84) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:36) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:115) at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:102) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:39) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:192) at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:165) at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:70) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:106) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:70) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:321) at org.infinispan.commands.tx.PrepareCommand.perform(PrepareCommand.java:115) at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:100) at org.infinispan.remoting.InboundInvocationHandlerImpl.access$000(InboundInvocationHandlerImpl.java:46) at org.infinispan.remoting.InboundInvocationHandlerImpl$2.run(InboundInvocationHandlerImpl.java:172) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724) 04:04:05,365 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread-2) ISPN000136: Execution error org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [segments.gen|M|query] for requestor [GlobalTransaction:<edg-perf12-2810>:2:remote]! Lock held by [GlobalTransaction:<edg-perf10-45266>:2:local] at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:192) at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:165) at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:184) at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:113) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.acquireAllLocks(OptimisticLockingInterceptor.java:262) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:84) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:36) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:115) at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:102) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:39) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:192) at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:165) at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:70) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:106) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:70) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:125) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:321) at org.infinispan.commands.tx.PrepareCommand.perform(PrepareCommand.java:115) at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:100) at org.infinispan.remoting.InboundInvocationHandlerImpl.access$000(InboundInvocationHandlerImpl.java:46) at org.infinispan.remoting.InboundInvocationHandlerImpl$2.run(InboundInvocationHandlerImpl.java:172) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724) {code} The exception above is thrown right after all nodes are started. Then the following exception is continuously thrown: {code} 04:04:05,633 ERROR [org.hibernate.search.exception.impl.LogErrorHandler] (Hibernate Search: Index updates queue processor for index query-1) HSEARCH000058: Exception occurred org.apache.lucene.index.IndexNotFoundException: no segments* file found in InfinispanDirectory{indexName='query'}: files: [] Primary Failure: Entity org.radargun.cachewrappers.InfinispanQueryWrapper$QueryableData Id S:_InstallBenchmarkStage_0 Work Type org.hibernate.search.backend.UpdateLuceneWork org.apache.lucene.index.IndexNotFoundException: no segments* file found in InfinispanDirectory{indexName='query'}: files: [] at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:667) at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:554) at org.apache.lucene.index.SegmentInfos.read(SegmentInfos.java:359) at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1138) at org.hibernate.search.backend.impl.lucene.IndexWriterHolder.createNewIndexWriter(IndexWriterHolder.java:148) at org.hibernate.search.backend.impl.lucene.IndexWriterHolder.getIndexWriter(IndexWriterHolder.java:115) at org.hibernate.search.backend.impl.lucene.AbstractWorkspaceImpl.getIndexWriter(AbstractWorkspaceImpl.java:117) at org.hibernate.search.backend.impl.lucene.LuceneBackendQueueTask.applyUpdates(LuceneBackendQueueTask.java:101) at org.hibernate.search.backend.impl.lucene.LuceneBackendQueueTask.run(LuceneBackendQueueTask.java:67) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) at java.util.concurrent.FutureTask.run(FutureTask.java:166) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724) ...... 04:14:21,605 ERROR [org.hibernate.search.exception.impl.LogErrorHandler] (Hibernate Search: Index updates queue processor for index query-1) HSEARCH000058: Exception occurred org.apache.lucene.index.IndexNotFoundException: no segments* file found in InfinispanDirectory{indexName='query'}: files: [] Primary Failure: Entity org.radargun.cachewrappers.InfinispanQueryWrapper$QueryableData Id S:key_0_0_0000000000000017 Work Type org.hibernate.search.backend.UpdateLuceneWork org.apache.lucene.index.IndexNotFoundException: no segments* file found in InfinispanDirectory{indexName='query'}: files: [] at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:667) at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:554) at org.apache.lucene.index.SegmentInfos.read(SegmentInfos.java:359) at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1138) at org.hibernate.search.backend.impl.lucene.IndexWriterHolder.createNewIndexWriter(IndexWriterHolder.java:148) at org.hibernate.search.backend.impl.lucene.IndexWriterHolder.getIndexWriter(IndexWriterHolder.java:115) at org.hibernate.search.backend.impl.lucene.AbstractWorkspaceImpl.getIndexWriter(AbstractWorkspaceImpl.java:117) at org.hibernate.search.backend.impl.lucene.LuceneBackendQueueTask.applyUpdates(LuceneBackendQueueTask.java:101) at org.hibernate.search.backend.impl.lucene.LuceneBackendQueueTask.run(LuceneBackendQueueTask.java:67) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) at java.util.concurrent.FutureTask.run(FutureTask.java:166) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724) {code} You can find the cache configuration attached.