xtrabackup 2.2.3 failed: expected log block no. 435565628, but got no. 439759928 from the log file

[Peiran Song]

Customer reported that xtrabackup 2.2.3 fails on taking incremental backups on one slave. Previous version of xtrabackup worked fine on this server before. And if the replication is stopped during the backup, backup would succeed.

Backup command:
----------------------------------------
innobackupex --incremental --incremental-lsn=41380448403316 /mnt/staging/mysqlA/aus-dbs16/5133 --no-timestamp --ibbackup=xtrabackup_55 --user=xxxx --password=XXXXXXX --slave-info --safe-slave-backup --tmpdir=/tmp/xbm-4135527 --throttle=0 --defaults-file=/var/lib/mysql/A/mysqlA.cnf --socket=/var/lib/mysql/A/mysqlA.sock --no-lock

Output:
----------------
140904 13:24:59 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file="/var/lib/mysql/A/mysqlA.cnf" --defaults-group="mysqld" --backup --suspend-at-end --target-dir=/mnt/staging/mysqlA/aus-dbs16/5133 --tmpdir=/tmp/xbm-4135527 --extra-lsndir='/tmp/xbm-4135527' --incremental-lsn='41380448403316'
                                        innobackupex: Waiting for ibbackup (pid=23021) to suspend innobackupex: Suspend file '/mnt/staging/mysqlA/aus-dbs16/5133/xtrabackup_suspend
ed_2'

                                        xtrabackup_55 version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
                                        incremental backup from 41380448403316 is enabled.
                                        xtrabackup: uses posix_fadvise().
                                        xtrabackup: cd to /var/lib/mysql/A
                                        xtrabackup: open files limit requested 0, set to 96000
                                        xtrabackup: using the following InnoDB configuration:
                                        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 = 2
                                        xtrabackup: innodb_log_file_size = 3221225472
                                        xtrabackup: using O_DIRECT
                                        >> log scanned up to (41454695642624)
                                        xtrabackup: using the full scan for incremental backup
                                        [01] Copying ./ibdata1 to /mnt/staging/mysqlA/aus-dbs16/5133/ibdata1.delta
                                        >> log scanned up to (41454695642624)
                                        >> log scanned up to (41454695642624)
....
...
                                        >> log scanned up to (41454695642624)
                                        >> log scanned up to (41454695642624)
                                        xtrabackup: error: log block numbers mismatch:
                                        xtrabackup: error: expected log block no. 435565628, but got no. 439759928 from the log file.
                                        xtrabackup: Error: xtrabackup_copy_logfile() failed.
                                        innobackupex: Error: The xtrabackup child process has died at /usr/bin/innobackupex line 2672.

Variables:
---------------------
innodb_log_block_size 512
innodb_log_buffer_size 16777216
innodb_log_file_size 3221225472
innodb_log_files_in_group 2

Status:
------------------
xtrabackup started at 13:24:59, failed at 13:58:06

At 13:28:05
Log sequence number 41454814261866
Log flushed up to 41454814255943
Last checkpoint at 41454812819846

At 13:54:04
Log sequence number 41456453356468
Log flushed up to 41456453355760
Last checkpoint at 41455591826645

Note:
--------------
1) This error looks similar to https://bugs.launchpad.net/percona-xtrabackup/+bug/1206309. However, in this case, the log block number is not near the wrap around position (1073741823).

2) The two xtrabackup outputs from the customer(one above, the other one in comment #8 of bug #1073741823) showed the same number of different log blocks between the expected no. and got no., which is 4194300.

3) Xtrabackup output showed that the log sequence number started from 41454695642624 and never move beyond it.

[Alexey Kopytov (akopytov)]

Please make sure that innodb_log_file_size used by the server and the value in my.cnf are the same.

One possible explanation for this bug could be that innodb_log_file_size value got changed in my.cnf without restarting the server. So InnoDB and PXB (which reads my.cnf) disagree on its value.

[Peiran Song (peiran-song)]

Alexey,

That should be the same.

From the xtrabackup output:

xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 3221225472

From show variables:

innodb_log_file_size 3221225472
innodb_log_files_in_group 2

[Nilnandan Joshi (nilnandan-joshi)]

Tried to verify with Xtrabackup 2.2.3 on PS 5.6.17. First take a fullbackup and then incremental on slave while running sysbench on master server for heavy load. I couldn't able to reproduce it.

Set variables :
innodb_log_block_size 512
innodb_log_buffer_size 16777216
innodb_log_file_size 50331648
innodb_log_files_in_group 2

Sysbench command on master:

sysbench --test=oltp --oltp-table-size=100000 --oltp-test-mode=complex --oltp-read-only=off --num-threads=100 --max-time=120 --max-requests=0 --mysql-db=dbtest --mysql-user=root --mysql-password=msandbox --mysql-socket=/tmp/mysql_sandbox20082.sock run

Take fullbackup:

nilnandan@Dell-XPS:~$ sudo innobackupex --defaults-file=/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/my.sandbox.cnf --user=root --password=msandbox --socket=/tmp/mysql_sandbox20083.sock /home/nilnandan/backup/
....
...
140909 15:37:27 innobackupex: Starting to backup non-InnoDB tables and files
innobackupex: in subdirectories of '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data'
innobackupex: Backing up files '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data/mysql/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (74 files)
>> log scanned up to (215795275)
innobackupex: Backing up files '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data/performance_schema/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (53 files)
innobackupex: Backing up file '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data/nil/db.opt'
innobackupex: Backing up file '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data/dbtest/db.opt'
innobackupex: Backing up file '/home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_17/node1/data/dbtest/sbtest.frm'
140909 15:37:28 innobackupex: Finished backing up non-InnoDB tables and files

140909 15:37:28 innobackupex: Executing LOCK BINLOG FOR BACKUP...
140909 15:37:28 innobackupex: Executing FLUSH ENGINE LOGS...
140909 15:37:28 innobackupex: Waiting for log copying to finish

xtrabackup: The latest check point (for incremental): '195285221'
xtrabackup: Stopping log copying thread.
.>> log scanned up to (215852629)

xtrabackup: Creating suspend file '/home/nilnandan/backup/2014-09-09_15-37-25/xtrabackup_log_copied' with pid '28997'
xtrabackup: Transaction log of lsn (195181186) to (215852629) was copied.
140909 15:37:29 innobackupex: Executing UNLOCK BINLOG
140909 15:37:29 innobackupex: Executing UNLOCK TABLES
140909 15:37:29 innobackupex: All tables unlocked

innobackupex: Backup created in directory '/home/nilnandan/backup/2014-09-09_15-37-25'
innobackupex: MySQL binlog position: filename 'mysql-bin.000002', position 120
140909 15:37:29 innobackupex: Connection to database server closed
140909 15:37:29 innobackupex: completed OK!

Checked xtrabackup_checkpoints

cat xtrabackup_checkpoints
backup_type = full-backuped
from_lsn = 0
to_lsn = 195285221
last_lsn = 215852629
compact = 0

Take incremental backup with to_lsn

nilnandan@Dell-XPS:~$ sudo sudo innobackupex --incremental --incremental-lsn=195285221 /home/nilnandan/backup/2014-09-09_15-37-25/incremental --slave-inf...

[egezon (egezon-berisha)]

Note that our MySQL version is 5.5.29, and the xtrabackup verison is 2.2.3

> select @@version;
+-----------------+
| @@version |
+-----------------+
| 5.5.29-29.4-log |
+-----------------+
1 row in set (0.00 sec)

> exit;
Bye

$ xtrabackup --version
xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )

[Shahriyar Rzayev (rzayev-sehriyar)]

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