Uploaded image for project: 'Infinispan'
  1. Infinispan
  2. ISPN-15237

SIFS Removing a non existent key causes index to not be correct

XMLWordPrintable

      While validating 14.0.19.Final against WildFly, we have a consistent failure in a test that uses a local cache with a persistent SIFS.
      After persisting several entries to the SIFS the test restarts the associated cache. At that point, a pair of the following exceptions are logged:

      09:59:47,511 ERROR [org.infinispan.persistence.sifs.Compactor] (blocking-thread--p3-t2) ISPN029021: File id 0 encountered an exception while compacting, file may be orphaned: java.lang.NullPointerException: No index info found for key: SessionMetaDataKey(SlbmKttMSStQY5URtO64K7aCMHYUsF5ntFc_sdvo) when processing file 0
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.sifs.Compactor.compactSingleFile(Compactor.java:564)
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.sifs.Compactor.processRequest(Compactor.java:430)
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.sifs.Compactor.lambda$start$0(Compactor.java:153)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.mixed.FlowableConcatMapCompletable$ConcatMapCompletableObserver.drain(FlowableConcatMapCompletable.java:187)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.mixed.ConcatMapXMainSubscriber.onNext(ConcatMapXMainSubscriber.java:106)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.flowable.FlowableObserveOn$ObserveOnSubscriber.runBackfused(FlowableObserveOn.java:444)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:174)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:324)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.runEager(ExecutorScheduler.java:289)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:250)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
	at org.wildfly.clustering.context@30.0.0.Final-SNAPSHOT//org.wildfly.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:32)
	at org.wildfly.clustering.context@30.0.0.Final-SNAPSHOT//org.wildfly.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:61)
	at java.base/java.lang.Thread.run(Thread.java:1583)

09:59:47,512 ERROR [org.infinispan.persistence.sifs.Compactor] (blocking-thread--p3-t2) ISPN029021: File id -1 encountered an exception while compacting, file may be orphaned: java.lang.NullPointerException: No index info found for key: SessionMetaDataKey(SlbmKttMSStQY5URtO64K7aCMHYUsF5ntFc_sdvo) when processing file 0
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.sifs.Compactor.compactSingleFile(Compactor.java:564)
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.sifs.Compactor.processRequest(Compactor.java:430)
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.sifs.Compactor.lambda$start$0(Compactor.java:153)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.mixed.FlowableConcatMapCompletable$ConcatMapCompletableObserver.drain(FlowableConcatMapCompletable.java:187)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.mixed.ConcatMapXMainSubscriber.onNext(ConcatMapXMainSubscriber.java:106)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.flowable.FlowableObserveOn$ObserveOnSubscriber.runBackfused(FlowableObserveOn.java:444)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:174)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:324)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.runEager(ExecutorScheduler.java:289)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:250)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
	at org.wildfly.clustering.context@30.0.0.Final-SNAPSHOT//org.wildfly.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:32)
	at org.wildfly.clustering.context@30.0.0.Final-SNAPSHOT//org.wildfly.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:61)
	at java.base/java.lang.Thread.run(Thread.java:1583)

      Unsurprisingly, following cache restart, the SIFS is unable to locate the entry for the key: SessionMetaDataKey(SlbmKttMSStQY5URtO64K7aCMHYUsF5ntFc_sdvo)

      Upon stopping the cache, a similar exception is logged:

      09:59:47,853 ERROR [org.infinispan.factories.impl.BasicComponentRegistryImpl] (ServerService Thread Pool -- 78) Error stopping component org.infinispan.persistence.manager.PersistenceManager: java.util.concurrent.CompletionException: java.lang.NullPointerException: No index info found for key: SessionMetaDataKey(SlbmKttMSStQY5URtO64K7aCMHYUsF5ntFc_sdvo) when processing file 0
	at org.infinispan@14.0.19.Final//org.infinispan.util.concurrent.CompletionStages.join(CompletionStages.java:89)
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.manager.PersistenceManagerImpl.stop(PersistenceManagerImpl.java:432)
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.support.DelegatingPersistenceManager.stop(DelegatingPersistenceManager.java:53)
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.support.CorePackageImpl$1.stop(CorePackageImpl.java:39)
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.support.CorePackageImpl$1.stop(CorePackageImpl.java:27)
	at org.infinispan@14.0.19.Final//org.infinispan.factories.impl.BasicComponentRegistryImpl.invokeStop(BasicComponentRegistryImpl.java:677)
	at org.infinispan@14.0.19.Final//org.infinispan.factories.impl.BasicComponentRegistryImpl.invokeStop(BasicComponentRegistryImpl.java:682)
	at org.infinispan@14.0.19.Final//org.infinispan.factories.impl.BasicComponentRegistryImpl.doStopWrapper(BasicComponentRegistryImpl.java:673)
	at org.infinispan@14.0.19.Final//org.infinispan.factories.impl.BasicComponentRegistryImpl.stopWrapper(BasicComponentRegistryImpl.java:661)
	at org.infinispan@14.0.19.Final//org.infinispan.factories.impl.BasicComponentRegistryImpl.stop(BasicComponentRegistryImpl.java:528)
	at org.infinispan@14.0.19.Final//org.infinispan.factories.AbstractComponentRegistry.internalStop(AbstractComponentRegistry.java:399)
	at org.infinispan@14.0.19.Final//org.infinispan.factories.AbstractComponentRegistry.stop(AbstractComponentRegistry.java:333)
	at org.infinispan@14.0.19.Final//org.infinispan.cache.impl.CacheImpl.performImmediateShutdown(CacheImpl.java:1062)
	at org.infinispan@14.0.19.Final//org.infinispan.cache.impl.CacheImpl.stop(CacheImpl.java:1029)
	at org.infinispan@14.0.19.Final//org.infinispan.cache.impl.AbstractDelegatingCache.stop(AbstractDelegatingCache.java:513)
	at org.infinispan@14.0.19.Final//org.infinispan.cache.impl.AbstractDelegatingCache.stop(AbstractDelegatingCache.java:513)
	at org.jboss.as.clustering.infinispan@30.0.0.Final-SNAPSHOT//org.jboss.as.clustering.infinispan.manager.DefaultCacheContainer$2.stop(DefaultCacheContainer.java:140)
	at org.wildfly.clustering.infinispan.embedded.service@30.0.0.Final-SNAPSHOT//org.wildfly.clustering.infinispan.service.CacheServiceConfigurator.accept(CacheServiceConfigurator.java:60)
	at org.wildfly.clustering.infinispan.embedded.service@30.0.0.Final-SNAPSHOT//org.wildfly.clustering.infinispan.service.CacheServiceConfigurator.accept(CacheServiceConfigurator.java:37)
	at org.wildfly.clustering.service@30.0.0.Final-SNAPSHOT//org.wildfly.clustering.service.FunctionalService.stop(FunctionalService.java:56)
	at org.wildfly.clustering.service@30.0.0.Final-SNAPSHOT//org.wildfly.clustering.service.AsyncServiceConfigurator$AsyncService.lambda$stop$1(AsyncServiceConfigurator.java:125)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
	at java.base/java.lang.Thread.run(Thread.java:1583)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.JBossThread.run(JBossThread.java:513)
