revision-id: ec995da254d0138faed66a5f580a744578d4efad (mariadb-10.2.23-125-gec995da254d) parent(s): 27232a9fa26c2320e344e37b95bb46a89fa33257 author: Sujatha committer: Sujatha timestamp: 2019-05-09 13:32:11 +0530 message: MDEV-19158: MariaDB 10.2.22 is writing duplicate entries into binary log Problem: ======== We have a Master/Master Setup on two servers, but are only writing to one of those servers (so it is essentially Master/Slave) We upgraded from 10.1.* to 10.2.22 last week and starting with the upgrade, we are getting duplicate key errors on the slave. BINLOG=mixed. Analysis: ========= This issue happens with LOCK TABLES and binlog_format=MIXED combination. When an UNSAFE statement is encountered in 'MIXED' mode, it is logged in the form of 'ROW' format. For all the tables that are part of LOCK TABLES list their table maps are written into the binary log. For each table in the list a check is done to see if 'check_table_binlog_row_based_done' flag is set or not. If it is not set a check process is initiated to see if table qualifies for row based binary logging or not and 'check_table_binlog_row_based_done' is set. This flag will be cleared at the time of closing thread tables. But there can be special cases where the LOCK TABLES contains more number of tables but the unsafe query is actually using subset of tables from LOCK TABLES list. For example: LOCK TABLES locks t1,t2,t3 but the unsafe statement makes use of only two tables t1,t3. In this case the 'check_table_binlog_row_based_done' flag is enabled for table 't2' while writing table map, but 'close_thread_tables' function call will not reset this flag. Since the flag is not cleared for table 't2' even a safe statement which used t2 will be logged in the form of row based format. This leads to an assert on debug builds and causes duplicate entries in release builds. In release builds a statement is logged in the form of both ROW and STATEMENT format. This causes the slave to fail with duplicate key error. Fix: === During 'close_thread_tables' when LOCK TABLE modes are active "ha_reset" is done for all the tables which were part of current statement. As mentioned in the example 'ha_reset' is called for tables 't1' and 't3'. This will clear the 'check_table_binlog_row_based_done' flag. At this point add a check for the rest of the tables to see if 'check_table_binlog_row_based_done' is enabled or not. If enabled clear the flag. --- mysql-test/suite/rpl/r/rpl_binlog_dup_entry.result | 29 +++++++++ mysql-test/suite/rpl/t/rpl_binlog_dup_entry.test | 72 ++++++++++++++++++++++ sql/handler.cc | 4 +- sql/handler.h | 5 ++ sql/sql_base.cc | 8 +++ 5 files changed, 116 insertions(+), 2 deletions(-) diff --git a/mysql-test/suite/rpl/r/rpl_binlog_dup_entry.result b/mysql-test/suite/rpl/r/rpl_binlog_dup_entry.result new file mode 100644 index 00000000000..108a65df07f --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_binlog_dup_entry.result @@ -0,0 +1,29 @@ +include/master-slave.inc +[connection master] +CREATE TABLE t1 (id mediumint(8) unsigned NOT NULL AUTO_INCREMENT, someLabel varchar(30) NOT NULL, flag tinyint(1) NOT NULL DEFAULT 0, PRIMARY KEY (id)) Engine=MyISAM; +CREATE TABLE t2 (id mediumint(8) unsigned NOT NULL AUTO_INCREMENT, data varchar(30) NOT NULL, status tinyint(1) NOT NULL, PRIMARY KEY (id)) Engine=MyISAM; +CREATE TABLE t3 (id mediumint(8) unsigned NOT NULL AUTO_INCREMENT, t1id mediumint(8) unsigned NOT NULL, flag tinyint(1) NOT NULL DEFAULT 0, status tinyint(1) NOT NULL DEFAULT 0, PRIMARY KEY (id)) Engine=MyISAM; +INSERT INTO t1 ( id, someLabel, flag ) VALUES ( 1, 'ABC', 0 ); +CREATE OR REPLACE TRIGGER doNothing +BEFORE UPDATE ON t1 +FOR EACH ROW +BEGIN +IF +new.someLabel != old.someLabel +THEN +UPDATE t3 SET t3.flag = 0; +END IF; +END| +FLUSH LOGS; +LOCK TABLES t1 WRITE, t2 WRITE; +INSERT INTO t2 (data, status) VALUES ('1', 4); +UPDATE t1 SET flag = 1 WHERE id = 1; +INSERT INTO t2 (data, status) VALUES ('2', 4); +UNLOCK TABLES; +connection slave; +include/diff_tables.inc [master:t1, slave:t1] +include/diff_tables.inc [master:t2, slave:t2] +include/diff_tables.inc [master:t3, slave:t3] +connection master; +DROP TABLE t1, t2, t3; +include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_binlog_dup_entry.test b/mysql-test/suite/rpl/t/rpl_binlog_dup_entry.test new file mode 100644 index 00000000000..869c715f407 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_binlog_dup_entry.test @@ -0,0 +1,72 @@ +# ==== Purpose ==== +# +# Test verifies that there are no duplicate entries in binlog (i.e a safe +# statement which follows an unsafe statement gets logged in both row format +# and statement format resulting in duplicate entry) when binlog-format=MIXED +# and LOCK TABLES are enabled. +# +# ==== Implementation ==== +# +# Steps: +# 1 - Create three tables t1,t2 and t3 with AUTO_INCREMENT on. +# 2 - Create a trigger on table t3, so that trigger execution results in +# unsafe statement. Note query that modifies autoinc column in +# sub-statement can make the master and slave inconsistent. Hence they +# are logged in row format. +# 3 - Lock tables t1,t2 and t3. +# 4 - Execute an unsafe update which modifies tables t1 and t3. But since t2 +# table is also locked its table map event also gets written into the +# binary log during the execution of update. +# 5 - Execute a safe DML operation using table 't2' and verify that master +# doesn't report any assert. +# 6 - Ensure that slave is in sync with master and data is consistent. +# +# ==== References ==== +# +# MDEV-19158: MariaDB 10.2.22 is writing duplicate entries into binary log + +--source include/have_binlog_format_mixed.inc +--source include/master-slave.inc + +CREATE TABLE t1 (id mediumint(8) unsigned NOT NULL AUTO_INCREMENT, someLabel varchar(30) NOT NULL, flag tinyint(1) NOT NULL DEFAULT 0, PRIMARY KEY (id)) Engine=MyISAM; +CREATE TABLE t2 (id mediumint(8) unsigned NOT NULL AUTO_INCREMENT, data varchar(30) NOT NULL, status tinyint(1) NOT NULL, PRIMARY KEY (id)) Engine=MyISAM; +CREATE TABLE t3 (id mediumint(8) unsigned NOT NULL AUTO_INCREMENT, t1id mediumint(8) unsigned NOT NULL, flag tinyint(1) NOT NULL DEFAULT 0, status tinyint(1) NOT NULL DEFAULT 0, PRIMARY KEY (id)) Engine=MyISAM; + +INSERT INTO t1 ( id, someLabel, flag ) VALUES ( 1, 'ABC', 0 ); + +DELIMITER |; + +CREATE OR REPLACE TRIGGER doNothing +BEFORE UPDATE ON t1 +FOR EACH ROW + BEGIN + IF + new.someLabel != old.someLabel + THEN + UPDATE t3 SET t3.flag = 0; + END IF; + END| + +DELIMITER ;| + +FLUSH LOGS; + +LOCK TABLES t1 WRITE, t2 WRITE; +INSERT INTO t2 (data, status) VALUES ('1', 4); +UPDATE t1 SET flag = 1 WHERE id = 1; +INSERT INTO t2 (data, status) VALUES ('2', 4); +UNLOCK TABLES; + +sync_slave_with_master; + +let $diff_tables= master:t1, slave:t1; +--source include/diff_tables.inc +let $diff_tables= master:t2, slave:t2; +--source include/diff_tables.inc +let $diff_tables= master:t3, slave:t3; +--source include/diff_tables.inc + +--connection master +DROP TABLE t1, t2, t3; + +--source include/rpl_end.inc diff --git a/sql/handler.cc b/sql/handler.cc index e5b452f9649..cb775a9390e 100644 --- a/sql/handler.cc +++ b/sql/handler.cc @@ -6030,8 +6030,8 @@ int handler::ha_reset() table->default_column_bitmaps(); pushed_cond= NULL; tracker= NULL; - mark_trx_read_write_done= check_table_binlog_row_based_done= - check_table_binlog_row_based_result= 0; + mark_trx_read_write_done= 0; + clear_cached_table_binlog_row_based_flag(); /* Reset information about pushed engine conditions */ cancel_pushed_idx_cond(); /* Reset information about pushed index conditions */ diff --git a/sql/handler.h b/sql/handler.h index d1e9f93797b..17bccbca845 100644 --- a/sql/handler.h +++ b/sql/handler.h @@ -3972,6 +3972,11 @@ class handler :public Sql_alloc public: inline bool check_table_binlog_row_based(bool binlog_row); + inline void clear_cached_table_binlog_row_based_flag() + { + check_table_binlog_row_based_done= 0; + check_table_binlog_row_based_result= 0; + } private: /* Cache result to avoid extra calls */ inline void mark_trx_read_write() diff --git a/sql/sql_base.cc b/sql/sql_base.cc index cb817e83fd7..50155cd7d45 100644 --- a/sql/sql_base.cc +++ b/sql/sql_base.cc @@ -583,6 +583,12 @@ bool close_cached_connection_tables(THD *thd, LEX_STRING *connection) Marks all tables in the list which were used by current substatement (they are marked by its query_id) as free for reuse. + Clear 'check_table_binlog_row_based_done' flag. For tables which were used + by current substatement the flag is cleared as part of 'ha_reset()' call. + For the rest of the open tables not used by current substament if this + flag is enabled as part of current substatement execution, clear the flag + explicitly. + NOTE The reason we reset query_id is that it's not enough to just test if table->query_id != thd->query_id to know if a table is in use. @@ -604,6 +610,8 @@ static void mark_used_tables_as_free_for_reuse(THD *thd, TABLE *table) table->query_id= 0; table->file->ha_reset(); } + else if (table->file->check_table_binlog_row_based_done) + table->file->clear_cached_table_binlog_row_based_flag(); } }