NPE when using optimistic locking with JbossCache 1.4.0.SP1,

[pkorros]

I am trying to setup JbossCache 1.4.0.sp1 to work with hibernate 3.2.GA using optimistic locking. When I use pessimistic locking I don;t have any errors but when I use OPTIMISTIC then I get many NullPointerExceptions when using optimistic locking with JbossCache 1.4.0.SP1, hibernate 3.2.GA.


The errors look like:
[org.jboss.cache.interceptors.TxInterceptor] There was a problem handling this request
java.lang.NullPointerException
at org.jboss.cache.interceptors.OptimisticNodeInterceptor.invoke(OptimisticNodeInterceptor.java:68) at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
at org.jboss.cache.interceptors.OptimisticCreateIfNotExistsInterceptor.invoke(OptimisticCreateIfNotExistsInterceptor.java:69)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:75)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:122)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:345)
at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:156)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:183)
at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:5520)
at org.jboss.cache.TreeCache.remove(TreeCache.java:3742)
at org.jboss.cache.TreeCache.remove(TreeCache.java:3297)
at org.hibernate.cache.OptimisticTreeCache.writeLoad(OptimisticTreeCache.java:76)
at org.hibernate.cache.TransactionalCache.put(TransactionalCache.java:55)
at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:156)
at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:842)
at org.hibernate.loader.Loader.doQuery(Loader.java:717)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
at org.hibernate.loader.Loader.doList(Loader.java:2144)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2028)
at org.hibernate.loader.Loader.list(Loader.java:2023)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:95)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1569)
at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:283)

My config file is like:
treecache.xml
...
org.jboss.cache.GenericTransactionManagerLookup
OPTIMISTIC
LOCAL
...

hibernate.cfg.xml
...
org.hibernate.cache.OptimisticTreeCacheProvider
...

any ideas on what is causing the error?

[manik]

This is odd, seems like the workspace node does not exist despite going through the CreateIfNotExists interceptor. Do you have some more logging around this, perhaps set it to TRACE level and get 25 messages before and say 5 messages after this stack trace? You could email this to me if it is too big to post here.

Thanks,
Manik

[pkorros]

Manik,

I sent the log file as you suggested to your email.

Thanks for the quick reply,
regards,

Panagiotis Korros

[manik]

This is an interesting exception - getting the Hibernate team involved. Can you confirm that this is using 3.2.0.GA? I see some log messages that should not be in 3.2.0.GA ... :S

[pkorros]

Yes I am using hibernate 3.2.GA.

From the manifest...
Implementation-Title: Hibernate3
Implementation-Version: 3.2.0.ga
Implementation-Vendor: hibernate.org
Hibernate-Version: 3.2.0.ga

Can you please tell me about those log messages?

[manik]

Hi,

This is related to http://jira.jboss.com/jira/browse/JBCACHE-767 and has to do with a bug in JBoss Cache 1.4.0.SP1.

I hope to release 1.4.0.SP2 fairly soon which will fix this, among others.

In the meanwhile, this is not a critical problem, just a scary stack trace in your logs, and it should not affect your app.

Cheers,
Manik

[manik]

Sorry about the misleading comment about the log messages I mentioned earlier - double checking, they seem fine.

[pkorros]

Thanks for your reply!

I just had the time to test this again using the OptimisticTreeCacheProvider and I also silenced the NPE by setting the TxInterceptor log level to WARN.

Now the system works ok with a single user but under load I get the following errors...

