Recover from fatal invalid cache state

[cdalexndr]

Ehcache 3.9.5

Stacktrace:

Caused by: java.lang.NullPointerException: null
	at org.ehcache.shadow.org.terracotta.offheapstore.disk.storage.FileBackedStorageEngine.findChunk(FileBackedStorageEngine.java:363) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.disk.storage.FileBackedStorageEngine.readKeyBuffer(FileBackedStorageEngine.java:264) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.storage.PortabilityBasedStorageEngine.readKey(PortabilityBasedStorageEngine.java:119) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.OffHeapHashMap$DirectEntry.<init>(OffHeapHashMap.java:1562) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.OffHeapHashMap$EntryIterator.create(OffHeapHashMap.java:1540) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.impl.internal.store.disk.factories.EhcachePersistentSegmentFactory$EhcachePersistentSegment$EntrySet$1.create(EhcachePersistentSegmentFactory.java:133) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.impl.internal.store.disk.factories.EhcachePersistentSegmentFactory$EhcachePersistentSegment$EntrySet$1.create(EhcachePersistentSegmentFactory.java:130) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.OffHeapHashMap$HashIterator.<init>(OffHeapHashMap.java:1400) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.OffHeapHashMap$EntryIterator.<init>(OffHeapHashMap.java:1535) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.AbstractLockedOffHeapHashMap$LockedEntryIterator.<init>(AbstractLockedOffHeapHashMap.java:385) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.impl.internal.store.disk.factories.EhcachePersistentSegmentFactory$EhcachePersistentSegment$EntrySet$1.<init>(EhcachePersistentSegmentFactory.java:130) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.impl.internal.store.disk.factories.EhcachePersistentSegmentFactory$EhcachePersistentSegment$EntrySet.iterator(EhcachePersistentSegmentFactory.java:130) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.concurrent.AbstractConcurrentOffHeapMap$AggregateEntrySet$1.getNextIterator(AbstractConcurrentOffHeapMap.java:454) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.concurrent.AbstractConcurrentOffHeapMap$AggregateIterator.<init>(AbstractConcurrentOffHeapMap.java:520) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.concurrent.AbstractConcurrentOffHeapMap$AggregateEntrySet$1.<init>(AbstractConcurrentOffHeapMap.java:450) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.shadow.org.terracotta.offheapstore.concurrent.AbstractConcurrentOffHeapMap$AggregateEntrySet.iterator(AbstractConcurrentOffHeapMap.java:450) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.impl.internal.store.offheap.AbstractOffHeapStore$1.<init>(AbstractOffHeapStore.java:501) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.impl.internal.store.offheap.AbstractOffHeapStore.iterator(AbstractOffHeapStore.java:500) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.impl.internal.store.tiering.TieredStore.iterator(TieredStore.java:234) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.core.SpecIterator.<init>(SpecIterator.java:39) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.core.EhcacheBase$Jsr107CacheBase.specIterator(EhcacheBase.java:645) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.jsr107.Eh107Cache.iterator_aroundBody54(Eh107Cache.java:503) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.ehcache.jsr107.Eh107Cache$AjcClosure55.run(Eh107Cache.java:1) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:167) ~[aspectjrt-1.9.6.jar:na]
	at pse.cache.CacheListenerAspect.around(CacheListenerAspect.java:38) ~[main/:na]
	at org.ehcache.jsr107.Eh107Cache.iterator(Eh107Cache.java:501) ~[ehcache-3.9.5.jar:3.9.5 ad079c948c87e261c36fd97fc51b65d927bbfde8]
	at pse.cache.CacheConfiguration.validateCache(CacheConfiguration.java:92) ~[main/:na]
	at pse.cache.CacheConfiguration.createCache(CacheConfiguration.java:85) ~[main/:na]
	at org.hibernate.cache.jcache.internal.JCacheRegionFactory.getOrCreateCache(JCacheRegionFactory.java:99) ~[hibernate-jcache-5.4.32.Final.jar:5.4.32.Final]
	at org.hibernate.cache.jcache.internal.JCacheRegionFactory.createDomainDataStorageAccess(JCacheRegionFactory.java:83) ~[hibernate-jcache-5.4.32.Final.jar:5.4.32.Final]
	at org.hibernate.cache.jcache.internal.JCacheRegionFactory.buildDomainDataRegion(JCacheRegionFactory.java:72) ~[hibernate-jcache-5.4.32.Final.jar:5.4.32.Final]
	at org.hibernate.cache.internal.EnabledCaching.prime(EnabledCaching.java:113) ~[hibernate-core-5.4.32.Final.jar:5.4.32.Final]
	at org.hibernate.metamodel.internal.MetamodelImpl.primeSecondLevelCacheRegions(MetamodelImpl.java:331) ~[hibernate-core-5.4.32.Final.jar:5.4.32.Final]
	at org.hibernate.metamodel.internal.MetamodelImpl.initialize(MetamodelImpl.java:160) ~[hibernate-core-5.4.32.Final.jar:5.4.32.Final]
	at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:303) ~[hibernate-core-5.4.32.Final.jar:5.4.32.Final]
	at org.hibernate.boot.internal.SessionFactoryBuilderImpl.build(SessionFactoryBuilderImpl.java:468) ~[hibernate-core-5.4.32.Final.jar:5.4.32.Final]
	at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl.build(EntityManagerFactoryBuilderImpl.java:1259) ~[hibernate-core-5.4.32.Final.jar:5.4.32.Final]
	at org.springframework.orm.jpa.vendor.SpringHibernateJpaPersistenceProvider.createContainerEntityManagerFactory(SpringHibernateJpaPersistenceProvider.java:58) ~[spring-orm-5.3.10.jar:5.3.10]
	at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.createNativeEntityManagerFactory(LocalContainerEntityManagerFactoryBean.java:365) ~[spring-orm-5.3.10.jar:5.3.10]
	at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.buildNativeEntityManagerFactory(AbstractEntityManagerFactoryBean.java:409) ~[spring-orm-5.3.10.jar:5.3.10]
	... 107 common frames omitted

