MySQL Bugs: #76312: MySQL Enterprise Backup fails when relay log is deleted during backup

Bug #76312	MySQL Enterprise Backup fails when relay log is deleted during backup
Submitted:	13 Mar 2015 10:31	Modified:	9 Dec 2015 20:53
Reporter:	Oli Sennhauser	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Enterprise Backup	Severity:	S3 (Non-critical)
Version:	3.11.1, 3.12.0	OS:	Linux (SLES 12)
Assigned to:		CPU Architecture:	Any
Tags:	mysql enterprise backup, mysqlbackup

Description:
MySQL Enterprise Backup fails when relay log is deleted during backup

How to repeat:
Typically our MySQL Enterprise Backup runs fine:

mysqlbackup --user=root --backup-dir=... backup-and-apply-log

But suddenly it fails with following error message:

...
150313 11:06:44 mysqlbackup: INFO: Starting to copy Binlog files...

mysqlbackup: Progress in MB: 47400 47600 47800 48000 48200 48400 48600 48800 49000 49200 49400 49600 49800 50000 50200 50400 50600 50800 51000 51200 51400 51600 51800 52000 52200 52400 52600 52800 53000 53200 53400 53600 53800 54000 54200 54400 54600 54800 55000 55200 55400 55600 55800 56000 56200 56400 56600 56800 57000 57200 57400 57600 57800 58000 58200 58400 58600 58800 59000 59200 59400 59600 59800 60000 60200 60400 60600 60800 61000 61200 61400 61600 61800 62000 62200 62400 62600 62800 63000 63200 63400 63600 63800 64000 64200 64400 64600 64800 65000 65200 65400 65600 65800 66000 66200 66400 66600

150313 11:09:04 mysqlbackup: INFO: Switching to log file 1, lsn 453000554496.

mysqlbackup: Progress in MB: 66800 67000 67200 67400 67600 67800 68000 68200 68400 68600 68800 69000 69200 69400 69600 69800 70000 70200 70400 70600 70800 71000 71200 71400 71600

mysqlbackup: ERROR: Opening of file /mysqlflash/data/icosdb200-relay-bin.000070 failed. Error code: 2, No such file or directory

I assume that during our backup the relay log file was deleted by MySQL and mysqlbackup memorized the files to backup before it reached that point...

Suggested fix:
Be more flexible in backing up non directly db related files.

Hello Oli,

Thank you for the report.

Thanks,
Umesh

This is observed when one of the relay log file is missing(slave-relay-bin.000099).

3.12.0 -> complains "mysqlbackup: Can't seek in file 'UNKNOWN' (Errcode: 9 - Bad file descriptor)"

3.11.1 -> complains " mysqlbackup: ERROR: Opening of file /export/umesh/mysql-5.6.25/log/slave-relay-bin.000099 failed. Error code: 2, No such file or directory"

// meb 3.12.0

[umshastr@hod03]~/bugs/meb/meb-3.12.0: bin/mysqlbackup --user=root --socket=/export/umesh/mysql-5.6.25/run/slave.sock --with-timestamp --backup-dir=/export/umesh/mysql-5.6.25/backup backup-and-apply-log
MySQL Enterprise Backup version 3.12.0 Linux-3.8.13-35.2.1.el7uek.x86_64-x86_64 [2015/03/10]
Copyright (c) 2003, 2015, Oracle and/or its affiliates. All Rights Reserved.

 mysqlbackup: INFO: Starting with following command line ...
 bin/mysqlbackup --user=root
        --socket=/export/umesh/mysql-5.6.25/run/slave.sock --with-timestamp
        --backup-dir=/export/umesh/mysql-5.6.25/backup backup-and-apply-log

 mysqlbackup: INFO:
 mysqlbackup: INFO: MySQL server version is '5.6.25-enterprise-commercial-advanced-log'.
 mysqlbackup: INFO: Got some server configuration information from running server.

IMPORTANT: Please check that mysqlbackup run completes successfully.
           At the end of a successful 'backup-and-apply-log' run mysqlbackup
           prints "mysqlbackup completed OK!".

150325 11:45:38 mysqlbackup: INFO: MEB logfile created at /export/umesh/mysql-5.6.25/backup/2015-03-25_11-45-38/meta/MEB_2015-03-25.11-45-38_backup_apply_log.log

..

150325 11:45:47 mysqlbackup: INFO: Copying /export/umesh/mysql-5.6.25/log/slave-relay-bin.000096.
150325 11:45:47 mysqlbackup: INFO: Copying /export/umesh/mysql-5.6.25/log/slave-relay-bin.000097.
 mysqlbackup: Progress in MB: 1800
150325 11:45:47 mysqlbackup: INFO: Copying /export/umesh/mysql-5.6.25/log/slave-relay-bin.000098.
mysqlbackup: Can't seek in file 'UNKNOWN' (Errcode: 9 - Bad file descriptor)
150325 11:45:48 mysqlbackup: INFO: All tables unlocked
150325 11:45:48 mysqlbackup: INFO: All MySQL tables were locked for 1.666 seconds.

mysqlbackup failed with errors!

// meb 3.11.1

[umshastr@hod03]~/bugs/meb/meb-3.11.1: bin/mysqlbackup --user=root --socket=/export/umesh/mysql-5.6.25/run/slave.sock --with-timestamp --backup-dir=/export/umesh/mysql-5.6.25/backup backup-and-apply-log
MySQL Enterprise Backup version 3.11.1 Linux-2.6.18-194.el5-x86_64 [2014/11/04]
Copyright (c) 2003, 2014, Oracle and/or its affiliates. All Rights Reserved.

 mysqlbackup: INFO: Starting with following command line ...
 bin/mysqlbackup --user=root
        --socket=/export/umesh/mysql-5.6.25/run/slave.sock --with-timestamp
        --backup-dir=/export/umesh/mysql-5.6.25/backup backup-and-apply-log

 mysqlbackup: INFO:
 mysqlbackup: INFO: MySQL server version is '5.6.25-enterprise-commercial-advanced-log'.
 mysqlbackup: INFO: Got some server configuration information from running server.

..
..
150325 11:47:29 mysqlbackup: INFO: Completing the copy of innodb files.
150325 11:47:30 mysqlbackup: INFO: Starting to copy Binlog files...
150325 11:47:31 mysqlbackup: INFO: Preparing to lock tables: Connected to mysqld server.
150325 11:47:31 mysqlbackup: INFO: Starting to lock all the tables...
150325 11:47:31 mysqlbackup: INFO: All tables are locked and flushed to disk
 mysqlbackup: Progress in MB: 1600 1800
 mysqlbackup: ERROR: Opening of file /export/umesh/mysql-5.6.25/log/slave-relay-bin.000099 failed. Error code: 2, No such file or directory
150325 11:47:33 mysqlbackup: INFO: All tables unlocked
150325 11:47:33 mysqlbackup: INFO: All MySQL tables were locked for 2.115 seconds.

mysqlbackup failed with errors!

Added the following entry to the MySQL Enterprise Backup 3.12.2 and 4.0.1
changelogs:

"A backup of a slave server failed if, during the backup, a relay log file
got purged from the slave server (for example, due to a log file rotation).
With this fix, backup continues even if mysqlbackup finds a relay log file
missing."