enableGreenNodeReplacement doesn't work for Aurora MySQL

firateren52 commented 2 months ago

Describe the bug

We are using this driver together with MySQL driver to connect to an AWS Aurora MySQL 8.0 cluster using default plugins with an internal HikariCP connection pool. We have the incorrect SERVER_ID bug which has -green-xxx after B/G switchover. When we have long running queries more than 5 minutes queries were failing, we found out our problem was similiar to https://github.com/aws/aws-advanced-jdbc-wrapper/issues/678. We started to use enableGreenNodeReplacement=true flag as it was supposed to fix but it didn't fix our problem. After some debugging i think enableGreenNodeReplacement implementation has a bug. When we disable efm2 plugin then our queries were succeeding.

Expected Behavior

We expect that enableGreenNodeReplacement=true flag actually works for Aurora MySQL database. We use efm2 plugin to use hostnames for the reader replicas that can actually be resolved( remove -green-xxx), so that the internal connection pools for read-only connections are populated.

What plugins are used? What other connection properties were set?

Plugins: auroraConnectionTracker,failover,efm2

Current Behavior

The driver seems to use data from the @@aurora_server_id to generate fqdn to connect to, but since the instances seem to retain server-ids from the blue/green deployment the fqdn is not valid and it fails to connect. enableGreenNodeReplacement flag is being removed for property list.

Jul 09, 2024 3:56:36 PM software.amazon.jdbc.util.SlidingExpirationCacheWithCleanupThread lambda$initCleanupThread$2
FINEST: Cleaning up...
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.plugin.efm2.MonitorImpl checkConnectionStatus
FINEST: Opening a monitoring connection to dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.DataSourceConnectionProvider connect
FINEST: Use main DataSource object to create a connection.
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'user' with value: root
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'password' with value: ***
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'zeroDateTimeBehavior' with value: CONVERT_TO_NULL
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'enabledTLSProtocols' with value: TLSv1.2
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.DataSourceConnectionProvider openConnection
WARNING: openConnection failed props: {password=***, enabledTLSProtocols=TLSv1.2, zeroDateTimeBehavior=CONVERT_TO_NULL, user=root} hostSpec: HostSpec[host=dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com, port=3306, READER, AVAILABLE, weight=2289, 2024-07-09 13:50:35.696012] protocol: jdbc:mysql:// targetDriverDialect: software.amazon.jdbc.targetdriverdialect.MysqlConnectorJTargetDriverDialect@2a685eba ds: com.mysql.cj.jdbc.MysqlDataSource@74a4ad68
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.DataSourceConnectionProvider openConnection
WARNING: openConnection failed throwable:Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server. cause: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.plugin.efm2.MonitorImpl updateNodeHealthStatus
FINE: Host dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com is *dead*.
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/': [WENT_DOWN, NODE_CHANGED]
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.plugin.efm2.HostMonitoringConnectionPlugin execute
FINEST: Monitoring deactivated for method 'PreparedStatement.executeQuery'.
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: Communications link failure

The last packet successfully received from the server was 46,010 milliseconds ago. The last packet sent successfully to the server was 46,011 milliseconds ago.
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/': [WENT_DOWN, NODE_CHANGED]
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverReader
FINE: Starting reader failover procedure.
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'dev-worker-db-read-01-green-udb6tb.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/', with properties '{database=gateway, password=***, enabledTLSProtocols=TLSv1.2, zeroDateTimeBehavior=CONVERT_TO_NULL, enableGreenNodeReplacement=true, user=root}'
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.DataSourceConnectionProvider connect
FINEST: Use main DataSource object to create a connection.
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/', with properties '{database=gateway, password=***, enabledTLSProtocols=TLSv1.2, zeroDateTimeBehavior=CONVERT_TO_NULL, enableGreenNodeReplacement=true, user=root}'
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'user' with value: root
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'password' with value: ***
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'zeroDateTimeBehavior' with value: CONVERT_TO_NULL
Jul 09, 2024 3:56:36 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget

FINE: Failed to connect to reader: 'dev-worker-db-read-01-green-udb6tb.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/'
{"thread":"pool-28-thread-4","level":"INFO","loggerName":"com.company.datasync.sql.SyncFunctions","message":"Copied 0 sms to smsArchive","timestamp":"2024-07-09T14:01:31.474Z","threadId":89}
{"thread":"pool-28-thread-1","level":"INFO","loggerName":"com.company.datasync.DataSync","message":"Moved 0 sms to smsArchive","timestamp":"2024-07-09T14:01:32.314Z","threadId":86}
{"thread":"pool-28-thread-3","level":"INFO","loggerName":"com.company.datasync.sql.SyncFunctions","message":"Copied 0 sms to smsArchive","timestamp":"2024-07-09T14:01:32.491Z","threadId":88}
{"thread":"pool-28-thread-7","level":"INFO","loggerName":"com.company.datasync.DataSync","message":"Moved 0 TLV to smsTLVData","timestamp":"2024-07-09T14:01:32.853Z","threadId":92}
{"thread":"pool-28-thread-6","level":"INFO","loggerName":"com.company.datasync.DataSync","message":"Copied 0 wallet changes to sql","timestamp":"2024-07-09T14:01:32.945Z","threadId":91}
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/', with properties '{database=gateway, password=***, enabledTLSProtocols=TLSv1.2, zeroDateTimeBehavior=CONVERT_TO_NULL, enableGreenNodeReplacement=true, user=root}'
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.DataSourceConnectionProvider connect
FINEST: Use main DataSource object to create a connection.
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'user' with value: root
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'dev-worker-db-read-01-green-udb6tb.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/', with properties '{database=gateway, password=***, enabledTLSProtocols=TLSv1.2, zeroDateTimeBehavior=CONVERT_TO_NULL, enableGreenNodeReplacement=true, user=root}'
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.DataSourceConnectionProvider connect
FINEST: Use a separate DataSource object to create a connection.
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'password' with value: ***
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'user' with value: root
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'password' with value: ***
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'zeroDateTimeBehavior' with value: CONVERT_TO_NULL
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'enabledTLSProtocols' with value: TLSv1.2
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'zeroDateTimeBehavior' with value: CONVERT_TO_NULL
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'enabledTLSProtocols' with value: TLSv1.2
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.DataSourceConnectionProvider openConnection

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Failed to connect to reader: 'dev-worker-db-read-01-green-udb6tb.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/'
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.DataSourceConnectionProvider openConnection
WARNING: openConnection failed props: {password=***, enabledTLSProtocols=TLSv1.2, zeroDateTimeBehavior=CONVERT_TO_NULL, user=root} hostSpec: HostSpec[host=dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com, port=3306, READER, NOT_AVAILABLE, weight=959, 2024-07-09 13:55:34.997268] protocol: jdbc:mysql:// targetDriverDialect: software.amazon.jdbc.targetdriverdialect.MysqlConnectorJTargetDriverDialect@2a685eba ds: com.mysql.cj.jdbc.MysqlDataSource@17485a2a
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.DataSourceConnectionProvider openConnection
WARNING: openConnection failed throwable:Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server. cause: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Jul 09, 2024 4:01:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Failed to connect to reader: 'dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/'
{"thread":"pool-28-thread-4","level":"INFO","loggerName":"com.company.datasync.sql.SyncFunctions","message":"Copied 0 sms to smsArchive","timestamp":"2024-07-09T14:01:33.509Z","threadId":89}
{"thread":"pool-28-thread-4","level":"INFO","loggerName":"com.company.datasync.sql.SyncFunctions","message":"Copied 0 sms to smsArchive","timestamp":"2024-07-09T14:01:34.531Z","threadId":89}
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'dev-worker-db-read-01-green-udb6tb.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/', with properties '{database=gateway, password=***, enabledTLSProtocols=TLSv1.2, zeroDateTimeBehavior=CONVERT_TO_NULL, enableGreenNodeReplacement=true, user=root}'
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.DataSourceConnectionProvider connect
FINEST: Use main DataSource object to create a connection.
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'user' with value: root
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'password' with value: ***
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'zeroDateTimeBehavior' with value: CONVERT_TO_NULL
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'enabledTLSProtocols' with value: TLSv1.2
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.DataSourceConnectionProvider openConnection
WARNING: openConnection failed props: {password=***, enabledTLSProtocols=TLSv1.2, zeroDateTimeBehavior=CONVERT_TO_NULL, user=root} hostSpec: HostSpec[host=dev-worker-db-read-01-green-udb6tb.chfjjzn6uhst.us-east-1.rds.amazonaws.com, port=3306, WRITER, NOT_AVAILABLE, weight=5, 2024-07-09 13:55:34.262839] protocol: jdbc:mysql:// targetDriverDialect: software.amazon.jdbc.targetdriverdialect.MysqlConnectorJTargetDriverDialect@2a685eba ds: com.mysql.cj.jdbc.MysqlDataSource@17485a2a
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.DataSourceConnectionProvider openConnection

WARNING: openConnection failed throwable:Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server. cause: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/', with properties '{database=gateway, password=***, enabledTLSProtocols=TLSv1.2, zeroDateTimeBehavior=CONVERT_TO_NULL, enableGreenNodeReplacement=true, user=root}'
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.DataSourceConnectionProvider connect
FINEST: Use main DataSource object to create a connection.
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'user' with value: root
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'password' with value: ***
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'zeroDateTimeBehavior' with value: CONVERT_TO_NULL
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.util.PropertyUtils setPropertyOnTarget
FINEST: Set property 'enabledTLSProtocols' with value: TLSv1.2
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.DataSourceConnectionProvider openConnection
WARNING: openConnection failed props: {password=***, enabledTLSProtocols=TLSv1.2, zeroDateTimeBehavior=CONVERT_TO_NULL, user=root} hostSpec: HostSpec[host=dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com, port=3306, READER, NOT_AVAILABLE, weight=959, 2024-07-09 13:55:34.997268] protocol: jdbc:mysql:// targetDriverDialect: software.amazon.jdbc.targetdriverdialect.MysqlConnectorJTargetDriverDialect@2a685eba ds: com.mysql.cj.jdbc.MysqlDataSource@17485a2a
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.DataSourceConnectionProvider openConnection
WARNING: openConnection failed throwable:Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server. cause: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Failed to connect to reader: 'dev-worker-db-read-02-green-wj1hhx.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/'
Jul 09, 2024 4:01:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Failed to connect to reader: 'dev-worker-db-read-01-green-udb6tb.chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/'
{"thread":"pool-28-thread-4","level":"INFO","loggerName":"com.company.datasync.sql.SyncFunctions","message":"Copied 0 sms to smsArchive","timestamp":"2024-07-09T14:01:35.549Z","threadId":89}
Jul 09, 2024 4:01:36 PM software.amazon.jdbc.util.SlidingExpirationCacheWithCleanupThread lambda$initCleanupThread$2
FINEST: Cleaning up...
Jul 09, 2024 4:01:36 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin processFailoverFailure
SEVERE: Unable to establish SQL connection to the reader instance.
{"thread":"pool-28-thread-2","level":"WARN","loggerName":"com.zaxxer.hikari.pool.ProxyConnection","message":"smpp.sql.system-reader - Connection software.amazon.jdbc.wrapper.ConnectionWrapper@3615b952 - com.mysql.cj.jdbc.ConnectionImpl@5b4b5fe8 marked as broken because of SQLSTATE(08001), ErrorCode(0)","timestamp":"2024-07-09T14:01:36.188Z","threadId":87,"exception":"software.amazon.jdbc.plugin.failover.FailoverFailedSQLException: Unable to establish SQL connection to the reader instance.\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.processFailoverFailure(FailoverConnectionPlugin.java:478)\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.failoverReader(FailoverConnectionPlugin.java:603)\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.failover(FailoverConnectionPlugin.java:558)\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.pickNewConnection(FailoverConnectionPlugin.java:727)\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.dealWithOriginalException(FailoverConnectionPlugin.java:508)\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.execute(FailoverConnectionPlugin.java:226)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$execute$5(ConnectionPluginManager.java:334)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$null$3(ConnectionPluginManager.java:267)\n\tat software.amazon.jdbc.ConnectionPluginManager.executeWithTelemetry(ConnectionPluginManager.java:240)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$makePluginChainFunc$4(ConnectionPluginManager.java:267)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$null$2(ConnectionPluginManager.java:268)\n\tat software.amazon.jdbc.plugin.AuroraConnectionTrackerPlugin.execute(AuroraConnectionTrackerPlugin.java:122)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$execute$5(ConnectionPluginManager.java:334)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$null$3(ConnectionPluginManager.java:267)\n\tat software.amazon.jdbc.ConnectionPluginManager.executeWithTelemetry(ConnectionPluginManager.java:240)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$makePluginChainFunc$4(ConnectionPluginManager.java:267)\n\tat software.amazon.jdbc.ConnectionPluginManager.executeWithSubscribedPlugins(ConnectionPluginManager.java:230)\n\tat software.amazon.jdbc.ConnectionPluginManager.execute(ConnectionPluginManager.java:331)\n\tat software.amazon.jdbc.util.WrapperUtils.executeWithPlugins(WrapperUtils.java:244)\n\tat software.amazon.jdbc.wrapper.PreparedStatementWrapper.executeQuery(PreparedStatementWrapper.java:224)\n\tat com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)\n\tat com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)\n\tat com.company.datasync.sql.SyncFunctions.syncSmsStatsData(SyncFunctions.java:1071)\n\tat com.company.datasync.DataSync.smsStatsGeneration(DbSync.java:622)\n\tat com.company.datasync.DataSync.generateSmsStats(DbSync.java:532)\n\tat java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)\n\tat java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)\n\tat java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat java.base/java.lang.Thread.run(Thread.java:829)\n"}
Jul 09, 2024 4:01:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.clearWarnings'
Jul 09, 2024 4:01:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'PreparedStatement.close'

