mariadb/mysql-test/suite/binlog/t/binlog_checkpoint.test
Brandon Nesterenko 812443c251 MDEV-29607: binlog.binlog_checkpoint fails in buildbot with result content mismatch
Problem:
========
There is a race condition in binlog.binlog_checkpoint between the
binlog background thread creating a binlog checkpoint event, and the
connection thread binlogging a query event for creating a table.
Because the test outputs the events for validation, the order
between these two events can be different, resulting in a failed
test.

Solution:
========
Instead of outputting the binlog events, use assert_grep to validate
the content of the binlog is correct.

Reviewed By:
============
Andrei Elkin <andrei.elkin@mariadb.com>
2022-11-25 12:45:35 -07:00

236 lines
8.1 KiB
Text

--source include/have_innodb.inc
--source include/have_debug.inc
--source include/have_debug_sync.inc
--source include/have_binlog_format_row.inc
SET @old_max_binlog_size= @@global.max_binlog_size;
SET GLOBAL max_binlog_size= 4096;
SET @old_innodb_flush_log_at_trx_commit= @@global.innodb_flush_log_at_trx_commit;
SET GLOBAL innodb_flush_log_at_trx_commit= 1;
RESET MASTER;
CREATE TABLE t1 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb;
CREATE TABLE t2 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Myisam;
--echo *** Test that RESET MASTER waits for pending commit checkpoints to complete.
# con1 will hang before doing commit checkpoint, blocking RESET MASTER.
connect(con1,localhost,root,,);
SET DEBUG_SYNC= "commit_after_group_release_commit_ordered SIGNAL con1_ready WAIT_FOR con1_go";
send INSERT INTO t1 VALUES (1, REPEAT("x", 4100));
connection default;
SET DEBUG_SYNC= "now WAIT_FOR con1_ready";
# Let's add a few binlog rotations just for good measure.
INSERT INTO t2 VALUES (1, REPEAT("x", 4100));
INSERT INTO t2 VALUES (2, REPEAT("x", 4100));
--source include/show_binary_logs.inc
--let $binlog_file= master-bin.000004
--let $binlog_start= 4
--source include/show_binlog_events.inc
SET DEBUG_SYNC= "execute_command_after_close_tables SIGNAL reset_master_done";
send RESET MASTER;
connect(con2,localhost,root,,);
--echo This will timeout, as RESET MASTER is blocked
SET DEBUG_SYNC= "now WAIT_FOR reset_master_done TIMEOUT 1";
# Wake up transaction to allow RESET MASTER to complete.
SET DEBUG_SYNC= "now SIGNAL con1_go";
connection con1;
reap;
connection default;
reap;
--source include/show_binary_logs.inc
--let $binlog_file= master-bin.000001
--let $binlog_start= 4
--source include/show_binlog_events.inc
--echo *** Test that binlog N is active, and commit checkpoint for (N-1) is
--echo *** done while there is still a pending commit checkpoint for (N-2).
connection con1;
SET DEBUG_SYNC= "commit_after_group_release_commit_ordered SIGNAL con1_ready WAIT_FOR con1_continue";
send INSERT INTO t1 VALUES (20, REPEAT("x", 4100));
connection default;
SET DEBUG_SYNC= "now WAIT_FOR con1_ready";
connection con2;
SET DEBUG_SYNC= "commit_after_group_release_commit_ordered SIGNAL con2_ready WAIT_FOR con2_continue";
send INSERT INTO t1 VALUES (21, REPEAT("x", 4100));
connection default;
SET DEBUG_SYNC= "now WAIT_FOR con2_ready";
--source include/show_binary_logs.inc
--let $binlog_file= master-bin.000001
--source include/show_binlog_events.inc
--let $binlog_file= master-bin.000002
--source include/show_binlog_events.inc
--let $binlog_file= master-bin.000003
--source include/show_binlog_events.inc
# We need to sync the test case with the background processing of the
# commit checkpoint, otherwise we get nondeterministic results.
SET DEBUG_SYNC= "RESET";
SET @old_dbug= @@global.DEBUG_DBUG;
SET GLOBAL debug_dbug="+d,binlog_background_checkpoint_processed";
SET DEBUG_SYNC= "now SIGNAL con2_continue";
connection con2;
reap;
connection default;
--echo con1 is still pending, no new binlog checkpoint should have been logged.
# Make sure commit checkpoint is processed before we check that no checkpoint
# event has been binlogged.
SET DEBUG_SYNC= "now WAIT_FOR binlog_background_checkpoint_processed";
SET GLOBAL debug_dbug= @old_dbug;
SET DEBUG_SYNC= "RESET";
--let $binlog_file= master-bin.000003
--source include/show_binlog_events.inc
SET DEBUG_SYNC= "now SIGNAL con1_continue";
connection con1;
reap;
connection default;
--echo No commit checkpoints are pending, a new binlog checkpoint should have been logged.
--let $binlog_file= master-bin.000003
# Wait for the master-bin.000003 binlog checkpoint to appear.
--let $wait_for_all= 0
--let $show_statement= SHOW BINLOG EVENTS IN "$binlog_file"
--let $field= Info
--let $condition= = "master-bin.000003"
--source include/wait_show_condition.inc
--source include/show_binlog_events.inc
--echo *** MDEV-4322: Broken XID counting during binlog rotation ***
# Test that binlog shutdown waits for any pending binlog checkpoints to have time to complete.
connection default;
# We will use debug_sync to setup a wait inside the background processing
# of binlog checkpoints. The wait is newer resumed, and will eventually
# time out. If server shutdown does not wait for checkpoint processing to
# complete, we will get an assert.
#
# It is a bit tricky to inject the wait properly as it has to happen in a
# background thread during shutdown. So we first inject a DBUG to set the
# debug_sync wait in the correct thread, then wait to be signalled that
# the inject happened so that we can remove it again from DBUG (else
# check_testcase will complain).
SET @old_dbug= @@global.DEBUG_DBUG;
SET GLOBAL debug_dbug="+d,inject_binlog_background_thread_before_mark_xid_done";
FLUSH LOGS;
INSERT INTO t1 VALUES (30, REPEAT("x", 4100));
SET DEBUG_SYNC= "now WAIT_FOR injected_binlog_background_thread";
SET GLOBAL debug_dbug= @old_dbug;
INSERT INTO t1 VALUES (31, REPEAT("x", 4100));
--source include/show_binary_logs.inc
SET debug_sync = 'reset';
SET GLOBAL max_binlog_size= @old_max_binlog_size;
SET GLOBAL innodb_flush_log_at_trx_commit= @old_innodb_flush_log_at_trx_commit;
--source include/shutdown_mysqld.inc
--source include/start_mysqld.inc
--echo *** MDEV-7402: 'reset master' hangs, waits for signalled COND_xid_list ***
connect(con3,localhost,root,,);
# Make the binlog background thread wait before clearing the pending checkpoint.
# The bug was that one RESET MASTER would clear the reset_master_pending
# flag set by another RESET MASTER; this could cause the wakeup from the
# binlog background thread not to be sent, and thus the second RESET MASTER
# to wait infinitely.
SET debug_sync="reset_logs_after_set_reset_master_pending SIGNAL reset_master_ready WAIT_FOR reset_master_cont";
send RESET MASTER;
--connection default
SET @old_dbug= @@global.DEBUG_DBUG;
SET GLOBAL debug_dbug="+d,inject_binlog_background_thread_before_mark_xid_done";
SET debug_sync="now WAIT_FOR reset_master_ready";
RESET MASTER;
SET debug_sync="now WAIT_FOR injected_binlog_background_thread";
SET GLOBAL debug_dbug=@old_dbug;
SET debug_sync="now SIGNAL reset_master_cont";
--connection con3
REAP;
--connection default
SET debug_sync = 'reset';
--echo *** MDEV-24660: MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed in MYSQL_BIN_LOG::cleanup
# Test a scenario of forcibly rolled back mixed engine "unsafe" transaction
# at shutdown. That should not let to the assert.
SET @old_max_binlog_size= @@global.max_binlog_size;
SET GLOBAL max_binlog_size= 4096;
--connect(con_24660,localhost,root,,)
# Construct an unsafe xa transaction that is rolled back
# in binlog at the shutdown time. That requires STATEMENT binlog format.
FLUSH LOGS;
--let $binlog_file = query_get_value(SHOW MASTER STATUS, File, 1)
SET @@session.binlog_format = STATEMENT;
CREATE TABLE tm (a INT) ENGINE = myisam;
call mtr.add_suppression("Table './test/tm' is marked as crashed");
call mtr.add_suppression("Checking table");
XA START 'xa1';
--let $a = `SELECT a + 1 FROM t1`
--eval INSERT INTO t1 VALUES ($a, 1)
INSERT INTO tm SET a = 1;
--inc $a
--let $repeat_x = `SELECT REPEAT("x", 4100)`
--disable_query_log
--eval INSERT INTO t1 VALUES ($a, "$repeat_x")
--enable_query_log
XA END 'xa1';
--connection default
# In the patch's base BBT would exit first to win the race against
# the XA transaction's binloging.
SET GLOBAL debug_dbug="+d,only_kill_system_threads_no_loop";
--source include/shutdown_mysqld.inc
--source include/start_mysqld.inc
--echo ** Proof of shutdown caused ROLLBACK-completed transaction
--let assert_file=$MYSQLTEST_VARDIR/tmp/binlog_decoded.out
--let datadir=`select @@datadir`
--echo # MYSQL_BINLOG datadir/binlog_file --result-file=assert_file
--exec $MYSQL_BINLOG $datadir/$binlog_file --result-file=$assert_file
--let $assert_text= No XA statements should be written into the binary log
--let $assert_count= 0
--let assert_select= XA START|XA END|XA PREPARE|XA COMMIT|XA ROLLBACK
--source include/assert_grep.inc
--let $assert_text= The transaction should be rolled back
--let $assert_count= 1
--let assert_select= ^ROLLBACK\$
--source include/assert_grep.inc
SELECT * FROM tm;
--eval SELECT * FROM t1 WHERE a = $a
# Clean up.
DROP TABLE t1, t2, tm;