SQL doublicate entry error

[Stephen Adler]

I've installed the 5.18.1 snapshot of dcm4chee-arc. I've uploaded over 2000 studies over the  past few days. I'm now combing through the log files to see if anything is amiss and I'm finding this one error which seems a bit distrubing...

2019-09-04 11:26:44,259 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) SQL Error: 1062, SQLState: 23000
2019-09-04 11:26:44,260 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) (conn=195) Duplicate entry 'hideRejected-
2128' for key 'UK_prn4qt6d42stw0gfi1yce1fap'
2019-09-04 11:26:44,261 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedScheduledExecutorService-default-Thread-1) WFLYEJB0034: EJB Invocation failed on component QueryAttribut
esEJB for method public org.dcm4chee.arc.entity.StudyQueryAttributes org.dcm4chee.arc.query.impl.QueryAttributesEJB.calculateStudyQueryAttributes(java.lang.Long,org.dcm4chee.ar
c.conf.QueryRetrieveView): javax.ejb.EJBException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

It points to some kind of duplicate key in the SQL database. I've configured my dcm4chee-arc installation with mariadb. It was a bit complicated since I used the mysql version of dcm4chee-arc distribution and managed to replace the oracle mysql version of the driver to the mariadb version. I'm not sure if this is at the root of the problem or there is something else going on. Do I need to worry about this error?

this error generates a huge java traceback.

[gunterze]

If you see a following message like

INFO ..... Failed to update DB - retry; ...

you can ignore them.

There is no way to suppress the logging of org.jboss.as.ejb3.invocation and org.hibernate.engine.jdbc.spi.SqlExceptionHelper by the application. You may switch them off by wildfly's logging configuration.

[Stephen Adler]

Unfortunately there are no retry INFO messages following these errors. I'm including more text from the log file, but excluding the java stack dumps. If you need the java stack dumps then let me know. It's a lot of log entries for what looks like one SQL failure... (more comments at the end of this post...)

2019-09-04 12:12:49,432 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (Thread-208 (ActiveMQ-client-global-threads)) Finished processing of Task[id=ID:d6ffe383-cf2e-11e9-90
38-000c2933fd34] at Queue Export4 with Status COMPLETED
2019-09-04 12:12:49,433 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (Thread-209 (ActiveMQ-client-global-threads)) Finished processing of Task[id=ID:d70058b5-cf2e-11e9-90
38-000c2933fd34] at Queue Export4 with Status COMPLETED
2019-09-04 12:12:49,438 INFO  [org.dcm4chee.arc.export.mgt.impl.ExportManagerEJB] (EE-ManagedScheduledExecutorService-default-Thread-1) Schedule ExportTask[pk=4926, exporterID=
CalculateStudySize, studyUID=1.2.826.0.1.3680043.2.1237.680599246919.20190815155153.1.709, seriesUID=*, objectUID=*]
2019-09-04 12:12:49,439 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (EE-ManagedScheduledExecutorService-default-Thread-1) Schedule Task[id=ID:d704ec97-cf2e-11e9-9038-000
c2933fd34] at Queue Export4
2019-09-04 12:12:49,443 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) SQL Error: 1062, SQLState: 23000
2019-09-04 12:12:49,443 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) (conn=200) Duplicate entry 'hideRejected-
2222' for key 'UK_prn4qt6d42stw0gfi1yce1fap'
2019-09-04 12:12:49,443 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (Thread-207 (ActiveMQ-client-global-threads)) Finished processing of Task[id=ID:d6ff6e52-cf2e-11e9-90
38-000c2933fd34] at Queue Export4 with Status COMPLETED
2019-09-04 12:12:49,443 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (Thread-210 (ActiveMQ-client-global-threads)) Start processing Task[id=ID:d70031a4-cf2e-11e9-9038-000
c2933fd34] from Queue Export4 with Status: SCHEDULED
2019-09-04 12:12:49,445 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedScheduledExecutorService-default-Thread-1) WFLYEJB0034: EJB Invocation failed on component QueryAttribut

