revision-id: c7a2d42c30b9c4b807ef661b44c733e4a111f348 (mariadb-10.1.33-36-gc7a2d42c30b) parent(s): 26be5072429082e634b8fc102609370975443439 author: Andrei Elkin committer: Andrei Elkin timestamp: 2018-06-12 20:55:28 +0300 message: MDEV-14014 Multi-Slave Replication Fail: bogus data in log event MDEV-7257 made a dump thread to read from binlog concurrently with writers as long as the read bytes are below a water-mark (MYSQL_BIN_LOG::binlog_end_pos). However it appeared to be possible a dump thread reader reach out for bytes past the water mark through a feature of IO_CACHE that fills in the internal buffer and while doing so it could read what the reader is not supposed to see (the bytes above MYSQL_BIN_LOG::binlog_end_pos). The issue is fixed with constraining the IO_CACHE buffer fill to respect the watermark. An added test simulates potentially unconstrained buffer fill and an assert guards this is not the case anymore. --- .../r/rpl_mdev14014_dirty_read_dump_thread.result | 14 +++++++ .../t/rpl_mdev14014_dirty_read_dump_thread.test | 44 ++++++++++++++++++++++ sql/log.cc | 2 + sql/sql_repl.cc | 30 ++++++++++++++- 4 files changed, 89 insertions(+), 1 deletion(-) diff --git a/mysql-test/suite/rpl/r/rpl_mdev14014_dirty_read_dump_thread.result b/mysql-test/suite/rpl/r/rpl_mdev14014_dirty_read_dump_thread.result new file mode 100644 index 00000000000..e8c5f49565c --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_mdev14014_dirty_read_dump_thread.result @@ -0,0 +1,14 @@ +include/rpl_init.inc [topology=1->2] +CREATE TABLE t1 (a INT); +include/rpl_sync.inc +SET @save_debug= @@GLOBAL.debug_dbug; +SET @@GLOBAL.debug_dbug="+d,dump_thread_wait_around_read"; +INSERT INTO t1 SET a=1; +SET debug_sync="at_after_write_to_binlog SIGNAL dump_go_on_reading"; +INSERT INTO t1 SET a=1; +include/rpl_sync.inc +SET debug_sync='reset'; +*** Clean up *** +SET @@GLOBAL.debug_dbug= @save_debug; +DROP TABLE t1; +include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_mdev14014_dirty_read_dump_thread.test b/mysql-test/suite/rpl/t/rpl_mdev14014_dirty_read_dump_thread.test new file mode 100644 index 00000000000..98e77439702 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_mdev14014_dirty_read_dump_thread.test @@ -0,0 +1,44 @@ +# ==== Purpose ==== +# +# Check out if there are any dirty read by dump threads of the master (server_1) +# +# ==== Related worklogs ==== +# +# MDEV-14014 +# MDEV-7257 + +--source include/have_debug_sync.inc +--source include/have_debug.inc + +--let $rpl_topology= 1->2 +--source include/rpl_init.inc + +--connection server_1 +CREATE TABLE t1 (a INT); +--source include/rpl_sync.inc + + +--connection server_1 +SET @save_debug= @@GLOBAL.debug_dbug; +SET @@GLOBAL.debug_dbug="+d,dump_thread_wait_around_read"; + +--connect(con1, localhost, root) +INSERT INTO t1 SET a=1; # incr BEP and breaks waiting to reading +#SET debug_sync="at_after_write_to_binlog SIGNAL dump_go_on_reading WAIT_FOR user_thread_go"; +SET debug_sync="at_after_write_to_binlog SIGNAL dump_go_on_reading"; +INSERT INTO t1 SET a=1; # the 2nd group is the extra, it must not be seen by the dump thread + +--source include/rpl_sync.inc + +--connection con1 +SET debug_sync='reset'; + + +# +--echo *** Clean up *** +# +--connection server_1 +SET @@GLOBAL.debug_dbug= @save_debug; +DROP TABLE t1; + +--source include/rpl_end.inc diff --git a/sql/log.cc b/sql/log.cc index 29f8c5639cf..f72238d39ce 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -7857,6 +7857,8 @@ MYSQL_BIN_LOG::trx_group_commit_leader(group_commit_entry *leader) bool any_error= false; bool all_error= true; + DEBUG_SYNC(leader->thd, "at_after_write_to_binlog"); + mysql_mutex_assert_not_owner(&LOCK_prepare_ordered); mysql_mutex_assert_owner(&LOCK_log); mysql_mutex_assert_not_owner(&LOCK_after_binlog_sync); diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc index 569c3d2c4ef..4144838a52a 100644 --- a/sql/sql_repl.cc +++ b/sql/sql_repl.cc @@ -2541,11 +2541,14 @@ static int send_events(binlog_send_info *info, IO_CACHE* log, LOG_INFO* linfo, { int error; ulong ev_offset; - +#ifndef DBUG_OFF + ulonglong dbug_events= 0; +#endif String *packet= info->packet; linfo->pos= my_b_tell(log); info->last_pos= my_b_tell(log); + log->end_of_file= end_pos; while (linfo->pos < end_pos) { if (should_stop(info)) @@ -2556,12 +2559,37 @@ static int send_events(binlog_send_info *info, IO_CACHE* log, LOG_INFO* linfo, if (reset_transmit_packet(info, info->flags, &ev_offset, &info->errmsg)) return 1; +#ifdef ENABLED_DEBUG_SYNC + DBUG_EXECUTE_IF("dump_thread_wait_around_read", + if (dbug_events++ == 0) + { + const char act[]= + "now " + "WAIT_FOR dump_go_on_reading"; + DBUG_ASSERT(debug_sync_service); + DBUG_ASSERT(!debug_sync_set_action( + info->thd, + STRING_WITH_LEN(act))); + } + ); +#endif + info->last_pos= linfo->pos; error= Log_event::read_log_event(log, packet, info->fdev, opt_master_verify_checksum ? info->current_checksum_alg : BINLOG_CHECKSUM_ALG_OFF); linfo->pos= my_b_tell(log); +#ifdef ENABLED_DEBUG_SYNC + DBUG_EXECUTE_IF("dump_thread_wait_around_read", + if (dbug_events == 1) + { + DBUG_ASSERT(log->pos_in_file + + (size_t) (log->read_end - log->buffer) + <= end_pos); + } + ); +#endif if (error) { set_read_error(info, error);