Bug #57225 Slave SQL thread wrongly reports relay log corruption on STOP SLAVE
Submitted: 4 Oct 2010 18:15 Modified: 17 Oct 2011 12:20
Reporter: Elena Stepanova Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.5, 5.6 OS:Any
Assigned to: Daogang Qu CPU Architecture:Any

[4 Oct 2010 18:15] Elena Stepanova
Description:
If slave is stopped while SQL thread is executing a long event involving non-transactional changes, and the one-minute waiting time is not enough to finish the event, SQL thread upon exit reports two errors in the error log file: 

first, 1593 ER_SLAVE_FATAL_ERROR with text 
'The slave SQL is stopped, leaving the current group of events unfinished with a non-transaction table changed....' 

which is expected, but then also 

1594 ER_SLAVE_RELAY_LOG_READ_FAILURE with text 
'Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code.'

which is not true -- relay log file is not corrupted, and is successfully executed upon later slave start (provided that appropriate measures against duplicate key problem have been taken).

The latter error is also given by SHOW SLAVE STATUS after slave stop.

How to repeat:
--source include/master-slave.inc
--source include/have_binlog_format_row.inc

--perl

open(O_FILE, ">> $ENV{MYSQLTEST_VARDIR}/tb.txt") or die("can't open \"$ENV{MYSQLTEST_VARDIR}/tb.txt\": $!");

for my $count ( 1..100000 )
{
        my $num = int(rand(9000000000))+1000000000;
        my $str = 'Test name';
        my $year = 1900 + ((localtime)[5]) - int(rand(100));
        print O_FILE ("$num\t$str\t$year\n");
}
close(O_FILE);

EOF

CREATE TABLE t_celosia_ddl_no_partitions (id INT NOT NULL AUTO_INCREMENT PRIMARY KEY,
                user_num BIGINT UNSIGNED,
                name TINYTEXT NOT NULL,
                year YEAR,
                modified TIME DEFAULT NULL,
                KEY user_num (user_num),
                INDEX name (name(255))) ENGINE = MyISAM;

CREATE TABLE t_celosia_log (id INT NOT NULL AUTO_INCREMENT PRIMARY KEY,
                table_name VARCHAR(32),
                update_time DATETIME NOT NULL,
                operation VARCHAR(32),
                connection INT,
                KEY update_time (update_time)) ENGINE = MyISAM;

CREATE TRIGGER ins_log_t_celosia_ddl_no_partitions AFTER INSERT ON t_celosia_ddl_no_partitions FOR EACH ROW INSERT INTO t_celosia_log VALUES
( NULL, 't_celosia_ddl_no_partitions', NOW(), CONCAT('INSERT ' ,new.id), CONNECTION_ID() );

eval LOAD DATA LOCAL INFILE '$MYSQLTEST_VARDIR/tb.txt'
INTO TABLE t_celosia_ddl_no_partitions (user_num, name, year);

--connection slave
let $show_statement= SHOW PROCESSLIST;
let $field= State;
let $condition= = 'Reading event from the relay log';
--source include/wait_show_condition.inc
--echo # Stopping slave...
STOP SLAVE;
--vertical_results
SHOW SLAVE STATUS;

# End of test case
[4 Oct 2010 21:48] Elena Stepanova
Probably the description should have said 'a long group of events' rather than 'a long event'..
[4 Oct 2010 21:49] Elena Stepanova
Cannot verify on 5.1 due to bug#57230.
[15 Dec 2010 22:34] Elena Stepanova
# Another test case, derived from current system scenarios

# Recommended to run as --nowarnings MTR flag

--source include/master-slave.inc
--source include/have_innodb.inc
--source include/have_binlog_format_mixed_or_statement.inc

--connection master

DROP DATABASE IF EXISTS slave_stop;
CREATE DATABASE slave_stop;
USE slave_stop;
CREATE TABLE slave_stop.t_data ( num INT ) ENGINE = InnoDB;

BEGIN;
REPLACE t_data VALUES (0);
CREATE TEMPORARY TABLE operations ( op VARCHAR(16) ) ENGINE = InnoDB;
SET @start = NOW();
# Presumably, if master executes the transaction longer than 70 seconds,
# slave will not be any faster, and hence STOP SLAVE won't be able
# to wait till the transaction is finished
--disable_query_log
while(`SELECT TIME_TO_SEC(TIMEDIFF(NOW(),@start)) < 70` )
{
        INSERT INTO t_data VALUES(1);
}
--enable_query_log
DROP TEMPORARY TABLE operations;
COMMIT;

--connection slave

let $show_statement= SHOW PROCESSLIST;
let $field= Info;
let $condition= LIKE 'INSERT%';
--source include/wait_show_condition.inc

STOP SLAVE;
--vertical_results
SHOW SLAVE STATUS;

# Cleanup
DROP DATABASE slave_stop;

--connection master
DROP DATABASE slave_stop;

--exit