Spurious error when innobackupex fails due to a failed system call

[Ovais Tariq]

I am reporting it as a separate bug as its a more general bug.

So coming from this bug https://bugs.launchpad.net/percona-xtrabackup/+bug/1155189 which causes xbstream to fail when extracting the archive. When I pipe the output from innobackupex directly to xbstream and xbstream fails while the backup is still in progress then the following error is reported:
Failed to stream xtrabackup_binary: Inappropriate ioctl for device at /usr/bin/innobackupex line 311.

This is spurious due to the fact that it does not report the correct error message, the error is actually due to a broken pipe which is found when I strace the call to xbstream inside innobackupex.

Following is the entire output of the innobackupex run:

[root@centos6_01 backup_test]# innobackupex --stream=xbstream ./ --include=test.* | xbstream -x -C uncompress/

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona Ireland Ltd 2009-2012. All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

130314 11:35:33 innobackupex: Starting mysql with options: --unbuffered --
130314 11:35:33 innobackupex: Connected to database with mysql child process (pid=6349)
130314 11:35:39 innobackupex: Connection to database server closed
IMPORTANT: Please check that the backup run completes successfully.
           At the end of a successful backup run innobackupex
           prints "completed OK!".

innobackupex: Using mysql Ver 14.14 Distrib 5.5.29, for Linux (x86_64) using readline 5.1
innobackupex: Using mysql server version Copyright (c) 2000, 2012, Oracle and/or its affiliates. All rights reserved.

innobackupex: Created backup directory /root/backup_test
130314 11:35:40 innobackupex: Starting mysql with options: --unbuffered --
130314 11:35:40 innobackupex: Connected to database with mysql child process (pid=6379)
130314 11:35:42 innobackupex: Connection to database server closed

130314 11:35:42 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-group="mysqld" --backup --suspend-at-end --target-dir=/tmp --tables='test.*' --stream=xbstream
innobackupex: Waiting for ibbackup (pid=6387) to suspend
innobackupex: Suspend file '/tmp/xtrabackup_suspended'

xtrabackup_55 version 2.0.5 for Percona Server 5.5.16 Linux (x86_64) (revision id: 499)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /var/lib/mysql
xtrabackup: Target instance is assumed as followings.
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 = 5242880
xtrabackup: using O_DIRECT
xtrabackup: tables regcomp(test.*): Success
130314 11:35:42 InnoDB: Warning: allocated tablespace 15, old maximum was 9
>> log scanned up to (23311379)
[01] Streaming ./ibdata1
>> log scanned up to (23311379)
[01] ...done
[01] Streaming ./test/t2.ibd
[01] ...done
[01] Streaming ./test/t3.ibd
[01] ...done
[01] Streaming ./test/test_export.ibd
[01] ...done

130314 11:35:50 innobackupex: Continuing after ibbackup has suspended
130314 11:35:50 innobackupex: Starting mysql with options: --unbuffered --
130314 11:35:50 innobackupex: Connected to database with mysql child process (pid=6401)
>> log scanned up to (23311379)
130314 11:35:52 innobackupex: Starting to lock all tables...
>> log scanned up to (23311379)
>> log scanned up to (23311379)
130314 11:36:02 innobackupex: All tables locked and flushed to disk

