[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 - Jira

Details

Type: Technical task
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.4(EOL)
Fix Version/s: 10.2.30, 10.3.21, 10.4.11
Component/s: mariabackup, Storage Engine - Aria
Labels:
None

Description

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

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

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.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

aria_recovery.trace
276 kB
2019-06-20 16:20
mbackup_backup_0.log
20 kB
2019-01-10 16:26
mbackup_backup_1.log
21 kB
2019-01-10 16:26
mbackup_backup_2.log
21 kB
2019-01-10 16:26
mbackup_prepare_0.log
2 kB
2019-01-10 16:26
mbackup_prepare_1.log
20 kB
2019-01-10 16:26
mbackup_prepare_2.log
20 kB
2019-01-10 16:26
mbackup_restore.log
18 kB
2019-01-10 16:26
mysql.err
16 kB
2019-01-10 16:28
trial.log
43 kB
2019-01-10 16:28

Issue Links

duplicates

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

Closed

relates to

MDEV-20578 Got error 126 when executing undo undo_key_delete upon Aria crash recovery

Closed

Activity

Ascending order - Click to sort in descending order

Elena Stepanova added a comment - 2019-06-20 16:03 - edited

The test case below reproduces the problem, although with a poor probability.
Also fails with -DEXTRA_DEBUG, aria_recovery.trace is attached.

10.4 02979daa -DEXTRA_DEBUG
2019-06-20 19:17:52 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 20% 31% 41% 51% 61% 72% 83% 94% 100% (0.0 seconds); transactions to roll back: 12019-06-20 19:17:52 0 [ERROR] mysqld: Index for table './test/t2.MAI' is corrupt; try to repair it
2019-06-20 19:17:52 0 [ERROR] mysqld: Got error 126 when executing undo undo_key_insert
2019-06-20 19:17:52 0 [ERROR] mysqld: Aria engine: Undo phase failed

It usually fails for me within 100 attempts, but it can vary on different machines and builds.

Run with

 --repeat=100 --mysqld=--aria-encrypt-tables=1  --mysqld=--file-key-management --mysqld=--file-key-management-filename=`pwd`/std_data/keys.txt --mysqld=--plugin-load-add=file_key_management --mysqld=--aria-checkpoint-interval=5

CREATE TABLE t1 (

    pk integer auto_increment,

    f char(32),

    key (f),

    primary key (pk)

) ENGINE=Aria;

CREATE TABLE t2 (

    f char(32),

    i int,

    pk integer auto_increment,

    key (f),

    primary key (pk)

) ENGINE=Aria;

ALTER TABLE t2 DISABLE KEYS;

INSERT INTO t2 VALUES

('symbolic', -1177681920, NULL),('who', 4, NULL),('w', 828571648, NULL),

('unemployment', 9, NULL),('wtdnoraf', 9, NULL),('tdnoraf', 1, NULL),

('nor', 1249640448, NULL),('p', NULL, NULL),('t', -465436672, NULL),

('orafbz', 0, NULL),('p', -505348096, NULL),('greet', 330039296, NULL),

('p', -991035392, NULL),('rafbz', 5, NULL),('afbzau', 1, NULL),

('fb', 371326976, NULL),('product', NULL, NULL),('bzau', 32178176, NULL),

('zaup', 1, NULL),('upuaxoa', 19464192, NULL),('puaxoa', NULL, NULL),

('l', NULL, NULL),('a', 2077491200, NULL),('oahaenad', NULL, NULL),

('explosion', NULL, NULL),('d', 9, NULL),('d', NULL, NULL),

('aenadu', 5, NULL),('y', 1, NULL),('m', 2, NULL),

('week', -1846804480, NULL),('spokesman', -1024983040, NULL),

('r', 210829312, NULL),('uwkygxpqzxi', NULL, NULL),('r', 4, NULL),

('w', 1166671872, NULL),('kygxp', -1138753536, NULL),

('absorb', -2141716480, NULL),('ygx', 1515061248, NULL),('m', 2, NULL),

('x', 9, NULL),('consider', -771424256, NULL),('z', NULL, NULL),

('cue', NULL, NULL),('institutional', 9, NULL),('wait', 895942656, NULL),

('p', 0, NULL),('ymfzlm', NULL, NULL),('specialty', -913768448, NULL),

('v', 543424512, NULL);

ALTER TABLE t2 ENABLE KEYS;

--connect (con1,localhost,root,,test)

--connect (con2,localhost,root,,test)

--connect (con3,localhost,root,,test)

SELECT * INTO OUTFILE 'load.data' FROM t2;

DELETE FROM t2 ORDER BY pk LIMIT 2;

--connection con1

INSERT INTO t2 () VALUES ();

--error ER_DUP_ENTRY

INSERT INTO t1 (pk, f) SELECT i, f FROM t2;

--send

  UPDATE t1 SET f = 'foo';

--connection con2

--send

  LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t2;

--connection default

--let $shutdown_timeout= 0

--source include/restart_mysqld.inc

DROP TABLE t1, t2;

--let $datadir= `SELECT @@datadir`

--remove_file $datadir/test/load.data

Couldn't reproduce with the test case above on 10.3.

Elena Stepanova added a comment - 2019-06-20 16:03 - edited The test case below reproduces the problem, although with a poor probability. Also fails with -DEXTRA_DEBUG , aria_recovery.trace is attached. 10.4 02979daa -DEXTRA_DEBUG 2019-06-20 19:17:52 0 [Note] mysqld: Aria engine: starting recovery recovered pages: 0% 10% 20% 31% 41% 51% 61% 72% 83% 94% 100% (0.0 seconds); transactions to roll back: 12019-06-20 19:17:52 0 [ERROR] mysqld: Index for table './test/t2.MAI' is corrupt; try to repair it 2019-06-20 19:17:52 0 [ERROR] mysqld: Got error 126 when executing undo undo_key_insert 2019-06-20 19:17:52 0 [ERROR] mysqld: Aria engine: Undo phase failed It usually fails for me within 100 attempts, but it can vary on different machines and builds. Run with --repeat=100 --mysqld=--aria-encrypt-tables=1 --mysqld=--file-key-management --mysqld=--file-key-management-filename=`pwd`/std_data/keys.txt --mysqld=--plugin-load-add=file_key_management --mysqld=--aria-checkpoint-interval=5 CREATE TABLE t1 ( pk integer auto_increment, f char (32), key (f), primary key (pk) ) ENGINE=Aria; CREATE TABLE t2 ( f char (32), i int , pk integer auto_increment, key (f), primary key (pk) ) ENGINE=Aria; ALTER TABLE t2 DISABLE KEYS; INSERT INTO t2 VALUES ( 'symbolic' , -1177681920, NULL ),( 'who' , 4, NULL ),( 'w' , 828571648, NULL ), ( 'unemployment' , 9, NULL ),( 'wtdnoraf' , 9, NULL ),( 'tdnoraf' , 1, NULL ), ( 'nor' , 1249640448, NULL ),( 'p' , NULL , NULL ),( 't' , -465436672, NULL ), ( 'orafbz' , 0, NULL ),( 'p' , -505348096, NULL ),( 'greet' , 330039296, NULL ), ( 'p' , -991035392, NULL ),( 'rafbz' , 5, NULL ),( 'afbzau' , 1, NULL ), ( 'fb' , 371326976, NULL ),( 'product' , NULL , NULL ),( 'bzau' , 32178176, NULL ), ( 'zaup' , 1, NULL ),( 'upuaxoa' , 19464192, NULL ),( 'puaxoa' , NULL , NULL ), ( 'l' , NULL , NULL ),( 'a' , 2077491200, NULL ),( 'oahaenad' , NULL , NULL ), ( 'explosion' , NULL , NULL ),( 'd' , 9, NULL ),( 'd' , NULL , NULL ), ( 'aenadu' , 5, NULL ),( 'y' , 1, NULL ),( 'm' , 2, NULL ), ( 'week' , -1846804480, NULL ),( 'spokesman' , -1024983040, NULL ), ( 'r' , 210829312, NULL ),( 'uwkygxpqzxi' , NULL , NULL ),( 'r' , 4, NULL ), ( 'w' , 1166671872, NULL ),( 'kygxp' , -1138753536, NULL ), ( 'absorb' , -2141716480, NULL ),( 'ygx' , 1515061248, NULL ),( 'm' , 2, NULL ), ( 'x' , 9, NULL ),( 'consider' , -771424256, NULL ),( 'z' , NULL , NULL ), ( 'cue' , NULL , NULL ),( 'institutional' , 9, NULL ),( 'wait' , 895942656, NULL ), ( 'p' , 0, NULL ),( 'ymfzlm' , NULL , NULL ),( 'specialty' , -913768448, NULL ), ( 'v' , 543424512, NULL ); ALTER TABLE t2 ENABLE KEYS; --connect (con1,localhost,root,,test) --connect (con2,localhost,root,,test) --connect (con3,localhost,root,,test) SELECT * INTO OUTFILE 'load.data' FROM t2; DELETE FROM t2 ORDER BY pk LIMIT 2; --connection con1 INSERT INTO t2 () VALUES (); --error ER_DUP_ENTRY INSERT INTO t1 (pk, f) SELECT i, f FROM t2; --send UPDATE t1 SET f = 'foo' ; --connection con2 --send LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t2; --connection default --let $shutdown_timeout= 0 --source include/restart_mysqld.inc DROP TABLE t1, t2; --let $datadir= `SELECT @@datadir` --remove_file $datadir/test/load.data Couldn't reproduce with the test case above on 10.3.

Michael Widenius added a comment - 2019-06-24 10:27

I checked all backup_before_prepare* tar file and Aria recovery works on all of them
I will talk with Vlad Lesin to understand how backup_0 is created.

Michael Widenius added a comment - 2019-06-24 10:27 I checked all backup_before_prepare* tar file and Aria recovery works on all of them I will talk with Vlad Lesin to understand how backup_0 is created.

Vladislav Lesin added a comment - 2019-12-18 18:01

As there is no mention about copying Aria log file during --prepare in mariabackup logs, I consider this bug as a duplicate of ~~MDEV-18310~~.

Vladislav Lesin added a comment - 2019-12-18 18:01 As there is no mention about copying Aria log file during --prepare in mariabackup logs, I consider this bug as a duplicate of MDEV-18310 .

MariaDB Server

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

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration