Release R2DBC connection when cleanup fails in transaction

[FutureGadget]

When using R2dbcTransactionManager, connection will not be released if it encounters error while doing afterCleanup.
As afterCleanup uses a database connection when doing setAutoCommit(true), it can be failed under some conditions where the connection not reliable.

The problem is that when this issue occurs, the number of acquired connections are not decreased because the connection is not released. Also, if all the connections in the pool are depleted, the connection pool cannot allocate further connections and the request that needs database connections hang.

I created a project to easily reproduce this issue: https://github.com/FutureGadget/spring-r2dbc-connection-not-released

Since I use Spring 5.3.25 in production, I hope this fix to be backported at least to 5.3.25 and later versions.
Thank you.

[FutureGadget]

@sbrannen Hi, thank you for adding tags for this PR. I know there are a lot of other urgent issues going on, but I just wonder if this issue can be fixed in the next release. Thank you.

[oshai]

This is related to jasync-sql/jasync-sql#347

[simonbasle]

@FutureGadget I was looking at the reproducer and I don't see it fail. Does it actually reproduce the issue ?
I even see the Releasing R2DBC Connection log:

DEBUG 35433 --- [-netty-thread-8] o.s.r.c.R2dbcTransactionManager          : Releasing R2DBC Connection [PooledConnection[com.github.jasync.r2dbc.mysql.JasyncClientConnection@45106529]] after transaction
DEBUG 35433 --- [-netty-thread-8] io.r2dbc.pool.PooledConnection           : Releasing connection
DEBUG 35433 --- [-netty-thread-8] io.r2dbc.pool.PooledConnection           : Release failed

[simonbasle]

the doCleanupAfterCompletion javadoc states that it "Should not throw any exceptions but just issue warnings on errors", so that's a good direction 👍

But its duplicates the logic a bit, and doesn't help in two additional corner cases: the setIsolationLevel call a few lines above fails or the releaseConnection inside this particular defer fails.

It would be better if each 3 steps were protected against errors (and if we did some logging while we're at it).

The three steps are represented as a Mono<Void> that gets concatenated to the afterCleanup via the .then(step) operator. Note that for the last one (deferred "Releasing R2DBC Connection" step), the only thing that actually needs protection is the inner call to ConnectionFactoryUtils.releaseConnection.

The following method would be a way of doing so with the onErrorComplete() operator:

	@NotNull
	private Mono<Void> safeCleanupStep(String stepDescription, Mono<Void> stepMono) {
		if (!this.logger.isDebugEnabled()) {
			return stepMono.onErrorComplete();
		}
		return stepMono.doOnError(e -> this.logger.debug(String.format("Error ignored during %s: %s", stepDescription, e)))
				.onErrorComplete();
	}

it can be used as in the following example:

if (shouldDoFoo) {
    Mono<Void> step = safeCleanupStep("doCleanupAfterCompletion when doing foo",
        someMonoForFoo());
    afterCleanup = afterCleanup.then(step);
}

wdyt?

(edit: the LogFormatUtils method with the full stacktrace I was originally referring to doesn't exist outside of my local machine. simplified the logging in safeCleanupStep)

[FutureGadget]

I agree with you.
It seems like setIsolationLevel has been removed since fae36e9.
Here is the updated code: 3724bb0
Thank you!

[FutureGadget]

@FutureGadget I was looking at the reproducer and I don't see it fail. Does it actually reproduce the issue ? I even see the Releasing R2DBC Connection log:

DEBUG 35433 --- [-netty-thread-8] o.s.r.c.R2dbcTransactionManager          : Releasing R2DBC Connection [PooledConnection[com.github.jasync.r2dbc.mysql.JasyncClientConnection@45106529]] after transaction
DEBUG 35433 --- [-netty-thread-8] io.r2dbc.pool.PooledConnection           : Releasing connection
DEBUG 35433 --- [-netty-thread-8] io.r2dbc.pool.PooledConnection           : Release failed

I've recently created a PR which can mitigate the issue on the driver side (jasync-sql/jasync-sql#378) and that's released in version 2.1.20. To reproduce this issue, I've downgraded the driver version to 2.1.19 on the main branch.
I tried it again and it correctly reproduces the issue mentioned here.
Sorry for the inconvenience.

[simonbasle]

(...) that's released in version 2.1.20. To reproduce this issue, I've downgraded the driver version to 2.1.19 on the main branch.

Ah that makes sense now @FutureGadget ! I saw this PR but GitHub indicated the fix was released in 2.1.21, so I didn't think twice about the sample using 2.1.20. Thanks for clarifying.

Will you have time in the next few days to take my suggestions from the PR review into account ?

[FutureGadget]

Will you have time in the next few days to take my suggestions from the PR review into account ?

No problem! I appreciate for the detailed review. Let me work on this right now.

[simonbasle]

Thanks @FutureGadget that looks good. I will polish a tiny bit, merge and backport to 5.3.x