MySQL Bugs: #56007: Blackhole slave replication: 2nd slave stops with an error for UPDATE statement

Bug #56007	Blackhole slave replication: 2nd slave stops with an error for UPDATE statement
Submitted:	16 Aug 2010 10:54
Reporter:	Serge Kozlov	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S2 (Serious)
Version:	5.6.99-m5	OS:	Any
Assigned to:	Assigned Account	CPU Architecture:	Any
Tags:	blackhole slave, HA_ERR_END_OF_FILE, nuts, row

Description:
There is the replication chain:

master -> slave -> slave2.

1st slave started with --default-storage=blackhole, master and slave2 use MyISAM or InnoDB as default engine.

Some UPDATE statements on master successfully go through slave but raise error 1032 (HA_ERR_END_OF_FILE for UPDATE) on slave2. The log file for slave2 is below:

100816 13:43:39 [Note] Plugin 'FEDERATED' is disabled.
100816 13:43:39 [Note] Plugin 'ndbcluster' is disabled.
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use InnoDB's own implementation
InnoDB: Compressed tables use zlib 1.2.3
100816 13:43:39  InnoDB: highest supported file format is Barracuda.
100816 13:43:40 InnoDB 1.2.0 started; log sequence number 1595675
100816 13:43:40 [Warning] /home/ksm/oracle/repo/build-next-mr/sql/.libs/lt-mysqld: unknown variable 'loose-debug-sync-timeout=300'
100816 13:43:40 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 21d70734-a923-11df-bc71-0800272f46ab.
100816 13:43:40 [Note] Event Scheduler: Loaded 0 events
100816 13:43:40 [Note] /home/ksm/oracle/repo/build-next-mr/sql/.libs/lt-mysqld: ready for connections.
Version: '5.6.99-m5-log'  socket: '/home/ksm/oracle/repo/build-next-mr/mysql-test/var/tmp/mysqld.3.sock'  port: 13002  Source distribution
100816 13:43:41 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=mysqld-relay-bin' to avoid this problem.
100816 13:43:41 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='13001', master_log_file='slave-bin.000001', master_log_pos='4'.
100816 13:43:41 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:13001',replication started in log 'slave-bin.000001' at position 4
100816 13:43:41 [Note] Slave SQL thread initialized, starting replication in log 'slave-bin.000001' at position 4, relay log './mysqld-relay-bin.000001' position: 4
100816 13:43:42 [Note] Slave: received end packet from server, apparent master shutdown:
100816 13:43:42 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'slave-bin.000001' at postion 2215
100816 13:43:42 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:13001' - retry-time: 60  retries: 86400, Error_code: 2003
100816 13:43:43 [Note] /home/ksm/oracle/repo/build-next-mr/sql/.libs/lt-mysqld: Normal shutdown

100816 13:43:43 [Note] Slave I/O thread killed during or after a reconnect done to recover from failed read
100816 13:43:43 [Note] Slave I/O thread exiting, read up to log 'slave-bin.000001', position 2215
100816 13:43:43 [Note] Event Scheduler: Purging the queue. 0 events
100816 13:43:43 [Note] Error reading relay log event: slave SQL thread was killed
100816 13:43:43  InnoDB: Starting shutdown...
100816 13:43:45  InnoDB: Shutdown completed; log sequence number 1595675
100816 13:43:45 [Note] /home/ksm/oracle/repo/build-next-mr/sql/.libs/lt-mysqld: Shutdown complete

How to repeat:
Use attached test case or dump file.

MTR test case and dump file

Attachment: bug56007.tgz (application/x-gzip, text), 1.55 KiB.

Find in what follows a simpler test case to reproduce the problem:

--source include/have_binlog_format_row.inc
--source include/master-slave.inc
--disable_warnings
--sync_slave_with_master
--connection slave
let $bhs_binlog_file= query_get_value(SHOW MASTER STATUS, File, 1);

--connect(slave3,127.0.0.1,root,,test,$SLAVE_MYPORT1,)
--connection slave3
STOP SLAVE;
RESET SLAVE;
--replace_result $SLAVE_MYPORT SLAVE_MYPORT $bhs_binlog_file BHS_BINLOG_FILE
--eval CHANGE MASTER TO master_host='127.0.0.1', master_port=$SLAVE_MYPORT, master_user='root', master_log_file = '$bhs_binlog_file';
START SLAVE;

--connection master
CREATE TABLE t1 (c_01 INT UNSIGNED, c_02 TEXT);
INSERT INTO t1 VALUES (1, 'k');
UPDATE t1 SET c_02 = 'G', c_01= 3 WHERE c_01 = 1;

--sync_slave_with_master
--connection slave
--save_master_pos
--connection slave3
--sync_with_master

exit;

To reproduce the problem with the test case provided at [29 Sep 23:49] Alfranio Correia, you still need both 

  rpl_row_bhs_bug56007-slave.opt and rpl_row_bhs_bug56007.cnf

provided at [16 Aug 12:59] Serge Kozlov.

The configuration files build the following structure:

  master (myisam) --> slave (blackhole, log-slave-updates) --> slave(myisam)

After running the test case, the second slave stops because the row to be
updated is not found. This happens because there is the following entry
in the first slave's binary log

### UPDATE test.t1
### WHERE
###   @1=1
###   @2='G'
### SET
###   @1=3
###   @2='G'

While the master which has the correct entry, there is

### UPDATE test.t1
### WHERE
###   @1=1
###   @2='K'
### SET
###   @1=3
###   @2='G'

Clearly, the second slave fails because there is no row (1,'G').

This bug fixed in 5.7.13