TwoPhaseCoordinator.beforeCompletion - failed for null
Hi
We really need your help!
The situation:
Bean A is stateless
Bean B is an MDB with @TransactionAttribute(TransactionAttributeType.NOT_SUPPORTED) on class level.
Bean A sends bean B a message. Bean B is invoked and begins a long running optimization job. Bean B regularly calls Bean A with its results. At some point Bean A decides that the result is sufficient and in the return value indicates to Bean B that is should persist its optimized solution.
Bean B calls bean A to persist the entire optimized solution through the below method. As you can see there are plenty of debug information to indicate the progress
@TransactionAttribute(TransactionAttributeType.REQUIRES_NEW)
public void persistAggregateResult(AggregateResult result) throws Exception
{
logger.debug("Enter persistAggregateResult method");
try
{
logger.debug("Dispatcher - Before Persist!");
entityManager.persist(result);
logger.debug("Dispatcher - Before Flush");
entityManager.flush();
logger.debug("Dispatcher - Before Refresh");
entityManager.refresh(result);
logger.debug("************** RESULT ************");
logger.debug(result.toString());
}
catch(Exception e)
{
logger.error("persistAggregateResult failed: "+e.getMessage());
throw e;
}
finally
{
logger.debug("Exit persistAggregateResult method");
}
}
We see that the persist, flush and refresh goes well as the id's within the AggregateResult object in fact has changed from 0 to a value consistent with DB sequences after the refresh.
We actually log the statement in the finally clause.
Then all the trouble begins. After a while, roughly equivalent to the configured JTA timeout, we get following WARN
2010-08-05 14:10:15,696 DEBUG [Bean A] (WorkManager(2)-12:) Exit persistAggregateResult method 2010-08-05 14:13:19,007 DEBUG [org.quartz.simpl.SimpleJobFactory] (ESBScheduler:jbossesb.esb:) Producing instance of Job 'ESBScheduler.ESBJ ob1',.jboss.soa.esb.schedule.SchedulerJob$ESBScheduledJob 2010-08-05 14:13:19,008 DEBUG [org.quartz.core.JobRunShell] (ESBScheduler:jbossesb.esb_Worker-0:) Calling execute on job ESBScheduler.ESBJo b1 2010-08-05 14:18:19,011 DEBUG [org.quartz.simpl.SimpleJobFactory] (ESBScheduler:jbossesb.esb:) Producing instance of Job 'ESBScheduler.ESBJ ob1',.jboss.soa.esb.schedule.SchedulerJob$ESBScheduledJob 2010-08-05 14:18:19,011 DEBUG [org.quartz.core.JobRunShell] (ESBScheduler:jbossesb.esb_Worker-0:) Calling execute on job ESBScheduler.ESBJo b1 2010-08-05 14:23:19,018 DEBUG [org.quartz.simpl.SimpleJobFactory] (ESBScheduler:jbossesb.esb:) Producing instance of Job 'ESBScheduler.ESBJ ob1',.jboss.soa.esb.schedule.SchedulerJob$ESBScheduledJob 2010-08-05 14:23:19,018 DEBUG [org.quartz.core.JobRunShell] (ESBScheduler:jbossesb.esb_Worker-0:) Calling execute on job ESBScheduler.ESBJo b1 2010-08-05 14:28:11,988 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-5:) [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id -3f57fef6:a960:4c5aa75e:1511 invoked while multiple threads active within it. 2010-08-05 14:28:11,990 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-5:) [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action -3f57fef6:a960:4c5aa75e:1511 aborting with 1 threads active! 2010-08-05 14:28:19,009 DEBUG [org.quartz.simpl.SimpleJobFactory] (ESBScheduler:jbossesb.esb:) Producing instance of Job 'ESBScheduler.ESBJ ob1',.jboss.soa.esb.schedule.SchedulerJob$ESBScheduledJob 2010-08-05 14:28:19,009 DEBUG [org.quartz.core.JobRunShell] (ESBScheduler:jbossesb.esb_Worker-0:) Calling execute on job ESBScheduler.ESBJo b1 2010-08-05 14:33:19,020 DEBUG [org.quartz.simpl.SimpleJobFactory] (ESBScheduler:jbossesb.esb:) Producing instance of Job 'ESBScheduler.ESBJ ob1',.jboss.soa.esb.schedule.SchedulerJob$ESBScheduledJob 2010-08-05 14:33:19,021 DEBUG [org.quartz.core.JobRunShell] (ESBScheduler:jbossesb.esb_Worker-0:) Calling execute on job ESBScheduler.ESBJo b1 2010-08-05 14:37:32,554 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (WorkManager(2)-12:) [com.arjuna.ats.arjuna.coordinator.TwoPhas eCoordinator_2] TwoPhaseCoordinator.beforeCompletion - failed for null javax.persistence.PersistenceException: java.lang.NullPointerException at org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:535) at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:114) at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:247) at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:86) at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177) at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1406) at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:134) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87) at org.jboss.aspects.tx.TxPolicy.endTransaction(TxPolicy.java:175) at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:87) at org.jboss.aspects.tx.TxInterceptor$RequiresNew.invoke(TxInterceptor.java:262) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:94) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:70) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77) at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:139) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:216) at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:186) at org.jboss.ejb3.stateless.StatelessLocalProxy.invoke(StatelessLocalProxy.java:81) at $Proxy153.persistAggregateResult(Unknown Source) - Bean A at ...persistAggregateResult(Bean B) at ...fireResultEvent(Bean B) at ...doContinue(Bean B) at ...run(Bean B) at ...onMessage(Bean B) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112) at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166) at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:57) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.tx.TxPolicy.invokeInNoTx(TxPolicy.java:66) at org.jboss.aspects.tx.TxInterceptor$NotSupported.invoke(TxInterceptor.java:112) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:70) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77) at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:139) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.mdb.MessagingContainer.localInvoke(MessagingContainer.java:262) at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.delivery(MessageInflowLocalProxy.java:268) at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:138) at $Proxy147.onMessage(Unknown Source) at org.jboss.resource.adapter.jms.inflow.JmsServerSession.onMessage(JmsServerSession.java:178) at org.jboss.jms.client.container.ClientConsumer.callOnMessageStatic(ClientConsumer.java:160) at org.jboss.jms.client.container.SessionAspect.handleRun(SessionAspect.java:831) at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect14.invoke(SessionAspect14.java) at org.jboss.jms.client.delegate.ClientSessionDelegate$run_N8003352271541955702.invokeNext(ClientSessionDelegate$run_N8003352271541955702.java) at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170) at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105) at org.jboss.jms.client.delegate.ClientSessionDelegate$run_N8003352271541955702.invokeNext(ClientSessionDelegate$run_N8003352271541955702.java) at org.jboss.jms.client.delegate.ClientSessionDelegate.run(ClientSessionDelegate.java) at org.jboss.jms.client.JBossSession.run(JBossSession.java:199) at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:237) at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:213) at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:275) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:756) at java.lang.Thread.run(Thread.java:595) Caused by: java.lang.NullPointerException at org.hibernate.collection.PersistentBag.equalsSnapshot(PersistentBag.java:80) at org.hibernate.engine.CollectionEntry.dirty(CollectionEntry.java:149) at org.hibernate.engine.CollectionEntry.preFlush(CollectionEntry.java:174) at org.hibernate.event.def.AbstractFlushingEventListener.prepareCollectionFlushes(AbstractFlushingEventListener.java:160) at org.hibernate.event.def.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:69) at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:26) at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000) at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338) at org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:523) ... 72 more
We figured out that it is the commit that fails but why?
What causes the nullPointerException? I mean all references within the AggregateResult object should have been resolved during the persist and/or the flush.
A little extra information: The AggregateResult object among others include a Collection with roughly 800.000 entries (ofcause none of them having null references)
We'd appreciate any help we can get with this.
Kind regards
Mads M Andersen