My createCache method:

    private static org.ehcache.config.CacheConfiguration<Object, Object> DEFAULT_CACHE_CONFIGURATION =
            CacheConfigurationBuilder.newCacheConfigurationBuilder(
                    Object.class, Object.class,
                    ResourcePoolsBuilder.newResourcePoolsBuilder()
                            .heap( 10000, EntryUnit.ENTRIES )
                            .disk( 100, MemoryUnit.MB, true )
                            .build() )
                    .build();

    protected Cache<Object, Object> createCache( String regionName ) {
        Cache<Object, Object> cache = getCacheManager().createCache( regionName, Eh107Configuration.fromEhcacheCacheConfiguration( DEFAULT_CACHE_CONFIGURATION ) );
        validateCache( cache );
        return new FailSafeCacheWrapper( cache );
    }

My validateCache method:

public static void validateCache( Cache<?, ?> cache ) {
        try {
            Iterator<? extends Entry<?, ?>> it = cache.iterator();
            if (it.hasNext()) {
                Entry<?, ?> entry = it.next();
                Object key = entry.getKey();
                Object value = entry.getValue();
            }
        } catch (SerializerException ex) {
            //obsolete in case class serialization changed
            log.warn( String.format( "Found obsolete cache data: %s", cache.getName() ), ex );
            cache.clear();
        }
    }

The NullPointerException is propagated up so that my app fails to start.
I'm not sure, but this error can be due to a forced shutdown that left the cache in an invalid state.
Even if the cache is in an invalid state, it should not disrupt the application workflow. It should auto reset the cache and log an error.

[chrisdennis]

If this happens after a clean shutdown then we have something to investigate. If as you suggest this is only occurring after an improper (forced) shutdown then I'm reluctant to chase this particular goose. Cache corruption in these disk stores can cause pretty much any detectable or undetectable error including presenting a 'legal' cache state that is incorrect but indistinguishable from the correct state. The best (or only) way to reliably handle these situations would be to add a persistent "I was shutdown correctly" flag to the disk and then only attempt recovery if the flag is set.

[cdalexndr]

I've tried to investigate this issue, but there are no source distributions under org.ehcache.shadow package. This makes user investigations hard by relying on decompiled sources.

What's the proper workaround to recover from this invalid state, besides manually deleting cache directory?
I tried using cache.clear() but the issue is still present.
I want to implement a custom workaround to make an automatic cache reset so that the app can start. If this happens in production, it's not ok to force the user to log in to his server to delete the cache files manually....

[chrisdennis]

I was in the process of working up the best way of fixing this... but then my dev laptop decided that was the perfect time to become an expensive brick :(.

I think it should be possible to 'skin' the necessary services to be more robust around shutdown/startup, but that might be better coded as an actual addtion to the product code. The current best current solution is probably to have a sentinel file that you touch after a clean shutdown, and then check (and delete) on startup. If no file on startup you trash the whole directory (programmatically), otherwise you delete and continue. This is essentially what could (or should?) be coded internally, but probably in a more fine-grained manner to deal with the full variety of services that use the disk.