Caused by: java.lang.NullPointerException: No index info found for key: SessionMetaDataKey(SlbmKttMSStQY5URtO64K7aCMHYUsF5ntFc_sdvo) when processing file 0
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.sifs.Compactor.compactSingleFile(Compactor.java:564)
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.sifs.Compactor.processRequest(Compactor.java:430)
	at org.infinispan@14.0.19.Final//org.infinispan.persistence.sifs.Compactor.lambda$start$0(Compactor.java:153)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.mixed.FlowableConcatMapCompletable$ConcatMapCompletableObserver.drain(FlowableConcatMapCompletable.java:187)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.mixed.ConcatMapXMainSubscriber.onNext(ConcatMapXMainSubscriber.java:106)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.flowable.FlowableObserveOn$ObserveOnSubscriber.runBackfused(FlowableObserveOn.java:444)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:174)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:324)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.runEager(ExecutorScheduler.java:289)
	at io.reactivex.rxjava3.rxjava@3.1.6//io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:250)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
	at org.wildfly.clustering.context@30.0.0.Final-SNAPSHOT//org.wildfly.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:32)
	at org.wildfly.clustering.context@30.0.0.Final-SNAPSHOT//org.wildfly.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:61)
	at java.base/java.lang.Thread.run(Thread.java:1583)

      As seen here: https://ci.wildfly.org/buildConfiguration/WF_PullRequest_LinuxJdk11/396167?hideProblemsFromDependencies=false&hideTestsFromDependencies=false&expandBuildChangesSection=true&expandBuildTestsSection=true

      Filing as blocker, since this regression prevents us from upgrading.

        1. server.log
          2.34 MB

              wburns@redhat.com Will Burns
              pferraro@redhat.com Paul Ferraro
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Created:
                Updated:
                Resolved: