Brandon Zeeb opened SPR-11654 and commented

We rely heavily on the Spring Cache et al family of abstractions. While the JMX statistics available for some caches are useful, in day to day development and production debugging it's often been essential to know of a particular object was provided by an implementation of Cache or if a backing store (ie: the @Cacheable annotation) was consulted instead.

In short, can we please have some cursory logging at debug level when a value is fetched from a Cache (as in, the key produced a value) and when no value was available? Ideally, the key would be logged in both cases. Optionally, a 3rd log message can be given for the value (with key) at trace level.

I leave it to you to decide where this will go, so long as this is the default behavior.

1 votes, 2 watchers

Comment From: spring-projects-issues

Stéphane Nicoll commented

We already log the key (that can be improved) but regarding the cache hit/miss this may become a duplicate log with the caching providers log itself. With regard to cache miss, you can get that information by a log of your own in the annotated method.

We may consider adding a log for a cache hit. Any idea for the format? Thanks!

Comment From: spring-projects-issues

Stéphane Nicoll commented

Brandon, any feedback on this one? Thanks.

Comment From: spring-projects-issues

Brandon Zeeb commented

In my investigation, there is not an overlap with other providers. I scoured the EhCache source as well as running the root logger at TRACE and did not see any indication of cache hit/miss in the logs. In addition, by using a Spring Cache abstraction, we all hope to remove ourselves from implementation specific Cache provider details, so even if EhCache did have a logger, I would not care.

I do not have a requirement for the specific log format, but within the message it would prefer to see: 1. The key 2. Some statement that indicates a value was fetched from the Cache 3. A string representation of the Cache. This could be a cache name, a cache toString. I don't care so long as it's useful.

An example might be: Cache ${cache} gave value for key ${key} or A value was retrieved for key ${key} in Cache ${cache}

I put it to you to devise a log statement format that is consistent with your logging standards and any other existing patterns.

As a second statement, it would be valuable to log the retrieved Value as a String at TRACE level. It would also be preferable to only log the first N bytes or characters of this value. This is an optional requirement, but should also contain the key and cache name.

Comment From: spring-projects-issues

Stéphane Nicoll commented

Alright there are two additional TRACE logs for cache hit and cache miss events. Please try 4.2.0.BUILD-SNAPSHOT, available in a couple of hours.

Comment From: elab

I was trying to get some logging (like described by @phasebash above) for hit/miss but couldn't find a way to do that. Is it still possible?

I'm using with @Cacheable with Coffeine. Logging settings:

org.springframework.cache: trace
com.github.benmanes.caffeine: trace

But this only produces the output Computed cache key like

2020-06-11 03:19:54,969 TRACE [http-nio-8080-exec-9] o.s.cache.interceptor.CacheInterceptor   : Computed cache key ... for operation ...

Comment From: elab

It turned out that the hit/miss logging only happens for not synchronized contexts. I.e. for @Cacheable(..., sync = false) (which is the default). In this case, the log entries will be printed:

Cache entry for key '<key>' found in cache '<cache name>'
No cache entry for key '<key>' in cache(s) [<cache name(s)>]

If @Cacheable(..., sync = true) is specified, no logging take place unfortunately. Could it possible to add that logging for the "sync" case, too?