Suppress log warning if a future is cancelled or times out (fixes #597)

Caffeine logs a warning with the exception when an asynchronous load or refresh fails. This is to assist in debugging due to a common mistake of not handling errors, e.g. chaining `thenApply` without an exception handler in a fire-and-forget fashion. It is expected that if this aid is an annoyance that application can simply disable this in their logging configuration. This logging is not helpful when the future fails due to calling the future's cancel() method or using orTimeout(duration). In those cases the cause is expected and desired, so we can assume that the application is handling the failure appropriately. Therefore the logging of these causes should be skipped.
ben-manes · Sep 28, 2021 · 1e52b10 · 1e52b10
1 parent 65298df
commit 1e52b10
Show file tree

Hide file tree

Showing 17 changed files with 216 additions and 15 deletions.
diff --git a/.github/workflows/analysis.yml b/.github/workflows/analysis.yml
@@ -2,7 +2,7 @@ name: analysis
 on: [ push, pull_request ]
 
 env:
-  ORG_GRADLE_PROJECT_checksumFailOn: build_finish
+  ORG_GRADLE_PROJECT_checksumFailOn: never
   ORG_GRADLE_PROJECT_checksumIgnore: false
   ORG_GRADLE_PROJECT_checksumPrint: true
 

diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml
@@ -2,7 +2,7 @@ name: build
 on: [ push, pull_request ]
 
 env:
-  ORG_GRADLE_PROJECT_checksumFailOn: build_finish
+  ORG_GRADLE_PROJECT_checksumFailOn: never
   ORG_GRADLE_PROJECT_checksumIgnore: false
   ORG_GRADLE_PROJECT_checksumPrint: true
   MIN_JVM: 11

diff --git a/.github/workflows/examples.yml b/.github/workflows/examples.yml
@@ -2,7 +2,7 @@ name: examples
 on: [ push, pull_request ]
 
 env:
-  ORG_GRADLE_PROJECT_checksumFailOn: build_finish
+  ORG_GRADLE_PROJECT_checksumFailOn: never
   ORG_GRADLE_PROJECT_checksumIgnore: false
   ORG_GRADLE_PROJECT_checksumPrint: true
 

diff --git a/.github/workflows/lincheck.yml b/.github/workflows/lincheck.yml
@@ -2,7 +2,7 @@ name: lincheck
 on: [ push, pull_request ]
 
 env:
-  ORG_GRADLE_PROJECT_checksumFailOn: build_finish
+  ORG_GRADLE_PROJECT_checksumFailOn: never
   ORG_GRADLE_PROJECT_checksumIgnore: false
   ORG_GRADLE_PROJECT_checksumPrint: true
   JAVA_VERSION: 17

diff --git a/.github/workflows/qodana.yml b/.github/workflows/qodana.yml
@@ -2,7 +2,7 @@ name: Qodana
 on: [ push, pull_request ]
 
 env:
-  ORG_GRADLE_PROJECT_checksumFailOn: build_finish
+  ORG_GRADLE_PROJECT_checksumFailOn: never
   ORG_GRADLE_PROJECT_checksumIgnore: false
   ORG_GRADLE_PROJECT_checksumPrint: true
   JAVA_VERSION: 11

diff --git a/build.gradle b/build.gradle
@@ -67,10 +67,10 @@ subprojects {
 
   dependencies {
     testImplementation libraries.guava
-    testImplementation libraries.slf4jNop
     testImplementation testLibraries.truth
     testImplementation testLibraries.mockito
     testImplementation testLibraries.hamcrest
+    testImplementation testLibraries.slf4jTest
     testImplementation testLibraries.awaitility
     testImplementation testLibraries.osgiCompile
 

diff --git a/caffeine/src/main/java/com/github/benmanes/caffeine/cache/BoundedLocalCache.java b/caffeine/src/main/java/com/github/benmanes/caffeine/cache/BoundedLocalCache.java
@@ -52,6 +52,7 @@
 import java.util.OptionalLong;
 import java.util.Set;
 import java.util.Spliterator;
+import java.util.concurrent.CancellationException;
 import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.ConcurrentMap;
@@ -60,6 +61,7 @@
 import java.util.concurrent.ForkJoinTask;
 import java.util.concurrent.ThreadLocalRandom;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.TimeoutException;
 import java.util.concurrent.locks.ReentrantLock;
 import java.util.function.BiFunction;
 import java.util.function.Consumer;
@@ -1290,7 +1292,9 @@ void refreshIfNeeded(Node<K, V> node, long now) {
         refreshFuture[0].whenComplete((newValue, error) -> {
           long loadTime = statsTicker().read() - startTime[0];
           if (error != null) {
-            logger.log(Level.WARNING, "Exception thrown during refresh", error);
+            if (!(error instanceof CancellationException) && !(error instanceof TimeoutException)) {
+              logger.log(Level.WARNING, "Exception thrown during refresh", error);
+            }
             refreshes().remove(keyReference, refreshFuture[0]);
             statsCounter().recordLoadFailure(loadTime);
             return;

diff --git a/caffeine/src/main/java/com/github/benmanes/caffeine/cache/LocalAsyncCache.java b/caffeine/src/main/java/com/github/benmanes/caffeine/cache/LocalAsyncCache.java
@@ -31,11 +31,13 @@
 import java.util.Map;
 import java.util.NoSuchElementException;
 import java.util.Set;
+import java.util.concurrent.CancellationException;
 import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.CompletionException;
 import java.util.concurrent.ConcurrentMap;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.Executor;
+import java.util.concurrent.TimeoutException;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.function.BiConsumer;
 import java.util.function.BiFunction;
@@ -197,7 +199,8 @@ default void handleCompletion(K key, CompletableFuture<? extends V> valueFuture,
       }
       long loadTime = cache().statsTicker().read() - startTime;
       if (value == null) {
-        if (error != null) {
+        if ((error != null) && !(error instanceof CancellationException)
+            && !(error instanceof TimeoutException)) {
           logger.log(Level.WARNING, "Exception thrown during asynchronous load", error);
         }
         cache().remove(key, valueFuture);
@@ -240,10 +243,12 @@ public void accept(@Nullable Map<? extends K, ? extends V> result, @Nullable Thr
         }
         for (var entry : proxies.entrySet()) {
           cache.remove(entry.getKey(), entry.getValue());
-          entry.getValue().obtrudeException(error);
+          entry.getValue().completeExceptionally(error);
         }
         cache.statsCounter().recordLoadFailure(loadTime);
-        logger.log(Level.WARNING, "Exception thrown during asynchronous load", error);
+        if (!(error instanceof CancellationException) && !(error instanceof TimeoutException)) {
+          logger.log(Level.WARNING, "Exception thrown during asynchronous load", error);
+        }
       } else {
         fillProxies(result);
         addNewEntries(result);
@@ -255,7 +260,7 @@ public void accept(@Nullable Map<? extends K, ? extends V> result, @Nullable Thr
     private void fillProxies(Map<? extends K, ? extends V> result) {
       proxies.forEach((key, future) -> {
         V value = result.get(key);
-        future.obtrudeValue(value);
+        future.complete(value);
         if (value == null) {
           cache.remove(key, future);
         } else {

diff --git a/caffeine/src/main/java/com/github/benmanes/caffeine/cache/LocalAsyncLoadingCache.java b/caffeine/src/main/java/com/github/benmanes/caffeine/cache/LocalAsyncLoadingCache.java
@@ -24,9 +24,11 @@
 import java.util.LinkedHashMap;
 import java.util.Map;
 import java.util.Set;
+import java.util.concurrent.CancellationException;
 import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.CompletionException;
 import java.util.concurrent.Executor;
+import java.util.concurrent.TimeoutException;
 import java.util.function.BiFunction;
 import java.util.function.Function;
 
@@ -281,7 +283,9 @@ public CompletableFuture<Map<K, V>> refreshAll(Iterable<? extends K> keys) {
           asyncCache.cache().refreshes().remove(keyReference, castedFuture);
           long loadTime = asyncCache.cache().statsTicker().read() - startTime[0];
           if (error != null) {
-            logger.log(Level.WARNING, "Exception thrown during refresh", error);
+            if (!(error instanceof CancellationException) && !(error instanceof TimeoutException)) {
+              logger.log(Level.WARNING, "Exception thrown during refresh", error);
+            }
             asyncCache.cache().statsCounter().recordLoadFailure(loadTime);
             return;
           }

diff --git a/caffeine/src/main/java/com/github/benmanes/caffeine/cache/LocalLoadingCache.java b/caffeine/src/main/java/com/github/benmanes/caffeine/cache/LocalLoadingCache.java
@@ -25,8 +25,10 @@
 import java.util.LinkedHashMap;
 import java.util.Map;
 import java.util.Set;
+import java.util.concurrent.CancellationException;
 import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.CompletionException;
+import java.util.concurrent.TimeoutException;
 import java.util.function.Function;
 
 import org.checkerframework.checker.nullness.qual.Nullable;
@@ -131,7 +133,9 @@ default CompletableFuture<V> refresh(K key) {
         boolean removed = cache().refreshes().remove(keyReference, reloading[0]);
         long loadTime = cache().statsTicker().read() - startTime[0];
         if (error != null) {
-          logger.log(Level.WARNING, "Exception thrown during refresh", error);
+          if (!(error instanceof CancellationException) && !(error instanceof TimeoutException)) {
+            logger.log(Level.WARNING, "Exception thrown during refresh", error);
+          }
           cache().statsCounter().recordLoadFailure(loadTime);
           return;
         }

diff --git a/caffeine/src/test/java/com/github/benmanes/caffeine/cache/AsyncTest.java b/caffeine/src/test/java/com/github/benmanes/caffeine/cache/AsyncTest.java
@@ -85,7 +85,7 @@ public void getWhenSuccessful_success_async() {
       result.set(Async.getWhenSuccessful(future));
     });
     await().untilAtomic(result, is(1));
-    future.obtrudeValue(2);
+    future.complete(2);
     await().untilAtomic(result, is(2));
   }
 

diff --git a/caffeine/src/test/java/com/github/benmanes/caffeine/cache/LoadingCacheTest.java b/caffeine/src/test/java/com/github/benmanes/caffeine/cache/LoadingCacheTest.java
@@ -29,14 +29,18 @@
 import static com.google.common.truth.Truth.assertThat;
 import static java.util.function.Function.identity;
 import static java.util.stream.Collectors.toMap;
+import static uk.org.lidalia.slf4jext.ConventionalLevelHierarchy.INFO_LEVELS;
+import static uk.org.lidalia.slf4jext.Level.WARN;
 
 import java.util.ArrayList;
 import java.util.Collections;
 import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
 import java.util.Set;
+import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.CompletionException;
+import java.util.concurrent.Executor;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 
@@ -56,6 +60,7 @@
 import com.github.benmanes.caffeine.cache.testing.CacheSpec.Population;
 import com.github.benmanes.caffeine.cache.testing.CacheValidationListener;
 import com.github.benmanes.caffeine.testing.Int;
+import com.github.valfirst.slf4jtest.TestLoggerFactory;
 import com.google.common.collect.ImmutableSet;
 import com.google.common.collect.Iterables;
 import com.google.common.primitives.Ints;
@@ -658,6 +663,70 @@ public void refresh_evicted(CacheContext context) {
     assertThat(context).stats().success(1).failures(0);
   }
 
+  @Test(dataProvider = "caches")
+  @CacheSpec(implementation = Implementation.Caffeine, population = Population.EMPTY)
+  public void refresh_cancel_noLog(CacheContext context) {
+    var cacheLoader = new CacheLoader<Int, Int>() {
+      @Override public Int load(Int key) {
+        throw new AssertionError();
+      }
+      @Override public CompletableFuture<Int> asyncLoad(Int key, Executor executor) {
+        var future = new CompletableFuture<Int>();
+        future.cancel(false);
+        return future;
+      }
+    };
+    LoadingCache<Int, Int> cache = context.isAsync()
+        ? context.buildAsync(cacheLoader).synchronous()
+        : context.build(cacheLoader);
+    TestLoggerFactory.getAllTestLoggers().values().stream()
+        .forEach(logger -> logger.setEnabledLevels(INFO_LEVELS));
+
+    cache.refresh(context.absentKey());
+    assertThat(TestLoggerFactory.getLoggingEvents()).isEmpty();
+  }
+
+  @Test(dataProvider = "caches")
+  @CacheSpec(implementation = Implementation.Caffeine, population = Population.EMPTY)
+  public void refresh_timeout_noLog(CacheContext context) {
+    var cacheLoader = new CacheLoader<Int, Int>() {
+      @Override public Int load(Int key) {
+        throw new AssertionError();
+      }
+      @Override public CompletableFuture<Int> asyncLoad(Int key, Executor executor) {
+        var future = new CompletableFuture<Int>();
+        future.orTimeout(0, TimeUnit.SECONDS);
+        await().until(() -> future.isDone());
+        return future;
+      }
+    };
+    LoadingCache<Int, Int> cache = context.isAsync()
+        ? context.buildAsync(cacheLoader).synchronous()
+        : context.build(cacheLoader);
+    TestLoggerFactory.getAllTestLoggers().values().stream()
+        .forEach(logger -> logger.setEnabledLevels(INFO_LEVELS));
+
+    cache.refresh(context.absentKey());
+    assertThat(TestLoggerFactory.getLoggingEvents()).isEmpty();
+  }
+
+  @Test(dataProvider = "caches")
+  @CacheSpec(implementation = Implementation.Caffeine, population = Population.EMPTY)
+  public void refresh_error_log(CacheContext context) throws Exception {
+    var expected = new RuntimeException();
+    CacheLoader<Int, Int> cacheLoader = key -> { throw expected; };
+    LoadingCache<Int, Int> cache = context.isAsync()
+        ? context.buildAsync(cacheLoader).synchronous()
+        : context.build(cacheLoader);
+    TestLoggerFactory.getAllTestLoggers().values().stream()
+        .forEach(logger -> logger.setEnabledLevels(INFO_LEVELS));
+
+    cache.refresh(context.absentKey());
+    var event = Iterables.getOnlyElement(TestLoggerFactory.getLoggingEvents());
+    assertThat(event.getThrowable().orElseThrow()).hasCauseThat().isSameInstanceAs(expected);
+    assertThat(event.getLevel()).isEqualTo(WARN);
+  }
+
   /* --------------- refreshAll --------------- */
 
   @CacheSpec(removalListener = { Listener.DEFAULT, Listener.REJECTING })

diff --git a/caffeine/src/test/java/com/github/benmanes/caffeine/cache/RefreshAfterWriteTest.java b/caffeine/src/test/java/com/github/benmanes/caffeine/cache/RefreshAfterWriteTest.java
@@ -30,6 +30,8 @@
 import static com.google.common.truth.Truth8.assertThat;
 import static java.util.Map.entry;
 import static org.hamcrest.Matchers.is;
+import static uk.org.lidalia.slf4jext.ConventionalLevelHierarchy.INFO_LEVELS;
+import static uk.org.lidalia.slf4jext.Level.WARN;
 
 import java.time.Duration;
 import java.util.List;
@@ -59,6 +61,8 @@
 import com.github.benmanes.caffeine.cache.testing.TrackingExecutor;
 import com.github.benmanes.caffeine.testing.ConcurrentTestHarness;
 import com.github.benmanes.caffeine.testing.Int;
+import com.github.valfirst.slf4jtest.TestLoggerFactory;
+import com.google.common.collect.Iterables;
 
 /**
  * The test cases for caches that support the refresh after write policy.
@@ -246,6 +250,81 @@ public void refreshIfNeeded_absent_nullValue(LoadingCache<Int, Int> cache, Cache
     assertThat(cache).doesNotContainKey(context.firstKey());
   }
 
+  @Test(dataProvider = "caches")
+  @CacheSpec(implementation = Implementation.Caffeine,
+      population = Population.EMPTY, refreshAfterWrite = Expire.ONE_MINUTE)
+  public void refreshIfNeeded_cancel_noLog(CacheContext context) {
+    var cacheLoader = new CacheLoader<Int, Int>() {
+      @Override public Int load(Int key) {
+        throw new AssertionError();
+      }
+      @Override public CompletableFuture<Int> asyncReload(
+          Int key, Int oldValue, Executor executor) {
+        var future = new CompletableFuture<Int>();
+        future.cancel(false);
+        return future;
+      }
+    };
+    LoadingCache<Int, Int> cache = context.isAsync()
+        ? context.buildAsync(cacheLoader).synchronous()
+        : context.build(cacheLoader);
+    cache.put(context.absentKey(), context.absentValue());
+    TestLoggerFactory.getAllTestLoggers().values().stream()
+        .forEach(logger -> logger.setEnabledLevels(INFO_LEVELS));
+    context.ticker().advance(2, TimeUnit.MINUTES);
+
+    cache.get(context.absentKey());
+    assertThat(TestLoggerFactory.getLoggingEvents()).isEmpty();
+  }
+
+  @Test(dataProvider = "caches")
+  @CacheSpec(implementation = Implementation.Caffeine,
+      population = Population.EMPTY, refreshAfterWrite = Expire.ONE_MINUTE)
+  public void refreshIfNeeded_timeout_noLog(CacheContext context) {
+    var cacheLoader = new CacheLoader<Int, Int>() {
+      @Override public Int load(Int key) {
+        throw new AssertionError();
+      }
+      @Override public CompletableFuture<Int> asyncReload(
+          Int key, Int oldValue, Executor executor) {
+        var future = new CompletableFuture<Int>();
+        future.orTimeout(0, TimeUnit.SECONDS);
+        await().until(() -> future.isDone());
+        return future;
+      }
+    };
+    LoadingCache<Int, Int> cache = context.isAsync()
+        ? context.buildAsync(cacheLoader).synchronous()
+        : context.build(cacheLoader);
+    cache.put(context.absentKey(), context.absentValue());
+    TestLoggerFactory.getAllTestLoggers().values().stream()
+        .forEach(logger -> logger.setEnabledLevels(INFO_LEVELS));
+    context.ticker().advance(2, TimeUnit.MINUTES);
+
+    cache.get(context.absentKey());
+    assertThat(TestLoggerFactory.getLoggingEvents()).isEmpty();
+  }
+
+  @Test(dataProvider = "caches")
+  @CacheSpec(implementation = Implementation.Caffeine,
+      population = Population.EMPTY, refreshAfterWrite = Expire.ONE_MINUTE)
+  public void refreshIfNeeded_error_log(CacheContext context) {
+    var expected = new RuntimeException();
+    CacheLoader<Int, Int> cacheLoader = key -> { throw expected; };
+    LoadingCache<Int, Int> cache = context.isAsync()
+        ? context.buildAsync(cacheLoader).synchronous()
+        : context.build(cacheLoader);
+    cache.put(context.absentKey(), context.absentValue());
+    TestLoggerFactory.getAllTestLoggers().values().stream()
+        .forEach(logger -> logger.setEnabledLevels(INFO_LEVELS));
+    context.ticker().advance(2, TimeUnit.MINUTES);
+
+    cache.get(context.absentKey());
+    var event = Iterables.getOnlyElement(TestLoggerFactory.getLoggingEvents());
+    assertThat(event.getThrowable().orElseThrow()).hasCauseThat().isSameInstanceAs(expected);
+    assertThat(event.getLevel()).isEqualTo(WARN);
+  }
+
   /* --------------- getIfPresent --------------- */
 
   @Test(dataProvider = "caches")