Concurrent requests to permanently delete (IOCM_EXPIRED) rejected study fails with EntityNotFoundException

[vrindanayak]

Note : Reported & tested for (CT/MR) studies with large number of instances (300+)

Steps to Reproduce

• Store a (CT/MR) study with large number of instances (300+)
• Reject study
• Trigger concurrent Delete Study Permanently REST service on rejected study using IOCM AE (eg. IOCM_EXPIRED)
• Fails with following in server log

09:04:15,704 INFO  [org.dcm4chee.arc.iocm.rs.StudyMgtRS] (default task-4) Process DELETE /dcm4chee-arc/aets/IOCM_EXPIRED/rs/studies/1.2.124.113532.80.22166.20879.20201207.211625.126275554 from [email protected]
09:04:15,729 INFO  [org.dcm4chee.arc.delete.impl.DeletionServiceImpl] (default task-4) Start deleting Study[pk=2610, uid=1.2.124.113532.80.22166.20879.20201207.211625.126275554, id=14572] from database
09:04:16,662 INFO  [org.dcm4chee.arc.iocm.rs.StudyMgtRS] (default task-3) Process DELETE /dcm4chee-arc/aets/IOCM_EXPIRED/rs/studies/1.2.124.113532.80.22166.20879.20201207.211625.126275554 from [email protected]
09:04:16,669 INFO  [org.dcm4chee.arc.delete.impl.DeletionServiceImpl] (default task-3) Start deleting Study[pk=2610, uid=1.2.124.113532.80.22166.20879.20201207.211625.126275554, id=14572] from database
09:04:17,029 INFO  [org.dcm4chee.arc.delete.impl.RejectExpiredStudiesScheduler] (EE-ManagedScheduledExecutorService-default-Thread-9) start RejectExpiredStudiesScheduler.execute()
09:04:17,063 INFO  [org.dcm4chee.arc.delete.impl.RejectExpiredStudiesScheduler] (EE-ManagedScheduledExecutorService-default-Thread-9) finished RejectExpiredStudiesScheduler.execute()
09:04:17,479 ERROR [org.jboss.as.ejb3.invocation] (default task-3) WFLYEJB0034: Jakarta Enterprise Beans Invocation failed on component DeletionServiceEJB for method public java.util.List org.dcm4chee.arc.delete.impl.DeletionServiceEJB.deleteStudy(org.dcm4chee.arc.delete.StudyDeleteContext,int,boolean): jakarta.ejb.EJBException: jakarta.persistence.EntityNotFoundException: Unable to find org.dcm4chee.arc.entity.AttributesBlob with id 89660
        at [email protected]//org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:268)
        ........
        ........
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-delete-5.32.0.jar//org.dcm4chee.arc.delete.impl.DeletionServiceEJB$$$view22.deleteStudy(Unknown Source)
        at jdk.internal.reflect.GeneratedMethodAccessor152.invoke(Unknown Source)
        ........
        ........
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-delete-5.32.0.jar//org.dcm4chee.arc.delete.impl.DeletionServiceEJB$Proxy$_$$_Weld$EnterpriseProxy$.deleteStudy(Unknown Source)
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-delete-5.32.0.jar//org.dcm4chee.arc.delete.impl.DeletionServiceImpl.deleteStudy(DeletionServiceImpl.java:240)
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-delete-5.32.0.jar//org.dcm4chee.arc.delete.impl.DeletionServiceImpl.deleteStudy(DeletionServiceImpl.java:171)
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-delete-5.32.0.jar//org.dcm4chee.arc.delete.impl.DeletionServiceImpl.deleteStudy(DeletionServiceImpl.java:146)
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-delete-5.32.0.jar//org.dcm4chee.arc.delete.impl.DeletionServiceImpl$Proxy$_$$_WeldClientProxy.deleteStudy(Unknown Source)
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-war-5.32.0-unsecure.war//org.dcm4chee.arc.iocm.rs.StudyMgtRS.deleteStudy(StudyMgtRS.java:158)
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-war-5.32.0-unsecure.war//org.dcm4chee.arc.iocm.rs.StudyMgtRS$Proxy$_$$_WeldSubclass.deleteStudy$$super(Unknown Source)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        ........
        ........
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-war-5.32.0-unsecure.war//org.dcm4chee.arc.iocm.rs.StudyMgtRS$Proxy$_$$_WeldSubclass.deleteStudy(Unknown Source)
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-war-5.32.0-unsecure.war//org.dcm4chee.arc.iocm.rs.StudyMgtRS$Proxy$_$$_WeldClientProxy.deleteStudy(Unknown Source)
        ........
        ........
