Confusing Log for FailoverConnectionPlugin

[droni1234]

Describe the bug

Receiving Random Error and a potential degraded connection

log message: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
log level: ERROR
logger component: software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin

Expected Behavior

To work without a problem or give a more actionable error message.
I am in the dark :)

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

Standard Configuration

Current Behavior

This is a filtered view of the Log history over the last 24 hours

I had trouble enabling trace logs, I will eventually try to get some later

Reproduction Steps

This is the configuration of my Datasource, I have resolved some constants and removed secrets

import lombok.NoArgsConstructor;
import org.apache.tomcat.jdbc.pool.DataSource;
import org.apache.tomcat.jdbc.pool.PoolProperties;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.beans.factory.annotation.Qualifier;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
@NoArgsConstructor
public class DataProvider {

	@Bean
	@Qualifier("writerDataSource")
	public DataSource writerDataSource(@Autowired final ServiceConfiguration configuration) {
		PoolProperties poolProperties = getPoolProperties(configuration, "jdbc:aws-wrapper:mysql://AURORA_WRITE_CLUSTER_ENDPOINT:3306/database?usePipelineAuth=false");

		DataSource datasource = new DataSource();
		datasource.setPoolProperties(poolProperties);

		return datasource;
	}

	@Bean
	@Qualifier("readerDataSource")
	public DataSource readerDataSource(@Autowired final ServiceConfiguration configuration) {
		PoolProperties poolProperties = getPoolProperties(configuration, "jdbc:aws-wrapper:mysql://AURORA_READ_ONLY_CLUSTER_ENDPOINT:3306/database?usePipelineAuth=false");

		DataSource datasource = new DataSource();
		datasource.setPoolProperties(poolProperties);

		return datasource;
	}

	private PoolProperties getPoolProperties(ServiceConfiguration configuration, String databaseUrl) {
		PoolProperties poolProperties = new PoolProperties();
		poolProperties.setUrl(databaseUrl);
		poolProperties.setDriverClassName("software.amazon.jdbc.Driver");
		poolProperties.setUsername("*********");
		poolProperties.setPassword("*********");
		poolProperties.setJmxEnabled(true);
		poolProperties.setTestWhileIdle(false);
		poolProperties.setTestOnBorrow(true);
		poolProperties.setValidationQuery("SELECT 1");
		poolProperties.setTestOnReturn(false);
		poolProperties.setValidationInterval(30_000);
		poolProperties.setTimeBetweenEvictionRunsMillis(30_000);
		poolProperties.setMaxActive(40);
		poolProperties.setInitialSize(10);
		poolProperties.setMaxWait(10_000);
		poolProperties.setRemoveAbandonedTimeout(60);
		poolProperties.setMinEvictableIdleTimeMillis(30_000);
		poolProperties.setMaxIdle(40);
		poolProperties.setMinIdle(5);
		poolProperties.setLogAbandoned(true);
		poolProperties.setRemoveAbandoned(true);
		poolProperties.setJdbcInterceptors(String.format(
				"org.apache.tomcat.jdbc.pool.interceptor.QueryTimeoutInterceptor(queryTimeout=%d)",
				10));

		return poolProperties;
	}

}

Possible Solution

No response

Additional Information/Context

I use tomcat-jdbc for connection pooling and as a Datasource
This issue appeared on the newest mariadb connector j version
as well as for the newest mysql connector j version I tried out.
I have recently upgraded to RDS 3 with mysql 8.

The AWS Advanced JDBC Driver version used

2.3.7

JDK version used

Java 17

Operating System and version

Docker Image eclipse-temurin:17-jre-jammy

[karenc-bq]

Hi @droni1234, this log message occurs when the wrapper throws a SQLState 08S02 FailoverSuccessException in the event of a successful failover. This error is to notify the client applications to reconfigure session states and retry previous operations. You can learn more about the error here.

You can enable driver logging using application.yml or application.properties, examples can be found here.

On the other hand, failover should only be triggered when there are connectivity issues to instances. Were the network issues expected?

[droni1234]

Hi there is some additional config (log4j2) I need to change for the logs to appear.
I am busy and will probably take some time to get logs.
There were no network issues expected, it feels to me like there is a problem with the Datasource configuration and the Connectionpool.

I will try to come back with logs in a month or two.

