Segmentation fault on --apply-log-only --prepare

I have all my backups made with Xtrabackup 2.1.3.
On preparing the backup in order to do a restore, Xtrabackup segfaults, and dumps core.
After that, it doesn’t work to re-run the prepare stage as shown below.

So I compiled Xtrabackup 2.1.4 (bzr branch lp:~akopytov/percona-xtrabackup/bugs-1177206-and-1187071-2.1), took a new full backup, and tried restoring that also.
Unfortunately with the same bad result. I have tested restoring databases from 4 different servers, and all my tests fail in the same way.

For me this means that I have 11TB useless backups on disk, and no backup of my databases since I have relied on Xtrabackup only :frowning:

mysqlbackup/sb3/base/2013-07-19_11-00-02/backup-my.cnf" --defaults-group=“mysqld” --prepare --target-dir=/srv/storage
/mysqlbackup/sb3/base/2013-07-19_11-00-02 --apply-log-only --tmpdir=/tmp

Expanding ./accesstoken/refreshtoken.ibd
Expanding ./accesstoken/externalapplication.ibd
Expanding ./accesstoken/accesstokenchannelid.ibd
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 = 856162304
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
130801 2:08:00 InnoDB: The InnoDB memory heap is disabled
130801 2:08:00 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130801 2:08:00 InnoDB: Compressed tables use zlib 1.2.3
130801 2:08:00 InnoDB: Initializing buffer pool, size = 100.0M
130801 2:08:00 InnoDB: Completed initialization of buffer pool
130801 2:08:01 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 899274494433
130801 2:08:01 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files…
InnoDB: Doing recovery: scanned up to log sequence number 899279736832 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 899284979712 (1 %)
InnoDB: Doing recovery: scanned up to log sequence number 899290222592 (2 %)
130801 2:08:40 InnoDB: Starting an apply batch of log records to the database…
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68
69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 899295465472 (2 %)
InnoDB: Doing recovery: scanned up to log sequence number 899300708352 (3 %)
InnoDB: Doing recovery: scanned up to log sequence number 899305951232 (4 %)
InnoDB: Doing recovery: scanned up to log sequence number 899311194112 (4 %)
130801 2:10:11 InnoDB: Starting an apply batch of log records to the database…
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68
69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 899316436992 (5 %)
InnoDB: Doing recovery: scanned up to log sequence number 899321679872 (6 %)
InnoDB: Doing recovery: scanned up to log sequence number 899326922752 (6 %)
InnoDB: Doing recovery: scanned up to log sequence number 899332165632 (7 %)
130801 2:11:02 InnoDB: Starting an apply batch of log records to the database…
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 Segmentation fault (core dumped)
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 389.

Re running doesnt work better:

mysqlbackup/sb3/base/2013-07-19_11-00-02/backup-my.cnf" --defaults-group=“mysqld” --prepare --target-dir=/srv/storage/mysqlbackup/sb3/base/2013-07-19_11-00-02 --apply-log-only --tmpdir=/tmp

xtrabackup_55 version 2.1.3 for MySQL server 5.5.17 Linux (x86_64) (revision id: undefined)
xtrabackup: cd to /srv/storage/mysqlbackup/sb3/base/2013-07-19_11-00-02
xtrabackup: This target seems to be not prepared yet.
130806 11:45:18 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
xtrabackup: Warning: cannot open ./xtrabackup_logfile. will try to find.
xtrabackup: ‘ib_logfile0’ seems to be ‘xtrabackup_logfile’. will retry.
xtrabackup: xtrabackup_logfile detected: size=963182592, start_lsn=(899274494433)
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 = 963182592
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 = 963182592
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
130806 11:45:18 InnoDB: The InnoDB memory heap is disabled
130806 11:45:18 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130806 11:45:18 InnoDB: Compressed tables use zlib 1.2.3
130806 11:45:18 InnoDB: Initializing buffer pool, size = 100.0M
130806 11:45:18 InnoDB: Completed initialization of buffer pool
130806 11:45:19 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 899274494433
130806 11:45:19 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files…
InnoDB: Doing recovery: scanned up to log sequence number 899279736832 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 899284979712 (1 %)
InnoDB: Doing recovery: scanned up to log sequence number 899290222592 (1 %)
130806 11:45:29 InnoDB: Starting an apply batch of log records to the database…
InnoDB: Progress in percents: 130806 11:45:29 InnoDB: Assertion failure in thread 139642902509312 in file log0recv.c line 1083
InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page) == dict_table_is_comp(index->table)
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.5/…-recovery.html
InnoDB: about forcing recovery.
Aborted (core dumped)
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 389.