esEJB for method public org.dcm4chee.arc.entity.StudyQueryAttributes org.dcm4chee.arc.query.impl.QueryAttributesEJB.calculateStudyQueryAttributes(java.lang.Long,org.dcm4chee.ar
c.conf.QueryRetrieveView): javax.ejb.EJBException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: java.sql.SQLIntegrityConstraintViolationException: (conn=200) Duplicate entry 'hideRejected-2222' for key 'UK_prn4qt6d42stw0gfi1yce1fap'

Caused by: java.sql.SQLException: Duplicate entry 'hideRejected-2222' for key 'UK_prn4qt6d42stw0gfi1yce1fap

2019-09-04 12:12:49,447 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedScheduledExecutorService-default-Thread-1) WFLYEJB0034: EJB Invocation failed on component QueryServiceEJB for method public org.dcm4che3.data.Attributes org.dcm4chee.arc.query.impl.QueryServiceEJB.queryStudyExportTaskInfo(java.lang.String,org.dcm4chee.arc.conf.QueryRetrieveView): javax.ejb.EJBTransactionRolledbackException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: javax.ejb.EJBException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: java.sql.SQLIntegrityConstraintViolationException: (conn=200) Duplicate entry 'hideRejected-2222' for key 'UK_prn4qt6d42stw0gfi1yce1fap'

Caused by: java.sql.SQLException: Duplicate entry 'hideRejected-2222' for key 'UK_prn4qt6d42stw0gfi1yce1fap'

019-09-04 12:12:49,448 WARN  [org.dcm4chee.arc.export.mgt.impl.ExportManagerEJB] (EE-ManagedScheduledExecutorService-default-Thread-1) Failed to query Export Task Info for ExportTask[pk=4926, exporterID=CalculateStudySize, studyUID=1.2.826.0.1.3680043.2.1237.680599246919.20190815155153.1.709, seriesUID=*, objectUID=*] - : javax.ejb.EJBTransactionRolledbackException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: javax.ejb.EJBException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: org.hibernate.exception.ConstraintViolationException: could not execute statement

Caused by: java.sql.SQLIntegrityConstraintViolationException: (conn=200) Duplicate entry 'hideRejected-2222' for key 'UK_prn4qt6d42stw0gfi1yce1fap'

Caused by: java.sql.SQLException: Duplicate entry 'hideRejected-2222' for key 'UK_prn4qt6d42stw0gfi1yce1fap'