[DyllanSowersTR]

I am also running into this problem. The error is being thrown when there is no failover event happening during my application's scale testing. The problem always happens during a DELETE operation as well.

Is there something else that can cause the FailoverSuccessSQLException asides from a legitimate failover event?

[aaron-congo]

Hi @DyllanSowersTR, that exception should only be thrown after a legitimate failover event. Are you able to provide me with more info? If possible, it would be great to have some sample code that reproduces the issue and logs for when this occurs. Additionally:

1. Which plugins are you using?
2. Which underlying driver are you using (mariadb or mysql-connector-j)?
3. Does this problem happen consistently for you?
4. Does the problem happen right away or only after running for awhile?
5. Are you also using tomcat-jdbc like the original poster?
6. If you are unable to post any sample code, can you give me details about the general behavior of your code?

Any additional details you can provide about your configuration would also be helpful, thanks!

[aaron-congo]

Hi @droni1234 and @DyllanSowersTR just following up here, are there any updates? @DyllanSowersTR, have you seen my questions above? Please let me know, thanks!

[droni1234]

Hey @aaron-congo,
unfortunately I don't have the capacity to get this tested with appropriate logs.
I only know that the system I am using is spinning up 2 containers that occasionally get restarted, which may result potentially in this error message.
Unfortunately my team and I have decided to not use the wrapper since we were getting a potential degradation.

[aaron-congo]

Hi @droni1234 , I'm sorry that the driver didn't work out for you in this scenario. We appreciate you taking the time in providing feedback.

Without knowing too much how the containers work in your environment, if the container restarts break the connection to your database, then failover is expected alongside the "failover success" message.

You mentioned you also observed degradation, could you please clarify what you meant here?

If others are experiencing something similar, we'd appreciate any relevant driver logs and info about your workflow to help determine what is happening. Thanks!

[droni1234]

Hi Aaron,

there was no degradation (at least I think that), what I meant was that I treat these warnings as a potential degradation. Components on my side have pretty strict alerting if we get too many warnings over 5 minutes there will be alerts.

Soo my question, what do I need to tell it to understand that it got restarted if that is the case. Does the pool need to properly close all connections? Can I configure anything?

I was contemplating if reducing the amounts of logs is possible, but I think since the connection Pool establishes all connections on boot this is not really possible.

Kind Regards
Phil

[aaron-congo]

Hi @droni1234,

It sounds like there are two things to address here:

1. You do not want error/warning logs when successful failover occurs
2. You want advice on how to handle successful failover events given that you are using tomcat's JDBC pool

Is this an accurate summary?

Also, can you please confirm whether or not the active SQL connection has changed due to a connection failure messages are expected? I know you said they were unexpected above but I'm not sure if you were aware that this message is expected if there are any network interruptions. I'm also not sure if the docker restarts you mentioned would cause network interruptions.

Please let me know, thanks!

[droni1234]

Yeah Aaron that is a pretty good summary.
Regarding the network issues I would need to investigate since that's happening outside of my context.

Kind regards

[aaron-congo]

Hi @droni1234, if you would like to avoid logs on successful failover, does it work for you to disable the failover plugin logs (see here for info on how to configure logging)? When failover succeeds, we are intentionally throwing an exception to get the user's attention, so we would like to keep the log level at SEVERE. If you disable failover plugin logs but still want logs for failover failures, you can catch FailoverFailedSQLException in your logic and log the event in your own code. I'm also curious if you are seeing WARNING/SEVERE logs from tomcat-jdbc or the mariadb/mysql drivers when failover occurs, since failover should only occur when a network issue has been detected by the underlying mariadb/mysql drivers.

Regarding tomcat-jdbc, I did some testing and it seems you do not have to do anything special with the pool when failover succeeds. You will have to catch the FailoverSuccessSQLException and re-configure session state if needed, but after that the connection can be used as normal. I did notice that, when failover fails, the broken connection is not evicted unless testOnReturn is enabled and we have passed the validationInterval (default value 3 seconds). This means you may still get the broken connection back from the pool. However, this behavior is controlled by tomcat-jdbc, not our driver, and it will also occur if you are using the plain mysql driver instead of our driver. Perhaps there is a way to configure tomcat-jdbc to evict the broken connection immediately but I could not find a way myself.