BUG#56442: Slave executes delayed statements when STOP SLAVE is issued

Problem:
When using the delayed slave feature, and the SQL thread is delaying,
and the user issues STOP SLAVE, the event we wait for was executed.
It should not be executed.
Fix:
Check the return value from the delay function,
slave.cc:slave_sleep(). If the return value is 1, it means the thread
has been stopped, in this case we don't execute the statement.

Also, refactored the test case for delayed slave a little: added the
test script include/rpl_assert.inc, which asserts that a condition holds
and prints a message if not. Made rpl_delayed_slave.test use this. The
advantage is that the test file is much easier to read and maintain,
because it is clear what is an assertion and what is not, and also the
expected result can be found in the test file, you don't have to compare
it to the result file.

Manually merged into MariaDB from MySQL commit
fd2b210383358fe7697f201e19ac9779879ba72a

Signed-off-by: Kristian Nielsen <knielsen@knielsen-hq.org>

mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc

@@ -10,21 +10,32 @@
 # - After one and a half delay, check the status. It should not be
 #   delaying and the query should be executed.
 #
+#
 # ==== Usage ====
 #
+# --let $query_number= 4
 # --source extra/rpl_tests/delayed_slave_wait_on_query.inc
+#
+# Parameters:
+# $query_number
+#   The value of the 'b' column in t1 for the row inserted by the query
+#   we are waiting for.
 
 connection master;
+
 --echo [on slave]
 --let $slave_timeout= $time1
-
 --source include/sync_slave_io_with_master.inc
 --echo # sleep 1*T
 --sleep $time1
 
---echo # Expect query not executed and status is 'Waiting until MASTER_DELAY...'
+--let $assert_text= Query $query_number should not be executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+--let $assert_cond= MAX(b) < $query_number FROM t1
---source include/show_delayed_slave_state.inc
+--source include/rpl_assert.inc
+
+--let $assert_text= Status should be 'Waiting until MASTER_DELAY...'
+--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Waiting until MASTER_DELAY%"
+--source include/rpl_assert.inc
 
 --echo # sleep 1*T
 --sleep $time1
@@ -32,8 +43,13 @@ SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
 --echo # sync with master (with timeout 1*T)
 --source include/sync_with_master.inc
 
---echo # Expect query executed and status is 'Has read all relay log...'
+--let $assert_text= Query $query_number should be executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+--let $assert_cond= MAX(b) = $query_number FROM t1
---source include/show_delayed_slave_state.inc
+--source include/rpl_assert.inc
+
+--let $assert_text= Status should be 'Has read all relay log...'
+--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Slave has read all relay log%"
+--source include/rpl_assert.inc
+
 
 --source include/check_slave_is_running.inc

mysql-test/include/rpl_assert.inc

