MySQL Bugs: #83927: MySQL Enterprise Backup does not restore binary logs to the right location

Bug #83927	MySQL Enterprise Backup does not restore binary logs to the right location
Submitted:	23 Nov 2016 8:46	Modified:	17 Jan 2019 1:54
Reporter:	Oli Sennhauser	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Enterprise Backup	Severity:	S3 (Non-critical)
Version:	4.0.3	OS:	Red Hat (7.2)
Assigned to:		CPU Architecture:	Any
Tags:	binary log, mysql enterprise backup, restore

Description:
MySQL Enterprise Backup does not restore binary logs to the right location.

right = the location they were originally during backup

How to repeat:
shell> mysqlbackup  --port=3308 --user=root --password='' --socket=/var/run/mysqld/mysql-olitest.sock \
 --backup-dir=/l/mysql/olibackup/backup1 --backup-image=olibckimg backup-to-image

MySQL Enterprise Backup version 4.0.3 Linux-3.8.13-118.4.2.el7uek.x86_64-x86_64 [2016/08/04]
Copyright (c) 2003, 2016, Oracle and/or its affiliates. All Rights Reserved.

 mysqlbackup: INFO: Starting with following command line ...
 mysqlbackup --port=3308 --user=root --password=
        --socket=/var/run/mysqld/mysql-olitest.sock
        --backup-dir=/l/mysql/olibackup/backup1 --backup-image=olibckimg
        backup-to-image

 mysqlbackup: INFO:
 mysqlbackup: INFO: MySQL server version is '5.7.16-enterprise-commercial-advanced-log'
 mysqlbackup: INFO: MySQL server compile os version is 'linux-glibc2.5'
 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-to-image' run mysqlbackup
           prints "mysqlbackup completed OK!".

161123 09:32:01 mysqlbackup: INFO: MEB logfile created at /l/mysql/olibackup/backup1/meta/MEB_2016-11-23.09-32-01_image_backup.log

--------------------------------------------------------------------
                       Server Repository Options:
--------------------------------------------------------------------
  datadir = /home/mysql/data/olitest/
  innodb_data_home_dir =
  innodb_data_file_path = ibdata1:12M:autoextend
  innodb_log_group_home_dir = /home/mysql/data/olitest/
  innodb_log_files_in_group = 2
  innodb_log_file_size = 16777216
  innodb_page_size = 16384
  innodb_checksum_algorithm = crc32
  innodb_buffer_pool_filename = ib_buffer_pool
  innodb_undo_directory = /home/mysql/data/olitest/
  innodb_undo_tablespaces = 0
  innodb_undo_logs = 128

--------------------------------------------------------------------
                       Backup Config Options:
--------------------------------------------------------------------
  datadir = /l/mysql/olibackup/backup1/datadir
  innodb_data_home_dir = /l/mysql/olibackup/backup1/datadir
  innodb_data_file_path = ibdata1:12M:autoextend
  innodb_log_group_home_dir = /l/mysql/olibackup/backup1/datadir
  innodb_log_files_in_group = 2
  innodb_log_file_size = 16777216
  innodb_page_size = 16384
  innodb_checksum_algorithm = crc32
  innodb_buffer_pool_filename = ib_buffer_pool
  innodb_undo_directory = /l/mysql/olibackup/backup1/datadir
  innodb_undo_tablespaces = 0
  innodb_undo_logs = 128

Backup Image Path = /l/mysql/olibackup/backup1/olibckimg
 mysqlbackup: INFO: Unique generated backup id for this is 14798899218747893

 mysqlbackup: INFO: Creating 14 buffers each of size 16777216.
161123 09:32:01 mysqlbackup: INFO: Full Image Backup operation starts with following threads
                1 read-threads    6 process-threads    1 write-threads
161123 09:32:01 mysqlbackup: INFO: System tablespace file format is Barracuda.
161123 09:32:01 mysqlbackup: INFO: Starting to copy all innodb files...
 mysqlbackup: INFO: Copying meta file /l/mysql/olibackup/backup1/backup-my.cnf.
161123 09:32:01 mysqlbackup: INFO: Found checkpoint at lsn 2541233.
161123 09:32:01 mysqlbackup: INFO: Starting log scan from lsn 2541056.
161123 09:32:01 mysqlbackup: INFO: Copying log...
161123 09:32:01 mysqlbackup: INFO: Log copied, lsn 2541242.
 mysqlbackup: INFO: Copying meta file /l/mysql/olibackup/backup1/meta/backup_create.xml.
161123 09:32:01 mysqlbackup: INFO: Copying /home/mysql/data/olitest/ibdata1 (Barracuda file format).
161123 09:32:01 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/engine_cost.ibd (Barracuda file format).
161123 09:32:01 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/gtid_executed.ibd (Barracuda file format).
161123 09:32:01 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/help_category.ibd (Barracuda file format).
161123 09:32:01 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/help_keyword.ibd (Barracuda file format).
161123 09:32:01 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/help_relation.ibd (Barracuda file format).
161123 09:32:01 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/help_topic.ibd (Barracuda file format).
161123 09:32:01 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/innodb_index_stats.ibd (Barracuda file format).
161123 09:32:01 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/innodb_table_stats.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/plugin.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/server_cost.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/servers.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/slave_master_info.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/slave_relay_log_info.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/slave_worker_info.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/time_zone.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/time_zone_leap_second.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/time_zone_name.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/time_zone_transition.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/mysql/time_zone_transition_type.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/sys/sys_config.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest/test/test.ibd (Barracuda file format).
161123 09:32:02 mysqlbackup: INFO: Completing the copy of innodb files.
161123 09:32:02 mysqlbackup: INFO: Starting to copy Binlog files...
161123 09:32:02 mysqlbackup: INFO: Preparing to lock tables: Connected to mysqld server.
161123 09:32:02 mysqlbackup: INFO: Starting to lock all the tables...
161123 09:32:02 mysqlbackup: INFO: All tables are locked and flushed to disk
161123 09:32:02 mysqlbackup: INFO: Copying /home/mysql/data/olitest-binlog/bsul0157_olitest_binlog.000001.
161123 09:32:02 mysqlbackup: INFO: Completed the copy of binlog files...
161123 09:32:02 mysqlbackup: INFO: Opening backup source directory '/home/mysql/data/olitest'
161123 09:32:02 mysqlbackup: INFO: Starting to backup all non-innodb files in
        subdirectories of '/home/mysql/data/olitest'
161123 09:32:02 mysqlbackup: INFO: Adding database directory: datadir
161123 09:32:02 mysqlbackup: INFO: Adding database directory: datadir
161123 09:32:02 mysqlbackup: INFO: Adding database directory: datadir
161123 09:32:02 mysqlbackup: INFO: Completing the copy of all non-innodb files.
161123 09:32:02 mysqlbackup: INFO: Adding database directory: datadir
161123 09:32:02 mysqlbackup: INFO: A copied database page was modified at 2541011.
          (This is the highest lsn found on page)
          Scanned log up to lsn 2541242.
          Was able to parse the log up to lsn 2541242.
161123 09:32:02 mysqlbackup: INFO: All tables unlocked
161123 09:32:02 mysqlbackup: INFO: All MySQL tables were locked for 0.155 seconds.
161123 09:32:02 mysqlbackup: INFO: Reading all global variables from the server.
161123 09:32:02 mysqlbackup: INFO: Completed reading of all global variables from the server.
 mysqlbackup: INFO: Writing config file for server '5.7.16-enterprise-commercial-advanced-log'.
161123 09:32:02 mysqlbackup: INFO: Creating server config files server-my.cnf and server-all.cnf in /l/mysql/olibackup/backup1
 mysqlbackup: INFO: Copying meta file /l/mysql/olibackup/backup1/meta/backup_variables.txt.
 mysqlbackup: INFO: Copying meta file /l/mysql/olibackup/backup1/datadir/ibbackup_logfile.
 mysqlbackup: INFO: Copying meta file /l/mysql/olibackup/backup1/server-all.cnf.
 mysqlbackup: INFO: Copying meta file /l/mysql/olibackup/backup1/server-my.cnf.
 mysqlbackup: INFO: Copying meta file /l/mysql/olibackup/backup1/meta/backup_content.xml.
 mysqlbackup: INFO: Copying meta file /l/mysql/olibackup/backup1/meta/image_files.xml.
161123 09:32:02 mysqlbackup: INFO: Full Image Backup operation completed successfully.
161123 09:32:02 mysqlbackup: INFO: Backup image created successfully.
 mysqlbackup: INFO: Image Path = /l/mysql/olibackup/backup1/olibckimg
161123 09:32:02 mysqlbackup: INFO: MySQL binlog position: filename bsul0157_olitest_binlog.000001, position 1465

-------------------------------------------------------------
   Parameters Summary
-------------------------------------------------------------
   Start LSN                  : 2541056
   End LSN                    : 2541242
-------------------------------------------------------------

mysqlbackup completed OK!

shell> mysqlbackup --user=root --backup-image=olibckimg \
--backup-dir=/l/mysql/olibackup/backup1 --datadir=/home/mysql/data/olitest copy-back-and-apply-log

