Nullpointer exception with HikariCP 4.0.3

[OHsechun]

Describe the bug

We use aws mysql jdbc driver with Hikaricp 4.0.3 (spring boot 2.6.2) Read-only datasource are set to aws mysql jdbc driver. Null pointer exception occurs from this.threadContainer.getMonitor(node).stopMonitoring(context); when executing select query.

  @Override
  public void stopMonitoring(MonitorConnectionContext context) {
    if (context == null) {
      logger.logWarn(NullArgumentMessage.getMessage("context"));
      return;
    }

    // Any 1 node is enough to find the monitor containing the context
    // All nodes will map to the same monitor
    final String node = this.threadContainer.getNode(context.getNodeKeys());

    if (node == null) {
      logger.logWarn(Messages.getString("DefaultMonitorService.InvalidContext"));
      return;
    }

    ->> this.threadContainer.getMonitor(node).stopMonitoring(context);
  }

stack trace is below

java.lang.NullPointerException: null
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.plugins.DefaultMonitorService.stopMonitoring(DefaultMonitorService.java:130)
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.plugins.NodeMonitoringConnectionPlugin.execute(NodeMonitoringConnectionPlugin.java:182)
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.plugins.failover.FailoverConnectionPlugin.execute(FailoverConnectionPlugin.java:248)
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.plugins.ConnectionPluginManager.execute(ConnectionPluginManager.java:138)
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.ConnectionProxy$JdbcInterfaceProxy.invoke(ConnectionProxy.java:320)\n\tat com.sun.proxy.$Proxy216.executeQuery(Unknown Source)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:57)
at org.hibernate.loader.Loader.getResultSet(Loader.java:2322)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2075)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2037)
at org.hibernate.loader.Loader.doQuery(Loader.java:956)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:357)
at org.hibernate.loader.Loader.doList(Loader.java:2868)\n\tat org.hibernate.loader.Loader.doList(Loader.java:2850)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2682)
at org.hibernate.loader.Loader.list(Loader.java:2677)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:540)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:400)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1454)
at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1649)
at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1617)
at org.hibernate.query.internal.AbstractProducedQuery.getSingleResult(AbstractProducedQuery.java:1665)
at com.querydsl.jpa.impl.AbstractJPAQuery.getSingleResult(AbstractJPAQuery.java:214)
at com.querydsl.jpa.impl.AbstractJPAQuery.fetchOne(AbstractJPAQuery.java:326)
at com.querydsl.core.support.FetchableQueryBase.fetchFirst(FetchableQueryBase.java:51)
....

java.lang.IllegalStateException: null
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.ConnectionProxy.invoke(ConnectionProxy.java:207)
at com.sun.proxy.$Proxy113.clearWarnings(Unknown Source)
at com.zaxxer.hikari.pool.HikariProxyConnection.clearWarnings(HikariProxyConnection.java)
at jdk.internal.reflect.GeneratedMethodAccessor98.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.springframework.jdbc.datasource.LazyConnectionDataSourceProxy$LazyConnectionInvocationHandler.invoke(LazyConnectionDataSourceProxy.java:378)\n\tat com.sun.proxy.$Proxy130.clearWarnings(Unknown Source)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.handleAndClearWarnings(SqlExceptionHelper.java:299)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.logAndClearWarnings(SqlExceptionHelper.java:269)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.releaseConnection(LogicalConnectionManagedImpl.java:215)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.close(LogicalConnectionManagedImpl.java:261)
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.close(JdbcCoordinatorImpl.java:175)
at org.hibernate.internal.AbstractSharedSessionContract.close(AbstractSharedSessionContract.java:374)
at org.hibernate.internal.SessionImpl.closeWithoutOpenChecks(SessionImpl.java:417)
at org.hibernate.internal.SessionImpl.close(SessionImpl.java:402)
at org.springframework.orm.jpa.EntityManagerFactoryUtils.closeEntityManager(EntityManagerFactoryUtils.java:427)
at org.springframework.orm.jpa.JpaTransactionManager.doCleanupAfterCompletion(JpaTransactionManager.java:650)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.cleanupAfterCompletion(AbstractPlatformTransactionManager.java:992)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:790)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:654)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:407)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698)
....
....
Caused by: java.lang.NullPointerException: null
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.plugins.DefaultMonitorService.stopMonitoringForAllConnections(DefaultMonitorService.java:141)
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.plugins.NodeMonitoringConnectionPlugin.checkIfChanged(NodeMonitoringConnectionPlugin.java:289)
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.plugins.NodeMonitoringConnectionPlugin.execute(NodeMonitoringConnectionPlugin.java:167)
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.plugins.failover.FailoverConnectionPlugin.execute(FailoverConnectionPlugin.java:248)
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.plugins.ConnectionPluginManager.execute(ConnectionPluginManager.java:138)
at software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ha.ConnectionProxy.invoke(ConnectionProxy.java:193)\n\t... 85 common frames omitted

Expected Behavior

No error occurs.

Current Behavior

