aws / aws-advanced-jdbc-wrapper

The Amazon Web Services JDBC Driver has been redesigned as an advanced JDBC wrapper. This wrapper is complementary to and extends the functionality of an existing JDBC driver to help an application take advantage of the features of clustered databases such as Amazon Aurora.
Apache License 2.0
220 stars 47 forks source link

ReadWriteSplitting plugin never switching to readers for Wildfly project #1096

Open juliendef opened 3 months ago

juliendef commented 3 months ago

Describe the bug

Using Java 8, Spring 2.1.3, Wildfly 10.1.0, MySQL 8.0.33 and AWS advanced JDBC wrapper 2.3.9.

[!NOTE] Even using Wildfly 26.1.1, Jdk 11, Spring 2.7.1, like your example. It wont do the transaction routing.

I can't reach my reader instance at all when a transaction is indicated as “readOnly”.

There's no call for switchConnectionIfRequired, as if the plugin wasn't listening to the transactional annotation and its readOnly property.

The following logs result from a test with the minimal example from the repo I've attached below

Expected Behavior

I personally built a version containing additional logs of aws-advanced-jdbc-wrapper, observing that switchConnectionIfRequired is never called, and I expect that to be the case when @transactional(readOnly=true) is being called

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

wrapperLoggerLevel=ALL&wrapperPlugins=readWriteSplitting,failover,efm2

Current Behavior

No switch is made on the reader, certainly because no call to that switchConnectionIfRequired

2024-08-20 15:53:00,403 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-8) Executing method: 'ResultSet.getInt'
2024-08-20 15:53:00,403 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-8) Executing method: 'ResultSet.next'
2024-08-20 15:53:00,403 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-8) Executing method: 'ResultSet.getString'
2024-08-20 15:53:00,403 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-8) Executing method: 'ResultSet.getInt'
2024-08-20 15:53:00,403 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-8) Executing method: 'ResultSet.next'
2024-08-20 15:53:00,403 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-8) Executing method: 'ResultSet.getString'
2024-08-20 15:53:00,403 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-8) Executing method: 'ResultSet.getInt'
2024-08-20 15:53:00,404 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-8) Executing method: 'ResultSet.next'
2024-08-20 15:53:00,404 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-8) Executing method: 'ResultSet.close'
2024-08-20 15:53:00,404 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-8) Executing method: 'Statement.close'
2024-08-20 15:53:10,602 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'Connection.createStatement'
2024-08-20 15:53:10,603 FINEST [software.amazon.jdbc.hostlistprovider.RdsHostListProvider] (default task-9) [From cache] Topology:
   HostSpec[host=test-mysql8-2.test.eu-west-1.rds.amazonaws.com, port=3306, READER, AVAILABLE, weight=1704, 2024-08-20 15:53:00.386371]
   HostSpec[host=test-mysql8-1.test.eu-west-1.rds.amazonaws.com, port=3306, WRITER, AVAILABLE, weight=10, 2024-08-20 15:53:00.131001]
2024-08-20 15:53:10,603 FINEST [software.amazon.jdbc.plugin.efm2.HostMonitoringConnectionPlugin] (default task-9) Executing method 'Statement.executeQuery', monitoring is activated.
2024-08-20 15:53:10,603 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'Statement.executeQuery'
2024-08-20 15:53:10,604 FINEST [software.amazon.jdbc.plugin.efm2.HostMonitoringConnectionPlugin] (default task-9) Monitoring deactivated for method 'Statement.executeQuery'.
2024-08-20 15:53:10,604 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.close'
2024-08-20 15:53:10,604 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'Statement.close'
2024-08-20 15:53:10,604 FINEST [software.amazon.jdbc.hostlistprovider.RdsHostListProvider] (default task-9) [From cache] Topology:
   HostSpec[host=test-mysql8-2.test.eu-west-1.rds.amazonaws.com, port=3306, READER, AVAILABLE, weight=1704, 2024-08-20 15:53:00.386371]
   HostSpec[host=test-mysql8-1.test.eu-west-1.rds.amazonaws.com, port=3306, WRITER, AVAILABLE, weight=10, 2024-08-20 15:53:00.131001]
