List:Commits« Previous MessageNext Message »
From:Luis Soares Date:July 14 2011 12:49pm
Subject:bzr push into mysql-5.1 branch (luis.soares:3570 to 3571) Bug#11753004
View as plain text  
 3571 Luis Soares	2011-07-14
      BUG#11753004: 44360: REPLICATION FAILED
                        
      The server crashes if it processes table map events that are
      corrupted, especially if they map different tables to the same
      identifier. This could happen, for instance, due to BUG 56226.
                        
      We fix this by checking whether the table map has already been
      mapped before actually applying the event. If it has been mapped
      with different settings an error is raised and the slave SQL
      thread stops. If it has been mapped with same settings the event
      is skipped. If the table is set to be ignored by the filtering
      rules, there is no change in behavior: the event is skipped and
      ids are not checked.
     @ mysql-test/suite/rpl/t/rpl_row_corruption.test
        Added a simple test case that checks both cases:
        - multiple table maps with the same identifier
        - multiple table maps with the same identifier, but only one
          is processed (the others are filtered out)

    added:
      mysql-test/suite/rpl/r/rpl_row_corruption.result
      mysql-test/suite/rpl/t/rpl_row_corruption-slave.opt
      mysql-test/suite/rpl/t/rpl_row_corruption.test
    modified:
      sql/log_event.cc
 3570 Luis Soares	2011-07-12 [merge]
      BUG#12695969
      
      Manually merged from mysql-5.0 into mysql-5.1.
      
      conflicts
      =========
      
      include/Makefile.am

    modified:
      include/Makefile.am
=== added file 'mysql-test/suite/rpl/r/rpl_row_corruption.result'
--- a/mysql-test/suite/rpl/r/rpl_row_corruption.result	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/r/rpl_row_corruption.result	2011-07-14 11:15:24 +0000
@@ -0,0 +1,49 @@
+include/master-slave.inc
+[connection master]
+CREATE TABLE t1_11753004 (c1 INT);
+CREATE TABLE t2_11753004 (c1 INT);
+INSERT INTO t1_11753004 VALUES (1);
+INSERT INTO t2_11753004 VALUES (2);
+call mtr.add_suppression(".*Found table map event mapping table id 0 which was already mapped but with different settings.*");
+include/stop_slave.inc
+SET @save_debug= @@global.debug;
+SET GLOBAL debug="+d,inject_tblmap_same_id_maps_diff_table";
+include/start_slave.inc
+UPDATE t1_11753004, t2_11753004 SET t1_11753004.c1=3, t2_11753004.c1=4 WHERE t1_11753004.c1=1 OR t2_11753004.c1=2;
+include/wait_for_slave_sql_error.inc [errno=1593 ]
+include/stop_slave.inc
+SET GLOBAL debug="-d,inject_tblmap_same_id_maps_diff_table";
+include/start_slave.inc
+include/rpl_reset.inc
+DROP TABLE t1_11753004, t2_11753004;
+include/stop_slave.inc
+SET GLOBAL debug="+d,inject_tblmap_same_id_maps_diff_table";
+include/start_slave.inc
+include/rpl_reset.inc
+CREATE TABLE t1_11753004 (c1 INT);
+CREATE TABLE t2_11753004_ign (c1 INT);
+INSERT INTO t1_11753004 VALUES (1);
+INSERT INTO t2_11753004_ign VALUES (2);
+UPDATE t1_11753004, t2_11753004_ign SET t1_11753004.c1=3, t2_11753004_ign.c1=4 WHERE t1_11753004.c1=1 OR t2_11753004_ign.c1=2;
+CREATE TABLE t1 (c1 INT);
+CREATE TABLE t2 (c1 INT);
+INSERT INTO t1 VALUES (1);
+INSERT INTO t2 VALUES (1);
+BINLOG '
+SOgWTg8BAAAAbgAAAHIAAAAAAAQANS42LjMtbTUtZGVidWctbG9nAAAAAAAAAAAAAAAAAAAAAAAA
+AAAAAAAAAAAAAAAAAABI6BZOEzgNAAgAEgAEBAQEEgAAVgAEGggAAAAICAgCAAAAAAVAYI8=
+'/*!*/;
+SET GLOBAL debug="+d,inject_tblmap_same_id_maps_diff_table";
+BINLOG '
+SOgWThMBAAAAKQAAAAYDAAAAAEIAAAAAAAEABHRlc3QAAnQxAAEDAAE=
+SOgWThMBAAAAKQAAAC8DAAAAAEMAAAAAAAEABHRlc3QAAnQyAAEDAAE=
+SOgWThgBAAAAKAAAAFcDAAAAAEIAAAAAAAAAAf///gEAAAD+AwAAAA==
+SOgWThgBAAAAKAAAAH8DAAAAAEMAAAAAAAEAAf///gEAAAD+BAAAAA==
+'/*!*/;
+ERROR HY000: Fatal error: Found table map event mapping table id 0 which was already mapped but with different settings.
+DROP TABLE t1,t2;
+SET GLOBAL debug="-d,inject_tblmap_same_id_maps_diff_table";
+DROP TABLE t1_11753004;
+DROP TABLE t2_11753004_ign;
+SET GLOBAL debug= @save_debug;
+include/rpl_end.inc

