Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-18185

MariaBackup --prepare fails with InnoDB: Failing assertion: 0 in rename_table_in_prepare

Details

    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.

      Attachments

        1. mbackup_backup.log
          127 kB
        2. mbackup_prepare.log
          3 kB
        3. mysql.err_orig
          314 kB
        4. mdev18185-mbackup_backup.log
          101 kB
        5. mdev18185-mbackup_prepare.log
          3 kB

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-18201 InnoDB: Operating system error number 2 in a file operation and InnoDB: Cannot open datafile for read-only upon startup on datadir restored from full backup

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            elenst Elena Stepanova created issue -
            elenst Elena Stepanova made changes -
            Field Original Value New Value
            Description {noformat:title=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
            {noformat}

            The backup datadir on which the failure can be observed is available here:
            <wait till I upload it>.

            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:
            {noformat:title=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
            {noformat}

            The test performs the following steps:
            - start the server with
            {noformat}
            /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
            {noformat}
            - 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];

            		{noformat:title=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
            {noformat}

            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:
            {noformat:title=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
            {noformat}

            The test performs the following steps:
            - start the server with
            {noformat}
            /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
            {noformat}
            - 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];

            elenst Elena Stepanova made changes -
            Assignee Elena Stepanova [ elenst ] Vladislav Vaintroub [ wlad ]
            elenst Elena Stepanova added a comment - - edited

            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

            elenst Elena Stepanova added a comment - - edited 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
            elenst Elena Stepanova made changes -
            Description {noformat:title=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
            {noformat}

            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:
            {noformat:title=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
            {noformat}

            The test performs the following steps:
            - start the server with
            {noformat}
            /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
            {noformat}
            - 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];

            		{noformat:title=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
            {noformat}

            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:
            {noformat:title=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
            {noformat}

            The test performs the following steps:
            - start the server with
            {noformat}
            /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
            {noformat}
            - 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.
            elenst Elena Stepanova made changes -
            Attachment mdev18185-mbackup_backup.log [ 46966 ]
            Attachment mdev18185-mbackup_prepare.log [ 46967 ]
            wlad Vladislav Vaintroub made changes -
            Status Open [ 1 ] Confirmed [ 10101 ]
            wlad Vladislav Vaintroub made changes -
            Status Confirmed [ 10101 ] In Progress [ 3 ]
            wlad Vladislav Vaintroub made changes -
            Affects Version/s 10.2 [ 14601 ]
            Affects Version/s 10.3 [ 22126 ]
            wlad Vladislav Vaintroub made changes -
            issue.field.resolutiondate 2019-01-09 21:43:27.0 2019-01-09 21:43:27.223
            wlad Vladislav Vaintroub made changes -
            Fix Version/s 10.4.2 [ 23229 ]
            Fix Version/s 10.3.13 [ 23215 ]
            Fix Version/s 10.2.22 [ 23250 ]
            Fix Version/s 10.4 [ 22408 ]
            Resolution Fixed [ 1 ]
            Status In Progress [ 3 ] Closed [ 6 ]
            wlad Vladislav Vaintroub made changes -
            serg Sergei Golubchik made changes -
            Workflow MariaDB v3 [ 91595 ] MariaDB v4 [ 155477 ]

            People

              wlad Vladislav Vaintroub
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.