MySQL Enterprise Backup version 4.0.3 Linux-3.8.13-118.4.2.el7uek.x86_64-x86_64 [2016/08/04]
Copyright (c) 2003, 2016, Oracle and/or its affiliates. All Rights Reserved.

 mysqlbackup: INFO: Starting with following command line ...
 mysqlbackup --user=root --backup-image=olibckimg
        --backup-dir=/l/mysql/olibackup/backup1
        --datadir=/home/mysql/data/olitest copy-back-and-apply-log

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

 mysqlbackup: INFO: Backup Image MEB version string: 4.0.3 [2016/08/04]
 mysqlbackup: INFO: MySQL server version is '5.7.16'
161123 09:38:10 mysqlbackup: INFO: MEB logfile created at /l/mysql/olibackup/backup1/meta/MEB_2016-11-23.09-38-10_copy_back_img_to_datadir.log

 mysqlbackup: WARNING: If you restore to a server of a different version, the innodb_data_file_path parameter might have a different default. In that case you need to add 'innodb_data_file_path=ibdata1:12M:autoextend' to the target server configuration.
 mysqlbackup: WARNING: If you restore to a server of a different version, the innodb_log_files_in_group parameter might have a different default. In that case you need to add 'innodb_log_files_in_group=2' to the target server configuration.
 mysqlbackup: WARNING: If you restore to a server of a different version, the innodb_log_file_size parameter might have a different default. In that case you need to add 'innodb_log_file_size=16777216' to the target server configuration.
 mysqlbackup: INFO: Keyring service not initialized. MEB cannot validate the encryption keys.
 mysqlbackup: INFO: Valid keyring to be specified on server start to access the encrypted tables.
--------------------------------------------------------------------
                       Server Repository Options:
--------------------------------------------------------------------
  datadir = /home/mysql/data/olitest
  innodb_data_home_dir = /home/mysql/data/olitest
  innodb_data_file_path = ibdata1:12M:autoextend
  innodb_log_group_home_dir = /home/mysql/data/olitest
  innodb_log_files_in_group = 2
  innodb_log_file_size = 16777216
  innodb_page_size = Null
  innodb_checksum_algorithm = crc32
  innodb_buffer_pool_filename = ib_buffer_pool

--------------------------------------------------------------------
                       Backup Config Options:
--------------------------------------------------------------------
  datadir = /l/mysql/olibackup/backup1/datadir
  innodb_data_home_dir = /l/mysql/olibackup/backup1/datadir
  innodb_data_file_path = ibdata1:12M:autoextend
  innodb_log_group_home_dir = /l/mysql/olibackup/backup1/datadir
  innodb_log_files_in_group = 2
  innodb_log_file_size = 16777216
  innodb_page_size = 16384
  innodb_checksum_algorithm = crc32
  innodb_buffer_pool_filename = ib_buffer_pool

 mysqlbackup: INFO: Creating 14 buffers each of size 16777216.
161123 09:38:10 mysqlbackup: INFO: Copy-back-and-apply-log operation starts with following threads
                1 read-threads    6 process-threads    1 write-threads
161123 09:38:10 mysqlbackup: INFO: Copying database directory: meta
161123 09:38:10 mysqlbackup: INFO: Copying ibdata1.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/engine_cost.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/gtid_executed.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/help_category.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/help_keyword.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/help_relation.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/help_topic.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying database directory: mysql
161123 09:38:10 mysqlbackup: INFO: Copying mysql/innodb_index_stats.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/innodb_table_stats.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/plugin.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/server_cost.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/servers.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/slave_master_info.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/slave_relay_log_info.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/slave_worker_info.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/time_zone.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/time_zone_leap_second.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/time_zone_name.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/time_zone_transition.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying mysql/time_zone_transition_type.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying database directory: performance_schema
161123 09:38:10 mysqlbackup: INFO: Copying sys/sys_config.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying database directory: sys
161123 09:38:10 mysqlbackup: INFO: Copying test/test.ibd.
161123 09:38:10 mysqlbackup: INFO: Copying database directory: test
161123 09:38:10 mysqlbackup: INFO: Copying bsul0157_olitest_binlog.000001.
161123 09:38:10 mysqlbackup: INFO: Copying database directory: mysql
161123 09:38:10 mysqlbackup: INFO: Copying database directory: performance_schema
161123 09:38:11 mysqlbackup: INFO: Copying database directory: sys
161123 09:38:11 mysqlbackup: INFO: Copying database directory: test
161123 09:38:11 mysqlbackup: INFO: Total files as specified in image: 299
 mysqlbackup: INFO: MySQL server version is '5.7.16-enterprise-commercial-advanced-log'
 mysqlbackup: INFO: MySQL server compile os version is 'linux-glibc2.5'
 mysqlbackup: INFO: Writing config file for server '5.7.16-enterprise-commercial-advanced-log'.
161123 09:38:11 mysqlbackup: INFO: Creating server config files server-my.cnf and server-all.cnf in /home/mysql/data/olitest
161123 09:38:11 mysqlbackup: INFO: Copy-back operation completed successfully.
 mysqlbackup: INFO: Source Image Path = /l/mysql/olibackup/backup1/olibckimg

 mysqlbackup: INFO: MySQL server version is '5.7.16-enterprise-commercial-advanced-log'
 mysqlbackup: INFO: Restoring ...5.7.16-enterprise-commercial-advanced-log version
 mysqlbackup: INFO: Creating 14 buffers each of size 65536.
161123 09:38:11 mysqlbackup: INFO: Apply-log operation starts with following threads
                1 read-threads    1 process-threads
 mysqlbackup: INFO: Using up to 100 MB of memory.
161123 09:38:11 mysqlbackup: INFO: ibbackup_logfile's creation parameters:
          start lsn 2541056, end lsn 2541242,
          start checkpoint 2541233.
 mysqlbackup: INFO: InnoDB: Doing recovery: scanned up to log sequence number 2541242.
 mysqlbackup: INFO: InnoDB: Starting an apply batch of log records to the database...
.
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
 mysqlbackup: INFO: InnoDB: Setting log file size to 16777216.
 mysqlbackup: INFO: InnoDB: Setting log file size to 16777216.
161123 09:38:11 mysqlbackup: INFO: We were able to parse ibbackup_logfile up to
          lsn 2541242.
 mysqlbackup: INFO: Last MySQL binlog file position 0 1465, file name bsul0157_olitest_binlog.000001:1465
161123 09:38:11 mysqlbackup: INFO: The first data file is '/home/mysql/data/olitest/ibdata1'
          and the new created log files are at '/home/mysql/data/olitest'
 mysqlbackup: INFO: MySQL server version is '5.7.16-enterprise-commercial-advanced-log'
 mysqlbackup: INFO: Restoring ...5.7.16-enterprise-commercial-advanced-log version
161123 09:38:11 mysqlbackup: INFO: Apply-log operation completed successfully.
161123 09:38:11 mysqlbackup: INFO: Full Backup has been restored successfully.

mysqlbackup completed OK! with 3 warnings

shell> ll olitest*
olitest:
total 45120
-rw-rw-r-- 1 mysql mysql      428 Nov 23 09:41 backup_variables.txt
-rw-rw-r-- 1 mysql mysql     1465 Nov 23 09:41 bsul0157_olitest_binlog.000001
-rw-rw-r-- 1 mysql mysql       33 Nov 23 09:41 bsul0157_olitest_binlog.index
<-- They were NOT here during backup!!!
-rw-rw-r-- 1 mysql mysql      413 Nov 23 09:41 ib_buffer_pool
-rw-rw-r-- 1 mysql mysql 12582912 Nov 23 09:41 ibdata1
-rw-rw---- 1 mysql mysql 16777216 Nov 23 09:41 ib_logfile0
-rw-rw---- 1 mysql mysql 16777216 Nov 23 09:41 ib_logfile1
drwxr-x--- 2 mysql mysql     4096 Nov 23 09:41 mysql
drwxr-x--- 2 mysql mysql     4096 Nov 23 09:41 performance_schema
-rw-rw-r-- 1 mysql mysql    15521 Nov 23 09:41 server-all.cnf
-rw-rw-r-- 1 mysql mysql     4691 Nov 23 09:41 server-my.cnf
drwxr-x--- 2 mysql mysql    12288 Nov 23 09:41 sys
drwxr-x--- 2 mysql mysql     4096 Nov 23 09:41 test

olitest-binlog:
total 0
<-- They should be here

Suggested fix:
1. Restore to the original location

Hello Oli,

Thank you for the report and steps.

Thanks,
Umesh

test results

Attachment: 83927.results (application/octet-stream, text), 22.20 KiB.

Posted by developer:
 
The fix has already been documented as a new feature in the MySQL Enterprise Backup 8.0.12 and 4.1.2 changelogs. The following have now been added:

- The associated bug numbers have been added to the changelogs for reference.  
- Before, it was not mentioned in the 4.1.2 changelog that the relay log is now also restored by default to its location on the backed up server; it has now been added.