[MDEV-28781] mariabackup rsync fails to copy /var/lib/mysql/var/lib/mysql/ib_buffer_pool Created: 2022-06-09  Updated: 2022-08-19  Resolved: 2022-08-01

Status: Closed
Project: MariaDB Server
Component/s: mariabackup
Affects Version/s: 10.3.35, 10.4.25, 10.5.16, 10.6.8
Fix Version/s: 10.3.36, 10.4.26, 10.5.17, 10.6.9, 10.7.5, 10.8.4, 10.9.2, 10.10.0

Type: Bug Priority: Blocker
Reporter: Cyprien Nicolas Assignee: Julius Goryavsky
Resolution: Fixed Votes: 2
Labels: None
Environment:

Debian Linux 10.12, using MariaDB APT repository


Issue Links:
Duplicate
is duplicated by MDEV-28814 MariaDB-10.6.8 mariabackup --rsync op... Closed
Problem/Incident
is caused by MDEV-27524 Incorrect binlogs after Galera SST us... Closed
Relates
relates to MDEV-28758 Mariabackup copies binary logs to bac... Closed

 Description   

Since I upgraded the mariadb stack from 10.5.15 to 10.5.16 I observe rsync errors during the daily mariabackup

Command :

/usr/bin/mariabackup --backup --rsync --tmpdir=/tmp --slave-info --target-dir=/var/backups/percona

Log output (end) :

[00] 2022-06-09 08:42:14 Starting prep copy of non-InnoDB tables and files
[00] 2022-06-09 08:42:14 Starting rsync as: rsync -t . --files-from=/tmp/xtrabackup_rsyncfiles_pass1 /var/backups/percona/
2022-06-09  8:42:14 0 [Note] InnoDB: Read redo log up to LSN=5532145282560
[00] 2022-06-09 08:42:14 >> log scanned up to (5532145282501)
rsync: link_stat "/var/lib/mysql/var/lib/mysql/ib_buffer_pool" failed: No such file or directory (2)
[00] 2022-06-09 08:42:15 >> log scanned up to (5532145282501)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1207) [sender=3.1.3]
[00] 2022-06-09 08:42:15 rsync finished successfully.
[00] 2022-06-09 08:42:15 Finished a prep copy of non-InnoDB tables and files
[00] 2022-06-09 08:42:15 Acquiring BACKUP LOCKS...
[00] 2022-06-09 08:42:15 Starting to backup non-InnoDB tables and files
[00] 2022-06-09 08:42:15 Starting rsync as: rsync -t . --files-from=/tmp/xtrabackup_rsyncfiles_pass2 /var/backups/percona/
rsync: link_stat "/var/lib/mysql/var/lib/mysql/ib_buffer_pool" failed: No such file or directory (2)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1207) [sender=3.1.3]
[00] 2022-06-09 08:42:15 Error: rsync failed with error code 1
mariabackup: Stopping log copying thread.[00] 2022-06-09 08:42:15 >> log scanned up to (5532145282501)

The files /tmp/xtrabackup_rsyncfiles_pass1 and /tmp/xtrabackup_rsyncfiles_pass2 contains relative paths in the form of ./<dbname>/<tablename>.<ext> except for the last line containing the absolute path /var/lib/mysql/ib_buffer_pool.

I upgraded from 10.3 to 10.5.15 mid-May, and it was working fine until the 10.5.16 upgrade last week.

Below are the defaults for mysqld and mariabackup, ***** replace redacted names.

mysqld --print-defaults

mysqld would have been started with the following arguments:
--socket=/run/mysqld/mysqld.sock --innodb_autoextend_increment=1 --innodb_buffer_pool_instances=1 --innodb_buffer_pool_size=2G --innodb_doublewrite=1 --innodb_file_format=Barracuda --innodb_file_per_table=1 --innodb_flush_log_at_trx_commit=1 --innodb_flush_log_at_trx_commit=2 --innodb_large_prefix=ON --innodb_lock_wait_timeout=60 --innodb_log_buffer_size=128M --innodb_log_file_size=48M --innodb_log_files_in_group=2 --innodb_log_group_home_dir=/var/lib/mysql/ --innodb_max_dirty_pages_pct=25 --innodb_thread_concurrency=16 --innodb_file_format=barracuda --sql_mode=ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION --innodb_adaptive_hash_index=OFF --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306 --basedir=/usr --datadir=/var/lib/mysql --tmpdir=/tmp --lc-messages-dir=/usr/share/mysql --skip-external-locking --bind-address=0.0.0.0 --key_buffer_size=16M --max_allowed_packet=16M --thread_stack=192K --thread_cache_size=8 --myisam_recover_options=BACKUP --query_cache_limit=1M --query_cache_size=16M --log_error=/var/log/mysql/error.log --expire_logs_days=10 --max_binlog_size=100M --character-set-server=utf8mb4 --collation-server=utf8mb4_general_ci --sql_mode=ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION --tmpdir=/var/mysqltmp --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306 --basedir=/usr --datadir=/var/lib/mysql --tmpdir=/tmp --language=/usr/share/mysql/english --long_query_time=2 --log_bin=/var/log/mysql/mysql-bin.log --server-id=1 --innodb_autoextend_increment=1 --innodb_buffer_pool_instances=1 --innodb_buffer_pool_size=2G --innodb_default_row_format=dynamic --innodb_doublewrite=1 --innodb_file_format=Barracuda --innodb_file_per_table=1 --innodb_flush_log_at_trx_commit=1 --innodb_flush_log_at_trx_commit=2 --innodb_large_prefix=ON --innodb_lock_wait_timeout=60 --innodb_log_buffer_size=128M --innodb_log_file_size=48M --innodb_log_files_in_group=2 --innodb_log_group_home_dir=/var/lib/mysql/ --innodb_max_dirty_pages_pct=25 --innodb_thread_concurrency=16 --long_query_time=0.1 --key_buffer=256M --max_allowed_packet=16M --max_connections=1000 --myisam-recover=BACKUP --query_cache_limit=1M --query_cache_size=128M --table_cache=256 --thread_cache_size=4 --expire_logs_days=11 --max_binlog_size=101M --binlog_do_db=***** --log-slave-updates --binlog_format=ROW --skip-slave-start=yes --log_bin_trust_function_creators=ON --ssl --ssl-ca=/etc/mysql/certs/ca-mysql-*****1-cert.pem --ssl-cert=/etc/mysql/certs/*****1-cert.pem --ssl-key=/etc/mysql/certs/*****1-key.pem --slow_query_log=ON --log_warnings=2 --general_log=OFF --log_error=/var/log/mysql/error.log --slow_query_log_file=/var/log/mysql/mysql-slow.log 

mariabackup --print-defaults

mariabackup would have been started with the following arguments:
--socket=/run/mysqld/mysqld.sock --innodb_autoextend_increment=1 --innodb_buffer_pool_instances=1 --innodb_buffer_pool_size=2G --innodb_doublewrite=1 --innodb_file_format=Barracuda --innodb_file_per_table=1 --innodb_flush_log_at_trx_commit=1 --innodb_flush_log_at_trx_commit=2 --innodb_large_prefix=ON --innodb_lock_wait_timeout=60 --innodb_log_buffer_size=128M --innodb_log_file_size=48M --innodb_log_files_in_group=2 --innodb_log_group_home_dir=/var/lib/mysql/ --innodb_max_dirty_pages_pct=25 --innodb_thread_concurrency=16 --innodb_file_format=barracuda --sql_mode=ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION --innodb_adaptive_hash_index=OFF --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306 --basedir=/usr --datadir=/var/lib/mysql --tmpdir=/tmp --lc-messages-dir=/usr/share/mysql --skip-external-locking --bind-address=0.0.0.0 --key_buffer_size=16M --max_allowed_packet=16M --thread_stack=192K --thread_cache_size=8 --myisam_recover_options=BACKUP --query_cache_limit=1M --query_cache_size=16M --log_error=/var/log/mysql/error.log --expire_logs_days=10 --max_binlog_size=100M --character-set-server=utf8mb4 --collation-server=utf8mb4_general_ci --sql_mode=ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION --tmpdir=/var/mysqltmp --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306 --basedir=/usr --datadir=/var/lib/mysql --tmpdir=/tmp --language=/usr/share/mysql/english --long_query_time=2 --log_bin=/var/log/mysql/mysql-bin.log --server-id=1 --innodb_autoextend_increment=1 --innodb_buffer_pool_instances=1 --innodb_buffer_pool_size=2G --innodb_default_row_format=dynamic --innodb_doublewrite=1 --innodb_file_format=Barracuda --innodb_file_per_table=1 --innodb_flush_log_at_trx_commit=1 --innodb_flush_log_at_trx_commit=2 --innodb_large_prefix=ON --innodb_lock_wait_timeout=60 --innodb_log_buffer_size=128M --innodb_log_file_size=48M --innodb_log_files_in_group=2 --innodb_log_group_home_dir=/var/lib/mysql/ --innodb_max_dirty_pages_pct=25 --innodb_thread_concurrency=16 --long_query_time=0.1 --key_buffer=256M --max_allowed_packet=16M --max_connections=1000 --myisam-recover=BACKUP --query_cache_limit=1M --query_cache_size=128M --table_cache=256 --thread_cache_size=4 --expire_logs_days=11 --max_binlog_size=101M --binlog_do_db=***** --log-slave-updates --binlog_format=ROW --skip-slave-start=yes --log_bin_trust_function_creators=ON --ssl --ssl-ca=/etc/mysql/certs/ca-mysql-*****1-cert.pem --ssl-cert=/etc/mysql/certs/*****1-cert.pem --ssl-key=/etc/mysql/certs/*****1-key.pem --slow_query_log=ON --log_warnings=2 --general_log=OFF --log_error=/var/log/mysql/error.log --slow_query_log_file=/var/log/mysql/mysql-slow.log 



 Comments   
Comment by Cyprien Nicolas [ 2022-06-09 ]

I just got a report from a collegue (same company) having the exact same issue after an upgrade from 10.3.27 to 10.3.35 yesterday.

Comment by Denis [ 2022-06-09 ]

the same issue with MariaDB-backup-10.6.8-1.el7.centos.x86_64, downgrading to the MariaDB-backup-10.6.7-1.el7.centos.x86_64 is solve issue

Comment by Nuno [ 2022-06-26 ]

I'm getting the exact same issue now, with MariaDB 10.8.3-MariaDB-log on AlmaLinux.

But same also happens on another database in a Docker container with 10.8.3-MariaDB-1:10.8.3+maria~jammy

AlmaLinux:

[00] 2022-06-26 07:01:10 Starting prep copy of non-InnoDB tables and files
[00] 2022-06-26 07:01:10 Starting rsync as: rsync -t . --files-from=/var/lib/mysqltmp/xtrabackup_rsyncfiles_pass1 /opt/backup/mysql/
rsync: link_stat "/var/lib/mysql/var/lib/mysql/ib_buffer_pool" failed: No such file or directory (2)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1189) [sender=3.1.3]
[00] 2022-06-26 07:01:10 rsync finished successfully.
[00] 2022-06-26 07:01:10 Finished a prep copy of non-InnoDB tables and files
[00] 2022-06-26 07:01:10 Acquiring BACKUP LOCKS...
[00] 2022-06-26 07:01:10 Starting to backup non-InnoDB tables and files
[00] 2022-06-26 07:01:10 Starting rsync as: rsync -t . --files-from=/var/lib/mysqltmp/xtrabackup_rsyncfiles_pass2 /opt/backup/mysql/
rsync: link_stat "/var/lib/mysql/var/lib/mysql/ib_buffer_pool" failed: No such file or directory (2)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1189) [sender=3.1.3]
[00] 2022-06-26 07:01:10 Error: rsync failed with error code 1
mariabackup: Stopping log copying thread.[00] 2022-06-26 07:01:10 >> log scanned up to (10109424124814)

Docker container:

[00] 2022-06-26 07:01:31 Starting prep copy of non-InnoDB tables and files
[00] 2022-06-26 07:01:31 Starting rsync as: rsync -t . --files-from=/tmp/xtrabackup_rsyncfiles_pass1 /backup/
rsync: [sender] link_stat "/var/lib/mysql/var/lib/mysql/ib_buffer_pool" failed: No such file or directory (2)
[00] 2022-06-26 07:01:32 >> log scanned up to (94185383726)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1333) [sender=3.2.3]
[00] 2022-06-26 07:01:32 rsync finished successfully.
[00] 2022-06-26 07:01:32 Finished a prep copy of non-InnoDB tables and files
[00] 2022-06-26 07:01:32 Acquiring BACKUP LOCKS...
[00] 2022-06-26 07:01:32 Starting to backup non-InnoDB tables and files
[00] 2022-06-26 07:01:32 Starting rsync as: rsync -t . --files-from=/tmp/xtrabackup_rsyncfiles_pass2 /backup/
rsync: [sender] link_stat "/var/lib/mysql/var/lib/mysql/ib_buffer_pool" failed: No such file or directory (2)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1333) [sender=3.2.3]
[00] 2022-06-26 07:01:32 Error: rsync failed with error code 1
mariabackup: Stopping log copying thread.[00] 2022-06-26 07:01:32 >> log scanned up to (94185383726)

igor, serg, marko, Any ideas? This might be critical as it is breaking our backups.

Thank you!

Comment by Sergei Golubchik [ 2022-06-28 ]

will be fixed in the next release

Comment by Julius Goryavsky [ 2022-08-01 ]

Fixed by MDEV-28758
(related commits: https://github.com/MariaDB/server/commit/5b4154373a93b323c3502692c46dcc51b1731785 and
https://github.com/MariaDB/server/commit/5197519f4f7b31c61e3abccf75650e5356aecd4c)

Comment by Nuno [ 2022-08-19 ]

I confirm this is resolved.
Thank you!

Generated at Thu Feb 08 10:03:26 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.