[MDEV-23080] mariabackup: position saved in xtrabackup_binlog_info is incorrect for replication Created: 2020-07-03  Updated: 2024-01-22  Resolved: 2021-07-27

Status: Closed
Project: MariaDB Server
Component/s: mariabackup
Affects Version/s: 10.4.13
Fix Version/s: 10.4.21, 10.5.12, 10.6.4

Type: Bug Priority: Critical
Reporter: Rick Pizzi Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 6
Labels: None

Issue Links:
Blocks
blocks MDEV-25136 Mariabackup crash with InnoDB: Assert... Closed
Relates
relates to MDEV-18917 Don't create xtrabackup_binlog_pos_in... Closed
relates to MDEV-21611 mariabackup should update binlog posi... Open
relates to MDEV-26391 mariabackup always triggers node desync Closed

 Description   

It appears that mariabackup no longer updates xtrabackup_binlog_info file after completing prepare phase. The position in the file is therefore incorrect and can't be used to set up replication after a restore. The position reported in the prepare phase log is correct, it's just that the file is not updated.

This is critical as a lot of DBAs and tools use the content of this file to set up replication, manually or automatically. Please fix it ASAP!

Thank you.

Rick

 Comments   
Comment by Vladislav Lesin [ 2020-07-06 ]

mariabackup does not update xtrabackup_binlog_info on --prepare. I suppose this is because binlog position is captured under backup lock, which, in turns, prevents binlog position updating. Do you use --no-lock during backup? Anyway, this is not 10.4.13-only issue, it affects all 10.2+.

Comment by Rick Pizzi [ 2020-07-07 ]

No we do not use --no-lock (and we never did).
This is what we used:

tool_command = --backup --tmpdir=/tmp --stream=xbstream --parallel=10 --datadir=/var/lib/mysql/

Comment by Rick Pizzi [ 2020-07-07 ]

Two notes -

1. xtrabackup DOES update that file on --prepare (checked sources for 2.4) and I am pretty sure it always did
2. I am pretty sure that mariabackup used to do the same until recently

Comment by Rick Pizzi [ 2020-07-07 ]

After perusing MariaDB source code I was able to track down where this has changed: here MDEV-18917

So, to make this clear, we had this issue in production where we have tried to take a full backup of a live galera node in order to create an async replica out of it.

The position saved in xtrabackup_binlog_info saved by the --backup option is not updated when we run --prepare later, and this is a bug as this position may change after --prepare.

Proof is, when --prepare completes OK, the updated binlog info position is printed out on stdout, but the file is not updated.

We tried to use the position in the file initially but that was wrong (replica broke with dupes because it is a position in the past)

Only when we used the correct position printed by --prepare on stdout the replica could be set up correctly.

Please, save what you print on stdout at end of --prepare to xtrabackup_binlog_info and make it work again. Thanks!

Comment by Rick Pizzi [ 2020-07-09 ]

Since it has been told to me that the position shoulnd't change after --prepare, here's how to see that it's not true.

1. create a one node galera cluster with 10.4.13
2. throw some sysbench load at it (I used oltp_insert.lua)
3. while sysbench runs, fire a mariabackup full backup to another node (details below)
4. after backup finishes, check content of xtrabackup_binlog_info on said node
5. run mariabackup --prepare on said node
6. at end of prepare, mariabackup will spit out a new, updated position (mariadb-bin.000004, position 512548623)
7. if you want to make this node become a replica of the galera node, you need to use the updated position or you'll get duplicates; in the example below I used the original position from the file, as you can see, it is incorrect!!

Sysbench preparation and run:

# sysbench --db-driver=mysql --mysql-host=localhost --mysql-user=root /usr/share/sysbench/oltp_insert.lua --tables=8 prepare
 
# sysbench --db-driver=mysql --mysql-host=localhost --mysql-user=root /usr/share/sysbench/oltp_insert.lua --tables=8 --threads=8 --time=0 run

Firing a full streaming backup live:

# mariabackup --user root --backup --parallel 8 --tmpdir=/tmp --stream=xbstream | ssh -q 192.168.2.91 mbstream -x -v -C /var/lib/mysql
 
[00] 2020-07-09 09:58:28 Connecting to MySQL server host: localhost, user: root, password: not set, port: not set, socket: not set
 
[00] 2020-07-09 09:58:28 Using server version 10.4.13-MariaDB-log
 
