Bug #91737 Please log GTID_EXECUTED when running RESET MASTER.
Submitted: 20 Jul 2018 11:40 Modified: 18 Jun 14:43
Reporter: Jean-François Gagné Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S4 (Feature request)
Version:5.7.22 OS:Any
Assigned to: CPU Architecture:Any
Tags: Contrbution, Contribution

[20 Jul 2018 11:40] Jean-François Gagné
Description:
Hi,

when fixing roque transactions on slaves, one strategy is to run RESET MASTER and to then set GTID_PURGED to a value without the GTIDs of the rogue transaction.  To do that, one would usually get the value of GTID_EXECUTED before RESET MASTER.

When setting GTID_PURGED after RESET MASTER, we have the following lines in the logs:

018-07-20T11:28:52.952169Z 4 [Note] @@GLOBAL.GTID_PURGED was changed from '' to '00016745-1111-1111-1111-111111111111:1-20'.
2018-07-20T11:28:52.952201Z 4 [Note] @@GLOBAL.GTID_EXECUTED was changed from '' to '00016745-1111-1111-1111-111111111111:1-20'.

However, there is no lines for RESET MASTER.

In the steps described above for fixing errant transactions, if the value of GTID_EXECUTED is lost after the RESET MASTER, there is no way to get it back and this becomes a very tricky situation to fix.

Please log the value of GTID_EXECUTED when running RESET MASTER (the same way it is logged when setting GTID_PURGED).

Many thanks,

JFG

How to repeat:
On the master:

master [localhost] {msandbox} ((none)) > show master status\G
*************************** 1. row ***************************
             File: mysql-bin.000003
         Position: 3444
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: 00016745-1111-1111-1111-111111111111:1-20
1 row in set (0.00 sec)

On the slave before rogue transactions:

slave1 [localhost] {msandbox} ((none)) > show master status\G
*************************** 1. row ***************************
             File: mysql-bin.000002
         Position: 154
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: 00016745-1111-1111-1111-111111111111:1-20
1 row in set (0.00 sec)

On the slave after rogue transactions:

slave1 [localhost] {msandbox} ((none)) > show master status\G
*************************** 1. row ***************************
             File: mysql-bin.000002
         Position: 483
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: 00016745-1111-1111-1111-111111111111:1-20,
00016746-2222-2222-2222-222222222222:1-2
1 row in set (0.00 sec)

Fixing rogue transactions on the slave:

slave1 [localhost] {msandbox} ((none)) > reset master;
Query OK, 0 rows affected (0.00 sec)

slave1 [localhost] {msandbox} ((none)) > set global gtid_purged='00016745-1111-1111-1111-111111111111:1-20';
Query OK, 0 rows affected (0.00 sec)

slave1 [localhost] {msandbox} ((none)) > show master status\G
*************************** 1. row ***************************
             File: mysql-bin.000001
         Position: 154
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: 00016745-1111-1111-1111-111111111111:1-20
1 row in set (0.00 sec)

And we only have this in the logs:

2018-07-20T11:28:52.952169Z 4 [Note] @@GLOBAL.GTID_PURGED was changed from '' to '00016745-1111-1111-1111-111111111111:1-20'.
2018-07-20T11:28:52.952201Z 4 [Note] @@GLOBAL.GTID_EXECUTED was changed from '' to '00016745-1111-1111-1111-111111111111:1-20'.

Suggested fix:
Here is a suggestion for the line to add in the logs:

2018-07-20T11:28:40.952201Z 4 [Note] @@GLOBAL.GTID_EXECUTED was changed from '00016745-1111-1111-1111-111111111111:1-20,00016746-2222-2222-2222-222222222222:1-2' to '' by RESET MASTER.
[20 Jul 2018 11:44] Simon Mudd
For completeness I'd log the user making this change which is also good for auditing...

2018-07-20T11:28:40.952201Z 4 [Note] RESET MASTER executed by 'user'@'host': @@GLOBAL.GTID_EXECUTED was changed from '00016745-1111-1111-1111-111111111111:1-20,00016746-2222-2222-2222-222222222222:1-2' to ''.
[24 Jul 2018 13:35] MySQL Verification Team
Hello Jean,

Thank you for the feature request!

regards,
Umesh
[9 May 14:37] J-F Aiven Gagné
More about this contribution in https://github.com/jfg956/mysql-server/pull/5

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: Bug91737_8.3.0_and_8.4.0.patch (application/octet-stream, text), 1.62 KiB.

[9 May 14:40] J-F Aiven Gagné
Some notes about my above contribution extracted from https://github.com/jfg956/mysql-server/pull/5

This PR merges on 8.3.0, and the patch file also applies on 8.4.0. It does not apply on 8.0.37, but it should not be too hard to adapt, let me know if this is needed.

Ideally, in addition to being included in a next Innovation Release, this would be back-ported in 8.4 and 8.0. Some might consider this a breaking change as it modifies logging, but others might consider this a "small enough" change with enough value to be back-ported. In case a change in logging is show-stopper for a back-port, this change could be put behind a "disabled by default" feature-flag / global variable (let me know if you need an updated patch for this).
[18 Jun 14:43] Jean-François Gagné
(update tags: was "Contrbution", now "Contrbution, Contribution")