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

Incremental prepare tries to access page which is out of tablespace bounds.

    Details

      Description

      10.4 30da40bb8c3

      2019-01-09 22:15:09 0 [Note] InnoDB: Starting final batch to recover 2011 pages from redo log.
      2019-01-09 22:15:09 0 [ERROR] [FATAL] InnoDB: Trying to read page number 96 in space 1239, space name test/t8#P#ver_pn, which is outside the tablespace bounds. Byte offset 0, len 16384
      190109 22:15:09 [ERROR] mysqld got signal 6 ;
       
      #4  0x00007fdd4b54d3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
      #5  0x000055da0a61be66 in ib::fatal::~fatal (this=0x7fff327b27d0, __in_chrg=<optimized out>) at /data/src/10.4/storage/innobase/ut/ut0ut.cc:765
      #6  0x000055da0a39c232 in fil_report_invalid_page_access (block_offset=96, space_id=1239, space_name=0x55da0d79b120 "test/t8#P#ver_pn", byte_offset=0, len=16384, is_read=true) at /data/src/10.4/storage/innobase/fil/fil0fil.cc:4141
      #7  0x000055da0a39ca5d in fil_io (type=..., sync=false, page_id=..., page_size=..., byte_offset=0, len=16384, buf=0x7fdd4695c000, message=0x7fdd4467aa98, ignore_missing_space=false) at /data/src/10.4/storage/innobase/fil/fil0fil.cc:4287
      #8  0x000055da0a34fbb5 in buf_read_page_low (err=0x7fff327b2f28, sync=false, type=64, mode=132, page_id=..., page_size=..., unzip=true, ignore_missing_space=false) at /data/src/10.4/storage/innobase/buf/buf0rea.cc:181
      #9  0x000055da0a351871 in buf_read_recv_pages (sync=false, space_id=1239, page_nos=0x7fff327b3110, n_stored=32) at /data/src/10.4/storage/innobase/buf/buf0rea.cc:924
      #10 0x000055da0a4adc6b in recv_read_in_area (page_id=...) at /data/src/10.4/storage/innobase/log/log0recv.cc:2001
      #11 0x000055da0a4ae2d4 in recv_apply_hashed_log_recs (last_batch=true) at /data/src/10.4/storage/innobase/log/log0recv.cc:2106
      #12 0x000055da0a5c4393 in srv_start (create_new_db=false) at /data/src/10.4/storage/innobase/srv/srv0start.cc:1861
      #13 0x000055da09b62845 in innodb_init () at /data/src/10.4/extra/mariabackup/xtrabackup.cc:1988
      #14 0x000055da09b6c9d8 in xtrabackup_prepare_func (argv=0x55da0cfd6a88) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5594
      #15 0x000055da09b6ebda in main_low (argv=0x55da0cfd6a88) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:6418
      #16 0x000055da09b6e3ee in main (argc=7, argv=0x7fff327ba398) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:6211
      

      The log is attached as mbackup_prepare_1.log

      Backup dirs before any attempts to prepare are stored here:
      ftp://ftp.askmonty.org/public/mdev18194/

      backup_0 is the initial full backup.
      backup_1 is the incremental backup.

      To reproduce, unpack the backups and run

      bin/mariabackup --prepare --apply-log-only --innodb-file-io-threads=1 --target-dir=backup_0 --user=root
      bin/mariabackup --prepare --apply-log-only --innodb-file-io-threads=1 --target-dir=backup_0 --incremental-dir=backup_1 --user=root
      


      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 MariaBackupIncremental scenario:

      github.com/MariaDB/randgen elenst-dev 0ebbe452a69, github.com/elenst/mariadb-toolbox master 6ded4b71568

      perl ./runall-new.pl --basedir=/home/travis/server/10.4 --vardir=/home/travis/logs/vardir2 --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=MariaBackupIncremental --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

        "--no-defaults" "--basedir=/home/travis/server/10.4" "--lc-messages-dir=/home/travis/server/10.4/share" "--character-sets-dir=/home/travis/server/10.4/share/charsets" "--tmpdir=/home/travis/logs/vardir2/tmp" "--core-file" "--datadir=/home/travis/logs/vardir2/data" "--max-allowed-packet=128Mb" "--port=19300" "--socket=/home/travis/logs/vardir2/mysql.sock" "--pid-file=/home/travis/logs/vardir2/mysql.pid" "--general-log" "--general-log-file=/home/travis/logs/vardir2/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 ~1 min, take the full backup from the running server:

        bin/mariabackup --backup --target-dir=/home/travis/logs/vardir2/backup_0 --protocol=tcp --port=19300 --user=root
        

        (succeeded, the log attached as mbackup_backup_0.log;

      • after another ~1 minute, run the incremental backup as

        bin/mariabackup --backup --target-dir=/home/travis/logs/vardir2/backup_1 --incremental-basedir=/home/travis/logs/vardir2/backup_0 --protocol=tcp --port=19300 --user=root
        

        (succeeded, the log attached as mbackup_backup_1.log;

      • after another ~1 minute, run the incremental backup again as

        bin/mariabackup --backup --target-dir=/home/travis/logs/vardir2/backup_2 --incremental-basedir=/home/travis/logs/vardir2/backup_1 --protocol=tcp --port=19300 --user=root
        

        (succeeded, the log attached as mbackup_backup_2.log;

      • let the test flow continue for a little while
      • shut down the server gracefully (succeeded, the error log is attached as mysql.err_orig;
      • run mariabackup --prepare on the full backup as

        bin/mariabackup --prepare --apply-log-only --innodb-file-io-threads=1 --target-dir=/home/travis/logs/vardir2/backup_0 --user=root
        

        (succeeded, the log attached as mbackup_prepare_0.log;

      • run mariabackup --prepare on the first incremental backup as

        bin/mariabackup --prepare --apply-log-only --innodb-file-io-threads=1 --target-dir=/home/travis/logs/vardir2/backup_0 --incremental-dir=/home/travis/logs/vardir2/backup_1 --user=root
        

        (failed, the log is attached as mbackup_prepare_1.log.


      I have no information yet whether the problem happens on 10.1.

        Attachments

        1. mbackup_backup_0.log
          146 kB
        2. mbackup_backup_1.log
          149 kB
        3. mbackup_backup_2.log
          50 kB
        4. mbackup_prepare_0.log
          65 kB
        5. mbackup_prepare_1.log
          53 kB
        6. mysql.err_orig
          270 kB

          Issue Links

            Activity

              People

              • Assignee:
                thiru Thirunarayanan Balathandayuthapani
                Reporter:
                elenst Elena Stepanova
              • Votes:
                2 Vote for this issue
                Watchers:
                8 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: