Percona Xtrabackup: Assertion failure in file trx0trx.cc

[Muhammad Irfan]

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

Get the latest version of Percona XtraBackup, documentation, and help resources:
http://www.percona.com/xb/p

150630 14:10:38 innobackupex: Starting the apply-log operation

IMPORTANT: Please check that the apply-log run completes successfully.
           At the end of a successful apply-log run innobackupex
           prints "completed OK!".

150630 14:10:38 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file="/mysqlbackup/DB_BKP/restore/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/mysqlbackup/DB_BKP/restore

xtrabackup version 2.2.11 based on MySQL server 5.6.24 Linux (x86_64) (revision id: )
xtrabackup: cd to /mysqlbackup/DB_BKP/restore
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(321873373467)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:100M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:100M: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: 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: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.3
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 60698157948 and 60698157948 in ibdata files do not match the log sequence number 321873373467 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 321873373184. A checkpoint was at 321873373467 and the maximum LSN on a database page was 0. It is possible that the database is now corrupt!
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5 log sequence number 321873381435
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 45 log sequence number 321873375725
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5946 log sequence number 321873640346
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 1216 log sequence number 321873375725
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 51 log sequence number 321873376192
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 1270 log sequence number 321873376192
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 53 log sequence number 321873378709
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5928 log sequence number 321873378709
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 58 log sequence number 321873381425
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5917 log sequence number 321873381425
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 3404 log sequence number 321873381425
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5904 log sequence number 321873384099
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5905 log sequence number 321873388306
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5898 log sequence number 321873407287
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5892 log sequence number 321873421925
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5899 log sequence number 321873437510
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5894 log sequence number 321873440112
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5900 log sequence number 321873469587
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5901 log sequence number 321873520093
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2015-06-30 14:10:52 7f373680e740 InnoDB: Error: page 5896 log sequence number 321873635409
InnoDB: is in the future! Current system log sequence number 321873373467.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
InnoDB: 4 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 400283392
InnoDB: Last MySQL binlog file position 0 229739200, file name /mysqldata/mysql55/mysql_logs/binary_logs/mysql-bin.000268
InnoDB: Cleaning up trx with id 400282936
2015-06-30 14:10:52 7f373680e740 InnoDB: Assertion failure in thread 139875114346304 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: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
08:40:52 UTC - xtrabackup got signal 6 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Thread pointer: 0x26c7eb0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x10000
xtrabackup(my_print_stacktrace+0x35) [0x9fa0f9]
xtrabackup(handle_fatal_signal+0x2bb) [0x7fb1e7]
/lib64/libpthread.so.0(+0xf130) [0x7f37363f3130]
/lib64/libc.so.6(gsignal+0x39) [0x7f37349655c9]
/lib64/libc.so.6(abort+0x148) [0x7f3734966cd8]
xtrabackup(trx_free_for_background(trx_t*)+0x1ce) [0x65bf77]
xtrabackup() [0x6ae204]
xtrabackup(trx_rollback_or_clean_recovered(unsigned long)+0xd3) [0x6ae351]
xtrabackup(recv_recovery_from_checkpoint_finish()+0x14b) [0x756bb7]
xtrabackup(innobase_start_or_create_for_mysql()+0x14d1) [0x72be0f]
xtrabackup() [0x609270]
xtrabackup() [0x611a71]
xtrabackup(main+0x8b8) [0x612eeb]
/lib64/libc.so.6(__libc_start_main+0xf5) [0x7f3734951af5]
xtrabackup() [0x605bd9]

Please report a bug at https://bugs.launchpad.net/percona-xtrabackup
innobackupex: got a fatal error with the following stacktrace: at /usr/bin/innobackupex line 2649.
        main::apply_log() called at /usr/bin/innobackupex line 1578
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 2649.

[Muhammad Irfan (muhammad-irfan)]

This is similar to https://bugs.launchpad.net/percona-xtrabackup/+bug/1403237

[Sergei Glushchenko (sergei.glushchenko)]

Please check that backup was taken by latest version of xtrabackup.

[Valerii Kravchuk (valerii-kravchuk)]

2.2.11 was used as far as I can see from the backup log:

...
innobackupex: Using server version 5.5.12-log

innobackupex: Created backup directory /mysqlbackup/DB_BKP

150630 04:00:04 innobackupex: Starting ibbackup with command: xtrabackup --defaults-group="mysqld" --backup --suspend-at-end --target-dir=/mysqltmp/mysql_temp55/ --datadir="/mysqldata/mysql55/mysql/" --innodb_log_file_size="268435456" --innodb_data_file_path="ibdata1:100M:autoextend" --tmpdir=/mysqltmp/mysql_temp55/ --extra-lsndir='/mysqltmp/mysql_temp55/' --parallel=1 --stream=tar
innobackupex: Waiting for ibbackup (pid=19667) to suspend
innobackupex: Suspend file '/mysqltmp/mysql_temp55//xtrabackup_suspended_2'

xtrabackup version 2.2.11 based on MySQL server 5.6.24 Linux (x86_64) (revision id: )
...

[Sergei Glushchenko (sergei.glushchenko)]

Valerii,

If I got it right, this assertion failure happened on corrupt backup (see #1470847). Should be invalid then?

[Valerii Kravchuk (valerii-kravchuk)]

Yes, we can assume for now that the root cause was a (silently) corrupted backup (and this is tracked in another bug report). Invalid for now, until we get a way to reproduce this with backup that was conmpletely successful.

[Shahriyar Rzayev (rzayev-sehriyar)]

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