"WARN Closing open connection prior to commit" when handling BEFORE_COMMIT event

[HelvetiaAppDev]

Describe the bug

When using javax.enterprise.event Events and an Observer with TransactionPhase.BEFORE_COMPLETION that queries anything with sql the WARN log WARN [io.agr.pool] (executor-thread-0) Datasource '': Closing open connection prior to commit appears.

Expected behavior

No WARN log.

Actual behavior

Logs WARN [io.agr.pool] (executor-thread-0) Datasource '': Closing open connection prior to commit

How to Reproduce?

Open the quarkus hibernate-orm-quickstart project. 1) add @Inject Event<Fruit> eventBus; in the FruitResource 2) add eventBus.fire(fruit); in the create method 3) create class ExampleEventObserver:

public class ExampleEventObserver
{
    @Inject
    EntityManager entityManager;

    public void beforeCompletion(@Observes(during = TransactionPhase.BEFORE_COMPLETION) Fruit exampleEvent) {
        // do some query -> this triggers the warning
        List<Fruit> resultList = entityManager.createNamedQuery("Fruits.findAll", Fruit.class).getResultList();
        System.out.println("done with example event");
    }
}

4) start FruitsEndpointTest.testListAllFruits and you will see the warning log directly underneath the "done with example event"

demo.zip

Output of uname -a or ver

Microsoft Windows [Version 10.0.19045.4412]

Output of java -version

openjdk version "17.0.2" 2022-01-18 OpenJDK Runtime Environment (build 17.0.2+8-86) OpenJDK 64-Bit Server VM (build 17.0.2+8-86, mixed mode, sharing)

Quarkus version or git rev

3.12.0

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.9.6

Additional information

This issue was already reported in version 1.13.6.FINAL in the following issue.

[quarkus-bot[bot]]

/cc @barreiro (agroal), @yrodiere (agroal)

[yrodiere]

Hi.

Thanks for reporting.

My tests indicate this warning has been there since Quarkus 3.10 at least, and likely before.

It's caused by the fact that your CDI listener executes after Hibernate ORM has closed the connection. Here is the event chain:

1. Transaction commit gets requested
2. Before completion event gets sent
3. Hibernate ORM gets the event, closes the connection accordingly
4. Your event listener gets the events, uses the entity manager and thus... re-opens the transaction
5. Nobody closes the connection!
6. Before completion event ends
7. Agroal checks the connection status, notices nobody closed it, issues a warning.

I'm honestly not sure how this could be solved. EDIT: Maybe the Hibernate ORM event listener for "before transaction completion" should execute after user-defined event listeners?

I suspect that using CDI events is not a good idea here if you intend to use the Hibernate ORM entity manager in the event listener; you should probably use Hibernate ORM's own events instead?

[mmusgrov]

This looks similar to issue #18737 which was fixed by reordering the Synchronization callbacks in the order [OTHER, HIBERNATE, AGROAL] (see PR #34160) so OTHER should include user callbacks and the connection should still be open when AGROAL callbacks run. I'm not sure which version incorporated that fix but there is a unit test to validate the connection remains open.

[mmusgrov]

@HelvetiaAppDev We already provide a test that's the same as your reproducer, can you include a full reproducer that I can run and debug please.

[edit] sorry I see that you have already provided the full reproducer, thanks.

[mmusgrov]

The test is https://github.com/quarkusio/quarkus/blob/3.12/extensions/hibernate-orm/deployment/src/test/java/io/quarkus/narayana/quarkus/TSRTest.java#L187

[yrodiere]

@HelvetiaAppDev We already provide a test that's the same as your reproducer, can you include a full reproducer that I can run and debug please.

@mmusgrov There's a reproducer in the issue description, though it requires a bit of fiddling.

Here, I changed it a bit and you can now just run tests and see the extra logs: i41757.zip

[mmusgrov]

I couldn't get either of the reproducers to work. Your updated one fails with:

