Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Bug Report: Incremental backup not working as described #13060

Closed
ankitthakwani opened this issue May 10, 2023 · 9 comments · Fixed by #13066
Closed

Bug Report: Incremental backup not working as described #13060

ankitthakwani opened this issue May 10, 2023 · 9 comments · Fixed by #13066
Assignees
@shlomi-noach
Labels
Component: Backup and Restore Type: Bug

Comments

@ankitthakwani
Copy link

Overview of the Issue

I am following https://github.com/vitessio/vitess/releases/tag/v16.0.0#vtctldclient-backup to do an incremental backup

mysql> \! vtctlclient --server 127.0.0.1:15999 -- Backup --incremental_from_pos "auto" dc1-903
E0510 12:58:04.289002   59158 main.go:96] E0510 07:28:04.288777 backup.go:108] E0510 07:28:04.288401 backup.go:135] backup is not usable, aborting it: [Code: FAILED_PRECONDITION
the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run

cannot get binary logs to backup in incremental backup]
E0510 12:58:04.349226   59158 main.go:96] E0510 07:28:04.348978 backup.go:108] E0510 07:28:04.348734 backup.go:143] failed to finish backup: [MalformedXML: The XML you provided was not well-formed or did not validate against our published schema
        status code: 400, request id: YFQN96WGJ871XV7A, host id: t0uM/vdQnSAYXgNp7QTw5aZR1zSZBQ8xnMe/DsXX01xzT9dsVU1UvvDVddoqF0RfgKSrHCR4Brw=]: %!v(MISSING)
Backup Error: rpc error: code = Unknown desc = TabletManager.Backup on dc1-0000000903 error: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run
E0510 12:58:04.393671   59158 main.go:105] remote error: rpc error: code = Unknown desc = TabletManager.Backup on dc1-0000000903 error: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run

Reproduction Steps

I will list down the steps and the corresponding logs

  1. Create a single sharded keyspace with 4 vttablets
[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>
dc1-0000000909 pitr 0 replica 127.0.0.1:15909 127.0.0.1:17909 [] <null>
  1. Note down the current master status from primary vttablet MySQL instance
[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 170732
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> DROP TABLE IF EXISTS txnInfo;
Query OK, 0 rows affected (0.16 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.19 sec)

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

  1. Execute a backup
    mysql> \! vtctlclient --server 127.0.0.1:15999 BackupShard pitr/0

  2. Check if backup was done
    vtctlclient --server 127.0.0.1:15999 ListBackups pitr/0

  3. Insert some data to increment GTID

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

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.08 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.07 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.09 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.03 sec)

mysql> 
mysql> SELECT * FROM txnInfo;
+----+----------------------------+
| id | created                    |
+----+----------------------------+
|  1 | 2023-05-10 12:57:52.850086 |
|  2 | 2023-05-10 12:57:52.882042 |
|  3 | 2023-05-10 12:57:52.958276 |
|  4 | 2023-05-10 12:57:52.961900 |
|  5 | 2023-05-10 12:57:53.014894 |
|  6 | 2023-05-10 12:57:53.079301 |
|  7 | 2023-05-10 12:57:53.129567 |
|  8 | 2023-05-10 12:57:53.183113 |
|  9 | 2023-05-10 12:57:53.276258 |
| 10 | 2023-05-10 12:57:53.296745 |
+----+----------------------------+
10 rows in set (0.00 sec)

mysql> 
mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: vt-0000000900-bin.000003
         Position: 54794
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-250,
f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
1 row in set (0.00 sec)
  1. Fire incremental backup
mysql> \! vtctlclient --server 127.0.0.1:15999 -- Backup --incremental_from_pos "auto" dc1-903
E0510 12:58:04.289002   59158 main.go:96] E0510 07:28:04.288777 backup.go:108] E0510 07:28:04.288401 backup.go:135] backup is not usable, aborting it: [Code: FAILED_PRECONDITION
the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run

cannot get binary logs to backup in incremental backup]
E0510 12:58:04.349226   59158 main.go:96] E0510 07:28:04.348978 backup.go:108] E0510 07:28:04.348734 backup.go:143] failed to finish backup: [MalformedXML: The XML you provided was not well-formed or did not validate against our published schema
        status code: 400, request id: YFQN96WGJ871XV7A, host id: t0uM/vdQnSAYXgNp7QTw5aZR1zSZBQ8xnMe/DsXX01xzT9dsVU1UvvDVddoqF0RfgKSrHCR4Brw=]: %!v(MISSING)