@@ -0,0 +1,118 @@
+# ==== Purpose ====
+#
+# Check if a condition holds, fail with debug info if not.
+#
+# The condition is parsed before executed. The following constructs
+# are supported:
+#
+#   [SQL STATEMENT, COLUMN, ROW]
+#     The square bracket is replaced by the result from SQL STATEMENT,
+#     in the given COLUMN and ROW.
+#
+#   <1>
+#     This is a shorthand for the result of the first executed square
+#     bracket. <2> is a shorthand for the second executed square
+#     bracket, and so on.
+#
+# ==== Usage ====
+#
+# --let $assert_text= Relay_Log_Pos must be smaller than pos.
+# --let $assert_cond= [SHOW SLAVE STATUS, Relay_Log_Pos, 1] >= $min_pos AND <1> <= $max_pos
+# [--let $assert_quiet= 1]
+# [--let $rpl_debug= 1]
+# --source include/rpl_assert.inc
+#
+# Parameters:
+#
+# $assert_text
+#   Text that describes what is being checked. By default, this text
+#   is written to the query log.
+#
+# $assert_cond
+#   Condition to check.  See above for details about the format.  The
+#   condition will be executed as `SELECT $assert_cond`.  Note: this
+#   condition is parsed using SQL statements, quoted inside single
+#   quotes, so it must not contain single quotes itself (use double
+#   quotes for strings).
+#
+# $assert_quiet
+#   Do not print $assert_text to the query log.
+#
+# $rpl_debug
+#   Print extra debug info.
+
+
+if ($rpl_debug)
+{
+  --echo # debug: assert_text='$assert_text' assert_cond='$assert_cond'
+}
+
+# Sanity-check input
+if (`SELECT "$assert_text" = ""`)
+{
+  --die ERROR IN TEST: the mysqltest variable rpl_test must be set
+}
+
+# Evaluate square brackets in cond.
+--let $_rpl_assert_substmt_number= 1
+--let $_rpl_interpolated_cond= $assert_cond
+--let $_rpl_assert_lbracket= `SELECT LOCATE('[', '$_rpl_interpolated_cond')`
+while ($_rpl_assert_lbracket)
+{
+  # Get position of right bracket
+  --let $_rpl_assert_rbracket= `SELECT LOCATE(']', '$_rpl_interpolated_cond')`
+  if (!$_rpl_assert_rbracket)
+  {
+    --echo BUG IN TEST: Mismatching square brackets in assert_cond: '$assert_cond'
+    --die BUG IN TEST: Mismatching square brackets in $assert_cond
+  }
+  # Get sub-statement and result of it
+  --let $_rpl_assert_substmt= `SELECT SUBSTRING('$_rpl_interpolated_cond', $_rpl_assert_lbracket + 1, $_rpl_assert_rbracket - $_rpl_assert_lbracket - 1)`
+  --let $_rpl_assert_substmt_result= query_get_value($_rpl_assert_substmt)
+  if ($rpl_debug)
+  {
+    --echo # debug: sub-statement='$_rpl_assert_substmt' result='$rpl_assert_result'
+  }
+  # Replace sub-statement by its result
+  --let $_rpl_interpolated_cond= `SELECT REPLACE('$_rpl_interpolated_cond', '[$_rpl_assert_substmt]', '$_rpl_assert_substmt_result')`
+  # Replace result references by result
+  --let $_rpl_interpolated_cond= `SELECT REPLACE('$_rpl_interpolated_cond', '<$_rpl_assert_substmt_number>', '$_rpl_assert_substmt_result')`
+
+  --let $_rpl_assert_lbracket= `SELECT LOCATE('[', '$_rpl_interpolated_cond')`
+
+  --inc $_rpl_assert_substmt_number
+}
+
+if ($rpl_debug)
+{
+  --echo # debug: interpolated_cond='$_rpl_interpolated_cond'
+}
+
+# Execute.
+--let $_rpl_assert_result= `SELECT $_rpl_interpolated_cond`
+
+if ($rpl_debug)
+{
+  --echo # debug: result='$_rpl_assert_result'
+}
+
+# Check.
+if (!$_rpl_assert_result)
+{
+  --echo ######## Test assertion failed: $assert_text ########
+  --echo Dumping debug info:
+  --source include/show_rpl_debug_info.inc
+  --echo Assertion text: '$assert_text'
+  --echo Assertion condition: '$assert_cond'
+  --echo Assertion condition, interpolated: '$_rpl_interpolated_cond'
+  --echo Assertion result: '$_rpl_assert_result'
+  --die Test assertion failed in rpl_assertion.inc
+}
+
+if (!$assert_quiet)
+{
+  --echo # Asserted this: $assert_text
+}
+
+--let $assert_text=
+--let $assert_cond=

mysql-test/suite/rpl/r/rpl_delayed_slave.result

@@ -3,153 +3,146 @@ include/master-slave.inc
 call mtr.add_suppression("Unsafe statement written to the binary log using statement format");
 call mtr.add_suppression("Unsafe statement written to the binary log using statement format");
 [on master]
-CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY);
+CREATE TABLE t1 (a VARCHAR(100), b INT);
+INSERT INTO t1 VALUES ("zero", 0);
 ==== Normal setup ====
 [on slave]
 include/stop_slave.inc
 # CHANGE MASTER TO MASTER_DELAY = 2*T
-# Checking that delay is what we set it to
-# Expect status to be ''
-SELECT STATE FROM INFORMATION_SCHEMA.PROCESSLIST ORDER BY ID DESC LIMIT 1;
-STATE
-
 include/start_slave.inc
+# Asserted this: SHOW SLAVE STATUS should return the same delay that we set with CHANGE MASTER
 [on master]