{"thread":"pool-28-thread-2","level":"ERROR","loggerName":"com.company.datasync.sql.SyncFunctions","message":"Sync smsStats sql error","timestamp":"2024-07-09T14:01:36.190Z","threadId":87,"exception":"software.amazon.jdbc.plugin.failover.FailoverFailedSQLException: Unable to establish SQL connection to the reader instance.\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.processFailoverFailure(FailoverConnectionPlugin.java:478)\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.failoverReader(FailoverConnectionPlugin.java:603)\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.failover(FailoverConnectionPlugin.java:558)\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.pickNewConnection(FailoverConnectionPlugin.java:727)\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.dealWithOriginalException(FailoverConnectionPlugin.java:508)\n\tat software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin.execute(FailoverConnectionPlugin.java:226)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$execute$5(ConnectionPluginManager.java:334)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$null$3(ConnectionPluginManager.java:267)\n\tat software.amazon.jdbc.ConnectionPluginManager.executeWithTelemetry(ConnectionPluginManager.java:240)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$makePluginChainFunc$4(ConnectionPluginManager.java:267)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$null$2(ConnectionPluginManager.java:268)\n\tat software.amazon.jdbc.plugin.AuroraConnectionTrackerPlugin.execute(AuroraConnectionTrackerPlugin.java:122)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$execute$5(ConnectionPluginManager.java:334)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$null$3(ConnectionPluginManager.java:267)\n\tat software.amazon.jdbc.ConnectionPluginManager.executeWithTelemetry(ConnectionPluginManager.java:240)\n\tat software.amazon.jdbc.ConnectionPluginManager.lambda$makePluginChainFunc$4(ConnectionPluginManager.java:267)\n\tat software.amazon.jdbc.ConnectionPluginManager.executeWithSubscribedPlugins(ConnectionPluginManager.java:230)\n\tat software.amazon.jdbc.ConnectionPluginManager.execute(ConnectionPluginManager.java:331)\n\tat software.amazon.jdbc.util.WrapperUtils.executeWithPlugins(WrapperUtils.java:244)\n\tat software.amazon.jdbc.wrapper.PreparedStatementWrapper.executeQuery(PreparedStatementWrapper.java:224)\n\tat com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)\n\tat com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)\n\tat com.company.datasync.sql.SyncFunctions.syncSmsStatsData(SyncFunctions.java:1071)\n\tat com.company.datasync.DataSync.smsStatsGeneration(DbSync.java:622)\n\tat com.company.datasync.DataSync.generateSmsStats(DbSync.java:532)\n\tat java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)\n\tat java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)\n\tat java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat java.base/java.lang.Thread.run(Thread.java:829)\n"}

