"could not prepare statement" ("Connection is closed") when reusing a session for another transaction after a rollback

[yrodiere]

Describe the bug

This sequence of actions causes ORM to reuse a connection that was closed implicitly by Agroal, ultimately throwing an exception:

• Open session manually
• Open JTA transaction manually
• Do stuff in ORM => ORM opens a transaction
• Roll back the transaction => ORM should have closed the connection, but it didn't, so Agroal closes the transaction without telling it.
• Start another transaction
• Do stuff in ORM => ORM thinks the connection is still open, so it reuses it, resulting in an exception.

This happens in particular when mass indexing in Hibernate Search, because Hibernate Search rolls back transactions instead of committing them, since it only reads data.

Expected behavior

No exception. ORM should close connections on rollback, at least with the default connection handling mode.

Actual behavior

Mass indexing fails after the first batch, with errors like this:

2021-04-13 08:53:01,407 ERROR [org.hib.sea.eng.rep.imp.LogFailureHandler] (Hibernate Search - Mass indexing - FruitEntity - Entity loading - 8) HSEARCH000058: Exception occurred javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not prepare statement
Failing operation:
Loading and extracting entity data for entity 'FruitEntity' during mass indexing
: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not prepare statement
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
	at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
	at org.hibernate.query.Query.getResultList(Query.java:165)
	at org.hibernate.query.criteria.internal.compile.CriteriaQueryTypeQueryAdapter.getResultList(CriteriaQueryTypeQueryAdapter.java:76)
	at org.hibernate.search.mapper.orm.massindexing.impl.IdentifierConsumerDocumentProducer.loadAndIndexList(IdentifierConsumerDocumentProducer.java:154)
	at org.hibernate.search.mapper.orm.massindexing.impl.IdentifierConsumerDocumentProducer.loadAndIndexAllFromQueue(IdentifierConsumerDocumentProducer.java:123)
	at org.hibernate.search.mapper.orm.massindexing.impl.IdentifierConsumerDocumentProducer.run(IdentifierConsumerDocumentProducer.java:103)
	at org.hibernate.search.util.common.impl.CancellableExecutionCompletableFuture$CompletingRunnable.run(CancellableExecutionCompletableFuture.java:49)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:264)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.hibernate.exception.GenericJDBCException: could not prepare statement
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
	at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:186)
	at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151)
	at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:2103)
	at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2040)
	at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2018)
	at org.hibernate.loader.Loader.doQuery(Loader.java:948)
	at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:349)
	at org.hibernate.loader.Loader.doList(Loader.java:2849)
	at org.hibernate.loader.Loader.doList(Loader.java:2831)
	at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2663)
	at org.hibernate.loader.Loader.list(Loader.java:2658)
	at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:506)
	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:1414)
	at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1625)
	at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1593)
	... 12 more
Caused by: java.sql.SQLException: Connection is closed
	at io.agroal.pool.wrapper.ConnectionWrapper.lambda$static$0(ConnectionWrapper.java:51)
	at com.sun.proxy.$Proxy92.prepareStatement(Unknown Source)
	at io.agroal.pool.wrapper.ConnectionWrapper.prepareStatement(ConnectionWrapper.java:616)
	at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
	at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
	... 28 more

To Reproduce

Originally reported by @suchwerk: thanks to him!

Reproducer (in Quarkus): https://github.com/suchwerk/quarkus-hibernate-search-massindexer

You'll need to start an Elasticsearch container, then run the tests:

docker run -it --rm=true --name es-7.10-it -p 9200:9200 -e "discovery.type=single-node" docker.elastic.co/elasticsearch/elasticsearch-oss:7.10.0
./mvnw clean verify

Configuration

N/A

Screenshots

N/A

Environment (please complete the following information):

Quarkus version or git rev

1.13.1.Final

Probably applies to 1.13.x only, since we switched the connection handling mode in 1.13.0.Final.

[yrodiere]

I opened https://hibernate.atlassian.net/browse/HHH-14557 to resolve the problem upstream.

In Quarkus itself, we mostly need to add a test. I suspect the mass indexing test we currently have uses a trivial dataset, resulting in only processing a single batch when mass indexing...

[quarkus-bot]

/cc @Sanne, @gsmet

[Sanne]

because Hibernate Search rolls back transactions instead of committing them, since it only reads data.

I'm not convinced that this is a good idea. There is wide-spread cargo-cult about this pattern but as far as I know it's better to still commit.

[yrodiere]

@Sanne Glad to hear that: hibernate/hibernate-search#2545. That was very old code, I think :)

[Sanne]

hoo yes I remember some discussions about that :)

+1 to just commit, but it's worth remembering the reason it used to be like that (as far as I remember now) : users might have dodgy code in their entities which makes it flagged dirty just because we've loaded it. Make sure to disable flushing.

[gsmet]

@suchwerk a workaround is coming in 1.13.2.Final!

[yrodiere]

Also, an actual fix was merged into Hibernate ORM: hibernate/hibernate-orm#3918

This issue should be completely fixed in Quarkus once we upgrade to ORM 5.4.31.Final or 5.5.0.Final (not released yet).