NPE occurs when using Infinispan as L2 Cache

Description

Pretty much randomly or so it seems, infinispan hibernate layer will throw a NPE. It occurs a lot when the j2EE server is started and overtime (once caches are warmer?) diminish.

The issue comes from the PutFromLoadValidator.Java(565).The cleaned element is null and the map.put(cleaned) fails since the key is coming from the cleaned element (cleaned.owner).

Complete stacktraces, the first on entity loading and the later on collection loading:

Cause: java.lang.NullPointerException

at org.hibernate.cache.infinispan.access.PutFromLoadValidator$PendingPut.access$700(PutFromLoadValidator.java:674)
at org.hibernate.cache.infinispan.access.PutFromLoadValidator$PendingPutMap.put(PutFromLoadValidator.java:627)
at org.hibernate.cache.infinispan.access.PutFromLoadValidator.cleanOutdatedPendingPuts(PutFromLoadValidator.java:565)
at org.hibernate.cache.infinispan.access.PutFromLoadValidator.preventOutdatedPendingPuts(PutFromLoadValidator.java:493)
at org.hibernate.cache.infinispan.access.PutFromLoadValidator.registerPendingPut(PutFromLoadValidator.java:438)
at org.hibernate.cache.infinispan.access.TransactionalAccessDelegate.get(TransactionalAccessDelegate.java:66)
at org.hibernate.cache.infinispan.entity.TransactionalAccess.get(TransactionalAccess.java:36)
at org.hibernate.engine.BatchFetchQueue.isCached(BatchFetchQueue.java:278)
at org.hibernate.engine.BatchFetchQueue.getEntityBatch(BatchFetchQueue.java:253)
at org.hibernate.loader.entity.BatchingEntityLoader.load(BatchingEntityLoader.java:90)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3270)
at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:496)
at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:477)
at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227)
at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:285)
at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152)
at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1080)
at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1028)
at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:623)
at org.hibernate.type.EntityType.resolve(EntityType.java:431)
at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:140)
at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:898)
at org.hibernate.loader.Loader.doQuery(Loader.java:773)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:270)
at org.hibernate.loader.Loader.loadEntityBatch(Loader.java:2047)
at org.hibernate.loader.entity.BatchingEntityLoader.load(BatchingEntityLoader.java:99)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3270)
at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:496)
at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:477)
at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227)
at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:285)
at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152)
at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1080)
at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1028)
at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:623)
at org.hibernate.type.EntityType.resolve(EntityType.java:431)
at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:140)
at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:898)
at org.hibernate.loader.Loader.doQuery(Loader.java:773)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:270)
at org.hibernate.loader.Loader.doList(Loader.java:2449)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2192)
at org.hibernate.loader.Loader.list(Loader.java:2187)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:452)
at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1258)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)

Cause: java.lang.NullPointerException

at org.hibernate.cache.infinispan.access.PutFromLoadValidator$PendingPut.access$700(PutFromLoadValidator.java:674)
at org.hibernate.cache.infinispan.access.PutFromLoadValidator$PendingPutMap.put(PutFromLoadValidator.java:627)
at org.hibernate.cache.infinispan.access.PutFromLoadValidator.cleanOutdatedPendingPuts(PutFromLoadValidator.java:565)
at org.hibernate.cache.infinispan.access.PutFromLoadValidator.preventOutdatedPendingPuts(PutFromLoadValidator.java:493)
at org.hibernate.cache.infinispan.access.PutFromLoadValidator.registerPendingPut(PutFromLoadValidator.java:438)
at org.hibernate.cache.infinispan.access.TransactionalAccessDelegate.get(TransactionalAccessDelegate.java:66)
at org.hibernate.cache.infinispan.collection.TransactionalAccess.get(TransactionalAccess.java:36)
at org.hibernate.engine.BatchFetchQueue.isCached(BatchFetchQueue.java:295)
at org.hibernate.engine.BatchFetchQueue.getCollectionBatch(BatchFetchQueue.java:203)
at org.hibernate.loader.collection.BatchingCollectionInitializer.initialize(BatchingCollectionInitializer.java:73)
at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:628)
at org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:83)
at org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1853)
at org.hibernate.collection.AbstractPersistentCollection.forceInitialization(AbstractPersistentCollection.java:479)
at org.hibernate.engine.StatefulPersistenceContext.initializeNonLazyCollections(StatefulPersistenceContext.java:899)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:275)
at org.hibernate.loader.Loader.doList(Loader.java:2449)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2192)
at org.hibernate.loader.Loader.list(Loader.java:2187)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:452)
at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1258)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)

For now I am masking this class with my own which essentially is a copy and paste but added a null check before trying to put back the element.
How the big question is : Is it normal that the element can be null and it's a simple null check that has been forgotten or the element should never be null and something bigger is going on ?

Environment

Hib 3.5.6
Infinispan 4.2.0.ALPHA2

(same thing happen with Hib 3.5.5 and IS 4.1.0.FINAL)

Activity

Show:
Galder Zamarreno
October 18, 2010, 6:25 PM

Chris, the code where this is coming from is relatively complex and so it's not a straightforward thing to figure out what the cause is, and whether the cause is a valid one and should protect against, or whether instead is a bug somewhere else in the code.

Unfortunately, there's not much logging in this area, so I don't think it'd help much unless it can clarify the following doubt I have:

Are you accessing Hibernate within transactions or not? If you're using transactions, what type of transactions and which is the transaction manager that you're using? Can you attach your hibernate configuration file?

Also, if you're using transactions, I'd like to understand the flow of transactions and whether a particular transaction can be accessed by different threads.

Based on what I've seen, a particular key can either be cleaned up:

a) This is materially impossible but by the same thread twice a row. I can't see how this can happen cos the same thread, concurrently would need to call one of the operations that can cleanup the pending map.

b) By the same transaction twice in a row. Now, if your transactions can span multiple threads, two parts of the same transaction might be calling clean up of the same key and since their transaction would be the same, this could be a possibility.

Brian Stansberry
October 19, 2010, 2:49 AM

I think this is the correct fix:

  1.  

    1.  

      1. Eclipse Workspace Patch 1.0
        #P hibernate-infinispan
        Index: src/main/java/org/hibernate/cache/infinispan/access/PutFromLoadValidator.java
        ===================================================================

      • src/main/java/org/hibernate/cache/infinispan/access/PutFromLoadValidator.java (revision 20852)
        +++ src/main/java/org/hibernate/cache/infinispan/access/PutFromLoadValidator.java (working copy)
        @@ -266,7 +266,7 @@
        PendingPutMap pending = pendingPuts.get(key);
        if (pending != null) {
        if (pending.size() == 0) {

  • pendingPuts.remove(key);
    + pendingPuts.remove(key, pending);
    }
    pending.releaseLock();
    }
    @@ -560,11 +560,13 @@
    if (map.acquireLock(100, TimeUnit.MILLISECONDS)) {
    try {
    PendingPut cleaned = map.remove(toClean.owner);

  • if (toClean.equals(cleaned) == false) {

  • // Oops. Restore it.

  • map.put(cleaned);
    + if (toClean.equals(cleaned) == false) {
    + if (cleaned != null) {
    + // Oops. Restore it.
    + map.put(cleaned);
    + }
    } else if (map.size() == 0) {

  • pendingPuts.remove(toClean.key);
    + pendingPuts.remove(toClean.key, map);
    }
    }
    finally {

The changes to pendingPuts.remove are not directly related to this issue; just I think they are the right thing to do.

What's happening is a race to the PendingPutMap lock between a thread cleaning an "outdated" pending put and either another thread doing the same, or the put itself coming in and cleaning it. For the losing thread, PendingPut cleaned = map.remove(toClean.owner); is returning null, since the winning thread already did the removal.

Galder Zamarreno
October 19, 2010, 10:42 AM

Fixed in 3.5.x, 3.6.x and trunk branches.

AlfredA
October 20, 2010, 5:22 AM
Edited

Thanks Brian and Galder !

Steve Ebersole
March 21, 2011, 7:09 PM

Bulk closing stale resolved issues

Fixed

Assignee

Galder Zamarreno

Reporter

AlfredA

Fix versions

Labels

None

backPortable

None

Suitable for new contributors

None

Requires Release Note

None

Pull Request

None

backportDecision

None

Affects versions

Priority

Critical
Configure