[CONJ-503] MariaDB Driver Uses Read Replicas for non-Read-Only Connections Created: 2017-07-06  Updated: 2017-08-16  Resolved: 2017-07-31

Status: Closed
Project: MariaDB Connector/J
Component/s: Failover
Affects Version/s: 2.0.2, 2.0.3
Fix Version/s: 2.1.0, 1.6.3

Type: Bug Priority: Major
Reporter: Joseph Witthuhn Assignee: Diego Dupin
Resolution: Fixed Votes: 0
Labels: None
Environment:

Amazon Linux
Oracle Java 8
Aurora (with read replicas and over SSL)
Jetty
Tomcat Pool
Hibernate
Spring Boot
Spring


 Description   

We have been struggling this for a couple of weeks, and I'm thinking we may have found an issue. We've tried to do everything we can to narrow it down to the driver.

Our context is that we are running an application in AWS against Aurora (and using Aurora failover mode) using Spring and Hibernate to manage transactions. Within writable transactions, we are seeing errors stating "The MySQL server is running with the --read-only option so it cannot execute this statement".

Throughout this report, I have omitted or modified the full names of our classes, packages, and hostnames (we don't really use single letters to name things), except where they may be useful.

Our connection string looks like this:
jdbc:mariadb:aurora://d-p-m-q.cluster-abcdefg1h2ij.us-east-1.rds.amazonaws.com:3306/d?useSSL=true&log=true&profileSql=true

Steps we have taken to troubleshoot:

  • Wrapped the DataSource with logging. After each call to getConnection, we call "isReadOnly" and log out the result.
  • Wrapped the Connection object itself with logging. For each call to "setReadOnly" we log out the value being passed in.

What we see in our log below is that we pulled a connection, our logging code called "isReadOnly", and got false. There was no line showing a call to setReadOnly. It then shows our connection going down trough a read replica (S) connection and not a Master (M) connection, which I believe it would have to in order to write successfully, right?

Behavior was observed in 2.0.2, and we upgrade to 2.0.3 to verify that the recent release wouldn't resolve the issue. We are unsure about recent versions prior to 2.0.2 (due to issues with SSL and Aurora failover in a few of the recent versions, we are upgrading to 2.0.2/2.0.3 from 1.4.6).

15:22:47.145 c.t.l.p.m.aurora.util.InstrumentedDataSource Connection pulled from pool. Read-only: false
 
15:22:47.147 org.mariadb.jdbc.internal.logging.ProtocolLoggingProxy Query - conn:3568(S) - 1.446 ms - "use `d`"
 
15:22:47.148 org.mariadb.jdbc.internal.logging.ProtocolLoggingProxy Query - conn:3568(S) - 1.138 ms - "set autocommit=0"
 
15:22:47.225 org.hibernate.engine.jdbc.spi.SqlExceptionHelper (conn:3568) The MySQL server is running with the --read-only option so it cannot execute this statement
 
15:22:47.225 org.mariadb.jdbc.MariaDbStatement error executing query
 
java.sql.SQLException: (conn:3568) The MySQL server is running with the --read-only option so it cannot execute this statement
 
	at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.get(ExceptionMapper.java:179)
 
	at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.getException(ExceptionMapper.java:118)
 
	at org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:245)
 
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:218)
 
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.execute(MariaDbPreparedStatementClient.java:153)
 
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeUpdate(MariaDbPreparedStatementClient.java:186)
 
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:204)
 
	at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:45)
 
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2949)
 
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3449)
 
	at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:89)
 
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:582)
 
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:456)
 
	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337)
 
	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
 
	at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1282)
 
	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:465)
 
	at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:2963)
 
	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2339)
 
	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:485)
 
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:147)
 
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$100(JdbcResourceLocalTransactionCoordinatorImpl.java:38)
 
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:231)
 
	at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:65)
 
	at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:61)
 
	at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517)
 
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:761)
 
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730)
 
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:504)
 
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:292)
 
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
 
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
 
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:656)
 
	at c.t.l.p.m.s.M$$EnhancerBySpringCGLIB$$8b81bfe2.pushLocalMessage(<generated>)
 
	at c.t.l.p.m.s.M$pushLocalMessage$2.call(Unknown Source)
 
	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
 
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
 
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:125)
 
	at c.t.l.p.m.s.M.p(M.groovy:44)
 
    ... (additional frames omitted here) ...
 