2019-09-04 12:12:49,450 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (Thread-206 (ActiveMQ-client-global-threads)) Finished processing of Task[id=ID:d6ff2031-cf2e-11e9-9038-000c2933fd34] at Queue Export4 with Status COMPLETED
2019-09-04 12:12:49,465 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (Thread-210 (ActiveMQ-client-global-threads)) Finished processing of Task[id=ID:d70031a4-cf2e-11e9-9038-000c2933fd34] at Queue Export4 with Status COMPLETED
2019-09-04 12:13:49,461 INFO  [org.dcm4chee.arc.export.mgt.impl.ExportManagerEJB] (EE-ManagedScheduledExecutorService-default-Thread-2) Schedule ExportTask[pk=4925, exporterID=CalculateQueryAttributes, studyUID=1.2.826.0.1.3680043.2.1237.680599246919.20190815155153.1.709, seriesUID=*, objectUID=*]
2019-09-04 12:13:49,464 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (EE-ManagedScheduledExecutorService-default-Thread-2) Schedule Task[id=ID:facc0328-cf2e-11e9-9038-000c2933fd34] at Queue Export4
2019-09-04 12:13:49,465 INFO  [org.dcm4chee.arc.export.mgt.impl.ExportManagerEJB] (EE-ManagedScheduledExecutorService-default-Thread-2) Schedule ExportTask[pk=4926, exporterID=CalculateStudySize, studyUID=1.2.826.0.1.3680043.2.1237.680599246919.20190815155153.1.709, seriesUID=*, objectUID=*]
2019-09-04 12:13:49,466 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (EE-ManagedScheduledExecutorService-default-Thread-2) Schedule Task[id=ID:facc5149-cf2e-11e9-9038-000c2933fd34] at Queue Export4
2019-09-04 12:13:49,473 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (Thread-211 (ActiveMQ-client-global-threads)) Start processing Task[id=ID:facc0328-cf2e-11e9-9038-000c2933fd34] from Queue Export4 with Status: SCHEDULED
2019-09-04 12:13:49,473 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (Thread-212 (ActiveMQ-client-global-threads)) Start processing Task[id=ID:facc5149-cf2e-11e9-9038-000c2933fd34] from Queue Export4 with Status: SCHEDULED
2019-09-04 12:13:49,477 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (Thread-212 (ActiveMQ-client-global-threads)) Finished processing of Task[id=ID:facc5149-cf2e-11e9-9038-000c2933fd34] at Queue Export4 with Status COMPLETED
2019-09-04 12:13:49,485 INFO  [org.dcm4chee.arc.qmgt.impl.QueueManagerEJB] (Thread-211 (ActiveMQ-client-global-threads)) Finished processing of Task[id=ID:facc0328-cf2e-11e9-9038-000c2933fd34] at Queue Export4 with Status COMPLETED
2019-09-04 12:14:59,788 INFO  [org.dcm4chee.arc.delete.impl.PurgeStorageScheduler] (EE-ManagedExecutorService-default-Thread-14) Start deletion on Storage[id=fs1, uri=file:///data0/MIPPACS-test]
2019-09-04 12:14:59,790 INFO  [org.dcm4chee.arc.delete.impl.PurgeStorageScheduler] (EE-ManagedExecutorService-default-Thread-14) Finished deletion on Storage[id=fs1, uri=file:///data0/MIPPACS-test]

One thing I've noticed is that it looks like postgresql is the preferred database for the development of dcm4chee-arc since the latest snapshot  (5.18.1) was a postgresql flavor. I need to use an opensource database since I'm running under linux and I've used mysql (now mariadb) for most of my software career. But with mysql being taken over by oracle and the mariadb fork, maybe it's less stable than postgresql? This dicom archive I'm setting up is for production use so if switching to postgresql means more reliable archive, then I'll spend the cycles setting up postresql DB. (Hopefully I can have postgresql and mariadb running side by side...)

Any advice?

[gunterze]

The error is caused by the concurrent processing of the task to eager calculate Query Attributes for a received Series and the task to eager calculate the size of received Studies.
It should not harm - it only causes that the values about the modality and the number of instances are not shown in the Export task list in the UI for the effected tasks.
You may avoid the error my using different values for Export Rule attribute Export Delay of the Export Rule "CalculateQueryAttributes" for the calculation of Query Attributes and of the Export Rule "CalculateStudySize" for the calculation of the Study Size.
Will change the value for Export Rule "CalculateStudySize" in the default configuration from 5 ("PT5M") to 6 ("PT6M") minutes.

[Stephen Adler]

I got another duplicate entry error. this is from a fresh install of 5.18.1, the one which I pulled from the github web site, not the one I built from the snapshot. Let me know if you need more data on this error...

Sep 07 13:02:22 mipdata0.nci.nih.gov standalone.sh[3608]: 13:02:22,261 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) SQL Error: 1062, SQLState: 23000

Sep 07 13:02:22 mipdata0.nci.nih.gov standalone.sh[3608]: 13:02:22,266 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) (conn=121) Duplicate entry 'hideRejected-434' for key 'UK_prn4qt6d42stw0gfi1yce1fap'
Sep 07 13:02:22 mipdata0.nci.nih.gov standalone.sh[3608]: 13:02:22,359 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedScheduledExecutorService-default-Thread-1) WFLYEJB0034: EJB Invocation failed on component QueryAttributesEJB for method public org.dcm4chee.arc.entity.StudyQueryAttributes org.dcm4chee.arc.query.impl.QueryAttributesEJB.calculateStudyQueryAttributes(java.lang.Long,org.dcm4chee.arc.conf.QueryRetrieveView): javax.ejb.EJBException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

I verified the Export Delay for calculate study size and calculate query attributes have different export delay. (PT5M for Calculate query attributes, and PT6M for Calculate Study Size)

[Gunter Zeilinger]

Have you changed the Export Delay of the Export Rule for the Study Size Calculation - manually or by applying

https://github.com/dcm4che/dcm4chee-arc-light/blob/master/dcm4chee-arc-assembly/src/main/resources/ldap/update-config-5.18.1.ldif ?

Sent with ProtonMail Secure Email.

‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐

On Saturday, September 7, 2019 7:05 PM, Stephen Adler <ad...@stephenadler.com> wrote:

I got another duplicate entry error. this is from a fresh install of 5.18.1, the one which I pulled from the github web site, not the one I built from the snapshot. Let me know if you need more data on this error...

Sep 07 13:02:22 mipdata0.nci.nih.gov standalone.sh[3608]: 13:02:22,261 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) SQL Error: 1062, SQLState: 23000

Sep 07 13:02:22 mipdata0.nci.nih.gov standalone.sh[3608]: 13:02:22,266 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) (conn=121) Duplicate entry 'hideRejected-434' for key 'UK_prn4qt6d42stw0gfi1yce1fap'

Sep 07 13:02:22 mipdata0.nci.nih.gov standalone.sh[3608]: 13:02:22,359 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedScheduledExecutorService-default-Thread-1) WFLYEJB0034: EJB Invocation failed on component QueryAttributesEJB for method public org.dcm4chee.arc.entity.StudyQueryAttributes org.dcm4chee.arc.query.impl.QueryAttributesEJB.calculateStudyQueryAttributes(java.lang.Long,org.dcm4chee.arc.conf.QueryRetrieveView): javax.ejb.EJBException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement

--

You received this message because you are subscribed to the Google Groups "dcm4che" group.

To unsubscribe from this group and stop receiving emails from it, send an email to dcm4che+u...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/dcm4che/23bd9d6b-c17c-4440-b586-ba840e5c75a7%40googlegroups.com.

[Stephen Adler]

I did a fresh install of dcm4chee-arc 5.18.1 from the release you posted a few days ago. the defaults should have been properly set. To confirm the Export Delay for Calculate Study Size in Archive Device is PT6M

[Stephen Adler]

Just to give one a sense of the frequency of these duplicate key errors, here's a grep'ed log file grepping on the SQL Error: 1062; SQLState: 23000

2019-09-07 14:24:06,868 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) SQL Error: 1062, SQLState: 23000
2019-09-07 14:24:07,130 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) SQL Error: 1062, SQLState: 23000
2019-09-07 14:25:07,392 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-2) SQL Error: 1062, SQLState: 23000
2019-09-07 14:26:08,458 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) SQL Error: 1062, SQLState: 23000
2019-09-07 14:27:08,628 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) SQL Error: 1062, SQLState: 23000
2019-09-07 14:27:08,913 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) SQL Error: 1062, SQLState: 23000

I'm getting these while I'm pushing data into the archive using the post method for in-place dicom object importation. The rate I'm able to push the dicom objects into the archive is about 30/sec.

[Gunter Zeilinger]

Would need the context of the WARN message, to see which action did the concurrent INSERT in the study_query_addr table.

Sent with ProtonMail Secure Email.

‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐

--

You received this message because you are subscribed to the Google Groups "dcm4che" group.