-INSERT INTO t1(a) VALUES ('normal setup');
+INSERT INTO t1 VALUES ('normal setup', 1);
 [on slave]
 include/sync_slave_io_with_master.inc
 # sleep 1*T
-# Expect query not executed and status is 'Waiting until MASTER_DELAY...'
+# Asserted this: Query 1 should not be executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+# Asserted this: Status should be 'Waiting until MASTER_DELAY...'
-a	b
-Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread
 # sleep 1*T
 # sync with master (with timeout 1*T)
 include/wait_for_slave_param.inc [Relay_Master_Log_File]
 include/wait_for_slave_param.inc [Exec_Master_Log_Pos]
-# Expect query executed and status is 'Has read all relay log...'
+# Asserted this: Query 1 should be executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+# Asserted this: Status should be 'Has read all relay log...'
-a	b
-normal setup	1
-Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread
 include/check_slave_is_running.inc
 ==== Slave lags "naturally" after master ====
 [on master]
 # CREATE FUNCTION delay_on_slave(time_units INT) RETURNS INT BEGIN IF @@GLOBAL.server_id = 2 THEN RETURN SLEEP(time_units * T); ELSE RETURN 0; END IF; END
-INSERT INTO t1(a) SELECT delay_on_slave(3);
+INSERT INTO t1 SELECT delay_on_slave(3), 2;
 Warnings:
 Note	1592	Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave.
 Note	1592	Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave.
-INSERT INTO t1(a) VALUES ('slave is already lagging: this statement should execute immediately');
+INSERT INTO t1 VALUES ('slave is already lagging: this statement should execute immediately', 3);
-INSERT INTO t1(a) SELECT delay_on_slave(2);
+INSERT INTO t1 SELECT delay_on_slave(2), 4;
 Warnings:
 Note	1592	Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave.
 Note	1592	Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave.
 [on slave]
 include/sync_slave_io_with_master.inc
 # sleep 1*T
-# Expect no query executed and status is 'Waiting until MASTER_DELAY...'
+# Asserted this: No query executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+# Asserted this: Status should be 'Waiting until MASTER_DELAY...'
-a	b
-normal setup	1
-Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread
 # wait for first query to execute
 # sleep 1*T
-# Expect second query executed and status is executing third query (i.e., 'User sleep')
+# Asserted this: Second query executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+# Asserted this: Status should be executing third query (i.e., 'User sleep')
-a	b
-slave is already lagging: this statement should execute immediately	3
-Slave_SQL_Running_State='User sleep'; SQL_Remaining_Delay is NULL; SQL thread is behind IO thread
 # sleep 2*T
-# Expect query executed and status is 'Has read all relay log...'
+# Asserted this: Third query executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+# Asserted this: Status should be 'Has read all relay log...'
-a	b
-0	4
-Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread
 ==== Seconds_Behind_Master ====
 # Bring slave to sync.
 include/stop_slave.inc
 CHANGE MASTER TO MASTER_DELAY = 0;
 include/start_slave.inc
-INSERT INTO t1(a) VALUES ('Syncing slave');
+INSERT INTO t1 VALUES ('Syncing slave', 5);
 include/stop_slave.inc
 # CHANGE MASTER TO MASTER_DELAY = 2*T
 include/start_slave.inc
-INSERT INTO t1(a) VALUES (delay_on_slave(1));
+INSERT INTO t1 VALUES (delay_on_slave(1), 6);
 Warnings:
 Note	1592	Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave.
 Note	1592	Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave.
 # sleep 1*T
+# Asserted this: Seconds_Behind_Master should be between 0 and the 2*T
 # sleep 1*T
-==== STOP SLAVE and START SLAVE ====
+# Asserted this: Seconds_Behind_Master should be at least 2*T
+==== STOP SLAVE / START SLAVE + DML ====
 include/stop_slave.inc
 # CHANGE MASTER TO MASTER_DELAY = 3*T
 include/start_slave.inc
-# Checking that delay is what we set it to
 [on master]
-INSERT INTO t1(a) VALUES ('stop slave and start slave');
+INSERT INTO t1 VALUES ('stop slave and start slave: DML', 7);
 [on slave]
 # sleep 1*T
-SET @before_stop_slave= UNIX_TIMESTAMP();
 include/stop_slave.inc
