MySQL Bugs: #67929: Race in bin log dump thread results in slave missing events

Bug #67929	Race in bin log dump thread results in slave missing events
Submitted:	17 Dec 2012 18:13	Modified:	3 Apr 2013 18:13
Reporter:	Justin Tolmer	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.1.63,5.6.9	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
In function mysql_binlog_send, there is a race condition which may cause the slave to miss events from the end of the master's bin log.

Path to reproducing the problem is:

Thread A:
  Bin log dump thread (function mysql_binlog_send)
  Hits EOF reading events from active bin log
  Exits the while (Log_event::read_log_event) loop
  Passes the test_for_non_eof_log_read_errors check
  Context switch away

Thread B:
  Perform some operation, generating enough replication events sufficient to cause the active bin log to rotate

Thread A:
  Context switch back
  Perform check for:
      if (!(flags & BINLOG_DUMP_NON_BLOCK) &&
        mysql_bin_log.is_active(log_file_name))
  is_active check fails so bin log dump thread moves to next bin log, skipping events written by thread B above. 

How to repeat:
Here's a patch for 5.1.63. It adds one DBUG_EXECUTE_IF statement and a test which reproduces the problem. 

diff --git a/mysql-test/suite/rpl/r/rpl_missing_events.result b/mysql-test/suite/rpl/r/rpl_missing_events.result
new file mode 100644
index 0000000..95d3285
--- /dev/null
+++ b/mysql-test/suite/rpl/r/rpl_missing_events.result
@@ -0,0 +1,22 @@
+include/master-slave.inc
+[connection master]
+include/stop_slave.inc
+CREATE TABLE t1 (a INT PRIMARY KEY);
+INSERT INTO t1 VALUES (0);
+INSERT INTO t1 VALUES (1);
+INSERT INTO t1 VALUES (2);
+SET GLOBAL DEBUG="d,binlog_dump_sleep_at_eof";
+include/start_slave.inc
+INSERT INTO t1 VALUES (3);
+INSERT INTO t1 VALUES (4);
+INSERT INTO t1 VALUES (5);
+FLUSH LOGS;
+INSERT INTO t1 VALUES (6);
+INSERT INTO t1 VALUES (7);
+INSERT INTO t1 VALUES (8);
+SELECT 9 - 6 AS diff_rows;
+diff_rows
+0
+SET GLOBAL debug='';
+DROP TABLE t1;
+include/rpl_end.inc
diff --git a/mysql-test/suite/rpl/t/rpl_missing_events.test b/mysql-test/suite/rpl/t/rpl_missing_events.test
new file mode 100644
index 0000000..e360904
--- /dev/null
+++ b/mysql-test/suite/rpl/t/rpl_missing_events.test
@@ -0,0 +1,41 @@
+--source include/master-slave.inc
+--source include/have_debug.inc
+
+let $debug_save= `SELECT @@GLOBAL.debug`;
+
+sync_slave_with_master;
+--source include/stop_slave.inc
+
+connection master;
+CREATE TABLE t1 (a INT PRIMARY KEY);
+INSERT INTO t1 VALUES (0);
+INSERT INTO t1 VALUES (1);
+INSERT INTO t1 VALUES (2);
+
+# Would be nice to use DEBUG_SYNC but I don't see how that can be done
+# on the bin log dump thread.
+SET GLOBAL DEBUG="d,binlog_dump_sleep_at_eof";
+
+connection slave;
+--source include/start_slave.inc
+sleep 3;
+
+connection master;
+INSERT INTO t1 VALUES (3);
+INSERT INTO t1 VALUES (4);
+INSERT INTO t1 VALUES (5);
+FLUSH LOGS;
+INSERT INTO t1 VALUES (6);
+INSERT INTO t1 VALUES (7);
+INSERT INTO t1 VALUES (8);
+let $rows_on_master= `SELECT COUNT(*) FROM t1`;
+
+sync_slave_with_master;
+let $rows_on_slave= `SELECT COUNT(*) FROM t1`;
+
+eval SELECT $rows_on_master - $rows_on_slave AS diff_rows;
+
+connection master;
+eval SET GLOBAL debug='$debug_save';
+DROP TABLE t1;
+--source include/rpl_end.inc
diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc
index 2793787..0f0d7a2 100644
--- a/sql/sql_repl.cc
+++ b/sql/sql_repl.cc
@@ -937,6 +937,8 @@ impossible position";
     if (test_for_non_eof_log_read_errors(error, &errmsg))
       goto err;
 
+    DBUG_EXECUTE_IF("binlog_dump_sleep_at_eof", my_sleep(6 * 1000 * 1000););
+
     if (!(flags & BINLOG_DUMP_NON_BLOCK) &&
         mysql_bin_log.is_active(log_file_name))
     {

Thank you for the report.

Test passes in my case and, if I understood correctly, it should fail reporting difference between number of records in master and slave tables. Please confirm or explain.

Against which version did you test? And I assume you used a debug build since the test requires that?

Thank you for the feedback.

Against 5.1.68. Yes, debug build.

Neither 5.1.67 nor 5.1.68 have been published so I can't test against those releases to know whether the bug has been fixed and / or my test is failing for some other reason when you test on that version.

I did verify that my test reproduces the problem consistently on the 5.1.66 code currently available in launchpad.

Are you sure that the DBUG_EXECUTE_IF at the bottom of my patch was successfully added to sql_repl.cc when you attempted to reproduce?

Hi Justin

This bug was already created on our side and was already in progress, but I must thank you for pin-pointing the problem in such a nice manner.
We are now looking into a solution, I hope we can get it soon. 

Thanks.

Pedro,

Could you comment on the Oracle-internal bug number of this bug?

This is a duplicate of an internally filed bug (not yet fixed).

Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Fixed in 5.1+. Documented fix in the 5.1.69, 5.5.31, 5.6.11, and 5.7.1
changelogs, as follows:

        It was possible immediately after detecting an EOF in the dump
        thread read event loop, and before deciding whether to change to
        a new binary log file, for new events to be written to the
        binary log concurrently with rotating the log. If log rotation
        occurred during this window, any events that also occurred at
        that time were dropped, resulting in loss of data. Now in such
        cases, steps are taken to make sure that no more events remain
        before allowing the log rotation to take place.

Closed.