MySQL Cluster: API node won't start successfully

Question

I am working on setting up a MySQL NDB cluster in a test environment. I have 1 management node, 2 SQL nodes and 4 NDB nodes. The management nodes and NDB nodes all start successfully. They are manually called, as per the MySQL documentation. If I call mysqld_safe manually, MySQL loads, connects to the management node and runs correctly. However if I call service mysql start, it loads MySQL and connects to the management node however it thinks there are no NDB nodes and just waits.

Now this is what really confuses me. If I run /etc/init.d/mysql start, I have the same issue as running the service. However if I run cp /etc/init.d/mysql ~; ./mysql start the service starts in a fraction of the time as it takes to run the service, and it loads correctly.

MySQL Cluster version is 7.4.10. Running on CentOS 7.

MySQL as Service

[root@MySQL1 mysql]# cat MySQL1.Cluster.err 
160329 12:38:56 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2016-03-29 12:38:56 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-03-29 12:38:56 0 [Note] /usr/sbin/mysqld (mysqld 5.6.28-ndb-7.4.10-cluster-gpl) starting as process 12269 ...
2016-03-29 12:38:56 12269 [Note] Plugin 'FEDERATED' is disabled.
2016-03-29 12:38:56 12269 [Note] InnoDB: Using atomics to ref count buffer pool pages
2016-03-29 12:38:56 12269 [Note] InnoDB: The InnoDB memory heap is disabled
2016-03-29 12:38:56 12269 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-03-29 12:38:56 12269 [Note] InnoDB: Memory barrier is not used
2016-03-29 12:38:56 12269 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-03-29 12:38:56 12269 [Note] InnoDB: Using Linux native AIO
2016-03-29 12:38:56 12269 [Note] InnoDB: Not using CPU crc32 instructions
2016-03-29 12:38:56 12269 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2016-03-29 12:38:56 12269 [Note] InnoDB: Completed initialization of buffer pool
2016-03-29 12:38:57 12269 [Note] InnoDB: Highest supported file format is Barracuda.
2016-03-29 12:38:57 12269 [Note] InnoDB: 128 rollback segment(s) are active.
2016-03-29 12:38:57 12269 [Note] InnoDB: Waiting for purge to start
2016-03-29 12:38:57 12269 [Note] InnoDB: 5.6.28 started; log sequence number 1626423
2016-03-29 12:38:57 12269 [Note] NDB: Changed global value of binlog_format from STATEMENT to MIXED
2016-03-29 12:38:57 12269 [Note] NDB: NodeID is 50, management server '10.0.0.200:1186'
2016-03-29 12:39:27 12269 [Note] NDB[0]: NodeID: 50, no storage nodes connected (timed out)
2016-03-29 12:39:27 12269 [Warning] NDB: server id set to zero - changes logged to bin log with server id zero will be logged with another server id by slave mysqlds
2016-03-29 12:39:27 12269 [Note] NDB Binlog: Starting...
2016-03-29 12:39:27 12269 [Note] NDB Binlog: Started
2016-03-29 12:39:27 12269 [Note] NDB Binlog: Setting up
2016-03-29 12:39:27 12269 [Note] NDB Binlog: Created schema Ndb object, reference: 0x80040032, name: 'Ndb Binlog schema change monitoring'
2016-03-29 12:39:27 12269 [Note] NDB Binlog: Created injector Ndb object, reference: 0x80050032, name: 'Ndb Binlog data change monitoring'
2016-03-29 12:39:27 12269 [Note] NDB Binlog: Setup completed
2016-03-29 12:39:27 12269 [Note] NDB Binlog: Wait for server start completed
2016-03-29 12:39:27 12269 [Note] NDB Util: Starting...
2016-03-29 12:39:27 12269 [Note] NDB Util: Wait for server start completed
2016-03-29 12:39:27 12269 [Note] NDB Index Stat: Starting...
2016-03-29 12:39:27 12269 [Note] NDB Index Stat: Wait for server start completed
2016-03-29 12:39:27 12269 [Note] Server hostname (bind-address): '*'; port: 3306
2016-03-29 12:39:27 12269 [Note] IPv6 is available.
2016-03-29 12:39:27 12269 [Note]   - '::' resolves to '::';
2016-03-29 12:39:27 12269 [Note] Server socket created on IP: '::'.
2016-03-29 12:39:27 12269 [Note] Event Scheduler: Loaded 0 events
2016-03-29 12:39:27 12269 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.28-ndb-7.4.10-cluster-gpl'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Cluster Community Server (GPL)
2016-03-29 12:39:27 12269 [Note] NDB Binlog: Check for incidents
2016-03-29 12:39:27 12269 [Note] NDB Binlog: Wait for cluster to start
2016-03-29 12:39:27 12269 [Note] NDB Util: Wait for cluster to start
2016-03-29 12:39:27 12269 [Note] NDB Util: Started
2016-03-29 12:39:27 12269 [Note] NDB Index Stat: Wait for cluster to start
2016-03-29 12:39:27 12269 [Note] NDB Index Stat: Started
2016-03-29 12:39:27 12269 [Note] created index stats Ndb object: reference 0x80070032, name: 'Ndb Index Statistics monitoring'
2016-03-29 12:39:57 12269 [Warning] NDB : Tables not available after 30 seconds.  Consider increasing --ndb-wait-setup value

