Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-19813 Aria crash recovery failures
  3. MDEV-18310

Aria engine: Undo phase failed with "Got error 121 when executing undo undo_key_delete" upon startup on datadir restored from incremental backup

Details

    Description

      Note: see also MDEV-18203 – different error, otherwise the same.

      10.4 4edb29380c980

      		 
      2019-01-18 21:26:44 0 [Note] mysqld: Aria engine: starting recovery
      		 
      recovered pages: 0% 10% 20% 30% 40% 50% 60% 70% 80% 90% 100% (20.8 seconds); transactions to roll back: 1
      		 
      Got error 121 when executing undo undo_key_delete
      		 
      2019-01-18 21:27:05 0 [ERROR] mysqld: Aria engine: Undo phase failed
      		 
      tables to flush: 8 7 6 5 4 3 2 1 0
      		 
      2019-01-18 21:27:05 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
      		 
      2019-01-18 21:27:05 0 [ERROR] Plugin 'Aria' init function returned error.
      		 
      2019-01-18 21:27:05 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.

      The backup dirs are here:
      ftp://ftp.askmonty.org/public/mdev18310

      backup_before_prepare_0 is the initial full backup
      backup_before_prepare_1 is the 1st incremental backup
      backup_before_prepare_2 is the 1st incremental backup
      backup_0 is the prepared backup after all prepare were executed on it.

      To reproduce the failure, restore backup_0 to the datadir and run the server on it. All server default options are sufficient.

      If you have doubts about the correctness of prepare, you can run it on non-prepared backups.

      mariabackup logs from all stages are attached with hopefully self-explanatory names (mbackup*.log).

      I have no information yet whether it affects previous versions.

      Notes on the origin of the report

      Please be aware it's not necessarily reproducible the same way.

      https://travis-ci.org/elenst/travis-tests/jobs/481392097
      # 2528 22 2
      Server: 10.4 4edb29380c98058a28e49c826bacee9c83473579
      Tests: elenst-dev 19e81706fbfffc28d2f71d2c22b361ecd4593d9a
      Toolbox: c949673e7706f81f5369ecd91b587b09674ece2b

      perl ./runall-new.pl --basedir=/home/travis/server --vardir=/home/travis/logs/vardir --duration=350 --threads=4 --seed=1547846609 --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 --engine=Aria --scenario=MariaBackupIncremental


      The test log is attached as trial.log

      Attachments

        1. mbackup_backup_0.log
          22 kB
        2. mbackup_backup_1.log
          22 kB
        3. mbackup_backup_2.log
          22 kB
        4. mbackup_prepare_0.log
          2 kB
        5. mbackup_prepare_1.log
          22 kB
        6. mbackup_prepare_2.log
          22 kB
        7. mbackup_restore.log
          19 kB
        8. mysql.err
          17 kB
        9. mysql.err_orig
          3 kB
        10. trial.log
          41 kB

        Issue Links

          is duplicated by

          Technical task - A technical task. MDEV-18203 Aria engine: Undo phase failed with "Got error 126 when executing undo undo_key_insert" upon startup on datadir restored from incremental backup

          • Major - Major loss of function.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-20578 Got error 126 when executing undo undo_key_delete upon Aria crash recovery

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            monty Michael Widenius added a comment -

            I checked the file backup_0.tar.gz

            The reason Aria recover fails is that there are not all Aria redo files in the backup.

            The only files that exists is:
            aria_log.00000001 of size 83009536
            This is in LSN: 1,0x4f2a000 in the aria_recovery.trace file

            The undo fails when trying to revert test/t5.

            shell> /my/maria-10.4/storage/maria/aria_chk -dvv test/t5.MAI
            Aria file: test/t5.MAI
            Record format: Block
            Crashsafe: yes
            Character set: latin1_swedish_ci (8)
            File-version: 3
            Creation time: 2019-01-18 23:23:34
            Check/recover time: 2019-01-18 23:23:34
            LSNs: create_rename (1,0x11b21), state_horizon (1,0x9d669e8), skip_redo (1,0x11b8b)

            As can be seen in LSN, the last update to the file was for LSN 1,0x9d669e8, which is bigger than what the aria_log could support.

            Vlad, can you please verify that mariabackup copies ALL aria_log files!
            I will in the mean time add a warning in recovery if we find a LSN on any page that is bigger than the maximum LSN that recovery can restore.

            monty Michael Widenius added a comment - I checked the file backup_0.tar.gz The reason Aria recover fails is that there are not all Aria redo files in the backup. The only files that exists is: aria_log.00000001 of size 83009536 This is in LSN: 1,0x4f2a000 in the aria_recovery.trace file The undo fails when trying to revert test/t5. shell> /my/maria-10.4/storage/maria/aria_chk -dvv test/t5.MAI Aria file: test/t5.MAI Record format: Block Crashsafe: yes Character set: latin1_swedish_ci (8) File-version: 3 Creation time: 2019-01-18 23:23:34 Check/recover time: 2019-01-18 23:23:34 LSNs: create_rename (1,0x11b21), state_horizon (1,0x9d669e8), skip_redo (1,0x11b8b) As can be seen in LSN, the last update to the file was for LSN 1,0x9d669e8, which is bigger than what the aria_log could support. Vlad, can you please verify that mariabackup copies ALL aria_log files! I will in the mean time add a warning in recovery if we find a LSN on any page that is bigger than the maximum LSN that recovery can restore.
            vlad.lesin Vladislav Lesin added a comment -

            The problem is that aria_log* files are not copied on --prepare --incremental step from incremental to destination backup directory. See ibx_copy_incremental_over_full().

            vlad.lesin Vladislav Lesin added a comment - The problem is that aria_log* files are not copied on --prepare --incremental step from incremental to destination backup directory. See ibx_copy_incremental_over_full().

            People

              vlad.lesin Vladislav Lesin
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 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.