I did try to file a bug on the mysql driver
(https://bugs.mysql.com/bug.php?id=109681), but they needed a reproducer
that does not depend on third party libraries and I was not able to
reproduce the issue without jooq.
I ended up implementing a hikari SQLExceptionOverride like the following to
work around the issue:
/**
* Tells the hikari connection pool not to mark a connection broken if it
sees a
* com.mysql.cj.jdbc.exceptions.MySQLTimeoutException.
* This exception is thrown on regular query timeouts that happen every
once in
* a while.
* When that happens, it triggers a bug in the mysql driver (or perhaps in
jooq)
* that leads to a NullPointerException.
* This class tells hikari that it should not close the connection when it
* encounters this exception.
* Must be enabled in spring config by setting
*
spring.datasource.hikari.exception-override-class-name=com.example.hikari.MysqlTimeoutExceptionOverride
*/
public class MysqlTimeoutExceptionOverride implements SQLExceptionOverride {
protected static final String msg = "Statement cancelled due to timeout
or client request";
@java.lang.Override
public Override adjudicate(SQLException sqlException) {
if
(sqlException.getClass().getName().equals("com.mysql.cj.jdbc.exceptions.MySQLTimeoutException")
&& sqlException.getMessage() != null &&
sqlException.getMessage().contains(msg)) {
return Override.DO_NOT_EVICT;
}
return SQLExceptionOverride.super.adjudicate(sqlException);
}
}
Best regards Jens
On Tuesday 27 August 2024 at 20:56:08 UTC+2 Gaurang j wrote:
> Did you get a resolution on this? And can you share what it was?
>
> On Wednesday 18 January 2023 at 05:06:01 UTC-8 Jens Teglhus Møller wrote:
>
>> Hi Lukas
>>
>> Yeah, that makes sense, I will try to raise a bug on the mysql driver.
>>
>> Best regards Jens
>>
>> On Wednesday, 18 January 2023 at 13:47:24 UTC+1 [email protected] wrote:
>>
>>> 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
>>>
>>>
>>>
>>> On Wed, Jan 18, 2023 at 1:09 PM Jens Teglhus Møller <
>>> [email protected]> wrote:
>>>
>>>> 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
>>>>
>>>> <https://groups.google.com/d/msgid/jooq-user/d108f7f6-def4-4fb0-9cc4-840159f3f85en%40googlegroups.com?utm_medium=email&utm_source=footer>
>>>> .
>>>>
>>>
--
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/c548c5be-2617-461b-ab09-46e41d2db6e7n%40googlegroups.com.