The most interesting lines in the above, that I can see, are:

2016-03-29 12:38:57 12269 [Note] NDB: NodeID is 50, management server '10.0.0.200:1186'
2016-03-29 12:39:27 12269 [Note] NDB[0]: NodeID: 50, no storage nodes connected (timed out)
2016-03-29 12:39:27 12269 [Warning] NDB: server id set to zero - changes logged to bin log with server id zero will be logged with another server id by slave mysqlds

Manual call to mysqld_safe

[root@MySQL1 mysql]# cat MySQL1.Cluster.err 
160329 12:44:15 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2016-03-29 12:44:16 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-03-29 12:44:16 0 [Note] /usr/sbin/mysqld (mysqld 5.6.28-ndb-7.4.10-cluster-gpl) starting as process 12684 ...
2016-03-29 12:44:16 12684 [Note] Plugin 'FEDERATED' is disabled.
2016-03-29 12:44:16 12684 [Note] InnoDB: Using atomics to ref count buffer pool pages
2016-03-29 12:44:16 12684 [Note] InnoDB: The InnoDB memory heap is disabled
2016-03-29 12:44:16 12684 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-03-29 12:44:16 12684 [Note] InnoDB: Memory barrier is not used
2016-03-29 12:44:16 12684 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-03-29 12:44:16 12684 [Note] InnoDB: Using Linux native AIO
2016-03-29 12:44:16 12684 [Note] InnoDB: Not using CPU crc32 instructions
2016-03-29 12:44:16 12684 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2016-03-29 12:44:16 12684 [Note] InnoDB: Completed initialization of buffer pool
2016-03-29 12:44:16 12684 [Note] InnoDB: Highest supported file format is Barracuda.
2016-03-29 12:44:16 12684 [Note] InnoDB: 128 rollback segment(s) are active.
2016-03-29 12:44:16 12684 [Note] InnoDB: Waiting for purge to start
2016-03-29 12:44:16 12684 [Note] InnoDB: 5.6.28 started; log sequence number 1626433
2016-03-29 12:44:16 12684 [Note] NDB: Changed global value of binlog_format from STATEMENT to MIXED
2016-03-29 12:44:16 12684 [Note] NDB: NodeID is 50, management server '10.0.0.200:1186'
2016-03-29 12:44:17 12684 [Note] NDB[0]: NodeID: 50, all storage nodes connected
2016-03-29 12:44:17 12684 [Warning] NDB: server id set to zero - changes logged to bin log with server id zero will be logged with another server id by slave mysqlds
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Starting...
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Started
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Setting up
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Created schema Ndb object, reference: 0x80040032, name: 'Ndb Binlog schema change monitoring'
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Created injector Ndb object, reference: 0x80050032, name: 'Ndb Binlog data change monitoring'
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Setup completed
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Wait for server start completed
2016-03-29 12:44:17 12684 [Note] NDB Util: Starting...
2016-03-29 12:44:17 12684 [Note] NDB Util: Wait for server start completed
2016-03-29 12:44:17 12684 [Note] NDB Index Stat: Starting...
2016-03-29 12:44:17 12684 [Note] NDB Index Stat: Wait for server start completed
2016-03-29 12:44:17 12684 [Note] Server hostname (bind-address): '*'; port: 3306
2016-03-29 12:44:17 12684 [Note] IPv6 is available.
2016-03-29 12:44:17 12684 [Note]   - '::' resolves to '::';
2016-03-29 12:44:17 12684 [Note] Server socket created on IP: '::'.
2016-03-29 12:44:17 12684 [Note] Event Scheduler: Loaded 0 events
2016-03-29 12:44:17 12684 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.28-ndb-7.4.10-cluster-gpl'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Cluster Community Server (GPL)
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Check for incidents
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Wait for cluster to start
2016-03-29 12:44:17 12684 [Note] NDB Util: Wait for cluster to start
2016-03-29 12:44:17 12684 [Note] NDB Util: Started
2016-03-29 12:44:17 12684 [Note] NDB Index Stat: Wait for cluster to start
2016-03-29 12:44:17 12684 [Note] NDB Index Stat: Started
2016-03-29 12:44:17 12684 [Note] created index stats Ndb object: reference 0x80070032, name: 'Ndb Index Statistics monitoring'
2016-03-29 12:44:17 12684 [Note] NDB Binlog: DISCOVER TABLE Event: REPL$mysql/ndb_schema
2016-03-29 12:44:17 12684 [Note] NDB Binlog: logging ./mysql/ndb_schema (UPDATED,USE_WRITE)
2016-03-29 12:44:17 12684 [Note] NDB Binlog: DISCOVER TABLE Event: REPL$mysql/ndb_apply_status
2016-03-29 12:44:17 12684 [Note] NDB Binlog: logging ./mysql/ndb_apply_status (UPDATED,USE_WRITE)
2016-03-29 12:44:17 12684 [Note] NDB: Cleaning stray tables from database 'ndbinfo'
2016-03-29 12:44:17 12684 [Note] NDB: Cleaning stray tables from database 'performance_schema'
2016-03-29 12:44:17 12684 [Note] NDB: Cleaning stray tables from database 'test'
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Wait for first event
2016-03-29 12:44:17 [NdbApi] INFO     -- Flushing incomplete GCI:s < 212100/0
2016-03-29 12:44:17 [NdbApi] INFO     -- Flushing incomplete GCI:s < 212100/0
2016-03-29 12:44:17 12684 [Note] NDB Binlog: starting log at epoch 212100/0
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Got first event
2016-03-29 12:44:17 12684 [Note] NDB Binlog: ndb tables writable
2016-03-29 12:44:17 12684 [Note] NDB Binlog: Startup and setup completed
2016-03-29 12:44:17 12684 [Note] NDB Schema dist: Data node: 12 reports subscribe from node 51, subscriber bitmask 800000
2016-03-29 12:44:17 12684 [Note] NDB Schema dist: Data node: 11 reports subscribe from node 51, subscriber bitmask 800000
2016-03-29 12:44:17 12684 [Note] NDB Schema dist: Data node: 13 reports subscribe from node 51, subscriber bitmask 800000
2016-03-29 12:44:17 12684 [Note] NDB Schema dist: Data node: 14 reports subscribe from node 51, subscriber bitmask 800000

