Suggestion: don't log stacktrace in case of a CancellationException

[Stephan202]

Caffeine logs a warning including stack trace if a Future completes exceptionally ((1), (2), (3), (4), maybe elsewhere). This is important for flows in which the exception isn't bubbled up, as it may otherwise hide application errors.

However, this code also logs a full stack trace if a Future is simply cancelled. The log line then states than a java.util.concurrent.CancellationException was thrown, while strictly speaking this exception was only created inside CompletableFuture#cancel(boolean).

My change request is this: would it be possible to identify CancellationExceptions and log those differently, e.g. as:

if (error instanceof CancellationException) {
  logger.log(Level.INFO, "Refresh task was cancelled");
} else {
  logger.log(Level.WARNING, "Exception thrown during refresh", error);
}

(This example is for the BoundedLocalCache case; I also changed WARNING to INFO, but have no strong opinion on that, actually.)

Context: we have a custom cache loader, and if its background bulk refresh logic can't keep up, it cancels the oldest refresh requests. When this happens a (very) large number of identical and rather uninformative stack traces is logged. In extreme cases this also causes our log agent to have trouble keeping up.

[ben-manes]

I think that's a good observation that cancellation should be special cased and is unlike the logging's intent. Do you think it should be logged at all? Either way seems reasonable to me, but I'd lean towards thinking cancellation is an explicit choice and expected if done, whereas most other exceptions are a surprise that the application is likely to silently swallow.

The same logic would also apply with TimeoutException (e.g. via orTimeout).

[Stephan202]

Do you think it should be logged at all?

I'd also be fine with not logging at all. Alternatively Level.TRACE could have the same effect in most setups. From our side either would be just fine. 👍

[Stephan202]

Tnx @ben-manes!

[ben-manes]

rolling this back from master as the CI is unhappy, but seems unrelated. If it fails only on the v3.dev branch then I'll have something to go off of, but I'm afraid it might be stuck failing on a prior green commit.

Unfortunately soft reference caching is flaky to test because we have to coerce the GC to maybe discard the entries. We do this using -XX:SoftRefLRUPolicyMSPerMB=0 and -XX:+UseParallelGC with Guava's GcFinalization.awaitFullGc(). That works most of the time and locally, but the CI is more finicky. That could be something minor like a new JDK patch release that tweaks the GC to break this, a VM's noisy neighbor causing fewer GCs due to cpu pressure, etc. It mostly. works but sometimes has bad days like now.

[ben-manes]

I'm not sure why, but debugging this and the slf4j-test logger causes the issues. There is nothing special about that logger, nothing is logged which would explain it, and it is cleared between tests. Either the logging tests should be dropped or the logger isolated so that it isn't used by the reference tests.

[ben-manes]

disabling the test loggers by default seems to have stabilized it.

[wpanas]

@ben-manes when this feature will be released? I'm looking forward to use it 😉

[ben-manes]

I'll take a look over the weekend. There haven't been many changes accumulated so I hadn't thought much about a release, but no harm to do so for these QoL touch ups.

[wpanas]

Thanks @ben-manes 😄 I would appreciate that!

[taaem]

@ben-manes would it also be possible to backport this to the 2.x.x releases? I'm looking forward to this in an application, which is sadly bound to Java 8 for now.

[ben-manes]

Perhaps, but please note that since this is logging you can easily handle it in your log configuration. A simple exception filter could be applied to this logger to ignore these cases. So while this change is nice, it really isn't necessary for anyone wanting this behavior. (See for example ch.qos.logback.core.filter.Filter if using logback)

[ben-manes]

Sorry for dragging my feet here. This is released in v2.9.3 and v3.0.5.