Vladislav Lesin added a comment - 2020-07-06 15:07 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+.

Rick Pizzi (Inactive) added a comment - 2020-07-07 07:13 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

Rick Pizzi (Inactive) added a comment - 2020-07-07 07:55 - edited 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!

Rick Pizzi (Inactive) added a comment - 2020-07-09 08:15 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

Vladislav Lesin added a comment - 2020-07-10 11:38 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.

Geoff Montee (Inactive) added a comment - 2020-07-10 17:01 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.

Geoff Montee (Inactive) added a comment - 2020-07-10 17:06 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 .

Rick Pizzi (Inactive) added a comment - 2020-07-13 08:43 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.

Rick Pizzi (Inactive) added a comment - 2020-07-13 10:18 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".

Vladislav Lesin added a comment - 2021-03-15 08:33 - edited 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 .

Sergei Golubchik added a comment - 2021-04-13 14:46 As the discussion above shows, there seems to be an issue in wsrep code ignoring BACKUP STAGE BLOCK_COMMIT mdl lock.

Leandro Pacheco (Inactive) added a comment - 2021-07-22 14:50 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.