Uploaded image for project: 'Causeway'
  1. Causeway
  2. CAUSEWAY-3654

Audit Trail can result in NPE, causing xactn to rollback, in some circumstances

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 2.0.0-RC3
    • 2.0.0-RC4
    • Ext Sec AuditTrail
    • None

    Description

      The code that triggered queued up commands and ran them in the background queue.  What the stack trace shows is that we have encountered a hollow entity while the InteractionService attempts to commit the transaction (as it winds down the interaction stack to 0).  The transition to hollow only happens on commit, so it means that there was another commit already.

      I captured a stack traces  to see where the entity was being transitioned to hollow:

      "quartzScheduler_Worker-8@21526" prio=5 tid=0x9f nid=NA runnable
      
      java.lang.Thread.State: RUNNABLE
          at org.apache.isis.persistence.jdo.datanucleus.entities.DnOidStoreAndRecoverHelper.storeOid(DnOidStoreAndRecoverHelper.java:49)
          at org.apache.isis.persistence.jdo.datanucleus.entities.DnStateManagerForIsis.lambda$disconnect$0(DnStateManagerForIsis.java:129)
          at org.apache.isis.persistence.jdo.datanucleus.entities.DnStateManagerForIsis$$Lambda$3581.1775298992.accept(Unknown Source:-1)
          at java.util.Optional.ifPresent(Optional.java:183)
          at org.apache.isis.persistence.jdo.datanucleus.entities.DnStateManagerForIsis.disconnect(DnStateManagerForIsis.java:129)
          at org.datanucleus.state.LifeCycleState.changeState(LifeCycleState.java:117)
          at org.datanucleus.api.jdo.state.PersistentDeleted.transitionCommit(PersistentDeleted.java:66)
          at org.datanucleus.state.StateManagerImpl.postCommit(StateManagerImpl.java:1223)
          at org.datanucleus.ExecutionContextImpl.postCommit(ExecutionContextImpl.java:4385)
          at org.datanucleus.ExecutionContextImpl.transactionCommitted(ExecutionContextImpl.java:745)
          at org.datanucleus.transaction.TransactionImpl.internalPostCommit(TransactionImpl.java:574)
          at org.datanucleus.transaction.TransactionImpl.commit(TransactionImpl.java:355)
          at org.datanucleus.api.jdo.JDOTransaction.commit(JDOTransaction.java:94)
          at org.apache.isis.persistence.jdo.spring.integration.JdoTransactionManager.doCommit(JdoTransactionManager.java:443)
          at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743)
          at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)
          at org.apache.isis.core.runtimeservices.transaction.TransactionServiceSpring.callTransactional(TransactionServiceSpring.java:115)
          at org.apache.isis.applib.services.xactn.TransactionalProcessor.callTransactional(TransactionalProcessor.java:71)
          at org.apache.isis.applib.services.xactn.TransactionalProcessor.runTransactional(TransactionalProcessor.java:82)
          at org.apache.isis.extensions.commandlog.applib.job.RunBackgroundCommandsJob.lambda$execute$4(RunBackgroundCommandsJob.java:107)
          at org.apache.isis.extensions.commandlog.applib.job.RunBackgroundCommandsJob$$Lambda$4549.469978661.run(Unknown Source:-1)
          at org.apache.isis.commons.functional.ThrowingRunnable.lambda$toCallable$0(ThrowingRunnable.java:41)
          at org.apache.isis.commons.functional.ThrowingRunnable$$Lambda$3543.1911045472.call(Unknown Source:-1)
          at org.apache.isis.core.runtimeservices.session.InteractionServiceDefault.callInternal(InteractionServiceDefault.java:328)
      
          at org.apache.isis.core.runtimeservices.session.InteractionServiceDefault.call(InteractionServiceDefault.java:269)
          at org.apache.isis.applib.services.iactnlayer.InteractionService.lambda$callAndCatch$0(InteractionService.java:152)
          at org.apache.isis.applib.services.iactnlayer.InteractionService$$Lambda$3241.4502127.call(Unknown Source:-1)
      
          at org.apache.isis.commons.functional.Try.call(Try.java:58)
          at org.apache.isis.applib.services.iactnlayer.InteractionService.callAndCatch(InteractionService.java:152)
          at org.apache.isis.applib.services.iactnlayer.InteractionService.runAndCatch(InteractionService.java:163)
          at org.apache.isis.extensions.commandlog.applib.job.RunBackgroundCommandsJob.lambda$execute$9(RunBackgroundCommandsJob.java:106)
          at org.apache.isis.extensions.commandlog.applib.job.RunBackgroundCommandsJob$$Lambda$3396.1208611345.accept(Unknown Source:-1)
          at java.util.Optional.ifPresent(Optional.java:183)
          at org.apache.isis.extensions.commandlog.applib.job.RunBackgroundCommandsJob.execute(RunBackgroundCommandsJob.java:104)
          at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
          at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
          - locked <0xa335> (a java.lang.Object)
       

      and I compared to the original stacktrace yielding the error:

      java.lang.NullPointerException: target is marked non-null but is null
          at org.apache.isis.commons.internal.reflection._Reflect.invokeMethodOn(_Reflect.java:571) ~[isis-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.metamodel.commons.CanonicalInvoker.invoke(CanonicalInvoker.java:76) ~[isis-core-metamodel-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.metamodel.object.MmInvokeUtils.invokeNoArg(MmInvokeUtils.java:108) ~[isis-core-metamodel-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.metamodel.facets.properties.accessor.PropertyAccessorFacetViaAccessor.getProperty(PropertyAccessorFacetViaAccessor.java:65) ~[isis-core-metamodel-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.metamodel.specloader.specimpl.OneToOneAssociationDefault.get(OneToOneAssociationDefault.java:155) ~[isis-core-metamodel-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.metamodel.services.objectlifecycle.PropertyChangeRecord.getPropertyValue(PropertyChangeRecord.java:138) ~[isis-core-metamodel-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.metamodel.services.objectlifecycle.PropertyChangeRecord.withPostValueSetToCurrent(PropertyChangeRecord.java:95) ~[isis-core-metamodel-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.persistence.commons.integration.changetracking.EntityChangeTrackerDefault.lambda$capturePostValuesAndDrain$0(EntityChangeTrackerDefault.java:164) ~[isis-persistence-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at java.util.stream.ReferencePipeline$11$1.accept(ReferencePipeline.java:441) ~[?:?]
          at java.util.Iterator.forEachRemaining(Iterator.java:133) ~[?:?]
          at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801) ~[?:?]
          at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484) ~[?:?]
          at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) ~[?:?]
          at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913) ~[?:?]
          at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
          at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578) ~[?:?]
          at org.apache.isis.persistence.commons.integration.changetracking.EntityChangeTrackerDefault.capturePostValuesAndDrain(EntityChangeTrackerDefault.java:168) ~[isis-persistence-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.commons.functional.ThrowingSupplier.get(ThrowingSupplier.java:61) ~[isis-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.commons.functional.ThrowingSupplier.get(ThrowingSupplier.java:49) ~[isis-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.commons.internal.base._Lazy_ThreadSafe.get(_Lazy_ThreadSafe.java:66) ~[isis-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.persistence.commons.integration.changetracking.EntityChangeTrackerDefault.snapshotPropertyChangeRecords(EntityChangeTrackerDefault.java:149) ~[isis-persistence-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.persistence.commons.integration.changetracking.EntityChangeTrackerDefault.getPropertyChanges(EntityChangeTrackerDefault.java:294) ~[isis-persistence-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.runtimeservices.publish.EntityPropertyChangePublisherDefault.publishChangedProperties(EntityPropertyChangePublisherDefault.java:95) ~[isis-core-runtimeservices-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.persistence.commons.integration.changetracking.EntityChangeTrackerDefault.doPublish(EntityChangeTrackerDefault.java:260) ~[isis-persistence-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.persistence.commons.integration.changetracking.EntityChangeTrackerDefault.onTransactionCompleting(EntityChangeTrackerDefault.java:250) ~[isis-persistence-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.persistence.commons.integration.changetracking.EntityChangeTrackerDefault$TransactionSubscriber.onTransactionCompleting(EntityChangeTrackerDefault.java:236) ~[isis-persistence-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at jdk.internal.reflect.GeneratedMethodAccessor179.invoke(Unknown Source) ~[?:?]
          at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
          at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
          at org.springframework.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:344) ~[spring-context-5.3.30.jar:5.3.30]
          at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:229) ~[spring-context-5.3.30.jar:5.3.30]
          at org.springframework.context.event.ApplicationListenerMethodAdapter.onApplicationEvent(ApplicationListenerMethodAdapter.java:166) ~[spring-context-5.3.30.jar:5.3.30]
          at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:178) ~[spring-context-5.3.30.jar:5.3.30]
          at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:171) ~[spring-context-5.3.30.jar:5.3.30]
          at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:145) ~[spring-context-5.3.30.jar:5.3.30]
          at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:421) ~[spring-context-5.3.30.jar:5.3.30]
          at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:391) ~[spring-context-5.3.30.jar:5.3.30]
          at org.apache.isis.core.runtimeservices.eventbus.EventBusServiceSpring.post(EventBusServiceSpring.java:43) ~[isis-core-runtimeservices-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.runtime.events.TransactionEventEmitter.beforeCompletion(TransactionEventEmitter.java:48) ~[isis-core-runtime-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.springframework.transaction.support.TransactionSynchronizationUtils.triggerBeforeCompletion(TransactionSynchronizationUtils.java:108) ~[spring-tx-5.3.30.jar:5.3.30]
          at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerBeforeCompletion(AbstractPlatformTransactionManager.java:926) ~[spring-tx-5.3.30.jar:5.3.30]
          at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:728) ~[spring-tx-5.3.30.jar:5.3.30]
          at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711) ~[spring-tx-5.3.30.jar:5.3.30]
          at org.apache.isis.core.interaction.integration.InteractionAwareTransactionalBoundaryHandler.lambda$newTransactionOrParticipateInExisting$1(InteractionAwareTransactionalBoundaryHandler.java:135) ~[isis-core-interaction-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.interaction.integration.InteractionAwareTransactionalBoundaryHandler$OnCloseHandle.lambda$runOnCloseTasks$1(InteractionAwareTransactionalBoundaryHandler.java:160) ~[isis-core-interaction-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at java.util.ArrayList.forEach(ArrayList.java:1541) ~[?:?]
          at org.apache.isis.core.interaction.integration.InteractionAwareTransactionalBoundaryHandler$OnCloseHandle.runOnCloseTasks(InteractionAwareTransactionalBoundaryHandler.java:157) ~[isis-core-interaction-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at java.util.Optional.ifPresent(Optional.java:183) ~[?:?]
          at org.apache.isis.core.interaction.integration.InteractionAwareTransactionalBoundaryHandler.onClose(InteractionAwareTransactionalBoundaryHandler.java:98) ~[isis-core-interaction-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.runtimeservices.session.InteractionServiceDefault.preInteractionClosed(InteractionServiceDefault.java:392) ~[isis-core-runtimeservices-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.runtimeservices.session.InteractionServiceDefault.closeInteractionLayerStackDownToStackSize(InteractionServiceDefault.java:418) ~[isis-core-runtimeservices-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.core.runtimeservices.session.InteractionServiceDefault.call(InteractionServiceDefault.java:271) ~[isis-core-runtimeservices-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.applib.services.iactnlayer.InteractionService.lambda$callAndCatch$0(InteractionService.java:152) ~[isis-applib-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.commons.functional.Try.call(Try.java:58) ~[isis-commons-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.applib.services.iactnlayer.InteractionService.callAndCatch(InteractionService.java:152) ~[isis-applib-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.applib.services.iactnlayer.InteractionService.runAndCatch(InteractionService.java:163) ~[isis-applib-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.apache.isis.extensions.commandlog.applib.job.RunBackgroundCommandsJob.lambda$execute$9(RunBackgroundCommandsJob.java:106) ~[isis-extensions-commandlog-applib-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at java.util.Optional.ifPresent(Optional.java:183) ~[?:?]
          at org.apache.isis.extensions.commandlog.applib.job.RunBackgroundCommandsJob.execute(RunBackgroundCommandsJob.java:104) ~[isis-extensions-commandlog-applib-2.0.0-SNAPSHOT.jar:2.0.0-SNAPSHOT]
          at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[quartz-2.3.2.jar:?]
          at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) ~[quartz-2.3.2.jar:?]
       

      The former comes from TransactionService committing, the latter from InteractionService also committing, but on entities already hollow.

      Looking at RunBackgroundCommandsJob, we see that the InteractionService calls TransactionService within:

       

      So the fix is I think is simply not to bother with call to transactionService ... each call to interactionService is already going to be in a separate transaction, I think.

      Attachments

        1. image-2023-12-08-18-12-43-554.png
          172 kB
          Daniel Keir Haywood

        Activity

          People

            danhaywood Daniel Keir Haywood
            danhaywood Daniel Keir Haywood
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: