Bug #75074 MEB 3.11.1 failing on relay log backup
Submitted: 2 Dec 2014 16:16 Modified: 6 Mar 2015 22:56
Reporter: Rafael Bos Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Enterprise Backup Severity:S2 (Serious)
Version:3.11.1 OS:Linux (rhel5 x86_64)
Assigned to: CPU Architecture:Any

[2 Dec 2014 16:16] Rafael Bos
Description:
Hi,
after upgrade of MEB 3.11.0 (3.10.1 as well) to 3.11.1, to avoid skipping of certain DBs (noted as Bug #19883801 in changelog) backup fails on relay logs apparently:

The error message is "Error while getting current log file from server in initialization for online backup"

This is part of the trace collected:
141202 14:46:41 mysqlbackup: INFO: Starting to copy all innodb files...
 mysqlbackup: TRACE_2: Value for Server Variable log_bin_index is: /var/mysql/binlog.index
 mysqlbackup: TRACE_2: Value for Server Variable relay_log_index is:
 mysqlbackup: TRACE_3: relay-log-index file : '/var/mysql/bhxpla05-relay-bin.index'
 mysqlbackup: TRACE_1: Bin Log : '/var/mysql/binlog.index'
 mysqlbackup: TRACE_1: Relay Log : '/var/mysql/bhxpla05-relay-bin.index'
stack_bottom = 0 thread_stack 0x10000
/opt/mysql/meb-3.11/bin/mysqlbackup(my_print_stacktrace+0x32)[0x5c321c]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb9ExceptionC1ENS_18enum_error_numbersEPKcS3_i+0x83)[0x485c73]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb10Log_copier22init_for_online_backupEv+0x7a)[0x4934fa]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb15Relaylog_copier22init_for_online_backupEv+0x1f)[0x49354f]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb15Relaylog_copier4initEv+0x9)[0x491249]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb8Data_set15init_log_copierEv+0x268)[0x482528]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb8Data_setC1Ev+0x3d7)[0x483467]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb13Read_data_mgrC1EPNS_12Buffer_queueES2_+0x26)[0x56fc66]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb7ManagerC1ENS_17enum_manager_typeEPNS_12Buffer_queueES3_j+0x10c)[0x496dbc]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb11Meb_session4initEv+0x367)[0x498777]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb11Meb_session12init_sessionEiPPc+0x16d)[0x4999bd]
/opt/mysql/meb-3.11/bin/mysqlbackup(_ZN3meb20mysqlbackup_parallelEiPPc+0x1a)[0x55f07a]
/opt/mysql/meb-3.11/bin/mysqlbackup(main+0xa6)[0x55f266]
/lib64/libc.so.6(__libc_start_main+0xf4)[0x3bbae1d9c4]
/opt/mysql/meb-3.11/bin/mysqlbackup(__gxx_personality_v0+0x2e9)[0x4698b9]
 mysqlbackup: ERROR: Error while getting current log file from server in initialization for online backup.
 mysqlbackup: TRACE_1: Error occurred and closing threads.
 mysqlbackup: TRACE_2: Value for Server Variable innodb_file_format is: Antelope
 mysqlbackup: TRACE_1: Inserting to history table.
 mysqlbackup: TRACE_1: Inserting to progress table.

Running MySQL 5.6 (MySQL-server-advanced-5.6.18-1) on rhel5 and rhel6 servers. Replication is stopped at this moment (and setup cleared with "reset slave"), but used on demand on this instance when required. When mysqlbackup is started with "--skip-relaylog" backup completes without any errors. The same applies when old relay logs are deleted.

How to repeat:
1. Setup replication on MySQL instance
2. Stop it, clear setup
3. Restart MySQL
4. Run mysqlbackup -> without --skip-relaylog, keep old relay logs

Suggested fix:
Same behavior as with 3.11.0 - backup completes even when relay logs exist.
[5 Dec 2014 13:02] MySQL Verification Team
Thank you for the report.
I tried with reported version and with latest MEB build but didn't see this issue on OL6/OL7 etc.
Could you please provide exact command used for backup, conf file used and any relevant info which would helps to to reproduce at our end?

Thanks,
Umesh
[9 Dec 2014 7:35] Rafael Bos
Backup command:

/opt/mysql/meb-3.11/bin/mysqlbackup --defaults-extra-file=/var/mysql/my.pwd --with-timestamp --backup-dir=/var/backup/mysql --debug --trace=3 --compress backup

Steps to reproduce the error:
1) # service mysql start
2) mysql> CHANGE MASTER TO ...
3) mysql> START SLAVE;
4) mysql> STOP SLAVE;
5) mysql> RESET SLAVE;
6) # service mysql stop
7) # service mysql start
8) # mysqlbackup ...

Sample config:
[client]
socket       = /var/mysql/mysql.sock
port         = 3306

[mysqld]
socket       = /var/mysql/mysql.sock
port         = 3306
datadir      = /var/mysql
bind-address = 1.2.3.4

tmpdir = /var/mysql/tmp

ignore-db-dir=lost+found

server-id   = 111
relay-log = test05-relay-bin
replicate-wild-do-table  = GPS.%

auto_increment_increment = 3
auto_increment_offset    = 3

max_allowed_packet = 1G

key_buffer_size = 128M
table_open_cache        = 2048
table_definition_cache  = 1024
open_files_limit        = 4096

join_buffer_size    =    256K
max_connections     =  500
max_connect_errors  =   10
max_delayed_threads =   0
max_sort_length     = 256
thread_cache_size   =   20

query_cache_size=32M

max_user_connections    = 2000
read_rnd_buffer_size    = 128K
read_buffer_size        = 128K
sort_buffer_size        = 256M
tmp_table_size  =  256M
max_heap_table_size     =  1G

# InnoDB
innodb_data_home_dir            = /var/mysql/innodb
innodb_log_group_home_dir       = /var/mysql/innodb
innodb_data_file_path           = ibdata1:4G:autoextend
innodb_file_per_table
innodb_buffer_pool_size         =  6G
innodb_flush_log_at_trx_commit  = 2
innodb_log_files_in_group       = 2
innodb_log_file_size            = 128M
innodb_log_buffer_size          = 8M
innodb_lock_wait_timeout        = 50
innodb_checksum_algorithm       = INNODB
binlog_checksum = NONE

[mysqld_safe]
socket   = /var/mysql/mysql.sock
pid_file = /var/mysql/test05.pid
user     = mysql
[9 Dec 2014 10:48] MySQL Verification Team
Thank you for the feedback.
Verified as described now.

Thanks,
Umesh
[9 Dec 2014 11:03] MySQL Verification Team
test results

Attachment: 75074.txt (text/plain), 11.30 KiB.

[26 Feb 2015 8:02] MySQL Verification Team
Bug #76046 Marked as duplicate of this
[6 Mar 2015 22:56] Daniel So
Added the following entry to the MySQL Enterprise Backup 3.12.0 changelog:

"After a RESET SLAVE statement was executed on a slave server, a subsequent backup for the slave server failed with an error, as mysqlbackup could not copy the relay log file from the server. This was because mysqlbackup could not detect the location of the current relay log after the slave reset, and the this fix makes sure mysqlbackup knows how to do that."