-# STOP SLAVE finished in time.
+# Asserted this: STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish
-# Expect query not executed and status is ''
+# Asserted this: SQL thread position should not increase after STOP SLAVE
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+# Asserted this: Query should not be executed after STOP SLAVE
-a	b
+# Asserted this: Status should be '' after STOP SLAVE
-0	6
-Slave_SQL_Running_State=''; SQL_Remaining_Delay is NULL; SQL thread is behind IO thread
 include/start_slave.inc
-# START SLAVE finished in time.
+# Asserted this: START SLAVE should finish quickly
 [on slave]
 include/sync_slave_io_with_master.inc
 # sleep 1*T
-# Expect query not executed and status is 'Waiting until MASTER_DELAY...'
+# Asserted this: Query 7 should not be executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+# Asserted this: Status should be 'Waiting until MASTER_DELAY...'
-a	b
-0	6
-Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread
 # sleep 1*T
 # sync with master (with timeout 1*T)
 include/wait_for_slave_param.inc [Relay_Master_Log_File]
 include/wait_for_slave_param.inc [Exec_Master_Log_Pos]
-# Expect query executed and status is 'Has read all relay log...'
+# Asserted this: Query 7 should be executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+# Asserted this: Status should be 'Has read all relay log...'
-a	b
+include/check_slave_is_running.inc
-stop slave and start slave	7
+==== STOP SLAVE / START SLAVE + DDL ====
-Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread
+This verifies BUG#56442
+[on master]
+CREATE TABLE t_check_dml_not_executed_prematurely (a INT);
+include/save_master_pos.inc
+[on slave]
+# sleep 1*T
+include/stop_slave.inc
+# Asserted this: STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish
+# Asserted this: SQL thread position should not increase after STOP SLAVE
+# Asserted this: Query should not be executed after STOP SLAVE
+# Asserted this: Status should be '' after STOP SLAVE
+include/start_slave.inc
+# Asserted this: START SLAVE should finish quickly
+# sleep 1*T
+# Asserted this: DDL Query should not be executed after START SLAVE
+# Asserted this: Status should be 'Waiting until MASTER_DELAY...'
+# sleep 1*T
+# sync with master (with timeout 1*T)
+include/wait_for_slave_param.inc [Relay_Master_Log_File]
+include/wait_for_slave_param.inc [Exec_Master_Log_Pos]
+# Asserted this: DDL Query should be executed
+# Asserted this: Status should be 'Has read all relay log...'
 include/check_slave_is_running.inc
 ==== Change back to no delay ====
 [on slave]
 include/stop_slave.inc
 CHANGE MASTER TO MASTER_DELAY = 0;
-# Expect delay is 0.
+# Asserted this: Delay should be 0 when we set it to 0
-SQL_Delay='0'
 include/start_slave.inc
 [on master]
-INSERT INTO t1(a) VALUES ('change back to no delay');
+INSERT INTO t1 VALUES ('change back to no delay', 8);
 [on slave]
 include/sync_slave_io_with_master.inc
 # sleep 1*T
-# Expect query executed and status is 'Has read all relay log...'
+# Asserted this: Query should be executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+# Asserted this: Status should be 'Slave has read all relay log...'
-a	b
-change back to no delay	8
-Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread
 ==== Reset delay with RESET SLAVE ====
 include/stop_slave.inc
 CHANGE MASTER TO MASTER_DELAY = 71;
 include/start_slave.inc
-# Expect delay is 71
+# Asserted this: Delay should be 71 when we set it to 71
-SQL_Delay='71'
 include/stop_slave.inc
 RESET SLAVE;
 [on master]
 RESET MASTER;
 [on slave]
 include/start_slave.inc
-# Expect delay is 0
+# Asserted this: Delay should be 0 after RESET SLAVE
-SQL_Delay='0'
+==== Set an invalid value for the delay ====
-==== Set a bad value for the delay ====
 include/stop_slave.inc
 # Expect error for setting negative delay
 CHANGE MASTER TO MASTER_DELAY = -1;
@@ -166,7 +159,7 @@ CHANGE MASTER TO MASTER_DELAY = 0;
 include/start_slave.inc
 ==== Clean up ====
 [on master]
-DROP TABLE t1;
+DROP TABLE t1, t_check_dml_not_executed_prematurely;
 DROP FUNCTION delay_on_slave;
 [on slave]
 include/rpl_end.inc

mysql-test/suite/rpl/t/rpl_delayed_slave.test

@@ -6,7 +6,7 @@
 #  - Verify that slave has executed the events after but not before the
 #    delay timeout.
 #
-#  - Verify that delay is correct works when slave is already lagging
+#  - Verify that delay is correct when slave is already lagging
 #    due to slow queries.
 #
 #  - Verify that Seconds_Behind_Master is greater than or equal to the
@@ -44,6 +44,7 @@
 # BUG#28760: Simulating a replication lag
 # [duplicate] BUG#22072: configurable delayed replication
 # [duplicate] BUG#21639: Add Replication Delay parameter
+# BUG#56442: Slave executes delayed statements when STOP SLAVE is issued
 #
 # ==== Issues with this Test Case ====
 #
@@ -79,7 +80,8 @@ if (`SELECT '$max_query_execution_time' > 0`) {
 
 
 --echo [on master]
-CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY);
+CREATE TABLE t1 (a VARCHAR(100), b INT);
+INSERT INTO t1 VALUES ("zero", 0);
 
 
 --echo ==== Normal setup ====
@@ -94,23 +96,17 @@ CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY);
 eval CHANGE MASTER TO MASTER_DELAY = $time2;
 --enable_query_log
 
---echo # Checking that delay is what we set it to
---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1)
-if (`SELECT $delay != $time2`) {
-  --echo Delay is wrong! Expected $time2, got $delay
-  --source include/show_rpl_debug_info.inc
-  --die wrong delay
-}
-
---echo # Expect status to be ''
-SELECT STATE FROM INFORMATION_SCHEMA.PROCESSLIST ORDER BY ID DESC LIMIT 1;
-
 --source include/start_slave.inc
 
+--let $assert_text= SHOW SLAVE STATUS should return the same delay that we set with CHANGE MASTER
+--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = $time2
+--source include/rpl_assert.inc
+
 --echo [on master]
 --connection master
-INSERT INTO t1(a) VALUES ('normal setup');
+INSERT INTO t1 VALUES ('normal setup', 1);
 
+--let $query_number= 1
 --source extra/rpl_tests/delayed_slave_wait_on_query.inc
 
 
@@ -124,20 +120,24 @@ INSERT INTO t1(a) VALUES ('normal setup');
 --eval CREATE FUNCTION delay_on_slave(time_units INT) RETURNS INT BEGIN IF @@GLOBAL.server_id = 2 THEN RETURN SLEEP(time_units * $time1); ELSE RETURN 0; END IF; END
 --enable_query_log
 
-INSERT INTO t1(a) SELECT delay_on_slave(3);
+INSERT INTO t1 SELECT delay_on_slave(3), 2;
 
 --save_master_pos
-INSERT INTO t1(a) VALUES ('slave is already lagging: this statement should execute immediately');
+INSERT INTO t1 VALUES ('slave is already lagging: this statement should execute immediately', 3);
-INSERT INTO t1(a) SELECT delay_on_slave(2);
+INSERT INTO t1 SELECT delay_on_slave(2), 4;
 
 --echo [on slave]
 --source include/sync_slave_io_with_master.inc
 --echo # sleep 1*T
 --sleep $time1
 
---echo # Expect no query executed and status is 'Waiting until MASTER_DELAY...'
+--let $assert_text= No query executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+--let $assert_cond= MAX(b) = 1 FROM t1
---source include/show_delayed_slave_state.inc
+--source include/rpl_assert.inc
+
+--let $assert_text= Status should be 'Waiting until MASTER_DELAY...'
+--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Waiting until MASTER_DELAY%"
+--source include/rpl_assert.inc
 
 --echo # wait for first query to execute
 --sync_with_master
@@ -145,27 +145,35 @@ SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
 --echo # sleep 1*T
 --sleep $time1
 
---echo # Expect second query executed and status is executing third query (i.e., 'User sleep')
+--let $assert_text= Second query executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+--let $assert_cond= MAX(b) = 3 FROM t1
---source include/show_delayed_slave_state.inc
+--source include/rpl_assert.inc
+
+--let $assert_text= Status should be executing third query (i.e., 'User sleep')
+--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = "User sleep"
+--source include/rpl_assert.inc
 
 --echo # sleep 2*T
 --sleep $time2
 
