9 Replies Latest reply on Jan 15, 2007 6:42 AM by Sami Männistö

    Problem with JBossCache configuration

    Sami Männistö Newbie

      Hi! I'm configuring JBossCache on our Jboss 4.0.5 server and now I'm getting a lot of log... I'm using Hibernate 3.2 and JbossCache 1.4 versions.

      When I start the server log gets filled with these INFO messages

      
      INFO [OptimisticNodeInterceptor] Cannot Handle Method _put(GlobalTransaction:<199.199.79.69:999>:1644, /ge/message/Customer/chains/ge.message.Customer.chains#191, item, CollectionCacheEntry[191], true, 0)
      
      


      and these WARN messages

      
      WARN [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.afterCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@41dc41dc
      
      


      Could someone tell me something about these messages?
      Do I have something wrong with my configs or why that INFO message keeps repeating?
      And what could cause the WARN messages? I couldn't find anything useful about it.

      Any info and help would be appreciated!


        • 1. Re: Problem with JBossCache configuration
          Manik Surtani Master

          The INFO message, which probably causes the cache to work incorrectly, is probably due to your using JBoss Cache with OPTIMISTIC locking while Hibernate is *not* configured with the OptimisticTreeCacheProvider.

          • 2. Re: Problem with JBossCache configuration
            Sami Männistö Newbie

            Hi! Thanks for reply!

            Now I have configured OptimisticTreeCacheProvider and got rid of
            Cannot Handle Method _put messages.
            But I still get those WARN messages....

            WARN [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.afterCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@4
            1dc41dc
            
            


            Any idea of what's causing them...?

            • 3. Re: Problem with JBossCache configuration
              Sami Männistö Newbie

              Now I am also getting these...

              13:56:48,033 WARN [TxInterceptor] Rolling back, exception encountered
              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.InvalidationInterceptor.invoke(InvalidationInterceptor.java:60)
               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.loadEntity(Loader.java:1851)
               at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48)
               at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42)
               at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:2992)
               at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:395)
               at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375)
               at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139)
               at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:195)
               at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:103)
               at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:878)
               at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:846)
               at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:557)
               at org.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:196)
               at org.hibernate.collection.PersistentSet.initializeFromCache(PersistentSet.java:124)
               at org.hibernate.cache.entry.CollectionCacheEntry.assemble(CollectionCacheEntry.java:35)
               at org.hibernate.event.def.DefaultInitializeCollectionEventListener.initializeCollectionFromCache(DefaultInitializeCollectionEventListener.java:130)
               at org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:48)
               at org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1716)
               at org.hibernate.collection.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:344)
               at org.hibernate.collection.AbstractPersistentCollection.read(AbstractPersistentCollection.java:86)
               at org.hibernate.collection.PersistentSet.iterator(PersistentSet.java:163)
              
              


              • 4. Re: Problem with JBossCache configuration
                Manik Surtani Master

                This is related to JBCACHE-894

                Upgrading to JBoss Cache 1.4.1 should fix this.

                • 5. Re: Problem with JBossCache configuration
                  Juha Moisio Newbie

                  Hi,

                  I'm LGSW_Sam's colleague.
                  We have now updated jboss cache to 1.4.1GA.

                  We are still getting

                  10:49:34,285 WARN [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.afterCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@247e247e
                  


                  Those NPE problems went away.

                  Br,

                  Juha


                  • 6. Re: Problem with JBossCache configuration
                    Manik Surtani Master

                    Is there anything in the log about why afterCompletion fails?

                    • 7. Re: Problem with JBossCache configuration
                      Sami Männistö Newbie

                      Hi Manik!

                      I can't see anything in the log for why afterCompletion fails...

                      This is the first occurence in log.

                      2007-01-13 13:35:40,068 INFO [STDOUT] Creating SchedulerService
                      2007-01-13 13:35:41,221 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.aft
                      erCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@3f8e3f8e
                      2007-01-13 13:35:41,239 INFO [STDOUT] SchedulerService - Starting
                      


                      This is the second occurence.
                      2007-01-13 13:35:58,434 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished commit phase
                      2007-01-13 13:35:58,434 TRACE [org.jboss.cache.interceptors.TxInterceptor] Running beforeCompletion on gtx GlobalTransaction:<192.194.71.62:41124>:1
                      2007-01-13 13:35:58,434 TRACE [org.jboss.cache.interceptors.TxInterceptor] No modifications in this tx. Skipping beforeCompletion()
                      2007-01-13 13:35:58,869 TRACE [org.jboss.cache.interceptors.TxInterceptor] calling aftercompletion for GlobalTransaction:<192.194.71.62:41124>:1
                      2007-01-13 13:35:58,869 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Running commit phase. One phase? false
                      2007-01-13 13:35:58,869 TRACE [org.jboss.cache.interceptors.TxInterceptor] running commit for GlobalTransaction:<192.194.71.62:41124>:1
                      2007-01-13 13:35:58,869 DEBUG [org.jboss.cache.interceptors.OptimisticValidatorInterceptor] commiting validated changes
                      2007-01-13 13:35:58,869 TRACE [org.jboss.cache.interceptors.InvalidationInterceptor] (192.194.71.62:41124) method call commit; id:11(GlobalTransaction:<192.1
                      94.71.62:41124>:1)
                      2007-01-13 13:35:58,869 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished local commit/rollback method for GlobalTransaction:<192.194.71.62:41124>:1
                      2007-01-13 13:35:58,869 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished commit phase
                      2007-01-13 13:35:58,871 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.aft
                      erCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@a000a
                      2007-01-13 13:35:58,887 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.aft
                      erCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@523e523e
                      2007-01-13 13:35:58,951 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.aft
                      erCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@4e884e88
                      2007-01-13 13:35:58,951 INFO [STDOUT] Starting checker....
                      2007-01-13 13:35:58,968 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.aft
                      erCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@a760a76
                      


                      This is the third occurence.
                      2007-01-13 13:35:59,548 INFO [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule: first pass
                      2007-01-13 13:35:59,550 INFO [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - fi
                      rst pass
                      2007-01-13 13:35:59,552 INFO [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pa
                      ss
                      2007-01-13 13:35:59,594 DEBUG [Sonic Resource Adapter for JCA] Timer-13 XAResource=1456363214
                      XAResourceWrapper.leaveTransaction: GlobalId=1--3f3db8c2:a43f:45a8c3c6:12f0, BranchQual=-3f3db8c2:a43f:45a8c3c6:130a
                      2007-01-13 13:35:59,607 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.aft
                      erCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@2caa2caa
                      2007-01-13 13:36:01,023 TRACE [org.jboss.cache.interceptors.TxInterceptor] (192.194.71.62:41124) call on method [_get; id:26(/fi/logiasoftware/messageserver/
                      config/Environment/fi.logiasoftware.messageserver.config.Environment#1, item, true)]
                      2007-01-13 13:36:01,023 TRACE [org.jboss.cache.interceptors.TxInterceptor] Creating transaction for thread Thread[Timer-14,5,jboss]
                      2007-01-13 13:36:01,026 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[Timer-
                      14,5,jboss]
                      2007-01-13 13:36:01,026 TRACE [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is null
                      


                      Next two log chapters occures very often. And are nearly same each time.
                      2007-01-13 13:36:01,919 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished commit phase
                      2007-01-13 13:36:01,973 TRACE [org.jboss.cache.interceptors.TxInterceptor] Running beforeCompletion on gtx GlobalTransaction:<192.194.71.62:41124>:2609
                      2007-01-13 13:36:01,974 TRACE [org.jboss.cache.interceptors.TxInterceptor] No modifications in this tx. Skipping beforeCompletion()
                      2007-01-13 13:36:01,975 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.aft
                      erCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@50b050b0
                      2007-01-13 13:36:01,975 TRACE [org.jboss.cache.interceptors.TxInterceptor] calling aftercompletion for GlobalTransaction:<192.194.71.62:41124>:2609
                      2007-01-13 13:36:01,975 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Running commit phase. One phase? false
                      2007-01-13 13:36:01,975 TRACE [org.jboss.cache.interceptors.TxInterceptor] running commit for GlobalTransaction:<192.194.71.62:41124>:2609
                      2007-01-13 13:36:01,975 DEBUG [org.jboss.cache.interceptors.OptimisticValidatorInterceptor] commiting validated changes
                      2007-01-13 13:36:01,975 TRACE [org.jboss.cache.interceptors.InvalidationInterceptor] (192.194.71.62:41124) method call commit; id:11(GlobalTransaction:<192.1
                      94.71.62:41124>:2609)
                      2007-01-13 13:36:01,975 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished local commit/rollback method for GlobalTransaction:<192.194.71.62:41124>:
                      2609
                      2007-01-13 13:36:01,975 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished commit phase
                      



                      007-01-13 13:36:02,150 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished commit phase
                      2007-01-13 13:36:02,150 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_4] TwoPhaseCoordinator.aft
                      erCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@7f547f54
                      2007-01-13 13:36:02,151 TRACE [org.jboss.cache.interceptors.TxInterceptor] (192.194.71.62:41124) call on method [_get; id:26(/fi/logiasoftware/messageserver/
                      config/Customer/chains/fi.logiasoftware.messageserver.config.Customer.chains#4, item, true)]
                      2007-01-13 13:36:02,151 TRACE [org.jboss.cache.interceptors.TxInterceptor] Creating transaction for thread Thread[Timer-14,5,jboss]
                      2007-01-13 13:36:02,153 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[Timer-
                      14,5,jboss]
                      2007-01-13 13:36:02,154 TRACE [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is null
                      2007-01-13 13:36:02,154 TRACE [org.jboss.cache.TreeCache] created new GTX: GlobalTransaction:<192.194.71.62:41124>:2628, local TX=TransactionImple < ac, Basi
                      cAction: -3f3db8c2:a43f:45a8c3c6:14e9 status: 0 >
                      2007-01-13 13:36:02,154 TRACE [org.jboss.cache.interceptors.TxInterceptor] Registering sync handler for tx TransactionImple < ac, BasicAction: -3f3db8c2:a43f
                      :45a8c3c6:14e9 status: 0 >, gtx GlobalTransaction:<192.194.71.62:41124>:2628
                      


                      Could this message relate to JBTM-182 or JBTM-183 bug?

                      • 8. Re: Problem with JBossCache configuration
                        Manik Surtani Master

                        I can't say for sure. Possibly something you may want to raise on the JBoss Transactions user forum.

                        • 9. Re: Problem with JBossCache configuration
                          Sami Männistö Newbie

                          It's just weird that this messages appeared after configuring JBossCache... Everything seemed to be fine and no WARN messages before that...