cluster connection error after data node failure.
Posted by: Filip Kryspin
Date: December 16, 2015 01:13PM
Date: December 16, 2015 01:13PM
Hi all,
I have following problem...
I've setupu six node cluster like so:
Cluster Configuration
---------------------
[ndbd(NDB)] 2 node(s)
id=3 @192.168.3.56 (mysql-5.6.27 ndb-7.4.8, Nodegroup: 0, *)
id=4 @192.168.10.56 (mysql-5.6.27 ndb-7.4.8, Nodegroup: 0)
[ndb_mgmd(MGM)] 2 node(s)
id=1 @192.168.3.55 (mysql-5.6.27 ndb-7.4.8)
id=2 @192.168.10.55 (mysql-5.6.27 ndb-7.4.8)
[mysqld(API)] 2 node(s)
id=5 @192.168.3.57 (mysql-5.6.27 ndb-7.4.8)
id=6 @192.168.10.57 (mysql-5.6.27 ndb-7.4.8)
In front I have JBOSS-EAP cluster connectiong to the mysql-cluster using JDBC connection in loadbalance mode (connector/J)
We've run some durability tests killing different nodes in the cluster.
In each scenarion we've killed only one node of fully working cluster.
We've watched JBOSS logs during those tests.
When we killed SQL node, we've seen connection errors to the failed node (for obvious reasons)and some tranzaction rollbacks. After few seconds all connections ware established towards remaining SQL node.
In next scenario we kiled one data node of fully working cluster.
I was expectiong this event to be transparent to the appliacaion server, but it isnt.
We've also noticed connection errors, tranzaction rollbacks for few seconds.
All connections to the mysql-cluster failed an restarted.
To avoid this my gues was to have mysql-cluster writing data to disk as often as possible. Therefore I used following directives in [ndb] section of config.ini
ODirect=1
TimeBetweenLocalCheckpoints=10
It didn't help.
My question tou You is is this correct cluster behavior? or I'm doing something wrong?
Below are the application server logs after the data node crush:
[Server:server-one] 20\:01\:59,152 INFO [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (EJB default - 55) HHH000010: On release of batch it still contained JDBC statements
[Server:server-one] 20\:01\:59,152 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 55) SQL Error: 1297, SQLState: HY000
[Server:server-one] 20\:01\:59,152 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 55) Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] 20\:01\:59,152 ERROR [org.hibernate.engine.jdbc.batch.internal.BatchingBatch] (EJB default - 55) HHH000315: Exception executing batch [could not execute batch]
[Server:server-one] 20\:01\:59,163 INFO [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (EJB default - 59) HHH000010: On release of batch it still contained JDBC statements
[Server:server-one] 20\:01\:59,163 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 59) SQL Error: 1297, SQLState: HY000
[Server:server-one] 20\:01\:59,163 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 59) Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] 20\:01\:59,163 ERROR [org.hibernate.engine.jdbc.batch.internal.BatchingBatch] (EJB default - 59) HHH000315: Exception executing batch [could not execute batch]
[Server:server-one] 20\:01\:59,153 ERROR [org.jboss.as.ejb3] (EJB default - 55) JBAS014268: Failure in caller transaction.: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not execute batch
.
.
.
[Server:server-one] Caused by: java.sql.BatchUpdateException: Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1809)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1271)
[Server:server-one] at sun.reflect.GeneratedMethodAccessor121.invoke(Unknown Source) [:1.8.0_60]
[Server:server-one] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_60]
[Server:server-one] at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_60]
[Server:server-one] at com.mysql.jdbc.MultiHostConnectionProxy$JdbcInterfaceProxy.invoke(MultiHostConnectionProxy.java:91)
[Server:server-one] at com.sun.proxy.$Proxy125.executeBatch(Unknown Source)
[Server:server-one] at org.jboss.jca.adapters.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:1077)
[Server:server-one] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:113) [hibernate-core-4.2.18.Final-redhat-2.jar:4.2.18.Final-redhat-2]
[Server:server-one] ... 157 more
[Server:server-one] Caused by: java.sql.SQLException: Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:998)
[Server:server-one] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3847)
[Server:server-one] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3783)
[Server:server-one] at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2447)
[Server:server-one] at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2594)
[Server:server-one] at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2545)
[Server:server-one] at com.mysql.jdbc.MultiHostMySQLConnection.execSQL(MultiHostMySQLConnection.java:140)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1901)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2113)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1767)
[Server:server-one] ... 165 more
.
.
.
[Server:server-one] 20\:01\:59,239 INFO [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (EJB default - 75) HHH000010: On release of batch it still contained JDBC statements
[Server:server-one] 20\:01\:59,239 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 75) SQL Error: 1297, SQLState: HY000
[Server:server-one] 20\:01\:59,239 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 75) Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] 20\:01\:59,239 ERROR [org.hibernate.engine.jdbc.batch.internal.BatchingBatch] (EJB default - 75) HHH000315: Exception executing batch [could not execute batch]
[Server:server-one] 20\:01\:59,240 ERROR [org.jboss.as.ejb3] (EJB default - 75) JBAS014268: Failure in caller transaction.: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not execute batch
[Server:server-one] at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387) [hibernate-entitymanager-4.2.18.Final-redhat-2.jar:4.2.18.Final-redhat-2]
[Server:server-one] at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310) [hibernate-entitymanager-4.2.18.Final-redhat-2.jar:4.2.18.Final-redhat-2]
[Server:server-one] at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:277) [hibernate-entitymanager-4.2.18.Final-redhat-2.jar:4.2.18.Final-redhat-2]
[Server:server-one] at pl.hilltech.mfs.service.dao.HostStatusStateDAO.findHostStatus(HostStatusStateDAO.java:51) [mfs-core-mfs.01.jar:]
[Server:server-one] at sun.reflect.GeneratedMethodAccessor130.invoke(Unknown Source) [:1.8.0_60]
[Server:server-one] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_60]
[Server:server-one] at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_60]
.
.
.
[Server:server-one] Caused by: java.sql.BatchUpdateException: Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1809)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1271)
[Server:server-one] at sun.reflect.GeneratedMethodAccessor121.invoke(Unknown Source) [:1.8.0_60]
[Server:server-one] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_60]
[Server:server-one] at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_60]
[Server:server-one] at com.mysql.jdbc.MultiHostConnectionProxy$JdbcInterfaceProxy.invoke(MultiHostConnectionProxy.java:91)
[Server:server-one] at com.sun.proxy.$Proxy125.executeBatch(Unknown Source)
[Server:server-one] at org.jboss.jca.adapters.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:1077)
[Server:server-one] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:113) [hibernate-core-4.2.18.Final-redhat-2.jar:4.2.18.Final-redhat-2]
[Server:server-one] ... 157 more
[Server:server-one] Caused by: java.sql.SQLException: Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:998)
[Server:server-one] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3847)
[Server:server-one] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3783)
[Server:server-one] at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2447)
[Server:server-one] at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2594)
[Server:server-one] at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2545)
[Server:server-one] at com.mysql.jdbc.MultiHostMySQLConnection.execSQL(MultiHostMySQLConnection.java:140)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1901)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2113)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1767)
[Server:server-one] ... 165 more
I have following problem...
I've setupu six node cluster like so:
Cluster Configuration
---------------------
[ndbd(NDB)] 2 node(s)
id=3 @192.168.3.56 (mysql-5.6.27 ndb-7.4.8, Nodegroup: 0, *)
id=4 @192.168.10.56 (mysql-5.6.27 ndb-7.4.8, Nodegroup: 0)
[ndb_mgmd(MGM)] 2 node(s)
id=1 @192.168.3.55 (mysql-5.6.27 ndb-7.4.8)
id=2 @192.168.10.55 (mysql-5.6.27 ndb-7.4.8)
[mysqld(API)] 2 node(s)
id=5 @192.168.3.57 (mysql-5.6.27 ndb-7.4.8)
id=6 @192.168.10.57 (mysql-5.6.27 ndb-7.4.8)
In front I have JBOSS-EAP cluster connectiong to the mysql-cluster using JDBC connection in loadbalance mode (connector/J)
We've run some durability tests killing different nodes in the cluster.
In each scenarion we've killed only one node of fully working cluster.
We've watched JBOSS logs during those tests.
When we killed SQL node, we've seen connection errors to the failed node (for obvious reasons)and some tranzaction rollbacks. After few seconds all connections ware established towards remaining SQL node.
In next scenario we kiled one data node of fully working cluster.
I was expectiong this event to be transparent to the appliacaion server, but it isnt.
We've also noticed connection errors, tranzaction rollbacks for few seconds.
All connections to the mysql-cluster failed an restarted.
To avoid this my gues was to have mysql-cluster writing data to disk as often as possible. Therefore I used following directives in [ndb] section of config.ini
ODirect=1
TimeBetweenLocalCheckpoints=10
It didn't help.
My question tou You is is this correct cluster behavior? or I'm doing something wrong?
Below are the application server logs after the data node crush:
[Server:server-one] 20\:01\:59,152 INFO [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (EJB default - 55) HHH000010: On release of batch it still contained JDBC statements
[Server:server-one] 20\:01\:59,152 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 55) SQL Error: 1297, SQLState: HY000
[Server:server-one] 20\:01\:59,152 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 55) Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] 20\:01\:59,152 ERROR [org.hibernate.engine.jdbc.batch.internal.BatchingBatch] (EJB default - 55) HHH000315: Exception executing batch [could not execute batch]
[Server:server-one] 20\:01\:59,163 INFO [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (EJB default - 59) HHH000010: On release of batch it still contained JDBC statements
[Server:server-one] 20\:01\:59,163 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 59) SQL Error: 1297, SQLState: HY000
[Server:server-one] 20\:01\:59,163 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 59) Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] 20\:01\:59,163 ERROR [org.hibernate.engine.jdbc.batch.internal.BatchingBatch] (EJB default - 59) HHH000315: Exception executing batch [could not execute batch]
[Server:server-one] 20\:01\:59,153 ERROR [org.jboss.as.ejb3] (EJB default - 55) JBAS014268: Failure in caller transaction.: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not execute batch
.
.
.
[Server:server-one] Caused by: java.sql.BatchUpdateException: Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1809)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1271)
[Server:server-one] at sun.reflect.GeneratedMethodAccessor121.invoke(Unknown Source) [:1.8.0_60]
[Server:server-one] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_60]
[Server:server-one] at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_60]
[Server:server-one] at com.mysql.jdbc.MultiHostConnectionProxy$JdbcInterfaceProxy.invoke(MultiHostConnectionProxy.java:91)
[Server:server-one] at com.sun.proxy.$Proxy125.executeBatch(Unknown Source)
[Server:server-one] at org.jboss.jca.adapters.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:1077)
[Server:server-one] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:113) [hibernate-core-4.2.18.Final-redhat-2.jar:4.2.18.Final-redhat-2]
[Server:server-one] ... 157 more
[Server:server-one] Caused by: java.sql.SQLException: Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:998)
[Server:server-one] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3847)
[Server:server-one] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3783)
[Server:server-one] at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2447)
[Server:server-one] at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2594)
[Server:server-one] at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2545)
[Server:server-one] at com.mysql.jdbc.MultiHostMySQLConnection.execSQL(MultiHostMySQLConnection.java:140)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1901)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2113)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1767)
[Server:server-one] ... 165 more
.
.
.
[Server:server-one] 20\:01\:59,239 INFO [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (EJB default - 75) HHH000010: On release of batch it still contained JDBC statements
[Server:server-one] 20\:01\:59,239 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 75) SQL Error: 1297, SQLState: HY000
[Server:server-one] 20\:01\:59,239 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (EJB default - 75) Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] 20\:01\:59,239 ERROR [org.hibernate.engine.jdbc.batch.internal.BatchingBatch] (EJB default - 75) HHH000315: Exception executing batch [could not execute batch]
[Server:server-one] 20\:01\:59,240 ERROR [org.jboss.as.ejb3] (EJB default - 75) JBAS014268: Failure in caller transaction.: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not execute batch
[Server:server-one] at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387) [hibernate-entitymanager-4.2.18.Final-redhat-2.jar:4.2.18.Final-redhat-2]
[Server:server-one] at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310) [hibernate-entitymanager-4.2.18.Final-redhat-2.jar:4.2.18.Final-redhat-2]
[Server:server-one] at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:277) [hibernate-entitymanager-4.2.18.Final-redhat-2.jar:4.2.18.Final-redhat-2]
[Server:server-one] at pl.hilltech.mfs.service.dao.HostStatusStateDAO.findHostStatus(HostStatusStateDAO.java:51) [mfs-core-mfs.01.jar:]
[Server:server-one] at sun.reflect.GeneratedMethodAccessor130.invoke(Unknown Source) [:1.8.0_60]
[Server:server-one] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_60]
[Server:server-one] at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_60]
.
.
.
[Server:server-one] Caused by: java.sql.BatchUpdateException: Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1809)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1271)
[Server:server-one] at sun.reflect.GeneratedMethodAccessor121.invoke(Unknown Source) [:1.8.0_60]
[Server:server-one] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_60]
[Server:server-one] at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_60]
[Server:server-one] at com.mysql.jdbc.MultiHostConnectionProxy$JdbcInterfaceProxy.invoke(MultiHostConnectionProxy.java:91)
[Server:server-one] at com.sun.proxy.$Proxy125.executeBatch(Unknown Source)
[Server:server-one] at org.jboss.jca.adapters.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:1077)
[Server:server-one] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:113) [hibernate-core-4.2.18.Final-redhat-2.jar:4.2.18.Final-redhat-2]
[Server:server-one] ... 157 more
[Server:server-one] Caused by: java.sql.SQLException: Got temporary error 4025 'Node failure caused abort of transaction' from NDBCLUSTER
[Server:server-one] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:998)
[Server:server-one] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3847)
[Server:server-one] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3783)
[Server:server-one] at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2447)
[Server:server-one] at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2594)
[Server:server-one] at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2545)
[Server:server-one] at com.mysql.jdbc.MultiHostMySQLConnection.execSQL(MultiHostMySQLConnection.java:140)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1901)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2113)
[Server:server-one] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1767)
[Server:server-one] ... 165 more
Subject
Views
Written By
Posted
Sorry, you can't reply to this topic. It has been closed.
Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.