16:01:36,991 ERROR [StdServerSession] failed to commit/rollback
org.jboss.tm.JBossRollbackException: Unable to commit, tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=pkor/28, BranchQual=, localId=28] status=STATUS_NO_TRANSACTION; - nested throwable: (java.lang.RuntimeException: )
at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:372)
at org.jboss.tm.TxManager.commit(TxManager.java:240)
at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:351)
at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:905)
at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:170)
at org.jboss.mq.SpySession.run(SpySession.java:323)
at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:194)
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748)
at java.lang.Thread.run(Thread.java:595)
Caused by: java.lang.RuntimeException:
at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1091)
at org.jboss.cache.interceptors.OrderedSynchronizationHandler.beforeCompletion(OrderedSynchronizationHandler.java:75)
at org.jboss.tm.TransactionImpl.doBeforeCompletion(TransactionImpl.java:1491)
at org.jboss.tm.TransactionImpl.beforePrepare(TransactionImpl.java:1110)
at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:324)
... 8 more
Caused by: org.jboss.cache.CacheException: Real node for /com/oakgrovesystems/reactor/processMediation/hibernate/HibProcess/com.oakgrovesystems.reactor.processMediation.hibernate.HibProcess#101709 is null, and this wasn't newly created in this tx!
at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.simpleValidate(OptimisticValidatorInterceptor.java:122)
at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.validateNodes(OptimisticValidatorInterceptor.java:101)
at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:66)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:95)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
at org.jboss.cache.interceptors.TxInterceptor.runPreparePhase(TxInterceptor.java:804)
at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1069)
... 12 more

What does that mean? any clues?

[manik]

Investigating ...

[manik]

Hi,

What steps take place to lead up to this? Do you have a unit test that recreates this?

Cheers,
Manik

[pkorros]

I don't have a unit test but I could send you a trace if that helps you.

The problem is happening in a transaction that is starting from a Message driven bean and calls several Session beans (all have transaction required attributes). So all the method calls participate in the same transaction.
When I execute one message at a time everything works correctly but when I fill the queue with many messages (many concurrent transactions) the problem appears.

In the Session beans the hibernate session usage is like...
Session.open()
...
Session.find()
...
Session.close()

When the operation is real-only, or

Session.open()
...
Session.find()
...
Session.flush()
Session.close()

When the operation is read-write.

When I use pessimistic locking everything works ok. The problem appears only when I use the optimistic locking cache.

[pkorros]

I don't have a unit test but I could send you a trace if that helps you.

The problem is happening in a transaction that is starting from a Message driven bean and calls several Session beans (all have transaction required attributes). So all the method calls participate in the same transaction.
When I execute one message at a time everything works correctly but when I fill the queue with many messages (many concurrent transactions) the problem appears.

In the Session beans the hibernate session usage is like...
Session.open()
...
Session.find()
...
Session.close()

When the operation is real-only, or

Session.open()
...
Session.find()
...
Session.flush()
Session.close()

When the operation is read-write.

When I use pessimistic locking everything works ok. The problem appears only when I use the optimistic locking cache.

[klaus_erber]

Hello,

I have similar problems as pkorror in JBoss-4.0.5.GA.

After I have prevent the NPEs via the Log4j konfiguration, I get also STATUS_NO_TRANSACTION errors. Like this:

2006-10-30 14:37:00,734 WARN [WorkManager(3)-20] [org.hibernate.cache.OptimisticTreeCache] Unexpected optimistic lock check on inserting data
2006-10-30 14:37:00,859 ERROR [WorkManager(3)-20] [org.jboss.resource.adapter.jms.inflow.JmsServerSession] org.jboss.resource.adapter.jms.inflow.JmsServerSession@1c2a7f5 failed to commit/rollback
org.jboss.tm.JBossRollbackException: Unable to commit, tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=pc3275/212, BranchQual=, localId=212] status=STATUS_NO_TRANSACTION; - nested throwable: (java.lang.RuntimeException: )
 at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:372)
 at org.jboss.tm.TxManager.commit(TxManager.java:240)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession$XATransactionDemarcationStrategy.end(JmsServerSession.java:471)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:260)
 at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:204)
 at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:275)
 at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
 at java.lang.Thread.run(Thread.java:595)
Caused by: java.lang.RuntimeException:
 at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1091)
 at org.jboss.cache.interceptors.OrderedSynchronizationHandler.beforeCompletion(OrderedSynchronizationHandler.java:75)
 at org.jboss.tm.TransactionImpl.doBeforeCompletion(TransactionImpl.java:1491)
 at org.jboss.tm.TransactionImpl.beforePrepare(TransactionImpl.java:1110)
 at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:324)
 ... 7 more
Caused by: java.lang.NullPointerException
 at java.lang.Integer.compareTo(Integer.java:939)
 at java.lang.Integer.compareTo(Integer.java:35)
 at org.hibernate.util.ComparableComparator.compare(ComparableComparator.java:13)
 at org.hibernate.cache.OptimisticTreeCache$DataVersionAdapter.newerThan(OptimisticTreeCache.java:297)
 at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.simpleValidate(OptimisticValidatorInterceptor.java:124)
 at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.validateNodes(OptimisticValidatorInterceptor.java:101)
 at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:66)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
 at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:95)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
 at org.jboss.cache.interceptors.TxInterceptor.runPreparePhase(TxInterceptor.java:804)
 at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1069)
 ... 11 more

or this:

2006-10-30 13:30:47,301 ERROR [WorkManager(3)-23] [org.jboss.resource.adapter.jms.inflow.JmsServerSession] org.jboss.resource.adapter.jms.inflow.JmsServerSession@1550f21 failed to commit/rollback
org.jboss.tm.JBossRollbackException: Unable to commit, tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=pc3275/188, BranchQual=, localId=188] status=STATUS_NO_TRANSACTION; - nested throwable: (java.lang.RuntimeException: )
 at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:372)
 at org.jboss.tm.TxManager.commit(TxManager.java:240)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession$XATransactionDemarcationStrategy.end(JmsServerSession.java:471)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:260)
 at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:204)
 at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:275)
 at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
 at java.lang.Thread.run(Thread.java:595)
Caused by: java.lang.RuntimeException:
 at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1091)
 at org.jboss.cache.interceptors.OrderedSynchronizationHandler.beforeCompletion(OrderedSynchronizationHandler.java:75)
 at org.jboss.tm.TransactionImpl.doBeforeCompletion(TransactionImpl.java:1491)
 at org.jboss.tm.TransactionImpl.beforePrepare(TransactionImpl.java:1110)
 at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:324)
 ... 7 more
Caused by: org.jboss.cache.CacheException: DataNode [/stockdata/IntervalStatus/de.spiegel.pistats.db.stock.IntervalStatus#de.spiegel.pistats.db.stock.IntervalStatusPK@e10feb05] version org.hibernate.cache.OptimisticTreeCache$DataVersionAdapter@358a80 [current=1, previous=0, src=SingleTableEntityPersister(de.spiegel.pistats.db.stock.IntervalStatus)] is newer than workspace node org.hibernate.cache.OptimisticTreeCache$DataVersionAdapter@358a80 [current=1, previous=0, src=SingleTableEntityPersister(de.spiegel.pistats.db.stock.IntervalStatus)]
 at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.simpleValidate(OptimisticValidatorInterceptor.java:127)
 at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.validateNodes(OptimisticValidatorInterceptor.java:101)
 at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:66)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
 at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:95)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
 at org.jboss.cache.interceptors.TxInterceptor.runPreparePhase(TxInterceptor.java:804)
 at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1069)
 ... 11 more

This happens, when I have a little bit more load und only with optimistic locking.

Funny: Hibernate statitics are reporting second level cache hits, but there ist nothing in the cache (NumberOfNodes is 0).

I will now switch back to pessimistic locking, but I will be glad, when I here that optimistic locking is working, to optimize the throughput.

greeting
Klaus Erber

[manik]

Have you tried this with 1.4.1.BETA?

http://labs.jboss.com/portal/jbosscache/download/index.html

[pkorros]

I tested again using JBoss 1.4.1.BETA and I am getting numerous exceptions like this:

Caused by: org.jboss.cache.optimistic.DataVersioningException: Attempting to apply data version of type class org.hibernate.cache.OptimisticTreeCache$NonLockingDataVersion to a node that already contains version of type class org.jboss.cache.optimistic.DefaultDataVersion
at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.simpleValidate(OptimisticValidatorInterceptor.java:144)
at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.validateNodes(OptimisticValidatorInterceptor.java:110)
at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:75)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:99)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
at org.jboss.cache.interceptors.OptimisticReplicationInterceptor.invoke(OptimisticReplicationInterceptor.java:85)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
at org.jboss.cache.interceptors.TxInterceptor.runPreparePhase(TxInterceptor.java:859)
at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1124)
... 135 more