[MDEV-18185] MariaBackup --prepare fails with InnoDB: Failing assertion: 0 in rename_table_in_prepare Created: 2019-01-09  Updated: 2019-01-10  Resolved: 2019-01-09

Status: Closed
Project: MariaDB Server
Component/s: mariabackup
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.4.2, 10.2.22, 10.3.13

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Vladislav Vaintroub
Resolution: Fixed Votes: 0
Labels: None

Attachments: File mbackup_backup.log     File mbackup_prepare.log     File mdev18185-mbackup_backup.log     File mdev18185-mbackup_prepare.log     File mysql.err_orig    
Issue Links:
Relates
relates to MDEV-18201 InnoDB: Operating system error number... Closed

 Description   

10.4 30da40bb8c30

 
mariabackup: cd to /data/bld/10.4/backup/
 
ERROR : File ./test/seq5.ren was not found, but expected during rename processing
 
2019-01-09 15:04:51 0x7f6ed8e60740  InnoDB: Assertion failure in file /data/src/10.4/extra/mariabackup/xtrabackup.cc line 5390
 
InnoDB: Failing assertion: 0
 
 
 
#5  0x000055ef2abf4edf in ut_dbg_assertion_failed (expr=0x55ef2ae277f6 "0", file=0x55ef2ae21fd0 "/data/src/10.4/extra/mariabackup/xtrabackup.cc", line=5390) at /data/src/10.4/storage/innobase/ut/ut0dbg.cc:60
 
#6  0x000055ef2a1479c1 in rename_table_in_prepare (datadir=".", from="test/seq4", to="test/seq5", extension=0x55ef2ae26cd2 ".ibd") at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5390
 
#7  0x000055ef2a1476e7 in rename_table_in_prepare (datadir=".", from="test/seq4", to="test/seq5", extension=0x0) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5379
 
#8  0x000055ef2a147f13 in prepare_handle_ren_files (datadir=0x55ef2ae26481 ".", db=0x7fff454cbe50 "test", filename=0x7fff454cce30 "seq4.ren") at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5414
 
#9  0x000055ef2a147269 in xb_process_datadir (path=0x55ef2ae26481 ".", suffix=0x55ef2ae277aa ".ren", func=0x55ef2a147c61 <prepare_handle_ren_files(char const*, char const*, char const*, void*)>) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5272
 
#10 0x000055ef2a1484ea in xtrabackup_prepare_func (argv=0x55ef2cdeba88) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5462
 
#11 0x000055ef2a14abda in main_low (argv=0x55ef2cdeba88) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:6418
 
#12 0x000055ef2a14a3ee in main (argc=4, argv=0x7fff454ce7f8) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:6211

The backup datadir on which the failure can be observed is available here:
ftp://ftp.askmonty.org/public/mdev18185-backup.tar.gz

It was stored after a failed --prepare attempt, hopefully it didn't corrupt it further. At least next attempts end with the same failure as the initial one.

To reproduce, just run mariabackup --prepare on it.

Notes on the origin of the report. Please be aware it's not easily reproducible the same way, the test is concurrent by nature, and apparently there is a race condition involved.

The problem initially happened by running the concurrent test with MariaBackupFull scenario:

github.com/MariaDB/randgen elenst-dev 5342873c97, github.com/elenst/mariadb-toolbox master 6ded4b71568

 
perl ./runall-new.pl --basedir=/home/travis/server/10.4 --vardir=/home/travis/logs/vardir --duration=350 --threads=4 --seed=1547032787 --reporters=Backtrace,ErrorLog,Deadlock --skip-gendata --gendata-advanced --views --grammar=conf/mariadb/generic-dml.yy --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=10 --mysqld=--loose-innodb-lock-wait-timeout=5 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --filter=/home/travis/mariadb-toolbox/travis/10.4-combo-filter.ff --mysqld=--innodb-encrypt-tables --mysqld=--innodb-encrypt-log --mysqld=--innodb-encryption-threads=4 --mysqld=--aria-encrypt-tables=1 --mysqld=--encrypt-tmp-disk-tables=1 --mysqld=--file-key-management --mysqld=--file-key-management-filename=/home/travis/mariadb-toolbox/data/keys.txt --mysqld=--plugin-load-add=file_key_management --engine=Aria --scenario=MariaBackupFull --redefine=conf/mariadb/alter_table.yy --redefine=conf/mariadb/modules/admin.yy --redefine=conf/mariadb/versioning.yy --redefine=conf/mariadb/sequences.yy

The test performs the following steps:

  • start the server with 

    /home/travis/server/bin/mysqld --no-defaults --basedir=/home/travis/server --lc-messages-dir=/home/travis/server/share --character-sets-dir=/home/travis/server/share/charsets --tmpdir=/home/travis/logs/vardir/tmp --core-file --datadir=/home/travis/logs/vardir/data --max-allowed-packet=128Mb --port=19300 --socket=/home/travis/logs/vardir/mysql.sock --pid-file=/home/travis/logs/vardir/mysql.pid --general-log --general-log-file=/home/travis/logs/vardir/mysql.log --log_output=FILE --max-statement-time=20 --lock-wait-timeout=10 --loose-innodb-lock-wait-timeout=5 --loose-debug_assert_on_not_freed_memory=0 --innodb-encrypt-tables --innodb-encrypt-log --innodb-encryption-threads=4 --aria-encrypt-tables=1 --encrypt-tmp-disk-tables=1 --file-key-management --file-key-management-filename=/home/travis/mariadb-toolbox/data/keys.txt --plugin-load-add=file_key_management

  • run concurrent DML/DDL flow on the server;
  • after ~100 seconds, take the full backup from the running server (succeeded, the log attached as mbackup_backup.log;
  • after another ~100 seconds, shut down the server gracefully (succeeded, the error log is attached as mysql.err_orig;
  • attempt to run mariabackup --prepare failed, the log attached as mbackup_prepare.log;

I have no information yet whether the problem happens on earlier versions.

 Comments   
Comment by Elena Stepanova [ 2019-01-09 ]

Here is a backup dir before any attempts to run prepare:
ftp://ftp.askmonty.org/public/mdev18185-backup_before_prepare.tar.gz

It was stored from a different occurrence of the failure, but the error on prepare is the same, including the guilty file name:

/home/travis/server/10.4/bin/mariabackup based on MariaDB server 10.4.2-MariaDB Linux (x86_64) 
mariabackup: cd to /home/travis/logs/vardir3/backup/
 
Removing ./test/t4.ibd
 
Renaming ./test/t4.new to ./test/t4.ibd
 
Removing ./test/seq10.ibd
 
Renaming ./test/seq10.new to ./test/seq10.ibd
 
Renaming ./test/#sql-6e62_10.new to ./test/#sql-6e62_10.ibd
 
ERROR : File ./test/seq5.ren was not found, but expected during rename processing
 
2019-01-09 16:19:22 0x7f137aeeb740  InnoDB: Assertion failure in file /data/src/10.4/extra/mariabackup/xtrabackup.cc line 5390
 
InnoDB: Failing assertion: 0

Corresponding backup/prepare logs: mdev18185-mbackup_backup.log mdev18185-mbackup_prepare.log

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