Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Batch transaction produces multiple tags in the TAGDEF table, causing IDX_TAGDEF_TYPESYSCODE constraint exceptions #3156

Open
seanmcilvenna opened this issue Nov 9, 2021 · 5 comments

Comments

@seanmcilvenna
Copy link
Contributor

Describe the bug
Encountered a race condition, where when a transaction is being processed that has multiple resources with the same tag, occasionally, the tag gets created multiple times in the TAGDEF table. Then, HAPI fails because it expects that the tags in that table be unique.

Here's an example of the exception I'm getting:

2021-11-09 00:06:37.591 [http-nio-8080-exec-8] WARN  o.h.e.jdbc.spi.SqlExceptionHelper [SqlExceptionHelper.java:137] SQL Error: 1062, SQLState: 23000
2021-11-09 00:06:37.593 [http-nio-8080-exec-8] ERROR o.h.e.jdbc.spi.SqlExceptionHelper [SqlExceptionHelper.java:142] Duplicate entry '0-https://x.org-y' for key 'IDX_TAGDEF_TYPESYSCODE'
2021-11-09 00:06:37.625 [http-nio-8080-exec-5] ERROR c.u.f.r.s.i.ExceptionHandlingInterceptor [ExceptionHandlingInterceptor.java:140] Failure during REST processing
ca.uhn.fhir.rest.server.exceptions.InternalErrorException: Failed to call access method: org.springframework.dao.DataIntegrityViolationException: could not execute batch; SQL [insert into hfj_tag_def (tag_code, tag_display, tag_system, tag_type, tag_id) values (?, ?, ?, ?, ?)]; constraint [IDX_TAGDEF_TYPESYSCODE]; nested exception is org.hibernate.exception.ConstraintViolationException: could not execute batch
at ca.uhn.fhir.rest.server.method.BaseMethodBinding.invokeServerMethod(BaseMethodBinding.java:272)
at ca.uhn.fhir.rest.server.method.BaseOutcomeReturningMethodBinding.invokeServer(BaseOutcomeReturningMethodBinding.java:154)
at ca.uhn.fhir.rest.server.method.CreateMethodBinding.invokeServer(CreateMethodBinding.java:41)
at ca.uhn.fhir.rest.server.RestfulServer.handleRequest(RestfulServer.java:1146)
at ca.uhn.fhir.rest.server.RestfulServer.doPost(RestfulServer.java:417)
at ca.uhn.fhir.rest.server.RestfulServer.service(RestfulServer.java:1862)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:126)
at org.springframework.boot.web.servlet.support.ErrorPageFilter.access$000(ErrorPageFilter.java:64)
at org.springframework.boot.web.servlet.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:101)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:119)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.lang.reflect.InvocationTargetException: null
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at ca.uhn.fhir.rest.server.method.BaseMethodBinding.invokeServerMethod(BaseMethodBinding.java:264)
... 39 common frames omitted
Caused by: org.springframework.dao.DataIntegrityViolationException: could not execute batch; SQL [insert into hfj_tag_def (tag_code, tag_display, tag_system, tag_type, tag_id) values (?, ?, ?, ?, ?)]; constraint [IDX_TAGDEF_TYPESYSCODE]; nested exception is org.hibernate.exception.ConstraintViolationException: could not execute batch
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:276)
at ca.uhn.fhir.jpa.config.HapiFhirHibernateJpaDialect.convertHibernateAccessException(HapiFhirHibernateJpaDialect.java:120)
at ca.uhn.fhir.jpa.config.HapiFhirHibernateJpaDialect.convertHibernateAccessExc...

To Reproduce

  1. Create a large bundle transaction with many resources that have the same tag
  2. Execute the transaction bundle
  3. Inconsistently and intermittently, it produces an error like shown in the description
  4. Look at the HFJ_TAGDEF table and see that the same tag is listed multiple times

Expected behavior
A lack should be placed on the TAGDEF table when being modified during the batch transaction, or something, so that it does not produce the same tag multiple times in a single transaction.

Environment (please complete the following information):

  • HAPI FHIR Version 5.4.1
  • OS: Ubuntu
  • Browser N/A
@tadgh
Copy link
Collaborator

tadgh commented Dec 15, 2021

Heya @seanmcilvenna , we are actively working on this now. Any chance you happen to have a PHI-redacted version of a bundle that causes this for you? Just to ensure we're working under identical conditions? Cheers

@TipzCM
Copy link
Collaborator

TipzCM commented Dec 16, 2021

Hi, also, if there's any chance you have additional details (more of the stack trace, etc), it could be helpful.

Or if you have encountered it again lately.

@dmeyers138
Copy link

dmeyers138 commented Jan 17, 2022

Hello,
I can only add that we have this problem as well and it occurs when multithreading, so if on a HAPI server with empty dataset for example 4 resources of one type (e.g. patient) are imported at the same time, there are said exceptions. The subsequent imports with new threads run without problems. However, the initial queries are discarded, i.e. we have data loss if we don't keep an eye on this. When using a mysql database I could not observe the behavior, only when using a postgresql db. we use ubuntu + hapi 5.5

@tgorton617
Copy link

I appear to have encountered the same issue, but with multiple single-record POSTs rather than a bundle. here's a short script that inconsistently replicates the issue:

#!/usr/bin/bash

