1 2 3 Previous Next 34 Replies Latest reply on Jan 29, 2007 6:16 PM by Manik Surtani

    NPE when using optimistic locking with JbossCache 1.4.0.SP1,

    Panagiotis Korros Newbie

      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?

        • 1. Re: NPE when using optimistic locking with JbossCache 1.4.0.
          Manik Surtani Master

          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

          • 2. Re: NPE when using optimistic locking with JbossCache 1.4.0.
            Panagiotis Korros Newbie

            Manik,

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

            Thanks for the quick reply,
            regards,

            Panagiotis Korros

            • 3. Re: NPE when using optimistic locking with JbossCache 1.4.0.
              Manik Surtani Master

              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

              • 4. Re: NPE when using optimistic locking with JbossCache 1.4.0.
                Panagiotis Korros Newbie

                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?

                • 5. Re: NPE when using optimistic locking with JbossCache 1.4.0.
                  Manik Surtani Master

                  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

                  • 6. Re: NPE when using optimistic locking with JbossCache 1.4.0.
                    Manik Surtani Master

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

                    • 7. Re: NPE when using optimistic locking with JbossCache 1.4.0.
                      Panagiotis Korros Newbie

                      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?

                      • 9. Re: NPE when using optimistic locking with JbossCache 1.4.0.
                        Manik Surtani Master

                        Hi,

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

                        Cheers,
                        Manik

                        • 10. Re: NPE when using optimistic locking with JbossCache 1.4.0.
                          Panagiotis Korros Newbie

                          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.

                          • 11. Re: NPE when using optimistic locking with JbossCache 1.4.0.
                            Panagiotis Korros Newbie

                            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.

                            • 12. Re: NPE when using optimistic locking with JbossCache 1.4.0.
                              Klaus Erber Newbie

                              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

                              • 14. Re: NPE when using optimistic locking with JbossCache 1.4.0.
                                Panagiotis Korros Newbie

                                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

                                1 2 3 Previous Next