To unsubscribe from this group and stop receiving emails from it, send an email to dcm4che+u...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/dcm4che/ef6644d2-3344-4a81-a3dd-7b56691487db%40googlegroups.com.

[Stephen Adler]

Does this help? One bit of caution. I've setup dcm4chee-arc 5 on two systems. One is my debugging system to kick the tires of dcm4chee-arc 5 and the other is my production system.

Test system-> RHEL 8 running in a client vmware environment

Production system-> RHEL 7 running directly in the server environment. (old school, no containers etc.)

I have not been able to replicate the errors on the Test system (RHEL 8). Maybe this is a RHEL 7 vs RHEL 8 or rather a mariadb 10.3.111-2 (RHEL8) vs mariadb 5.5.64 (RHEL7).... Maybe I should upgrade my server to RHEL8 which would be a lot of work... Or maybe switch to postgresql version of dcm4chee-arc 5.... I don't want you to waste too much time on this if it is a bug in mysql...

2019-09-07 15:26:59,583 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-2) SQL Error: 1062, SQLState: 23000
2019-09-07 15:26:59,583 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-2) (conn=363) Duplicate entry 'hideRejected-508' for key 'UK_prn4qt6d42stw0gfi1yce1fap'
2019-09-07 15:26:59,610 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedScheduledExecutorService-default-Thread-2) WFLYEJB0034: EJB Invocation failed on component QueryAttributesEJB for method public org.dcm4chee.arc.entity.StudyQueryAttributes org.dcm4chee.arc.query.impl.QueryAttributesEJB.calculateStudyQueryAttributes(java.lang.Long,org.dcm4chee.arc.conf.QueryRetrieveView): javax.ejb.EJBException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement
    at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:246)
    at org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew(CMTTxInterceptor.java:380)
--
    at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
    at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:185)
    ... 124 more

2019-09-07 15:28:00,036 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-2) SQL Error: 1062, SQLState: 23000
2019-09-07 15:28:00,037 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-2) (conn=349) Duplicate entry 'hideRejected-689' for key 'UK_prn4qt6d42stw0gfi1yce1fap'
2019-09-07 15:28:00,065 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedScheduledExecutorService-default-Thread-2) WFLYEJB0034: EJB Invocation failed on component QueryAttributesEJB for method public org.dcm4chee.arc.entity.StudyQueryAttributes org.dcm4chee.arc.query.impl.QueryAttributesEJB.calculateStudyQueryAttributes(java.lang.Long,org.dcm4chee.arc.conf.QueryRetrieveView): javax.ejb.EJBException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement
    at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:246)
    at org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew(CMTTxInterceptor.java:380)
--
    at org.apache.activemq.artemis.ra.ActiveMQRAMessageProducer.send(ActiveMQRAMessageProducer.java:135)
    at org.apache.activemq.artemis.jms.client.ActiveMQJMSProducer.send(ActiveMQJMSProducer.java:97)
    ... 153 more

2019-09-07 15:29:00,417 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) SQL Error: 1062, SQLState: 23000
2019-09-07 15:29:00,417 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EE-ManagedScheduledExecutorService-default-Thread-1) (conn=350) Duplicate entry 'hideRejected-506' for key 'UK_prn4qt6d42stw0gfi1yce1fap'
2019-09-07 15:29:00,560 ERROR [org.jboss.as.ejb3.invocation] (EE-ManagedScheduledExecutorService-default-Thread-1) WFLYEJB0034: EJB Invocation failed on component QueryAttributesEJB for method public org.dcm4chee.arc.entity.StudyQueryAttributes org.dcm4chee.arc.query.impl.QueryAttributesEJB.calculateStudyQueryAttributes(java.lang.Long,org.dcm4chee.arc.conf.QueryRetrieveView): javax.ejb.EJBException: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement
    at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:246)
    at org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew(CMTTxInterceptor.java:380)

[Gunter Zeilinger]

Would also need the log messages on INFO level - the concurrent conflicitng INSERT is itself successful, so it does not show a trace on WARN or ERROR level

