hapifhir
JobMaintenanceServiceImpl is failing with: Unable to access lob stream - hapifhir 6.1.0:
We have upgraded to hapifhir 6.1.0 and starts seeing stacktraces from an internal service: "JobMaintenanceServiceImpl is failing with: Unable to access lob stream"
To Reproduce We do not have to do anything. It seems to be related to scheduled jobs.
Expected behavior No exception stacktraces
Environment (please complete the following information):
- HAPI FHIR Version 6.1.0
- OS: linux (K8S)
- Browser: N/A
Additional context
2022-09-14 12:02:32.044 ERROR 1 [ler-clustered-3] o.q.c.JobRunShell : Job HAPI.ca.uhn.fhir.batch2.maintenance.JobMaintenanceServiceImpl$JobMaintenanceScheduledJob threw an unhandled Exception: org.springframework.orm.jpa.JpaSystemException: Unable to access lob stream; nested exception is org.hibernate.HibernateException: Unable to access lob stream at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:331) at ca.uhn.fhir.jpa.config.HapiFhirHibernateJpaDialect.convertHibernateAccessException(HapiFhirHibernateJpaDialect.java:121) at ca.uhn.fhir.jpa.config.HapiFhirHibernateJpaDialect.convertHibernateAccessException(HapiFhirHibernateJpaDialect.java:64) at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:233) at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:61) at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:242) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:152) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:145) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) at jdk.proxy2/jdk.proxy2.$Proxy260.fetchChunks(Unknown Source) at ca.uhn.fhir.jpa.batch2.JpaJobPersistenceImpl.fetchChunks(JpaJobPersistenceImpl.java:261) at ca.uhn.fhir.jpa.batch2.JpaJobPersistenceImpl.lambda$fetchAllWorkChunksIterator$4(JpaJobPersistenceImpl.java:277) at ca.uhn.fhir.model.api.PagingIterator.fetchNextBatch(PagingIterator.java:70) at ca.uhn.fhir.model.api.PagingIterator.hasNext(PagingIterator.java:52) at ca.uhn.fhir.batch2.progress.JobInstanceProgressCalculator.calculateAndStoreInstanceProgress(JobInstanceProgressCalculator.java:52) at ca.uhn.fhir.batch2.maintenance.JobInstanceProcessor.cleanupInstance(JobInstanceProcessor.java:97) at ca.uhn.fhir.batch2.maintenance.JobInstanceProcessor.process(JobInstanceProcessor.java:71) at ca.uhn.fhir.batch2.maintenance.JobMaintenanceServiceImpl.runMaintenancePass(JobMaintenanceServiceImpl.java:121) at ca.uhn.fhir.batch2.maintenance.JobMaintenanceServiceImpl$JobMaintenanceScheduledJob.execute(JobMaintenanceServiceImpl.java:137) at org.quartz.core.JobRunShell.run(JobRunShell.java:202) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) Caused by: org.hibernate.HibernateException: Unable to access lob stream at org.hibernate.type.descriptor.java.DataHelper.extractString(DataHelper.java:270) at org.hibernate.type.descriptor.java.StringTypeDescriptor.wrap(StringTypeDescriptor.java:75) at org.hibernate.type.descriptor.java.StringTypeDescriptor.wrap(StringTypeDescriptor.java:22) at org.hibernate.type.descriptor.sql.ClobTypeDescriptor$1.doExtract(ClobTypeDescriptor.java:44) at org.hibernate.type.descriptor.sql.BasicExtractor.extract(BasicExtractor.java:47) at org.hibernate.type.AbstractStandardBasicType.nullSafeGet(AbstractStandardBasicType.java:257) at org.hibernate.type.AbstractStandardBasicType.nullSafeGet(AbstractStandardBasicType.java:253) at org.hibernate.type.AbstractStandardBasicType.nullSafeGet(AbstractStandardBasicType.java:243) at org.hibernate.type.AbstractStandardBasicType.hydrate(AbstractStandardBasicType.java:329) at org.hibernate.persister.entity.AbstractEntityPersister.hydrate(AbstractEntityPersister.java:3214) at org.hibernate.loader.Loader.loadFromResultSet(Loader.java:1887) at org.hibernate.loader.Loader.hydrateEntityState(Loader.java:1811) at org.hibernate.loader.Loader.instanceNotYetLoaded(Loader.java:1784) at org.hibernate.loader.Loader.getRow(Loader.java:1624) at org.hibernate.loader.Loader.getRowFromResultSet(Loader.java:748) at org.hibernate.loader.Loader.getRowsFromResultSet(Loader.java:1047) at org.hibernate.loader.Loader.processResultSet(Loader.java:998) at org.hibernate.loader.Loader.doQuery(Loader.java:967) 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:1459) at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1649) at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1617) at org.hibernate.query.Query.getResultList(Query.java:165) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at org.springframework.orm.jpa.SharedEntityManagerCreator$DeferredQueryInvocationHandler.invoke(SharedEntityManagerCreator.java:406) at jdk.proxy2/jdk.proxy2.$Proxy424.getResultList(Unknown Source) at org.springframework.data.jpa.repository.query.JpaQueryExecution$CollectionExecution.doExecute(JpaQueryExecution.java:128) at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:90) at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:156) at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:144) at org.springframework.data.repository.core.support.RepositoryMethodInvoker.doInvoke(RepositoryMethodInvoker.java:137) at org.springframework.data.repository.core.support.RepositoryMethodInvoker.invoke(RepositoryMethodInvoker.java:121) at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:159) at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:138) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:80) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137) ... 18 more Caused by: org.postgresql.util.PSQLException: Large Objects may not be used in auto-commit mode. at org.postgresql.largeobject.LargeObjectManager.open(LargeObjectManager.java:243) at org.postgresql.largeobject.LargeObjectManager.open(LargeObjectManager.java:229) at org.postgresql.jdbc.AbstractBlobClob.getLo(AbstractBlobClob.java:272) at org.postgresql.jdbc.AbstractBlobClob.getBinaryStream(AbstractBlobClob.java:117) at org.postgresql.jdbc.PgClob.getCharacterStream(PgClob.java:54) at org.hibernate.type.descriptor.java.DataHelper.extractString(DataHelper.java:263) ... 69 more 2022-09-14 12:02:32.116 ERROR 1 [ler-clustered-3] o.q.c.ErrorLogger : Job (HAPI.ca.uhn.fhir.batch2.maintenance.JobMaintenanceServiceImpl$JobMaintenanceScheduledJob threw an exception. org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: org.springframework.orm.jpa.JpaSystemException: Unable to access lob stream; nested exception is org.hibernate.HibernateException: Unable to access lob stream] at org.quartz.core.JobRunShell.run(JobRunShell.java:213) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) Caused by: org.springframework.orm.jpa.JpaSystemException: Unable to access lob stream; nested exception is org.hibernate.HibernateException: Unable to access lob stream at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:331) at ca.uhn.fhir.jpa.config.HapiFhirHibernateJpaDialect.convertHibernateAccessException(HapiFhirHibernateJpaDialect.java:121) at ca.uhn.fhir.jpa.config.HapiFhirHibernateJpaDialect.convertHibernateAccessException(HapiFhirHibernateJpaDialect.java:64) at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:233) at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:61) at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:242) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:152) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:145) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) at jdk.proxy2/jdk.proxy2.$Proxy260.fetchChunks(Unknown Source) at ca.uhn.fhir.jpa.batch2.JpaJobPersistenceImpl.fetchChunks(JpaJobPersistenceImpl.java:261) at ca.uhn.fhir.jpa.batch2.JpaJobPersistenceImpl.lambda$fetchAllWorkChunksIterator$4(JpaJobPersistenceImpl.java:277) at ca.uhn.fhir.model.api.PagingIterator.fetchNextBatch(PagingIterator.java:70) at ca.uhn.fhir.model.api.PagingIterator.hasNext(PagingIterator.java:52) at ca.uhn.fhir.batch2.progress.JobInstanceProgressCalculator.calculateAndStoreInstanceProgress(JobInstanceProgressCalculator.java:52) at ca.uhn.fhir.batch2.maintenance.JobInstanceProcessor.cleanupInstance(JobInstanceProcessor.java:97) at ca.uhn.fhir.batch2.maintenance.JobInstanceProcessor.process(JobInstanceProcessor.java:71) at ca.uhn.fhir.batch2.maintenance.JobMaintenanceServiceImpl.runMaintenancePass(JobMaintenanceServiceImpl.java:121) at ca.uhn.fhir.batch2.maintenance.JobMaintenanceServiceImpl$JobMaintenanceScheduledJob.execute(JobMaintenanceServiceImpl.java:137) at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ... 1 more Caused by: org.hibernate.HibernateException: Unable to access lob stream at org.hibernate.type.descriptor.java.DataHelper.extractString(DataHelper.java:270) at org.hibernate.type.descriptor.java.StringTypeDescriptor.wrap(StringTypeDescriptor.java:75) at org.hibernate.type.descriptor.java.StringTypeDescriptor.wrap(StringTypeDescriptor.java:22) at org.hibernate.type.descriptor.sql.ClobTypeDescriptor$1.doExtract(ClobTypeDescriptor.java:44) at org.hibernate.type.descriptor.sql.BasicExtractor.extract(BasicExtractor.java:47) at org.hibernate.type.AbstractStandardBasicType.nullSafeGet(AbstractStandardBasicType.java:257) at org.hibernate.type.AbstractStandardBasicType.nullSafeGet(AbstractStandardBasicType.java:253) at org.hibernate.type.AbstractStandardBasicType.nullSafeGet(AbstractStandardBasicType.java:243) at org.hibernate.type.AbstractStandardBasicType.hydrate(AbstractStandardBasicType.java:329) at org.hibernate.persister.entity.AbstractEntityPersister.hydrate(AbstractEntityPersister.java:3214) at org.hibernate.loader.Loader.loadFromResultSet(Loader.java:1887) at org.hibernate.loader.Loader.hydrateEntityState(Loader.java:1811) at org.hibernate.loader.Loader.instanceNotYetLoaded(Loader.java:1784) at org.hibernate.loader.Loader.getRow(Loader.java:1624) at org.hibernate.loader.Loader.getRowFromResultSet(Loader.java:748) at org.hibernate.loader.Loader.getRowsFromResultSet(Loader.java:1047) at org.hibernate.loader.Loader.processResultSet(Loader.java:998) at org.hibernate.loader.Loader.doQuery(Loader.java:967) 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:1459) at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1649) at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1617) at org.hibernate.query.Query.getResultList(Query.java:165) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at org.springframework.orm.jpa.SharedEntityManagerCreator$DeferredQueryInvocationHandler.invoke(SharedEntityManagerCreator.java:406) at jdk.proxy2/jdk.proxy2.$Proxy424.getResultList(Unknown Source) at org.springframework.data.jpa.repository.query.JpaQueryExecution$CollectionExecution.doExecute(JpaQueryExecution.java:128) at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:90) at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:156) at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:144) at org.springframework.data.repository.core.support.RepositoryMethodInvoker.doInvoke(RepositoryMethodInvoker.java:137) at org.springframework.data.repository.core.support.RepositoryMethodInvoker.invoke(RepositoryMethodInvoker.java:121) at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:159) at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:138) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:80) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137) ... 18 more Caused by: org.postgresql.util.PSQLException: Large Objects may not be used in auto-commit mode. at org.postgresql.largeobject.LargeObjectManager.open(LargeObjectManager.java:243) at org.postgresql.largeobject.LargeObjectManager.open(LargeObjectManager.java:229) at org.postgresql.jdbc.AbstractBlobClob.getLo(AbstractBlobClob.java:272) at org.postgresql.jdbc.AbstractBlobClob.getBinaryStream(AbstractBlobClob.java:117) at org.postgresql.jdbc.PgClob.getCharacterStream(PgClob.java:54) at org.hibernate.type.descriptor.java.DataHelper.extractString(DataHelper.java:263) ... 69 more
That exception as well as the attached stack trace both suggest that this DB call is happening without an active database transaction.
JpaJobPersistenceImpl is definitely marked as @Transactional here: link
And yet the attached stack trace shows that calls to it have not been wrapped in a transaction:
at jdk.proxy2/jdk.proxy2.$Proxy260.fetchChunks(Unknown Source) at ca.uhn.fhir.jpa.batch2.JpaJobPersistenceImpl.fetchChunks(JpaJobPersistenceImpl.java:261) at ca.uhn.fhir.jpa.batch2.JpaJobPersistenceImpl.lambda$fetchAllWorkChunksIterator$4(JpaJobPersistenceImpl.java:277) at ca.uhn.fhir.model.api.PagingIterator.fetchNextBatch(PagingIterator.java:70) at ca.uhn.fhir.model.api.PagingIterator.hasNext(PagingIterator.java:52)
This isn't occurring on any of the environments I have access to - Is this using the JPA Starter project? Maybe something is wrong with how boot is wiring the @Transactional annotation?
We are using XA transactions with Atomikos. I agree that JpaJobPersistenceImpl is marked @Transactional, but in our case we still see the exception. The workaround we have come up with is to mark runMaintenancePass() @Transactional commit
This sounds to me like it's a bug with Atomikos (or a config issue) if it's not respecting the transactional annotation on the JpaJobPersistenceImpl. We deliberately don't mark the method you patched as transactional because the maintenance service is designed to work in individually committed chunks as opposed to doing all work in one big outer one.
We see the error and are not using Atomikos. I'll try to see if I can cook up a scenario using the starter project
We see the same issue. I was able to reproduce it using the starter project. Apparently the exception is caused by SearchParameters having more than one base.
Steps to reproduce:
- Use a
hapi-fhir-jpaserver-startertagimage/v6.1.0adjusted to use PostgreSQL (you can find one here https://github.com/rti/hapi-fhir-jpaserver-starter/tree/v6.1.0-postgres) - Start the server using
docker compose up - As soon as you add a
SearchParameterwith multiplebasetypes and wait a bit or restart the server to trigger batch processing, the exception will be thrown.
curl -X 'POST' \
'http://localhost:8080/fhir/' \
-H 'accept: application/fhir+json' \
-H 'Content-Type: application/fhir+json' \
-d '{
"resourceType": "Bundle",
"type": "transaction",
"entry": [
{
"fullUrl": "SearchParameter/example",
"resource": {
"resourceType": "SearchParameter",
"id": "SearchParameter-Example",
"url": "https://example.org/fhir/SearchParameter/example",
"name": "example",
"base": [
"Organization", "Group"
],
"status": "active",
"code": "example",
"type": "string",
"expression": "identifier.value"
},
"request": {
"method": "PUT",
"url": "SearchParameter/example"
}
}
]
}'
