Test suite crash in the middle after migration to Micronaut 4

[loicmathieu]

Hi,

After migration to Micronaut 4, our test suite that uses the database (with @MicronauTest(transactional=false) crashed in the middle (usually around test 70th to 90th of more than 110) with the following exception:

java.util.concurrent.ExecutionException: io.micronaut.data.connection.jdbc.exceptions.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection
        at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
        at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
        at io.kestra.jdbc.runner.JdbcExecutor.lambda$run$2(JdbcExecutor.java:192)
        at java.base/java.lang.Thread.run(Thread.java:833)
    Caused by: io.micronaut.data.connection.jdbc.exceptions.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection
        at io.micronaut.data.connection.jdbc.operations.DefaultDataSourceConnectionOperations.openConnection(DefaultDataSourceConnectionOperations.java:59)
        at io.micronaut.data.connection.jdbc.operations.DefaultDataSourceConnectionOperations.openConnection(DefaultDataSourceConnectionOperations.java:43)
        at io.micronaut.data.connection.support.AbstractConnectionOperations.openNewConnectionInternal(AbstractConnectionOperations.java:195)
        at io.micronaut.data.connection.support.AbstractConnectionOperations.getConnection(AbstractConnectionOperations.java:168)
        at io.micronaut.transaction.support.AbstractTransactionOperations.openNewConnectionAndTransaction(AbstractTransactionOperations.java:541)
        at io.micronaut.transaction.support.AbstractTransactionOperations.getTransaction(AbstractTransactionOperations.java:477)
        at io.micronaut.configuration.jooq.MicronautTransactionProvider.begin(MicronautTransactionProvider.java:56)
        at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$3(DefaultDSLContext.java:525)
        at org.jooq.impl.Tools$3$1.block(Tools.java:6068)
        at java.base/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3465)
        at java.base/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3436)
        at org.jooq.impl.Tools$3.get(Tools.java:6065)
        at org.jooq.impl.DefaultDSLContext.transactionResult0(DefaultDSLContext.java:579)
        at org.jooq.impl.DefaultDSLContext.transactionResult(DefaultDSLContext.java:503)
        at org.jooq.impl.DefaultDSLContext.transaction(DefaultDSLContext.java:592)
        at io.kestra.jdbc.JooqDSLContextWrapper.lambda$transaction$1(JooqDSLContextWrapper.java:58)
        at net.jodah.failsafe.Functions.lambda$get$0(Functions.java:48)
        at net.jodah.failsafe.RetryPolicyExecutor.lambda$supply$0(RetryPolicyExecutor.java:66)
        at net.jodah.failsafe.FallbackExecutor.lambda$supply$0(FallbackExecutor.java:45)
        at net.jodah.failsafe.Execution.executeSync(Execution.java:128)
        at net.jodah.failsafe.FailsafeExecutor.call(FailsafeExecutor.java:379)
        at net.jodah.failsafe.FailsafeExecutor.get(FailsafeExecutor.java:68)
        at io.kestra.core.utils.RetryUtils$Instance.wrap(RetryUtils.java:134)
        at io.kestra.core.utils.RetryUtils$Instance.runRetryIf(RetryUtils.java:93)
        at io.kestra.jdbc.JooqDSLContextWrapper.transaction(JooqDSLContextWrapper.java:55)
        at io.kestra.jdbc.runner.AbstractJdbcExecutionDelayStorage.get(AbstractJdbcExecutionDelayStorage.java:26)
        at io.kestra.jdbc.runner.JdbcExecutor.executionDelaySend(JdbcExecutor.java:653)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        ... 1 common frames omitted
        Suppressed: java.lang.NullPointerException: Cannot invoke "io.micronaut.configuration.jooq.MicronautTransaction.getTxStatus()" because "transaction" is null
                at io.micronaut.configuration.jooq.MicronautTransactionProvider.getTransactionStatus(MicronautTransactionProvider.java:72)
                at io.micronaut.configuration.jooq.MicronautTransactionProvider.rollback(MicronautTransactionProvider.java:67)
                at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$3(DefaultDSLContext.java:555)
                ... 25 common frames omitted
    Caused by: java.sql.SQLException: HikariDataSource HikariDataSource (HikariPool-12) has been closed.
        at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:95)
        at io.micronaut.data.connection.jdbc.operations.DefaultDataSourceConnectionOperations.openConnection(DefaultDataSourceConnectionOperations.java:57)
        ... 32 common frames omitted

Any idea of what's going on?

[graemerocher]

@dstepanov is this a known tx management issue?

@loicmathieu can you provide anymore detail on the code paths?

[dstepanov]

It is very bad practice to have exit(1)

[loicmathieu]

@dstepanov I know, don't blame me :)

If I replcae the Runtime.getRuntime().exit(1) to properly close our JdbcExecutor using something like the following, tests are no more crashing (well I have 14 failures so something fishy still occurs).

                        try {
                            close();
                        }
                        catch (IOException ioe) {
                            log.error("Unable to property close the executor", ioe);
                        }

[dstepanov]

Can you try to debug what is closing the pool?

[loicmathieu]

Just discovered that we had a bug in the way we handle our executor threads, fixing it solved the SQLException we saw.

Thanks for your help.