Problem with JBossCache configuration

[lgsw_sam]

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!

[manik]

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.

[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...?

[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)

[manik]

This is related to JBCACHE-894

Upgrading to JBoss Cache 1.4.1 should fix this.

[s0d0]

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

[manik]

Is there anything in the log about why afterCompletion fails?

[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?

[manik]

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

[lgsw_sam]

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