search

vitessio / vitess

Vitess is a database clustering system for horizontal scaling of MySQL.
http://vitess.io
Apache License 2.0
18.46k stars 2.09k forks source link

Bug Report: PITR not restoring to the desired GTID/state #13027

Open ankitthakwani opened 1 year ago

ankitthakwani commented 1 year ago

Overview of the Issue

PITR not working as described in https://vitess.io/docs/16.0/reference/features/recovery/

After restoring the backup, the state is not getting rolled forward as described

Reproduction Steps

Steps to reproduce

  1. Create a single shard keyspace - "pitr" and start correspoding vttablets and mysql

  2. Take backup ( I am using compressed and streamed xtrabackup and saving it on S3), , lets call is DS0(Database state 0) vtctlclient --server 127.0.0.1:15999 BackupShard pitr/0

  3. Insert some data in the primary instance to increase GTID counter, lets call is DS1

  4. Make a note of the current timestamp

  5. Insert some data in the primary instance to increase GTID counter, lets call is DS2

  6. As per the documents in https://vitess.io/docs/16.0/reference/features/recovery/, create a new snapshot keyspace - pitr_restored, use the timestamp from Point 4

vtctldclient --server 127.0.0.1:15999 CreateKeyspace --type=SNAPSHOT --base-keyspace=pitr --snapshot-timestamp=2023-05-05T09:33:00Z pitr_restored

  1. Start the corresponding vttablet and mysql for pitr_restored keyspace

  2. Expected database restore state to be DS1 but it is DS0 which means Binary log apply is not working as expected.

Following are logs from the steps above on my system, demonstrating the issue

[vitess@workernode-upi-v1-10011441 ~]$ vtctldclient --server 127.0.0.1:15999 GetTablets | grep pitr
dc1-0000000900 pitr 0 primary 127.0.0.1:15900 127.0.0.1:17900 [] 2023-05-05T07:27:47Z
dc1-0000000902 pitr 0 rdonly 127.0.0.1:15902 127.0.0.1:17902 [] <null>
dc1-0000000903 pitr 0 replica 127.0.0.1:15903 127.0.0.1:17903 [] <null>

[vitess@workernode-upi-v1-10011441 ~]$ vtctlclient --server 127.0.0.1:15999 ListBackups pitr/0
[vitess@workernode-upi-v1-10011441 ~]$ 

[vitess@workernode-upi-v1-10011441 ~]$ mysql -uvt_dba  -S ${VTDATAROOT}/vt_0000000900/mysql.sock vt_pitr
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 107925
Server version: 8.0.29-21 Percona Server (GPL), Release 21, Revision c59f87d2854

Copyright (c) 2009-2022 Percona LLC and/or its affiliates
Copyright (c) 2000, 2022, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SET time_zone = '+00:00';
Query OK, 0 rows affected (0.00 sec)

mysql> 
mysql> DROP TABLE IF EXISTS txnInfo;
Query OK, 0 rows affected (0.07 sec)

mysql> 
mysql> CREATE TABLE `txnInfo` (
    ->   `id` bigint NOT NULL AUTO_INCREMENT,
    ->   `created` timestamp(6) DEFAULT NULL,
    ->   PRIMARY KEY (`id`)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci;
Query OK, 0 rows affected (0.18 sec)

mysql> 
mysql> 
mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: vt-0000000900-bin.000003
         Position: 21534
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-142,
f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
1 row in set (0.00 sec)

mysql> -- TAKE DB BACKUP

mysql> \! vtctlclient --server 127.0.0.1:15999 BackupShard pitr/0

mysql> \! vtctlclient --server 127.0.0.1:15999 ListBackups pitr/0
2023-05-08.100706.dc1-0000000903

mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: vt-0000000900-bin.000003
         Position: 21534
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-142,
f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
1 row in set (0.00 sec)

mysql> -- INSERT SOME DATA

mysql> 
mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.03 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.02 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.07 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.02 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.01 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.00 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.05 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.05 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.05 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.03 sec)

mysql> 
mysql> SELECT * FROM txnInfo;
+----+----------------------------+
| id | created                    |
+----+----------------------------+
|  1 | 2023-05-08 10:07:26.649175 |
|  2 | 2023-05-08 10:07:26.683593 |
|  3 | 2023-05-08 10:07:26.700026 |
|  4 | 2023-05-08 10:07:26.767802 |
|  5 | 2023-05-08 10:07:26.792034 |
|  6 | 2023-05-08 10:07:26.804216 |
|  7 | 2023-05-08 10:07:26.807450 |
|  8 | 2023-05-08 10:07:26.862235 |
|  9 | 2023-05-08 10:07:26.910654 |
| 10 | 2023-05-08 10:07:26.967557 |
+----+----------------------------+
10 rows in set (0.00 sec)

mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: vt-0000000900-bin.000003
         Position: 24624
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-152,
f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
1 row in set (0.00 sec)

mysql> SELECT NOW();
+---------------------+
| NOW()               |
+---------------------+
| 2023-05-08 10:08:17 |
+---------------------+
1 row in set (0.00 sec)

mysql> -- USE ABOVE TIMESTAMP FOR PITR Keyspace

mysql> \! vtctldclient --server 127.0.0.1:15999 CreateKeyspace --type=SNAPSHOT --base-keyspace=pitr --snapshot-timestamp=2023-05-08T10:08:17Z pitr_restored
Successfully created keyspace pitr_restored. Result:
{
  "name": "pitr_restored",
  "keyspace": {
    "served_froms": [],
    "keyspace_type": 1,
    "base_keyspace": "pitr",
    "snapshot_time": {
      "seconds": "1683540497",
      "nanoseconds": 0
    },
    "durability_policy": "none"
  }
}
mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: vt-0000000900-bin.000003
         Position: 24624
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-152,
f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
1 row in set (0.01 sec)

mysql> -- INSERT MORE DATA TO INCREMENT GTID COUNTER TO MOVE AHEAD OF PITR GTID

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.03 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.05 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.00 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.06 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.05 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.02 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.05 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.04 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.05 sec)

mysql> INSERT INTO txnInfo SET created=NOW(6);
Query OK, 1 row affected (0.03 sec)

mysql> 
mysql> SELECT * FROM txnInfo;
+----+----------------------------+
| id | created                    |
+----+----------------------------+
|  1 | 2023-05-08 10:07:26.649175 |
|  2 | 2023-05-08 10:07:26.683593 |
|  3 | 2023-05-08 10:07:26.700026 |
|  4 | 2023-05-08 10:07:26.767802 |
|  5 | 2023-05-08 10:07:26.792034 |
|  6 | 2023-05-08 10:07:26.804216 |
|  7 | 2023-05-08 10:07:26.807450 |
|  8 | 2023-05-08 10:07:26.862235 |
|  9 | 2023-05-08 10:07:26.910654 |
| 10 | 2023-05-08 10:07:26.967557 |
| 11 | 2023-05-08 10:09:45.897923 |
| 12 | 2023-05-08 10:09:45.934515 |
| 13 | 2023-05-08 10:09:45.977705 |
| 14 | 2023-05-08 10:09:45.980739 |
| 15 | 2023-05-08 10:09:46.043767 |
| 16 | 2023-05-08 10:09:46.093865 |
| 17 | 2023-05-08 10:09:46.113253 |
| 18 | 2023-05-08 10:09:46.160734 |
| 19 | 2023-05-08 10:09:46.205015 |
| 20 | 2023-05-08 10:09:46.255032 |
+----+----------------------------+
20 rows in set (0.00 sec)

mysql> 
mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: vt-0000000900-bin.000003
         Position: 27714
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-162,
f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
1 row in set (0.00 sec)

Start the mysql and vttablet of pitr_restore keyspace, following are the logs

I0508 15:42:36.876157   52987 mysqld.go:431] Mysqld.Start(1683540756) stdout: 2023-05-08T10:12:36.875016Z mysqld_safe Logging to '/data/vitess/vtdataroot/vt_0000000909/error.log'.
I0508 15:42:36.951262   52987 mysqld.go:431] Mysqld.Start(1683540756) stdout: 2023-05-08T10:12:36.950036Z mysqld_safe Starting mysqld daemon with databases from /data/vitess/vtdataroot/vt_0000000909/data
I0508 15:42:39.189429   52987 backup.go:391] Restore: removing state file
I0508 15:42:39.189527   52987 backup.go:397] Restore: complete
I0508 15:42:39.189608   52987 restore.go:223] Restore: got a restore manifest: &{xtrabackup c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-142,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 <nil> <nil> false 2023-05-08T10:07:06Z 2023-05-08T10:07:11Z f7393495-eb11-11ed-8cf4-3c5731cc0ff6 dc1-0000000903 pitr 0}, err=<nil>, waitForBackupInterval=0s
I0508 15:42:39.189635   52987 restore.go:243] Restore: pos=MySQL56/c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-142,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
I0508 15:42:39.189695   52987 restore.go:247] Restore: Restoring to time seconds:1683540497 from binlog
I0508 15:42:39.189931   52987 engine.go:157] VStreamer: opening
I0508 15:42:39.191070   52987 uvstreamer.go:405] Stream() called
I0508 15:42:39.192159   52987 vstreamer.go:172] Starting Stream() with startPos MySQL56/c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-142,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
I0508 15:42:39.192186   52987 engine.go:227] Schema Engine: opening
I0508 15:42:39.193978   52987 binlog_connection.go:80] new binlog connection: serverID=30698689
I0508 15:42:39.193995   52987 binlog_connection.go:126] sending binlog dump command: startPos=c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-142,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1, serverID=30698689
I0508 15:42:39.202398   52987 vstreamer.go:982] stream (at source tablet) ended @ c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-153,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
I0508 15:42:39.202422   52987 binlog_connection.go:290] closing binlog socket to unblock reads
I0508 15:42:39.202481   52987 uvstreamer.go:229] uvstreamer context is being cancelled
I0508 15:42:39.202484   52987 binlog_connection.go:298] waiting for binlog dump thread to end
I0508 15:42:39.202514   52987 binlog_connection.go:304] closing binlog MySQL client with serverID 30698689. Will recycle ID.
I0508 15:42:39.202535   52987 engine.go:191] VStreamer: closed
I0508 15:42:39.202567   52987 pool.go:159] connpool - started execution of Close
I0508 15:42:39.202572   52987 pool.go:161] connpool - found the pool
I0508 15:42:39.202576   52987 pool.go:168] connpool - calling close on the pool
I0508 15:42:39.202631   52987 pool.go:170] connpool - acquiring lock
I0508 15:42:39.202640   52987 pool.go:172] connpool - acquired lock
I0508 15:42:39.202647   52987 pool.go:175] connpool - closing dbaPool
I0508 15:42:39.202655   52987 pool.go:177] connpool - finished execution of Close
I0508 15:42:39.202664   52987 engine.go:283] Schema Engine: closed
I0508 15:42:39.202704   52987 restore.go:332] going to restore upto the GTID - MySQL56/c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-153,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
I0508 15:42:39.203553   52987 query.go:81] exec STOP SLAVE FOR CHANNEL '' 
I0508 15:42:39.203935   52987 query.go:81] exec STOP SLAVE IO_THREAD FOR CHANNEL ''
I0508 15:42:39.204094   52987 query.go:81] exec CHANGE MASTER TO MASTER_HOST='127.0.0.1', MASTER_PORT=17900, MASTER_USER='vt_repl_pitr', MASTER_PASSWORD='Password@123', MASTER_AUTO_POSITION=1;
I0508 15:42:39.304614   52987 query.go:81] exec START SLAVE UNTIL SQL_BEFORE_GTIDS = 'f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1'
I0508 15:42:39.315523   52987 restore.go:486] Waiting for position to reach%!(EXTRA string=f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1)