mariabackup based on MariaDB server 10.4.13-MariaDB Linux (x86_64)
 
[00] 2020-07-09 09:58:28 uses posix_fadvise().
 
[00] 2020-07-09 09:58:28 cd to /var/lib/mysql/
 
[00] 2020-07-09 09:58:28 open files limit requested 65535, set to 65535
 
[00] 2020-07-09 09:58:28 mariabackup: using the following InnoDB configuration:
 
[00] 2020-07-09 09:58:28 innodb_data_home_dir = 
[00] 2020-07-09 09:58:28 innodb_data_file_path = ibdata1:12M:autoextend
 
[00] 2020-07-09 09:58:28 innodb_log_group_home_dir = ./
 
[00] 2020-07-09 09:58:28 InnoDB: Using Linux native AIO
 
2020-07-09  9:58:28 0 [Note] InnoDB: Number of pools: 1
 
[00] 2020-07-09 09:58:28 mariabackup: Generating a list of tablespaces
 
2020-07-09  9:58:28 0 [Warning] InnoDB: Allocated tablespace ID 1 for mysql/innodb_table_stats, old maximum was 0
 
[00] 2020-07-09 09:58:32 ib_logfile0
 
[00] 2020-07-09 09:58:42 >> log scanned up to (1615817920)
 
[00] 2020-07-09 09:58:42 mariabackup: Starting 8 threads for parallel data files transfer
 
[05] 2020-07-09 09:58:42 Streaming ./mysql/gtid_slave_pos.ibd
 
[01] 2020-07-09 09:58:42 Streaming ./mysql/transaction_registry.ibd
 
[03] 2020-07-09 09:58:42 Streaming ./mysql/innodb_table_stats.ibd
 
[04] 2020-07-09 09:58:42 Streaming ./mysql/innodb_index_stats.ibd
 
[03] 2020-07-09 09:58:42         ...done
 
[01] 2020-07-09 09:58:42         ...done
 
[08] 2020-07-09 09:58:42 Streaming ibdata1
 
[00] 2020-07-09 09:58:42 mysql/innodb_table_stats.ibd
 
[04] 2020-07-09 09:58:42         ...done
 
[00] 2020-07-09 09:58:42 mysql/transaction_registry.ibd
 
[00] 2020-07-09 09:58:42 mysql/innodb_index_stats.ibd
 
[05] 2020-07-09 09:58:42         ...done
 
[03] 2020-07-09 09:58:42 Streaming ./sbtest/sbtest1.ibd
 
[01] 2020-07-09 09:58:42 Streaming ./sbtest/sbtest2.ibd
 
[04] 2020-07-09 09:58:42 Streaming ./sbtest/sbtest3.ibd
 
[05] 2020-07-09 09:58:42 Streaming ./sbtest/sbtest4.ibd
 
[02] 2020-07-09 09:58:42 Streaming ./mysql/wsrep_streaming_log.ibd
 
[06] 2020-07-09 09:58:42 Streaming ./mysql/wsrep_cluster.ibd
 
[02] 2020-07-09 09:58:42         ...done
 
[06] 2020-07-09 09:58:42         ...done
 
[07] 2020-07-09 09:58:42 Streaming ./mysql/wsrep_cluster_members.ibd
 
[07] 2020-07-09 09:58:42         ...done
 
[00] 2020-07-09 09:58:42 mysql/gtid_slave_pos.ibd
 
2020-07-09  9:58:43 0 [Note] InnoDB: Read redo log up to LSN=1615883264
 
[00] 2020-07-09 09:58:43 >> log scanned up to (1616385599)
 
[00] 2020-07-09 09:58:44 >> log scanned up to (1617265854)
 
[00] 2020-07-09 09:58:44 ibdata1
 
[00] 2020-07-09 09:58:45 >> log scanned up to (1618200502)
 
[04] 2020-07-09 09:58:46         ...done
 
[00] 2020-07-09 09:58:46 sbtest/sbtest3.ibd
 
[04] 2020-07-09 09:58:46 Streaming ./sbtest/sbtest5.ibd
 
[00] 2020-07-09 09:58:47 >> log scanned up to (1618948541)
 
[00] 2020-07-09 09:58:48 sbtest/sbtest2.ibd
 
[00] 2020-07-09 09:58:48 mysql/wsrep_streaming_log.ibd
 
[01] 2020-07-09 09:58:48         ...done
 
[00] 2020-07-09 09:58:48 mysql/wsrep_cluster.ibd
 
[06] 2020-07-09 09:58:48 Streaming ./sbtest/sbtest6.ibd
 
[02] 2020-07-09 09:58:48 Streaming ./sbtest/sbtest7.ibd
 
[05] 2020-07-09 09:58:51         ...done
 
[07] 2020-07-09 09:58:51 Streaming ./sbtest/sbtest8.ibd
 
[00] 2020-07-09 09:58:51 sbtest/sbtest4.ibd
 
[00] 2020-07-09 09:58:51 mysql/wsrep_cluster_members.ibd
 
[03] 2020-07-09 09:58:56         ...done
 
[00] 2020-07-09 09:58:56 sbtest/sbtest1.ibd
 
[04] 2020-07-09 09:58:59         ...done
 
[00] 2020-07-09 09:58:59 sbtest/sbtest5.ibd
 
2020-07-09  9:59:02 0 [Note] InnoDB: Read redo log up to LSN=1620062208
 
[00] 2020-07-09 09:59:04 sbtest/sbtest6.ibd
 
[06] 2020-07-09 09:59:04         ...done
 
[02] 2020-07-09 09:59:07         ...done
 
[00] 2020-07-09 09:59:07 sbtest/sbtest7.ibd
 
[07] 2020-07-09 09:59:10         ...done
 
[00] 2020-07-09 09:59:10 sbtest/sbtest8.ibd
 
2020-07-09  9:59:17 0 [Note] InnoDB: Read redo log up to LSN=1634545664
 
[00] 2020-07-09 09:59:27 >> log scanned up to (1655120613)
 
[00] 2020-07-09 09:59:28 >> log scanned up to (1655895379)
 
[00] 2020-07-09 09:59:29 >> log scanned up to (1657152495)
 
[00] 2020-07-09 09:59:31 >> log scanned up to (1658459170)
 
[08] 2020-07-09 09:59:31         ...done
 
2020-07-09  9:59:32 0 [Note] InnoDB: Read redo log up to LSN=1658524672
 
[00] 2020-07-09 09:59:32 >> log scanned up to (1659560714)
 
[00] 2020-07-09 09:59:33 Acquiring BACKUP LOCKS...
 
[00] 2020-07-09 09:59:33 Starting to backup non-InnoDB tables and files
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/db.opt to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/db.frm to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/db.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/db.MAD to <STDOUT>
 
[00] 2020-07-09 09:59:33 mysql/db.opt
 
[00] 2020-07-09 09:59:33 mysql/db.frm
 
[00] 2020-07-09 09:59:33 mysql/db.MAI
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/global_priv.frm to <STDOUT>
 
[00] 2020-07-09 09:59:33 mysql/db.MAD
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/global_priv.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/global_priv.MAD to <STDOUT>
 
[00] 2020-07-09 09:59:33 mysql/global_priv.frm
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/user.frm to <STDOUT>
 
[00] 2020-07-09 09:59:33 mysql/global_priv.MAI
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/roles_mapping.frm to <STDOUT>
 
[00] 2020-07-09 09:59:33 mysql/global_priv.MAD
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/roles_mapping.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/roles_mapping.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/func.frm to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/func.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/func.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/plugin.frm to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/plugin.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/plugin.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[00] 2020-07-09 09:59:33 >> log scanned up to (1660475534)
 
[00] 2020-07-09 09:59:33 mysql/user.frm
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/servers.frm to <STDOUT>
 
[00] 2020-07-09 09:59:33 mysql/roles_mapping.frm
 
[00] 2020-07-09 09:59:33 mysql/roles_mapping.MAI
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/servers.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/servers.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/tables_priv.frm to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/tables_priv.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[00] 2020-07-09 09:59:33 mysql/roles_mapping.MAD
 
[00] 2020-07-09 09:59:33 mysql/func.frm
 
[00] 2020-07-09 09:59:33 mysql/func.MAI
 
[00] 2020-07-09 09:59:33 mysql/func.MAD
 
[00] 2020-07-09 09:59:33 mysql/plugin.frm
 
[00] 2020-07-09 09:59:33 mysql/plugin.MAI
 