If you look at the same section in these logs, it's different:

2016-03-29 12:44:16 12684 [Note] NDB: NodeID is 50, management server '10.0.0.200:1186'
2016-03-29 12:44:17 12684 [Note] NDB[0]: NodeID: 50, all storage nodes connected
2016-03-29 12:44:17 12684 [Warning] NDB: server id set to zero - changes logged to bin log with server id zero will be logged with another server id by slave mysqlds

In the latter case, I can also see that the API node has connected to the management node, in the former the management node is waiting for a connection.

Answer 1

Ok. The issue is related to SELinux. I put SELinux in permissive mode with setenforce 0 and restarted MySQL, and it connected fine - this gave it away pretty quickly. So I loaded audit2why and figured it out from that. I ran the following command then setenforce 1 to re-enable SELinux, restarted MySQL and it all works as expected!

The magic command:
setsebool -P mysql_connect_any 1

It looks like what is happening is MySQL will connect to the management node and read the storage nodes, but in trying to connect to the storage nodes (I have mine configured on port 50501, rather than random ports) SELinux steps in and blocks the request.

The final output from ndb_mgm:

ndb_mgm> show
Cluster Configuration
---------------------
[ndbd(NDB)] 4 node(s)
id=11   @10.0.0.220  (mysql-5.6.28 ndb-7.4.10, Nodegroup: 0, *)
id=12   @10.0.0.221  (mysql-5.6.28 ndb-7.4.10, Nodegroup: 0)
id=13   @10.0.0.222  (mysql-5.6.28 ndb-7.4.10, Nodegroup: 1)
id=14   @10.0.0.223  (mysql-5.6.28 ndb-7.4.10, Nodegroup: 1)

[ndb_mgmd(MGM)] 1 node(s)
id=1    @10.0.0.200  (mysql-5.6.28 ndb-7.4.10)

[mysqld(API)]   2 node(s)
id=50   @10.0.0.210  (mysql-5.6.28 ndb-7.4.10)
id=51   @10.0.0.211  (mysql-5.6.28 ndb-7.4.10)