Percona XtraBackup moved to https://jira.percona.com/projects/PXB

Percona Xtrabackup: Starting LSN is bigger than ending LSN

Bug #1470847 reported by Muhammad Irfan
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraBackup moved to https://jira.percona.com/projects/PXB
Fix Released
Medium
Sergei Glushchenko
Percona XtraBackup moved to https://jira.percona.com/projects/PXB 2.3.2
2.2
Fix Released
Medium
Sergei Glushchenko
Percona XtraBackup moved to https://jira.percona.com/projects/PXB 2.2.12
2.3
Fix Released
Medium
Sergei Glushchenko
Percona XtraBackup moved to https://jira.percona.com/projects/PXB 2.3.2

Bug Description

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 04:00:02 innobackupex: Executing a version check against the server...
150630 04:00:02 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup' as 'bkpusr' (using password: YES).
150630 04:00:02 innobackupex: Connected to MySQL server
*******************************************************************
 Using the default of SSL_verify_mode of SSL_VERIFY_NONE for client
 is deprecated! Please set SSL_verify_mode to SSL_VERIFY_PEER
 together with SSL_ca_file|SSL_ca_path for verification.
 If you really don't want to verify the certificate and keep the
 connection open to Man-In-The-Middle attacks please set
 SSL_verify_mode explicitly to SSL_VERIFY_NONE in your application.
*******************************************************************
  at /usr/bin/innobackupex line 512.
150630 04:00:03 innobackupex: Done.
150630 04:00:03 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup' as 'bkpusr' (using password: YES).
150630 04:00:03 innobackupex: Connected to MySQL server
150630 04:00:03 innobackupex: Starting the backup operation

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

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: )
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /mysqldata/mysql55/mysql/
xtrabackup: open files limit requested 0, set to 20000
xtrabackup: using the following InnoDB configuration:
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 = 2
xtrabackup: innodb_log_file_size = 268435456
>> log scanned up to (321873373184)
xtrabackup: Generating a list of tablespaces
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] Streaming ./ibdata1
[01] ...done
[01] Streaming ./db/table.ibd
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/table.ibd
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/table.ibd
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/mapping.ibd
[01] ...done
[01] Streaming ./db/transaction.ibd
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/code.ibd
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/code_pog_filter.ibd
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/promo_filter.ibd
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] ...done
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/marketing.ibd
[01] ...done
[01] Streaming ./db/urls.ibd
[01] ...done
[01] Streaming ./db/deal.ibd
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/affiliate.ibd
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/product.ibd
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./score/shipping.ibd
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/table.ibd
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/freebie.ibd
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] ...done
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/table.ibd
[01] ...done
[01] Streaming ./db/table.ibd
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
[01] ...done
>> log scanned up to (321873373184)
xtrabackup: Creating suspend file '/mysqltmp/mysql_temp55//xtrabackup_suspended_2' with pid '19667'

150630 04:47:46 innobackupex: Continuing after ibbackup has suspended
150630 04:47:46 innobackupex: Executing FLUSH TABLES...
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
..
..
..
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
150630 04:50:31 innobackupex: Executing FLUSH TABLES WITH READ LOCK...
150630 04:50:31 innobackupex: All tables locked and flushed to disk

150630 04:50:31 innobackupex: Starting to backup non-InnoDB tables and files
innobackupex: in subdirectories of '/mysqldata/mysql55/mysql/'
innobackupex: Backing up files '/mysqldata/mysql55/mysql//db/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (33 files)
>> log scanned up to (321873373184)
innobackupex: Backing up files '/mysqldata/mysql55/mysql//db/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (26 files)
innobackupex: Backing up files '/mysqldata/mysql55/mysql//db/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (35 files)
innobackupex: Backing up files '/mysqldata/mysql55/mysql//db/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (13 files)
innobackupex: Backing up files '/mysqldata/mysql55/mysql//scp/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (183 files)
>> log scanned up to (321873373184)
innobackupex: Backing up files '/mysqldata/mysql55/mysql//db/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (27 files)
>> log scanned up to (321873373184)
innobackupex: Backing up files '/mysqldata/mysql55/mysql//db/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (32 files)
innobackupex: Backing up files '/mysqldata/mysql55/mysql//db/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (23 files)
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/db.opt'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/mapping.frm'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/score.frm'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/subscriber.frm'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/score.frm'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/detail.frm'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/zentrix.frm'
innobackupex: Backing up files '/mysqldata/mysql55/mysql//fc/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (72 files)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/db.opt'
>> log scanned up to (321873373184)
..
>> log scanned up to (321873373184)
..
>> log scanned up to (321873373184)
..
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
..
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
..
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
..
>> log scanned up to (321873373184)
..
>> log scanned up to (321873373184)
innobackupex: Backing up file '/mysqldata/mysql55/mysql//percona/checksums.frm'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//percona/db.opt'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//testnew/db.opt'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//testnew/name1.frm'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//testnew/name.frm'
innobackupex: Backing up files '/mysqldata/mysql55/mysql//search/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (17 files)
>> log scanned up to (321873373184)
..
/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (25 files)
innobackupex: Backing up files '/mysqldata/mysql55/mysql//db/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (13 files)
..
>> log scanned up to (321873373184)
/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (105 files)
innobackupex: Backing up files '/mysqldata/mysql55/mysql//subcategory_info/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (99 files)
>> log scanned up to (321873373184)
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/db.opt'
innobackupex: Backing up files '/mysqldata/mysql55/mysql//db/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (48 files)
innobackupex: Backing up file '/mysqldata/mysql55/mysql//table.frm'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/db.opt'
innobackupex: Backing up file '/mysqldata/mysql55/mysql//db/table.frm'
150630 04:50:58 innobackupex: Finished backing up non-InnoDB tables and files