Reproduction Steps

Connect to an AWS Aurora MySQL cluster that has been deployed with blue/green deployment and therefore has incorrect SERVER_ID in information_schema.replica_host_status table and at least one reader replica using the plugins above. Aurora MySQL cluster version should be lower than 3.07.0 as this SERVER_ID bug has been fixed in this version.

more info: https://docs.aws.amazon.com/AmazonRDS/latest/AuroraMySQLReleaseNotes/AuroraMySQL.Updates.3070.html

Possible Solution

After some debugging i think i found the issue, in MysqlConnectorJDriverHelper class you are removing properties except a provided list and therefore enableGreenNodeReplacement flag is being removed too so when you check the flag in DataSourceConnectionProvider the flag isn't there and exception is thrown. So for Aurora MySQL databases enableGreenNodeReplacement flag is ineffective, other databases may have this bug as well.

https://github.com/Bit-Quill/aws-advanced-jdbc-wrapper/blob/5f22be871112e10051881a404f531da057373c1d/wrapper/src/main/java/software/amazon/jdbc/targetdriverdialect/MysqlConnectorJDriverHelper.java#L67

https://github.com/aws/aws-advanced-jdbc-wrapper/blob/e90e1aba7e34bb1068789469cd508c35a5cd7b17/wrapper/src/main/java/software/amazon/jdbc/DataSourceConnectionProvider.java#L177

Additional Information/Context

We have reproduced this bug in both below Aurora RDS MySQL versions:

5.7.mysql_aurora.2.11.2
8.0.mysql_aurora.3.06.1

Aurora DB instances:

dev-worker-db-read-02
dev-worker-db-read-01

SERVER_ID values after B/G switchover:

dev-worker-db-read-02-green-wj1hhx
dev-worker-db-read-01-green-udb6tb

Other libraries: HikariCP version 5.0.1 Dagger version 2.9

HikariCP normal connection params:

dataSource.jdbcUrl= jdbc:aws-wrapper:mysql://dev-worker-db.cluster-chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/gateway?enabledTLSProtocols=TLSv1.2&zeroDateTimeBehavior=CONVERT_TO_NULL&jdbcCompliantTruncation=false&rewriteBatchedStatements=true&enableGreenNodeReplacement=true
dataSourceClassName=software.amazon.jdbc.ds.AwsWrapperDataSource
dataSource.targetDataSourceClassName=com.mysql.cj.jdbc.MysqlDataSource
maximumPoolSize=3
minimumIdle=1
idleTimeout=60000
maxLifetime=300000

HikariCP reader connection params:

dataSource.jdbcUrl=jdbc:aws-wrapper:mysql://dev-worker-db.cluster-ro-chfjjzn6uhst.us-east-1.rds.amazonaws.com:3306/gateway?enabledTLSProtocols=TLSv1.2&zeroDateTimeBehavior=CONVERT_TO_NULL&enableGreenNodeReplacement=true
dataSourceClassName=software.amazon.jdbc.ds.AwsWrapperDataSource
dataSource.targetDataSourceClassName=com.mysql.cj.jdbc.MysqlDataSource
maximumPoolSize=3
minimumIdle=1
idleTimeout=60000
maxLifetime=300000

sample code to show how we create connections:

import com.zaxxer.hikari.HikariConfig;
import com.zaxxer.hikari.pool.HikariPool;
import dagger.Module;
import dagger.Provides;