Caused by: jakarta.persistence.EntityNotFoundException: Unable to find org.dcm4chee.arc.entity.AttributesBlob with id 89660
        at [email protected]//org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl$JpaEntityNotFoundDelegate.handleEntityNotFound(EntityManagerFactoryBuilderImpl.java:183)
        ........
        ........
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-delete-5.32.0.jar//org.dcm4chee.arc.delete.impl.DeletionServiceEJB.deleteInstances(DeletionServiceEJB.java:533)
        at deployment.dcm4chee-arc-ear-5.32.0-psql.ear.dcm4chee-arc-delete-5.32.0.jar//org.dcm4chee.arc.delete.impl.DeletionServiceEJB.deleteStudy(DeletionServiceEJB.java:330)
        at jdk.internal.reflect.GeneratedMethodAccessor152.invoke(Unknown Source)
        ........
        ........
        ... 148 more
        ........
        ........
09:04:18,190 INFO  [org.dcm4chee.arc.delete.impl.DeletionServiceImpl] (default task-4) Successfully delete Study[pk=2610, uid=1.2.124.113532.80.22166.20879.20201207.211625.126275554, id=14572] from database

Note : Even after some time, if only a single request is triggered to permanently delete the study, it shows success in UI / server log, but the study remains in DB

10:17:48,442 INFO  [org.dcm4chee.arc.qido.QidoRS] (default task-4) Process GET /dcm4chee-arc/aets/IOCM_EXPIRED/rs/studies?limit=21&includefield=all&offset=0&orderby=PatientName,-StudyDate,-StudyTime from [email protected]
10:17:48,527 INFO  [org.dcm4chee.arc.qido.QidoRS] (default task-4) SearchForStudies: 1 Matches
10:17:55,019 INFO  [org.dcm4chee.arc.conf.rs.ConfigurationRS] (default task-4) Process GET /dcm4chee-arc/devices/dcm4chee-arc from [email protected]
10:17:56,641 INFO  [org.dcm4chee.arc.iocm.rs.StudyMgtRS] (default task-4) Process DELETE /dcm4chee-arc/aets/IOCM_EXPIRED/rs/studies/1.2.124.113532.80.22166.20879.20201207.211625.126275554 from [email protected]
10:17:56,647 INFO  [org.dcm4chee.arc.delete.impl.DeletionServiceImpl] (default task-4) Start deleting Study[pk=2613, uid=1.2.124.113532.80.22166.20879.20201207.211625.126275554, id=14572] from database
10:17:56,652 INFO  [org.dcm4chee.arc.delete.impl.DeletionServiceImpl] (default task-4) Successfully delete Study[pk=2613, uid=1.2.124.113532.80.22166.20879.20201207.211625.126275554, id=14572] from database
10:18:03,441 INFO  [org.dcm4chee.arc.qido.QidoRS] (default task-4) Process GET /dcm4chee-arc/aets/IOCM_EXPIRED/rs/studies?limit=21&includefield=all&offset=0&orderby=PatientName,-StudyDate,-StudyTime from [email protected]
10:18:03,449 INFO  [org.dcm4chee.arc.qido.QidoRS] (default task-4) SearchForStudies: 1 Matches

Related #4443

[gunterze]

fixed by #4462