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

[tyfoni-systematic]

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 (#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):

• HAPI FHIR Version: 5.7.0
• OS: [e.g. iOS]. Linux/Kubernetes
• Browser [e.g. chrome, safari]: N/A

Workaround
I will make a local modification reverting "3156 multiple tag race condition (#3297)" to get the previous behaviour.

Additional context
The Goal resource (xml):
<Goal xmlns="http://hl7.org/fhir"> <lifecycleStatus value="accepted"/> <description> <coding> <system value="http://ehealth.sundhed.dk/cs/goal-description"/> <code value="reference-value"/> </coding> </description> <subject> <reference value="https://patient.local.ehealth.sundhed.dk/fhir/Patient/46350"/> </subject> <startDate value="2022-02-22"/> <target> <measure> <coding> <system value="urn:oid:1.2.208.176.2.1"/> <code value="NPU03011"/> </coding> </measure> </target> <addresses> <reference value="https://careplan.local.ehealth.sundhed.dk/fhir/ServiceRequest/3"/> </addresses> </Goal>
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]

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]

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]

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]

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]

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]

@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 :
9d70dbd#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]

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.