import javax.inject.Named;
import javax.inject.Singleton;

@Module
public class DatabaseModule {

    @Provides
    @Singleton
    @Named("system")
    public HikariPool providesSystemPool() {
        final HikariConfig config = new HikariConfig(properties);
        config.setExceptionOverrideClassName("software.amazon.jdbc.util.HikariCPSQLException");
        final HikariPool pool = new HikariPool(config);
        return pool;
    }
}

software.amazon.jdbc.DataSourceConnectionProvider update we did to log properties and other info:

public class DataSourceConnectionProvider implements ConnectionProvider {
.
.
.
  protected Connection openConnection(
      final @NonNull DataSource ds,
      final @NonNull String protocol,
      final @NonNull TargetDriverDialect targetDriverDialect,
      final @NonNull HostSpec hostSpec,
      final @NonNull Properties props)
      throws SQLException {

    try {
      return ds.getConnection();
    } catch (Throwable throwable) {
      LOGGER.warning("openConnection failed props: " + props + " hostSpec: " + hostSpec + " protocol: " + protocol + " targetDriverDialect: " + targetDriverDialect + " ds: " + ds);
      LOGGER.warning("openConnection failed throwable:" + throwable);

      if (!PropertyDefinition.ENABLE_GREEN_NODE_REPLACEMENT.getBoolean(props)) {
        throw throwable;
      }

      UnknownHostException unknownHostException = null;
      int maxDepth = 100;
      Throwable loopThrowable = throwable;
      while (--maxDepth > 0 && loopThrowable != null) {
        if (loopThrowable instanceof UnknownHostException) {
          unknownHostException = (UnknownHostException) loopThrowable;
          break;
        }
        loopThrowable = loopThrowable.getCause();
      }

The AWS Advanced JDBC Driver version used

4.3.7

JDK version used

openjdk 11.0.19 2023-04-18 LTS

Operating System and version

Linux 6.1.94-99.176.amzn2023.x86_64 x86_64

sergiyvamz commented 2 months ago

Hi @firateren52 ,

Thanks for reaching out and raising this issue.

Would you give more details about the application:

What frameworks or libraries do you use (like Spring framework, Hibernate, etc)?
What connection string do you use to connect to your Hikari CP? What other connection pool settings are there?
Could you provide driver logs starting some time before the issue occurs? It's important to understand the issue context.
Woud you be able to provde a sample app that replicate the issue?

We'll take a look at this and keep you updated as we investigate. Thank you for your patience!

sergiyvamz commented 2 months ago

Hi,

A quick question about your connection url. I don't see configuration parameter enableGreenNodeReplacement in there. I'd expect to see something ...&enableGreenNodeReplacement=true in the connection url.

firateren52 commented 2 months ago

Hi @sergiyvamz, sorry i pasted from a wrong place so please disregard that, can you please remove your quote from your comment as it shows our database url? i shared more redacted logs, sample code to show how we configure HikariCP and also added the DataSourceConnectionProvider code we updated to add 2 log statements which you can see in logs. If you compare the properties listed in "Trying to connect to reader" log with the properties listed in "openConnection failed props" logs it's pretty obvious enableGreenNodeReplacement was present but then it's removed. I did write a simple unit test and verified this behavior as well and pointed out the line where enableGreenNodeReplacement is being removed in the Possible Solution section. Le me know if you need more info please. Thanks.

karenc-bq commented 2 months ago

Hi @firateren52, we merged a fix for this issue, could you please check out the snapshot build aws-advanced-jdbc-wrapper-2.3.8-20240719.225239-21.jar and let us know if this resolves the issue for you? For details on how to use the snapshot build see here.

firateren52 commented 1 month ago

@karenc-bq yes i verified with the snapshoot the bug is fixed. When will you release the next version? is it recommended to use this snapshoot version in prod? thank you!

hsuamz commented 1 month ago

Thanks @firateren52 for confirming the fix with our snapshot build. We are preparing for a new release and it will come out before the end of July.

aws / aws-advanced-jdbc-wrapper