Cache abstraction does not log hit / miss for synchronized access

[elab]

General logging of hit / miss has been added in #16277.
For synchronized cache contexts (@Cacheable(sync=true)), no logging happens yet.
It's also not that straightforward, since in that case the mapping function will be passed directly to the Cache implementation (e.g. Caffeine) and Spring has no knowledge about if the mapper function has been called or if the returned value has been retrieved from the cache.

What we can do? I would propose to decorate the mapping function with an "invoked" flag (which will tell if the function has been invoked by the cache implementation) and with a logging for the "miss" case. The logging directly inside the function is necessary because we want to log misses before invocation of the underlying mapper function. The flag "invoked" is necessary to recognize the "hit" case (we can only definitely say that after the value has been returned from the cache implementation).

Here is the place in the code:

spring-framework/spring-context/src/main/java/org/springframework/cache/interceptor/CacheAspectSupport.java

Lines 377 to 384 in 1279b3b

	if (contexts.isSynchronized()) {
	CacheOperationContext context = contexts.get(CacheableOperation.class).iterator().next();
	if (isConditionPassing(context, CacheOperationExpressionEvaluator.NO_RESULT)) {
	Object key = generateKey(context, CacheOperationExpressionEvaluator.NO_RESULT);
	Cache cache = context.getCaches().iterator().next();
	try {
	return wrapCacheValue(method, cache.get(key, () -> unwrapReturnValue(invokeOperation(invoker))));
	}

The line return wrapCacheValue(method, cache.get(key, () -> unwrapReturnValue(invokeOperation(invoker)))); could be changed to something like that:

boolean[] invoked = new boolean[1];
Object returnValue = wrapCacheValue(method, cache.get(key, () -> {
    invoked[0] = true; // cache miss; log "miss" *before* calling the underlying mapper function
    if (logger.isTraceEnabled()) {
        logger.trace("No cache entry for key '" + key + "' in cache " + cache.getName());
    }
    unwrapReturnValue(invokeOperation(invoker)));
});
if (!invoked[0]) { // cache hit; log "hit" after retrieving the value from the cache
    if (logger.isTraceEnabled()) {
        logger.trace("Cache entry for key '" + key + "' found in cache '" + cache.getName() + "'");
    }
}
return returnValue;

What do you think? Perhaps any easier solution possible?

[elab]

Hi, is there any news on this issue?
We would like to switch to Spring's declarative caching control (@Cacheable annotation, synchronized) , but currently blocked by this issue, as we are required to log hits and misses.

[snicoll]

Thanks for the report and the suggestion. This is fixed in the upcoming 5.2.9 and 5.3.0.RC1. Feel free to give 5.2.9.BUILD-SNAPSHOT a try from https://repo.spring.io/snapshot. A new snapshot with the fix should be available in a few minutes.

[xenoterracide]

reading your patch... this was only fixed for synchronized? why not unsynchronized? why is it not for everything? I'm trying to figure out if I'm getting cache hits (seems to be misses), nothing is being logged for calls to this this method... even though I'm definitely calling it, it does seem to have cache misses.

2022-10-17 12:09:07.172 TRACE 77112 --- [  restartedMain] o.s.c.a.AnnotationCacheOperationSource   : Adding cacheable method 'findAll' with attribute: [Builder[public java.util.List com.capitalone.e1.domain.core.dmsr.BusinessDivisionRepository.findAll()] caches=[book-divisions] | key='' | keyGenerator='' | cacheManager='' | cacheResolver='' | condition='' | unless='' | sync='false']

just using simple cache per the reference docs as I have not configured anything regarding the cache starter.

spring.cache.cache-names=book-divisions
spring.cache.caffeine.spec=maximumSize=1000,expireAfterAccess=60s

[xenoterracide]

worth mentioning if the log isn't saying it that method has no arguments