[Commits] ec995da254d: MDEV-19158: MariaDB 10.2.22 is writing duplicate entries into binary log

sujatha sujatha.sivakumar at mariadb.com
Thu May 9 11:05:56 EEST 2019


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();
   }
 }
 


More information about the commits mailing list