[ERROR] Could not find goal 'native-image-agent' in plugin io.quarkus.platform:quarkus-maven-plugin:3.10.0 among available goals add-extension, add-extensions, analyze-call-tree, build, create, create-extension, create-jbang, dependency-tree, deploy, dev, generate-code, generate-code-tests, go-offline, help, image-build, image-push, info, list-categories, list-extensions, list-platforms, prepare, prepare-tests, remote-dev, remove-extension, remove-extensions, run, test, track-config-changes, update -> [Help 1]

and the one attached to the issue fails with:

jakarta.ws.rs.NotFoundException: RESTEASY003210: Could not find resource for full path: http://localhost:8081/hello

The fix was tested against the original reproducer which I was able to run so I'll see if I can get that working again with whatever release the fix went into.

[mmusgrov]

FYI I'm still failing to get either of these reproducers to work and the original one attached to #18737 doesn't seem to run with the later quarkus versions (it runs on the version reported in that original issue). I recently upgraded my laptop to Fedora 40 so it may be some incompatibility. I also can't compile quarkus with Java version: 17.0.11, only 21. Suffice to say, please bear with me until I figure out what's wrong with my install, unless you have some suggestions about the failure messages I reported in my last comment.

[mmusgrov]

I'll try to find some time next week to create my own reproducer, if I'm successful I'll report back ...

[mmusgrov]

I managed to create my own reproducer by modifying the hibernate-orm quickstart: issue-41757.zip

I'm busy tomorrow so I will try to debug it early next week.

[andreas-eberle]

Hi @mmusgrov,

did you have a chance to look at this issue? I also run into it after upgrading my service.

[mmusgrov]

@andreas-eberle I will provide an update this week.

[mmusgrov]

What's happening is that during the CDI before transaction completion observer event there is a hibernate-orm query which obtains a connection but it does not release it until the after transaction completion callback runs, however the warning is generated by agroal from its before transaction completion handler and it expects the connection to have already been closed. I'm pretty sure that hibernate isn't supposed to wait until the after completion event before releasing the connection and that is where the problem lies.

I will spend another couple of days trying to understand how hibernate connection management should work but if I don't make progress then I will ask someone from the hibernate team to take over.

[gsmet]

/cc @yrodiere ^

[yrodiere]

@mmusgrov did you see my comment further above? Maybe it changed, but last time I checked, Hibernate ORM did close the connection on the before completion event... it's just that the custom "before completion" CDI handler executes after that and leads to Hibernate ORM reopening a connection... and then there's no event handler from ORM executing until after the transaction.

It's caused by the fact that your CDI listener executes after Hibernate ORM has closed the connection. Here is the event chain:

1. Transaction commit gets requested

2. Before completion event gets sent

3. Hibernate ORM gets the event, closes the connection accordingly

4. Your event listener gets the events, uses the entity manager and thus... re-opens the transaction

5. Nobody closes the connection!

6. Before completion event ends

7. Agroal checks the connection status, notices nobody closed it, issues a warning.

Regarding resolution, still quoting my earlier message:

I'm honestly not sure how this could be solved. EDIT: Maybe the Hibernate ORM event listener for "before transaction completion" should execute after user-defined event listeners?

I suspect that using CDI events is not a good idea here if you intend to use the Hibernate ORM entity manager in the event listener; you should probably use Hibernate ORM's own events instead?

[mmusgrov]

EDIT: Maybe the Hibernate ORM event listener for "before transaction completion" should execute after user-defined event listeners?

I suspect that using CDI events is not a good idea here if you intend to use the Hibernate ORM entity manager in the event listener; you should probably use Hibernate ORM's own events instead?

So would the "fix" be to update the hibernate documentation?

[yrodiere]

EDIT: Maybe the Hibernate ORM event listener for "before transaction completion" should execute after user-defined event listeners?

So would the "fix" be to update the hibernate documentation?

