Bug #70296 replication errors are reported inconsistently
Submitted: 11 Sep 2013 9:04 Modified: 11 Sep 2013 11:47
Reporter: Simon Mudd (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.6.13 OS:Any
Assigned to: CPU Architecture:Any

[11 Sep 2013 9:04] Simon Mudd
Description:
A recent master server upgrade triggered these errors on a slave:

2013-09-11 10:31:08 59919 [Note] Slave: received end packet from server, apparent master shutdown:
2013-09-11 10:31:08 59919 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'binlog.000819' at position 650414825
2013-09-11 10:31:08 59919 [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.
2013-09-11 10:31:08 59919 [ERROR] Slave I/O: error reconnecting to master 'replication_user@myserver.example.com:3306' - retry-time: 60  retries: 1, Error_code: 2003
2013-09-11 10:32:08 59919 [Note] Slave: connected to master 'replication_user@myserver.example.com:3306',replication resumed in log 'binlog.000819' at position 650414825 

Note: the inconsistent logging from the Slave I/O thread.

How to repeat:
setup a master/slave chain using 5.6.13.
stop the master and look at the logs on the slave.

Suggested fix:
- Adjust so the slave I/O thread prefixes its messages in a consistent way (makes processing log files easier).
- Add the master hostname to the logging of the shutdown.
- Consider adding some mechanism so the master can tell the slave that it is deliberately shutting down, and thus the slave should disconnect, rather than the slave just assuming that is what has happened. It then makes it possible to detect a deliberate shutdown of the master from an expected failure.

for example:

2013-09-11 10:31:08 59919 [Note] Slave I/O thread: received end packet from server, unexpected shutdown of master mymaster.example.com:3306
or
2013-09-11 10:31:08 59919 [Note] Slave I/O thread: disconnecting as master mymaster.example.com:3306 is shutting down.

then

2013-09-11 10:31:08 59919 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'binlog.000819' at position 650414825
2013-09-11 10:31:08 59919 [Warning] Slave I/O thread: 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.
2013-09-11 10:31:08 59919 [ERROR] Slave I/O thread: error reconnecting to master 'replication_user@myserver.example.com:3306' - retry-time: 60  retries: 1, Error_code: 2003
2013-09-11 10:32:08 59919 [Note] Slave I/O thread: connected to master 'replication_user@myserver.example.com:3306',replication resumed in log 'binlog.000819' at position 650414825

perhaps these are minor changes but improving the consistency of the logging makes it much easier to parse and process the logs than is currently possible.
[11 Sep 2013 11:47] MySQL Verification Team
Hello Simon,

Thank you for the bug report.
Verified as described.

Thanks,
Umesh