Sent with ProtonMail Secure Email.

‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐

--

You received this message because you are subscribed to the Google Groups "dcm4che" group.

To unsubscribe from this group and stop receiving emails from it, send an email to dcm4che+u...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/dcm4che/3aa0761b-f9e0-4f3f-b7d2-3386eeb4e667%40googlegroups.com.

[Stephen Adler]

My saga continues. I turned on INFO message output on my mysql 5.18.1 install and I could not reproduce the duplicate key error. I then went ahead and setup a psql version of dcm4chee-arc 5.18.1 and I was able to catch an instance of the duplicate key error. See output below. I then went through some performance testing and got the psql server working as optimally as I could. I then proceeded to import my dcm4chee-arc 2 data archive but could not reproduce another duplicate key error. Either by running the dcm4chee-arc 5.18.1 psql setup with or without the INFO messages being dumped to the log file. One does get a factor of ~2 improvement in data importation rates when you turn off the INFO messages. I was achieving about 200 objects/second importation rate. I did turn off the digest algorithm (set it to -).

I'm going to run a few more tests before I start the official 3.5T migration of my dicom archive, and I'll post any more glitches, but I'm getting the warm fuzzies right now that the data migration should go OK.

2019-09-08 09:13:37,120 INFO  [org.dcm4chee.arc.store.impl.StoreServiceEJB] (default task-132) 127....@127.0.0.1->MIPPACS: Create Location[pk=2309, systemID=fs1, path=2018/1/12/14/BE638A92/C3D6A535\
/0B3C2EA3, tsuid=1.2.840.10008.1.2.1, size=8192, status=OK, objectType=DICOM_FILE]
2019-09-08 09:13:37,121 INFO  [org.dcm4chee.arc.store.impl.StoreServiceEJB] (default task-131) 127....@127.0.0.1->MIPPACS: Create Series[pk=47, uid=1.2.840.113619.2.25.4.2147483647.1515785070.701, \
no=13, mod=PT]
2019-09-08 09:13:37,121 INFO  [org.dcm4chee.arc.store.impl.StoreServiceEJB] (default task-131) 127....@127.0.0.1->MIPPACS: Create Instance[pk=2310, uid=1.2.840.113619.2.5.4250306284.85621.151578505\
3.261, class=1.2.840.10008.5.1.4.1.1.128, no=34]
2019-09-08 09:13:37,121 INFO  [org.dcm4chee.arc.store.impl.StoreServiceEJB] (default task-131) 127....@127.0.0.1->MIPPACS: Create Location[pk=2310, systemID=fs1, path=2018/1/12/14/BE638A92/C1BF27F0\
/0B1FF8D2, tsuid=1.2.840.10008.1.2.1, size=8192, status=OK, objectType=DICOM_FILE]
2019-09-08 09:13:37,128 INFO  [org.dcm4chee.arc.stow.ImportStorageRS] (default task-133) Process POST /dcm4chee-arc/aets/MIPPACS/rs/instances/storage/fs1?null from nu...@127.0.0.1
2019-09-08 09:13:37,156 INFO  [org.dcm4chee.arc.stow.ImportStorageRS] (default task-134) Process POST /dcm4chee-arc/aets/MIPPACS/rs/instances/storage/fs1?null from nu...@127.0.0.1
2019-09-08 09:13:37,195 INFO  [org.dcm4chee.arc.stow.ImportStorageRS] (default task-135) Process POST /dcm4chee-arc/aets/MIPPACS/rs/instances/storage/fs1?null from nu...@127.0.0.1
2019-09-08 09:13:37,237 INFO  [org.dcm4chee.arc.store.impl.StoreServiceImpl] (default task-105) 127....@127.0.0.1->MIPPACS: Updated DB in 199 ms
2019-09-08 09:13:37,237 INFO  [org.dcm4chee.arc.stow.ImportStorageRS] (default task-136) Process POST /dcm4chee-arc/aets/MIPPACS/rs/instances/storage/fs1?null from nu...@127.0.0.1
2019-09-08 09:13:37,245 INFO  [org.dcm4chee.arc.store.impl.StoreServiceImpl] (default task-100) 127....@127.0.0.1->MIPPACS: Updated DB in 176 ms
2019-09-08 09:13:37,245 INFO  [org.dcm4chee.arc.store.impl.StoreServiceImpl] (default task-97) 127....@127.0.0.1->MIPPACS: Updated DB in 162 ms
2019-09-08 09:13:37,245 INFO  [org.dcm4chee.arc.store.impl.StoreServiceImpl] (default task-115) 127....@127.0.0.1->MIPPACS: Updated DB in 169 ms
2019-09-08 09:13:37,245 INFO  [org.dcm4chee.arc.store.impl.StoreServiceImpl] (default task-132) 127....@127.0.0.1->MIPPACS: Updated DB in 144 ms
2019-09-08 09:13:37,245 INFO  [org.dcm4chee.arc.store.impl.StoreServiceImpl] (default task-101) 127....@127.0.0.1->MIPPACS: Updated DB in 262 ms
2019-09-08 09:13:37,245 INFO  [org.dcm4chee.arc.store.impl.StoreServiceImpl] (default task-112) 127....@127.0.0.1->MIPPACS: Updated DB in 158 ms
2019-09-08 09:13:37,245 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-131) SQL Error: 0, SQLState: 23505
2019-09-08 09:13:37,246 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-131) ERROR: duplicate key value violates unique constraint "uk_pt5qn20x278wb1f7p2t3lcxv"
  Detail: Key (study_iuid)=(1.2.840.113619.2.25.4.2147483647.1515785051.612) already exists.
