search

hapifhir / hapi-fhir

🔥 HAPI FHIR - Java API for HL7 FHIR Clients and Servers
http://hapifhir.io
Apache License 2.0
1.96k stars 1.3k forks source link

BaseHapiFhirDao.getOrCreateTag (hapi-fhir 5.7.0) causes exception: org.hibernate.exception.GenericJDBCException: could not prepare statement #3412

Open tyfoni-systematic opened 2 years ago

tyfoni-systematic commented 2 years ago

Describe the bug We are upgrading from hapi-fhir 5.4.0 to 5.7.0, and when testing resource creation (eg. Goal) we get an error: Internal Server Error: HAPI-2023: Tag get/create failed after 10 attempts with error(s): org.hibernate.exception.GenericJDBCException: could not prepare statement We suspect that the new behaviour is caused by: "3156 multiple tag race condition (https://github.com/hapifhir/hapi-fhir/pull/3297)" in combination with our dependency on XA with Atomikos and postgresql.

To Reproduce Steps to reproduce the behavior:

  1. Create a resource, eg. Goal using IGenericClient
  2. See response: Internal Server Error: HAPI-2023: Tag get/create failed after 10 attempts with error(s): org.hibernate.exception.GenericJDBCException: could not prepare statement

Expected behavior That 'suspend/resume' transaction is not a requirement.

Environment (please complete the following information):

Workaround I will make a local modification reverting "3156 multiple tag race condition (https://github.com/hapifhir/hapi-fhir/pull/3297)" to get the previous behaviour.

Additional context The Goal resource (xml): `

Underlying exception: XA resource 'HAPI PU': suspend for XID 'XID: 31302E312E3232392E38312E746D313634353533343239333236373030373032:31302E312E3232392E38312E746D363936' raised -3: the XA resource detected an internal error org.postgresql.xa.PGXAException: suspend/resume not implemented at org.postgresql.xa.PGXAConnection.end(PGXAConnection.java:286) at com.atomikos.datasource.xa.XAResourceTransaction.xaSuspend(XAResourceTransaction.java:623) at com.atomikos.datasource.xa.session.BranchEnlistedStateHandler.transactionSuspended(BranchEnlistedStateHandler.java:94) at com.atomikos.datasource.xa.session.TransactionContext.transactionSuspended(TransactionContext.java:94) at com.atomikos.datasource.xa.session.SessionHandleState.notifyBeforeUse(SessionHandleState.java:168) at com.atomikos.jdbc.internal.AtomikosJdbcConnectionProxy.enlist(AtomikosJdbcConnectionProxy.java:88) at com.atomikos.jdbc.internal.AtomikosJdbcConnectionProxy.updateTransactionContext(AtomikosJdbcConnectionProxy.java:61) at com.atomikos.jdbc.internal.AbstractJdbcConnectionProxy.prepareStatement(AbstractJdbcConnectionProxy.java:64) at jdk.internal.reflect.GeneratedMethodAccessor46.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at com.atomikos.util.DynamicProxySupport.callProxiedMethod(DynamicProxySupport.java:159) at com.atomikos.util.DynamicProxySupport.invoke(DynamicProxySupport.java:116) at com.sun.proxy.$Proxy132.prepareStatement(Unknown Source) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151) at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:2122) at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2059) at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2037) at org.hibernate.loader.Loader.doQuery(Loader.java:956) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:357) at org.hibernate.loader.Loader.doList(Loader.java:2868) at org.hibernate.loader.Loader.doList(Loader.java:2850) at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2682) at org.hibernate.loader.Loader.list(Loader.java:2677) at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:540) at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:400) at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219) at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1454) at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1649) at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1617) at org.hibernate.query.internal.AbstractProducedQuery.getSingleResult(AbstractProducedQuery.java:1665) at org.hibernate.query.criteria.internal.compile.CriteriaQueryTypeQueryAdapter.getSingleResult(CriteriaQueryTypeQueryAdapter.java:111) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao$1.readOrCreate(BaseHapiFhirDao.java:478) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao$1.doInTransaction(BaseHapiFhirDao.java:491) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao$1.doInTransaction(BaseHapiFhirDao.java:472) at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.getOrCreateTag(BaseHapiFhirDao.java:472) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.getTagOrNull(BaseHapiFhirDao.java:422) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.extractTagsRi(BaseHapiFhirDao.java:355) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.updateTags(BaseHapiFhirDao.java:751) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.populateResourceIntoEntity(BaseHapiFhirDao.java:699) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.updateEntity(BaseHapiFhirDao.java:1312) at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.doCreateForPostOrPut(BaseHapiFhirResourceDao.java:328) at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.doCreateForPost(BaseHapiFhirResourceDao.java:246) at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.lambda$create$0(BaseHapiFhirResourceDao.java:213) at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) at ca.uhn.fhir.jpa.dao.tx.HapiTransactionService.doExecuteCallback(HapiTransactionService.java:150) at ca.uhn.fhir.jpa.dao.tx.HapiTransactionService.execute(HapiTransactionService.java:84) at ca.uhn.fhir.jpa.dao.tx.HapiTransactionService.execute(HapiTransactionService.java:76) at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.create(BaseHapiFhirResourceDao.java:213) at com.systematic.ehealth.dao.EHealthFhirResourceDao.lambda$create$2(EHealthFhirResourceDao.java:109) at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) at com.systematic.ehealth.dao.EHealthFhirResourceDao.create(EHealthFhirResourceDao.java:109) at com.systematic.ehealth.dao.EHealthFhirResourceDao.create(EHealthFhirResourceDao.java:49) `

jamesagnew commented 2 years ago

Ah interesting. We create tag definitions in a new transaction in order to avoid deadlocks and race conditions where multiple threads try to create the same tag at the same time.

This mechanism obviously doesn't work with XA, so I guess we need to make it optional. Will add a flag.

XcrigX commented 1 year ago

We hit this today on HAPI 6.4.0 - is there a workaround for it?
(correction: I believe the version we hit this was 6.4.3, not 6.4.0)

Thopap commented 1 year ago

We have moved from 6.2 to 6.4.4 and also experience this this error "HAPI-2023: Tag get/create failed after 10 attempts with error(s): " in the client response.

In the logfile, we see: 2023-03-30T09:52:01,481 ERROR [https-jsse-nio-8445-exec-4] org.hibernate.engine.jdbc.batch.internal.BatchingBatch - HHH000315: Exception executing batch [java.sql.BatchUpdateException: Batch entry 0 insert into hfj_tag_def (tag_code, tag_display, tag_system, tag_type, tag_user_selected, tag_version, tag_id) values ('http://hl7.org/fhir/StructureDefinition/vitalsigns', NULL, 'https://github.com/hapifhir/hapi-fhir/ns/jpa/profile', 1, 'FALSE', NULL, 252) was aborted: ERROR: duplicate key value violates unique constraint "idx_tagdef_typesyscode" Detail: Key (tag_type, tag_system, tag_code)=(1, https://github.com/hapifhir/hapi-fhir/ns/jpa/profile, http://hl7.org/fhir/StructureDefinition/vitalsigns) already exists. Call getNextException to see other errors in the batch.], SQL: insert into hfj_tag_def (tag_code, tag_display, tag_system, tag_type, tag_user_selected, tag_version, tag_id) values (?, ?, ?, ?, ?, ?, ?) 2023-03-30T09:52:01,484 WARN [https-jsse-nio-8445-exec-4] org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 23505 2023-03-30T09:52:01,484 ERROR [https-jsse-nio-8445-exec-4] org.hibernate.engine.jdbc.spi.SqlExceptionHelper - Batch entry 0 insert into hfj_tag_def (tag_code, tag_display, tag_system, tag_type, tag_user_selected, tag_version, tag_id) values ('http://hl7.org/fhir/StructureDefinition/vitalsigns', NULL, 'https://github.com/hapifhir/hapi-fhir/ns/jpa/profile', 1, 'FALSE', NULL, 252) was aborted: ERROR: duplicate key value violates unique constraint "idx_tagdef_typesyscode" Detail: Key (tag_type, tag_system, tag_code)=(1, https://github.com/hapifhir/hapi-fhir/ns/jpa/profile, http://hl7.org/fhir/StructureDefinition/vitalsigns) already exists. Call getNextException to see other errors in the batch. 2023-03-30T09:52:01,484 ERROR [https-jsse-nio-8445-exec-4] org.hibernate.engine.jdbc.spi.SqlExceptionHelper - ERROR: duplicate key value violates unique constraint "idx_tagdef_typesyscode" Detail: Key (tag_type, tag_system, tag_code)=(1, https://github.com/hapifhir/hapi-fhir/ns/jpa/profile, http://hl7.org/fhir/StructureDefinition/vitalsigns) already exists.

From the logfile it seems to be related to #3156

jamesagnew commented 1 year ago

If anyone can contribute a PR with a unit test that demonstrates this issue, that would go a long way towards helping us fix. I still don't actually understand what is causing this.

XcrigX commented 1 year ago

My prior comment I think was incorrect. I experienced the problem after bumping up the base HAPI version in JPA Starter from 6.4.0 to 6.4.3, when I rolled back to 6.4.0 the problem seems to have gone away. It may have been an issue of stale DDLs? I did not update the DDLs when trying the updated version. I haven't had a chance to troubleshoot further yet though.

I'll note, the tags that were failing for me had a version in them, such as "http://hl7.org/fhir/us/carin-bb/StructureDefinition/C4BB-Practitioner|1.1.0" - I don't know if this contributed to the problem, but I notice my hfj_tag_def table as a tag_version column which is not populated. Could some part of the code be stripping that version prior to the lookup but keeping it on the insert? Just an untested thought..

Thopap commented 1 year ago

@jamesagnew: Not 100% sure if this is an issue on our side.

The table hfj_tag_def seems to be have a unqiue contraint IDX_TAGDEF_TYPESYSCODE accross 3 columns.

As part of 6.4, it looks like this contraint was dropped and recreated with a different name IDX_TAGDEF_TYPESYSCODEVERUS : https://github.com/hapifhir/hapi-fhir/commit/9d70dbd08f36cd75d006612a54e1c07e996ecb65#diff-e5fcc6e1634304b61a6d38a2bedc19ca29a238d6cb8fe34bd42c9831854f43e2R112

The new contraint is accross 5 columns.

Either the upgrade (on postgresql on our side) do not run at all on our side or there was some failure in the execution. The Error during runtime looks like the old constraint is still active.

DoodlesOnMyFood commented 1 year ago

In my case, after I migrated tag_user_selected were all set null, but BaseHapiFhirDao.buildTagQuery seems to force tag_user_selected predicates to be true or false, resulting in always failing to fetch existing tags. BaseHapiFhirDao.getOrCreateTag will then try to create a new tag, which violates idx_tagdef_typesyscode.

  • © Githubissues.
  • Githubissues is a development platform for aggregating issues.