innobackupex/xtrabackup fails at --apply-log phase

Hi,

I have a couple servers running percona-server 5.5.35-33.0-log; let’s name them A and B. They were set up in a simple replication, with A being master and B replica. Then A failed, and it being a production environment, app servers were switched to B, which temporarily became master for the time being. Now, A has been fixed (hardware problems), and now it is time to recreate the replication, only the other way around, B is now master, and A is about to become a replica.

However, after creating a snapshot backup at B with

innobackupex /mnt

it completes ok. I don’t have the log, but here’s xtrabackup_info:

uuid = 9f7940f4-44f5-11e4-aa6b-002590a749b4
name =
tool_name = innobackupex
tool_command = /mnt
tool_version = 1.5.1-xtrabackup
ibbackup_version = xtrabackup version 2.2.4 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
server_version = 5.5.35-33.0-log
start_time = 2014-09-26 00:34:35
end_time = 2014-09-26 00:50:46
lock_time = 2
binlog_pos = filename ‘mysql-bin.002457’, position 740539493
innodb_from_lsn = 0
innodb_to_lsn = 76297919300312
partial = N
incremental = N
format = file
compact = N
compressed = N
encrypted = N

However, the preparation phase then fails with:

140926 00:57:55 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file=“/mnt/2014-09-26_00-34-35/backup-my.cnf” --defaults-group=“mysqld” --prepare --target-dir=/mnt/2014-09-26_00-34-35 --tmpdir=/tmp

xtrabackup version 2.2.4 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
xtrabackup: cd to /mnt/2014-09-26_00-34-35
xtrabackup: This target seems to be not prepared yet.
2014-09-26 00:57:55 7f99b86c0720 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=2654208, start_lsn=(76297838733305)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:5000M;ibdata2:100M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2654208
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:5000M;ibdata2:100M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2654208
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.7
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: The log sequence numbers 76297838681272 and 76297838681272 in ibdata files do not match the log sequence number 76297838733305 in the ib_logfiles!
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files…
InnoDB: Restoring possible half-written data pages
InnoDB: from the doublewrite buffer…
InnoDB: We scanned the log up to 76297838732800. A checkpoint was at 76297838733305 and the maximum LSN on a database page was 0. It is possible that the database is now corrupt!
2014-09-26 00:57:55 7f99b86c0720 InnoDB: Error: page 2 log sequence number 76297839732066
InnoDB: is in the future! Current system log sequence number 76297838733305.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: [url]http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html[/url]
InnoDB: for more information.
2014-09-26 00:57:55 7f99b86c0720 InnoDB: Error: page 5 log sequence number 76297842656983
InnoDB: is in the future! Current system log sequence number 76297838733305.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: [url]http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html[/url]
InnoDB: for more information.
2014-09-26 00:57:55 7f99b86c0720 InnoDB: Error: page 6 log sequence number 76297841171636
InnoDB: is in the future! Current system log sequence number 76297838733305.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: [url]http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html[/url]
InnoDB: for more information.
2014-09-26 00:57:55 7f99b86c0720 InnoDB: Error: page 47 log sequence number 76297841199489
InnoDB: is in the future! Current system log sequence number 76297838733305.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: [url]http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html[/url]
InnoDB: for more information.

…some more pages like that

2014-09-26 00:57:55 7f99b86c0720 InnoDB: Error: page 580 log sequence number 76297839732857
InnoDB: is in the future! Current system log sequence number 76297838733305.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: [url]http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html[/url]
InnoDB: for more information.
InnoDB: 5 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 4724367616
InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 0 412597992, file name mysql-bin.038983
InnoDB: Last MySQL binlog file position 0 4562401, file name ./mysql-bin.002457
InnoDB: Cleaning up trx with id 4724367107
2014-09-26 00:57:55 7f99b86c0720 InnoDB: Assertion failure in thread 140298200811296 in file trx0trx.cc line 292
InnoDB: Failing assertion: trx->update_undo == NULL
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: [url]http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html[/url]
InnoDB: about forcing recovery.
Aborted
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 2617.

This indicates some data corruption, however, the server being backed up starts up normally, like this:

140926 00:32:41 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
140926 00:32:42 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql/
140926 0:32:42 [Warning] option ‘table_definition_cache’: unsigned value 128 adjusted to 400
140926 0:32:42 [Note] Plugin ‘FEDERATED’ is disabled.
140926 0:32:42 InnoDB: The InnoDB memory heap is disabled
140926 0:32:42 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140926 0:32:42 InnoDB: Compressed tables use zlib 1.2.3
140926 0:32:42 InnoDB: Using Linux native AIO
140926 0:32:42 InnoDB: Initializing buffer pool, size = 48.0G
140926 0:32:45 InnoDB: Completed initialization of buffer pool
140926 0:32:45 InnoDB: highest supported file format is Barracuda.
140926 0:32:47 InnoDB: Waiting for the background threads to start
140926 0:32:48 Percona XtraDB (http://www.percona.com) 5.5.35-rel33.0 started; log sequence number 76297838681272
140926 0:32:48 [Note] Event Scheduler: Loaded 0 events
140926 0:32:48 [Note] /usr/sbin/mysqld: ready for connections.
Version: ‘5.5.35-33.0-log’ socket: ‘/var/run/mysqld/mysqld.sock’ port: 3306 Percona Server (GPL), Release 33.0

with no indications for recovery.

I suspect that the reason hides somewhere in the fact of this server being previously a slave. Any ideas?

Just to be sure, I have ran a script doing innochecksum -v over all the data available and it came out all “okays”.