150630 04:50:58 innobackupex: Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
150630 04:50:58 innobackupex: Waiting for log copying to finish

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

xtrabackup: Creating suspend file '/mysqltmp/mysql_temp55//xtrabackup_log_copied' with pid '19667'
xtrabackup: Transaction log of lsn (321873373467) to (321873373184) was copied.
150630 04:50:59 innobackupex: All tables unlocked

innobackupex: Backup created in directory '/mysqlbackup/DB_BKP'
innobackupex: MySQL binlog position: filename 'mysql-bin.000268', position 280446195
150630 04:50:59 innobackupex: Connection to database server closed
innobackupex: You must use -i (--ignore-zeros) option for extraction of the tar stream.
150630 04:50:59 innobackupex: completed OK!

Tags: i56186
Revision history for this message
Valerii Kravchuk (valerii-kravchuk) wrote :

This is easy to confirm with code review. Main backup function, xtrabackup_backup_func, is declared void:

openxs@ao756:~/git/percona-xtrabackup$ grep -rn xtrabackup_backup_func *
storage/innobase/xtrabackup/src/xtrabackup.cc:3278:xtrabackup_backup_func(void)
storage/innobase/xtrabackup/src/xtrabackup.cc:6367: xtrabackup_backup_func();

and ends up like this:

...
   3736 msg("xtrabackup: Transaction log of lsn (" LSN_PF ") to (" LSN_PF
   3737 ") was copied.\n", checkpoint_lsn_start, log_copy_scanned_lsn);
   3738 xb_filters_free();
   3739
   3740 xb_data_files_close();
   3741 }

It is used like this:

   6365 /* --backup */
   6366 if (xtrabackup_backup)
   6367 xtrabackup_backup_func();
   6368
   6369 /* --stats */
   6370 if (xtrabackup_stats)
   6371 xtrabackup_stats_func();
   6372
   6373 /* --prepare */
   6374 if (xtrabackup_prepare)
   6375 xtrabackup_prepare_func();
   6376
   6377 xb_regex_end();
   6378
   6379 exit(EXIT_SUCCESS);

So, there are no checks of checkpoint_lsn_start value vs log_copy_scanned_lsn value and if this function is used and was executed, xtrabackup process just exits with success, no matter what happens. innobackupex script then has no way to find out there was a problem:

if ( $ibbackup_exit_code == 0 ) {
   # program has completed successfully
   print STDERR "$now $prefix completed OK!\n";
}
else {
   print STDERR "$now $prefix $option_ibbackup_binary failed! (exit code $ibbackup_exit_code) The backup may not be complete.\n";
}

Changed in percona-xtrabackup:
status: New → Confirmed
Valerii Kravchuk (valerii-kravchuk)
tags: added: i55995
Valerii Kravchuk (valerii-kravchuk)
tags: added: i56186
removed: i55995
Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :

Here is the test case:

#
# Bug 1470847: starting LSN is bigger than ending LSN makes no error
#

MYSQLD_EXTRA_MY_CNF_OPTS="
innodb-log-files-in-group=4
innodb-log-file-size=2M
"
start_server

# setup InnoDB to flush agressively
run_cmd ${MYSQL} ${MYSQL_ARGS} -e "SET GLOBAL innodb_old_blocks_time=250; \
SET GLOBAL innodb_old_blocks_pct=5; \
SET GLOBAL innodb_max_dirty_pages_pct=0;"

load_sakila

# wait for InnoDB to flush
sleep 5

# pass wrong value for innodb-log-files-in-group
run_cmd_expect_failure xtrabackup --backup --target-dir=$topdir/backup \
                                  --innodb-log-files-in-group=3

Changed in percona-xtrabackup:
status: Confirmed → In Progress
assignee: nobody → Sergei Glushchenko (sergei.glushchenko)
importance: Undecided → Medium
milestone: none → future-2.2-releases
Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :

xtrabackup doesn't check whether checkpoint LSN which we start to copy from actually made it into redo logs. Fix will be to make that check and exit with failure if check is failed.

Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :

https://bugs.launchpad.net/percona-xtrabackup/+bug/1470847

Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :

https://github.com/percona/percona-xtrabackup/pull/81

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.