Hi Libing,
Great work.
See some comments in-line.
Cheers.
Li-Bing.Song@stripped wrote:
> #At file:///home/anders/work/bzrwork/bug42914/mysql-5.1-bugteam/ based on
> revid:davi.arnaut@stripped
>
> 3069 Li-Bing.Song@stripped 2009-08-25
> Bug #42914 Log event that larger than max_allowed_packet results in stop of
> slave I/O thread, But there is no Last_IO_Error reported.
>
> On master, if replicated event larger than max_allowed_packet,
> master sends an error message ER_MASTER_FATAL_ERROR_READING_BINLOG to slave.
> This message results in stop of slave I/O thread.
> On slave, slave I/O thread will stop when receiveing a packet larger than
> max_allowed_packet.
> In both the cases, there is no Last_IO_Error reported.
>
> This patch adds code to report Last_IO_Error befor slave I/O thread stopping.
> There is another case which results in stop of slave I/O thread, but dose not
> report a Last_IO_Error.
> This patch fixs it too.
>
Find below a suggestion.
On the master, if a binary log event is larger than max_allowed_packet,
the error message ER_MASTER_FATAL_ERROR_READING_BINLOG is
sent to a slave when it requests a dump from the master, thus leading
the I/O Thread to stop.
On a slave, the I/O thread stops when receiving a packet larger than
max_allowed_packet.
In both cases, however, there was no Last_IO_Error reported.
This patch adds code to report the Last_IO_Error before stopping the
I/O Thread and also reports the case the out memory pops up while
handling packets from the master.
> added:
> mysql-test/suite/rpl/r/rpl_packet_row.result
> mysql-test/suite/rpl/t/rpl_packet_row.cnf
> mysql-test/suite/rpl/t/rpl_packet_row.test
> modified:
> mysql-test/suite/rpl/r/rpl_packet.result
> mysql-test/suite/rpl/t/rpl_packet.test
>
Why don't you split the tests? One that checks errors on the slave side
and other on the master?
> sql/slave.cc
> === modified file 'mysql-test/suite/rpl/r/rpl_packet.result'
> --- a/mysql-test/suite/rpl/r/rpl_packet.result 2009-01-23 12:22:05 +0000
> +++ b/mysql-test/suite/rpl/r/rpl_packet.result 2009-08-25 14:17:34 +0000
> @@ -32,6 +32,9 @@ include/start_slave.inc
> CREATE TABLE `t1` (`f1` LONGTEXT) ENGINE=MyISAM;
> INSERT INTO `t1`(`f1`) VALUES
> ('aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!
aa!
>
> aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!
aa!
> aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!
> aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa2048');
> Slave_IO_Running = No (expect No)
> +SELECT "Got a packet bigger than 'max_allowed_packet' bytes" AS Last_IO_Error;
> +Last_IO_Error
> +Got a packet bigger than 'max_allowed_packet' bytes
> ==== clean up ====
> DROP TABLE t1;
> SET @@global.max_allowed_packet= 1024;
>
> === added file 'mysql-test/suite/rpl/r/rpl_packet_row.result'
> --- a/mysql-test/suite/rpl/r/rpl_packet_row.result 1970-01-01 00:00:00 +0000
> +++ b/mysql-test/suite/rpl/r/rpl_packet_row.result 2009-08-25 14:17:34 +0000
> @@ -0,0 +1,19 @@
> +stop slave;
> +drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
> +reset master;
> +reset slave;
> +drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
> +start slave;
> +DROP TABLE IF EXISTS t1;
> +CREATE TABLE t1 (f1 int PRIMARY KEY, f2 LONGTEXT, f3 LONGTEXT) ENGINE=MyISAM;
> +SELECT @@global.max_allowed_packet;
> +@@global.max_allowed_packet
> +2048
> +INSERT INTO t1(f1, f2, f3) VALUES(1, REPEAT('a', @@global.max_allowed_packet),
> REPEAT('b', @@global.max_allowed_packet));
> +Slave_IO_Running = No (expect No)
> +SELECT "Got fatal error 1236: 'error reading log entry' from master when reading
> data from binary log" AS Last_IO_Error;
> +Last_IO_Error
> +Got fatal error 1236: 'error reading log entry' from master when reading data from
> binary log
> +==== clean up ====
> +DROP TABLE t1;
> +DROP TABLE t1;
>
> === modified file 'mysql-test/suite/rpl/t/rpl_packet.test'
> --- a/mysql-test/suite/rpl/t/rpl_packet.test 2009-01-23 12:22:05 +0000
> +++ b/mysql-test/suite/rpl/t/rpl_packet.test 2009-08-25 14:17:34 +0000
> @@ -86,6 +86,12 @@ connection slave;
> --source include/wait_for_slave_io_to_stop.inc
> let $slave_io_running= query_get_value(SHOW SLAVE STATUS, Slave_IO_Running, 1);
> --echo Slave_IO_Running = $slave_io_running (expect No)
> +#
> +# Bug42914: The slave I/O thread must stop after trying to read the above
> +# event, but there is no Last_IO_Error reported.
> +#
> +let $last_io_error= query_get_value(SHOW SLAVE STATUS, Last_IO_Error, 1);
> +eval SELECT "$last_io_error" AS Last_IO_Error;
>
> --echo ==== clean up ====
> connection master;
>
> === added file 'mysql-test/suite/rpl/t/rpl_packet_row.cnf'
> --- a/mysql-test/suite/rpl/t/rpl_packet_row.cnf 1970-01-01 00:00:00 +0000
> +++ b/mysql-test/suite/rpl/t/rpl_packet_row.cnf 2009-08-25 14:17:34 +0000
> @@ -0,0 +1,5 @@
> +!include ../my.cnf
> +[mysqld.1]
> +max-allowed-packet=2048
> +[mysqld.2]
> +max-allowed-packet=2048
>
> === added file 'mysql-test/suite/rpl/t/rpl_packet_row.test'
> --- a/mysql-test/suite/rpl/t/rpl_packet_row.test 1970-01-01 00:00:00 +0000
> +++ b/mysql-test/suite/rpl/t/rpl_packet_row.test 2009-08-25 14:17:34 +0000
> @@ -0,0 +1,33 @@
> +#
>
> +# Bug#42914: On master, if replicated event larger than max_allowed_packet,
> +# master sends an error message ER_MASTER_FATAL_ERROR_READING_BINLOG to slave.
> +# This message results in stop of slave I/O thread. But There is no
> +# Last_IO_Error report.
> +#
>
On the master, if a binary log event is larger than max_allowed_packet,
the error message ER_MASTER_FATAL_ERROR_READING_BINLOG is
sent to a slave when it requests a dump from the master, thus leading
the I/O Thread to stop. However, there is no Last_IO_Error report.
> +
> +source include/master-slave.inc;
> +source include/have_binlog_format_row.inc;
> +disable_warnings;
> +DROP TABLE IF EXISTS t1;
> +enable_warnings;
> +CREATE TABLE t1 (f1 int PRIMARY KEY, f2 LONGTEXT, f3 LONGTEXT) ENGINE=MyISAM;
> +
> +SELECT @@global.max_allowed_packet;
> +INSERT INTO t1(f1, f2, f3) VALUES(1, REPEAT('a', @@global.max_allowed_packet),
> REPEAT('b', @@global.max_allowed_packet));
> +
> +connection slave;
> +# The slave I/O thread must stop after receiving
> +# ER_MASTER_FATAL_ERROR_READING_BINLOG error message from master.
> +--source include/wait_for_slave_io_to_stop.inc
> +let $slave_io_running= query_get_value(SHOW SLAVE STATUS, Slave_IO_Running, 1);
> +--echo Slave_IO_Running = $slave_io_running (expect No)
> +let $last_io_error= query_get_value(SHOW SLAVE STATUS, Last_IO_Error, 1);
> +eval SELECT "$last_io_error" AS Last_IO_Error;
> +
> +--echo ==== clean up ====
> +connection master;
> +DROP TABLE t1;
> +# slave is stopped
> +connection slave;
> +DROP TABLE t1;
> +# End of tests
>
> === modified file 'sql/slave.cc'
> --- a/sql/slave.cc 2009-08-13 20:45:01 +0000
> +++ b/sql/slave.cc 2009-08-25 14:17:34 +0000
> @@ -2681,15 +2681,22 @@ Log entry on master is longer than max_a
> slave. If the entry is correct, restart the server with a higher value of \
> max_allowed_packet",
> thd->variables.max_allowed_packet);
> + mi->report(ERROR_LEVEL, ER_NET_PACKET_TOO_LARGE,
> + ER(ER_NET_PACKET_TOO_LARGE));
> goto err;
> case ER_MASTER_FATAL_ERROR_READING_BINLOG:
> - sql_print_error(ER(mysql_error_number), mysql_error_number,
> - mysql_error(mysql));
> + mi->report(ERROR_LEVEL, ER_MASTER_FATAL_ERROR_READING_BINLOG,
> + ER(ER_MASTER_FATAL_ERROR_READING_BINLOG),
> + mysql_error_number, mysql_error(mysql));
> goto err;
> case EE_OUTOFMEMORY:
> case ER_OUTOFMEMORY:
> sql_print_error("\
> Stopping slave I/O thread due to out-of-memory error from master");
> +
> + mi->report(ERROR_LEVEL, ER_OUTOFMEMORY,
> + ER(ER_OUTOFMEMORY), "\
> +Stopping slave I/O thread due to out-of-memory error from master");
> goto err;
> }
> if (try_to_reconnect(thd, mysql, mi, &retry_count, suppress_warnings,
>
Why did you keep the old sql_print_error(s) in some cases?
>
> ------------------------------------------------------------------------
>
>
>
