Warning logs when using Aurora MySQL and a Hikari connection pool.

[jbrookspd]

I'm trying out a spring boot application using the aws-advanced-jdbc-wrapper and a Hikari connection pool. The driver seems to be functioning properly but produces a substantial amount of WARN level log messages.

Data source configuration:

 datasource:
    url: jdbc:aws-wrapper:mysql://${DATABASE_HOST}/logexecution?useSSL=FALSE&allowPublicKeyRetrieval=true
    username: ${DATABASE_USER}
    password: ${DATABASE_PASSWORD}
    driver-class-name: software.amazon.jdbc.Driver
    hikari:
      data-source-properties:
        wrapperPlugins: auroraConnectionTracker,failover,efm
        wrapperDialect: aurora-mysql
        wrapperLogUnclosedConnections: true
        wrapperLoggerLevel: FINE
      exception-override-class-name: software.amazon.jdbc.util.HikariCPSQLException
      max-lifetime: 30000
      maximum-pool-size: 15
      connection-timeout: 1200
      validation-timeout: 1000
      pool-name: log-execution
      minimum-idle: 10
      idle-timeout: 10000

Warning log message:
2023-11-27T22:02:57.995Z WARN 1 --- [oundedElastic-2] com.zaxxer.hikari.pool.PoolBase : log-execution - Failed to validate connection software.amazon.jdbc.wrapper.ConnectionWrapper@7f349fe9 - com.mysql.cj.jdbc.ConnectionImpl@797d980e (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.

Has anyone seen this behavior before or see a setting that is missing or incorrect?

[brunos-bq]

Hi @jbrookspd,

Thanks for reaching out and raising this issue.

We'll take a look at this and keep you updated as we investigate.

For some reason, it seems that either your application either Hikari is trying to perform an operation on a connection that is already closed. Do the warning log messages come with an additional stack trace?

Thank you for your patience!

[jbrookspd]

I turned on debug logging to see if I could find any more information from hikari. It looks like they are being added, fail to validate, and then close fairly rapidly. Here is a logging sample.

1 | 11/28/20239:43:41.308 AM | 2023-11-28T16:43:41.308Z DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : log-execution - Closing connection software.amazon.jdbc.wrapper.ConnectionWrapper@39176c1e - com.mysql.cj.jdbc.ConnectionImpl@41c9e84d: (connection is dead)Source:52.32.7.75Name:eks-rdc-sandbox.rba-log-e...fd6dc9d-2grfh.log-executionCategory:sandbox/rba-log-execution...-execution-55bfd6dc9d-2grfh
-- | -- | --
2 | 11/28/20239:43:41.308 AM | 2023-11-28T16:43:41.308Z  WARN 1 --- [oundedElastic-5] com.zaxxer.hikari.pool.PoolBase          : log-execution - Failed to validate connection software.amazon.jdbc.wrapper.ConnectionWrapper@39176c1e - com.mysql.cj.jdbc.ConnectionImpl@41c9e84d (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.Source:52.32.7.75Name:eks-rdc-sandbox.rba-log-e...fd6dc9d-2grfh.log-executionCategory:sandbox/rba-log-execution...-execution-55bfd6dc9d-2grfh
3 | 11/28/20239:43:21.000 AM | 2023-11-28T16:43:21.174Z DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : log-execution - Added connection software.amazon.jdbc.wrapper.ConnectionWrapper@39176c1e - com.mysql.cj.jdbc.ConnectionImpl@41c9e84dSource:52.32.7.75Name:eks-rdc-sandbox.rba-log-e...fd6dc9d-2grfh.log-executionCategory:sandbox/rba-log-execution...-execution-55bfd6dc9d-2grfh

[brunos-bq]

Hello @jbrookspd ,

Thanks for the quick reply.

As of now we are still unable to determine the reason those connections are getting closed. Would you be able to tune the wrapperLoggerLevel to FINEST and see whether that gives us more insight on what might be happening?

[jbrookspd]

I'm not seeing any extra log messages related to the Failed to validate connection log lines with the logger level set to FINEST, but I am occasionally seeing these as well.

2023-11-29T18:15:06.753Z ERROR 1 --- [oundedElastic-7] s.a.j.p.f.FailoverConnectionPlugin       : The active SQL connection has changed due to a connection failure. Please re-configure session state if required.

[jbrookspd]

For what it's worth I tried the snapshot driver but don't see any change in behavior.

[jbrookspd]

I've made a very simple app that uses the wrapper driver for testing here and can see these warning messages periodically (4-15 about every 30 min).

2023-12-18T22:36:45.646Z WARN 1 --- [test-app] [nio-8080-exec-6] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection software.amazon.jdbc.wrapper.ConnectionWrapper@adb45f5 - com.mysql.cj.jdbc.ConnectionImpl@173db0b3 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.

Are these warning expected behavior when using hikari with the wrapper driver?

[jbrookspd]

I tried adding these properties at FINEST as well but still don't get any additional logging. Is there some other way to get more detailed logs?

software:
  amazon:
    jdbc:
      Driver:
        level: FINEST
      plugin:
        level: FINEST

Alternatively I started with the hikari settings from the spring boot example in this repo, is there a different hikari config for mysql that would be better?