GTID when backup was taken --> c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-142,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
Expected GTID after PITR  --> c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-152,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
Actual GTID during PITR    --> f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1

In above it is clear to see that it is stuck waiting for f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 which is not correct.

Binary Version

vtgate --version
Version: 16.0.0 (Git revision bb768df0008fc09f7e6868a4fa571c32cc1cb526 branch 'HEAD') built on Tue Feb 28 16:28:18 UTC 2023 by runner@fv-az397-717 using go1.20.1 linux/amd64

Operating System and Environment details

[vitess@workernode-upi-v1-10011441 tmp]$ cat /etc/os-release
NAME="CentOS Linux"
VERSION="7 (Core)"
ID="centos"
ID_LIKE="rhel fedora"
VERSION_ID="7"
PRETTY_NAME="CentOS Linux 7 (Core)"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:centos:centos:7"
HOME_URL="https://www.centos.org/"
BUG_REPORT_URL="https://bugs.centos.org/"

CENTOS_MANTISBT_PROJECT="CentOS-7"
CENTOS_MANTISBT_PROJECT_VERSION="7"
REDHAT_SUPPORT_PRODUCT="centos"
REDHAT_SUPPORT_PRODUCT_VERSION="7"

Log Fragments

No response

ankitthakwani commented 1 year ago

Interesting observation, when I manually fire the correct START SLAVE SQL_THREAD UNTIL SQL_BEFORE_GTIDS command then PITR process catches up

mysql> START SLAVE SQL_THREAD UNTIL SQL_BEFORE_GTIDS = 'c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:153';
Query OK, 0 rows affected, 1 warning (0.08 sec)

mysql> SHOW SLAVE STATUS\G
Empty set, 1 warning (0.00 sec)

mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: vt-0000000909-bin.000009
         Position: 3227
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-152,
f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
1 row in set (0.00 sec)

mysql> SET time_zone = '+00:00';
Query OK, 0 rows affected (0.00 sec)

mysql> SELECT * FROM txnInfo;
+----+----------------------------+
| id | created                    |
+----+----------------------------+
|  1 | 2023-05-08 10:07:26.649175 |
|  2 | 2023-05-08 10:07:26.683593 |
|  3 | 2023-05-08 10:07:26.700026 |
|  4 | 2023-05-08 10:07:26.767802 |
|  5 | 2023-05-08 10:07:26.792034 |
|  6 | 2023-05-08 10:07:26.804216 |
|  7 | 2023-05-08 10:07:26.807450 |
|  8 | 2023-05-08 10:07:26.862235 |
|  9 | 2023-05-08 10:07:26.910654 |
| 10 | 2023-05-08 10:07:26.967557 |
+----+----------------------------+
10 rows in set (0.00 sec)

I manually fired the above START SLAVE SQL_THREAD UNTIL SQL_BEFORE_GTIDS = 'c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:153'; just before I0508 17:34:05.212090 timestamp, see the timestamps in following vttablet log

I0508 15:42:39.204094   52987 query.go:81] exec CHANGE MASTER TO MASTER_HOST='127.0.0.1', MASTER_PORT=17900, MASTER_USER='vt_repl_pitr', MASTER_PASSWORD='Password@123', MASTER_AUTO_POSITION=1;
I0508 15:42:39.304614   52987 query.go:81] exec START SLAVE UNTIL SQL_BEFORE_GTIDS = 'f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1'
I0508 15:42:39.315523   52987 restore.go:486] Waiting for position to reach%!(EXTRA string=f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1)

