Bug #78710 Deadlock on ReplicationConnection and ReplicationConnectionGroup when failover.
Submitted: 5 Oct 2015 22:53 Modified: 2 Dec 2015 0:10
Reporter: Weihong Zhang Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / J Severity:S1 (Critical)
Version:5.1.36 OS:Microsoft Windows (7)
Assigned to: Filipe Silva CPU Architecture:Any
Tags: deadlock, fabric, failover, ReplicationConnection, ReplicationConnectionGroup

[5 Oct 2015 22:53] Weihong Zhang
Description:
I have two Mysql 5.6 data server(Primary and Secondary) and one Mysql 5.6 fabric DB. I have mysql-connector-java-5.1.36.jar. Fabric setup as monitor and failover. My java app connects Fabric and Primary DB. When I stop the Primary Mysql DB, Fabric change the Secondary as new Primary DB. But the java app face a Deadlock on connector API. See the Deadlock stack trace log below:

Name: http-bio-8080-exec-21
State: BLOCKED on com.mysql.jdbc.ReplicationConnection@2124a231 owned by: http-bio-8080-exec-9
Total blocked: 3  Total waited: 1

Stack trace: 
com.mysql.jdbc.ReplicationConnection.addSlaveHost(ReplicationConnection.java:317)
com.mysql.jdbc.ReplicationConnectionGroup.addSlaveHost(ReplicationConnectionGroup.java:99)
com.mysql.fabric.jdbc.FabricMySQLConnectionProxy.syncGroupServersToReplicationConnectionGroup(FabricMySQLConnectionProxy.java:500)
   - locked com.mysql.jdbc.ReplicationConnectionGroup@318c160f
com.mysql.fabric.jdbc.FabricMySQLConnectionProxy.interceptException(FabricMySQLConnectionProxy.java:239)
   - locked com.mysql.fabric.jdbc.JDBC4FabricMySQLConnectionProxy@586b5be5
com.mysql.fabric.jdbc.ErrorReportingExceptionInterceptor.interceptException(ErrorReportingExceptionInterceptor.java:56)
com.mysql.jdbc.ConnectionImpl$ExceptionInterceptorChain.interceptException(ConnectionImpl.java:143)
com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1056)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3434)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3334)
com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3774)
com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2447)
com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2594)
com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2541)
   - locked com.mysql.jdbc.LoadBalancingConnectionProxy@705e44bc
com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:4882)
   - locked com.mysql.jdbc.LoadBalancingConnectionProxy@705e44bc
com.mysql.jdbc.MultiHostMySQLConnection.setAutoCommit(MultiHostMySQLConnection.java:2035)
sun.reflect.GeneratedMethodAccessor34.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:606)
com.mysql.jdbc.LoadBalancingConnectionProxy.invokeMore(LoadBalancingConnectionProxy.java:458)
   - locked com.mysql.jdbc.LoadBalancingConnectionProxy@705e44bc
com.mysql.jdbc.MultiHostConnectionProxy.invoke(MultiHostConnectionProxy.java:394)
   - locked com.mysql.jdbc.LoadBalancingConnectionProxy@705e44bc
com.sun.proxy.$Proxy72.setAutoCommit(Unknown Source)
com.mysql.jdbc.ReplicationConnection.setAutoCommit(ReplicationConnection.java:653)
com.mysql.fabric.jdbc.FabricMySQLConnectionProxy.setAutoCommit(FabricMySQLConnectionProxy.java:652)
org.apache.commons.dbcp.DelegatingConnection.setAutoCommit(DelegatingConnection.java:371)
org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.setAutoCommit(PoolingDataSource.java:328)
org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.releaseManagedConnection(JdbcTransaction.java:127)
org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doCommit(JdbcTransaction.java:119)
org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:178)
org.hibernate.ejb.TransactionImpl.commit(TransactionImpl.java:75)

Name: http-bio-8080-exec-9
State: BLOCKED on com.mysql.jdbc.ReplicationConnectionGroup@318c160f owned by: http-bio-8080-exec-21
Total blocked: 12  Total waited: 26

