MySQL Bugs: #74687: Server consumes a GTID on shutdown

Bug #74687	Server consumes a GTID on shutdown - slaves show missing executed GTID
Submitted:	4 Nov 2014 16:15	Modified:	20 Aug 2019 23:49
Reporter:	Van Stokes	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.6.21 x64	OS:	Any (Ubuntu 14.04.1 x64)
Assigned to:		CPU Architecture:	Any
Tags:	binlog, GTID, replication, shutdown

Description:
MySQL Server: 5.6.21 x64
OS: Ubuntu 12.04 x64 / 14.04 x64
Configuration: 4x Masters in loop (circular) replication

When shutting down a MASTER server, a GTID is consumed by the server being shutdown. The shutdown server shows that the GTID as executed, the replicating MASTER servers show that the GTID is missing/skipped. The GTID does get replicated (i.e in RETRIEVED_GTID_SET) by not executed (but not in EXECUTED_GTID_SET). It is presumed that the missing GTID's are related to a 'shutdown' command not wanting to issued on downstream servers.

Here is a repeatable example:

Server 819c985c-d384-11e3-a621-00259002979a was shutdown twice (using Ubuntu service mysql stop/start and service mysql restart). Notice how the downstream MASTERs EXECUTED_GTID_SET shows missing GTIDs.

RETRIEVED_GTID_SET
69cf02cd-1731-11e3-9a19-002590854928:1-117618841,
708bb615-d393-11e3-a682-003048c3ab22:1-38388307,
819c985c-d384-11e3-a621-00259002979a:1-14105600,
9204e764-d379-11e3-a5d9-0013726268ea:1-50578

EXECUTED_GTID_SET
69cf02cd-1731-11e3-9a19-002590854928:1-117618841,
708bb615-d393-11e3-a682-003048c3ab22:1-38388307,
819c985c-d384-11e3-a621-00259002979a:1-14105506:14105508-14105569:14105571-14105600,
9204e764-d379-11e3-a5d9-0013726268ea:1-50578

How to repeat:
Set up GTID replication using two or more masters.

Restart one master server and notice that the other master server(s) will show a skip in the GTID_EXECUTED.

Suggested fix:
A) Do not consume a GTID on shutdown;
B) or write a blank transaction for the consumed GTID to the BINLOG

Thank you for the bug report. Yes please provide the server configurations.

Server 819c985c-d384-11e3-a621-00259002979a configuration

Attachment: my.cnf (application/octet-stream, text), 8.44 KiB.

File attached.

All master servers are configured the same. The only differences between the servers are these settings:

report-host
server-id
auto-increment-offset
innodb-buffer-pool-instances
innodb-buffer-pool-size

Problem still persists as of 5.6.28.

Hello Van Stokes,

Thank you for the requested details.
My sincere apologies, somehow this report went off the radar for long.
I tried to reproduce the issue with 2 masters with sandbox using 5.6.35 but not seeing the reported issue. Are you able to reproduce this issue with current GA? Please let us know.  I'm shortly joining the steps tried at my end for this and can confirm the same. 

Thanks,
Umesh

5.6.35 test details

Attachment: 74687_5.6.35.results (application/octet-stream, text), 4.95 KiB.

The problem is still occurring as of 5.6.35 and 5.7.17. We have a mix or versions right now because we are migrating to 5.7. Masters are 5.6.35 and slaves are 5.7.17. In a couple of weeks all the masters will be updated to 5.7. Our MySQL servers auto-rebooted this weekend because of an Ubuntu update. One slave skipped a GTID but another slave did NOT skip the GTID.

mysql slave01> SHOW SLAVE STATUS \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: mysql01.econocaribe.com
                  Master_User: rs_1013
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: master-bin.000226
          Read_Master_Log_Pos: 40963586
               Relay_Log_File: slave-relay-bin.000110
                Relay_Log_Pos: 40940756
        Relay_Master_Log_File: master-bin.000226
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 40940541
              Relay_Log_Space: 40964216
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 0
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 1001
                  Master_UUID: 819c985c-d384-11e3-a621-00259002979a
             Master_Info_File: /d01/mysql/data/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
           Master_Retry_Count: 86400
                  Master_Bind: 
      Last_IO_Error_Timestamp: 
     Last_SQL_Error_Timestamp: 
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
           Retrieved_Gtid_Set:
278bfda1-b93d-11e4-801b-14feb5d284bc:4324329-7160763,
69cf02cd-1731-11e3-9a19-002590854928:2785759-4855727,
708bb615-d393-11e3-a682-003048c3ab22:3816694-12627317,
819c985c-d384-11e3-a621-00259002979a:647526-1129135
            Executed_Gtid_Set:
278bfda1-b93d-11e4-801b-14feb5d284bc:1-7160763,
69cf02cd-1731-11e3-9a19-002590854928:1-4709632:4709634-4855727,
708bb615-d393-11e3-a682-003048c3ab22:1-12627317,
819c985c-d384-11e3-a621-00259002979a:1-970639:970641-1129135
                Auto_Position: 1
         Replicate_Rewrite_DB: 
                 Channel_Name: 
           Master_TLS_Version: 
1 row in set (0.00 sec)

Note Executed_Gtid_Set: 69cf02cd-1731-11e3-9a19-002590854928:1-4709632:4709634-4855727,
Yet Retrieved_Gtid_Set: 69cf02cd-1731-11e3-9a19-002590854928:2785759-4855727,

However, SLAVE02 does NOT show the GTID skip in sequence!

mysql slave02> SHOW SLAVE STATUS \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: mysql01.econocaribe.com
                  Master_User: rs_7001
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: master-bin.000226
          Read_Master_Log_Pos: 44111061
               Relay_Log_File: slave-relay-bin.000672
                Relay_Log_Pos: 44110814
        Relay_Master_Log_File: master-bin.000226
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 44110599
              Relay_Log_Space: 44111691
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 0
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 1001
                  Master_UUID: 819c985c-d384-11e3-a621-00259002979a
             Master_Info_File: /d01/mysql/data/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
           Master_Retry_Count: 86400
                  Master_Bind: 
      Last_IO_Error_Timestamp: 
     Last_SQL_Error_Timestamp: 
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
           Retrieved_Gtid_Set:
278bfda1-b93d-11e4-801b-14feb5d284bc:6453343-7160763,
69cf02cd-1731-11e3-9a19-002590854928:4275556-4858336,
708bb615-d393-11e3-a682-003048c3ab22:12190266-12627318,
819c985c-d384-11e3-a621-00259002979a:970627-1129167
            Executed_Gtid_Set:
278bfda1-b93d-11e4-801b-14feb5d284bc:1-7160763,
5fe8a377-dd7c-11e6-bdfe-003048c680d0:1-6,
69cf02cd-1731-11e3-9a19-002590854928:1-4858336,
708bb615-d393-11e3-a682-003048c3ab22:1-12627318,
819c985c-d384-11e3-a621-00259002979a:1-1129167
                Auto_Position: 1
         Replicate_Rewrite_DB: 
                 Channel_Name: 
           Master_TLS_Version: 
1 row in set (0.00 sec)

I believe the problem occurs when the MySQL service is being shutdown when the OS is shutting down. Perhaps the MySQL process is killed by the OS (Ubuntu) because MySQL is taking too long to shutdown because the transaction is taking to long to be applied. We run PARALLEL slave threads and I think this is what is happening:

01) Slave thread 1 begins executing GTID 69cf02cd-1731-11e3-9a19-002590854928:4709632
02) Slave thread 2 begins executing GTID 69cf02cd-1731-11e3-9a19-002590854928:4709633 (the skipped one)
03) Slave thread 1 finishes executing GTID 69cf02cd-1731-11e3-9a19-002590854928:4709632
04) Slave thread 1 begins executing GTID 69cf02cd-1731-11e3-9a19-002590854928:4709634
05) OS shutdown begins (shutdown -r now)
06) Slave thread 1 finishes executing GTID 69cf02cd-1731-11e3-9a19-002590854928:4709634 (last recorded GTID)
07) OS shutdown timer expires, MySQL service forcibly terminated
08) OS restarts
09) MySQL service started
10) Slaves threads start from last recorded GTID 69cf02cd-1731-11e3-9a19-002590854928:4709634 thus skipping GTID 69cf02cd-1731-11e3-9a19-002590854928:4709633.

Could you please try latest releases, it was not able to be repeated with earliest version.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".