2024-08-20 15:53:10,604 FINEST [software.amazon.jdbc.plugin.efm2.HostMonitoringConnectionPlugin] (default task-9) Executing method 'Connection.setAutoCommit', monitoring is activated.
2024-08-20 15:53:10,604 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'Connection.setAutoCommit'
2024-08-20 15:53:10,605 FINEST [software.amazon.jdbc.states.SessionStateServiceImpl] (default task-9) Current session state:
autoCommit: true -> false
readOnly: false -> (blank)
catalog: (blank) -> (blank)
schema: (blank) -> (blank)
holdability: (blank) -> (blank)
networkTimeout: (blank) -> (blank)
transactionIsolation: 4 -> (blank)
typeMap: (blank) -> (blank)

2024-08-20 15:53:10,605 FINEST [software.amazon.jdbc.plugin.efm2.HostMonitoringConnectionPlugin] (default task-9) Monitoring deactivated for method 'Connection.setAutoCommit'.
2024-08-20 15:53:10,605 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'Connection.createStatement'
2024-08-20 15:53:10,606 FINEST [software.amazon.jdbc.hostlistprovider.RdsHostListProvider] (default task-9) [From cache] Topology:
   HostSpec[host=test-mysql8-2.test.eu-west-1.rds.amazonaws.com, port=3306, READER, AVAILABLE, weight=1704, 2024-08-20 15:53:00.386371]
   HostSpec[host=test-mysql8-1.test.eu-west-1.rds.amazonaws.com, port=3306, WRITER, AVAILABLE, weight=10, 2024-08-20 15:53:00.131001]
2024-08-20 15:53:10,606 FINEST [software.amazon.jdbc.plugin.efm2.HostMonitoringConnectionPlugin] (default task-9) Executing method 'Statement.executeQuery', monitoring is activated.
2024-08-20 15:53:10,606 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'Statement.executeQuery'
2024-08-20 15:53:10,607 FINEST [software.amazon.jdbc.plugin.efm2.HostMonitoringConnectionPlugin] (default task-9) Monitoring deactivated for method 'Statement.executeQuery'.
2024-08-20 15:53:10,607 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.next'
2024-08-20 15:53:10,608 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.getString'
2024-08-20 15:53:10,608 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.getInt'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.next'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.getString'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.getInt'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.next'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.getString'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.getInt'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.next'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.getString'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.getInt'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.next'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.getString'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.getInt'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.next'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'ResultSet.close'
2024-08-20 15:53:10,609 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'Statement.close'
2024-08-20 15:53:10,610 FINEST [software.amazon.jdbc.hostlistprovider.RdsHostListProvider] (default task-9) [From cache] Topology:
   HostSpec[host=test-mysql8-2.test.eu-west-1.rds.amazonaws.com, port=3306, READER, AVAILABLE, weight=1704, 2024-08-20 15:53:00.386371]
   HostSpec[host=test-mysql8-1.test.eu-west-1.rds.amazonaws.com, port=3306, WRITER, AVAILABLE, weight=10, 2024-08-20 15:53:00.131001]
2024-08-20 15:53:10,610 FINEST [software.amazon.jdbc.plugin.efm2.HostMonitoringConnectionPlugin] (default task-9) Executing method 'Connection.commit', monitoring is activated.
2024-08-20 15:53:10,610 FINEST [software.amazon.jdbc.plugin.DefaultConnectionPlugin] (default task-9) Executing method: 'Connection.commit'
2024-08-20 15:53:10,610 FINEST [software.amazon.jdbc.plugin.efm2.HostMonitoringConnectionPlugin] (default task-9) Monitoring deactivated for method 'Connection.commit'

Reproduction Steps

Minimal example that reproduces the problem, read Wildfly on Docker chapter for fast reproduction. Feel free to ask

Possible Solution

Perhaps because of the JTA Wildfly?

Additional Information/Context

No response

The AWS Advanced JDBC Driver version used

2.3.9

JDK version used

8 (also tested on 11)

Operating System and version

CentOS Linux 7 (docker image)

aaron-congo commented 2 months ago

Hi @juliendef ,

Thanks for reaching out and raising this issue.

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

Thank you for your patience!

aaron-congo commented 1 month ago

Hi @juliendef, I've been trying to use your poc to reproduce the issue but am running into some problems. I'm not familiar with wildfly, but I'm following the steps in the poc's README to use wildfly locally. After deploying to wildfly, do I need to also run the application locally (eg through intellij)? When I do I get the below error. I've verified that java:jboss/datasources/MyPool is defined in standalone.xml and the wildfly management console seems to list the aws driver. If I go to localhost:8080/rw I get Not Found. Any ideas on how to fix this?