---echo # Expect query executed and status is 'Has read all relay log...'
+--let $assert_text= Third query executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+--let $assert_cond= MAX(b) = 4 FROM t1
---source include/show_delayed_slave_state.inc
+--source include/rpl_assert.inc
+
+--let $assert_text= Status should be 'Has read all relay log...'
+--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Slave has read all relay log%"
+--source include/rpl_assert.inc
 
 
 --echo ==== Seconds_Behind_Master ====
 
 --echo # Bring slave to sync.
 --source include/stop_slave.inc
-eval CHANGE MASTER TO MASTER_DELAY = 0;
+CHANGE MASTER TO MASTER_DELAY = 0;
 --source include/start_slave.inc
 
 --connection master
-INSERT INTO t1(a) VALUES ('Syncing slave');
+INSERT INTO t1 VALUES ('Syncing slave', 5);
 --sync_slave_with_master
 
 --source include/stop_slave.inc
@@ -176,38 +184,28 @@ eval CHANGE MASTER TO MASTER_DELAY = $time2;
 --source include/start_slave.inc
 
 --connection master
-INSERT INTO t1(a) VALUES (delay_on_slave(1));
+INSERT INTO t1 VALUES (delay_on_slave(1), 6);
 --save_master_pos
 --connection slave
 
 --echo # sleep 1*T
 --sleep $time1
 
-if ($bug_53167_is_fixed) {
+--let $assert_cond= [SHOW SLAVE STATUS, Seconds_Behind_Master, 1] >= 0 AND <1> < $time2
-
+--let $assert_text= Seconds_Behind_Master should be between 0 and the 2*T
---let $seconds_behind_master= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
+--source include/rpl_assert.inc
-if (`SELECT $seconds_behind_master <= 0 OR $seconds_behind_master >= $time2`) {
-  --echo Seconds_Behind_Master was $seconds_behind_master. Expected that 0 < Seconds_Behind_Master < SQL_Delay = $time2
-  --source include/show_rpl_debug_info.inc
-  --die Seconds_Behind_Master was wrong
-}
-
-}
 
 --echo # sleep 1*T
 --sleep $time1
 
---let $seconds_behind_master= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
+--let $assert_cond= [SHOW SLAVE STATUS, Seconds_Behind_Master, 1] >= $time2
-if (`SELECT $seconds_behind_master < $time2`) {
+--let $assert_text= Seconds_Behind_Master should be at least 2*T
-  --echo Seconds_Behind_Master was $seconds_behind_master. Expected it to be >= SQL_Delay = $time2
+--source include/rpl_assert.inc
-  --source include/show_rpl_debug_info.inc
-  --die Seconds_Behind_Master was < SQL_Delay
-}
 
 --sync_with_master
 
 
---echo ==== STOP SLAVE and START SLAVE ====
+--echo ==== STOP SLAVE / START SLAVE + DML ====
 
 # Set up a longer delay.
 --source include/stop_slave.inc
@@ -219,71 +217,141 @@ eval CHANGE MASTER TO MASTER_DELAY = $time3;
 
 --source include/start_slave.inc
 
---echo # Checking that delay is what we set it to
---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1)
-if (`SELECT $delay != $time3`) {
-  --echo Delay is wrong! Expected $time2, got $delay
-  --source include/show_rpl_debug_info.inc
-  --die wrong delay
-}
-
 --echo [on master]
 --connection master
-INSERT INTO t1(a) VALUES ('stop slave and start slave');
+INSERT INTO t1 VALUES ('stop slave and start slave: DML', 7);
 
 --echo [on slave]
 --connection slave
 --echo # sleep 1*T
 --sleep $time1
-SET @before_stop_slave= UNIX_TIMESTAMP();
+--let $timestamp_before_stop= `SELECT UNIX_TIMESTAMP()`
+--let $relay_log_pos_before_stop= query_get_value(SHOW SLAVE STATUS, Relay_Log_Pos, 1)
 --source include/stop_slave.inc
-if (`SELECT UNIX_TIMESTAMP() - @before_stop_slave >= $time1`)
-{
-  --source include/show_rpl_debug_info.inc
-  --die STOP SLAVE did not finish in time
-}
---echo # STOP SLAVE finished in time.
 