Error occurs irregularly (especially starting point to test). There is another something strange that slave connections are moved to master instance increasingly. Below is datasource property:

  datasource:
    my-service:
      master:
        driver-class-name: com.mysql.cj.jdbc.Driver
        jdbc-url: jdbc:mysql://{identifier}.cluster-{XYZ}.ap-northeast-2.rds.amazonaws.com:3306/{db_name}?zeroDateTimeBehavior=convertToNull&useUnicode=yes&characterEncoding=UTF-8&connectTimeout=2000&serverTimezone=Asia/Seoul&useTimezone=true&useSSL=false
        username: user
        password: pass
        maximum-pool-size: 100
      slave:
        driver-class-name: software.aws.rds.jdbc.mysql.Driver
        jdbc-url: jdbc:mysql:aws://{identifier}.cluster-ro-{XYZ}.ap-northeast-2.rds.amazonaws.com:3306/{db_name}?zeroDateTimeBehavior=CONVERT_TO_NULL&useUnicode=yes&characterEncoding=UTF-8&connectTimeout=2000&serverTimezone=Asia/Seoul&useTimezone=true&useSSL=false
        username: user
        password: pass
        maximum-pool-size: 100

But when test started, connections moved to master instance like below

After testing finished (no query), connections are divided correctly.

Reproduction Steps

Burst select query about 7~8000 request / second to AWS Arurora MySQL RDS cluster(1 master, 1 slave) with aws mysql jdbc driver datasource using spring boot 2.6.2.

Possible Solution

No response

Additional Information/Context

No response

The AWS JDBC Driver for MySQL version used

1.1.0

JDK version used

1.8

Operating System and version

amazon linux2 / Debian GNU/Linux 11 (docker container)

[sergiyvamz]

Hello @OHsechun

Thank you for reaching out! We're looking into the issue and we'll keep you updated.

[sergiyvamz]

Hello @OHsechun

There's a fix to the issue available and a snapshot build is ready. Are you able to confirm if the issue is fixed? https://github.com/awslabs/aws-mysql-jdbc#using-a-snapshot-of-the-driver

Thank you!

[OHsechun]

@sergiyvamz Sure, I'll try it

[OHsechun]

@sergiyvamz I tested it again. There is no error logs but slave connections moved to master instance. Why slave connections moved to master even though there is no failover, no read-replica scale in/out. I think this is failover behavior of read-only cluster endpoint.

Initial connection: any Aurora Replica
Failover behavior: prioritize connecting to any active Aurora Replica but might connect to the primary DB instance if it provides a faster connection

[sergiyvamz]

Hello @OHsechun

I'm glad to hear the issue is fixed!

As for wrong replica connection as you mentioned, it's hard to understand the case. Would you mind to provide more details about it?

• What connection string do you use? Is it a cluster endpoint or a cluster reader endpoint or an instance endpoint?
• What's you cluster configuration? How many replicas your cluster has?
• Can you provide a driver log?

Thank you!

[OHsechun]

As I reffered above, datasource setting is below

  datasource:
    my-service:
      master:
        driver-class-name: com.mysql.cj.jdbc.Driver
        jdbc-url: jdbc:mysql://{identifier}.cluster-{XYZ}.ap-northeast-2.rds.amazonaws.com:3306/{db_name}?zeroDateTimeBehavior=convertToNull&useUnicode=yes&characterEncoding=UTF-8&connectTimeout=2000&serverTimezone=Asia/Seoul&useTimezone=true&useSSL=false
        username: user
        password: pass
        maximum-pool-size: 100
      slave:
        driver-class-name: software.aws.rds.jdbc.mysql.Driver
        jdbc-url: jdbc:mysql:aws://{identifier}.cluster-ro-{XYZ}.ap-northeast-2.rds.amazonaws.com:3306/{db_name}?zeroDateTimeBehavior=CONVERT_TO_NULL&useUnicode=yes&characterEncoding=UTF-8&connectTimeout=2000&serverTimezone=Asia/Seoul&useTimezone=true&useSSL=false
        username: user
        password: pass
        maximum-pool-size: 100

I used cluster reader endpoint for slave connections. My RDS Aruroa mysql cluster has 1 master and 1 read-only replica. There is no warn or error logs during this strange working.

[sergiyvamz]

Hello @OHsechun

That strange behaviour you're experiencing may have different nature. Aurora Reader endpoint can be resolved to a writer node in some case. https://docs.aws.amazon.com/AmazonRDS/latest/AuroraUserGuide/Aurora.Overview.Endpoints.html#Aurora.Endpoints.Reader

If your cluster contains only a primary instance and no Aurora Replicas, the reader endpoint connects to the primary instance. In that case, you can perform write operations through this endpoint.

Also, the driver may prioritize connecting to a writer node. It's hardly possible to troubleshoot such issue without driver logs. Can you provide driver logs that shows that strange behaviour?

Thank you!

[congoamz]

The fix for this issue was merged in with this commit and will be included in the next release. I'll close this ticket since there hasn't been any further discussion. Please reopen this ticket if the issue still persists. Thank you!