Bug #84618 Wrong CommunicationOpened event in the NDB cluster log
Submitted: 23 Jan 2017 14:47 Modified: 31 Jan 2017 11:41
Reporter: Michael Prokopiv Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Cluster: Cluster (NDB) storage engine Severity:S3 (Non-critical)
Version:mysql-5.6.28 ndb-7.4.10 OS:Oracle Linux (Oracle Linux Server release 6.3)
Assigned to: MySQL Verification Team CPU Architecture:Any

[23 Jan 2017 14:47] Michael Prokopiv 
Description:
In a free seconds, after the API client finished work and closed communictaion to cluster (CommunicationClosed and Disconnected events):
Communication to Node 30 closed ()
Node 30 Disconnected
happens wrong event about the communication with client is opened,  (CommunicationOpened event):
Communication to Node 30 opened

Grepped log example:
2017-01-21 22:00:01 [MgmtSrvr] INFO     -- Node 30: BSAN
2017-01-21 22:00:01 [MgmtSrvr] INFO     -- Node 3: Node 30 Connected
2017-01-21 22:00:02 [MgmtSrvr] INFO     -- Node 3: Node 30: API mysql-5.6.25 ndb-7.4.7
2017-01-22 02:45:31 [MgmtSrvr] INFO     -- Node 3: Communication to Node 30 closed
2017-01-22 02:45:31 [MgmtSrvr] ALERT    -- Node 3: Node 30 Disconnected
2017-01-22 02:45:34 [MgmtSrvr] INFO     -- Node 3: Communication to Node 30 opened
2017-01-22 22:00:01 [MgmtSrvr] INFO     -- Node 30: BSAN
2017-01-22 22:00:02 [MgmtSrvr] INFO     -- Node 3: Node 30 Connected
2017-01-22 22:00:02 [MgmtSrvr] INFO     -- Node 3: Node 30: API mysql-5.6.25 ndb-7.4.7
2017-01-23 02:46:37 [MgmtSrvr] INFO     -- Node 3: Communication to Node 30 closed
2017-01-23 02:46:37 [MgmtSrvr] ALERT    -- Node 3: Node 30 Disconnected
2017-01-23 02:46:40 [MgmtSrvr] INFO     -- Node 3: Communication to Node 30 opened
2017-01-17 22:00:01 [MgmtSrvr] INFO     -- Node 30: BSAN
2017-01-17 22:00:02 [MgmtSrvr] INFO     -- Node 3: Node 30 Connected
2017-01-17 22:00:02 [MgmtSrvr] INFO     -- Node 3: Node 30: API mysql-5.6.25 ndb-7.4.7
2017-01-18 02:46:06 [MgmtSrvr] INFO     -- Node 3: Communication to Node 30 closed
2017-01-18 02:46:06 [MgmtSrvr] ALERT    -- Node 3: Node 30 Disconnected
2017-01-18 02:46:09 [MgmtSrvr] INFO     -- Node 3: Communication to Node 30 opened
2017-01-18 22:00:01 [MgmtSrvr] INFO     -- Node 30: BSAN
2017-01-18 22:00:02 [MgmtSrvr] INFO     -- Node 3: Node 30 Connected
2017-01-18 22:00:02 [MgmtSrvr] INFO     -- Node 3: Node 30: API mysql-5.6.25 ndb-7.4.7
2017-01-19 02:49:37 [MgmtSrvr] INFO     -- Node 3: Communication to Node 30 closed
2017-01-19 02:49:37 [MgmtSrvr] ALERT    -- Node 3: Node 30 Disconnected
2017-01-19 02:49:40 [MgmtSrvr] INFO     -- Node 3: Communication to Node 30 opened

example with MySQL server:
2017-01-23 17:45:37 [MgmtSrvr] INFO     -- Node 3: mysqld --server-id=0
2017-01-23 17:45:37 [MgmtSrvr] INFO     -- Node 2: Node 3 Connected
2017-01-23 17:45:38 [MgmtSrvr] INFO     -- Node 2: Node 3: API mysql-5.6.31 ndb-7.4.12
2017-01-23 17:46:01 [MgmtSrvr] ALERT    -- Node 2: Node 3 Disconnected
2017-01-23 17:46:01 [MgmtSrvr] INFO     -- Node 2: Communication to Node 3 closed
2017-01-23 17:46:05 [MgmtSrvr] INFO     -- Node 2: Communication to Node 3 opened

How to repeat:
Start any NDB API client and stop

Suggested fix:
Correct event trigger conditions
[31 Jan 2017 5:07] MySQL Verification Team 
Hi,

I can't reproduce this? Can you please let me know exactly what you did? How your client connect/disconnect code looks like? This looks like bug in your clients code to me as when I do a simple connect, get some data, disconnect, I don't get this ghost "communication opened" you are getting.

Thanks
Bogdan
[31 Jan 2017 11:41] Michael Prokopiv 
Hi, Bogdan!

Just start and stop your MySQL server node:
mysqld_safe&
mysqladmin shutdown

and in the cluster log (/var/log/ndb_1_cluster.log) you'll see:
2017-01-23 17:45:37 [MgmtSrvr] INFO -- Node 3: mysqld --server-id=0
2017-01-23 17:45:37 [MgmtSrvr] INFO -- Node 2: Node 3 Connected
2017-01-23 17:45:38 [MgmtSrvr] INFO -- Node 2: Node 3: API
mysql-5.6.31 ndb-7.4.12
2017-01-23 17:46:01 [MgmtSrvr] ALERT -- Node 2: Node 3 Disconnected
2017-01-23 17:46:01 [MgmtSrvr] INFO -- Node 2: Communication to Node
3 closed
2017-01-23 17:46:05 [MgmtSrvr] INFO -- Node 2: Communication to Node
3 opened

so, the issue is the last record - "Communication to Node
3 opened"

BR, Michael