=== added file 'mysql-test/suite/rpl/t/rpl_row_corruption-slave.opt'
--- a/mysql-test/suite/rpl/t/rpl_row_corruption-slave.opt	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_row_corruption-slave.opt	2011-07-14 11:15:24 +0000
@@ -0,0 +1 @@
+--replicate-ignore-table=test.t2_11753004_ign

=== added file 'mysql-test/suite/rpl/t/rpl_row_corruption.test'
--- a/mysql-test/suite/rpl/t/rpl_row_corruption.test	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_row_corruption.test	2011-07-14 11:15:24 +0000
@@ -0,0 +1,115 @@
+#
+--source include/master-slave.inc
+--source include/have_debug.inc
+--source include/have_binlog_format_row.inc
+
+# BUG#11753004: 44360: REPLICATION FAILED 
+
+## assert that we get an error when checking the
+## identifiers at the slave (instead of a crash or
+## different table being updated)
+
+--let $t1= t1_11753004
+--let $t2= t2_11753004
+--let $t2_ign= t2_11753004_ign
+
+## test #1: assert that we get an error raised when multiple
+##          tables in the same RBR statement are mapped with the
+##          same identifier
+
+--eval CREATE TABLE $t1 (c1 INT)
+--eval CREATE TABLE $t2 (c1 INT)
+--eval INSERT INTO $t1 VALUES (1)
+--eval INSERT INTO $t2 VALUES (2)
+
+--sync_slave_with_master
+call mtr.add_suppression(".*Found table map event mapping table id 0 which was already mapped but with different settings.*");
+
+# stop the slave and inject corruption
+--source include/stop_slave.inc
+SET @save_debug= @@global.debug;
+SET GLOBAL debug="+d,inject_tblmap_same_id_maps_diff_table";
+--source include/start_slave.inc
+--connection master
+# both tables get mapped to 0 (in a way, simulating scenario 
+# originated by BUG#56226)
+--eval UPDATE $t1, $t2 SET $t1.c1=3, $t2.c1=4 WHERE $t1.c1=1 OR $t2.c1=2
+--connection slave
+
+# wait for error 1593 (ER_SLAVE_FATAL_ERROR)
+--let $slave_sql_errno=1593 
+--source include/wait_for_slave_sql_error.inc
+--source include/stop_slave.inc
+
+# clean up
+SET GLOBAL debug="-d,inject_tblmap_same_id_maps_diff_table";
+--source include/start_slave.inc
+--connection master
+--source include/rpl_reset.inc
+--eval DROP TABLE $t1, $t2
+--sync_slave_with_master
+
+## test #2: assert that ignored tables that may have been mapped
+##          with the same identifier are skipped, thus no error
+##          is raised.
+
+--connection slave
+--source include/stop_slave.inc
+SET GLOBAL debug="+d,inject_tblmap_same_id_maps_diff_table";
+--source include/start_slave.inc
+--source include/rpl_reset.inc
+--connection master
+--eval CREATE TABLE $t1 (c1 INT)
+--eval CREATE TABLE $t2_ign (c1 INT)
+--eval INSERT INTO $t1 VALUES (1)
+--eval INSERT INTO $t2_ign VALUES (2)
+--eval UPDATE $t1, $t2_ign SET $t1.c1=3, $t2_ign.c1=4 WHERE $t1.c1=1 OR $t2_ign.c1=2
+
+# must not raise error as second table is filtered
+--sync_slave_with_master
+
+
+## test #3: check that BINLOG statements will also raise an
+##          error if containing table map events mapping different
+##          tables to same table identifier.
+
+CREATE TABLE t1 (c1 INT);
+CREATE TABLE t2 (c1 INT);
+
+INSERT INTO t1 VALUES (1);
+INSERT INTO t2 VALUES (1);
+
+# FD event
+BINLOG '
+SOgWTg8BAAAAbgAAAHIAAAAAAAQANS42LjMtbTUtZGVidWctbG9nAAAAAAAAAAAAAAAAAAAAAAAA
+AAAAAAAAAAAAAAAAAABI6BZOEzgNAAgAEgAEBAQEEgAAVgAEGggAAAAICAgCAAAAAAVAYI8=
+'/*!*/;
+
+#110708 12:21:44 server id 1  end_log_pos 774   Table_map: `test`.`t1` mapped to number 66
+# at 774
+#110708 12:21:44 server id 1  end_log_pos 815   Table_map: `test`.`t2` mapped to number 67
+# at 815
+#110708 12:21:44 server id 1  end_log_pos 855   Update_rows: table id 66
+# at 855
+#110708 12:21:44 server id 1  end_log_pos 895   Update_rows: table id 67 flags: STMT_END_F
+SET GLOBAL debug="+d,inject_tblmap_same_id_maps_diff_table";
+--error ER_SLAVE_FATAL_ERROR
+BINLOG '
+SOgWThMBAAAAKQAAAAYDAAAAAEIAAAAAAAEABHRlc3QAAnQxAAEDAAE=
+SOgWThMBAAAAKQAAAC8DAAAAAEMAAAAAAAEABHRlc3QAAnQyAAEDAAE=
+SOgWThgBAAAAKAAAAFcDAAAAAEIAAAAAAAAAAf///gEAAAD+AwAAAA==
+SOgWThgBAAAAKAAAAH8DAAAAAEMAAAAAAAEAAf///gEAAAD+BAAAAA==
+'/*!*/;
+
+
+# clean up
+DROP TABLE t1,t2;
+--connection slave
+SET GLOBAL debug="-d,inject_tblmap_same_id_maps_diff_table";
+--connection master
+--eval DROP TABLE $t1
+--eval DROP TABLE $t2_ign
+--sync_slave_with_master
+SET GLOBAL debug= @save_debug;
+
+--source include/rpl_end.inc