[00] 2020-07-09 09:59:33 mysql/plugin.MAD
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/tables_priv.MAD to <STDOUT>
 
[00] 2020-07-09 09:59:33 mysql/servers.frm
 
[00] 2020-07-09 09:59:33 mysql/servers.MAI
 
[00] 2020-07-09 09:59:33 mysql/servers.MAD
 
[00] 2020-07-09 09:59:33 mysql/tables_priv.frm
 
[00] 2020-07-09 09:59:33 mysql/tables_priv.MAI
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/columns_priv.frm to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/columns_priv.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/columns_priv.MAD to <STDOUT>
 
[00] 2020-07-09 09:59:33 mysql/tables_priv.MAD
 
[00] 2020-07-09 09:59:33 mysql/columns_priv.frm
 
[00] 2020-07-09 09:59:33 mysql/columns_priv.MAI
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/help_topic.frm to <STDOUT>
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/help_topic.MAI to <STDOUT>
 
[00] 2020-07-09 09:59:34 mysql/columns_priv.MAD
 
[01] 2020-07-09 09:59:33         ...done
 
[01] 2020-07-09 09:59:33 Streaming ./mysql/help_topic.MAD to <STDOUT>
 
[00] 2020-07-09 09:59:34 mysql/help_topic.frm
 
[00] 2020-07-09 09:59:34 mysql/help_topic.MAI
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/help_category.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/help_category.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/help_category.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/help_relation.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/help_relation.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/help_relation.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[00] 2020-07-09 09:59:34 mysql/help_topic.MAD
 
[00] 2020-07-09 09:59:34 mysql/help_category.frm
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/help_keyword.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/help_keyword.MAI to <STDOUT>
 
[00] 2020-07-09 09:59:34 mysql/help_category.MAI
 
[00] 2020-07-09 09:59:34 mysql/help_category.MAD
 
[00] 2020-07-09 09:59:34 mysql/help_relation.frm
 
[00] 2020-07-09 09:59:34 mysql/help_relation.MAI
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/help_keyword.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_name.frm to <STDOUT>
 
[00] 2020-07-09 09:59:34 mysql/help_relation.MAD
 
[00] 2020-07-09 09:59:34 mysql/help_keyword.frm
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_name.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_name.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_transition.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_transition.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_transition.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[00] 2020-07-09 09:59:34 mysql/help_keyword.MAI
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_transition_type.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_transition_type.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_transition_type.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_leap_second.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_leap_second.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/time_zone_leap_second.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/proc.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/proc.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[00] 2020-07-09 09:59:34 mysql/help_keyword.MAD
 
[00] 2020-07-09 09:59:34 mysql/time_zone_name.frm
 
[00] 2020-07-09 09:59:34 mysql/time_zone_name.MAI
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/proc.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/procs_priv.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/procs_priv.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/procs_priv.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/general_log.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/general_log.CSM to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/general_log.CSV to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/slow_log.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/slow_log.CSM to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/slow_log.CSV to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/event.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/event.MAI to <STDOUT>
 
[00] 2020-07-09 09:59:34 mysql/time_zone_name.MAD
 
[00] 2020-07-09 09:59:34 mysql/time_zone.frm
 
[00] 2020-07-09 09:59:34 mysql/time_zone.MAI
 
[00] 2020-07-09 09:59:34 mysql/time_zone.MAD
 
[00] 2020-07-09 09:59:34 mysql/time_zone_transition.frm
 
[00] 2020-07-09 09:59:34 mysql/time_zone_transition.MAI
 
[00] 2020-07-09 09:59:34 mysql/time_zone_transition.MAD
 
[00] 2020-07-09 09:59:34 mysql/time_zone_transition_type.frm
 
[00] 2020-07-09 09:59:34 mysql/time_zone_transition_type.MAI
 
[00] 2020-07-09 09:59:34 mysql/time_zone_transition_type.MAD
 
[00] 2020-07-09 09:59:34 mysql/time_zone_leap_second.frm
 
[00] 2020-07-09 09:59:34 mysql/time_zone_leap_second.MAI
 
[00] 2020-07-09 09:59:34 mysql/time_zone_leap_second.MAD
 
[00] 2020-07-09 09:59:34 mysql/proc.frm
 
[00] 2020-07-09 09:59:34 mysql/proc.MAI
 
[00] 2020-07-09 09:59:34 mysql/proc.MAD
 
[00] 2020-07-09 09:59:34 mysql/procs_priv.frm
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/event.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/innodb_table_stats.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/innodb_index_stats.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/transaction_registry.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/proxies_priv.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/proxies_priv.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[00] 2020-07-09 09:59:34 mysql/procs_priv.MAI
 
[00] 2020-07-09 09:59:34 mysql/procs_priv.MAD
 
[00] 2020-07-09 09:59:34 mysql/general_log.frm
 
[00] 2020-07-09 09:59:34 mysql/general_log.CSM
 
[00] 2020-07-09 09:59:34 mysql/general_log.CSV
 
[00] 2020-07-09 09:59:34 mysql/slow_log.frm
 
[00] 2020-07-09 09:59:34 mysql/slow_log.CSM
 
[00] 2020-07-09 09:59:34 mysql/slow_log.CSV
 
[00] 2020-07-09 09:59:34 mysql/event.frm
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/proxies_priv.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/table_stats.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/table_stats.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/table_stats.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/column_stats.frm to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/column_stats.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[01] 2020-07-09 09:59:34 Streaming ./mysql/column_stats.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:34         ...done
 
[00] 2020-07-09 09:59:34 mysql/event.MAI
 
[00] 2020-07-09 09:59:34 mysql/event.MAD
 
[00] 2020-07-09 09:59:34 mysql/innodb_table_stats.frm
 
[00] 2020-07-09 09:59:34 mysql/innodb_index_stats.frm
 
[00] 2020-07-09 09:59:34 mysql/transaction_registry.frm
 
[00] 2020-07-09 09:59:34 mysql/proxies_priv.frm
 
[01] 2020-07-09 09:59:35 Streaming ./mysql/index_stats.frm to <STDOUT>
 
[00] 2020-07-09 09:59:35 mysql/proxies_priv.MAI
 
[00] 2020-07-09 09:59:35 mysql/proxies_priv.MAD
 
[00] 2020-07-09 09:59:35 mysql/table_stats.frm
 
[00] 2020-07-09 09:59:35 mysql/table_stats.MAI
 
[00] 2020-07-09 09:59:35 mysql/table_stats.MAD
 
[00] 2020-07-09 09:59:35 mysql/column_stats.frm
 
[00] 2020-07-09 09:59:35 mysql/column_stats.MAI
 
[00] 2020-07-09 09:59:35 mysql/column_stats.MAD
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./mysql/index_stats.MAI to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./mysql/index_stats.MAD to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./mysql/gtid_slave_pos.frm to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./mysql/wsrep_cluster.frm to <STDOUT>
 
[00] 2020-07-09 09:59:35 mysql/index_stats.frm
 
[00] 2020-07-09 09:59:35 mysql/index_stats.MAI
 
[00] 2020-07-09 09:59:35 mysql/index_stats.MAD
 
[00] 2020-07-09 09:59:35 mysql/gtid_slave_pos.frm
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./mysql/wsrep_cluster_members.frm to <STDOUT>
 
[00] 2020-07-09 09:59:35 mysql/wsrep_cluster.frm
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./mysql/wsrep_streaming_log.frm to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./performance_schema/db.opt to <STDOUT>
 
[00] 2020-07-09 09:59:35 mysql/wsrep_cluster_members.frm
 
[00] 2020-07-09 09:59:35 mysql/wsrep_streaming_log.frm
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./test/db.opt to <STDOUT>
 
[00] 2020-07-09 09:59:35 performance_schema/db.opt
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./sbtest/db.opt to <STDOUT>
 
[00] 2020-07-09 09:59:35 test/db.opt
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./sbtest/sbtest1.frm to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./sbtest/sbtest2.frm to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./sbtest/sbtest3.frm to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./sbtest/sbtest4.frm to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./sbtest/sbtest5.frm to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./sbtest/sbtest6.frm to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./sbtest/sbtest7.frm to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./sbtest/sbtest8.frm to <STDOUT>
 
[01] 2020-07-09 09:59:35         ...done
 
[00] 2020-07-09 09:59:35 Finished backing up non-InnoDB tables and files
 
[01] 2020-07-09 09:59:35 Streaming ./aria_log_control to <STDOUT>
 
[00] 2020-07-09 09:59:35 sbtest/db.opt
 
[00] 2020-07-09 09:59:35 sbtest/sbtest1.frm
 
[00] 2020-07-09 09:59:35 sbtest/sbtest2.frm
 
[00] 2020-07-09 09:59:35 sbtest/sbtest3.frm
 
[00] 2020-07-09 09:59:35 sbtest/sbtest4.frm
 
[00] 2020-07-09 09:59:35 sbtest/sbtest5.frm
 
[00] 2020-07-09 09:59:35 sbtest/sbtest6.frm
 
[00] 2020-07-09 09:59:35 sbtest/sbtest7.frm
 
[00] 2020-07-09 09:59:35 sbtest/sbtest8.frm
 
[01] 2020-07-09 09:59:35         ...done
 
[01] 2020-07-09 09:59:35 Streaming ./aria_log.00000001 to <STDOUT>
 
[00] 2020-07-09 09:59:35 aria_log_control
 
[01] 2020-07-09 09:59:35         ...done
 
[00] 2020-07-09 09:59:35 aria_log.00000001
 
[00] 2020-07-09 09:59:35 Waiting for log copy thread to read lsn 1660476165
 
[00] 2020-07-09 09:59:35 >> log scanned up to (1661419696)
 
[00] 2020-07-09 09:59:35 Streaming xtrabackup_binlog_info
 
[00] 2020-07-09 09:59:35         ...done
 
[00] 2020-07-09 09:59:35 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
 
[00] 2020-07-09 09:59:35 xtrabackup_binlog_info
 
[00] 2020-07-09 09:59:35 mariabackup: The latest check point (for incremental): '1605890730'
 
mariabackup: Stopping log copying thread.[00] 2020-07-09 09:59:35 >> log scanned up to (1661450921)
 
 
 
[00] 2020-07-09 09:59:35 >> log scanned up to (1661676169)
 
[00] 2020-07-09 09:59:37 Executing BACKUP STAGE END
 
[00] 2020-07-09 09:59:37 All tables unlocked
 
[00] 2020-07-09 09:59:37 Streaming ib_buffer_pool to <STDOUT>
 
[00] 2020-07-09 09:59:37         ...done
 
[00] 2020-07-09 09:59:37 Backup created in directory '/root/xtrabackup_backupfiles/'
 
[00] 2020-07-09 09:59:37 MySQL binlog position: filename 'mariadb-bin.000004', position '512291507', GTID of the last change '0-1-41,1-1-2426302'
 
[00] 2020-07-09 09:59:37 Streaming backup-my.cnf
 
[00] 2020-07-09 09:59:37         ...done
 
[00] 2020-07-09 09:59:37 Streaming xtrabackup_info
 
[00] 2020-07-09 09:59:37         ...done
 
[00] 2020-07-09 09:59:37 Redo log (from LSN 1578036179 to 1661676169) was copied.
 
[00] 2020-07-09 09:59:37 xtrabackup_checkpoints
 
[00] 2020-07-09 09:59:37 ib_buffer_pool
 
[00] 2020-07-09 09:59:37 backup-my.cnf
 
[00] 2020-07-09 09:59:37 xtrabackup_info
 
[00] 2020-07-09 09:59:37 completed OK!

Checking the saved position on the target node:

# cat /var/lib/mysql/xtrabackup_binlog_info 
mariadb-bin.000004	512291507	0-1-41,1-1-2426302

Preparing backup on target node (please note the position has changed):

# mariabackup --prepare --use-memory=1G --target-dir=/var/lib/mysql
 
mariabackup based on MariaDB server 10.4.13-MariaDB Linux (x86_64)
 
[00] 2020-07-09 10:00:12 cd to /var/lib/mysql/
 
[00] 2020-07-09 10:00:12 This target seems to be not prepared yet.
 
[00] 2020-07-09 10:00:12 mariabackup: using the following InnoDB configuration for recovery:
 
[00] 2020-07-09 10:00:12 innodb_data_home_dir = .
 
[00] 2020-07-09 10:00:12 innodb_data_file_path = ibdata1:12M:autoextend
 
[00] 2020-07-09 10:00:12 innodb_log_group_home_dir = .
 
[00] 2020-07-09 10:00:12 InnoDB: Using Linux native AIO
 
[00] 2020-07-09 10:00:12 Starting InnoDB instance for recovery.
 
[00] 2020-07-09 10:00:12 mariabackup: Using 1073741824 bytes for buffer pool (set by --use-memory parameter)
 
2020-07-09 10:00:12 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2020-07-09 10:00:12 0 [Note] InnoDB: Uses event mutexes
 
2020-07-09 10:00:12 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
2020-07-09 10:00:12 0 [Note] InnoDB: Number of pools: 1
 
2020-07-09 10:00:12 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
2020-07-09 10:00:12 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 1, chunk size = 1G
 
2020-07-09 10:00:12 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-07-09 10:00:12 0 [Note] InnoDB: page_cleaner coordinator priority: -20
 
2020-07-09 10:00:12 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1602230839
 
2020-07-09 10:00:17 0 [Note] InnoDB: Starting final batch to recover 2535 pages from redo log.
 
2020-07-09 10:00:20 0 [Note] InnoDB: Last binlog file '/var/lib/mysql/mariadb-bin.000004', position 512548623
 
[00] 2020-07-09 10:00:20 Last binlog file /var/lib/mysql/mariadb-bin.000004, position 512548623
 
[00] 2020-07-09 10:00:20 mariabackup: Recovered WSREP position: 658a888a-c1b7-11ea-aebd-036b2ff6acd3:2426699
 
[00] 2020-07-09 10:00:20 completed OK!

Setting up and starting target node:

# chown -R mysql:mysql /var/lib/mysql/*
 
# chown mysql:mysql /var/lib/mysql/
 
# service mariadb start
 
Redirecting to /bin/systemctl start mariadb.service
 
# mysql -A
 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
 
Your MariaDB connection id is 8
 
Server version: 10.4.13-MariaDB MariaDB Server
 
 
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
 
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
 
 
MariaDB [(none)]>

Trying to set up replication with the original position from the file - this is incorrect and will yeld duplicates:

MariaDB [(none)]> change master to master_host='192.168.2.90', master_port = 3306, master_user = 'sst', master_password = 'sst', master_log_file = 'mariadb-bin.000004', master_log_pos = 512291507;
 
Query OK, 0 rows affected (0.045 sec)
 
 
 
MariaDB [(none)]> start slave;
 
Query OK, 0 rows affected (0.002 sec)
 
 
 
MariaDB [(none)]> show slave status\G
 
*************************** 1. row ***************************
 
                Slave_IO_State: Waiting for master to send event
 
                   Master_Host: 192.168.2.90
 
                   Master_User: sst
 
                   Master_Port: 3306
 
                 Connect_Retry: 60
 
               Master_Log_File: mariadb-bin.000004
 
           Read_Master_Log_Pos: 527772019
 
                Relay_Log_File: docker2-relay-bin.000002
 
                 Relay_Log_Pos: 557
 
         Relay_Master_Log_File: mariadb-bin.000004
 
              Slave_IO_Running: Yes
 
             Slave_SQL_Running: No
 
               Replicate_Do_DB: 
           Replicate_Ignore_DB: 
            Replicate_Do_Table: 
        Replicate_Ignore_Table: 
       Replicate_Wild_Do_Table: 
   Replicate_Wild_Ignore_Table: 
                    Last_Errno: 1062
 
                    Last_Error: Could not execute Write_rows_v1 event on table sbtest.sbtest4; Duplicate entry '27058' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log mariadb-bin.000004, end_log_pos 512292093
 
                  Skip_Counter: 0
 
           Exec_Master_Log_Pos: 512291507
 
               Relay_Log_Space: 15481380
 
               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: NULL
 
 Master_SSL_Verify_Server_Cert: No
 
                 Last_IO_Errno: 0
 
                 Last_IO_Error: 
                Last_SQL_Errno: 1062
 
                Last_SQL_Error: Could not execute Write_rows_v1 event on table sbtest.sbtest4; Duplicate entry '27058' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log mariadb-bin.000004, end_log_pos 512292093
 
   Replicate_Ignore_Server_Ids: 
              Master_Server_Id: 1
 
                Master_SSL_Crl: 
            Master_SSL_Crlpath: 
                    Using_Gtid: No
 
                   Gtid_IO_Pos: 
       Replicate_Do_Domain_Ids: 
   Replicate_Ignore_Domain_Ids: 
                 Parallel_Mode: conservative
 
                     SQL_Delay: 0
 
           SQL_Remaining_Delay: NULL
 
       Slave_SQL_Running_State: 
              Slave_DDL_Groups: 0
 