Caused by: java.sql.SQLException: The MySQL server is running with the --read-only option so it cannot execute this statement
 
Query is: insert into m (c) values (?), parameters ['2017-07-06 20:22:47.186']
 
	at org.mariadb.jdbc.internal.util.LogQueryTool.exceptionWithQuery(LogQueryTool.java:146)
 
	at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:223)
 
	at sun.reflect.GeneratedMethodAccessor178.invoke(Unknown Source)
 
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 
	at java.lang.reflect.Method.invoke(Method.java:498)
 
	at org.mariadb.jdbc.internal.failover.AbstractMastersListener.invoke(AbstractMastersListener.java:368)
 
	at org.mariadb.jdbc.internal.failover.FailoverProxy.executeInvocation(FailoverProxy.java:222)
 
	at org.mariadb.jdbc.internal.failover.FailoverProxy.invoke(FailoverProxy.java:215)
 
	at com.sun.proxy.$Proxy131.executeQuery(Unknown Source)
 
	at sun.reflect.GeneratedMethodAccessor178.invoke(Unknown Source)
 
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 
	at java.lang.reflect.Method.invoke(Method.java:498)
 
	at org.mariadb.jdbc.internal.logging.ProtocolLoggingProxy.invoke(ProtocolLoggingProxy.java:104)
 
	at com.sun.proxy.$Proxy131.executeQuery(Unknown Source)
 
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:212)
 
	... 120 common frames omitted
 
15:22:47.225 org.hibernate.engine.jdbc.spi.SqlExceptionHelper SQL Error: 1290, SQLState: HY000
 
15:22:47.228 org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl HHH000010: On release of batch it still contained JDBC statements
 
15:22:47.231 org.mariadb.jdbc.internal.logging.ProtocolLoggingProxy Query - conn:3568(S) - 2.109 ms - "ROLLBACK"
 
15:22:47.233 org.mariadb.jdbc.internal.logging.ProtocolLoggingProxy Query - conn:3568(S) - 1.32 ms - "set autocommit=1"
 
15:22:47.266 java.lang.Class ExceptionId: 5c925bc1-d670-4e0b-a2bc-2285de64929c - Message: An unexpected error has occurred
 
org.springframework.orm.jpa.JpaSystemException: could not execute statement; nested exception is org.hibernate.exception.GenericJDBCException: could not execute statement
 
	at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:333)
 
	at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:244)
 
	at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:521)
 
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:761)
 
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730)
 
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:504)
 
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:292)
 
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
 
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
 
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:656)
 
	at c.t.l.p.m.s.M$$EnhancerBySpringCGLIB$$8b81bfe2.pushLocalMessage(<generated>)
 
	at c.t.l.p.m.s.M$pushLocalMessage$2.call(Unknown Source)
 
	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
 
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
 
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:125)
 
	at c.t.l.p.m.s.M.p(M.groovy:44)
 
    ... (additional frames omitted here) ...
 
Caused by: org.hibernate.exception.GenericJDBCException: could not execute statement
 
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
 
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109)
 
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:95)
 
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:207)
 
	at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:45)
 
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2949)
 
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3449)
 
	at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:89)
 
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:582)
 
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:456)
 
	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337)
 
	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
 
	at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1282)
 
	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:465)
 
	at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:2963)
 
	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2339)
 
	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:485)
 
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:147)
 
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$100(JdbcResourceLocalTransactionCoordinatorImpl.java:38)
 
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:231)
 
	at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:65)
 
	at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:61)
 
	at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517)
 
	... 98 common frames omitted
 
Caused by: java.sql.SQLException: (conn:3568) The MySQL server is running with the --read-only option so it cannot execute this statement
 
	at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.get(ExceptionMapper.java:179)
 
	at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.getException(ExceptionMapper.java:118)
 
	at org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:245)
 
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:218)
 
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.execute(MariaDbPreparedStatementClient.java:153)
 
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeUpdate(MariaDbPreparedStatementClient.java:186)
 
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:204)
 
	... 117 common frames omitted
 
Caused by: java.sql.SQLException: The MySQL server is running with the --read-only option so it cannot execute this statement
 
