keepDataAfterExpired and loader exceptions

[rene-m-hernandez]

After deploying cache2k with a loader that always threw an exception, we experienced an OOM.

We originally had set keepDataAfterExpired=true (in combination with refreshAhead=true), with the desire to allow stale data to remain in the cache. Java docs:

  /**
   * Expired data is kept in the cache until the entry is evicted. This consumes memory,
   * but if the data is accessed again the previous data can be used by the cache loader
   * for optimizing (e.g. if-modified-since for a HTTP request). Default value: {@code false}
   *
   * @see AdvancedCacheLoader
   */

Unfortunately, when this is true, Cache2k appears to cache exceptions, which was completely unexpected (is this clearly documented somewhere?) Additionally, the default ExceptionPropagator appends a message to the original exception. These two behaviors combined lead to a cache entry that is an ever-growing exception so long as the cache loader continues to fail, eventually causing OOM.

Is there anyway to prevent exceptions from being cached? Our two options appear to be: keepDataAfterExpired=false (undesired), or provide a custom ExceptionPropagator that does not infinitely grow entries that contain exceptions.

An example exception (stored in the cache as an entry) that continued to grow:

! Causing: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:27:41.064, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:26:41.806, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:26:40.806, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:26:11.536, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:26:10.536, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:23:11.242, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:23:10.242, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:19:40.977, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:19:39.977, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:16:40.675, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:16:39.675, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:13:40.416, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:13:39.416, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:12:10.085, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:12:09.084, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:10:09.8, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:10:08.8, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:09:39.612, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:09:38.612, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:07:09.318, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:07:08.318, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:03:39.045, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:03:38.044, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:00:08.652, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 18:00:07.652, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:56:38.384, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:56:37.383, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:53:08.021, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:53:07.021, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:49:37.739, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:49:36.739, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:46:37.414, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:46:36.414, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:43:07.056, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:43:06.055, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:40:06.768, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:40:05.768, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:39:36.519, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:39:35.519, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:39:16.288, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:39:15.288, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:38:45.993, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:38:44.992, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:37:45.761, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:37:44.761, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:36:45.508, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:36:44.508, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:33:45.112, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:33:44.112, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:30:44.741, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:30:43.741, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:30:14.446, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:30:13.446, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:29:14.148, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:29:13.148, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:28:43.846, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:28:42.846, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:28:13.585, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:28:12.584, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:27:43.276, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:27:42.276, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:27:12.961, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:27:11.961, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:26:12.589, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:26:11.589, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:25:42.218, cause: org.cache2k.integration.CacheLoaderException: expiry=2020-10-19 17:25:41.218, cause: java.lang.RuntimeException: 

[cruftex]

Unfortunately, when this is true, Cache2k appears to cache exceptions, which was completely unexpected (is this clearly documented somewhere?)

Yes! There is a whole chapter on it: https://cache2k.org/docs/latest/user-guide.html#resilience-and-exceptions

Try setting resilienceDuration to 0

Additionally, the default ExceptionPropagator appends a message to the original exception. These two behaviors combined lead to a cache entry that is an ever-growing exception so long as the cache loader continues to fail, eventually causing OOM.

Are you speaking of one cache or is that multiple caches stacked together? Can you give some minimal code to reproduce that?

[cruftex]

Are you speaking of one cache or is that multiple caches stacked together? Can you give some minimal code to reproduce that?

Hmm, with more thought of it, I assume that you are accessing the previous entry in the cache loader.
Accessing the entry value leads consequently to an exception because the loader generated the exception in the first place.

I am currently working on a 2.0 version. I recall that I found some inconsistencies in 1.4 and 1.6. If an exception occurred the advanced loader might get a null entry or an entry with exception. The latest code is consistent and you get an entry with exception information from the previous load.

[rene-m-hernandez]

Unfortunately, I had read section 9 of the documentation and the behavior still remained unclear to me. There is mention of "Cached Exceptions", subsection header 9.7.4, but that refers to eternal entries. I did not mention in my original post that we have a custom expiryPolicy set. However, I did just see section 2.9 which clearly states that exceptions will be cached if an expiry is set.

