Patch approved. New test runs successfully with fix, and fails with
assertion without.
--
Øystein
Sven Sandberg wrote:
> #At file:///home/sven/bzr/b40482-incident_log_event_assertion/5.1-rpl/
>
> 2692 Sven Sandberg 2008-11-06
> BUG#40482: server/mysqlbinlog crashes when reading invalid Incident_log_event
> Problem: When an Incident_log_event contains a bad incident number on disk,
> the server crashes with an assertion.
> Fix: Don't validate input with assertions. Use errors.
> added:
> mysql-test/include/cleanup_fake_relay_log.inc
> mysql-test/include/setup_fake_relay_log.inc
> mysql-test/std_data/bug40482-bin.000001
> mysql-test/suite/rpl/r/rpl_binlog_corruption.result
> mysql-test/suite/rpl/t/rpl_binlog_corruption-master.opt
> mysql-test/suite/rpl/t/rpl_binlog_corruption.test
> modified:
> sql/log_event.cc
> sql/log_event.h
> sql/rpl_constants.h
>
> per-file messages:
> mysql-test/include/cleanup_fake_relay_log.inc
> Added auxiliary file to restore things that setup_fake_relay_log.inc did.
> mysql-test/include/setup_fake_relay_log.inc
> Added auxiliary file to setup replication from an existing relay log.
> mysql-test/std_data/bug40482-bin.000001
> Binlog file for rpl.rpl_binlog_corruption
> mysql-test/suite/rpl/t/rpl_binlog_corruption.test
> New test file.
> sql/log_event.cc
> Check that the incident number is correct at the time the event is constructed.
> Do not assert it at the time it is printed.
> sql/log_event.h
> Incident_log_event::is_valid() should verify that the incident number is valid.
> sql/rpl_constants.h
> Incident numbers should be hard-coded, since they may appear in files.
> === added file 'mysql-test/include/cleanup_fake_relay_log.inc'
> --- a/mysql-test/include/cleanup_fake_relay_log.inc 1970-01-01 00:00:00 +0000
> +++ b/mysql-test/include/cleanup_fake_relay_log.inc 2008-11-06 14:02:05 +0000
> @@ -0,0 +1,16 @@
> +# ==== Purpose ====
> +#
> +# Clean up files create by setup_fake_relay_log.inc.
> +#
> +# ==== Usage ====
> +#
> +# See setup_fake_relay_log.inc
> +
> +--echo Cleaning up after setup_fake_relay_log.inc
> +
> +# Remove files.
> +remove_file $_fake_relay_log;
> +remove_file $_fake_relay_index;
> +--disable_query_log
> +eval SET @@global.relay_log_purge= $_fake_relay_log_purge;
> +--enable_query_log
>
> === added file 'mysql-test/include/setup_fake_relay_log.inc'
> --- a/mysql-test/include/setup_fake_relay_log.inc 1970-01-01 00:00:00 +0000
> +++ b/mysql-test/include/setup_fake_relay_log.inc 2008-11-06 14:02:05 +0000
> @@ -0,0 +1,78 @@
> +# ==== Purpose ====
> +#
> +# Setup replication from an existing relay log in the current
> +# connection.
> +#
> +# ==== Usage ====
> +#
> +# Make sure the slave is not running and issue:
> +#
> +# let $fake_relay_log= /path/to/fake-relay-log-file.000001
> +# source include/setup_fake_relay_log.inc;
> +# START SLAVE SQL_THREAD; # setup_fake_relay_log doesn't start slave
> +# ...
> +# source include/cleanup_fake_relay_log.inc
> +#
> +# You must run the server with --relay-log=FILE. You probably want to
> +# run with --replicate-same-server-id too.
> +#
> +# ==== Implementation ====
> +#
> +# First makes a sanity check, ensuring that the slave threads are not
> +# running. Then copies the $fake_relay_log to RELAY_BIN-fake.000001,
> +# where RELAY_BIN is the basename of the relay log, and updates
> +# RELAY_BIN.index. Finally issues CHANGE MASTER so that it uses the
> +# given files.
> +#
> +# ==== Side effects ====
> +#
> +# Creates a binlog file and a binlog index file, and sets
> +# @@global.relay_log_purge=1. All this is restored when you call
> +# cleanup_fake_relay_log.inc.
> +#
> +# Enables the query log.
> +
> +
> +--disable_query_log
> +
> +# Print message.
> +let $_fake_relay_log_printable= `SELECT REPLACE('$fake_relay_log',
> '$MYSQL_TEST_DIR', 'MYSQL_TEST_DIR')`;
> +--echo Setting up fake replication from $_fake_relay_log_printable
> +
> +# Sanity check.
> +let $_sql_running= query_get_value(SHOW SLAVE STATUS, Slave_SQL_Running, 1);
> +let $_io_running= query_get_value(SHOW SLAVE STATUS, Slave_IO_Running, 1);
> +if (`SELECT "$_sql_running" = "Yes" OR "$_io_running" = "Yes"`) {
> + --echo Error: Slave was running when test case sourced
> + --echo include/setup_fake_replication.inc
> + --echo Slave_IO_Running = $_io_running; Slave_SQL_Running = $_sql_running
> + --echo Printing some debug info:
> + SHOW SLAVE STATUS;
> + SHOW MASTER STATUS;
> + SHOW BINLOG EVENTS;
> + SHOW PROCESSLIST;
> +}
> +
> +# Read server variables.
> +let $MYSQLD_DATADIR= `SELECT @@datadir`;
> +let $_fake_filename= query_get_value(SHOW VARIABLES LIKE 'relay_log', Value, 1);
> +if (`SELECT '$_fake_filename' = ''`) {
> + --echo Badly written test case: relay_log variable is empty. Please use the
> + --echo server option --relay-log=FILE.
> +}
> +let $_fake_relay_log= $MYSQLD_DATADIR/$_fake_filename-fake.000001;
> +let $_fake_relay_index= $MYSQLD_DATADIR/$_fake_filename.index;
> +# Need to restore relay_log_purge in cleanup_fake_relay_log.inc, since
> +# CHANGE MASTER modifies it (see the manual for CHANGE MASTER).
> +let $_fake_relay_log_purge= `SELECT @@global.relay_log_purge`;
> +
> +# Create relay log file.
> +copy_file $fake_relay_log $_fake_relay_log;
> +
> +# Create relay log index.
> +eval SELECT '$_fake_relay_log' INTO OUTFILE '$_fake_relay_index';
> +
> +# Setup replication from existing relay log.
> +eval CHANGE MASTER TO MASTER_HOST='dummy.localdomain',
> RELAY_LOG_FILE='$_fake_relay_log', RELAY_LOG_POS=4;
> +
> +--enable_query_log
>
> === added file 'mysql-test/std_data/bug40482-bin.000001'
> Binary files a/mysql-test/std_data/bug40482-bin.000001 1970-01-01 00:00:00 +0000 and
> b/mysql-test/std_data/bug40482-bin.000001 2008-11-06 14:02:05 +0000 differ
>
> === added file 'mysql-test/suite/rpl/r/rpl_binlog_corruption.result'
> --- a/mysql-test/suite/rpl/r/rpl_binlog_corruption.result 1970-01-01 00:00:00 +0000
> +++ b/mysql-test/suite/rpl/r/rpl_binlog_corruption.result 2008-11-06 14:02:05 +0000
> @@ -0,0 +1,8 @@
> +call mtr.add_suppression('Found invalid event in binary log');
> +==== Initialize ====
> +Setting up fake replication from MYSQL_TEST_DIR/std_data/bug40482-bin.000001
> +==== Test ====
> +START SLAVE SQL_THREAD;
> +Last_SQL_Error = 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. If you want to check the master's binary log or slave's relay log, you
> will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave.
> +==== Clean up ====
> +Cleaning up after setup_fake_relay_log.inc
>
> === added file 'mysql-test/suite/rpl/t/rpl_binlog_corruption-master.opt'
> --- a/mysql-test/suite/rpl/t/rpl_binlog_corruption-master.opt 1970-01-01 00:00:00
> +0000
> +++ b/mysql-test/suite/rpl/t/rpl_binlog_corruption-master.opt 2008-11-06 14:02:05
> +0000
> @@ -0,0 +1 @@
> +--replicate-same-server-id --relay-log=slave-relay-bin
>
> === added file 'mysql-test/suite/rpl/t/rpl_binlog_corruption.test'
> --- a/mysql-test/suite/rpl/t/rpl_binlog_corruption.test 1970-01-01 00:00:00 +0000
> +++ b/mysql-test/suite/rpl/t/rpl_binlog_corruption.test 2008-11-06 14:02:05 +0000
> @@ -0,0 +1,42 @@
> +# ==== Purpose ====
> +#
> +# Verify that the slave stops gracefully when reading a relay log with
> +# corrupted data.
> +#
> +# ==== Implementation ====
> +#
> +# Setup "fake replication" where the slave only starts the SQL thread,
> +# not the IO thread, and reads from an existing relay log that has
> +# been prepared so that it contains the error. This requires some
> +# extra server options: see the -master.opt file.
> +#
> +# ==== Related bugs ====
> +#
> +# BUG#31793: log event corruption causes crash
> +# BUG#40482: server/mysqlbinlog crashes when reading invalid Incident_log_event
> +
> +source include/have_log_bin.inc;
> +# BUG#40482 only manifested itself in debug-compiled binaries.
> +source include/have_debug.inc;
> +
> +call mtr.add_suppression('Found invalid event in binary log');
> +
> +
> +#
> +# BUG#40482: server/mysqlbinlog crashes when reading invalid Incident_log_event
> +#
> +# The relay log contains an Incident_log_event with a non-existing
> +# incident number.
> +
> +--echo ==== Initialize ====
> +let $fake_relay_log= $MYSQL_TEST_DIR/std_data/bug40482-bin.000001;
> +source include/setup_fake_relay_log.inc;
> +
> +--echo ==== Test ====
> +START SLAVE SQL_THREAD;
> +source include/wait_for_slave_sql_error.inc;
> +let $error= query_get_value(SHOW SLAVE STATUS, Last_SQL_Error, 1);
> +--echo Last_SQL_Error = $error
> +
> +--echo ==== Clean up ====
> +source include/cleanup_fake_relay_log.inc;
>
> === modified file 'sql/log_event.cc'
> --- a/sql/log_event.cc 2008-10-23 19:27:09 +0000
> +++ b/sql/log_event.cc 2008-11-06 14:02:05 +0000
> @@ -9035,7 +9035,17 @@ Incident_log_event::Incident_log_event(c
> DBUG_PRINT("info",("event_len: %u; common_header_len: %d; post_header_len: %d",
> event_len, common_header_len, post_header_len));
>
> - m_incident= static_cast<Incident>(uint2korr(buf + common_header_len));
> + int incident_number= uint2korr(buf + common_header_len);
> + if (incident_number >= (int)INCIDENT_COUNT ||
> + incident_number <= (int)INCIDENT_NONE)
> + {
> + // If the incident is not recognized, this binlog event is
> + // invalid. If we set incident_number to INCIDENT_NONE, the
> + // invalidity will be detected by is_valid().
> + incident_number= INCIDENT_NONE;
> + DBUG_VOID_RETURN;
> + }
> + m_incident= static_cast<Incident>(incident_number);
> char const *ptr= buf + common_header_len + post_header_len;
> char const *const str_end= buf + event_len;
> uint8 len= 0; // Assignment to keep compiler happy
> @@ -9063,9 +9073,6 @@ Incident_log_event::description() const
>
> DBUG_PRINT("info", ("m_incident: %d", m_incident));
>
> - DBUG_ASSERT(0 <= m_incident);
> - DBUG_ASSERT((size_t) m_incident <= sizeof(description)/sizeof(*description));
> -
> return description[m_incident];
> }
>
>
> === modified file 'sql/log_event.h'
> --- a/sql/log_event.h 2008-09-29 05:36:42 +0000
> +++ b/sql/log_event.h 2008-11-06 14:02:05 +0000
> @@ -3886,7 +3886,10 @@ public:
>
> virtual Log_event_type get_type_code() { return INCIDENT_EVENT; }
>
> - virtual bool is_valid() const { return 1; }
> + virtual bool is_valid() const
> + {
> + return m_incident > INCIDENT_NONE && m_incident < INCIDENT_COUNT;
> + }
> virtual int get_data_size() {
> return INCIDENT_HEADER_LEN + 1 + m_message.length;
> }
>
> === modified file 'sql/rpl_constants.h'
> --- a/sql/rpl_constants.h 2007-03-29 18:31:09 +0000
> +++ b/sql/rpl_constants.h 2008-11-06 14:02:05 +0000
> @@ -6,10 +6,10 @@
> */
> enum Incident {
> /** No incident */
> - INCIDENT_NONE,
> + INCIDENT_NONE = 0,
>
> /** There are possibly lost events in the replication stream */
> - INCIDENT_LOST_EVENTS,
> + INCIDENT_LOST_EVENTS = 1,
>
> /** Shall be last event of the enumeration */
> INCIDENT_COUNT
>
>
