Key equality detection log message doesn't include key value

[zetlan]

In v3.1.2 release notes, you write that you "Added detection for when a key's equality has changed and corrupted the underlying map"; that error message is logged from BoundedLocalCache.logIfAlive().

In an application I manage we use LoadingCache fairly frequently, and we are seeing these messages in the logs, but they are always missing the value of node.getKeyReference(). Here's an example:

com.github.benmanes.caffeine.cache.BoundedLocalCache: An invalid state was detected that occurs if the keys equals or hashCode was modified while it resided in the cache. This violation of the Map contract can lead to non-deterministic behavior (key: {}).

There is clearly something wrong in our code that's triggering the error to occur in the first place, which is what I'm trying to troubleshoot, but lacking useful logging here I'm not sure where to look.

Would it be possible to:

• fix whatever is preventing the node key reference from being incorporated into the logs?
• add some debug-level logging to help identify the class of the node, or a stacktrace by which the cache lookup occurred, and/or something else helpful for troubleshooting?

[ben-manes]

Oh, thanks for raising this.

Including the class makes sense. This string looks like an empty Map, so maybe someone used that as a key and modified the map later on? Adding class type for context is a great idea.

For the exception it might not be as helpful as we'd hope. Most of the checks use requireIsAlive() which throws an IllegalStateException back to the caller. The logIfAlive() method is called during eviction, which by default runs on the ForkJoinPool.commonPool(). It is also called by Map.clear() / Cache.invalidateAll() which are not commonly used. It's a good idea though because you could then switch to a same thread executor (Runnable::run) and get the caller, so certainly a worthwhile change.

I don't think there are enough changes to warrant a release atm, but what do you think about running a patch jar? That's easy to do via jitpack, the snapshot repo, or your own repository.

[ben-manes]

Oh, this logging of {} is also my mistake of not using MessageFormat enough where that doesn't seem to be the correct syntax. I'll make sure that text formatting is asserted.

[ben-manes]

the ' started a literal string that needs to be escaped ('') and the parameters index ({0}). Sorry for not testing that explicitly.

[ben-manes]

It seems that formatting would be broken regardless due to SLF4J-529, so if you use slf4j it would not print out correctly. Instead formatting it explicit seems to be the best approach.

[zetlan]

Appreciate the fast response on this! I don't think I can run a patch in our "sanctioned" environments, but I can certainly clone the repo and install locally – especially if I can come up with a reproducible fail case on my end (I have a couple good candidates already). I'll grab the latest from the main branch & see how that goes.

[ben-manes]

Let me know if it's not easily reproducible and I'll cut a release. A minor version bump is far better than the aggravation and time wasted if it isn't apparent. You can use the sonatype snapshot repository or jitpack repository (fixed version by git hash) rather than building a jar locally.

[zetlan]

I think a release would be much simpler – our build/packaging system is complicated enough to make adding external repos rather difficult.

[zetlan]

@ben-manes I'm able to reliably reproduce the error though actually asserting against it is tricky. Here's a gist which should demonstrate the issue.

Assuming the new commit will successfully log the class name being used as the key – I think it will – that will be enough for me to track down the specific LoadingCache in our code and address.

Many, many thanks for your help on this.

[ben-manes]

Great, I’ll release it in a few minutes. You can look at my unit test updates too, where I capture the log message’s output to assert the contents.

[ben-manes]

Released 3.1.6. It will take a while to get through the CI action and show up on maven central (I think they have an SLA of 2 hours, but it has gotten better recently)

[ben-manes]

@zetlan I see the artifact on Central's repository. The search ui will take longer to update, but you can resolve it in your build if you update. Good luck!

[zetlan]

The hero I needed! Thanks @ben-manes – will holler if I see anything else amiss.