I0508 17:34:05.212090   52987 query.go:81] exec STOP SLAVE
I0508 17:34:05.225934   52987 query.go:81] exec RESET SLAVE ALL
I0508 17:34:05.314984   52987 restore.go:304] Restore: changing tablet type to REPLICA for cell:"dc1" uid:909
I0508 17:34:05.315011   52987 tm_state.go:186] Changing Tablet Type: REPLICA for cell:"dc1" uid:909
I0508 17:34:05.315105   52987 tm_state.go:381] Publishing state: alias:{cell:"dc1" uid:909} hostname:"127.0.0.1" port_map:{key:"grpc" value:16909} port_map:{key:"vt" value:15909} keyspace:"pitr_restored" shard:"0" type:REPLICA db_name_override:"vt_pitr" mysql_hostname:"127.0.0.1" mysql_port:17909 db_server_version:"8.0.29" default_conn_collation:255
I0508 17:34:05.352438   52987 tm_state.go:101] In tmState.Open()
I0508 17:34:05.352487   52987 shard_sync.go:79] Change to tablet state
I0508 17:34:05.352659   52987 restore.go:136] No vttablet_restore_done hook.
I0508 17:34:05.353294   52987 updatestreamctl.go:228] Enabling update stream, dbname: vt_pitr
I0508 17:34:05.353354   52987 state_manager.go:221] Starting transition to REPLICA Serving, timestamp: 0001-01-01 00:00:00 +0000 UTC
I0508 17:34:05.353430   52987 tablegc.go:206] TableGC - started execution of Close. Acquiring initMutex lock
I0508 17:34:05.353436   52987 tablegc.go:209] TableGC - acquired lock
I0508 17:34:05.353441   52987 tablegc.go:211] TableGC - no collector is open
I0508 17:34:05.353456   52987 engine.go:90] messager Engine - started execution of Close. Acquiring mu lock
I0508 17:34:05.353462   52987 engine.go:92] messager Engine - acquired mu lock
I0508 17:34:05.353467   52987 engine.go:95] messager Engine is not open
I0508 17:34:05.355010   52987 engine.go:227] Schema Engine: opening
I0508 17:34:05.447053   52987 engine.go:502] schema engine created [txnInfo], altered [], dropped []
I0508 17:34:05.447102   52987 engine.go:157] VStreamer: opening
I0508 17:34:05.447116   52987 query_engine.go:270] Query Engine: opening
I0508 17:34:05.448824   52987 tx_engine.go:157] TxEngine transition: AcceptingReadOnly
I0508 17:34:05.448878   52987 stateful_connection_pool.go:77] Starting transaction id: {1683540737351698135}
I0508 17:34:05.448938   52987 repltracker.go:108] Replication Tracker: going into non-primary mode
I0508 17:34:05.457069   52987 state_manager.go:611] TabletServer transition: REPLICA: Not connected to mysql -> REPLICA: Serving for tablet :pitr_restored/0
I0508 17:34:05.459683   52987 state_manager.go:604] Tablet Init took 6708117 ms
I0508 17:34:05.459696   52987 state_manager.go:711] State: exiting lameduck
I0508 17:34:05.459704   52987 tm_state.go:381] Publishing state: alias:{cell:"dc1" uid:909} hostname:"127.0.0.1" port_map:{key:"grpc" value:16909} port_map:{key:"vt" value:15909} keyspace:"pitr_restored" shard:"0" type:REPLICA db_name_override:"vt_pitr" mysql_hostname:"127.0.0.1" mysql_port:17909 db_server_version:"8.0.29" default_conn_collation:255
ankitthakwani commented 1 year ago

I think the issue is at https://github.com/vitessio/vitess/blob/fd81a3a4c6e7d563c13a9e552fe25222caedc9ca/go/vt/vttablet/tabletmanager/restore.go#L449

func (tm *TabletManager) catchupToGTID(ctx context.Context, afterGTIDPos string, beforeGTIDPos string) error {
    var afterGTIDStr string
    if afterGTIDPos != "" {
        afterGTIDParsed, err := mysql.DecodePosition(afterGTIDPos)
        if err != nil {
            return err
        }
        afterGTIDStr = afterGTIDParsed.GTIDSet.Last()
    }

I cannot understand why is afterGTIDParsed.GTIDSet.Last() being used here. The changing GTID can be the one appearing earlier in GTID set for e.g. c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-162,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1