List:Commits« Previous MessageNext Message »
From:Sven Sandberg Date:November 13 2008 5:50pm
Subject:bzr commit into mysql-5.1 branch (sven:2706) Bug#40482
View as plain text  
#At file:///home/sven/bzr/b40482-incident_log_event_assertion/5.1-bugteam/

 2706 Sven Sandberg	2008-11-13
      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-13 17:50:30 +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-13 17:50:30 +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-13 17:50:30 +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-13 17:50:30 +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-13 17:50:30 +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-13 17:50:30 +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-20 18:50:08 +0000
+++ b/sql/log_event.cc	2008-11-13 17:50:30 +0000
@@ -9057,7 +9057,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 >= INCIDENT_COUNT ||
+      incident_number <= 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
@@ -9085,9 +9095,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-08-27 18:52:44 +0000
+++ b/sql/log_event.h	2008-11-13 17:50:30 +0000
@@ -3870,7 +3870,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-13 17:50:30 +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

Thread
bzr commit into mysql-5.1 branch (sven:2706) Bug#40482Sven Sandberg13 Nov