| Bug #75261 | mysql logging around a slave disconnection sometimes is not clear | ||
|---|---|---|---|
| Submitted: | 18 Dec 2014 13:07 | Modified: | 17 Jan 2015 10:10 |
| Reporter: | Simon Mudd (OCA) | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S3 (Non-critical) |
| Version: | 5.6.15 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | i/o thread, logging, replication | ||
[18 Dec 2014 13:07]
Simon Mudd
[31 Dec 2014 20:08]
MySQL Verification Team
The io thread reconnect messages are a known noisy behavior we have other request on this as well: Bug #72629 Slave security warning printed too often On the vague is the io thread connected or not, i'm still investigating, everytime i see reconnecting to retry in tests, slave status io running shows : connecting (on 5.6.22) 2014-12-22 22:04:27 19371 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:3306' - retry-time: 60 retries: 1, Error_code: 2003 Slave_IO_Running: Connecting Will investigate some more.
[16 Jan 2015 18:42]
MySQL Verification Team
The issue is this: Normal IO disconnection/Reconnection results in: (omitting the start slave repository spam) 2014-12-22 22:04:27 19371 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'binlog-bin.000030' at position 120 2014-12-22 22:04:27 19371 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:3306' - retry-time: 60 retries: 1, Error_code: 2003 At this point slave status will show io thread status of "connecting"..., once it does reconnect: 2014-12-22 22:13:27 19371 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:3306' - retry-time: 60 retries: 10, Error_code: 2003 2014-12-22 22:14:27 19371 [Note] Slave: connected to master 'root@127.0.0.1:3306',replication resumed in log 'binlog-bin.000030' at position 120 Now it's possible to reproduce the lack of the slave io thread connected ack if one kills the binlog thread on the master: 2015-01-16 13:22:34 1862 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'shannons-binlog-bin.000006' at position 120 2015-01-16 13:22:34 1862 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information. ^ the above is all that will be logged when the master recreates the binlog dump thread. To reproduce, setup a slave, kill the master binlog dump thread while tailing the slave error log. Suppose this can happen with brief network events as well. Either way the above doesn't seem correct, if we're reconnecting it should log when it has reconnected as the original filer states.
[16 Jan 2015 18:50]
MySQL Verification Team
Verified as described see test in previous comment to reproduce io reconnection confusion with no ack there was actually a successful reconnect.
[17 Jan 2015 10:10]
Simon Mudd
While usually I stop a slave connection cleanly on a slave (STOP SLAVE) sometimes I have to kill the connections on the master (KILL <slave_thread_id_on_master>), so it may not just be network "drops" that cause this, but deliberate cleanups by the DBA, or even maintenance on the master, or for example a vip being taken down and brought up again. Under good circumstances once a slave is working this type of logging is infrequent, but if these situations occur it's really good to see the (change in) state of the I/O thread in the slave's log. So the logging should IMO show the correct connection being made, when disconnections happen, and periodically if retrying to connect indicate the connection is down. (if the logging clearly shows the i/o thread is not connected that's less important of course but it's good to know there's a continuing connection problem.)
