Mdm: auto link creation NullPointerException "org.hl7.fhir.instance.model.api.IAnyResource.getUserData(String)" because "theResource" is null

[cspielmann]

Describe the bug With the mdm enabled, when I push 2 patients. The second mdm link is not created. reason is unknown. An Exception stack is thrown int he server

To Reproduce Steps to reproduce the behavior:

1. $mdm-clear
2. delete all patients (DELETE http://localhost:8888/fhir/Patient?identifier=http%3A%2F%2Fcns.lu%2Fpatient%2Fmatricule%7C)
3. create 2 patients (actually using an update to force the id of the Patient resource to a custom id) (always recreating the same patient)
4. $mdm-query-links

expecting 2 links but only one is created.

Expected behavior error stack into the 2022-07-13 16:24:19.820 [empi-1] ERROR ca.uhn.fhir.log.mdm_troubleshooting [MdmMessageHandler.java:183] Failure during MDM processing: Cannot invoke "org.hl7.fhir.instance.model.api.IAnyResource.getUserData(String)" because "theResource" is null java.lang.NullPointerException: Cannot invoke "org.hl7.fhir.instance.model.api.IAnyResource.getUserData(String)" because "theResource" is null at ca.uhn.fhir.jpa.dao.index.IdHelperService.getPidOrThrowException(IdHelperService.java:634) at ca.uhn.fhir.jpa.mdm.svc.MdmLinkSvcImpl.goldenResourceLinkedAsNoMatch(MdmLinkSvcImpl.java:82) at ca.uhn.fhir.jpa.mdm.svc.MdmLinkSvcImpl.updateLink(MdmLinkSvcImpl.java:64) at ca.uhn.fhir.jpa.mdm.svc.MdmLinkSvcImpl$$FastClassBySpringCGLIB$$5cb436e9.invoke(<generated>) at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698) at ca.uhn.fhir.jpa.mdm.svc.MdmLinkSvcImpl$$EnhancerBySpringCGLIB$$d3544dbd.updateLink(<generated>) at ca.uhn.fhir.jpa.mdm.svc.MdmEidUpdateService.linkToNewGoldenResourceAndFlagAsDuplicate(MdmEidUpdateService.java:129) at ca.uhn.fhir.jpa.mdm.svc.MdmEidUpdateService.handleMdmUpdate(MdmEidUpdateService.java:83) at ca.uhn.fhir.jpa.mdm.svc.MdmMatchLinkSvc.handleMdmWithSingleCandidate(MdmMatchLinkSvc.java:161) at ca.uhn.fhir.jpa.mdm.svc.MdmMatchLinkSvc.doMdmUpdate(MdmMatchLinkSvc.java:86) at ca.uhn.fhir.jpa.mdm.svc.MdmMatchLinkSvc.updateMdmLinksForMdmSource(MdmMatchLinkSvc.java:74) at ca.uhn.fhir.jpa.mdm.svc.MdmMatchLinkSvc$$FastClassBySpringCGLIB$$95ebff3e.invoke(<generated>) at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698) at ca.uhn.fhir.jpa.mdm.svc.MdmMatchLinkSvc$$EnhancerBySpringCGLIB$$7ebd03dc.updateMdmLinksForMdmSource(<generated>) at ca.uhn.fhir.jpa.mdm.broker.MdmMessageHandler.handleUpdateResource(MdmMessageHandler.java:173) at ca.uhn.fhir.jpa.mdm.broker.MdmMessageHandler.matchMdmAndUpdateLinks(MdmMessageHandler.java:106) at ca.uhn.fhir.jpa.mdm.broker.MdmMessageHandler.handleMessage(MdmMessageHandler.java:84) at org.springframework.messaging.support.ExecutorSubscribableChannel$SendTask.run(ExecutorSubscribableChannel.java:144) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:833) 2022-07-13 16:24:19.820 [empi-1] ERROR ca.uhn.fhir.log.mdm_troubleshooting [MdmMessageHandler.java:183] Failure during MDM processing: Cannot invoke "org.hl7.fhir.instance.model.api.IAnyResource.getUserData(String)" because "theResource" is null java.lang.NullPointerException: Cannot invoke "org.hl7.fhir.instance.model.api.IAnyResource.getUserData(String)" because "theResource" is null at ca.uhn.fhir.jpa.dao.index.IdHelperService.getPidOrThrowException(IdHelperService.java:634) at ca.uhn.fhir.jpa.mdm.svc.MdmLinkSvcImpl.goldenResourceLinkedAsNoMatch(MdmLinkSvcImpl.java:82) at ca.uhn.fhir.jpa.mdm.svc.MdmLinkSvcImpl.updateLink(MdmLinkSvcImpl.java:64) at ca.uhn.fhir.jpa.mdm.svc.MdmLinkSvcImpl$$FastClassBySpringCGLIB$$5cb436e9.invoke(<generated>) at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698) at ca.uhn.fhir.jpa.mdm.svc.MdmLinkSvcImpl$$EnhancerBySpringCGLIB$$d3544dbd.updateLink(<generated>) at ca.uhn.fhir.jpa.mdm.svc.MdmEidUpdateService.linkToNewGoldenResourceAndFlagAsDuplicate(MdmEidUpdateService.java:129) at ca.uhn.fhir.jpa.mdm.svc.MdmEidUpdateService.handleMdmUpdate(MdmEidUpdateService.java:83) at ca.uhn.fhir.jpa.mdm.svc.MdmMatchLinkSvc.handleMdmWithSingleCandidate(MdmMatchLinkSvc.java:161) at ca.uhn.fhir.jpa.mdm.svc.MdmMatchLinkSvc.doMdmUpdate(MdmMatchLinkSvc.java:86) at ca.uhn.fhir.jpa.mdm.svc.MdmMatchLinkSvc.updateMdmLinksForMdmSource(MdmMatchLinkSvc.java:74) at ca.uhn.fhir.jpa.mdm.svc.MdmMatchLinkSvc$$FastClassBySpringCGLIB$$95ebff3e.invoke(<generated>) at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698) at ca.uhn.fhir.jpa.mdm.svc.MdmMatchLinkSvc$$EnhancerBySpringCGLIB$$7ebd03dc.updateMdmLinksForMdmSource(<generated>) at ca.uhn.fhir.jpa.mdm.broker.MdmMessageHandler.handleUpdateResource(MdmMessageHandler.java:173) at ca.uhn.fhir.jpa.mdm.broker.MdmMessageHandler.matchMdmAndUpdateLinks(MdmMessageHandler.java:106) at ca.uhn.fhir.jpa.mdm.broker.MdmMessageHandler.handleMessage(MdmMessageHandler.java:84) at org.springframework.messaging.support.ExecutorSubscribableChannel$SendTask.run(ExecutorSubscribableChannel.java:144) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:833)

Screenshots NA

Environment (please complete the following information):

• HAPI FHIR Version 5.7.0
• OS: Windows
• Browser NA

Additional context In attachement, the client trace, the mdm server trace, the patients, the link created.

[cspielmann]

single_created_link.txt server_mdm_trace.txt client_mdm_trace.txt mdm_patients.txt

the files

[cspielmann]

other hints:

• if I do a $mdm-clear and then a $mdm-submit on the same 2 patients, then I have 2 links.
• if I do an $expunge of all patient before, and then create the first version of the patients, i have the same issue.

[cspielmann]

the rules mdm-rules_json.txt

[cspielmann]

I am trying do perform benchmarking of mdm matching results vs a set of predefined patients. So this error is very annoying indeed. I don't get what I am doing wrong. I think to this bug. but the root reason is unclear.

[tadgh]

Heya, I'll investigate this. Sounds like an easy to replicate bug.

1. PUT a patient with a given ID.
2. PUT another patient with a different given ID.

Can you share with me the contents of the patients you are storing? If so, I should be able to write a test to replicate this.

[cspielmann]

Hello @tadgh I have attached those files in one of my previous comment: mdm_patients.txt contains the (anonymised) patients I am using. I hope this is enough. if not tell me.

[cspielmann]

this behavior is very annoying. I don't get what kind of workaround I could implement as I need to keep somehow the identifier. I may move it as a regular identifier to my resource to overcome the issue. but it will add complexity to my treatments.

[tadgh]

Heya, I will work on replicating this. If there is a logic bug, i think you've provided enough sample data here for me to replicate it. How are you running hapi-fhir, via the jpaserver-starter? or have you written your own wrapper?

[tadgh]

Couple of clarifying questions:

1. Are you submitting the resources via bundle, or just via individual PUTs
2. What are the precise steps to replicate the failure from a fresh empty server state that has never been booted before? Bulleted steps will allow me to quickly hit the ground running on this once i have time for it.

Thanks for the extra information about the fact that it works with $mdm-clear and then submit. I wonder if this is a timing issue possibly.

[tadgh]

Hey I've written a test for this, this test does the following:

1. Start a server with MDM, with your specific MDM rules.
2. Create Patient 1 (with the details provided in your sample json) via http PUT.
3. Create Patient 2 (with the details provided in your sample json) via http PUT.

No error is thrown, 2 links exist as expected. Can you perhaps give me all the related settings you happen to be running with? Database, DaoConfig Settings, partitioning?

Also, I looked at your client logs, if that script is automated, its not surprising its not pulling the correct data, if its making its calls very quickly. MDM is an asynchronous process that occurs after the patient is actually stored, completely outside of the http request/response loop. If you care about being notified when MDM processing is completed, there is a Pointcut you can register an interceptor on (search for MDM_AFTER_PERSISTED_RESOURCE_CHECKED at this link).

Any tips for me on how to get this particular stack trace replicated?

[cspielmann]

Thanks for the feedback and the asynchronous hint, I will strip my test to barebone and come back to you with all the details.

[cspielmann]

Testcase:

• deleting the H2 database files
• starting the hapi-jpa server
• executing the sequence of rest http calls in attachment (intelliJ http) that creates 2 patients with PUT
• no error
• re-executing the same sequence of rest http that creates 2 patients with PUT
• error (same stack as in the issue creation)

in attachment:

• the mdm-rules.json
• the yaml of configuration of hapi-jpa server
• the patients : they are exactly the same except the id
• the intelliJ http file
• the logs ( with mdm logs enabled) bug.zip

[tadgh]

Perfect, thanks much. I will replicate this next :)

[tadgh]

Heya, I have replicated your steps locally and everything is working fine for me. Is there some config you haven't shared? I see you are pointing at 8888 but i don't see where you modify the base 8080 port

[cspielmann]

Hello, Thanks a lot for the feedback.

Actually i am running it with jetty : >mvn -Djetty.port=8888 jetty:run

As everything is working fine on your side with the test case above, I wonder what is going on on my side. Could you confirm that you tested with 5.7.0 version ?

[tadgh]

Oh my apologies, I totally missed that and tested on 6.0.1. Doing 5.7.0 now

[tadgh]

Can you point me to the precise commit you are using to replicate this on hapi-fhir-jpaserver-starter? I have checked out a version that uses 5.7.0 but I'd like to be sure we're on exactly the same page.

As an aside, since it seems to work there, is there some reason you can't just upgrade to 6.X?

[tadgh]

ok finally managed to replicate it. Let's see if I can find the root cause :)

EDIT: I've managed to replicate it in our master environment too. I'll go ahead and write a test against this.

[tadgh]

I have made the fix! It it in a PR here: https://github.com/hapifhir/hapi-fhir/pull/3851

It will be available in 6.1.0 when it is released.