Aria crash recovery failures (MDEV-19813)

[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 Created: 2019-01-10  Updated: 2019-12-18  Resolved: 2019-12-18

Status: Closed
Project: MariaDB Server
Component/s: mariabackup, Storage Engine - Aria
Affects Version/s: 10.4
Fix Version/s: 10.2.30, 10.3.21, 10.4.11

Type: Technical task Priority: Major
Reporter: Elena Stepanova Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: None

Attachments: File aria_recovery.trace     File mbackup_backup_0.log     File mbackup_backup_1.log     File mbackup_backup_2.log     File mbackup_prepare_0.log     File mbackup_prepare_1.log     File mbackup_prepare_2.log     File mbackup_restore.log     File mysql.err     File trial.log    
Issue Links:
Duplicate
duplicates MDEV-18310 Aria engine: Undo phase failed with "... Closed
Relates
relates to MDEV-20578 Got error 126 when executing undo und... Closed

 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.



 Comments   
Comment by Elena Stepanova [ 2019-06-20 ]

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.

Comment by Michael Widenius [ 2019-06-24 ]

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.

Comment by Vladislav Lesin [ 2019-12-18 ]

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.

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