[hibernate-issues] [JIRA] (HHH-13926) StaleStateException should (optionally) not leak statements in the logs
Mickaël TRICOT (JIRA)
jira at hibernate.atlassian.net
Wed Jul 8 16:10:05 EDT 2020
Mickaël TRICOT ( https://hibernate.atlassian.net/secure/ViewProfile.jspa?accountId=557058%3A0d3f573f-438e-4be7-b5ec-528c5465e34b ) *commented* on HHH-13926 ( https://hibernate.atlassian.net/browse/HHH-13926?atlOrigin=eyJpIjoiY2MyYmM3MzRmMTVhNDE2OGIxYmJhODg0ZGFlZDMzMTgiLCJwIjoiaiJ9 )
Re: StaleStateException should (optionally) not leak statements in the logs ( https://hibernate.atlassian.net/browse/HHH-13926?atlOrigin=eyJpIjoiY2MyYmM3MzRmMTVhNDE2OGIxYmJhODg0ZGFlZDMzMTgiLCJwIjoiaiJ9 )
Hello Sanne,
The problem in my case is that we handle nominative health data and we can’t have them in the applications logs. Here is an example stacktrace:
13:52:46.834 [ForkJoinPool.commonPool-worker-3] ERROR o.h.e.j.batch.internal.BatchingBatch - HHH000315: Exception executing batch [org.hibernate.StaleStateException: Batch update returned unexpected row count from update [1]; actual row count: 0; expected: 1; statement executed: HikariProxyPreparedStatement at 1522577332 wrapping update patient set city='Gotham', country='US', line='Manoir Wayne', postal_code='12000', birth_date='1964-03-12 +00', email='batman at goth.com', family_name_official='Wayne', family_name_usual=NULL, first_name='Bruce', gender='male', last_crm_update='2020-04-03 13:52:21.638307+00', last_modified='2020-04-03 13:42:06.158879+00', phone='06 01 01 01 05', version=2 where id='749863f8-f148-4f3b-90eb-35841a26e12f'::uuid and version=1], SQL: update patient set city=?, country=?, line=?, postal_code=?, birth_date=?, email=?, family_name_official=?, family_name_usual=?, first_name=?, gender=?, last_crm_update=?, last_modified=?, phone=?, version=? where id=? and version=?
13:52:46.847 [ForkJoinPool.commonPool-worker-3] ERROR c.s.s.backend.infra.job.JobDecorator - Job failed: AutoUpdateCrmAppointments
[1] org.springframework.orm.ObjectOptimisticLockingFailureException: Batch update returned unexpected row count from update [1]; actual row count: 0; expected: 1; statement executed: HikariProxyPreparedStatement at 1522577332 wrapping update patient set city='Gotham', country='US', line='Manoir Wayne', postal_code='12000', birth_date='1964-03-12 +00', email='batman at goth.com', family_name_official='Wayne', family_name_usual=NULL, first_name='Bruce', gender='male', last_crm_update='2020-04-03 13:52:21.638307+00', last_modified='2020-04-03 13:42:06.158879+00', phone='06 01 01 01 05', version=2 where id='749863f8-f148-4f3b-90eb-35841a26e12f'::uuid and version=1; nested exception is org.hibernate.StaleStateException: Batch update returned unexpected row count from update [1]; actual row count: 0; expected: 1; statement executed: HikariProxyPreparedStatement at 1522577332 wrapping update patient set city='Gotham', country='US', line='Manoir Wayne', postal_code='12000', birth_date='1964-03-12 +00', email='batman at goth.com', family_name_official='Wayne', family_name_usual=NULL, first_name='Bruce', gender='male', last_crm_update='2020-04-03 13:52:21.638307+00', last_modified='2020-04-03 13:42:06.158879+00', phone='06 01 01 01 05', version=2 where id='749863f8-f148-4f3b-90eb-35841a26e12f'::uuid and version=1
[1] at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:340)
[1] at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:255)
[1] at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:538)
[1] at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743)
[1] at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)
[1] at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:631)
[1] at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:385)
[1] at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:118)
[1] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
[1] at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
[1] at net.javacrumbs.shedlock.core.DefaultLockingTaskExecutor.executeWithLock(DefaultLockingTaskExecutor.java:73)
[1] at net.javacrumbs.shedlock.spring.aop.MethodProxyScheduledLockAdvisor$LockingInterceptor.invoke(MethodProxyScheduledLockAdvisor.java:85)
[1] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
[1] at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
[1] at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
[1] at com.serenitymedicalservices.smc.backend.use_cases.crm.AutoUpdateCrmAppointments$$EnhancerBySpringCGLIB$$3cbc2df0.perform(<generated>)
[1] at com.serenitymedicalservices.smc.backend.infra.job.JobDecorator.run(JobDecorator.java:35)
[1] at com.serenitymedicalservices.smc.backend.infra.job.RunAsyncJob.lambda$perform$0(RunAsyncJob.java:13)
[1] at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1800)
[1] at java.base/java.util.concurrent.CompletableFuture$AsyncRun.exec(CompletableFuture.java:1792)
[1] at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
[1] at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1016)
[1] at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1665)
[1] at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1598)
[1] at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)
[1] Caused by: org.hibernate.StaleStateException: Batch update returned unexpected row count from update [1]; actual row count: 0; expected: 1; statement executed: HikariProxyPreparedStatement at 1522577332 wrapping update patient set city='Gotham', country='US', line='Manoir Wayne', postal_code='12000', birth_date='1964-03-12 +00', email='batman at goth.com', family_name_official='Wayne', family_name_usual=NULL, first_name='Bruce', gender='male', last_crm_update='2020-04-03 13:52:21.638307+00', last_modified='2020-04-03 13:42:06.158879+00', phone='06 01 01 01 05', version=2 where id='749863f8-f148-4f3b-90eb-35841a26e12f'::uuid and version=1
[1] at org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:67)
[1] at org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:54)
[1] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.checkRowCounts(BatchingBatch.java:149)
[1] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:124)
[1] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.doExecuteBatch(BatchingBatch.java:105)
[1] at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.execute(AbstractBatchImpl.java:148)
[1] at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.executeBatch(JdbcCoordinatorImpl.java:198)
[1] at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:633)
[1] at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478)
[1] at java.base/java.util.LinkedHashMap.forEach(LinkedHashMap.java:723)
[1] at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475)
[1] at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:348)
[1] at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40)
[1] at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:102)
[1] at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1352)
[1] at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:443)
[1] at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3202)
[1] at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2370)
[1] at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:447)
[1] at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183)
[1] at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40)
[1] at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281)
[1] at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101)
[1] at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:534)
[1] ... 22 common frames omitted
You are correct, the problem is not the statement but the parameter values. I would be perfectly fine if we would just remove those values from the exception message.
We use:
* Spring Boot 2.3.1
* HikariCP 3.4.5
* PostgreSQL driver 42.2.14
Thanks for your help
( https://hibernate.atlassian.net/browse/HHH-13926#add-comment?atlOrigin=eyJpIjoiY2MyYmM3MzRmMTVhNDE2OGIxYmJhODg0ZGFlZDMzMTgiLCJwIjoiaiJ9 ) Add Comment ( https://hibernate.atlassian.net/browse/HHH-13926#add-comment?atlOrigin=eyJpIjoiY2MyYmM3MzRmMTVhNDE2OGIxYmJhODg0ZGFlZDMzMTgiLCJwIjoiaiJ9 )
Get Jira notifications on your phone! Download the Jira Cloud app for Android ( https://play.google.com/store/apps/details?id=com.atlassian.android.jira.core&referrer=utm_source%3DNotificationLink%26utm_medium%3DEmail ) or iOS ( https://itunes.apple.com/app/apple-store/id1006972087?pt=696495&ct=EmailNotificationLink&mt=8 ) This message was sent by Atlassian Jira (v1001.0.0-SNAPSHOT#100133- sha1:abe90d4 )
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/hibernate-issues/attachments/20200708/2ffa57f2/attachment.html
More information about the hibernate-issues
mailing list