innobackupex "completed OK" when backing up a "remote" server

[Fernando Laudares Camargos]

I've come across a situation where it was attempted to backup a remote server by providing --host and MySQL credentials to access the target server remotely, like running below command from server 192.168.70.2:

[root@node1 mysql]# innobackupex --host 192.168.70.3 --user=fernando --password=XXXXXX /tmp

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

151006 23:48:33 innobackupex: Executing a version check against the server...
151006 23:48:33 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;host=192.168.70.3' as 'fernando' (using password: YES).
151006 23:48:33 innobackupex: Connected to MySQL server
151006 23:48:33 innobackupex: Done.
151006 23:48:33 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;host=192.168.70.3' as 'fernando' (using password: YES).
151006 23:48:33 innobackupex: Connected to MySQL server
151006 23:48:33 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.6.24-72.2-56

innobackupex: Created backup directory /tmp/2015-10-06_23-48-33

151006 23:48:33 innobackupex: Starting ibbackup with command: xtrabackup --defaults-group="mysqld" --backup --suspend-at-end --target-dir=/tmp/2015-10-06_23-48-33 --innodb_log_file_size="50331648" --innodb_data_file_path="ibdata1:12M:autoextend" --tmpdir=/tmp --extra-lsndir='/tmp'
innobackupex: Waiting for ibbackup (pid=12831) to suspend
innobackupex: Suspend file '/tmp/2015-10-06_23-48-33/xtrabackup_suspended_2'

xtrabackup version 2.2.12 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 8726828)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /var/lib/mysql
xtrabackup: open files limit requested 0, set to 1024
xtrabackup: using the following InnoDB configuration:
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 = 2
xtrabackup: innodb_log_file_size = 50331648
>> log scanned up to (1601046)
xtrabackup: Generating a list of tablespaces
[01] Copying ./ibdata1 to /tmp/2015-10-06_23-48-33/ibdata1
[01] ...done
>> log scanned up to (1601046)
xtrabackup: Creating suspend file '/tmp/2015-10-06_23-48-33/xtrabackup_suspended_2' with pid '12831'

151006 23:48:35 innobackupex: Continuing after ibbackup has suspended
151006 23:48:35 innobackupex: Executing LOCK TABLES FOR BACKUP...
151006 23:48:35 innobackupex: Backup tables lock acquired

151006 23:48:35 innobackupex: Starting to backup non-InnoDB tables and files
innobackupex: in subdirectories of '/var/lib/mysql/'
151006 23:48:35 innobackupex: Finished backing up non-InnoDB tables and files

151006 23:48:35 innobackupex: Executing LOCK BINLOG FOR BACKUP...
151006 23:48:35 innobackupex: Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
151006 23:48:35 innobackupex: Waiting for log copying to finish

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

xtrabackup: Creating suspend file '/tmp/2015-10-06_23-48-33/xtrabackup_log_copied' with pid '12831'
xtrabackup: Transaction log of lsn (1601046) to (1601046) was copied.
151006 23:48:36 innobackupex: Executing UNLOCK BINLOG
151006 23:48:36 innobackupex: Executing UNLOCK TABLES
151006 23:48:36 innobackupex: All tables unlocked

innobackupex: Backup created in directory '/tmp/2015-10-06_23-48-33'
151006 23:48:36 innobackupex: Connection to database server closed
151006 23:48:36 innobackupex: completed OK!

It's surprising that it "completed OK" considering there was no mysqld running on the host from where I ran innobackupex, even though there was an existing /etc/my.cnf file and the datadir referenced by it contained:

[root@node1 mysql]# ls -l
total 110592
-rw-r----- 1 mysql mysql 12582912 Oct 6 23:47 ibdata1
-rw-r--r-- 1 mysql mysql 50331648 Oct 6 23:48 ib_logfile0
-rw-r--r-- 1 mysql mysql 50331648 Oct 6 23:48 ib_logfile1

If we attempt to have the backup prepared, it "completes OK" as well:

[root@flc-node1 mysql]# innobackupex --apply-log /tmp/2015-10-06_23-48-33

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

151006 23:48:53 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!".

151006 23:48:53 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file="/tmp/2015-10-06_23-48-33/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/tmp/2015-10-06_23-48-33

xtrabackup version 2.2.12 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 8726828)
xtrabackup: cd to /tmp/2015-10-06_23-48-33
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(1601046)
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 = 2097152
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 = 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: Not 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: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.24 started; log sequence number 1601046

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:

xtrabackup: Recovered WSREP position: 00000000-0000-0000-0000-000000000000:-1
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 1601056

151006 23:48:55 innobackupex: Restarting xtrabackup with command: xtrabackup --defaults-file="/tmp/2015-10-06_23-48-33/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/tmp/2015-10-06_23-48-33
for creating ib_logfile*

xtrabackup version 2.2.12 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 8726828)
xtrabackup: cd to /tmp/2015-10-06_23-48-33
xtrabackup: This target seems to be already prepared.
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.
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 = 2
xtrabackup: innodb_log_file_size = 50331648
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 = 2
xtrabackup: innodb_log_file_size = 50331648
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: Not using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Setting log file ./ib_logfile101 size to 48 MB
InnoDB: Setting log file ./ib_logfile1 size to 48 MB
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=1601056
InnoDB: Highest supported file format is Barracuda.
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.24 started; log sequence number 1601548

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 1601558
151006 23:48:57 innobackupex: completed OK!

Resulting in:

[root@node1 mysql]# ls -l /tmp/2015-10-06_23-48-33
total 112656
-rw-r--r-- 1 root root 358 Oct 6 23:48 backup-my.cnf
-rw-r----- 1 root root 12582912 Oct 6 23:48 ibdata1
-rw-r--r-- 1 root root 50331648 Oct 6 23:48 ib_logfile0
-rw-r--r-- 1 root root 50331648 Oct 6 23:48 ib_logfile1
-rw-r----- 1 root root 89 Oct 6 23:48 xtrabackup_checkpoints
-rw-r--r-- 1 root root 39 Oct 6 23:48 xtrabackup_galera_info
-rw-r--r-- 1 root root 542 Oct 6 23:48 xtrabackup_info
-rw-r----- 1 root root 2097152 Oct 6 23:48 xtrabackup_logfile

This was tested in a server with:

$ rpm -qa |grep -i percona
Percona-XtraDB-Cluster-server-56-5.6.24-25.11.1.el6.x86_64
Percona-Server-shared-51-5.1.73-rel14.12.624.rhel6.x86_64
Percona-XtraDB-Cluster-client-56-5.6.24-25.11.1.el6.x86_64
percona-toolkit-2.2.11-1.noarch
Percona-XtraDB-Cluster-galera-3-3.11-1.rhel6.x86_64
Percona-XtraDB-Cluster-shared-56-5.6.24-25.11.1.el6.x86_64
percona-xtrabackup-2.2.12-1.el6.x86_64
percona-release-0.1-3.noarch

I've also tried with percona-xtrabackup-23-2.3.1beta1-1.el6.x86_64

Ideally we should improve pre-run "health check" and raise errors in such situation.

[Sergei Glushchenko (sergei.glushchenko)]

What would be the check we might perform? I can only suggest that xtrabackup will ask server to create a file and check if this file is accessible. SELECT INTO OUTFILE would do the trick, but it will impose additional requirements on MySQL server configuration and xtrabackup user grants.

[Shahriyar Rzayev (rzayev-sehriyar)]

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