Query is: insert into m (c) values (?), parameters ['2017-07-06 20:22:47.186']
 
	at org.mariadb.jdbc.internal.util.LogQueryTool.exceptionWithQuery(LogQueryTool.java:146)
 
	at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:223)
 
	at sun.reflect.GeneratedMethodAccessor178.invoke(Unknown Source)
 
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 
	at java.lang.reflect.Method.invoke(Method.java:498)
 
	at org.mariadb.jdbc.internal.failover.AbstractMastersListener.invoke(AbstractMastersListener.java:368)
 
	at org.mariadb.jdbc.internal.failover.FailoverProxy.executeInvocation(FailoverProxy.java:222)
 
	at org.mariadb.jdbc.internal.failover.FailoverProxy.invoke(FailoverProxy.java:215)
 
	at com.sun.proxy.$Proxy131.executeQuery(Unknown Source)
 
	at sun.reflect.GeneratedMethodAccessor178.invoke(Unknown Source)
 
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 
	at java.lang.reflect.Method.invoke(Method.java:498)
 
	at org.mariadb.jdbc.internal.logging.ProtocolLoggingProxy.invoke(ProtocolLoggingProxy.java:104)
 
	at com.sun.proxy.$Proxy131.executeQuery(Unknown Source)
 
	at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:212)
 
	... 120 common frames omitted



 Comments   
Comment by Joseph Witthuhn [ 2017-07-14 ]

Interesting note. By extending the MariaDbDataSource object and overriding its getConnection methods, we were able to workaround this bug. We simply call the driver's implementation first, and then call setReadOnly(false) before returning the connection.

Then, if we are in a read-only transaction, the framework will call setReadOnly(true). And everything seems to work.

I still believe this is a bug though, because if isReadOnly() returns false, I don't think we should have to follow it up with a call to setReadOnly(false) to get a writable connection to the master node.

Comment by Diego Dupin [ 2017-07-24 ]

After investigation, there is a regression on 1.6.x and 2.0.x version that concern aurora only : Connection.isReadOnly() is always returning false. This is now corrected in snapshot version.

can you check the result using SNAPSHOT version ?

<repositories>
 
    <repository>
 
        <id>sonatype-nexus-snapshots</id>
 
        <name>Sonatype Nexus Snapshots</name>
 
        <url>https://oss.sonatype.org/content/repositories/snapshots</url>
 
    </repository>
 
</repositories>
 
 
 
<dependencies>
 
    <dependency>
 
        <groupId>org.mariadb.jdbc</groupId>
 
        <artifactId>mariadb-java-client</artifactId>
 
        <version>2.1.0-SNAPSHOT</version>
 
    </dependency>
 
</dependencies>

Comment by Joseph Witthuhn [ 2017-07-25 ]

We tried this and still see the same error, but I think there is an issue blocking our test from being a "good test".

It looks like your commit for the fix was made at July 24, 2017 13:40 GMT. But the last snapshot was published at July 23, 2017 13:16 GMT. I'm guessing that means that the snapshot you referred to doesn't include your changes?

Comment by Diego Dupin [ 2017-07-31 ]

Sorry for that.

Issue has been identified, and reproduced.
Correction has been released in 2.1.0 and 1.6.3 version.
(released on maven / release on MariaDB website normally tomorrow).

So i'll close this issue, but feel free to create a new one if there is any need.

Comment by Joseph Witthuhn [ 2017-08-02 ]

We upgraded, but now we are getting this unrelated error which prevents us from validating the fix.

java.sql.SQLNonTransientConnectionException: DNS host "d-p-m-c.cluster-abcdefg1h2ik.us-east-1.rds.amazonaws.com" not found in certificate alt-names certificate SubjectAltNames [{"rds-aurora-d-p-m-c-cluster-lmnop34qrs56.cluster-abcdefg1h2ik.us-east-1.rds.amazonaws.com"|DNS},{"rds-aurora-d-p-m-c-cluster-lmnop34qrs56.cluster-ro-abcdefg1h2ik.us-east-1.rds.amazonaws.com"|DNS}]
 
This verification can be disable using the option "disableSslHostnameVerification" but won't prevent man-in-the-middle attacks anymore

I'm assuming that this is unrelated to the CONJ-503 change. I will open up a support case for this unrelated issue with Amazon and will circle back to confirm the fix for this bug once we work through that one.

Comment by Joseph Witthuhn [ 2017-08-16 ]

We were able to work around the AWS certificate issue and can confirm that this fix worked for us.

Thanks!

Generated at Thu Feb 08 03:16:08 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.