Hi
We have noticed a bad interaction between jooq and the hikaricp connection pool.
If the jdbc driver throws an exception, hikari closes the connection but jooq continues to work on it which leads to a NPE.
Basically if you run a query like (works against mysql):
jooq.transaction(t -> {
t.dsl().query("select sleep(10)").queryTimeout(1).execute();
})
Then the mysql jdbc driver throws a MySQLTimeoutException which leads to hikari closing the connection.
Hikari first logs a warning with a stacktrace:
WARN c.zaxxer.hikari.pool.ProxyConnection - HikariPool-1 - Connection com.mysql.cj.jdbc.ConnectionImpl@39909d1a marked as broken because of SQLSTATE(null), ErrorCode(0)
com.mysql.cj.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request
at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:113)
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:916)
at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:354)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java)
at org.jooq.tools.jdbc.DefaultPreparedStatement.execute(DefaultPreparedStatement.java:219)
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:419)
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:340)
at jooqbug.JooqHikariMysqlTest.lambda$timeoutTestTransaction$1(JooqHikariMysqlTest.java:59)
at org.jooq.impl.DefaultDSLContext.lambda$transaction$5(DefaultDSLContext.java:612)
at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$3(DefaultDSLContext.java:550)
at org.jooq.impl.Tools$3$1.block(Tools.java:5658)
at java.base/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463)
at java.base/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
at org.jooq.impl.Tools$3.get(Tools.java:5655)
at org.jooq.impl.DefaultDSLContext.transactionResult0(DefaultDSLContext.java:598)
at org.jooq.impl.DefaultDSLContext.transactionResult(DefaultDSLContext.java:522)
at org.jooq.impl.DefaultDSLContext.transaction(DefaultDSLContext.java:611)
at jooqbug.JooqHikariMysqlTest.lambda$timeoutTestTransaction$2(JooqHikariMysqlTest.java:58)
then jooq causes a NPE when trying to fetch warnings:
Caused by: java.lang.NullPointerException: Cannot invoke "com.mysql.cj.NativeSession.getProtocol()" because "this.session" is null
at com.mysql.cj.jdbc.StatementImpl.getWarnings(StatementImpl.java:1733)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.getWarnings(HikariProxyPreparedStatement.java)
at org.jooq.tools.jdbc.DefaultStatement.getWarnings(DefaultStatement.java:211)
at org.jooq.impl.Tools.consumeWarnings(Tools.java:4278)
at org.jooq.impl.Tools.safeClose(Tools.java:3143)
at org.jooq.impl.Tools.safeClose(Tools.java:3130)
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:362)
at jooqbug.JooqHikariMysqlTest.lambda$timeoutTestTransaction$1(JooqHikariMysqlTest.java:59)
at org.jooq.impl.DefaultDSLContext.lambda$transaction$5(DefaultDSLContext.java:612)
at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$3(DefaultDSLContext.java:550)
at org.jooq.impl.Tools$3$1.block(Tools.java:5658)
at java.base/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463)
at java.base/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
at org.jooq.impl.Tools$3.get(Tools.java:5655)
at org.jooq.impl.DefaultDSLContext.transactionResult0(DefaultDSLContext.java:598)
at org.jooq.impl.DefaultDSLContext.transactionResult(DefaultDSLContext.java:522)
at org.jooq.impl.DefaultDSLContext.transaction(DefaultDSLContext.java:611)
at jooqbug.JooqHikariMysqlTest.lambda$timeoutTestTransaction$2(JooqHikariMysqlTest.java:58)
at org.junit.jupiter.api.AssertThrows.assertThrows(AssertThrows.java:53)
... 73 more
Suppressed: org.jooq.exception.DataAccessException: Cannot set autoCommit
at org.jooq.impl.DefaultConnectionProvider.setAutoCommit(DefaultConnectionProvider.java:207)
at org.jooq.impl.DefaultTransactionProvider.brace(DefaultTransactionProvider.java:226)
at org.jooq.impl.DefaultTransactionProvider.rollback(DefaultTransactionProvider.java:209)
at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$3(DefaultDSLContext.java:574)
... 82 more
Caused by: java.sql.SQLException: Connection is closed
at com.zaxxer.hikari.pool.ProxyConnection$ClosedConnection.lambda$getClosedConnection$0(ProxyConnection.java:515)
at jdk.proxy3/jdk.proxy3.$Proxy23.setAutoCommit(Unknown Source)
at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:414)
at com.zaxxer.hikari.pool.HikariProxyConnection.setAutoCommit(HikariProxyConnection.java)
at org.jooq.impl.DefaultConnectionProvider.setAutoCommit(DefaultConnectionProvider.java:204)
I'm not sure if this is actually a bug in jooq, but it has bitten us a couple if times because the NPE shadows the underlying cause.
It only happens when running query in a transaction, normal usage is fine (this is also shown in the MCVE).
I will create an issue on github if this is considered a bug that should be fixed.
Best regards Jens