=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc	2011-07-03 15:47:37 +0000
+++ b/sql/log_event.cc	2011-07-14 11:15:24 +0000
@@ -8222,6 +8222,97 @@ Table_map_log_event::~Table_map_log_even
  */
 
 #if !defined(MYSQL_CLIENT) && defined(HAVE_REPLICATION)
+
+enum enum_tbl_map_status
+{
+  /* no duplicate identifier found */
+  OK_TO_PROCESS= 0,
+
+  /* this table map must be filtered out */
+  FILTERED_OUT= 1,
+
+  /* identifier mapping table with different properties */
+  SAME_ID_MAPPING_DIFFERENT_TABLE= 2,
+  
+  /* a duplicate identifier was found mapping the same table */
+  SAME_ID_MAPPING_SAME_TABLE= 3
+};
+
+/*
+  Checks if this table map event should be processed or not. First
+  it checks the filtering rules, and then looks for duplicate identifiers
+  in the existing list of rli->tables_to_lock.
+
+  It checks that there hasn't been any corruption by verifying that there
+  are no duplicate entries with different properties.
+
+  In some cases, some binary logs could get corrupted, showing several
+  tables mapped to the same table_id, 0 (see: BUG#56226). Thus we do this
+  early sanity check for such cases and avoid that the server crashes 
+  later.
+
+  In some corner cases, the master logs duplicate table map events, i.e.,
+  same id, same database name, same table name (see: BUG#37137). This is
+  different from the above as it's the same table that is mapped again 
+  to the same identifier. Thus we cannot just check for same ids and 
+  assume that the event is corrupted we need to check every property. 
+
+  NOTE: in the event that BUG#37137 ever gets fixed, this extra check 
+        will still be valid because we would need to support old binary 
+        logs anyway.
+
+  @param rli The relay log info reference.
+  @param table_list A list element containing the table to check against.
+  @return OK_TO_PROCESS 
+            if there was no identifier already in rli->tables_to_lock 
+            
+          FILTERED_OUT
+            if the event is filtered according to the filtering rules
+
+          SAME_ID_MAPPING_DIFFERENT_TABLE 
+            if the same identifier already maps a different table in 
+            rli->tables_to_lock
+
+          SAME_ID_MAPPING_SAME_TABLE 
+            if the same identifier already maps the same table in 
+            rli->tables_to_lock.
+*/
+static enum_tbl_map_status
+check_table_map(Relay_log_info const *rli, RPL_TABLE_LIST *table_list)
+{
+  DBUG_ENTER("check_table_map");
+  enum_tbl_map_status res= OK_TO_PROCESS;
+
+  if (rli->sql_thd->slave_thread /* filtering is for slave only */ &&
+      (!rpl_filter->db_ok(table_list->db) ||
+       (rpl_filter->is_on() && !rpl_filter->tables_ok("", table_list))))
+    res= FILTERED_OUT;
+  else
+  {
+    for(RPL_TABLE_LIST *ptr= static_cast<RPL_TABLE_LIST*>(rli->tables_to_lock);
+        ptr; 
+        ptr= static_cast<RPL_TABLE_LIST*>(ptr->next_local))
+    {
+      if (ptr->table_id == table_list->table_id)
+      {
+
+        if (strcmp(ptr->db, table_list->db) || 
+            strcmp(ptr->alias, table_list->table_name) || 
+            ptr->lock_type != TL_WRITE) // the ::do_apply_event always sets TL_WRITE
+          res= SAME_ID_MAPPING_DIFFERENT_TABLE;
+        else
+          res= SAME_ID_MAPPING_SAME_TABLE;
+
+        break;
+      }
+    }
+  }
+
+  DBUG_PRINT("debug", ("check of table map ended up with: %u", res));
+
+  DBUG_RETURN(res);
+}
+
 int Table_map_log_event::do_apply_event(Relay_log_info const *rli)
 {
   RPL_TABLE_LIST *table_list;
@@ -8248,20 +8339,13 @@ int Table_map_log_event::do_apply_event(
   table_list->alias= table_list->table_name = tname_mem;
   table_list->lock_type= TL_WRITE;
   table_list->next_global= table_list->next_local= 0;
-  table_list->table_id= m_table_id;
+  table_list->table_id= DBUG_EVALUATE_IF("inject_tblmap_same_id_maps_diff_table", 0, m_table_id);
   table_list->updating= 1;
   strmov(table_list->db, rpl_filter->get_rewrite_db(m_dbnam, &dummy_len));
   strmov(table_list->table_name, m_tblnam);
-
-  int error= 0;
-
-  if (rli->sql_thd->slave_thread /* filtering is for slave only */ &&
-      (!rpl_filter->db_ok(table_list->db) ||
-       (rpl_filter->is_on() && !rpl_filter->tables_ok("", table_list))))
-  {
-    my_free(memory, MYF(MY_WME));
-  }
-  else
+  DBUG_PRINT("debug", ("table: %s is mapped to %u", table_list->table_name, table_list->table_id));
+  enum_tbl_map_status tblmap_status= check_table_map(rli, table_list);
+  if (tblmap_status == OK_TO_PROCESS)
   {
     DBUG_ASSERT(thd->lex->query_tables != table_list);
 
@@ -8290,8 +8374,48 @@ int Table_map_log_event::do_apply_event(
     const_cast<Relay_log_info*>(rli)->tables_to_lock_count++;
     /* 'memory' is freed in clear_tables_to_lock */
   }
+  else  // FILTERED_OUT, SAME_ID_MAPPING_*
+  {
+    /*
+      If mapped already but with different properties, we raise an
+      error.
+      If mapped already but with same properties we skip the event.
+      If filtered out we skip the event.
+
+      In all three cases, we need to free the memory previously 
+      allocated.
+     */
+    if (tblmap_status == SAME_ID_MAPPING_DIFFERENT_TABLE)
+    {
+      /*
+        Something bad has happened. We need to stop the slave as strange things
+        could happen if we proceed: slave crash, wrong table being updated, ...
+        As a consequence we push an error in this case.
+       */
+
+      char buf[256];
+
+      my_snprintf(buf, sizeof(buf), 
+                  "Found table map event mapping table id %u which "
+                  "was already mapped but with different settings.",
+                  table_list->table_id);
+
+      if (thd->slave_thread)
+        rli->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, 
+                    ER(ER_SLAVE_FATAL_ERROR), buf);
+      else
+        /* 
+          For the cases in which a 'BINLOG' statement is set to 
+          execute in a user session 
+         */
+        my_printf_error(ER_SLAVE_FATAL_ERROR, ER(ER_SLAVE_FATAL_ERROR), 
+                        MYF(0), buf);
+    } 
+    
+    my_free(memory, MYF(0));
+  }
 
-  DBUG_RETURN(error);
+  DBUG_RETURN(tblmap_status == SAME_ID_MAPPING_DIFFERENT_TABLE);
 }
 
 Log_event::enum_skip_reason

No bundle (reason: useless for push emails).
Thread
bzr push into mysql-5.1 branch (luis.soares:3570 to 3571) Bug#11753004Luis Soares17 Jul