Bug #105234 START SLAVE UNTIL SQL_AFTER_GTIDS Does not Stop When Past GTID
Submitted: 15 Oct 2021 0:58 Modified: 27 Oct 2021 19:53
Reporter: Jervin Real Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:8.0.26 OS:Any
Assigned to: CPU Architecture:Any

[15 Oct 2021 0:58] Jervin Real
Description:
When using START SLAVE UNTIL with GTIDS, specifying a GTID set that has already been executed does not prevent the replication from stopping.

How to repeat:
slave1 [localhost:21628] {msandbox} ((none)) > show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for source to send event
                  Master_Host: 127.0.0.1
                  Master_User: rsandbox
                  Master_Port: 21627
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 8328
               Relay_Log_File: mysql-relay.000003
                Relay_Log_Pos: 458
        Relay_Master_Log_File: mysql-bin.000001
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
..,
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 8328
              Relay_Log_Space: 9050
              Until_Condition: SQL_AFTER_GTIDS
...
        Seconds_Behind_Master: 0
...
             Master_Server_Id: 21627
                  Master_UUID: 00021627-1111-1111-1111-111111111111
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Replica has read all relay log; waiting for more updates
...
           Retrieved_Gtid_Set: 00021627-1111-1111-1111-111111111111:1-33
            Executed_Gtid_Set: 00021627-1111-1111-1111-111111111111:1-33
                Auto_Position: 1
...
1 row in set, 1 warning (0.00 sec)

slave1 [localhost:21628] {msandbox} ((none)) > stop slave; start slave until SQL_BEFORE_GTIDS = '00020135-1111-1111-1111-111111111111:10';
Query OK, 0 rows affected, 1 warning (0.01 sec)

Query OK, 0 rows affected, 1 warning (0.00 sec)

slave1 [localhost:21628] {msandbox} ((none)) > show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for source to send event
                  Master_Host: 127.0.0.1
                  Master_User: rsandbox
                  Master_Port: 21627
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 8328
               Relay_Log_File: mysql-relay.000004
                Relay_Log_Pos: 458
        Relay_Master_Log_File: mysql-bin.000001
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
...
          Exec_Master_Log_Pos: 8328
              Relay_Log_Space: 965
              Until_Condition: SQL_BEFORE_GTIDS
...
        Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
...
             Master_Server_Id: 21627
                  Master_UUID: 00021627-1111-1111-1111-111111111111
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Replica has read all relay log; waiting for more updates
...
           Retrieved_Gtid_Set: 00021627-1111-1111-1111-111111111111:1-33
            Executed_Gtid_Set: 00021627-1111-1111-1111-111111111111:1-33
...
1 row in set, 1 warning (0.00 sec)

When not using GTID, this is not the case.

slave1 [localhost:21628] {msandbox} ((none)) > show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for source to send event
                  Master_Host: 127.0.0.1
                  Master_User: rsandbox
                  Master_Port: 21627
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 8326
               Relay_Log_File: mysql-relay.000002
                Relay_Log_Pos: 8541
        Relay_Master_Log_File: mysql-bin.000001
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
...
          Exec_Master_Log_Pos: 8326
              Relay_Log_Space: 8746
              Until_Condition: None
...
        Seconds_Behind_Master: 0
...
             Master_Server_Id: 100
                  Master_UUID: 00021627-1111-1111-1111-111111111111
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Replica has read all relay log; waiting for more updates
           Master_Retry_Count: 86400
...
1 row in set, 1 warning (0.00 sec)

slave1 [localhost:21628] {msandbox} ((none)) > stop slave; start slave until master_log_file='mysql-bin.000001', master_log_pos=8000;
Query OK, 0 rows affected, 2 warnings (0.00 sec)

Query OK, 0 rows affected, 4 warnings (0.00 sec)

slave1 [localhost:21628] {msandbox} ((none)) > show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for source to send event
                  Master_Host: 127.0.0.1
                  Master_User: rsandbox
                  Master_Port: 21627
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 8326
               Relay_Log_File: mysql-relay.000002
                Relay_Log_Pos: 8541
        Relay_Master_Log_File: mysql-bin.000001
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
...
          Exec_Master_Log_Pos: 8326
              Relay_Log_Space: 9119
              Until_Condition: Master
               Until_Log_File: mysql-bin.000001
                Until_Log_Pos: 8000