---echo # Expect query not executed and status is ''
+--let $assert_text= STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1
---source include/show_delayed_slave_state.inc
+--source include/rpl_assert.inc
+
+--let $assert_text= SQL thread position should not increase after STOP SLAVE
+--let $assert_cond= [SHOW SLAVE STATUS, Relay_Log_Pos, 1] = $relay_log_pos_before_stop
+--source include/rpl_assert.inc
+
+--let $assert_text= Query should not be executed after STOP SLAVE
+--let $assert_cond= MAX(b) = 6 FROM t1
+--source include/rpl_assert.inc
+
+--let $assert_text= Status should be '' after STOP SLAVE
+--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = ""
+--source include/rpl_assert.inc
 
 --source include/start_slave.inc
-if (`SELECT UNIX_TIMESTAMP() - @before_stop_slave >= $time1`)
-{
-  --source include/show_rpl_debug_info.inc
-  --die START SLAVE did not finish in time
-}
---echo # START SLAVE finished in time.
 
+--let $assert_text= START SLAVE should finish quickly
+--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1
+--source include/rpl_assert.inc
+
+--let $query_number= 7
 --source extra/rpl_tests/delayed_slave_wait_on_query.inc
 
 
+--echo ==== STOP SLAVE / START SLAVE + DDL ====
+
+--echo This verifies BUG#56442
+
+--echo [on master]
+--connection master
+CREATE TABLE t_check_dml_not_executed_prematurely (a INT);
+--source include/save_master_pos.inc
+
+--echo [on slave]
+--connection slave
+--echo # sleep 1*T
+--sleep $time1
+
+--let $timestamp_before_stop= `SELECT UNIX_TIMESTAMP()`
+--let $relay_log_pos_before_stop= query_get_value(SHOW SLAVE STATUS, Relay_Log_Pos, 1)
+--source include/stop_slave.inc
+
+--let $assert_text= STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish
+--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1
+--source include/rpl_assert.inc
+
+--let $assert_text= SQL thread position should not increase after STOP SLAVE
+--let $assert_cond= [SHOW SLAVE STATUS, Relay_Log_Pos, 1] = $relay_log_pos_before_stop
+--source include/rpl_assert.inc
+
+--let $assert_text= Query should not be executed after STOP SLAVE
+--let $assert_cond= COUNT(*) = 0 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_NAME = "t_check_dml_not_executed_prematurely"
+--source include/rpl_assert.inc
+
+--let $assert_text= Status should be '' after STOP SLAVE
+--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = ""
+--source include/rpl_assert.inc
+
+--source include/start_slave.inc
+
+--let $assert_text= START SLAVE should finish quickly
+--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1
+--source include/rpl_assert.inc
+
+--echo # sleep 1*T
+--sleep $time1
+
+--let $assert_text= DDL Query should not be executed after START SLAVE
+--let $assert_cond= COUNT(*) = 0 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_NAME = "t_check_dml_not_executed_prematurely"
+--source include/rpl_assert.inc
+
+--let $assert_text= Status should be 'Waiting until MASTER_DELAY...'
+--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Waiting until MASTER_DELAY%"
+--source include/rpl_assert.inc
+
+--echo # sleep 1*T
+--sleep $time1
+
+--echo # sync with master (with timeout 1*T)
+--source include/sync_with_master.inc
+
+--let $assert_text= DDL Query should be executed
+--let $assert_cond= COUNT(*) = 1 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_NAME = "t_check_dml_not_executed_prematurely"
+--source include/rpl_assert.inc
+
+--let $assert_text= Status should be 'Has read all relay log...'
+--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Slave has read all relay log%"
+--source include/rpl_assert.inc
+
+--source include/check_slave_is_running.inc
+
+
 --echo ==== Change back to no delay ====
 
 --echo [on slave]
 --connection slave
 --source include/stop_slave.inc
-eval CHANGE MASTER TO MASTER_DELAY = 0;
+CHANGE MASTER TO MASTER_DELAY = 0;
 
---echo # Expect delay is 0.
+--let $assert_text= Delay should be 0 when we set it to 0
---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1)
+--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = 0
---echo SQL_Delay='$delay'
+--source include/rpl_assert.inc
 
 --source include/start_slave.inc
 
 --echo [on master]
 --connection master
-INSERT INTO t1(a) VALUES ('change back to no delay');
+INSERT INTO t1 VALUES ('change back to no delay', 8);
 
 --echo [on slave]
 --source include/sync_slave_io_with_master.inc
 --echo # sleep 1*T
 --sleep $time1
 
---echo # Expect query executed and status is 'Has read all relay log...'
+--let $assert_text= Query should be executed
-SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
+--let $assert_cond= MAX(b) = 8 FROM t1
---source include/show_delayed_slave_state.inc
+--source include/rpl_assert.inc
+
+--let $assert_text= Status should be 'Slave has read all relay log...'
+--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" Like "Slave has read all relay log%"
+--source include/rpl_assert.inc
 
 
 --echo ==== Reset delay with RESET SLAVE ====
@@ -292,9 +360,9 @@ SELECT * FROM t1 ORDER BY b DESC LIMIT 1;
 CHANGE MASTER TO MASTER_DELAY = 71;
 --source include/start_slave.inc
 
---echo # Expect delay is 71
+--let $assert_text= Delay should be 71 when we set it to 71
---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1)
+--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = 71
---echo SQL_Delay='$delay'
+--source include/rpl_assert.inc
 
 --source include/stop_slave.inc
 RESET SLAVE;
@@ -305,12 +373,12 @@ RESET MASTER;
 --connection slave
 --source include/start_slave.inc
 
---echo # Expect delay is 0
+--let $assert_text= Delay should be 0 after RESET SLAVE
---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1)
+--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = 0
---echo SQL_Delay='$delay'
+--source include/rpl_assert.inc
 
 
---echo ==== Set a bad value for the delay ====
+--echo ==== Set an invalid value for the delay ====
 
 --source include/stop_slave.inc
 
@@ -339,7 +407,7 @@ CHANGE MASTER TO MASTER_DELAY = 0;
 
 --echo [on master]
 --connection master
-DROP TABLE t1;
+DROP TABLE t1, t_check_dml_not_executed_prematurely;
 DROP FUNCTION delay_on_slave;
 
 --echo [on slave]

sql/slave.cc

@@ -3410,17 +3410,21 @@ has_temporary_error(THD *thd)
 /**
   If this is a lagging slave (specified with CHANGE MASTER TO MASTER_DELAY = X), delays accordingly. Also unlocks rli->data_lock.
 
-  Design note: this is the place to unlock rli->data_lock here since
+  Design note: this is the place to unlock rli->data_lock. The lock
-  it should be held when reading delay info from rli, but it should
+  must be held when reading delay info from rli, but it should not be
-  not be held while sleeping.
+  held while sleeping.
 
   @param ev Event that is about to be executed.
 
   @param thd The sql thread's THD object.
 
   @param rli The sql thread's Relay_log_info structure.
+
+  @retval 0 If the delay timed out and the event shall be executed.
+
+  @retval nonzero If the delay was interrupted and the event shall be skipped.
 */
-static void sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi)
+static int sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi)
 {
   Relay_log_info* rli= rgi->rli;
   long sql_delay= rli->get_sql_delay();
@@ -3459,14 +3463,13 @@ static void sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi)
                           nap_time));
       rli->start_sql_delay(sql_delay_end);
       mysql_mutex_unlock(&rli->data_lock);
-      slave_sleep(thd, nap_time, sql_slave_killed, rgi);
+      DBUG_RETURN(slave_sleep(thd, nap_time, sql_slave_killed, rgi));
-      DBUG_VOID_RETURN;
     }
   }
 
   mysql_mutex_unlock(&rli->data_lock);
 
-  DBUG_VOID_RETURN;
+  DBUG_RETURN(0);
 }
 
 
@@ -3696,7 +3699,8 @@ apply_event_and_update_pos(Log_event* ev, THD* thd, rpl_group_info *rgi)
   if (reason == Log_event::EVENT_SKIP_NOT)
   {
     // Sleeps if needed, and unlocks rli->data_lock.
-    sql_delay_event(ev, thd, rgi);
+    if (sql_delay_event(ev, thd, rgi))
+      return 0;
   }
   else
     mysql_mutex_unlock(&rli->data_lock);