innobackupex in rsync mode fails with 'no space on device' but completes with OK message

[JeffWRule]

Ran innobackupex with the command below. Device really did run out of space during rsync, but still completed with status of OK. This is not supposed to happen it should not end with OK message if something went wrong.

My automation depends on not finding OK as indicated in the manual. Manual indicates it will only print OK if it really worked.

Command line: innobackupex --defaults-extra-file=/etc/mysql.cnf --backup --compress --parallel=4 --rsync --incremental --incremental-basedir=./full_backup_20151216/2015-12-27_01-10-11 ./full_backup_20151216

Log.....

151228 01:10:11 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!".

151228 01:10:11 version_check Connected to MySQL server
151228 01:10:11 version_check Executing a version check against the server...
151228 01:10:11 version_check Done.
Using server version 5.6.26-74.0-log
innobackupex version 2.3.2 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 306a2e0)
incremental backup from 14900595279201 is enabled.
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /srv/mysql
xtrabackup: open files limit requested 0, set to 16000
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 = 2147483648
151228 01:10:11 >> log scanned up to (14900595284937)
.
. lots more log here removed for brevity...
.
151228 01:15:43 >> log scanned up to (14900595284977)
151228 01:15:44 >> log scanned up to (14900595284977)
rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)
rsync: close failed on "/backup-data/marsdb/innobackupex/mysql/full_backup_20151216/2015-12-28_01-10-11/cosmic/.cosmic_variant.MYD.fHzcJi": No space left on device (28)
rsync error: error in file IO (code 11) at receiver.c(730) [receiver=3.0.6]
rsync: connection unexpectedly closed (62 bytes received so far) [sender]
rsync error: error in rsync protocol data stream (code 12) at io.c(600) [sender=3.0.6]
151228 01:15:45 Error: rsync failed with error code 1
151228 01:15:45 Executing LOCK BINLOG FOR BACKUP...
151228 01:15:45 [00] Compressing xtrabackup_binlog_info
151228 01:15:45 [00] ...done
151228 01:15:45 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
xtrabackup: The latest check point (for incremental): '14900595284977'
xtrabackup: Stopping log copying thread.
.151228 01:15:45 >> log scanned up to (14900595284977)

151228 01:15:45 Executing UNLOCK BINLOG
151228 01:15:45 Executing UNLOCK TABLES
151228 01:15:45 All tables unlocked
151228 01:15:45 Backup created in directory '/backup-data/marsdb/innobackupex/mysql/full_backup_20151216/2015-12-28_01-10-11'
MySQL binlog position: filename 'marsdb-bin.000210', position '1043201980'
151228 01:15:45 [00] Compressing backup-my.cnf
151228 01:15:45 [00] ...done
151228 01:15:45 [00] Compressing xtrabackup_info
151228 01:15:45 [00] ...done
xtrabackup: Transaction log of lsn (14900595284937) to (14900595284977) was copied.
151228 01:15:45 completed OK!

real 5m33.759s
user 0m47.671s
sys 3m8.492s

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-xtrabackup/pull/162
https://github.com/percona/percona-xtrabackup/pull/163

[JeffWRule (jeffwrule)]

Great! thanks!

> On Mar 10, 2016, at 11:03 AM, Sergei Glushchenko <email address hidden> wrote:
>
> ** Changed in: percona-xtrabackup/2.3
> Milestone: future-2.3-releases => 2.3.4
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1537256
>
> Title:
> innobackupex in rsync mode fails with 'no space on device' but
> completes with OK message
>
> Status in Percona XtraBackup:
> Fix Released
> Status in Percona XtraBackup 2.3 series:
> Fix Released
> Status in Percona XtraBackup 2.4 series:
> Fix Released
>
> Bug description:
> Ran innobackupex with the command below. Device really did run out of
> space during rsync, but still completed with status of OK. This is not
> supposed to happen it should not end with OK message if something went
> wrong.
>
> My automation depends on not finding OK as indicated in the manual.
> Manual indicates it will only print OK if it really worked.
>
>
> Command line: innobackupex --defaults-extra-file=/etc/mysql.cnf --backup --compress --parallel=4 --rsync --incremental --incremental-basedir=./full_backup_20151216/2015-12-27_01-10-11 ./full_backup_20151216
>
> Log.....
>
>
> 151228 01:10:11 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!".
>
> 151228 01:10:11 version_check Connected to MySQL server
> 151228 01:10:11 version_check Executing a version check against the server...
> 151228 01:10:11 version_check Done.
> Using server version 5.6.26-74.0-log
> innobackupex version 2.3.2 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 306a2e0)
> incremental backup from 14900595279201 is enabled.
> xtrabackup: uses posix_fadvise().
> xtrabackup: cd to /srv/mysql
> xtrabackup: open files limit requested 0, set to 16000
> 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 = 2147483648
> 151228 01:10:11 >> log scanned up to (14900595284937)
> .
> . lots more log here removed for brevity...
> .
> 151228 01:15:43 >> log scanned up to (14900595284977)
> 151228 01:15:44 >> log scanned up to (14900595284977)
> rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)
> rsync: close failed on "/backup-data/marsdb/innobackupex/mysql/full_backup_20151216/2015-12-28_01-10-11/cosmic/.cosmic_variant.MYD.fHzcJi": No space left on device (28)
> rsync error: error in file IO (code 11) at receiver.c(730) [receiver=3.0.6]
> rsync: connection unexpectedly closed (62 bytes received so far) [sender]
> rsync error: error in rsync protocol data stream (code 12) at io.c(600) [sender=3.0.6]
> 151228 01:15:45 Error: rsync failed with error code 1
> 151228 01:15:45 Executing LOCK BINLOG FOR BACKUP...
> 151228 01:15:45 [00] Compressing xtrabackup_binlog_info
> 151228 01:15:45 [00] ...done
> 151228 0...

[Shahriyar Rzayev (rzayev-sehriyar)]

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