Backup Error: rpc error: code = Unknown desc = TabletManager.Backup on dc1-0000000903 error: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run
E0510 12:58:04.393671   59158 main.go:105] remote error: rpc error: code = Unknown desc = TabletManager.Backup on dc1-0000000903 error: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run

Corresponding vtctld logs

I0510 12:57:32.069857   82561 server.go:485] I0510 07:27:32.069528 builtinbackupengine.go:628] Done taking Backup "ib_logfile0"
I0510 12:57:32.069902   82561 backup.go:108] I0510 07:27:32.069528 builtinbackupengine.go:628] Done taking Backup "ib_logfile0"
I0510 12:57:34.076778   82561 server.go:485] I0510 07:27:34.076336 builtinbackupengine.go:388] resetting mysqld read-only to true
I0510 12:57:34.076842   82561 backup.go:108] I0510 07:27:34.076336 builtinbackupengine.go:388] resetting mysqld read-only to true
I0510 12:57:34.202878   82561 replication.go:190] Getting a new durability policy for semi_sync
I0510 12:57:46.417431   82561 s3.go:279] ListBackups: [s3] dir: pitr/0, bucket: paymentsbank-upi-vitess-bkp-nonprod
I0510 12:57:46.442519   82561 s3.go:291] objName: staging/pitr/0/
I0510 12:58:04.173777   82561 server.go:485] I0510 07:28:04.173306 builtinbackupengine.go:179] Executing Backup at 2023-05-10 12:58:04.121935503 +0530 IST m=+4360.496626477 for keyspace/shard pitr/0 on tablet dc1-0000000903, concurrency: 4, compress: true, incrementalFromPos: auto
I0510 12:58:04.173824   82561 backup.go:108] I0510 07:28:04.173306 builtinbackupengine.go:179] Executing Backup at 2023-05-10 12:58:04.121935503 +0530 IST m=+4360.496626477 for keyspace/shard pitr/0 on tablet dc1-0000000903, concurrency: 4, compress: true, incrementalFromPos: auto
I0510 12:58:04.173844   82561 server.go:485] I0510 07:28:04.173343 builtinbackupengine.go:193] auto evaluating incremental_from_pos
I0510 12:58:04.173861   82561 backup.go:108] I0510 07:28:04.173343 builtinbackupengine.go:193] auto evaluating incremental_from_pos
I0510 12:58:04.217041   82561 server.go:485] I0510 07:28:04.216799 builtinbackupengine.go:212] auto evaluated incremental_from_pos: MySQL56/c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-240,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
I0510 12:58:04.217079   82561 backup.go:108] I0510 07:28:04.216799 builtinbackupengine.go:212] auto evaluated incremental_from_pos: MySQL56/c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-240,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
E0510 12:58:04.288751   82561 server.go:485] E0510 07:28:04.288401 backup.go:135] backup is not usable, aborting it: [Code: FAILED_PRECONDITION
the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run

cannot get binary logs to backup in incremental backup]
E0510 12:58:04.288795   82561 backup.go:108] E0510 07:28:04.288401 backup.go:135] backup is not usable, aborting it: [Code: FAILED_PRECONDITION
the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run

cannot get binary logs to backup in incremental backup]
E0510 12:58:04.348959   82561 server.go:485] E0510 07:28:04.348734 backup.go:143] failed to finish backup: [MalformedXML: The XML you provided was not well-formed or did not validate against our published schema
        status code: 400, request id: YFQN96WGJ871XV7A, host id: t0uM/vdQnSAYXgNp7QTw5aZR1zSZBQ8xnMe/DsXX01xzT9dsVU1UvvDVddoqF0RfgKSrHCR4Brw=]: %!v(MISSING)
E0510 12:58:04.348992   82561 backup.go:108] E0510 07:28:04.348734 backup.go:143] failed to finish backup: [MalformedXML: The XML you provided was not well-formed or did not validate against our published schema
        status code: 400, request id: YFQN96WGJ871XV7A, host id: t0uM/vdQnSAYXgNp7QTw5aZR1zSZBQ8xnMe/DsXX01xzT9dsVU1UvvDVddoqF0RfgKSrHCR4Brw=]: %!v(MISSING)

Relevant MANIFEST file contents

vitess@workernode-upi-v1-10011441 ~]$ cat MANIFEST 
{
  "BackupMethod": "builtin",
  "Position": "MySQL56/c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-240,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1",
  "PurgedPosition": "MySQL56/c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1",
  "FromPosition": "",
  "Incremental": false,
  "BackupTime": "2023-05-10T07:27:27Z",
  "FinishedTime": "2023-05-10T07:27:32Z",
  "ServerUUID": "f7393495-eb11-11ed-8cf4-3c5731cc0ff6",
  "TabletAlias": "dc1-0000000903",
  "Keyspace": "pitr",
  "Shard": "0",
  "CompressionEngine": "pargzip",
  "FileEntries": [
    {
      "Base": "InnoDBData",
      "Name": "ib_buffer_pool",
      "Hash": "9f2ffefc",
      "ParentPath": ""
    },

Binary Version

[vitess@workernode-upi-v1-10011441 ~]$ vttablet --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 ~]$ uname -m
x86_64

[vitess@workernode-upi-v1-10011441 ~]$ uname -sr
Linux 3.10.0-1160.83.1.el7.x86_64

[vitess@workernode-upi-v1-10011441 ~]$ 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

Provided above
@ankitthakwani ankitthakwani added Needs Triage This issue needs to be correctly labelled and triaged Type: Bug labels May 10, 2023
@shlomi-noach
Copy link
Contributor

Can you please try the same, but replace

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

with

mysql> \! vtctlclient --server 127.0.0.1:15999 Backup <tablet-name>

and see if the problem remains the same?

@shlomi-noach shlomi-noach added Component: Backup and Restore and removed Needs Triage This issue needs to be correctly labelled and triaged labels May 10, 2023
@shlomi-noach shlomi-noach self-assigned this May 10, 2023
@ankitthakwani
Copy link
Author

Same problem

[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>
dc1-0000000909 pitr 0 replica 127.0.0.1:15909 127.0.0.1:17909 [] <null>
[vitess@workernode-upi-v1-10011441 ~]$ 
[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 171043
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> 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.20 sec)

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

mysql> \! vtctlclient --server 127.0.0.1:15999 Backup dc1-902

mysql> 

mysql> \! vtctlclient --server 127.0.0.1:15999 ListBackups pitr/0
2023-05-10.084811.dc1-0000000902
mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: vt-0000000900-bin.000003
         Position: 56564
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-256,
f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
1 row in set (0.00 sec)

mysql> 
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.01 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.03 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.00 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.01 sec)

mysql> 
mysql> SELECT * FROM txnInfo;
+----+----------------------------+
| id | created                    |
+----+----------------------------+
|  1 | 2023-05-10 14:19:18.173187 |
|  2 | 2023-05-10 14:19:18.222851 |
|  3 | 2023-05-10 14:19:18.246798 |
|  4 | 2023-05-10 14:19:18.263148 |
|  5 | 2023-05-10 14:19:18.285348 |
|  6 | 2023-05-10 14:19:18.289411 |
|  7 | 2023-05-10 14:19:18.320141 |
|  8 | 2023-05-10 14:19:18.357843 |
|  9 | 2023-05-10 14:19:18.362113 |
| 10 | 2023-05-10 14:19:18.366148 |
+----+----------------------------+
10 rows in set (0.00 sec)

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

mysql> \! vtctlclient --server 127.0.0.1:15999 -- Backup --incremental_from_pos "auto" dc1-902
E0510 14:19:42.968803   55404 main.go:96] E0510 08:49:42.968464 backup.go:108] E0510 08:49:42.968086 backup.go:135] backup is not usable, aborting it: [Code: FAILED_PRECONDITION
the very first binlog file vt-0000000902-bin.000004 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-51,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run

cannot get binary logs to backup in incremental backup]
E0510 14:19:43.027122   55404 main.go:96] E0510 08:49:43.026660 backup.go:108] E0510 08:49:43.026215 backup.go:143] failed to finish backup: [MalformedXML: The XML you provided was not well-formed or did not validate against our published schema
	status code: 400, request id: 2X0KTB4HCRSMYM4C, host id: /pFbGYCt4Gej5LOIZvaZ8dRpPwSrNobB7ZfnU2HqxXWT0ZzfHIPEoRfQJQFlIJS1qNc4BwzIJTg=]: %!v(MISSING)
Backup Error: rpc error: code = Unknown desc = TabletManager.Backup on dc1-0000000902 error: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000902-bin.000004 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-51,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000902-bin.000004 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-51,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run
E0510 14:19:43.069251   55404 main.go:105] remote error: rpc error: code = Unknown desc = TabletManager.Backup on dc1-0000000902 error: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000902-bin.000004 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-51,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000902-bin.000004 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-51,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run

@shlomi-noach
Copy link
Contributor

I am now able to reproduce. Looks like this happens when the first available binary log is the very binary log which the backup needs to copy. Investigating.

@shlomi-noach
Copy link
Contributor

More precisely, the problem happens when the first binary log's Previous GTIDs is exactly @@gtid_purged.

@ankitthakwani
Copy link
Author

OK, is there any work around this problem such as purging some binary logs before backup?

