Percona Xtrabackup: Starting LSN is bigger than ending LSN
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona XtraBackup moved to https://jira.percona.com/projects/PXB |
Fix Released
|
Medium
|
Sergei Glushchenko | ||
2.2 |
Fix Released
|
Medium
|
Sergei Glushchenko | ||
2.3 |
Fix Released
|
Medium
|
Sergei Glushchenko |
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://
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:
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_
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/
150630 04:00:03 innobackupex: Done.
150630 04:00:03 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:
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-
innobackupex: Waiting for ibbackup (pid=19667) to suspend
innobackupex: Suspend file '/mysqltmp/
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/
xtrabackup: open files limit requested 0, set to 20000
xtrabackup: using the following InnoDB configuration:
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
>> 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/transactio
>> 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_
>> log scanned up to (321873373184)
[01] ...done
[01] Streaming ./db/promo_
>> 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/
>> 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/
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/
innobackupex: Backing up files '/mysqldata/
>> log scanned up to (321873373184)
innobackupex: Backing up files '/mysqldata/
innobackupex: Backing up files '/mysqldata/
innobackupex: Backing up files '/mysqldata/
innobackupex: Backing up files '/mysqldata/
>> log scanned up to (321873373184)
innobackupex: Backing up files '/mysqldata/
>> log scanned up to (321873373184)
innobackupex: Backing up files '/mysqldata/
innobackupex: Backing up files '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up files '/mysqldata/
>> log scanned up to (321873373184)
>> log scanned up to (321873373184)
innobackupex: Backing up file '/mysqldata/
>> 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/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up files '/mysqldata/
>> log scanned up to (321873373184)
..
/*.{frm,
innobackupex: Backing up files '/mysqldata/
..
>> log scanned up to (321873373184)
/*.{frm,
innobackupex: Backing up files '/mysqldata/
>> log scanned up to (321873373184)
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up files '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
innobackupex: Backing up file '/mysqldata/
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/
xtrabackup: Transaction log of lsn (321873373467) to (321873373184) was copied.
150630 04:50:59 innobackupex: All tables unlocked
innobackupex: Backup created in directory '/mysqlbackup/
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!
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 * innobase/ xtrabackup/ src/xtrabackup. cc:3278: xtrabackup_ backup_ func(void) innobase/ xtrabackup/ src/xtrabackup. cc:6367: xtrabackup_ backup_ func();
storage/
storage/
and ends up like this:
... lsn_start, log_copy_ scanned_ lsn); files_close( );
3736 msg("xtrabackup: Transaction log of lsn (" LSN_PF ") to (" LSN_PF
3737 ") was copied.\n", checkpoint_
3738 xb_filters_free();
3739
3740 xb_data_
3741 }
It is used like this:
6365 /* --backup */ backup_ func(); stats_func( ); prepare) prepare_ func();
6366 if (xtrabackup_backup)
6367 xtrabackup_
6368
6369 /* --stats */
6370 if (xtrabackup_stats)
6371 xtrabackup_
6372
6373 /* --prepare */
6374 if (xtrabackup_
6375 xtrabackup_
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 ) { ibbackup_ binary failed! (exit code $ibbackup_ exit_code) The backup may not be complete.\n";
# program has completed successfully
print STDERR "$now $prefix completed OK!\n";
}
else {
print STDERR "$now $prefix $option_
}