Incorrect backup status reported

[Ankit]

I am using following command to take a full DB backup

innobackupex --defaults-extra-file=/home/dba/admin/logs/admur.mysqld.tmp --defaults-group=mysqld --lock-wait-timeout=3600 --parallel=2 --encrypt=AES256 --encrypt-threads=2 --encrypt-key-file=/home/dba/admin/config/dbbackup_keyfile.txt --stream=xbstream --compress --compress-threads=2 --no-timestamp ./ > /home/dba/dbBkp/m1.thakwani.com.mysqld.2017-06-14-10-58-18.full.encrypted.xbstream.qpress

The log message is :

170614 10:58:19 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!".

170614 10:58:19 version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;port=3306;mysql_socket=/u01/mysql06/mysqllogs/mysql.sock' as 'bkpusr' (using password: YES).
170614 10:58:19 version_check Connected to MySQL server
170614 10:58:19 version_check Executing a version check against the server...
170614 10:58:19 version_check Done.
170614 10:58:19 Connecting to MySQL server host: localhost, user: bkpusr, password: set, port: 3306, socket: /u01/mysql06/mysqllogs/mysql.sock
Using server version 5.7.18-log
innobackupex version 2.4.7 based on MySQL server 5.7.13 Linux (x86_64) (revision id: 05f1fcf)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /u01/mysql06/mysqldata
xtrabackup: open files limit requested 65535, set to 65535
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 = 58720256
xtrabackup: using O_DIRECT
InnoDB: Number of pools: 1
InnoDB: Operating system error number 13 in a file operation.
InnoDB: The error means mysqld does not have the access rights to the directory.
InnoDB: Error in opening ./ib_logfile0
innobackupex: completed OK!

Even though the backup fails because of file permission, the backup is reported as completed successfully with "innobackupex: completed OK!" message in the end.

As per the documentation at https://www.percona.com/doc/percona-xtrabackup/LATEST/howtos/recipes_ibkx_local.html if message ""innobackupex: completed OK!" is printed at the end then backup is deemed to be successful but this is not the case here.

[Muhammad Irfan (muhammad-irfan)]

Can you please share my.cnf contents and backup-my.cnf file contents from backup directory.

[Ankit (ankit-thakwani)]

The backup-my.cnf is not available since the backup file was not created, following are contents of /etc/my.cnf

[mysql]

# CLIENT #
port = 3306
socket = /u01/mysql06/mysqllogs/mysql.sock

[client]
port = 3306
socket = /u01/mysql06/mysqllogs/mysql.sock

[mysqld]

# GENERAL #
server_id = 300640
character_set_server = utf8
user = mysql
default-storage-engine = InnoDB
socket = /u01/mysql06/mysqllogs/mysql.sock
pid-file = /u01/mysql06/mysqllogs/mysql.pid
port = 3306

# MyISAM #
key-buffer-size = 32M
myisam-recover-options = FORCE,BACKUP

# PASSWORD PLUGIN #
#plugin-load-add = validate_password.so
#validate-password = FORCE_PLUS_PERMANENT
#validate_password_policy = STRONG

# SAFETY #
max-allowed-packet = 52M
max-connect-errors = 1000000
sql_mode = ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION
skip-name-resolve
sysdate-is-now = 1
default-time-zone = '+05:30'
#innodb = FORCE
innodb-strict-mode = 1
interactive_timeout = 180
wait_timeout = 180
skip-symbolic-links

# DATA STORAGE #
datadir = /u01/mysql06/mysqldata

# BINARY LOGGING #
binlog_format = ROW
binlog_row_image = FULL
log-bin = /u01/mysql06/mysqllogs/binlogs/mysql-bin
expire-logs-days = 10
sync-binlog = 0
binlog_rows_query_log_events = OFF
binlog_checksum = CRC32

# REPLICATION #
read_only = 0
skip-slave-start = 1
relay-log = /u01/mysql06/mysqllogs/relaylogs/relay-bin
slave-net-timeout = 60
master_info_repository = TABLE
relay_log_info_repository = TABLE
relay_log_recovery = ON
master_verify_checksum = ON
log_slave_updates = ON
sync_master_info = 1000

# CACHES AND LIMITS #
tmp-table-size = 32M
max-heap-table-size = 32M
query-cache-type = 0
query-cache-size = 0
max-connections = 500
thread-cache-size = 50
open-files-limit = 65535
table-definition-cache = 1024
table-open-cache = 500

# INNODB #
innodb_io_capacity = 250
innodb-flush-method = O_DIRECT
innodb_data_file_path = ibdata1:100M:autoextend
innodb-log-files-in-group = 2
innodb-log-file-size = 56M
innodb-flush-log-at-trx-commit = 0
innodb-file-per-table = 1
innodb-buffer-pool-size = 128M
innodb_buffer_pool_instances = 12
innodb_thread_concurrency = 0
innodb_commit_concurrency = 0
innodb_online_alter_log_max_size = 5368709120
innodb_buffer_pool_dump_at_shutdown = ON
innodb_buffer_pool_load_at_startup = ON
innodb_monitor_enable = all
innodb_ad...

[Vasily Nemkov (vasily.nemkov)]

Wasn't able to reproduce the bug against both reported 2.4.7 and the most recent development version 2.4. After a careful inspection of the code, the bug itself looks unrealistic - PXB terminates itself right after printing out information about IO error.
Are you sure that you don't have any kind of a wrapper script or a custom build?

[Shahriyar Rzayev (rzayev-sehriyar)]

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