Bad interaction between jooq and hikaricp

[Jens Teglhus Møller]

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

[Lukas Eder]

Hi Jens,

Thanks for your message. I don't think jOOQ can make any assumptions about this connection pool or mysql-connector behaviour. If you supply jOOQ with a Connection, jOOQ can only assume that it isn't stale.

It looks more like a bug in the mysql-connector, where the NullPointerException is thrown (StatementImpl::getWarnings). Looking at the source code (I have version 8.0.31), StatementImpl::realClose sets all plenty of properties to null but doesn't synchronize on the "checkClosed().getConnectionMutex()", which to me looks like a bug worth reporting to Oracle/MySQL. There does seem to be a race condition between the two methods.

I hope this helps,

Lukas

--
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 jooq-user+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jooq-user/d108f7f6-def4-4fb0-9cc4-840159f3f85en%40googlegroups.com.

[Jens Teglhus Møller]

Hi Lukas

Yeah, that makes sense, I will try to raise a bug on the mysql driver.

Best regards Jens