TAG=tag$RANDOM

for i in {1..5}
do
    FAMILYNAME=Smith$RANDOM
    GIVENNAME=John$RANDOM
    curl \
        https://$SERVER/Patient \
        -X POST \
        --header "Content-Type: application/fhir+json" \
        -w "got %{http_code} - %{time_pretransfer} sec to connect, %{time_starttransfer} sec to respond, %{time_total} sec total \n" \
        -s  \
        --data "{
  \"meta\": {
      \"tag\" : [ 
        {
            \"system\" : \"http://mydomain/fhir/custom_tag/test/$TAG\",
            \"code\" : \"a code\"
        }
    ]
  },
  \"resourceType\": \"Patient\",
  \"name\": [ {
      \"family\": \"$FAMILYNAME\",
      \"given\": [ \"$GIVENNAME\" ]
  } ],
  \"gender\": \"male\",
  \"birthDate\": \"1974-12-25\"
}" \
        --output ./result$i.txt &

done

@XcrigX
Copy link
Contributor

XcrigX commented Mar 23, 2023

I'm seeing this on HAPI 6.4.0 talking to an Azure SQL database.
Here is the stack trace and errors I'm seeing.

2023-03-23 14:06:49.668 [https-jsse-nio-8443-exec-5] WARN ca.uhn.fhir.jpa.dao.BaseHapiFhirDao [BaseHapiFhirDao.java:477] Transaction failed with: could not execute batch; SQL [insert into hfj_tag_def (tag_code, tag_display, tag_system, tag_type, tag_user_selected, tag_version, tag_id) values (?, ?, ?, ?, ?, ?, ?)]; constraint [null]; nested exception is org.hibernate.exception.ConstraintViolationException: could not execute batch. Transaction will rollback and be reattempted. 2023-03-23 14:06:49.668 [https-jsse-nio-8443-exec-8] ERROR o.h.e.j.batch.internal.BatchingBatch [BatchingBatch.java:134] HHH000315: Exception executing batch [java.sql.BatchUpdateException: Violation of UNIQUE KEY constraint 'IDX_TAGDEF_TYPESYSCODE'. Cannot insert duplicate key in object 'hapifhir.hfj_tag_def'. The duplicate key value is (1, https://github.com/hapifhir/hapi-fhir/ns/jpa/profile, http://hl7.org/fhir/us/carin-bb/StructureDefinition/C4BB-Coverage|1.1.0).], SQL: insert into hfj_tag_def (tag_code, tag_display, tag_system, tag_type, tag_user_selected, tag_version, tag_id) values (?, ?, ?, ?, ?, ?, ?) 2023-03-23 14:06:49.669 [https-jsse-nio-8443-exec-8] WARN o.h.e.jdbc.spi.SqlExceptionHelper [SqlExceptionHelper.java:137] SQL Error: 2627, SQLState: 23000 2023-03-23 14:06:49.669 [https-jsse-nio-8443-exec-8] ERROR o.h.e.jdbc.spi.SqlExceptionHelper [SqlExceptionHelper.java:142] Violation of UNIQUE KEY constraint 'IDX_TAGDEF_TYPESYSCODE'. Cannot insert duplicate key in object 'hapifhir.hfj_tag_def'. The duplicate key value is (1, https://github.com/hapifhir/hapi-fhir/ns/jpa/profile, http://hl7.org/fhir/us/carin-bb/StructureDefinition/C4BB-Coverage|1.1.0). 2023-03-23 14:06:49.669 [https-jsse-nio-8443-exec-5] ERROR c.u.f.r.s.i.ExceptionHandlingInterceptor [ExceptionHandlingInterceptor.java:175] Failure during REST processing ca.uhn.fhir.rest.server.exceptions.InternalErrorException: HAPI-2023: Tag get/create failed after 10 attempts with error(s): at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.getOrCreateTag(BaseHapiFhirDao.java:494) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.getTagOrNull(BaseHapiFhirDao.java:403) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.extractTagsRi(BaseHapiFhirDao.java:347) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.updateTags(BaseHapiFhirDao.java:763) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.populateResourceIntoEntity(BaseHapiFhirDao.java:622) at ca.uhn.fhir.jpa.dao.BaseHapiFhirDao.updateEntity(BaseHapiFhirDao.java:1017) at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.doCreateForPostOrPut(BaseHapiFhirResourceDao.java:372) at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.doUpdate(BaseHapiFhirResourceDao.java:1709) at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.lambda$update$17(BaseHapiFhirResourceDao.java:1645) at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) at ca.uhn.fhir.jpa.dao.tx.HapiTransactionService.doExecuteCallback(HapiTransactionService.java:290) at ca.uhn.fhir.jpa.dao.tx.HapiTransactionService.doExecute(HapiTransactionService.java:204) at ca.uhn.fhir.jpa.dao.tx.HapiTransactionService$ExecutionBuilder.execute(HapiTransactionService.java:374) at ca.uhn.fhir.jpa.dao.tx.HapiTransactionService.execute(HapiTransactionService.java:141) at ca.uhn.fhir.jpa.dao.tx.HapiTransactionService.execute(HapiTransactionService.java:127) at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.update(BaseHapiFhirResourceDao.java:1645) at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao$$FastClassBySpringCGLIB$$5578fb67.invoke(<generated>) at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants