Multiple Slave IO Threads

[Jervin R]

Reporting on behalf of Marcos and the customer:

We'ves seen a slave instance where multiple slave IO instance wanted to start replication. From the relay log we can see this:

#150730 13:30:35 server id 64623 end_log_pos 107 Start: binlog v 4, server v 5.5.20-55-log created 150730 13:30:35
BINLOG '
a4m6VQ9v/AAAZwAAAGsAAAAAAAQANS41LjIwLTU1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 150
#150730 11:30:27 server id 64523 end_log_pos 0 Start: binlog v 4, server v 5.5.20-55-log created 150730 11:30:27

Two distinct server ids which should not happen, if a change master is initiated, I expect it to clear the existing relay logs not write to the last one.

This also may have caused multiple entries on the master.info file:

----------------------------------------
cat mysql-master.info
18
mysql-bin.000458
224734730
45.db.prod.slv.HOST
repl
password
7023
60
0

0
1800.000

0
18
mysql-bin.000458
224730887
45.db.prod.slv.HOST
repl
password
7023
60
0
----------------------------------------

Version is Version: '5.5.20-55-log' socket: '/var/lib/mysql/mysql.sock23' port: 7023 Percona Server (GPL), Release rel24.1, Revision 217

[markus_albe (markus-albe)]

sanitized relay log dump for positions seen in error log

```/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150730 13:30:35 server id 64623 end_log_pos 107 Start: binlog v 4, server v 5.5.20-55-log created 150730 13:30:35
BINLOG '
a4m6VQ9v/AAAZwAAAGsAAAAAAAQANS41LjIwLTU1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 150
#150730 11:30:27 server id 64523 end_log_pos 0 Start: binlog v 4, server v 5.5.20-55-log created 150730 11:30:27
BINLOG '
Q226VQ8L/AAAZwAAAAAAAAAAAAQANS41LjIwLTU1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 87508984
#150730 13:30:41 server id 64523 end_log_pos 87496169 Query thread_id=439840 exec_time=0 error_code=0
SET TIMESTAMP=1438288241/*!*/;
SET @@session.pseudo_thread_id=439840/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=2097152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 87509055
#150730 13:30:41 server id 64523 end_log_pos 87496169 Query thread_id=439840 exec_time=0 error_code=0
SET TIMESTAMP=1438288241/*!*/;
BEGIN
/*!*/;
# at 87509126
#150730 13:30:41 server id 64523 end_log_pos 87496627 Query thread_id=439840 exec_time=0 error_code=0
use zapps23/*!*/;
SET TIMESTAMP=1438288241/*!*/;
<STATEMENT>
/*!*/;
# at 87509584
#150730 13:30:41 server id 64523 end_log_pos 87496627 Query thread_id=439840 exec_time=0 error_code=0
SET TIMESTAMP=1438288241/*!*/;
<STATEMENT>
/*!*/;
# at 87510042
#150730 13:30:41 server id 64523 end_log_pos 87496654 Xid = 301895834
COMMIT/*!*/;
# at 87510069
#150730 13:30:41 server id 64523 end_log_pos 87496654 Xid = 301895834
COMMIT/*!*/;
# at 87510096
#150730 13:30:41 server id 64523 end_log_pos 87496725 Query thread_id=439842 exec_time=0 error_code=0
SET TIMESTAMP=1438288241/*!*/;
BEGIN
/*!*/;
# at 87510167
#150730 13:30:41 server id 64523 end_log_pos 87496725 Query thread_id=439842 exec_time=0 error_code=0
SET TIMESTAMP=1438288241/*!*/;
BEGIN
/*!*/;
# at 87510238
#150730 13:30:41 server id 64523 end_log_pos 87499143 Query thread_id=439842 exec_time=0 error_code=0
SET TIMESTAMP=1438288241/*!*/;
<STATEMENT>
/*!*/;
# at 87512656
#150730 13:30:41 server id 64523 end_log_pos 87499143 Query thread_id=439842 exec_time=0 error_code=0
SET TIMESTAMP=1438288241/*!*/;
<STATEMENT>
/*!*/;
# at 87515074
#150730 13:30:41 server id 64523 end_log_pos 87499170 Xid = 301895923
COMMIT/*!*/;
# at 87515101
#150730 13:30:41 server id 64523 end_log_pos 87499170 Xid = 301895923
COMMIT/*!*/;
# at 87515128
#150730 13:30:41 server id 64523 end_log_pos 87499241 Query thread_id=439840 exec_time=0 error_code=0
SET TIMESTAMP=1438288241/*!*/;
B...

[Shahriyar Rzayev (rzayev-sehriyar)]

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