Unable to connect SQL node to a MySQL cluster

[Cyril CLARISSE]

Hi all,

I'm stuck with the setting of a new MySQL cluster based on the lastest cluster rpms (7.0.9).
I followed the How-to (http://dev.mysql.com/doc/refman/5.1/en/mysql-cluster-multi-computer.html) and even being in the same configuration, my SQL node cannot connect to the cluster.

Here is my configuration :
2x data nodes with this my.cnf :
[mysqld]
ndbcluster
ndb-connectstring=172.16.10.12

[mysql_cluster]
ndb-connectstring=172.16.10.12

1x SQL node with this my.cnf :
[mysqld]
ndbcluster
server-id=4
ndb-nodeid=4
ndb-connectstring=172.16.10.12

[mysql_cluster]
ndb-connectstring=172.16.10.12


1x Mgmt node with this config.ini :
[ndbd default]
NoOfReplicas=2

[tcp default]

[ndb_mgmd]
Id=1
hostname=172.16.10.12
datadir=/var/lib/mysql-cluster

[ndbd]
Id=2
hostname=172.16.10.20
datadir=/var/lib/mysql-cluster
MaxNoOfExecutionThreads=8

[ndbd]
Id=3
hostname=172.16.10.21
datadir=/var/lib/mysql-cluster
MaxNoOfExecutionThreads=8

[mysqld]
Id=4

I start the mgmt node like this :
ndb_mgmd -f /var/lib/mysql-cluster/config.ini

The data nodes like this (the 1st time):
ndbmtd --initial

And finally the SQL node like this :
service mysql start

But on the Mgmt node, here is the output of the show command :
ndb_mgm> show
Connected to Management Server at: 172.16.10.12:1186
Cluster Configuration
---------------------
[ndbd(NDB)] 2 node(s)
id=2 @172.16.10.20 (mysql-5.1.39 ndb-7.0.9, Nodegroup: 0, Master)
id=3 @172.16.10.21 (mysql-5.1.39 ndb-7.0.9, Nodegroup: 0)

[ndb_mgmd(MGM)] 1 node(s)
id=1 @172.16.10.12 (mysql-5.1.39 ndb-7.0.9)

[mysqld(API)] 2 node(s)
id=4 (not connected, accepting connect from any host)

I never managed to get the mysqld in a "connected" state.

Here are the logs on the Mgmt node :
...
2009-12-11 14:28:42 [MgmtSrvr] INFO -- Got initial configuration from '/var/lib/mysql-cluster/config.ini', will try to set it when all ndb_mgmd(s) started
2009-12-11 14:28:42 [MgmtSrvr] INFO -- Mgmt server state: nodeid 1 reserved for ip 172.16.10.12, m_reserved_nodes 0000000000000000000000000000000000000000000000000000000000000002.
2009-12-11 14:28:42 [MgmtSrvr] INFO -- Node 1: Node 1 Connected
2009-12-11 14:28:42 [MgmtSrvr] INFO -- Id: 1, Command port: *:1186
2009-12-11 14:28:42 [MgmtSrvr] INFO -- Starting initial configuration change
2009-12-11 14:28:42 [MgmtSrvr] INFO -- Configuration 1 commited
2009-12-11 14:28:42 [MgmtSrvr] INFO -- Config change completed! New generation: 1
2009-12-11 14:29:34 [MgmtSrvr] INFO -- Mgmt server state: nodeid 2 reserved for ip 172.16.10.20, m_reserved_nodes 0000000000000000000000000000000000000000000000000000000000000006.
2009-12-11 14:29:34 [MgmtSrvr] INFO -- Node 1: Node 2 Connected
2009-12-11 14:29:35 [MgmtSrvr] INFO -- Mgmt server state: nodeid 2 freed, m_reserved_nodes 0000000000000000000000000000000000000000000000000000000000000002.
2009-12-11 14:29:37 [MgmtSrvr] INFO -- Node 2: Initial start, waiting for 3 to connect, nodes [ all: 2 and 3 connected: 2 no-wait: ]
2009-12-11 14:29:40 [MgmtSrvr] INFO -- Mgmt server state: nodeid 3 reserved for ip 172.16.10.21, m_reserved_nodes 000000000000000000000000000000000000000000000000000000000000000a.
2009-12-11 14:29:40 [MgmtSrvr] INFO -- Node 1: Node 3 Connected
2009-12-11 14:29:40 [MgmtSrvr] INFO -- Node 2: Initial start, waiting for 3 to connect, nodes [ all: 2 and 3 connected: 2 no-wait: ]
2009-12-11 14:29:40 [MgmtSrvr] INFO -- Node 2: Node 3 Connected
2009-12-11 14:29:40 [MgmtSrvr] INFO -- Node 2: Initial start with nodes 2 and 3 [ missing: no-wait: ]
2009-12-11 14:29:40 [MgmtSrvr] INFO -- Node 2: CM_REGCONF president = 2, own Node = 2, our dynamic id = 1
2009-12-11 14:29:41 [MgmtSrvr] INFO -- Mgmt server state: nodeid 3 freed, m_reserved_nodes 0000000000000000000000000000000000000000000000000000000000000002.
2009-12-11 14:29:43 [MgmtSrvr] INFO -- Node 2: Node 3: API mysql-5.1.39 ndb-7.0.9
2009-12-11 14:29:43 [MgmtSrvr] INFO -- Node 3: CM_REGCONF president = 2, own Node = 3, our dynamic id = 2
2009-12-11 14:29:43 [MgmtSrvr] INFO -- Node 2: Start phase 1 completed
2009-12-11 14:29:43 [MgmtSrvr] INFO -- Node 3: Start phase 1 completed
2009-12-11 14:29:43 [MgmtSrvr] INFO -- Node 3: Node 2: API mysql-5.1.39 ndb-7.0.9
2009-12-11 14:29:43 [MgmtSrvr] INFO -- Node 2: Start phase 2 completed (initial start)
2009-12-11 14:29:43 [MgmtSrvr] INFO -- Node 3: Start phase 2 completed (initial start)
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 2: Start phase 3 completed (initial start)
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 2: Local redo log file initialization status:
#Total files: 64, Completed: 0
#Total MBytes: 1024, Completed: 0
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 2: Local redo log file initialization status:
#Total files: 64, Completed: 0
#Total MBytes: 1024, Completed: 0 - Repeated 3 times
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 3: Start phase 3 completed (initial start)
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 3: Local redo log file initialization status:
#Total files: 64, Completed: 0
#Total MBytes: 1024, Completed: 0
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 3: Local redo log file initialization status:
#Total files: 64, Completed: 0
#Total MBytes: 1024, Completed: 0 - Repeated 3 times
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 2: Local redo log file initialization completed:
#Total files: 64, Completed: 16
#Total MBytes: 1024, Completed: 256
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 2: Local redo log file initialization completed:
#Total files: 64, Completed: 16
#Total MBytes: 1024, Completed: 256 - Repeated 3 times
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 3: Local redo log file initialization completed:
#Total files: 64, Completed: 16
#Total MBytes: 1024, Completed: 256
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 3: Local redo log file initialization completed:
#Total files: 64, Completed: 16
#Total MBytes: 1024, Completed: 256 - Repeated 3 times
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 2: Start phase 4 completed (initial start)
2009-12-11 14:29:44 [MgmtSrvr] INFO -- Node 3: Start phase 4 completed (initial start)
2009-12-11 14:29:45 [MgmtSrvr] INFO -- Node 2: Local checkpoint 1 started. Keep GCI = 1 oldest restorable GCI = 1
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Start phase 5 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Start phase 6 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: President restarts arbitration thread [state=1]
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Start phase 7 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Start phase 5 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Start phase 6 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Start phase 7 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Start phase 8 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Start phase 9 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Start phase 100 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Start phase 101 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Started (mysql-5.1.39 ndb-7.0.9)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Start phase 8 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Start phase 9 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Start phase 100 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Start phase 101 completed (initial start)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Started (mysql-5.1.39 ndb-7.0.9)
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Node 1: API mysql-5.1.39 ndb-7.0.9
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Node 1: API mysql-5.1.39 ndb-7.0.9
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Prepare arbitrator node 1 [ticket=1d95000103f7f796]
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Started arbitrator node 1 [ticket=1d95000103f7f796]
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Communication to Node 4 opened
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 2: Communication to Node 5 opened
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Communication to Node 4 opened
2009-12-11 14:29:47 [MgmtSrvr] INFO -- Node 3: Communication to Node 5 opened
2009-12-11 14:30:43 [MgmtSrvr] INFO -- Mgmt server state: nodeid 4 reserved for ip 172.16.10.13, m_reserved_nodes 0000000000000000000000000000000000000000000000000000000000000012.
2009-12-11 14:30:43 [MgmtSrvr] INFO -- Node 4: mysqld --server-id=4
2009-12-11 14:31:03 [MgmtSrvr] WARNING -- Node 2: Releasing node id allocation for node 4


and the logs on the Mysql node :
091211 14:30:43 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
091211 14:30:43 [Note] Plugin 'FEDERATED' is disabled.
091211 14:30:43 InnoDB: Started; log sequence number 0 44233
091211 14:30:43 [Note] NDB: NodeID is 4, management server '172.16.10.12:1186'
091211 14:30:44 [Note] NDB[0]: NodeID: 4, no storage nodes connected (timed out)
091211 14:30:44 [Note] Starting Cluster Binlog Thread
091211 14:30:44 [Note] Event Scheduler: Loaded 0 events
091211 14:30:59 [Warning] NDB : Tables not available after 15 seconds. Consider increasing --ndb-wait-setup value
091211 14:30:59 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.39-ndb-7.0.9-cluster-gpl' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Cluster Server (GPL)

What sound strange to me is the theses 2 lines but I do not see how to solve this :
- 2009-12-11 14:31:03 [MgmtSrvr] WARNING -- Node 2: Releasing node id allocation for node 4
- 091211 14:30:44 [Note] NDB[0]: NodeID: 4, no storage nodes connected (timed out)

also the storage node are already connected to the cluster (check the show output).

Anyone can see what is the issue (no iptables on hosts) ? Thanks by advance.