Assertion failure occurs when trying to run xtrabackup_51 apply log

[Lachlan Mulcahy]

Took a backup using the following command:

innobackupex-1.5.1 --stream=tar /mysqldb/data --user=root --password=password --slave-info | nc backupHost 10000

Then when I attempted to use xtrabackup_51 to apply-log-only I got an Assertion failure:

Running apply-log with command: xtrabackup_51 --prepare --apply-log-only --target-dir=/data/backups/dbi02-int/13 --defaults-file=/data/backups/dbi02-int/13/backup-my.cnf 1>&2

Error: There was an error applying logs - The process returned code 134. The output from the apply log process is as follows:

xtrabackup: cd to /data/backups/dbi02-int/13
xtrabackup: This target seems to be not prepared yet.
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: The InnoDB memory heap is disabled
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
110322 21:10:11 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
110322 21:10:30 InnoDB: Assertion failure in thread 47127742904576 in file btr/btr0pcur.c line 402
InnoDB: Failing assertion: btr_page_get_prev(next_page, mtr) == buf_frame_get_page_no(page)
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
xtrabackup_51 Ver 1.4 Rev 193 for 5.1.42 unknown-linux-gnu (x86_64)
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(4881 3598676457)
sh: line 1: 6521 Aborted xtrabackup_51 --prepare --apply-log-only --target-dir=/data/backups/dbi02-int/13 --defaults-file=/data/backups/dbi02-int/13/backup-my.cnf 1>&2

Not sure why this occurs??

[Vadim Tkachenko (vadim-tk)]

As we discussed the crash does not happen with 'xtrabackup' binary.
we think it is related to bug in recovery logic in built-in InnoDB/5.1

Corresponding bug is
http://bugs.mysql.com/bug.php?id=60613

[Vadim Tkachenko (vadim-tk)]

Stack trace for reference
(gdb) bt
#0 0x00000032a4c30265 in raise () from /lib64/libc.so.6
#1 0x00000032a4c31d10 in abort () from /lib64/libc.so.6
#2 0x000000000041daa5 in btr_pcur_move_to_next_page (cursor=0x7fff6e41f710, mtr=0x7fff6e41f250) at btr/btr0pcur.c:402
#3 0x00000000004428f2 in btr_pcur_move_to_next_user_rec (in_crash_recovery=1) at ../../storage/innobase/include/btr0pcur.ic:329
#4 dict_check_tablespaces_and_store_max_id (in_crash_recovery=1) at dict/dict0load.c:260
#5 0x00000000004bd60e in innobase_start_or_create_for_mysql () at srv/srv0start.c:1537
#6 0x0000000000407c37 in innodb_init () at xtrabackup.c:2067
#7 xtrabackup_prepare_func () at xtrabackup.c:5104
#8 0x000000000040b11c in main (argc=0, argv=0x15f53978) at xtrabackup.c:5795

[Stewart Smith (stewart)]

This looks like it may have been confirmed - Vadim/Lachlan can either of you verify that for some set of data file it's reproducible?

[Vadim Tkachenko (vadim-tk)]

Stewart,

I do not have repeatable dataset, may be Lachlan has.

If it is comes from bug in build-in InnoDB, I am not sure how much we can do there.

[Lachlan Mulcahy (lachlan-mulcahy)]

I was able to work around in my case by using xtrabackup binary for both backup and restore. The xtrabackup_51 binary seems to just assert.

It is for this reason that I wanted the fix of innobackupex to respect --ibbackup= parameter properly, since it keeps autodetecting that it should use the xtrabackup_51 binary that won't work during apply log.

[Stewart Smith (stewart)]

This looks like it should still be open (probably confirmed) and although we dont' have a good solution yet, keep an eye open.

[Lachlan Mulcahy (lachlan-mulcahy)]

It is entirely possible that this crash was a fault of not putting --defaults-file=/path/to/backup-my.cnf as the first param on the command line.

There is a limitation (some say bug?) that xtrabackup/innoDB will only read the defaults file if it is the first option on the command line. As a result, putting it last will ignore it and can give you an incorrect innodb_data_file_path -- for instance.. specifying the default of ibdata1:10M:autoextend -- this will cause a crash if you in fact had a data file path like ibdata1:2000M;ibdata2:10M:autoextend for your actual files.

I'd suggest anyone seeing an issue like this double check the position of their defaults file on the command line arguments and verify that innodb_data_file_path that xtrabackup spits back at you in the beginning of the output is what you are actually using on the system you backed up.

[Alexey Kopytov (akopytov)]

The problem with --defaults-file being ignored is fixed in 1.7.0beta1: xtrabackup fails with an error message when --defaults-file is not the first command line argument, bug #798488.

[Alexey Kopytov (akopytov)]

Setting to Invalid in 2.1, as support for builtin-based binary has been dropped there.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-64