Incremental Backups with Log Archiving for XtraDB uses the xtrabackup_logfile when it shouldn't which causes backup to fail during the --prepare

[Hrvoje Matijakovic]

Incremental Backups with Log Archiving for XtraDB uses the xtrabackup_logfile when it shouldn't which causes backup to fail during the --prepare:

root@trusty:/tmp/backup2# xtrabackup --prepare --target-dir=/tmp/backup2/
xtrabackup version 2.3.5 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 45cda89)
xtrabackup: cd to /tmp/backup2/
xtrabackup: This target seems to be already prepared with --apply-log-only.
xtrabackup: xtrabackup_logfile detected: size=121847808, start_lsn=(828293142)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 121847808
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 121847808
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.8
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: Log scan progressed past the checkpoint lsn 828293142
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: Doing recovery: scanned up to log sequence number 833536000 (4%)
InnoDB: Doing recovery: scanned up to log sequence number 838778880 (9%)
InnoDB: Doing recovery: scanned up to log sequence number 844021760 (14%)
InnoDB: Doing recovery: scanned up to log sequence number 849264640 (19%)
InnoDB: Doing recovery: scanned up to log sequence number 854507520 (24%)
InnoDB: Doing recovery: scanned up to log sequence number 859750400 (29%)
InnoDB: Doing recovery: scanned up to log sequence number 864993280 (33%)
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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 870236160 (38%)
InnoDB: Doing recovery: scanned up to log sequence number 875479040 (43%)
InnoDB: Doing recovery: scanned up to log sequence number 880721920 (48%)
InnoDB: Doing recovery: scanned up to log sequence number 885964800 (53%)
InnoDB: Doing recovery: scanned up to log sequence number 891207680 (58%)
InnoDB: Doing recovery: scanned up to log sequence number 896450560 (62%)
InnoDB: Doing recovery: scanned up to log sequence number 901693440 (67%)
InnoDB: Doing recovery: scanned up to log sequence number 906936320 (72%)
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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 912179200 (77%)
InnoDB: Doing recovery: scanned up to log sequence number 917422080 (82%)
InnoDB: Doing recovery: scanned up to log sequence number 922664960 (87%)
InnoDB: Doing recovery: scanned up to log sequence number 927907840 (91%)
InnoDB: Doing recovery: scanned up to log sequence number 933150720 (96%)
InnoDB: Doing recovery: scanned up to log sequence number 936595531 (99%)
InnoDB: The log sequence number in the ibdata files is higher than the log sequence number in the ib_logfiles! Are you sure you are using the right ib_logfiles to start up the database. Log sequence number in the ib_logfiles is 828293142, logsequence numbers stamped to ibdata file headers are between 965342153 and 965342153.
InnoDB: We scanned the log up to 936595531. A checkpoint was at 828293142 and the maximum LSN on a database page was 965306588. It is possible that the database is now corrupt!
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 7 log sequence number 936624936
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 11 log sequence number 936627116
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 275 log sequence number 936595905
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 527 log sequence number 936595905
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 276 log sequence number 936597037
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 421 log sequence number 936597037
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 277 log sequence number 936622570
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 387 log sequence number 936622570
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 278 log sequence number 936597994
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 279 log sequence number 936598571
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 341 log sequence number 936598571
InnoDB: is in the future! Current system log sequence number 936595531.
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.
2016-10-12 14:29:47 7f24f7259780 InnoDB: Error: page 280 log sequence number 936623998
InnoDB: is in the future! Current system log sequence number 936595531.
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: 1048576 bytes should have been written. Only 978944 bytes written. Retrying again to write the remaining bytes.
InnoDB: Retry attempts for writing partial data failed.
2016-10-12 14:32:53 7f24f7259780 InnoDB: Error: Write to file ./ibdata1 failed at offset 37575720960.
InnoDB: 1048576 bytes should have been written, only 978944 were written.
InnoDB: Operating system error number 28.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 28 means 'No space left on device'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
InnoDB: Error: trying to access page number 2228580 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
2016-10-12 14:32:53 7f24f7259780 InnoDB: Assertion failure in thread 139796741986176 in file fil0fil.cc line 5627
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.
14:32:53 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: 0x0
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+0x2e) [0x96d4ae]
xtrabackup(handle_fatal_signal+0x262) [0x7798d2]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330) [0x7f24f6e38330]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37) [0x7f24f559cc37]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148) [0x7f24f55a0028]
xtrabackup() [0x6f6a6c]
xtrabackup(buf_read_page(unsigned long, unsigned long, unsigned long)+0xac) [0x63eb3c]
xtrabackup(buf_page_get_gen(unsigned long, unsigned long, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*)+0x230) [0x6187d0]
xtrabackup(trx_undo_lists_init(trx_rseg_t*)+0x6b6) [0x9eb9a6]
xtrabackup() [0x6b541a]
xtrabackup(trx_rseg_array_init(unsigned char*, ib_bh_t*, mtr_t*)+0x75) [0x6b5f95]
xtrabackup(trx_sys_init_at_db_start()+0x2e7) [0x5d3107]
xtrabackup(innobase_start_or_create_for_mysql()+0x1945) [0x5dc3b5]
xtrabackup() [0x56d7cb]
xtrabackup(main+0x1189) [0x580a29]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5) [0x7f24f5587f45]
xtrabackup() [0x5940ca]

Please report a bug at https://bugs.launchpad.net/percona-xtrabackup

Backup was initially prepared as described in Bug #1632734

[Shahriyar Rzayev (rzayev-sehriyar)]

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