@shlomi-noach
Copy link
Contributor

is there any work around this problem

I believe a workaround is to take another full backup; but I'm still looking to solve this in code.

@ankitthakwani
Copy link
Author

Another full backup too is not helping here

[vitess@workernode-upi-v1-10011441 ~]$ vtctlclient --server 127.0.0.1:15999 ListBackups pitr/0
2023-05-10.092230.dc1-0000000902
[vitess@workernode-upi-v1-10011441 ~]$ vtctlclient --server 127.0.0.1:15999 BackupShard pitr/0

[vitess@workernode-upi-v1-10011441 ~]$ vtctlclient --server 127.0.0.1:15999 ListBackups pitr/0
2023-05-10.092230.dc1-0000000902
2023-05-10.103138.dc1-0000000902

[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 171425
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> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: vt-0000000900-bin.000008
         Position: 237
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-278,
f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1
1 row in set (0.00 sec)

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.03 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.01 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.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.01 sec)

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

mysql> 
mysql> SELECT * FROM txnInfo;
+----+----------------------------+
| id | created                    |
+----+----------------------------+
|  1 | 2023-05-10 14:52:51.652826 |
|  2 | 2023-05-10 14:52:51.685360 |
|  3 | 2023-05-10 14:52:51.702543 |
|  4 | 2023-05-10 14:52:51.730095 |
|  5 | 2023-05-10 14:52:51.771156 |
|  6 | 2023-05-10 14:52:51.819835 |
|  7 | 2023-05-10 14:52:51.826286 |
|  8 | 2023-05-10 14:52:51.896517 |
|  9 | 2023-05-10 14:52:51.956537 |
| 10 | 2023-05-10 14:52:52.035918 |
| 11 | 2023-05-10 16:02:03.944260 |
| 12 | 2023-05-10 16:02:03.971499 |
| 13 | 2023-05-10 16:02:04.005332 |
| 14 | 2023-05-10 16:02:04.015880 |
| 15 | 2023-05-10 16:02:04.020687 |
| 16 | 2023-05-10 16:02:04.063018 |
| 17 | 2023-05-10 16:02:04.066174 |
| 18 | 2023-05-10 16:02:04.125615 |
| 19 | 2023-05-10 16:02:04.170359 |
| 20 | 2023-05-10 16:02:04.181023 |
+----+----------------------------+
20 rows in set (0.00 sec)

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

mysql> exit
Bye


[vitess@workernode-upi-v1-10011441 ~]$ vtctlclient --server 127.0.0.1:15999 -- Backup --incremental_from_pos "auto" dc1-903
E0510 16:02:18.171524  143308 main.go:96] E0510 10:32:18.171223 backup.go:108] E0510 10:32:18.170855 backup.go:135] backup is not usable, aborting it: [Code: FAILED_PRECONDITION
the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run

cannot get binary logs to backup in incremental backup]
E0510 16:02:18.237769  143308 main.go:96] E0510 10:32:18.237568 backup.go:108] E0510 10:32:18.237169 backup.go:143] failed to finish backup: [MalformedXML: The XML you provided was not well-formed or did not validate against our published schema
	status code: 400, request id: FMJDQ1JCM5AVTX84, host id: HgcuHCt5b3SLuP/AUwONox7xybmDH6r2jhHFsKBXZqkk/ds513oNDGgH0bYEZGyqlhe8xsCWA+Y=]: %!v(MISSING)
Backup Error: rpc error: code = Unknown desc = TabletManager.Backup on dc1-0000000903 error: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run
E0510 16:02:18.324319  143308 main.go:105] remote error: rpc error: code = Unknown desc = TabletManager.Backup on dc1-0000000903 error: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run: cannot get binary logs to backup in incremental backup: the very first binlog file vt-0000000903-bin.000005 has PreviousGTIDs c35c3322-eb10-11ed-aeb1-3c5731cc0ff6:1-70,f7393495-eb11-11ed-8cf4-3c5731cc0ff6:1 that exceed given incremental backup pos. There are GTID entries that are missing and this backup cannot run

@shlomi-noach
Copy link
Contributor

FWIW, I was only able to reproduce when using vtctl ... BackupShard. When using vtctl ... Backup I could not reproduce it. It's entirely possible I missed something of course.

@shlomi-noach shlomi-noach mentioned this issue May 10, 2023
Merged
4 tasks
@shlomi-noach
Copy link
Contributor

Addressed by #13066

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@shlomi-noach shlomi-noach

Labels
Component: Backup and Restore Type: Bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Incremental backup: fix calculation of binlog files to use planetscale/vitess
2 participants
@shlomi-noach @ankitthakwani