2019-09-08 09:13:37,246 INFO  [org.dcm4chee.arc.export.mgt.impl.ExportManagerEJB] (default task-126) Create ExportTask[pk=47, exporterID=CalculateQueryAttributes, studyUID=1.2.840.113704.7.1.0.212210\
8768171.1516810556.0, seriesUID=*, objectUID=*]
2019-09-08 09:13:37,246 INFO  [org.dcm4chee.arc.export.mgt.impl.ExportManagerEJB] (default task-127) Create ExportTask[pk=48, exporterID=CalculateQueryAttributes, studyUID=1.2.840.113704.7.1.0.212210\
8768171.1516810556.0, seriesUID=*, objectUID=*]
2019-09-08 09:13:37,246 INFO  [org.dcm4chee.arc.export.mgt.impl.ExportManagerEJB] (default task-108) Create ExportTask[pk=49, exporterID=CalculateQueryAttributes, studyUID=1.2.826.0.1.3680043.2.1237.\
680599246919.20171030214526.1.398, seriesUID=*, objectUID=*]
2019-09-08 09:13:37,245 INFO  [org.dcm4chee.arc.store.impl.StoreServiceImpl] (default task-98) 127....@127.0.0.1->MIPPACS: Updated DB in 169 ms
2019-09-08 09:13:37,246 ERROR [org.hibernate.internal.ExceptionMapperStandardImpl] (default task-131) HHH000346: Error during managed flush [org.hibernate.exception.ConstraintViolationException: coul\
d not execute statement]
2019-09-08 09:13:37,245 INFO  [org.dcm4chee.arc.store.impl.StoreServiceImpl] (default task-119) 127....@127.0.0.1->MIPPACS: Updated DB in 169 ms
2019-09-08 09:13:37,247 WARN  [com.arjuna.ats.arjuna] (default task-131) ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffff0a8584c7:49b15d8a:5d74fd4d:8778, o\
rg.wildfly.transaction.client.AbstractTransaction$AssociatingSynchronization@6850d577 >: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execut\
e statement
        at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
        at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181)
        at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:188)