Could be, but that particular line you're quoting suggests to change how we order handlers instead. Because there's specific code in Quarkus for that, as you said before:

This looks similar to issue #18737 which was fixed by reordering the Synchronization callbacks in the order [OTHER, HIBERNATE, AGROAL] (see PR #34160) so OTHER should include user callbacks and the connection should still be open when AGROAL callbacks run. I'm not sure which version incorporated that fix but there is a unit test to validate the connection remains open.

That being said, the order I witnessed when I looked at the reproducer was HIBERNATE, OTHER, AGROAL. So either that changed, or I was just mistaken, or there's something fishy here.

[mmusgrov]

The reordering of synchronizations only applies to interposed ones but the hibernate synchronization is just a standard one.

[mmusgrov]

The hibernate sync doesn't close the connection until the after transaction synchronization but agroal issues the warning about it still being open in the before synchronization event. I agree with you that there does not seem to be a fix for this and we should use your suggestion about asking users to use Hibernate ORM's own events.

[mmusgrov]

Or alternatively, hibernate could close it in an interposed before synchronization and then it could be ordered before the agroal synch runs. But that sounds like an excessive amount of work for such a niche edge case.

[yrodiere]

The hibernate sync doesn't close the connection until the after transaction synchronization but agroal issues the warning about it still being open in the before synchronization event

To settle things once and for all, using that code on Quarkus 3.16.0, placing breakpoints where it makes sense, I get this order:

Method 'org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.beforeCompletion()' entered at org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:35)
Method 'io.agroal.pool.ConnectionHandler.onConnectionWrapperClose()' entered at io.agroal.pool.ConnectionHandler.onConnectionWrapperClose(ConnectionHandler.java:112)
Method breakpoint reached. Method 'io.agroal.pool.ConnectionHandler.onConnectionWrapperClose()' is about to exit at io.agroal.pool.ConnectionHandler.onConnectionWrapperClose(ConnectionHandler.java:118)
Method breakpoint reached. Method 'org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.beforeCompletion()' is about to exit at org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:38)
Method 'com.example.ExampleEventObserver_Observer_beforeCompletion_LAnOPKDgXTeTTYiWQJ6TFx_YJQU.notify()' entered at com.example.ExampleEventObserver_Observer_beforeCompletion_LAnOPKDgXTeTTYiWQJ6TFx_YJQU.notify(ObserverMethod.java:-1)
Method breakpoint reached. Method 'com.example.ExampleEventObserver_Observer_beforeCompletion_LAnOPKDgXTeTTYiWQJ6TFx_YJQU.notify()' is about to exit at com.example.ExampleEventObserver_Observer_beforeCompletion_LAnOPKDgXTeTTYiWQJ6TFx_YJQU.notify(ObserverMethod.java:-1)
Method 'io.agroal.pool.ConnectionHandler.transactionBeforeCompletion()' entered at io.agroal.pool.ConnectionHandler.transactionBeforeCompletion(ConnectionHandler.java:334)
Method 'io.agroal.pool.ConnectionHandler.onConnectionWrapperClose()' entered at io.agroal.pool.ConnectionHandler.onConnectionWrapperClose(ConnectionHandler.java:112)
Method breakpoint reached. Method 'io.agroal.pool.ConnectionHandler.onConnectionWrapperClose()' is about to exit at io.agroal.pool.ConnectionHandler.onConnectionWrapperClose(ConnectionHandler.java:118)
Method breakpoint reached. Method 'io.agroal.pool.ConnectionHandler.transactionBeforeCompletion()' is about to exit at io.agroal.pool.ConnectionHandler.transactionBeforeCompletion(ConnectionHandler.java:342)
Method 'io.agroal.pool.ConnectionHandler.transactionEnd()' entered at io.agroal.pool.ConnectionHandler.transactionEnd(ConnectionHandler.java:368)
Method breakpoint reached. Method 'io.agroal.pool.ConnectionHandler.transactionEnd()' is about to exit at io.agroal.pool.ConnectionHandler.transactionEnd(ConnectionHandler.java:374)
Method 'org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.afterCompletion()' entered at org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.afterCompletion(RegisteredSynchronization.java:42)
Method breakpoint reached. Method 'org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.afterCompletion()' is about to exit at org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.afterCompletion(RegisteredSynchronization.java:45)

