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

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

VotersWatch issueWatchersLinkCloneUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    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

        Activity

          This comment will be Viewable by All Users Viewable by All Users
          Cancel

          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:

              Slack

                Issue deployment