MySQL Bugs: #71565: Please report full GTID state when stopping / start a slave

Bug #71565	Please report full GTID state when stopping / start a slave
Submitted:	3 Feb 2014 15:14	Modified:	2 Sep 2016 21:33
Reporter:	Simon Mudd (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S4 (Feature request)
Version:	5.6.16, 5.7.3, 5.7.14	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	windmill

Description:
Related to bug#70048

When replication is started or stopped the binlog position is shown but not GTID related information.
If GTID is being used then it's very important for diagnosing errors that the exact state of the slave vs the state known on the master is shown so it's possible to diagnose and resolve the issue. That information is not currently visible.

How to repeat:
Stopping a slave (5.7.3) shows something like:

2014-02-03T15:03:42.395390Z 306985 [Note] Slave I/O thread exiting, read up to log 'binlog.000802', position 651090510

No reference is made to the GTID status of the server. If this is a slave with no local transactions, as is quite frequent, the local state is basically a mirror of the position relative to the master.

On starting replication you see something like:

2014-02-03 16:05:56 2273 [Note] Slave SQL thread initialized, starting replication in log 'binlog.001110' at position 174068573, relay log '../log/relaylog.003307' position: 174068777
2014-02-03 16:05:56 2273 [Note] Slave I/O thread: connected to master 'master_user@masterhost:3306',replication started in log 'binlog.001144' at position 628809229

Again no reference to the GTID state.

Suggested fix:
Please show:

- the MASTER_AUTO_POSITION variable setting,
- on connection to the master, the GTID state of the master (assuming you get this)
- the GTID state of the slave

The SQL thread should also indicate the transaction it has last commited

note: even if there are local changes taking place having these values gives you a much better idea of the state of the system should there be doubts about this later.

I also notice that neither server-id or server-uuid is shown on server startup. These values are vital to replication and any duplicates can cause problems which may not be obvious (2 slaves with the same id), so I would also suggest that on startup mysqld logs the server-id and server-uuid values it is using.

Perhaps for clarification this was intended to be shown when gtid_mode = ON.

So please also log the gtid_mode, which also has 4 possible states (even if 2 are internal states) so that this is explicitly shown, and even if gtid_mode = OFF.

Given the slave "negotiates with the master", if the I/O thread knows the master's gtid_mode then it would be useful to also log that too.

If gtid_mode it is OFF these values are expected to be empty I believe so there should be no harm done in logging them.

This will help with http://dev.mysql.com/worklog/task/?id=7083 which makes no mention of modifying logging to show this information and it would be very helpful here.

Thank you for your feature request.

Contribution submitted via Github - Print GTID info on STOP/START SLAVE (*) Contribution by Daniël van Eeden (Github dveeden, mysql-server/pull/32#issuecomment-159269007): I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: git_patch_51631844.txt (text/plain), 3.76 KiB.

Just to note that in 5.7 using  log_error_verbosity = 2 (as 3 is too noisy) there's no logging of any positions when replication starts or stops so it's completely impossible to see any references to replication master or position at all.

For debugging of issues, analysis of problems etc it's extremely important to record this information (including on server shutdown if applicable) and that's not visible now. Please consider ensuring this information is visible even at this verbosity level.

Posted by developer:
 
Yes Luis, it should be a good idea.

Related: Bug#91741.