Slave_Non_Transactional_Groups: 0
 
    Slave_Transactional_Groups: 1
 
1 row in set (0.009 sec)
 
 
 
MariaDB [(none)]>

So, the position WILL change in the prepare phase - maybe not always, but often. And I think this is pretty normal, and it always has been this way in xtrabackup.

Please, revert the change in MDEV-18917 and save the updated position from prepare.

Thank you!
Rick

Comment by Vladislav Lesin [ 2020-07-10 ]

The reason why xtrabackup_binlog_info is updated during --prepare in Percona's version of xtrabackup is explained in these two blueprints: https://blueprints.launchpad.net/percona-server/+spec/backup-safe-binlog-info, https://blueprints.launchpad.net/percona-xtrabackup/+spec/lockless-binlog-info. Briefly. Their server has their own implementation of backup locks. When "LOCK TABLES FOR BACKUP" is taken, all non-transactional updates flush binlog coordinates to InnoDB unconditionally. That is why xtrabackup can trust binary log information stored in the InnoDB system header and avoid executing LOCK BINLOG FOR
BACKUP. So the position, stored in xtrabackup_binlog_info, can be changed during backup after it was stored, and this position is restored from InnoDB system header during --prepare.

In the case of mariabackup, the Server has another locks, particularly, BACKUP STAGE BLOCK_COMMIT, which must block any changes in binary logs. xtrabackup_binlog_info is updated under BLOCK_COMMIT lock, that is why --prepare must not change the position in xtrabackup_binlog_info. So the bug is not that mariabackup does not update xtrabackup_binlog_info on --prepare, but that BLOCK_COMMIT allows to update binlog position(at least in InnoDB system header) in some cases. We should find those cases, but not ignore them.

Comment by Geoff Montee (Inactive) [ 2020-07-10 ]

xtrabackup_binlog_pos_innodb was removed because the position in that file was never guaranteed to be consistent with MariaDB. The position in that file was only guaranteed to be consistent with Percona Server, because Percona Server had some special feature that allowed it to be consistent. This is described in more detail in MDEV-18917.

For Mariabackup, users should use xtrabackup_binlog_info instead. If that position is inconsistent for some reason, then it sounds like a bug in Mariabackup.

Comment by Geoff Montee (Inactive) [ 2020-07-10 ]

rpizzi,

6. at end of prepare, mariabackup will spit out a new, updated position (mariadb-bin.000004, position 512548623)

....
[00] 2020-07-09 10:00:20 Last binlog file /var/lib/mysql/mariadb-bin.000004, position 512548623
[00] 2020-07-09 10:00:20 mariabackup: Recovered WSREP position: 658a888a-c1b7-11ea-aebd-036b2ff6acd3:2426699
[00] 2020-07-09 10:00:20 completed OK

Right. This is a known issue in Mariabackup. This issue was already previously reported as MDEV-21611.

Comment by Rick Pizzi [ 2020-07-13 ]

GeoffMontee the position in xtrabackup_binlog_info is incorrect, see my test case above, The correct one is the one that prepare spits out. I keep hearing that this position taken at backup shouldn't change after a prepare but I believe that's not true.

Comment by Rick Pizzi [ 2020-07-13 ]

So I have tried the same test above with Percona Xtrabackup 2.4.20 and MariaDB 10.2.32 and the position stays the same.
So, I will change this bug title to "position saved in xtrabackup_binlog_info is incorrect for replication".

Comment by Vladislav Lesin [ 2021-03-15 ]

There is at least one place where Galera's code bypasses backup locks during DDL execution came from another node, what can cause the effect when binlog position is changed under backup BLOCK_COMMIT lock: MDEV-25136.

Comment by Sergei Golubchik [ 2021-04-13 ]

As the discussion above shows, there seems to be an issue in wsrep code ignoring BACKUP STAGE BLOCK_COMMIT mdl lock.

Comment by Leandro Pacheco (Inactive) [ 2021-07-22 ]

Opened a PR (https://github.com/MariaDB/server/pull/1877) which modifies BACKUP STAGE BLOCK_DDL/BLOCK_COMMIT to behave as FTWRL when wsrep is enabled: replication is paused in the node until BACKUP STAGE END.

Generated at Thu Feb 08 09:19:41 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.