Hi,
We encounter these kinds of errors:
org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: delete from hsearch_agent where id=?
whenever we shutdown our application on deployment, while using outbox-polling strategy. I wanted to know if there is a way to provide a signal to hibernate-search so that this is handled gracefully?
Hello,
What is the full stack trace, including the JDBC error (if any)?
javax.persistence.OptimisticLockException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: delete from hsearch_agent where id=?
at org.hibernate.internal.ExceptionConverterImpl.wrapStaleStateException(ExceptionConverterImpl.java:238) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:93) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.ExceptionConverterImpl.convertCommitException(ExceptionConverterImpl.java:65) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
Caused by: org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: delete from hsearch_agent where id=?
at org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:67) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:54) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.checkRowCounts(BatchingBatch.java:151) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:126) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.doExecuteBatch(BatchingBatch.java:106) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.execute(AbstractBatchImpl.java:148) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.executeBatch(JdbcCoordinatorImpl.java:198) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:633) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at java.util.LinkedHashMap.forEach(LinkedHashMap.java:684) ~[?:1.8.0_342]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:344) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:99) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1362) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:453) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3212) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2380) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:448) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
javax.persistence.RollbackException: Error while committing the transaction
at org.hibernate.internal.ExceptionConverterImpl.convertCommitException(ExceptionConverterImpl.java:81) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:104) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.search.mapper.orm.common.spi.TransactionHelper.commit(TransactionHelper.java:103) ~[hibernate-search-mapper-orm-6.1.5.Final.jar!/:6.1.5.Final]
at org.hibernate.search.mapper.orm.common.spi.TransactionHelper.inTransaction(TransactionHelper.java:60) ~[hibernate-search-mapper-orm-6.1.5.Final.jar!/:6.1.5.Final]
at org.hibernate.search.mapper.orm.coordination.outboxpolling.event.impl.OutboxPollingEventProcessor$Worker.work(OutboxPollingEventProcessor.java:247) ~[hibernate-search-mapper-orm-coordination-outbox-polling-6.1.5.Final.jar!/:6.1.5.Final]
at org.hibernate.search.engine.backend.orchestration.spi.SingletonTask$RunnableWrapper.run(SingletonTask.java:199) [hibernate-search-engine-6.1.5.Final.jar!/:6.1.5.Final]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_342]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_342]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_342]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_342]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_342]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_342]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_342]
Caused by: javax.persistence.OptimisticLockException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: delete from hsearch_agent where id=?
at org.hibernate.internal.ExceptionConverterImpl.wrapStaleStateException(ExceptionConverterImpl.java:238) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:93) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.ExceptionConverterImpl.convertCommitException(ExceptionConverterImpl.java:65) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
... 12 more
Caused by: org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: delete from hsearch_agent where id=?
at org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:67) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:54) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.checkRowCounts(BatchingBatch.java:151) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:126) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.doExecuteBatch(BatchingBatch.java:106) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.execute(AbstractBatchImpl.java:148) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.executeBatch(JdbcCoordinatorImpl.java:198) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:633) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at java.util.LinkedHashMap.forEach(LinkedHashMap.java:684) ~[?:1.8.0_342]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:344) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:99) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1362) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:453) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3212) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2380) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:448) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
This is… interesting. Shutdown is supposed to be graceful by default, so this situation is abnormal.
First, I would recommend that you upgrade to Hibernate Search 6.1.7.Final, which includes a few fixes to this particular code compared to 6.1.5.Final. Perhaps that will solve your problem.
If the problem still occurs on 6.1.7.Final, the only way I could see this happening is if an agent (A) was forcefully kicked out by another (B), because it failed to issue a pulse in a timely manner, but A finally unregistered itself before B could finish kicking it out.
I’d like to confirm that theory before we try to address the problem. Could you please either:
TRACE level on the logger category org.hibernate.search.mapper.orm.coordination.outboxpolling, and provide the logs of your application when that problem occurs (I’ll need the logs of all application instances, preferably from startup to shutdown).I will upgrade to 6.1.7.Final first and see if the problem persists or not.
It will take some effort to get the TRACE level logs, since I cannot enable it on production systems due to possibility of logs flooding. I will still try to reproduce the scenario on our lower environment on an isolated system if the upgrade doesn’t work.
Thanks.
Rightly so. This will likely produce lots of logs.
Thanks, please keep us updated!
@yrodiere This is another type of ERROR log which is encountered on shutdown:
org.hibernate.search.util.common.SearchException: HSEARCH400588: Call to the bulk REST API failed: HSEARCH400007: Elasticsearch request failed: Connection is closed
Request: POST /_bulk with parameters {}
Response: (no response)
at org.hibernate.search.backend.elasticsearch.orchestration.impl.ElasticsearchDefaultWorkSequenceBuilder$BulkedWorkExecutionState.onBulkWorkComplete(ElasticsearchDefaultWorkSequenceBuilder.java:239) ~[hibernate-search-backend-elasticsearch-6.1.5.Final.jar!/:6.1.5.Final]
at org.hibernate.search.util.common.impl.Futures.lambda$handler$3(Futures.java:100) ~[hibernate-search-util-common-6.1.5.Final.jar!/:6.1.5.Final]
at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:774) ~[?:1.8.0_342]
at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:750) ~[?:1.8.0_342]
at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_342]
at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) ~[?:1.8.0_342]
at org.hibernate.search.backend.elasticsearch.client.impl.ElasticsearchClientImpl$1.onFailure(ElasticsearchClientImpl.java:130) ~[hibernate-search-backend-elasticsearch-6.1.5.Final.jar!/:6.1.5.Final]
at org.elasticsearch.client.RestClient$FailureTrackingResponseListener.onDefinitiveFailure(RestClient.java:633) ~[elasticsearch-rest-client-7.10.0.jar!/:7.10.0]
at org.elasticsearch.client.RestClient$1.failed(RestClient.java:391) ~[elasticsearch-rest-client-7.10.0.jar!/:7.10.0]
at org.apache.http.concurrent.BasicFuture.failed(BasicFuture.java:137) ~[httpcore-4.4.14.jar!/:4.4.14]
at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.executionFailed(DefaultClientExchangeHandlerImpl.java:101) ~[httpasyncclient-4.1.4.jar!/:4.1.4]
at org.apache.http.impl.nio.client.AbstractClientExchangeHandler.failed(AbstractClientExchangeHandler.java:426) ~[httpasyncclient-4.1.4.jar!/:4.1.4]
at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.endOfInput(HttpAsyncRequestExecutor.java:356) ~[httpcore-nio-4.4.14.jar!/:4.4.14]
at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:261) ~[httpcore-nio-4.4.14.jar!/:4.4.14]
at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81) ~[httpasyncclient-4.1.4.jar!/:4.1.4]
at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39) ~[httpasyncclient-4.1.4.jar!/:4.1.4]
at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:121) ~[httpcore-nio-4.4.14.jar!/:4.4.14]
at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162) ~[httpcore-nio-4.4.14.jar!/:4.4.14]
at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337) ~[httpcore-nio-4.4.14.jar!/:4.4.14]
at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315) ~[httpcore-nio-4.4.14.jar!/:4.4.14]
at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276) ~[httpcore-nio-4.4.14.jar!/:4.4.14]
at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104) ~[httpcore-nio-4.4.14.jar!/:4.4.14]
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:591) ~[httpcore-nio-4.4.14.jar!/:4.4.14]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_342]
Caused by: org.hibernate.search.util.common.SearchException: HSEARCH400007: Elasticsearch request failed: Connection is closed
Request: POST /_bulk with parameters {}
Response: (no response)
at org.hibernate.search.backend.elasticsearch.work.impl.AbstractNonBulkableWork.lambda$execute$2(AbstractNonBulkableWork.java:60) ~[hibernate-search-backend-elasticsearch-6.1.5.Final.jar!/:6.1.5.Final]
at org.hibernate.search.util.common.impl.Futures.lambda$handler$1(Futures.java:63) ~[hibernate-search-util-common-6.1.5.Final.jar!/:6.1.5.Final]
at java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:884) ~[?:1.8.0_342]
at java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:866) ~[?:1.8.0_342]
... 20 more
Caused by: org.apache.http.ConnectionClosedException: Connection is closed
... 12 more
Is this an expected behaviour?
EDIT: this might be unrelated. Could be ignored if not known.
It’s not. Hibernate Search normally waits until all indexing works were processed before closing the client.
This could however happen if you’re aggressively shutting down threads in your JVM (sending interrupt signals), or if you shut down the network or Elasticsearch before shutting down Hibernate Search.
Possibly, yes.
Hi @yrodiere , even after upgrading to 6.1.7.Final, the issue did not get fixed.
I will try to describe the scenario for you to get an idea. On production, we have different sets of servers who all have outbox-polling strategy enabled on them. We do deployment on all sets in parallel except one. The deployment is of blue green type.
For instance, there is 1 server A, 2 server Bs, 5 server Cs etc.
For deployment of A, we first terminate existing server (exceptional case), and with that also we get this exception
org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: delete from hsearch_agent where id=?
For all other server sets, new servers are deployed first and older ones get terminated after that. (all these are AWS EC2s with Springboot based jars). The error only shows up for “some” servers in those server sets. So it is probably not something that is bound to happen each and every time.
Thanks for the details. I’ll need more info to fix this, though; as I explained we do have code to gracefully shut down agents when the application shuts down, as well as tests which so far haven’t been failing (even randomly).
Ideally, I would need a reproducer. If you can provide one, that would be great. Try to use the same database, the same Hibernate Search configuration, the same method of shutdown (signals ? other?). You probably don’t need to bother using the same domain model as you’re getting errors in agent management, which is kind of orthogonal to indexing. Just make sure to have at least one indexed entity.
There are test case template here, but they’re not really adapted to multi-instance testing. If you can’t automate the test and just provide a list of instructions, that’s fine, though.
The database, Hibernate Search configuration and method of shutdown are already the same between all of them.
I will see if I can come up with a reproducer.
@yrodiere I tried implementing a graceful shutdown using custom endpoint in actuator, I encountered this error:
org.hibernate.search.util.common.SearchException: HSEARCH000520: Hibernate Search encountered failures during shutdown. Failures:
Hibernate ORM mapping:
failures:
- EntityManagerFactory is closed
at org.hibernate.search.engine.reporting.spi.RootFailureCollector.checkNoFailure(RootFailureCollector.java:53) ~[hibernate-search-engine-6.1.7.Final.jar!/:6.1.7.Final]
at org.hibernate.search.engine.common.impl.SearchIntegrationImpl.close(SearchIntegrationImpl.java:168) ~[hibernate-search-engine-6.1.7.Final.jar!/:6.1.7.Final]
at org.hibernate.search.mapper.orm.mapping.impl.HibernateSearchContextProviderService.close(HibernateSearchContextProviderService.java:36) ~[hibernate-search-mapper-orm-6.1.7.Final.jar!/:6.1.7.Final]
at org.hibernate.search.mapper.orm.bootstrap.impl.HibernateOrmIntegrationBooterImpl.lambda$orchestrateBootAndShutdown$5(HibernateOrmIntegrationBooterImpl.java:156) ~[hibernate-search-mapper-orm-6.1.7.Final.jar!/:6.1.7.Final]
at java.util.concurrent.CompletableFuture.biAccept(CompletableFuture.java:1190) ~[?:1.8.0_342]
at java.util.concurrent.CompletableFuture$BiAccept.tryFire(CompletableFuture.java:1155) ~[?:1.8.0_342]
at java.util.concurrent.CompletableFuture$CoCompletion.tryFire(CompletableFuture.java:1034) ~[?:1.8.0_342]
at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) [?:1.8.0_342]
at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1975) [?:1.8.0_342]
at org.hibernate.search.mapper.orm.bootstrap.impl.HibernateSearchSessionFactoryObserver.sessionFactoryClosing(HibernateSearchSessionFactoryObserver.java:50) [hibernate-search-mapper-orm-6.1.7.Final.jar!/:6.1.7.Final]
at org.hibernate.internal.SessionFactoryObserverChain.sessionFactoryClosing(SessionFactoryObserverChain.java:48) [hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:793) [hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_342]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_342]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_342]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_342]
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.invokeProxyMethod(AbstractEntityManagerFactoryBean.java:519) [spring-orm-5.3.9.jar!/:5.3.9]
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean$ManagedEntityManagerFactoryInvocationHandler.invoke(AbstractEntityManagerFactoryBean.java:734) [spring-orm-5.3.9.jar!/:5.3.9]
at com.sun.proxy.$Proxy281.close(Unknown Source) [?:?]
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.destroy(AbstractEntityManagerFactoryBean.java:653) [spring-orm-5.3.9.jar!/:5.3.9]
at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:200) [spring-beans-5.3.9.jar!/:5.3.9]
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:587) [spring-beans-5.3.9.jar!/:5.3.9]
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:559) [spring-beans-5.3.9.jar!/:5.3.9]
at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1152) [spring-beans-5.3.9.jar!/:5.3.9]
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:520) [spring-beans-5.3.9.jar!/:5.3.9]
at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1145) [spring-beans-5.3.9.jar!/:5.3.9]
at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1106) [spring-context-5.3.9.jar!/:5.3.9]
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1075) [spring-context-5.3.9.jar!/:5.3.9]
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.doClose(ServletWebServerApplicationContext.java:172) [spring-boot-2.5.4.jar!/:2.5.4]
at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1021) [spring-context-5.3.9.jar!/:5.3.9]
at org.springframework.boot.SpringApplication.close(SpringApplication.java:1401) [spring-boot-2.5.4.jar!/:2.5.4]
at org.springframework.boot.SpringApplication.exit(SpringApplication.java:1388) [spring-boot-2.5.4.jar!/:2.5.4]
This is the snippet that is used to invoke the shutdown:
SpringApplication.exit(applicationContext, () -> 0);
You probably have a log with more details (a relevant stacktrace, in particular) before this. Can you paste that log?
The one that I provided is logged by org.hibernate.search.mapper.orm.bootstrap.impl.HibernateOrmIntegrationBooterImpl.
Another is logged by org.hibernate.search.engine.reporting.impl.LogFailureHandler
HSEARCH000058: Exception occurred java.lang.IllegalStateException: EntityManagerFactory is closed
Failing operation:
Executing task 'Outbox event processor'
java.lang.IllegalStateException: EntityManagerFactory is closed
at org.hibernate.internal.SessionFactoryImpl.validateNotClosed(SessionFactoryImpl.java:530) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionFactoryImpl.getCache(SessionFactoryImpl.java:828) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.AbstractSharedSessionContract.<init>(AbstractSharedSessionContract.java:159) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.AbstractSessionImpl.<init>(AbstractSessionImpl.java:29) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionImpl.<init>(SessionImpl.java:221) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.internal.SessionFactoryImpl$SessionBuilderImpl.openSession(SessionFactoryImpl.java:1282) ~[hibernate-core-5.4.32.Final.jar!/:5.4.32.Final]
at org.hibernate.search.mapper.orm.common.spi.SessionHelper.openSession(SessionHelper.java:28) ~[hibernate-search-mapper-orm-6.1.7.Final.jar!/:6.1.7.Final]
at org.hibernate.search.mapper.orm.coordination.outboxpolling.event.impl.OutboxPollingEventProcessor$Worker.work(OutboxPollingEventProcessor.java:242) ~[hibernate-search-mapper-orm-coordination-outbox-polling-6.1.7.Final.jar!/:6.1.7.Final]
at org.hibernate.search.engine.backend.orchestration.spi.SingletonTask$RunnableWrapper.run(SingletonTask.java:199) [hibernate-search-engine-6.1.7.Final.jar!/:6.1.7.Final]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_342]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_342]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_342]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_342]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_342]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_342]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_342]
Ok, so this is actually your problem:
hibernate-core-5.4.32.Final
You’re using Hibernate ORM 5.4, which:
There’s no workaround on the Hibernate Search side, your only solution is to either live with those errors (they’re not critical, as long as they happen only on shutdown), or upgrade to Hibernate ORM 5.6 (or, better, 6.2; but that’s probably more work).
Thanks for the pointer, I will try upgrading the Hibernate ORM.
Update: This is fixed by upgrading to 5.6.11.Final version for hibernate-core. Now, this log shows up on triggering application shutdown:
Agent '#1 - Outbox event processor': leaving cluster
Thanks @yrodiere.