-
1. Re: Problem with JBossCache configuration
manik Jan 11, 2007 8:23 AM (in response to lgsw_sam)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
lgsw_sam Jan 12, 2007 5:20 AM (in response to lgsw_sam)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
lgsw_sam Jan 12, 2007 6:58 AM (in response to lgsw_sam)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 Jan 12, 2007 8:50 AM (in response to lgsw_sam)This is related to JBCACHE-894
Upgrading to JBoss Cache 1.4.1 should fix this. -
5. Re: Problem with JBossCache configuration
s0d0 Jan 13, 2007 3:47 AM (in response to lgsw_sam)Hi,
I'm LGSW_Sam's colleague.
We have now updated jboss cache to 1.4.1GA.
We are still getting10: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 Jan 15, 2007 5:39 AM (in response to lgsw_sam)Is there anything in the log about why afterCompletion fails?
-
7. Re: Problem with JBossCache configuration
lgsw_sam Jan 15, 2007 6:29 AM (in response to lgsw_sam)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 Jan 15, 2007 6:36 AM (in response to lgsw_sam)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
lgsw_sam Jan 15, 2007 6:42 AM (in response to lgsw_sam)It's just weird that this messages appeared after configuring JBossCache... Everything seemed to be fine and no WARN messages before that...