1 Reply Latest reply on Oct 8, 2010 2:30 AM by Mads Moelgaard Andersen

    TwoPhaseCoordinator.beforeCompletion - failed for null

    Mads Moelgaard Andersen Newbie

      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

        • 1. Re: TwoPhaseCoordinator.beforeCompletion - failed for null
          Mads Moelgaard Andersen Newbie

          Hi

           

          To those that might be interested.

           

          This was caused by a circular reference between attributes on two entities with many-to-one relations. Accidentally we set the references on both attributes on both entities. The result was as massive amount of iterations (10 to the 15th power) in order to resolve its commit. Of cause this would result in a transaction timeout regardless of how much we extended the timeout.

           

          The moment we stopped setting the reference from the one-part of the relation to the many-part of the relation it all worked.

           

          best regards

          Mads M Andersen