Stack trace: 
com.mysql.fabric.jdbc.FabricMySQLConnectionProxy.syncGroupServersToReplicationConnectionGroup(FabricMySQLConnectionProxy.java:464)
com.mysql.fabric.jdbc.FabricMySQLConnectionProxy.interceptException(FabricMySQLConnectionProxy.java:239)
   - locked com.mysql.fabric.jdbc.JDBC4FabricMySQLConnectionProxy@72079cf8
com.mysql.fabric.jdbc.ErrorReportingExceptionInterceptor.interceptException(ErrorReportingExceptionInterceptor.java:56)
com.mysql.jdbc.ConnectionImpl$ExceptionInterceptorChain.interceptException(ConnectionImpl.java:143)
com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1056)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3434)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3334)
com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3774)
com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2447)
com.mysql.jdbc.ConnectionImpl.pingInternal(ConnectionImpl.java:4007)
com.mysql.jdbc.ConnectionImpl.ping(ConnectionImpl.java:3987)
com.mysql.jdbc.LoadBalancingConnectionProxy.doPing(LoadBalancingConnectionProxy.java:510)
   - locked com.mysql.jdbc.LoadBalancingConnectionProxy@51d29844
com.mysql.jdbc.LoadBalancedMySQLConnection.ping(LoadBalancedMySQLConnection.java:46)
com.mysql.jdbc.LoadBalancedMySQLConnection.ping(LoadBalancedMySQLConnection.java:41)
sun.reflect.GeneratedMethodAccessor43.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:606)
com.mysql.jdbc.LoadBalancingConnectionProxy.invokeMore(LoadBalancingConnectionProxy.java:458)
   - locked com.mysql.jdbc.LoadBalancingConnectionProxy@51d29844
com.mysql.jdbc.MultiHostConnectionProxy.invoke(MultiHostConnectionProxy.java:394)
   - locked com.mysql.jdbc.LoadBalancingConnectionProxy@51d29844
com.sun.proxy.$Proxy72.ping(Unknown Source)
com.mysql.jdbc.ReplicationConnection.doPing(ReplicationConnection.java:792)
   - locked com.mysql.jdbc.ReplicationConnection@2124a231
com.mysql.jdbc.StatementImpl.doPingInstead(StatementImpl.java:1493)
   - locked com.mysql.fabric.jdbc.JDBC4FabricMySQLConnectionProxy@72079cf8
com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1381)
   - locked com.mysql.fabric.jdbc.JDBC4FabricMySQLConnectionProxy@72079cf8
sun.reflect.GeneratedMethodAccessor42.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:606)
com.mysql.jdbc.MultiHostConnectionProxy$JdbcInterfaceProxy.invoke(MultiHostConnectionProxy.java:91)
com.sun.proxy.$Proxy74.executeQuery(Unknown Source)
org.apache.commons.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208)
org.apache.commons.dbcp.PoolableConnectionFactory.validateConnection(PoolableConnectionFactory.java:658)
org.apache.commons.dbcp.PoolableConnectionFactory.validateObject(PoolableConnectionFactory.java:635)
org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:855)
   - locked org.apache.commons.pool.impl.GenericObjectPool@5d4c6dad
org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)

How to repeat:
Need to have heavy load on the app/DB. In the fabric fail over time, at least two transactions open and one transaction is getting connection(doPing()).

So in the failover time, one thread hold a ReplicationConnection lock before two threads all try to interceptException.

Suggested fix:
Do not synchronized on method.
[8 Oct 2015 10:59] Filipe Silva
Hi Weihong,

Thank you for this bug report. Verified as described.
[2 Dec 2015 0:10] Daniel So
Added the following entry to the Connector/J 5.1.38 changelog:

"A deadlock was observed when in the same server group, two concurrent threads were using different Fabric connections, and one executed a failover procedure while the other simultaneously called a method that acquired a lock on the underlying replication connection instance monitor. This fix revised the locking mechanism of replication connections, in order to prevent the observed deadlocks."