So I checked this forum and found out one problem could come from me doing apply logs on the backup server, and not the actual server I want to restore to in the end. I took a new fullbackup, and tried again:

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 = 573194240
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
130807 14:02:32 InnoDB: The InnoDB memory heap is disabled
130807 14:02:32 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130807 14:02:32 InnoDB: Compressed tables use zlib 1.2.3
130807 14:02:32 InnoDB: Initializing buffer pool, size = 100.0M
130807 14:02:32 InnoDB: Completed initialization of buffer pool
130807 14:02:32 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 960942418808
130807 14:02:32 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files…
InnoDB: Doing recovery: scanned up to log sequence number 960947661312 (1 %)
InnoDB: Doing recovery: scanned up to log sequence number 960952904192 (2 %)
InnoDB: Doing recovery: scanned up to log sequence number 960958147072 (3 %)
130807 14:02:37 InnoDB: Starting an apply batch of log records to the database…
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 960963389952 (4 %)
InnoDB: Doing recovery: scanned up to log sequence number 960968632832 (5 %)
InnoDB: Doing recovery: scanned up to log sequence number 960973875712 (6 %)
130807 14:02:56 InnoDB: Starting an apply batch of log records to the database…
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 960979118592 (7 %)
InnoDB: Doing recovery: scanned up to log sequence number 960984361472 (8 %)
InnoDB: Doing recovery: scanned up to log sequence number 960989604352 (9 %)
InnoDB: Doing recovery: scanned up to log sequence number 960994847232 (10 %)
130807 14:04:04 InnoDB: Starting an apply batch of log records to the database…
[COLOR=#B22222]InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 InnoDB: Probable data corruption on page 388973
InnoDB: Original record (compact record)
InnoDB: on that page.
InnoDB: Cannot find the dir slot for record (compact record)
InnoDB: on that page!
130807 14:04:13 InnoDB: Page dump in ascii and hex (16384 bytes):
len 16384; hex 913adde20005ef6d0005ef6a0005ef6e000000dfbeeb19ab45 bf000000000000000000000452005e3e6782f52567118e31b5 00050000021d00000001126a224f0000000000000000059b00 00000000000000000000000000000000000000010002001a69 6e66696d756d0006000b000073757072656d756d0000102a93 8000124f1199be9280000000011cbd0c00001800158000124f 1199beb480000000011cbcb0000020168f8000124f1199beed 80000000011cbcbd08002800158000124f1199bfe080000000 011cbc6c00003012b48000124f1199c03880000000011cbbed 0000380fea8000124f1199c0a480000000011cc0b100004000 158000124f1199c0a580000000011cbb880700480fab800012 4f1199c0db80000000011cbb870000503cf38000124f1199c1 6280000000011cbc3f0600582d488000124f1199c166800000 00011cbc3e0000602d1e8000124f1199c16d80000000011cbc 3d05006800158000124f1199c20a80000000011cbc3c000070 296d8000124f1199c21e80000000011cbc3b00007800158000 124f1199c26e80000000011cbc3a00008000158000124f1199 c27b80000000011cbc0c0500883c368000124f1199c2938000 0000011cbb8a00009000158000124f1199c2f080000000011c bb8600009828ef8000124f1199c2fd80000000011cbb700000 a01dc78000124f1199c30080000000011cbc390800a83bcd80 00124f1199d30080000000011cbc380400b000158000124f11 99d35b80000000011cbc370000b82

InnoDB: End of page dump
130807 14:04:14 InnoDB: Page checksum 3742725938, prior-to-4.0.14-form checksum 1918383901
InnoDB: stored checksum 2436554210, prior-to-4.0.14-form stored checksum 223
InnoDB: Page lsn 223 3203078571, low 4 bytes of lsn at page end 3203078571
InnoDB: Page number (if stored to page already) 388973,
InnoDB: space id (if created with >= MySQL-4.1.1 and stored already) 1106
InnoDB: Page may be an index page where index id is 1435
Segmentation fault
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 389.

I found out these problems came when I created the backups with “–compact” option. The documentation are wrong about how to do restore, and theres an example ‘find’ which doesn’t find any compressed files…

Hi jostmart,

It would be helpful to know what parts of our documentation you think are wrong so we can double check them. From your first post I don’t see you using the --rebuild-indexes parameter that is mandatory when you are preparing a compact backup. In your logs seems that you are running --prepare and --apply-log-only that is usually executed when preparing incremental backups.

Please, share the full command that you use to take backups and the one used to prepare it.

Thank you.