...
             Master_Server_Id: 100
                  Master_UUID: 00021627-1111-1111-1111-111111111111
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
...
1 row in set, 1 warning (0.00 sec)

Suggested fix:
Replication should not run if all conditions in the UNTIL clause are met.
[25 Oct 2021 11:42] MySQL Verification Team
Hi Jervin,

I'm having issue reproducing this.

What's the content of your master/my.sandbox.cnf and node#/my.sandbox.cnf ?

thanks
[25 Oct 2021 21:18] Jervin Real
Hi,

Configs are basically defaults generated by dbdeployer.

This master/my.sandbox.cnf

[mysql]
prompt='master [\h:21627] {\u} (\d) > '
#

[client]
user               = msandbox
password           = msandbox
port               = 21627
socket             = /tmp/mysql_sandbox21627.sock

[mysqld]
user               = jervin
port               = 21627
socket             = /tmp/mysql_sandbox21627.sock
basedir            = /home/jervin/opt/mysql/8.0.26
datadir            = /home/jervin/sandboxes/rsandbox_8_0_26/master/data
tmpdir             = /home/jervin/sandboxes/rsandbox_8_0_26/master/tmp
pid-file           = /home/jervin/sandboxes/rsandbox_8_0_26/master/data/mysql_sandbox21627.pid
bind-address       = 127.0.0.1
report-host = node-1
report-port=21627
log-error=/home/jervin/sandboxes/rsandbox_8_0_26/master/data/msandbox.err
server-id=100

# basic replication options
relay-log-index=mysql-relay
relay-log=mysql-relay
log-bin=mysql-bin

mysqlx-port=31627
mysqlx-socket=/tmp/mysqlx-31627.sock

And this is one of the replicas:

[mysql]
prompt='slave1 [\h:21628] {\u} (\d) > '
#

[client]
user               = msandbox
password           = msandbox
port               = 21628
socket             = /tmp/mysql_sandbox21628.sock

[mysqld]
user               = jervin
port               = 21628
socket             = /tmp/mysql_sandbox21628.sock
basedir            = /home/jervin/opt/mysql/8.0.26
datadir            = /home/jervin/sandboxes/rsandbox_8_0_26/node1/data
tmpdir             = /home/jervin/sandboxes/rsandbox_8_0_26/node1/tmp
pid-file           = /home/jervin/sandboxes/rsandbox_8_0_26/node1/data/mysql_sandbox21628.pid
bind-address       = 127.0.0.1
report-host = node-2
report-port=21628
log-error=/home/jervin/sandboxes/rsandbox_8_0_26/node1/data/msandbox.err
server-id=200

# basic replication options
relay-log-index=mysql-relay
relay-log=mysql-relay
log-bin=mysql-bin

mysqlx-port=31628
mysqlx-socket=/tmp/mysqlx-31628.sock
[27 Oct 2021 19:53] MySQL Verification Team
Thanks for the report
[19 Jan 2022 2:01] MySQL Verification Team
Hi,

One thing my colleague from dev team noticed that we would like to doublecheck:

In the 'How to repeat' steps, looks like you used a different server-uuid in start 'slave until SQL_BEFORE_GTIDS' command.

slave1 [localhost:21628] {msandbox} ((none)) > show slave status \G
*************************** 1. row ***************************
...
             Master_Server_Id: 21627
                  Master_UUID: **00021627**-1111-1111-1111-111111111111
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Replica has read all relay log; waiting for
more updates
...
           Retrieved_Gtid_Set: **00021627**-1111-1111-1111-111111111111:1-33
            Executed_Gtid_Set: **00021627**-1111-1111-1111-111111111111:1-33
                Auto_Position: 1
...
1 row in set, 1 warning (0.00 sec)

slave1 [localhost:21628] {msandbox} ((none)) > stop slave; start slave until
SQL_BEFORE_GTIDS = '**00020135**-1111-1111-1111-111111111111:10';

Could you please confirm the difference in server-uuid is intentional or a mistake? 

Is this mistake copy/pasting from different reproduction turns or something else

Thanks