From ce8077d8d37e37f4b007f64c5ca301d096699db8 Mon Sep 17 00:00:00 2001 From: Luis Soares Date: Thu, 14 Jul 2011 12:15:24 +0100 Subject: [PATCH] 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. --- .../suite/rpl/r/rpl_row_corruption.result | 49 ++++++ .../suite/rpl/t/rpl_row_corruption-slave.opt | 1 + .../suite/rpl/t/rpl_row_corruption.test | 115 ++++++++++++++ sql/log_event.cc | 148 ++++++++++++++++-- 4 files changed, 301 insertions(+), 12 deletions(-) create mode 100644 mysql-test/suite/rpl/r/rpl_row_corruption.result create mode 100644 mysql-test/suite/rpl/t/rpl_row_corruption-slave.opt create mode 100644 mysql-test/suite/rpl/t/rpl_row_corruption.test diff --git a/mysql-test/suite/rpl/r/rpl_row_corruption.result b/mysql-test/suite/rpl/r/rpl_row_corruption.result new file mode 100644 index 00000000000..7fd47a20f03 --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_row_corruption.result @@ -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 diff --git a/mysql-test/suite/rpl/t/rpl_row_corruption-slave.opt b/mysql-test/suite/rpl/t/rpl_row_corruption-slave.opt new file mode 100644 index 00000000000..da199510eb3 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_row_corruption-slave.opt @@ -0,0 +1 @@ +--replicate-ignore-table=test.t2_11753004_ign diff --git a/mysql-test/suite/rpl/t/rpl_row_corruption.test b/mysql-test/suite/rpl/t/rpl_row_corruption.test new file mode 100644 index 00000000000..a7650c615a3 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_row_corruption.test @@ -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 diff --git a/sql/log_event.cc b/sql/log_event.cc index 1f58c7ed1bf..82a6d9e8ffc 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -8222,6 +8222,97 @@ Table_map_log_event::~Table_map_log_event() */ #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(rli->tables_to_lock); + ptr; + ptr= static_cast(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(Relay_log_info const *rli) 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(Relay_log_info const *rli) const_cast(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. - DBUG_RETURN(error); + 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(tblmap_status == SAME_ID_MAPPING_DIFFERENT_TABLE); } Log_event::enum_skip_reason