Incorrect "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 '<default>': Closing open connection prior to commit appears.

Expected behavior

No WARN log, as everything works as intended.

Actual behavior

Logs WARN [io.agr.pool] (executor-thread-0) Datasource '<default>': 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"

Output of uname -a or ver

Microsoft Windows [Version 10.0.19042.928]

Output of java -version

java version "11.0.5" 2019-10-15 LTS Java(TM) SE Runtime Environment 18.9 (build 11.0.5+10-LTS) Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.5+10-LTS, mixed mode)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

1.13.6.FINAL and 2.0.2.FINAL

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

Apache Maven 3.6.3

Additional information

No response

[gsmet]

Could you please provide a reproducer? (a small Maven project reproducing the behavior out of the box)

Thanks!

[HelvetiaAppDev]

Of course, hope this works.
reproducer.zip

[gsmet]

I confirm I get the warning by running mvn clean install with the reproducer.

@Sanne does it ring a bell? Do you know who would be the right person to look at this?

[Sanne]

Interesting, thanks I'll have a better look tomorrow.

[barreiro]

The thing here is that Hibernate closes the connections on BEFORE_COMPLETION as well. After a little debugging is not yet clear to me if a second Synchronization is registered or not, and if it is, it's not clear that it runs.

[HelvetiaAppDev]

Hi @Sanne @barreiro
Do you guys maybe have an update on this?
Or is possible to somehow disable/avoid this warning?
Thanks!

[barreiro]

Hello @HelvetiaAppDev. When looking at this, I saw that there are 3 Synchronization registered: [Hibernate, Agroal*, Arc*] in that order, where * are 'interposed' synchronizations. Your event handler is executed by Arc after the previous synchronizations run. It causes Hibernate to acquire a second connection that is not properly closed as it's synchronization already ran.