Additionally, your poc README mentions using SSM to port forward RDS to your local machine. What is SSM? And is port forwarding needed even if you specify the RDS URL in the data source? So far I've been trying to run it without port forwarding by specifying the RDS URL in the data source.

Error I'm seeing when running application through intellij after deploying to wildfly:

Exception in thread "main" org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'dataSourceScriptDatabaseInitializer' defined in class path resource [org/springframework/boot/autoconfigure/sql/init/DataSourceInitializationConfiguration.class]: Unsatisfied dependency expressed through method 'dataSourceScriptDatabaseInitializer' parameter 0; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dataSource' defined in class path resource [org/springframework/boot/autoconfigure/jdbc/JndiDataSourceAutoConfiguration.class]: Bean instantiation via factory method failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [javax.sql.DataSource]: Factory method 'dataSource' threw exception; nested exception is org.springframework.jdbc.datasource.lookup.DataSourceLookupFailureException: Failed to look up JNDI DataSource with name 'java:jboss/datasources/MyPool'; nested exception is javax.naming.NoInitialContextException: Need to specify class name in environment or system property, or in an application resource file: java.naming.factory.initial
juliendef commented 2 weeks ago

Hi @aaron-congo , sorry for the delay

Assuming you're trying to run Wildfly locally without Docker (easiest)

After deploying to wildfly, do I need to also run the application locally (eg through intellij)?

No need to run on intellij if the .war artefact is deployed on Wildfly. It's completely separate. Also when running Wildfly locally using /bin/standalone.sh, the logs of the deployed application will appear on the same terminal

What is SSM?

I mention this for my colleagues (because we don't have direct access to RDS, we're going through AWS Systems Manager Agent), but the aim is to have access from your PC to RDS. Any way you can.

After that, in README, chapter Create datasource, it's expected to modify the datasource configuration according to your connection. Precisely, changing the connection-url, myUser and myPassword from the following :

/subsystem=datasources/data-source=MyPool:add(jndi-name=java:jboss/datasources/MyPool, driver-name="aws-wrapper", connection-url="jdbc:aws-wrapper:mysql://localhost:3326/myDb?wrapperLoggerLevel=ALL&wrapperPlugins=readWriteSplitting,failover,efm2")
/subsystem=datasources/data-source=MyPool:write-attribute(name=user-name, value=myUser)
/subsystem=datasources/data-source=MyPool:write-attribute(name=password, value=myPassword)

The exception you share with me seems to be a problem linked to the RDS connection.

Otherwise, another important point so that your endpoint localhost:8080/rw can respond. You'll need to adapt the code to your DB schema. Please change this entity according to your DB schema

aaron-congo commented 2 weeks ago

Hi @juliendef,

The problem I was encountering was because I was using the newest version of wildfly which is incompatible with your poc, I overlooked the fact that your poc uses 26.1.1 and the error I was getting didn't make that clear. After switching to 26.1.1 I was able to reproduce the problem.

The key reason why your poc never switches to the reader is that "Connection.setReadOnly(true)" is never called. This is the method that needs to be used to tell our wrapper to switch to a reader connection (see docs here). I debugged one of our non-wildfly spring examples and compared it to your poc. In our example, JpaTransactionManager is used by default as the underlying transaction manager. This transaction manager automatically calls "Connection.setReadOnly(true)" when it hits a @Transactional(readOnly=true) annotation. In contrast, wildfly automatically uses JtaTransactionManager, which does not automatically call "Connection.setReadOnly(true)" when it hits this annotation.

I'm not too familiar with wildfly or spring-boot, do you know if there is a way to configure your poc to use JpaTransactionManager instead of JtaTransactionManager? The key thing that needs to happen is that Connection.setReadOnly is called to switch to a reader.

One more note, please see this section of our docs because there is a related limitation regarding the @Transactional(readOnly=true) annotation. To summarize the docs, if you want to have read/write load balancing with spring you should either: A. use the read/write plugin but make sure that internal connection pools are also enabled, or B. do not use the read/write plugin, instead use the writer cluster URL for your writes and the reader cluster URL for your reads