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.

I have create a MVCE that shows the issue for jooq 
3.16.13: https://github.com/djarnis73/jooq-hikari

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

-- 
You received this message because you are subscribed to the Google Groups "jOOQ 
User Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to [email protected].
To view this discussion on the web visit 
https://groups.google.com/d/msgid/jooq-user/d108f7f6-def4-4fb0-9cc4-840159f3f85en%40googlegroups.com.

Reply via email to