So to sum up:

• "before completion" event
  1. Hibernate -- which closes the connection
  2. User -- calling Hibernate, thus reopening the connection
  3. Agroal -- finding a "leaked" connection, thus closing it
• "after completion" event
  1. Agroal
  2. Hibernate -- which does not close anything, since there's nothing to close.

I agree with you that there does not seem to be a fix for this and we should use your suggestion about asking users to use Hibernate ORM's own events.

That is indeed the only workaround I can see at the moment.

Or alternatively, hibernate could close it in an interposed before synchronization and then it could be ordered before the agroal synch runs. But that sounds like an excessive amount of work for such a niche edge case.

Agreed we won't drop everything just for this -- and anyway it would likely require changes upstream, so it'll take a while to propagate to Quarkus.

However, that's an interesting suggestion. Would you say that -- on top of fixing this -- it makes more sense to have Hibernate ORM use interposed transactions? I wonder what sort of problems it could cause depending on the environment... E.g. Hibernate ORM now having its synchronization executed after some other synchronization provided by another library/framework...

[mmusgrov]

That's a nice analysis and very clear context for the subsequent discussions.

I notice that hibernate-core offers both strategies (interposed vs normal synchronizations) in AbstractJtaPlatform and that it seems to be using normal synchronizations although it looks to be a simple config switch to get it move to using interposed ones. I have limited knowledge of hibernate so cannot say why cleaning up the transaction in a normal synch would not suffice. I think we'd need a compelling case to switch to using interposed in quarkus and I doubt the current issue is enough to do that.

[mmusgrov]

Actually I don't see how to change JtaSynchronizationStrategy to use SynchronizationRegistryBasedSynchronizationStrategy - I guess I could change it locally and test it but I'm not so sure what I'd do with the outcome of that experiment.

[yrodiere]

Actually I don't see how to change JtaSynchronizationStrategy to use SynchronizationRegistryBasedSynchronizationStrategy - I guess I could change it locally and test it but I'm not so sure what I'd do with the outcome of that experiment.

Hibernate ORM in Quarkus already has its own JTA platform:

https://github.com/quarkusio/quarkus/blob/c695d69fdc93f19a8ca9d2e8b41e7b3cae13dee6/extensions/hibernate-orm/runtime/src/main/java/io/quarkus/hibernate/orm/runtime/customized/QuarkusJtaPlatform.java#L18

From what I can see it probably uses this Narayana synchronization registry:

https://github.com/quarkusio/quarkus/blob/c695d69fdc93f19a8ca9d2e8b41e7b3cae13dee6/extensions/narayana-jta/runtime/src/main/java/io/quarkus/narayana/jta/runtime/internal/tsr/TransactionSynchronizationRegistryWrapper.java#L25

Though I'm not sure why were' discussing that exactly; seems to me the only thing that needs to change is this method, so that it calls retrieveTransactionSynchronizationRegistry().registerInterposedSynchronization(synchronization); instead of what it currently does?

https://github.com/quarkusio/quarkus/blob/c695d69fdc93f19a8ca9d2e8b41e7b3cae13dee6/extensions/hibernate-orm/runtime/src/main/java/io/quarkus/hibernate/orm/runtime/customized/QuarkusJtaPlatform.java#L71-L76

I have, however, no idea what the consequences of that would be, beyond what you already explained :)

[mmusgrov]

Thanks for the links.

I have, however, no idea what the consequences of that would be, beyond what you already explained :)

Neither do i but it would be an interesting exercise - I will add it to my todo list, at a lower priority, and experiment with it.