Unfortunately, settings resilienceDuration(0) does not have the desired effect.

I will provide a code example first thing tomorrow!

[cruftex]

Also check your loader implementation. I assume that you do currentEntry.getValue in the loader, however, as the JavaDoc on that method says: @throws CacheLoaderException if loading produced an exception. To avoid that, you can do currentEntry.getException and check for an exception first.

[cruftex]

Unfortunately, settings resilienceDuration(0) does not have the desired effect.

Probably because it would just prevent an exception being cached by expiring that entry immediately. However, with
keepDataAfterExpired you still see the previous load result (which is expired) in the loader call. You would not see it anywhere else, since the cache will not hand out expired data.

[cruftex]

BTW, its good that you came up with this issue. Exception caching and resilience will not be enabled by default in 2.0
to avoid surprises: #164

However, that would not make a difference in your situation using the AdvancedCacheLoader and keepDataAfterExpired.
That is a separate logic. I see whether I can improve the documentation and detect that problem.

[rene-m-hernandez]

Also check your loader implementation. I assume that you do currentEntry.getValue in the loader, however, as the JavaDoc on that method says: @throws CacheLoaderException if loading produced an exception. To avoid that, you can do currentEntry.getException and check for an exception first.

@cruftex Sorry for not getting back to you sooner. The above quote was in fact the issue.

It wasn't that my loader was throwing a RuntimeException continuously, it was that i was calling currentEntry.getValue in the loader without checking currentEntry.getException != null. Behavior is different if AdvancedCacheLoader throws a RuntimException vs CacheLoaderException. In case of RuntimeException, everything works as expected. In case of CacheLoaderException (e.g. calling currentyEntry.getValue when currentEntry.getException != null), the Exception propagator will append to the existing entry as previously described infinitely growing the heap if the loader continues to throw the CacheLoaderException

[rene-m-hernandez]

An example:

package com.github.cache2k

import org.cache2k.Cache;
import org.cache2k.Cache2kBuilder;
import org.cache2k.CacheEntry;
import org.cache2k.integration.AdvancedCacheLoader;
import org.junit.Before;
import org.junit.Test;

public class Cache2kLoadFailure {
    private Cache<String, String> testCache;

    @Before
    public void before() {
        testCache = new Cache2kBuilder<String, String>() {}
                .name("heap-exhaustion-cache")
                .expiryPolicy((key, value, loadTime, oldEntry) -> 0)
                .keepDataAfterExpired(true)
                .refreshAhead(true)
                .loader(new AdvancedCacheLoader<String, String>() {
                    @Override
                    public String load(String key, long startTime, CacheEntry<String, String> currentEntry) {
                        if(currentEntry != null) { // Entry will be null at first run. This fills the entry with an exception at first
                            // if(currentEntry.getException != null) fixes the issue
                            currentEntry.getValue();
                        } 

                        throw new RuntimeException("Runtime exception");
                    }
                })
                .build();
    }

    @Test
    public void failLoop() {
        while(true) {
            // increase the upper bound of this loop to exhaust the heap quicker
            for(int i = 0; i < 100; i++) {
                String key = "test" + i;
                try {
                    testCache.get(key);
                } catch(Exception e) {

                }
            }
        }
    }
}

[cruftex]

@rene-m-hernandez No worries. Thanks for the feedback!

Using getValue in the loader is indeed an unfortunate pitfall. Code that does that will work perfectly until an
exception happens and then never recover.

Ideas:

Add behavior that detects a CacheLoaderException coming from a loader with the same cause then
currently in the entry and replace it with CyclicCacheLoaderException and hinder it from appending.

Maybe don't call the loader with an entry if the entry has an exception. Probably every loader would
ignore the exception anyways and do the same as no previous value is available.
That's a bit inconsistent with the rest of the cache, however, in the context of the loader it makes sense.
The whole resilience concept is about making the application more robust. This pitfall actually would
lead to the exactly opposite. The application might fail completely from just one exception.

[cruftex]

Delivered and released as preview: https://github.com/cache2k/cache2k/releases/tag/v1.9.2.Alpha