To fix the ordering, changes are required in either or both Hibernate and Arc to change the way the Synchronization are registered. (I'm assuming doing database operations in BEFORE_COMPLETION is a valid use case).

My understanding is that the Arc synchronization should not be interposed and we need to make sure it's executed before Hibernate. It's important because, from what I remember, in that case it will still be possible to run the Hibernate synchronization in the case it's not yet registered.

@mmusgrov @ochaloup Can any of you give some advice here? Do you know the reasons why the Arc synchronization is 'interposed'?

[ochaloup]

@barreiro I think this was something which is managed in WildFly.
The JPA and synchronization could be elaborated in details by @scottmarlow, I think.

What I can say the Hibernate uses the SynchronizationRegistryBasedSynchronizationStrategy in WildFly (https://github.com/wildfly/wildfly/blob/main/jpa/hibernate5/src/main/java/org/jboss/as/jpa/hibernate5/JBossAppServerJtaPlatform.java#L44) which means that the Hibernate synchronization is registered as interposed (https://github.com/hibernate/hibernate-orm/blob/main/hibernate-core/src/main/java/org/hibernate/engine/transaction/jta/platform/internal/SynchronizationRegistryBasedSynchronizationStrategy.java#L29).
Any JCA synchronization goes at the end of other interposed synchronization by fact there is this handling
(https://github.com/wildfly/wildfly/blob/main/transactions/src/main/java/org/jboss/as/txn/service/internal/tsr/JCAOrderedLastSynchronizationList.java, called from https://github.com/wildfly/wildfly/blob/main/transactions/src/main/java/org/jboss/as/txn/service/internal/tsr/TransactionSynchronizationRegistryWrapper.java#L61)

On the other hand the Weld is registered as standard synchronization
https://github.com/wildfly/wildfly/blob/main/weld/transactions/src/main/java/org/jboss/as/weld/services/bootstrap/WeldTransactionServices.java#L95

The WildFly processing in this case would be
(I haven't tried that just based of the observation thus I hope my elaboration is correct.)

[Weld,Hibernate*,JCA**]

where * is interposed synchronization and ** is post-interposed synchronization
(Weld processes the user code which touches the database and I think it's correct to do some database cleanup tasks in the Synchronization#beforeCompletion, Hibernate does the flushes, JCA closes the connection)

(with all that handling in WildFly there could be still some corner cases - jakartaee/cdi#467 - as the CDI event observers are a bit of a corner case, which is what my CDI guru @manovotn is happy to tell me anytime I ask him about this topic :-)

I'm not sure why the Arc observers synchronization is interposed in Quarkus (@mkouba @manovotn ?) and maybe the Agroal will need some special handling as it's done for JCA in WildFly (?)

[scottmarlow]

FYI jakartaee/cdi#467 might be of interest as that issue requested that CDI events always run as interposed synchronizations but as pointed out in comment, the WildFly implement of Weld TransactionalServices#registerSynchronization could of made CDI events run as interposed sync but didn't.

@barreiro I think this was something which is managed in WildFly.
The JPA and synchronization could be elaborated in details by @scottmarlow, I think.

In WildFly, we purposely invoke the JCA synchronization last so that database connections aren't closed before Hibernate calls connection.close(). JCA used to complain when Hibernate closed connections after JCA had closed them, so that was solved by ordering the synchronization invocation order.

[manovotn]

I'm not sure why the Arc observers synchronization is interposed in Quarkus (@mkouba @manovotn ?)

Hmm, you're right. Didn't even know we use interposed synchronization here.
I suppose we could change that, but from all the various discussions on this topic, I cannot say I know which way is the "correct" one anymore :-)

[manovotn]

Hmm, apparently it was me who implemented it that way as can be seen in - #6581
Though I found no trace as to why I used interposed synchronization.

[scottmarlow]

I suppose we could change that, but from all the various discussions on this topic, I cannot say I know which way is the "correct" one anymore :-)

Could you somehow let applications decide whether they want to use interposed or non-interposed synchronization? Then they can either use the default or change it.

I prefer that applications use non-interposed so that application level syncs are called first for Synchronization#beforeCompletion() but that is also a change in (Arc) application level behavior. So, I'm also not sure which way should be default.

[manovotn]

I talked about this with @ochaloup and we came to a conclusion that Arc should use standard synchronization rather than interposed. One of the reasons being that this is really of a user-invoked synchronization rather than a container-invoked one which makes usage of interposed synch dubious.

As to what is described in jakartaee/cdi#467 plus the configurable option - the CDI issue isn't completely legitimate request because there would first have to be adjustments on JTA spec side. From what I understood (@ochaloup will correct me if I am wrong), JTA cannot guarantee entity manager state at that point making this requirement a non-portable one anyway.
So I would refrain from implementing the config yet but I will leave a note in the code for future reference. It would be easily implementable but unless we have the requirement, I don't think we want to introduce extra config options.

Will send a PR to fix the Arc-side of this issue shortly.

[barreiro]

Thank you all. I'll retest this one once Arc get's updated.

I'm not sure why the Arc observers synchronization is interposed in Quarkus and maybe the Agroal will need some special handling as it's done for JCA in WildFly (?)

Maybe not in this case, as Agroal does it's action on afterCompletion while Hibernate and Arc do beforeCompletion (I introduced the DELAYED_ACQUISITION_AND_RELEASE_BEFORE_COMPLETION mode in Hibernate that is now used as default in Quarkus. That is something different than what's used on WildFly).

In WildFly, we purposely invoke the JCA synchronization last so that database connections aren't closed before Hibernate calls connection.close(). JCA used to complain when Hibernate closed connections after JCA had closed them, so that was solved by ordering the synchronization invocation order.

Enforcing the sychronization order it's something to take into consideration, but I would like to avoid that complexity.

[scottmarlow]

In WildFly, we purposely invoke the JCA synchronization last so that database connections aren't closed before Hibernate calls connection.close(). JCA used to complain when Hibernate closed connections after JCA had closed them, so that was solved by ordering the synchronization invocation order.

Enforcing the sychronization order it's something to take into consideration, but I would like to avoid that complexity.

Perhaps compare the performance impact of enabling/disabling Hibernate ORM database connection caching. If the connection caching doesn't help performance, then consider disabling the database connection caching instead of forcing the synchronization order. You probably need to check the performance impact with an active JTA transaction and without a JTA transaction as that could impact how the JCA layer does its database connection caching.

[Sanne]

Let me clarify a couple of things:

• The DELAYED_ACQUISITION_AND_RELEASE_BEFORE_COMPLETION strategy has already been benchmarked, and we'd want to keep this choice if possible as there are meaningul benefits.
• There is no JCA integration and we don't plan to have support for JCA in Quarkus.
• Don't worry about "portability" issues - this is a single, opinionated platform which means components can't be swapped out freely.

Many thanks @manovotn for stepping in on the Arc side - that seems like the sensible solution.

[manovotn]

FTR, Arc portion of the fix was merged into main branch.

[HelvetiaAppDev]

Any updates?
I tried the same reproducer with quarkus 2.5.1-FINAL and the warn log still happens.

[geoand]

Is this still a problem with the latest versions of Quarkus?

[HelvetiaAppDev]

@geoand yes, this issue still exist when setting the Quarkus version in the reproducer to 2.16.6.Final and then running mvn clean test:

2023-04-10 17:06:35,224 INFO  [io.quarkus] (main) hibernate-orm-quickstart 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.16.6.Final) started in 3.214s. Listening on: http://localhost:8081
2023-04-10 17:06:35,227 INFO  [io.quarkus] (main) Profile test activated.
2023-04-10 17:06:35,227 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-orm, jdbc-h2, jdbc-postgresql, narayana-jta, resteasy, resteasy-jackson, smallrye-context-propagation, vertx]
done with example event
2023-04-10 17:06:36,573 WARN  [io.agr.pool] (executor-thread-0) Datasource '<default>': Closing open connection prior to commit

[jesperpedersen]

This is really not good...

@mmusgrov Can you help ?

[mmusgrov]

Are you guys asking us to provide configurable ordering semantics for synchronizations, if so it's been discussed before in the spec group (jakartaee/transactions#65). Or are you wanting to explore adding something specific to the config for the narayana-jta extension?

[jesperpedersen]

WildFly has a layer to deal with ordering - should Quarkus have the same (in some way) ? It is a discussion how to deal with it here - but TX resources needs to be handled correctly; otherwise we have to enforce 2PC semantics.

[mmusgrov]

I will propose a narayana-jta extension change and base it on WLFY-3619 which adds similar functionality for WildFly by wrapping the TSR.

[mmusgrov]

I think I figured out what's going on:

The reproducer performs a Hibernate update and also registers a CDI beforeCompletion observer which performs a hibernate query.

This scenario results in three interposed synchronizatons; Hibernate, Agroal and ARC in that order (the CDI beforeCompletion observer is called from the ARC synch).

With the observer present, a connection wrapper is opened by the observer to perform a hibernate query, but nothing closes the wrapper, and then the transaction moves to the commit phase and calls LocalXAResource#commit() [1] which detects that there is still an open wrapper [2] and generates the offending WARN(ing) message.

Remark: Without the observer all the wrappers have been closed before commit phase runs (and that the Agroal connection is returned to the pool, ie gets closed, during the Agroal afterCompletion synchronization).

I did add synchronization ordering semantics to the narayana-jta extension to experiment with ordering the ARC synch to run first (ARC, Hibernate, Agroal) but that turned out to not be possible because Hibernate is by-passing the Quarkus TSR [3] and is registering directly with Narayana [4], @Sanne who should I ask to get that looked into i.e. to decouple hibernate core from narayana?

If running the ARC synch first does not fix the issue then where is the best place to ensure that the wrapper (opened by the ARC synch) is closed before the commit phase runs?

[1] https://github.com/agroal/agroal/blob/1.11/agroal-narayana/src/main/java/io/agroal/narayana/LocalXAResource.java#L68
[2] https://github.com/agroal/agroal/blob/1.11/agroal-pool/src/main/java/io/agroal/pool/ConnectionHandler.java#L306
[3] https://github.com/quarkusio/quarkus/blob/main/extensions/narayana-jta/runtime/src/main/java/io/quarkus/narayana/jta/runtime/NarayanaJtaProducers.java#L56
[4] https://github.com/hibernate/hibernate-orm/blob/5.3/hibernate-core/src/main/java/org/hibernate/engine/transaction/jta/platform/internal/TransactionManagerBasedSynchronizationStrategy.java#L30

[jesperpedersen]

@Sanne I agree with @mmusgrov - we need a SPI to decouple this

[Sanne]

Hi Mike, thanks for looking!

The component you point at in [4] is an SPI - in fact we can register any different strategy implementation.

Within Quarkus, this is controlled by https://github.com/quarkusio/quarkus/blob/ebee0a4b66d1b4dba9c51165e78d22fbf3b90d3e/extensions/hibernate-orm/runtime/src/main/java/io/quarkus/hibernate/orm/runtime/customized/QuarkusJtaPlatform.java

You're free to customize that class, you can either change its implementation of registerSynchronization or change the delegation, which currently points to TransactionManagerBasedSynchronizationStrategy to any other implementation.

[Sanne]

P.S. I hope we can change our implementations to avoid such problems w/o needing to expose configuration properties.

In an ideal world we should enforce the safer approach w/o giving any alternatives.

[mmusgrov]

Thanks, I'll take a look and see how to configure it to use the narayana-jta produced TSR - I'll update the thread when I've done that and retested with a different ordering for the interposed Synchronizations.

[mmusgrov]

I took another look at this and found that if I order the ARC synchs to run first the WARN message disappears.
I also updated the hibernate-orm extension [1] to force it to use the TSR produced by the narayana-jta extension but the fix works without changing hibernate-orm.

@Sanne I think the hibernate-orm extension update is going to be needed at some point, should I include the update in the PR that I'll be raising for this issue?

[1] https://github.com/quarkusio/quarkus/compare/2.0.2.Final...mmusgrov:quarkus:18737-synch-order-on-2.0.2.Final?expand=1#diff-59c1f2cf299f54295dcfd03743b9c3ec971313e8fe109ac1c4aadce465786619R35

[mmusgrov]

Actually if the hibernate-orm change isn't required for this issue it's best if I remove that change.

I do have a follow up question: will running the ARC interposed synchs first cause any issues (they run last in the current codebase).

[scottmarlow]

What impact would an application library registering a sync have on this ordering scheme?

Would it help to instead ensure that Hibernate ORM syncs (perhaps both before/after competition) always run last?

[mmusgrov]

What impact would an application library registering a sync have on this ordering scheme?

The way I coded it [1] means that such an interposed sync will run after the ARC ones but before the Agroal ones. Apart from that caveat all other interposed syncs will be ordered in the order that they were registered.

Would it help to instead ensure that Hibernate ORM syncs (perhaps both before/after competition) always run last?

The Agroal afterCompletion synchronization [2,3] needs to run last: it checks that all of the connection wrappers are closed and it returns the connection back to the connection pool. But I could run the Hibernate ORM syncs after the other ones, so [ARC, other syncs, Hibernate, Agroal]? (Narayana runs the afterCompletions in reverse order compared to beforeCompletions and we would want to maintain that policy).

[1] https://github.com/quarkusio/quarkus/compare/2.0.2.Final...mmusgrov:quarkus:18737-synch-order-on-2.0.2.Final?expand=1#diff-eb042caa54555177c75fa37d6a25c9718840b45ee89997cf60fea2d6e5e15331R85
[2] https://github.com/agroal/agroal/blob/1.11/agroal-narayana/src/main/java/io/agroal/narayana/NarayanaTransactionIntegration.java#L188
[3] https://github.com/agroal/agroal/blob/1.11/agroal-pool/src/main/java/io/agroal/pool/ConnectionHandler.java#L332

[Sanne]

The Agroal afterCompletion synchronization [2,3] needs to run last: it checks that all of the connection wrappers are closed and it returns the connection back to the connection pool. But I could run the Hibernate ORM syncs after the other ones, so [ARC, other syncs, Hibernate, Agroal]? (Narayana runs the afterCompletions in reverse order compared to beforeCompletions and we would want to maintain that policy).

That sounds reasonable 👍 N.B. I'm not an expert in this field myself.

[scottmarlow]

What impact would an application library registering a sync have on this ordering scheme?

The way I coded it [1] means that such an interposed sync will run after the ARC ones but before the Agroal ones. Apart from that caveat all other interposed syncs will be ordered in the order that they were registered.

Thanks for the code link and explanation. The [1] code ordering looks like the best approach.

[yrodiere]

Fixed by #34160