A soft-locked cache entry was removed already. Out of balance lock/unlock sequences?

Question

I'am using java 1.6, spring 2.5, hibernate 3.3.1 and ehcache 2.6.0. Programs is connected to two databases. There is two ehcache configurations, but in this case only one is used. At the end of the batch the programs return this error :

    2012-10-23 15:44:43,406 ERROR (AbstractReadWriteEhcacheAccessStrategy.java:159) - Cache dao.data.MyObject Key dao.data.MyObject#28 Lockable : null
A soft-locked cache entry was removed already. Out of balance lock/unlock sequences ?

What can produce this error ?

Answer 1

I'm being hit by this right now, so I'll share my findings.

First, some background:

• We use Hibernate 3.5.2 & EhCache 2.7.0
• There is only one database (another one is accessed for reading only, but no caching is used there, as it is updated externally), and single cache instance (no clustering)
• The problem happens upon update of an entity mapped with InheritanceType.JOINED and CacheConcurrencyStrategy.READ_WRITE (but not when we switch to NONSTRICT_READ_WRITE). Also, judging from code inspection, it would happen upon delete as well.

What I've found by debugging Hibernate and EhCache code:

1. Hibernate's EntityUpdateAction (in execute()) invokes EntityRegionAccessStrategy.lockItem()
2. EhCache's implementation (in AbstractReadWriteEhcacheAccessStrategy) changes mapping for given key from cached entity to a lock
3. Hibernate detects that entity is mapped to more than 1 table, and hence cache invalidation is required (see AbstractEntityPersister.isCacheInvalidationRequired())
4. It proceeds to call persister.getCacheAccessStrategy().remove(), which, in EhCache's implementation, removes mapping for given cache key. However, while Hibernate expects that that will in fact remove cached entity, with EhCache it removes the lock (which was put there in step 2.)
5. After transaction completion, in EntityUpdateAction.doAfterTransactionCompletion(), Hibernate detects that cache invalidation was required, and proceeds to call unlockItem(), which fails if there is no mapping for given cache key, resulting in error message you described

It seems to me that this is a problem in EhCache implementation of lockItem() and unlockItem() (in READ_WRITE case). It should not replace actual items with locks, but store locks separately. At very least, one could say that Hibernate and EhCache are not 100% compatible in this scenario.

Few final notes:

• It seems that this error is harmless and can be safely suppressed via log4j config.
• I've managed to repeat this in a different scenario (which boils down to same lock/remove/unlock sequence). This time, instead of joined inheritance, a native SQL was triggering the removal. Everything else is pretty much the same.
• Relevant bits of Hibernate and EhCache code: EntityRegionAccessStrategy, EntityAction, CollectionRegionAccessStrategy, CollectionAction and related implementing/extending concrete classes.

HTH