MDEV-25611: RESET MASTER causes the server to hang

RESET MASTER waits for storage engines to reply to a binlog checkpoint
requests. If this response is delayed for a long time for some reason, then
RESET MASTER can hang.

Fix this by forcing a log sync in all engines just before waiting for the
checkpoint reply.

(Waiting for old checkpoint responses is needed to preserve durability of
any commits that were synced to disk in the to-be-deleted binlog but not yet
synced in the engine.)

Reviewed-by: Andrei Elkin <andrei.elkin@mariadb.com>
Signed-off-by: Kristian Nielsen <knielsen@knielsen-hq.org>

Author: knielsen

mysql-test/suite/binlog/r/binlog_mdev25611.result

@@ -0,0 +1,28 @@
+*** MDEV-25611: RESET MASTER hangs waiting for InnoDB to flush its log
+SET @old_dbug= @@global.DEBUG_DBUG;
+SET GLOBAL debug_dbug="+d,ib_log_checkpoint_avoid";
+SET @old_flush= @@GLOBAL.innodb_flush_log_at_trx_commit;
+SET GLOBAL innodb_flush_log_at_trx_commit= 0;
+SET @old_flush_timeout= @@GLOBAL.innoDB_flush_log_at_timeout;
+SET GLOBAL innoDB_flush_log_at_timeout=2700;
+connection default;
+CREATE TABLE t1 (a INT PRIMARY KEY, b INT) ENGINE=InnoDB STATS_PERSISTENT=0;
+INSERT INTO t1 VALUES (1,1);
+INSERT INTO t1 VALUES (2,1);
+INSERT INTO t1 VALUES (3,1);
+connect  stop_purge,localhost,root,,;
+START TRANSACTION WITH CONSISTENT SNAPSHOT;
+connection default;
+INSERT INTO t1 VALUES (4,2);
+DELETE FROM t1 WHERE a in (1,2,3);
+FLUSH BINARY LOGS;
+connection stop_purge;
+ROLLBACK;
+connection default;
+disconnect stop_purge;
+RESET MASTER;
+connection default;
+DROP TABLE t1;
+SET GLOBAL debug_dbug= @old_dbug;
+SET GLOBAL innodb_flush_log_at_trx_commit= @old_flush;
+SET GLOBAL innoDB_flush_log_at_timeout= @old_flush_timeout;

mysql-test/suite/binlog/t/binlog_mdev25611.test

@@ -0,0 +1,54 @@
+source include/have_innodb.inc;
+source include/have_log_bin.inc;
+source include/have_binlog_format_mixed.inc;
+
+--echo *** MDEV-25611: RESET MASTER hangs waiting for InnoDB to flush its log
+# Error injection to minimize extra log flushing inside innodb.
+SET @old_dbug= @@global.DEBUG_DBUG;
+SET GLOBAL debug_dbug="+d,ib_log_checkpoint_avoid";
+# Couple other settings that reduce redo log flushing, thus potentially
+# triggering the hang.
+SET @old_flush= @@GLOBAL.innodb_flush_log_at_trx_commit;
+SET GLOBAL innodb_flush_log_at_trx_commit= 0;
+SET @old_flush_timeout= @@GLOBAL.innoDB_flush_log_at_timeout;
+SET GLOBAL innoDB_flush_log_at_timeout=2700;
+
+--connection default
+CREATE TABLE t1 (a INT PRIMARY KEY, b INT) ENGINE=InnoDB STATS_PERSISTENT=0;
+INSERT INTO t1 VALUES (1,1);
+INSERT INTO t1 VALUES (2,1);
+INSERT INTO t1 VALUES (3,1);
+
+connect (stop_purge,localhost,root,,);
+# This blocks purge due to old data being still visible.
+START TRANSACTION WITH CONSISTENT SNAPSHOT;
+
+--connection default
+INSERT INTO t1 VALUES (4,2);
+DELETE FROM t1 WHERE a in (1,2,3);
+
+# Rotate the binlog and wait for everything to settle down and latest binlog
+# checkpoint to be done. The small sleep helps trigger the bug more reliably
+# before the fix.
+FLUSH BINARY LOGS;
+--sleep 0.1
+
+# Now unblock the purge, and wait for some purge records to be written
+# to the redo log so the LSN is incremented but will not be synced to
+# disk until something else happens.
+--connection stop_purge
+ROLLBACK;
+--connection default
+--disconnect stop_purge
+
+--sleep 0.1
+
+# Now see if RESET MASTER will request and wait for a binlog checkpoint that is never reported.
+RESET MASTER;
+
+# Clean up.
+--connection default
+DROP TABLE t1;
+SET GLOBAL debug_dbug= @old_dbug;
+SET GLOBAL innodb_flush_log_at_trx_commit= @old_flush;
+SET GLOBAL innoDB_flush_log_at_timeout= @old_flush_timeout;

sql/log.cc

@@ -4435,6 +4435,9 @@ bool MYSQL_BIN_LOG::reset_logs(THD *thd, bool create_new_log,
     mark_xids_active(current_binlog_id, 1);
     do_checkpoint_request(current_binlog_id);
 
+    /* Flush all engine logs to force checkpoint responses to come through. */
+    ha_flush_logs();
+
     /* Now wait for all checkpoint requests and pending unlog() to complete. */
     mysql_mutex_lock(&LOCK_xid_list);
     for (;;)

storage/innobase/handler/ha_innodb.cc

@@ -1583,10 +1583,9 @@ innobase_start_trx_and_assign_read_view(
 @return false */
 static bool innobase_flush_logs(handlerton*)
 {
-  if (!srv_read_only_mode && srv_flush_log_at_trx_commit)
-    /* Write any outstanding redo log. Durably if
-    innodb_flush_log_at_trx_commit=1. */
-    log_buffer_flush_to_disk(srv_flush_log_at_trx_commit == 1);
+  if (!srv_read_only_mode)
+    /* Write and flush any outstanding redo log. */
+    log_buffer_flush_to_disk(true);
   return false;
 }