130314 11:36:02 innobackupex: Starting to backup non-InnoDB tables and files
innobackupex: in subdirectories of '/var/lib/mysql'
percona.deadlocks.frm is skipped because it does not match test.*.
percona.db.opt is skipped because it does not match test.*.
innobackupex: Backing up files '/var/lib/mysql/performance_schema/*.{frm,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (18 files)
performance_schema.threads.frm is skipped because it does not match test.*.
performance_schema.mutex_instances.frm is skipped because it does not match test.*.
performance_schema.events_waits_summary_by_thread_by_event_name.frm is skipped because it does not match test.*.
performance_schema.file_summary_by_instance.frm is skipped because it does not match test.*.
performance_schema.events_waits_summary_by_instance.frm is skipped because it does not match test.*.
performance_schema.file_instances.frm is skipped because it does not match test.*.
performance_schema.setup_instruments.frm is skipped because it does not match test.*.
performance_schema.rwlock_instances.frm is skipped because it does not match test.*.
performance_schema.events_waits_history.frm is skipped because it does not match test.*.
performance_schema.performance_timers.frm is skipped because it does not match test.*.
performance_schema.events_waits_summary_global_by_event_name.frm is skipped because it does not match test.*.
performance_schema.cond_instances.frm is skipped because it does not match test.*.
performance_schema.setup_timers.frm is skipped because it does not match test.*.
performance_schema.file_summary_by_event_name.frm is skipped because it does not match test.*.
performance_schema.events_waits_history_long.frm is skipped because it does not match test.*.
performance_schema.db.opt is skipped because it does not match test.*.
performance_schema.setup_consumers.frm is skipped because it does not match test.*.
performance_schema.events_waits_current.frm is skipped because it does not match test.*.
innobackupex: Backing up file '/var/lib/mysql/test/t2.frm'
innobackupex: Backing up file '/var/lib/mysql/test/test_export.frm'
innobackupex: Backing up file '/var/lib/mysql/test/t1.frm'
innobackupex: Backing up file '/var/lib/mysql/test/t3.frm'
innobackupex: Backing up files '/var/lib/mysql/mysql/*.{frm,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (72 files)
mysql.db.MYI is skipped because it does not match test.*.
mysql.func.MYD is skipped because it does not match test.*.
mysql.user.MYD is skipped because it does not match test.*.
mysql.proc.MYI is skipped because it does not match test.*.
mysql.time_zone_name.MYI is skipped because it does not match test.*.
mysql.time_zone_transition_type.frm is skipped because it does not match test.*.
mysql.help_relation.MYI is skipped because it does not match test.*.
mysql.help_relation.MYD is skipped because it does not match test.*.
mysql.general_log.CSM is skipped because it does not match test.*.
mysql.time_zone_transition.MYD is skipped because it does not match test.*.
mysql.event.frm is skipped because it does not match test.*.
mysql.func.frm is skipped because it does not match test.*.
mysql.db.MYD is skipped because it does not match test.*.
mysql.servers.MYD is skipped because it does not match test.*.
mysql.help_keyword.frm is skipped because it does not match test.*.
mysql.time_zone_name.MYD is skipped because it does not match test.*.
mysql.user.MYI is skipped because it does not match test.*.
mysql.help_topic.MYD is skipped because it does not match test.*.
mysql.time_zone_transition.MYI is skipped because it does not match test.*.
mysql.help_topic.MYI is skipped because it does not match test.*.
mysql.servers.MYI is skipped because it does not match test.*.
mysql.slow_log.CSV is skipped because it does not match test.*.
mysql.proc.frm is skipped because it does not match test.*.
mysql.time_zone_transition_type.MYI is skipped because it does not match test.*.
mysql.help_keyword.MYI is skipped because it does not match test.*.
mysql.procs_priv.MYD is skipped because it does not match test.*.
mysql.slow_log.frm is skipped because it does not match test.*.
mysql.user.frm is skipped because it does not match test.*.
mysql.ndb_binlog_index.frm is skipped because it does not match test.*.
mysql.slow_log.CSM is skipped because it does not match test.*.
mysql.plugin.frm is skipped because it does not match test.*.
mysql.help_category.MYI is skipped because it does not match test.*.
mysql.plugin.MYI is skipped because it does not match test.*.
mysql.procs_priv.frm is skipped because it does not match test.*.
mysql.columns_priv.MYD is skipped because it does not match test.*.
mysql.columns_priv.frm is skipped because it does not match test.*.
mysql.func.MYI is skipped because it does not match test.*.
mysql.event.MYD is skipped because it does not match test.*.
mysql.time_zone.MYI is skipped because it does not match test.*.
mysql.time_zone_name.frm is skipped because it does not match test.*.
mysql.host.MYD is skipped because it does not match test.*.
mysql.time_zone_leap_second.frm is skipped because it does not match test.*.
mysql.help_category.frm is skipped because it does not match test.*.
mysql.general_log.CSV is skipped because it does not match test.*.
mysql.help_topic.frm is skipped because it does not match test.*.
mysql.proxies_priv.MYI is skipped because it does not match test.*.
mysql.proxies_priv.frm is skipped because it does not match test.*.
mysql.plugin.MYD is skipped because it does not match test.*.
mysql.time_zone_transition_type.MYD is skipped because it does not match test.*.
mysql.servers.frm is skipped because it does not match test.*.
mysql.proxies_priv.MYD is skipped because it does not match test.*.
mysql.ndb_binlog_index.MYD is skipped because it does not match test.*.
mysql.time_zone.MYD is skipped because it does not match test.*.
mysql.time_zone_leap_second.MYD is skipped because it does not match test.*.
mysql.columns_priv.MYI is skipped because it does not match test.*.
mysql.time_zone_transition.frm is skipped because it does not match test.*.
mysql.time_zone.frm is skipped because it does not match test.*.
mysql.tables_priv.frm is skipped because it does not match test.*.
mysql.help_keyword.MYD is skipped because it does not match test.*.
mysql.help_relation.frm is skipped because it does not match test.*.
mysql.tables_priv.MYI is skipped because it does not match test.*.
mysql.tables_priv.MYD is skipped because it does not match test.*.
mysql.procs_priv.MYI is skipped because it does not match test.*.
mysql.event.MYI is skipped because it does not match test.*.
mysql.host.MYI is skipped because it does not match test.*.
mysql.time_zone_leap_second.MYI is skipped because it does not match test.*.
mysql.general_log.frm is skipped because it does not match test.*.
mysql.ndb_binlog_index.MYI is skipped because it does not match test.*.
mysql.db.frm is skipped because it does not match test.*.
mysql.host.frm is skipped because it does not match test.*.
mysql.help_category.MYD is skipped because it does not match test.*.
mysql.proc.MYD is skipped because it does not match test.*.
130314 11:36:02 innobackupex: Finished backing up non-InnoDB tables and files

130314 11:36:02 innobackupex: Waiting for log copying to finish

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

xtrabackup: Streaming transaction log from a temporary file...
xtrabackup: Done.
xtrabackup: Transaction log of lsn (23311379) to (23311379) was copied.
xb_stream_read_chunk(): wrong chunk magic at offset 0x1b3990e.
130314 11:36:05 innobackupex: All tables unlocked
130314 11:36:05 innobackupex: Connection to database server closed

innobackupex: Backup created in directory '/root/backup_test'
innobackupex: MySQL binlog position: filename '', position
Failed to stream xtrabackup_binary: Inappropriate ioctl for device at /usr/bin/innobackupex line 311.

The strace log shows the following:
write(1, "XBSTCK01\0P\21\0\0\0xtrabackup_binary\r"..., 51) = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) @ 0 (0) ---
+++ killed by SIGPIPE +++

It would be good to have the exact error code reported.

[Alexey Kopytov (akopytov)]

I believe this bug is no longer valid for any supported versions: we no longer attempt to print $! when a system() call fails. Instead, we print its return value.

[Shahriyar Rzayev (rzayev-sehriyar)]

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