Major Description
When admin user tries to add an entry to non authorized indexed cache, an exception is thrown which is visible in the entry creation pop-up. Anyway, when I am refreshing the page, the entry was created and is there. The error is not 100% reproducible, I am not sure why this happens, as when I am doing it manually the entry creation proceeds and no exception is there. But error is 100% reproducible with our automated Cypress test.
The exception is:
2023-08-24 19:14:48,173 WARN (Hibernate Search - default backend - Worker thread - 0) [org.hibernate.search.backend.lucene.lowlevel.writer.impl.IndexWriterProvider] HSEARCH000052: An index writer operation failed. Resetting the index writer and forcing release of locks. Context: index 'org.infinispan.Child' 2023-08-24 19:14:48,174 ERROR (Hibernate Search - default backend - Worker thread - 0) [org.hibernate.search.engine.reporting.impl.LogFailureHandler] HSEARCH000058: Exception occurred org.hibernate.search.util.common.SearchException: HSEARCH600118: A failure occurred during a low-level write operation and the index writer had to be reset. Some write operations may have been lost as a result. Failure: Underlying file changed by an external force at 2023-08-24T17:07:48.77Z, (lock=NativeFSLock(path=/home/amanukya/IdeaProjects/infinispan-console-ng/server/infinispan-server/infinispan-4-e2e/data/indexed-cache-no-auth/org.infinispan.Child/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2023-08-24T17:07:48.770702639Z)) Context: index 'org.infinispan.Child' Failing operation: UpdateEntryWork[type=updateEntry, tenantId=null, entityTypeName=org.infinispan.Child, entityIdentifier=[B@2bfcbd7e] org.hibernate.search.util.common.SearchException: HSEARCH600118: A failure occurred during a low-level write operation and the index writer had to be reset. Some write operations may have been lost as a result. Failure: Underlying file changed by an external force at 2023-08-24T17:07:48.77Z, (lock=NativeFSLock(path=/home/amanukya/IdeaProjects/infinispan-console-ng/server/infinispan-server/infinispan-4-e2e/data/indexed-cache-no-auth/org.infinispan.Child/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2023-08-24T17:07:48.770702639Z)) Context: index 'org.infinispan.Child' at org.hibernate.search.backend.lucene.lowlevel.writer.impl.IndexWriterDelegatorImpl.closeAfterFailure(IndexWriterDelegatorImpl.java:153) at org.hibernate.search.backend.lucene.lowlevel.writer.impl.IndexWriterProvider.clearAfterFailure(IndexWriterProvider.java:98) at org.hibernate.search.backend.lucene.lowlevel.index.impl.IndexAccessorImpl.cleanUpAfterFailure(IndexAccessorImpl.java:171) at org.hibernate.search.backend.lucene.orchestration.impl.LuceneBatchedWorkProcessor.submit(LuceneBatchedWorkProcessor.java:66) at org.hibernate.search.backend.lucene.orchestration.impl.LuceneBatchedWork.submitTo(LuceneBatchedWork.java:26) at org.hibernate.search.backend.lucene.orchestration.impl.LuceneBatchedWork.submitTo(LuceneBatchedWork.java:14) at org.hibernate.search.engine.backend.orchestration.spi.BatchingExecutor$BatchWorker.work(BatchingExecutor.java:173) at org.hibernate.search.engine.backend.orchestration.spi.SingletonTask$RunnableWrapper.run(SingletonTask.java:199) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:833) Caused by: org.apache.lucene.store.AlreadyClosedException: Underlying file changed by an external force at 2023-08-24T17:07:48.77Z, (lock=NativeFSLock(path=/home/amanukya/IdeaProjects/infinispan-console-ng/server/infinispan-server/infinispan-4-e2e/data/indexed-cache-no-auth/org.infinispan.Child/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2023-08-24T17:07:48.770702639Z)) at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:191) at org.apache.lucene.store.LockValidatingDirectoryWrapper.createOutput(LockValidatingDirectoryWrapper.java:43) at org.apache.lucene.store.TrackingDirectoryWrapper.createOutput(TrackingDirectoryWrapper.java:43) at org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.<init>(CompressingStoredFieldsWriter.java:121) at org.apache.lucene.codecs.compressing.CompressingStoredFieldsFormat.fieldsWriter(CompressingStoredFieldsFormat.java:130) at org.apache.lucene.codecs.lucene87.Lucene87StoredFieldsFormat.fieldsWriter(Lucene87StoredFieldsFormat.java:141) at org.apache.lucene.index.StoredFieldsConsumer.initStoredFieldsWriter(StoredFieldsConsumer.java:48) at org.apache.lucene.index.StoredFieldsConsumer.startDocument(StoredFieldsConsumer.java:55) at org.apache.lucene.index.DefaultIndexingChain.startStoredFields(DefaultIndexingChain.java:452) at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:488) at org.apache.lucene.index.DocumentsWriterPerThread.updateDocuments(DocumentsWriterPerThread.java:208) at org.apache.lucene.index.DocumentsWriter.updateDocuments(DocumentsWriter.java:415) at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1471) at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1464) at org.hibernate.search.backend.lucene.lowlevel.writer.impl.IndexWriterDelegatorImpl.updateDocuments(IndexWriterDelegatorImpl.java:82) at org.hibernate.search.backend.lucene.work.impl.UpdateEntryWork.execute(UpdateEntryWork.java:46) at org.hibernate.search.backend.lucene.work.impl.UpdateEntryWork.execute(UpdateEntryWork.java:24) at org.hibernate.search.backend.lucene.orchestration.impl.LuceneBatchedWorkProcessor.submit(LuceneBatchedWorkProcessor.java:63) ... 10 more 2023-08-24 19:14:48,177 ERROR (non-blocking-thread-infinispan-4-e2e-p2-t19) [org.infinispan.interceptors.impl.InvocationContextInterceptor] ISPN000136: Error executing command PutKeyValueCommand on Cache 'indexed-cache-no-auth', writing keys [WrappedByteArray[\J09\s\t\r\i\n\g\K\e\y (11 bytes)]] org.apache.lucene.store.AlreadyClosedException: Underlying file changed by an external force at 2023-08-24T17:07:48.77Z, (lock=NativeFSLock(path=/home/amanukya/IdeaProjects/infinispan-console-ng/server/infinispan-server/infinispan-4-e2e/data/indexed-cache-no-auth/org.infinispan.Child/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2023-08-24T17:07:48.770702639Z)) at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:191) at org.apache.lucene.store.LockValidatingDirectoryWrapper.createOutput(LockValidatingDirectoryWrapper.java:43) at org.apache.lucene.store.TrackingDirectoryWrapper.createOutput(TrackingDirectoryWrapper.java:43) at org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.<init>(CompressingStoredFieldsWriter.java:121) at org.apache.lucene.codecs.compressing.CompressingStoredFieldsFormat.fieldsWriter(CompressingStoredFieldsFormat.java:130) at org.apache.lucene.codecs.lucene87.Lucene87StoredFieldsFormat.fieldsWriter(Lucene87StoredFieldsFormat.java:141) at org.apache.lucene.index.StoredFieldsConsumer.initStoredFieldsWriter(StoredFieldsConsumer.java:48) at org.apache.lucene.index.StoredFieldsConsumer.startDocument(StoredFieldsConsumer.java:55) at org.apache.lucene.index.DefaultIndexingChain.startStoredFields(DefaultIndexingChain.java:452) at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:488) at org.apache.lucene.index.DocumentsWriterPerThread.updateDocuments(DocumentsWriterPerThread.java:208) at org.apache.lucene.index.DocumentsWriter.updateDocuments(DocumentsWriter.java:415) at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1471) at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1464) at org.hibernate.search.backend.lucene.lowlevel.writer.impl.IndexWriterDelegatorImpl.updateDocuments(IndexWriterDelegatorImpl.java:82) at org.hibernate.search.backend.lucene.work.impl.UpdateEntryWork.execute(UpdateEntryWork.java:46) at org.hibernate.search.backend.lucene.work.impl.UpdateEntryWork.execute(UpdateEntryWork.java:24) at org.hibernate.search.backend.lucene.orchestration.impl.LuceneBatchedWorkProcessor.submit(LuceneBatchedWorkProcessor.java:63) at org.hibernate.search.backend.lucene.orchestration.impl.LuceneBatchedWork.submitTo(LuceneBatchedWork.java:26) at org.hibernate.search.backend.lucene.orchestration.impl.LuceneBatchedWork.submitTo(LuceneBatchedWork.java:14) at org.hibernate.search.engine.backend.orchestration.spi.BatchingExecutor$BatchWorker.work(BatchingExecutor.java:173) at org.hibernate.search.engine.backend.orchestration.spi.SingletonTask$RunnableWrapper.run(SingletonTask.java:199) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:833) 2023-08-24 19:14:48,178 ERROR (non-blocking-thread-infinispan-4-e2e-p2-t19) [org.infinispan.rest.RestRequestHandler] ISPN012005: An error occurred while responding to the client java.util.concurrent.CompletionException: org.infinispan.commons.CacheException: Underlying file changed by an external force at 2023-08-24T17:07:48.77Z, (lock=NativeFSLock(path=/home/amanukya/IdeaProjects/infinispan-console-ng/server/infinispan-server/infinispan-4-e2e/data/indexed-cache-no-auth/org.infinispan.Child/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2023-08-24T17:07:48.770702639Z)) at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:332) at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:347) at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:636) at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162) at org.infinispan.interceptors.impl.QueueAsyncInvocationStage.invokeQueuedHandlers(QueueAsyncInvocationStage.java:114) at org.infinispan.interceptors.impl.QueueAsyncInvocationStage.accept(QueueAsyncInvocationStage.java:87) at org.infinispan.interceptors.impl.QueueAsyncInvocationStage.accept(QueueAsyncInvocationStage.java:33) at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162) at org.infinispan.util.concurrent.NonBlockingManagerImpl.lambda$completeExceptionally$1(NonBlockingManagerImpl.java:58) at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:403) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at java.base/java.lang.Thread.run(Thread.java:833) Caused by: org.infinispan.commons.CacheException: Underlying file changed by an external force at 2023-08-24T17:07:48.77Z, (lock=NativeFSLock(path=/home/amanukya/IdeaProjects/infinispan-console-ng/server/infinispan-server/infinispan-4-e2e/data/indexed-cache-no-auth/org.infinispan.Child/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2023-08-24T17:07:48.770702639Z)) at org.infinispan.interceptors.impl.InvocationContextInterceptor.rethrowException(InvocationContextInterceptor.java:139) at org.infinispan.interceptors.impl.InvocationContextInterceptor.lambda$new$0(InvocationContextInterceptor.java:62) at org.infinispan.interceptors.InvocationExceptionFunction.apply(InvocationExceptionFunction.java:25) at org.infinispan.interceptors.impl.QueueAsyncInvocationStage.invokeQueuedHandlers(QueueAsyncInvocationStage.java:124) ... 14 more Caused by: org.apache.lucene.store.AlreadyClosedException: Underlying file changed by an external force at 2023-08-24T17:07:48.77Z, (lock=NativeFSLock(path=/home/amanukya/IdeaProjects/infinispan-console-ng/server/infinispan-server/infinispan-4-e2e/data/indexed-cache-no-auth/org.infinispan.Child/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2023-08-24T17:07:48.770702639Z)) at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:191) at org.apache.lucene.store.LockValidatingDirectoryWrapper.createOutput(LockValidatingDirectoryWrapper.java:43) at org.apache.lucene.store.TrackingDirectoryWrapper.createOutput(TrackingDirectoryWrapper.java:43) at org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.<init>(CompressingStoredFieldsWriter.java:121) at org.apache.lucene.codecs.compressing.CompressingStoredFieldsFormat.fieldsWriter(CompressingStoredFieldsFormat.java:130) at org.apache.lucene.codecs.lucene87.Lucene87StoredFieldsFormat.fieldsWriter(Lucene87StoredFieldsFormat.java:141) at org.apache.lucene.index.StoredFieldsConsumer.initStoredFieldsWriter(StoredFieldsConsumer.java:48) at org.apache.lucene.index.StoredFieldsConsumer.startDocument(StoredFieldsConsumer.java:55) at org.apache.lucene.index.DefaultIndexingChain.startStoredFields(DefaultIndexingChain.java:452) at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:488) at org.apache.lucene.index.DocumentsWriterPerThread.updateDocuments(DocumentsWriterPerThread.java:208) at org.apache.lucene.index.DocumentsWriter.updateDocuments(DocumentsWriter.java:415) at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1471) at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1464) at org.hibernate.search.backend.lucene.lowlevel.writer.impl.IndexWriterDelegatorImpl.updateDocuments(IndexWriterDelegatorImpl.java:82) at org.hibernate.search.backend.lucene.work.impl.UpdateEntryWork.execute(UpdateEntryWork.java:46) at org.hibernate.search.backend.lucene.work.impl.UpdateEntryWork.execute(UpdateEntryWork.java:24) at org.hibernate.search.backend.lucene.orchestration.impl.LuceneBatchedWorkProcessor.submit(LuceneBatchedWorkProcessor.java:63) at org.hibernate.search.backend.lucene.orchestration.impl.LuceneBatchedWork.submitTo(LuceneBatchedWork.java:26) at org.hibernate.search.backend.lucene.orchestration.impl.LuceneBatchedWork.submitTo(LuceneBatchedWork.java:14) at org.hibernate.search.engine.backend.orchestration.spi.BatchingExecutor$BatchWorker.work(BatchingExecutor.java:173) at org.hibernate.search.engine.backend.orchestration.spi.SingletonTask$RunnableWrapper.run(SingletonTask.java:199) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ... 1 more
Please see also the attached screenshot of entry creation page.
