From 5563202089e78855ad9295a3526a70e766d8a42d Mon Sep 17 00:00:00 2001 From: Andrei Date: Tue, 30 Aug 2022 00:26:20 +0300 Subject: [PATCH 1/3] MDEV-29322 ASAN heap-use-after-free in Query_log_event::do_apply_event The ASAN report was made in the parallel slave execution of a query event and implicitly involved (so also parallelly run) Format-Description event. The Query actually had unexpected impossible dependency on a preceding "old" FD whose instance got destructed, to cause the ASAN error. The case is fixed with storing the FD's value into Query-log-event at its instantiating on slave. The stored value is from the very FD of the Query's original binlog so remains to be correct at the query event applying. The branch C. of a new rpl_parallel_29322.test also demonstrates (may need few --repeat though) the bug in its simple form of the same server version binlog. --- .../suite/rpl/include/rpl_parallel_29322.inc | 111 ++++++++ .../suite/rpl/r/rpl_parallel_29322.result | 238 ++++++++++++++++++ .../suite/rpl/t/rpl_parallel_29322.test | 64 +++++ sql/log_event.cc | 2 +- sql/log_event.h | 2 +- sql/log_event_server.cc | 7 +- 6 files changed, 416 insertions(+), 8 deletions(-) create mode 100644 mysql-test/suite/rpl/include/rpl_parallel_29322.inc create mode 100644 mysql-test/suite/rpl/r/rpl_parallel_29322.result create mode 100644 mysql-test/suite/rpl/t/rpl_parallel_29322.test diff --git a/mysql-test/suite/rpl/include/rpl_parallel_29322.inc b/mysql-test/suite/rpl/include/rpl_parallel_29322.inc new file mode 100644 index 00000000000..54eb13d7f09 --- /dev/null +++ b/mysql-test/suite/rpl/include/rpl_parallel_29322.inc @@ -0,0 +1,111 @@ +# A "body" for rpl.rpl_parallel_29322 that runs having as input +# the master and slave @@global.explicit_defaults_for_timestamp. +# +# The Key notes +# ------------- +# On master: a sequence of binlog files is composed with +# different server versions. +# On slave: to first try enqueuing all master events. +# Due to binlog files are from different version +# servers when the new (of binlog 2) FD shows up the enqueuing +# will hiccup as workers have to +# process all events already scheduled (see wait_condition below). +# This part proves of the different server version the binlogs +# indeed are. +# After the worker is unblocked the exection proceeds. +# +# In the end compare table definitions and print table data +# to prove correctness. + +--connection slave +--source include/stop_slave.inc +reset slave; + +--connection master +--let $datadir= `SELECT @@datadir` + +reset master; # Master starts a new serious of binlog files + +create table t2 (a timestamp, b int); +show create table t2; +--save_master_pos + +--connection slave +--source include/start_slave.inc +--sync_with_master +--source include/stop_slave.inc + +# load for two $same_version_binlogs branches +--connection master +if (!$same_version_binlogs) +{ + insert into t2 values (null, 1); + flush binary logs; + flush binary logs; + insert into t2 values (null, 2); +} +if ($same_version_binlogs) +{ +--disable_query_log + --let $count=8 + while ($count) + { + --let $queries=4 + while ($queries) + { + insert into t2 values (null, 1); + --dec $queries + } + flush binary logs; + flush binary logs; + --dec $count + } +--enable_query_log +} +--save_master_pos + +if (!$same_version_binlogs) +{ + --move_file $datadir/master-bin.000002 $datadir/master-bin.000002.sav + --copy_file $MYSQL_TEST_DIR/std_data/mdev29078-mysql-bin.000001 $datadir/master-bin.000002 + --exec $MYSQL_BINLOG --short-form $datadir/master-bin.000002 + + # To demonstrate different version binlogs, hold back worker + # until the SQL thread state shows waiting. + --connection slave1 + lock table t2 write; +} + +--connection slave +--source include/start_slave.inc + +if (!$same_version_binlogs) +{ + --let $slave_waits_for=Waiting for worker threads to be idle + --let $wait_condition= SELECT COUNT(*) > 0 FROM information_schema.processlist WHERE state = "$slave_waits_for" + --source include/wait_condition.inc + + --connection slave1 + unlock tables; + + --connection slave + --sync_with_master + show create table t1; + set statement time_zone='+2:00' for select * from t1; + drop table t1; + + --connection master + --remove_file $datadir/master-bin.000002 + --move_file $datadir/master-bin.000002.sav $datadir/master-bin.000002 +} + +--connection slave +--sync_with_master +show create table t2; +--let $diff_tables=master:t2,slave:t2 +--source include/diff_tables.inc + +--connection master +drop table t2; + +--sync_slave_with_master diff --git a/mysql-test/suite/rpl/r/rpl_parallel_29322.result b/mysql-test/suite/rpl/r/rpl_parallel_29322.result new file mode 100644 index 00000000000..43cac55aec8 --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_parallel_29322.result @@ -0,0 +1,238 @@ +# +# MDEV-29322 ASAN use-after-free options_written_to_bin_log +# +include/master-slave.inc +[connection master] +# A. set the master and slave explicit_defaults_for_timestamp values crisscross to (1,0) +connection master; +set @sav.explicit_defaults_for_timestamp = @@session.explicit_defaults_for_timestamp; +set @@session.explicit_defaults_for_timestamp = 1; +connection slave; +set @sav.explicit_defaults_for_timestamp = @@global.explicit_defaults_for_timestamp; +set global explicit_defaults_for_timestamp = 0; +set @sav.slave_parallel_workers = @@global.slave_parallel_workers; +include/stop_slave.inc +set @@global.slave_parallel_workers = 1; +include/start_slave.inc +connection slave; +include/stop_slave.inc +reset slave; +connection master; +reset master; +create table t2 (a timestamp, b int); +show create table t2; +Table Create Table +t2 CREATE TABLE `t2` ( + `a` timestamp NULL DEFAULT NULL, + `b` int(11) DEFAULT NULL +) ENGINE=MyISAM DEFAULT CHARSET=latin1 +connection slave; +include/start_slave.inc +include/stop_slave.inc +connection master; +insert into t2 values (null, 1); +flush binary logs; +flush binary logs; +insert into t2 values (null, 2); +/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; +/*!40019 SET @@session.max_insert_delayed_threads=0*/; +/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; +DELIMITER /*!*/; +ROLLBACK/*!*/; +use `test`/*!*/; +SET TIMESTAMP=1658586280/*!*/; +SET @@session.pseudo_thread_id=999999999/*!*/; +SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/; +SET @@session.sql_mode=1411383296/*!*/; +SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/; +/*!\C utf8 *//*!*/; +SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/; +SET @@session.lc_time_names=0/*!*/; +SET @@session.collation_database=DEFAULT/*!*/; +create table t1 (f1 timestamp, f2 timestamp) +/*!*/; +START TRANSACTION +/*!*/; +SET TIMESTAMP=1658586288/*!*/; +insert t1 values (NULL, NULL) +/*!*/; +SET TIMESTAMP=1658586288/*!*/; +COMMIT +/*!*/; +START TRANSACTION +/*!*/; +SET TIMESTAMP=1658586335/*!*/; +insert t1 () values () +/*!*/; +SET TIMESTAMP=1658586335/*!*/; +COMMIT +/*!*/; +DELIMITER ; +# End of log file +ROLLBACK /* added by mysqlbinlog */; +/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; +/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; +connection slave1; +lock table t2 write; +connection slave; +include/start_slave.inc +connection slave1; +unlock tables; +connection slave; +show create table t1; +Table Create Table +t1 CREATE TABLE `t1` ( + `f1` timestamp NULL DEFAULT NULL, + `f2` timestamp NULL DEFAULT NULL +) ENGINE=MyISAM DEFAULT CHARSET=latin1 +set statement time_zone='+2:00' for select * from t1; +f1 f2 +NULL NULL +NULL NULL +drop table t1; +connection master; +connection slave; +show create table t2; +Table Create Table +t2 CREATE TABLE `t2` ( + `a` timestamp NULL DEFAULT NULL, + `b` int(11) DEFAULT NULL +) ENGINE=MyISAM DEFAULT CHARSET=latin1 +include/diff_tables.inc [master:t2,slave:t2] +connection master; +drop table t2; +connection slave; +# B. alternate the master and slave vars' values to (0,1) +connection master; +set @@session.explicit_defaults_for_timestamp = 0; +connection slave; +set @@global.explicit_defaults_for_timestamp = 1; +connection slave; +include/stop_slave.inc +reset slave; +connection master; +reset master; +create table t2 (a timestamp, b int); +show create table t2; +Table Create Table +t2 CREATE TABLE `t2` ( + `a` timestamp NOT NULL DEFAULT current_timestamp() ON UPDATE current_timestamp(), + `b` int(11) DEFAULT NULL +) ENGINE=MyISAM DEFAULT CHARSET=latin1 +connection slave; +include/start_slave.inc +include/stop_slave.inc +connection master; +insert into t2 values (null, 1); +flush binary logs; +flush binary logs; +insert into t2 values (null, 2); +/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; +/*!40019 SET @@session.max_insert_delayed_threads=0*/; +/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; +DELIMITER /*!*/; +ROLLBACK/*!*/; +use `test`/*!*/; +SET TIMESTAMP=1658586280/*!*/; +SET @@session.pseudo_thread_id=999999999/*!*/; +SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/; +SET @@session.sql_mode=1411383296/*!*/; +SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/; +/*!\C utf8 *//*!*/; +SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/; +SET @@session.lc_time_names=0/*!*/; +SET @@session.collation_database=DEFAULT/*!*/; +create table t1 (f1 timestamp, f2 timestamp) +/*!*/; +START TRANSACTION +/*!*/; +SET TIMESTAMP=1658586288/*!*/; +insert t1 values (NULL, NULL) +/*!*/; +SET TIMESTAMP=1658586288/*!*/; +COMMIT +/*!*/; +START TRANSACTION +/*!*/; +SET TIMESTAMP=1658586335/*!*/; +insert t1 () values () +/*!*/; +SET TIMESTAMP=1658586335/*!*/; +COMMIT +/*!*/; +DELIMITER ; +# End of log file +ROLLBACK /* added by mysqlbinlog */; +/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; +/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; +connection slave1; +lock table t2 write; +connection slave; +include/start_slave.inc +connection slave1; +unlock tables; +connection slave; +show create table t1; +Table Create Table +t1 CREATE TABLE `t1` ( + `f1` timestamp NOT NULL DEFAULT current_timestamp() ON UPDATE current_timestamp(), + `f2` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' +) ENGINE=MyISAM DEFAULT CHARSET=latin1 +set statement time_zone='+2:00' for select * from t1; +f1 f2 +2022-07-23 16:24:48 2022-07-23 16:24:48 +2022-07-23 16:25:35 0000-00-00 00:00:00 +drop table t1; +connection master; +connection slave; +show create table t2; +Table Create Table +t2 CREATE TABLE `t2` ( + `a` timestamp NOT NULL DEFAULT current_timestamp() ON UPDATE current_timestamp(), + `b` int(11) DEFAULT NULL +) ENGINE=MyISAM DEFAULT CHARSET=latin1 +include/diff_tables.inc [master:t2,slave:t2] +connection master; +drop table t2; +connection slave; +# C. the bug case on the same version binlogs also to demo on the patch's base +include/stop_slave.inc +set @@global.slave_parallel_workers = 4; +include/start_slave.inc +connection slave; +include/stop_slave.inc +reset slave; +connection master; +reset master; +create table t2 (a timestamp, b int); +show create table t2; +Table Create Table +t2 CREATE TABLE `t2` ( + `a` timestamp NOT NULL DEFAULT current_timestamp() ON UPDATE current_timestamp(), + `b` int(11) DEFAULT NULL +) ENGINE=MyISAM DEFAULT CHARSET=latin1 +connection slave; +include/start_slave.inc +include/stop_slave.inc +connection master; +connection slave; +include/start_slave.inc +connection slave; +show create table t2; +Table Create Table +t2 CREATE TABLE `t2` ( + `a` timestamp NOT NULL DEFAULT current_timestamp() ON UPDATE current_timestamp(), + `b` int(11) DEFAULT NULL +) ENGINE=MyISAM DEFAULT CHARSET=latin1 +include/diff_tables.inc [master:t2,slave:t2] +connection master; +drop table t2; +connection slave; +connection master; +set @@session.explicit_defaults_for_timestamp = @sav.explicit_defaults_for_timestamp; +connection slave; +set @@global.explicit_defaults_for_timestamp = @sav.explicit_defaults_for_timestamp; +include/stop_slave.inc +set @@global.slave_parallel_workers = @sav.slave_parallel_workers; +include/start_slave.inc +include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_parallel_29322.test b/mysql-test/suite/rpl/t/rpl_parallel_29322.test new file mode 100644 index 00000000000..675960592f8 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_parallel_29322.test @@ -0,0 +1,64 @@ +--echo # +--echo # MDEV-29322 ASAN use-after-free options_written_to_bin_log +--echo # + +# The tests verify that at query execution slave parallel workers successfully +# find a correct options_written_to_bin_log value associated with the query. +# There are three test branches, A and B take care of different server version +# binlogs. The homogeneous binlog case of C. branch is also for how-to-reproduce +# the bug, may need few --repeat :s though. + +--source include/have_binlog_format_mixed.inc +--source include/master-slave.inc + +--echo # A. set the master and slave explicit_defaults_for_timestamp values crisscross to (1,0) +--let $same_version_binlogs=0 + +--connection master +# Configure master and slave with different values of the following variable: +set @sav.explicit_defaults_for_timestamp = @@session.explicit_defaults_for_timestamp; +set @@session.explicit_defaults_for_timestamp = 1; +--connection slave +# slave must produce the master version of the table definition and its data +set @sav.explicit_defaults_for_timestamp = @@global.explicit_defaults_for_timestamp; +set global explicit_defaults_for_timestamp = 0; +# the global var gets changed in the included file +set @sav.slave_parallel_workers = @@global.slave_parallel_workers; +--source include/stop_slave.inc +set @@global.slave_parallel_workers = 1; +--source include/start_slave.inc + +--source suite/rpl/include/rpl_parallel_29322.inc + +--echo # B. alternate the master and slave vars' values to (0,1) + +--connection master +# Configure master and slave with different values of the following variable: +set @@session.explicit_defaults_for_timestamp = 0; +--connection slave +# slave must produce the master version of the table definition and its data +set @@global.explicit_defaults_for_timestamp = 1; + +--source suite/rpl/include/rpl_parallel_29322.inc + + +--echo # C. the bug case on the same version binlogs also to demo on the patch's base +--let $same_version_binlogs=1 +# with more workers the bug shows more likeky on the patch's base slave. +--source include/stop_slave.inc +set @@global.slave_parallel_workers = 4; +--source include/start_slave.inc + +--source suite/rpl/include/rpl_parallel_29322.inc + +# cleanup +--connection master +set @@session.explicit_defaults_for_timestamp = @sav.explicit_defaults_for_timestamp; +--connection slave +set @@global.explicit_defaults_for_timestamp = @sav.explicit_defaults_for_timestamp; +--source include/stop_slave.inc +set @@global.slave_parallel_workers = @sav.slave_parallel_workers; +--source include/start_slave.inc + + +--source include/rpl_end.inc diff --git a/sql/log_event.cc b/sql/log_event.cc index 4c4514bb4e2..20cf4d45073 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -1528,7 +1528,7 @@ Query_log_event::Query_log_event(const char* buf, uint event_len, switch (*pos++) { case Q_FLAGS2_CODE: CHECK_SPACE(pos, end, 4); - flags2_inited= 1; + flags2_inited= description_event->options_written_to_bin_log; flags2= uint4korr(pos); DBUG_PRINT("info",("In Query_log_event, read flags2: %lu", (ulong) flags2)); pos+= 4; diff --git a/sql/log_event.h b/sql/log_event.h index 4c2ee3e484e..096d8587848 100644 --- a/sql/log_event.h +++ b/sql/log_event.h @@ -2088,7 +2088,7 @@ public: flags2==0 (5.0 master, we know this has a meaning of flags all down which must influence the query). */ - bool flags2_inited; + uint32 flags2_inited; bool sql_mode_inited; bool charset_inited; diff --git a/sql/log_event_server.cc b/sql/log_event_server.cc index 7a8561051ba..56d1c978ac4 100644 --- a/sql/log_event_server.cc +++ b/sql/log_event_server.cc @@ -1713,12 +1713,7 @@ int Query_log_event::do_apply_event(rpl_group_info *rgi, thd->slave_expected_error= expected_error; if (flags2_inited) { - /* - all bits of thd->variables.option_bits which are 1 in - OPTIONS_WRITTEN_TO_BIN_LOG must take their value from - flags2. - */ - ulonglong mask= rli->relay_log.description_event_for_exec->options_written_to_bin_log; + ulonglong mask= flags2_inited; thd->variables.option_bits= (flags2 & mask) | (thd->variables.option_bits & ~mask); } From bc12478a9a2ac77937c18f54d6c6563d5c1980f9 Mon Sep 17 00:00:00 2001 From: Andrei Date: Tue, 16 Aug 2022 20:03:15 +0300 Subject: [PATCH 2/3] MDEV-24660 MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' The shutdown time assert was caused by untimely deactivation of the binlog background thread and related structs destruction. It could specifically occur when a transaction is replication unsafe and has to be completed with a ROLLBACK event in binlog. This gets fixed with the binlog background thread stop relocation to a point and user transactions have been completed. A test case is added to binlog.binlog_checkpoint which also receives as a bonus a minor correction to reactivate a MDEV-4322 test case that originally required a shutdown phase (that ceased to do). --- .../suite/binlog/r/binlog_checkpoint.result | 52 ++++++++++++++++-- .../suite/binlog/t/binlog_checkpoint.test | 53 +++++++++++++++++-- sql/log.cc | 6 ++- sql/mysqld.cc | 13 +++-- 4 files changed, 110 insertions(+), 14 deletions(-) diff --git a/mysql-test/suite/binlog/r/binlog_checkpoint.result b/mysql-test/suite/binlog/r/binlog_checkpoint.result index 9e987913423..7578a9fc6d9 100644 --- a/mysql-test/suite/binlog/r/binlog_checkpoint.result +++ b/mysql-test/suite/binlog/r/binlog_checkpoint.result @@ -129,6 +129,9 @@ master-bin.000004 # master-bin.000005 # master-bin.000006 # 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; +# restart *** MDEV-7402: 'reset master' hangs, waits for signalled COND_xid_list *** connect con3,localhost,root,,; SET debug_sync="reset_logs_after_set_reset_master_pending SIGNAL reset_master_ready WAIT_FOR reset_master_cont"; @@ -144,7 +147,48 @@ SET debug_sync="now SIGNAL reset_master_cont"; connection con3; connection default; SET debug_sync = 'reset'; -DROP TABLE t1, t2; -SET GLOBAL max_binlog_size= @old_max_binlog_size; -SET GLOBAL innodb_flush_log_at_trx_commit= @old_innodb_flush_log_at_trx_commit; -SET debug_sync = 'reset'; +*** MDEV-24660: MYSQL_BIN_LOG::cleanup(): Assertion `b->xid_count == 0' failed in MYSQL_BIN_LOG::cleanup +SET @old_max_binlog_size= @@global.max_binlog_size; +SET GLOBAL max_binlog_size= 4096; +connect con_24660,localhost,root,,; +FLUSH LOGS; +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'; +INSERT INTO t1 VALUES (2, 1); +INSERT INTO tm SET a = 1; +XA END 'xa1'; +connection default; +SET GLOBAL debug_dbug="+d,only_kill_system_threads_no_loop"; +# restart +** Proof of shutdown caused ROLLBACK-completed transaction +include/show_binlog_events.inc +Log_name Pos Event_type Server_id End_log_pos Info +master-bin.000002 # Format_desc # # SERVER_VERSION, BINLOG_VERSION +master-bin.000002 # Gtid_list # # [] +master-bin.000002 # Binlog_checkpoint # # master-bin.000001 +master-bin.000002 # Binlog_checkpoint # # master-bin.000002 +master-bin.000002 # Gtid # # GTID #-#-# +master-bin.000002 # Query # # use `test`; CREATE TABLE tm (a INT) ENGINE = myisam +master-bin.000002 # Gtid # # BEGIN GTID #-#-# +master-bin.000002 # Query # # use `mtr`; INSERT INTO test_suppressions (pattern) VALUES ( NAME_CONST('pattern',_latin1'Table \'./test/tm\' is marked as crashed' COLLATE 'latin1_swedish_ci')) +master-bin.000002 # Query # # COMMIT +master-bin.000002 # Gtid # # BEGIN GTID #-#-# +master-bin.000002 # Query # # use `mtr`; INSERT INTO test_suppressions (pattern) VALUES ( NAME_CONST('pattern',_latin1'Checking table' COLLATE 'latin1_swedish_ci')) +master-bin.000002 # Query # # COMMIT +master-bin.000002 # Gtid # # BEGIN GTID #-#-# +master-bin.000002 # Query # # use `test`; INSERT INTO tm SET a = 1 +master-bin.000002 # Query # # COMMIT +master-bin.000002 # Gtid # # BEGIN GTID #-#-# +master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (2, 1) +master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (3, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx") +master-bin.000002 # Query # # ROLLBACK +master-bin.000002 # Rotate # # master-bin.000003;pos=POS +SELECT * FROM tm; +a +1 +SELECT * FROM t1 WHERE a = 3; +a b +DROP TABLE t1, t2, tm; diff --git a/mysql-test/suite/binlog/t/binlog_checkpoint.test b/mysql-test/suite/binlog/t/binlog_checkpoint.test index cdb71887ad6..19b48ef68b0 100644 --- a/mysql-test/suite/binlog/t/binlog_checkpoint.test +++ b/mysql-test/suite/binlog/t/binlog_checkpoint.test @@ -140,10 +140,15 @@ 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 *** ---source include/wait_for_binlog_checkpoint.inc connect(con3,localhost,root,,); # Make the binlog background thread wait before clearing the pending checkpoint. @@ -169,9 +174,47 @@ 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 +--source include/show_binlog_events.inc +SELECT * FROM tm; +--eval SELECT * FROM t1 WHERE a = $a # Clean up. -DROP TABLE t1, t2; -SET GLOBAL max_binlog_size= @old_max_binlog_size; -SET GLOBAL innodb_flush_log_at_trx_commit= @old_innodb_flush_log_at_trx_commit; -SET debug_sync = 'reset'; +DROP TABLE t1, t2, tm; diff --git a/sql/log.cc b/sql/log.cc index ae89d57f885..ea094d74213 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -3412,6 +3412,7 @@ void MYSQL_BIN_LOG::stop_background_thread() &LOCK_binlog_background_thread); mysql_mutex_unlock(&LOCK_binlog_background_thread); binlog_background_thread_started= false; + binlog_background_thread_stop= true; // mark it's not going to restart } } @@ -3610,7 +3611,8 @@ bool MYSQL_BIN_LOG::open(const char *log_name, DBUG_RETURN(1); } - if (!binlog_background_thread_started && + if ((!binlog_background_thread_started && + !binlog_background_thread_stop) && start_binlog_background_thread()) DBUG_RETURN(1); } @@ -10343,6 +10345,7 @@ binlog_background_thread(void *arg __attribute__((unused))) thd->store_globals(); thd->security_ctx->skip_grants(); thd->set_command(COM_DAEMON); + THD_count::count--; /* Load the slave replication GTID state from the mysql.gtid_slave_pos @@ -10432,6 +10435,7 @@ binlog_background_thread(void *arg __attribute__((unused))) THD_STAGE_INFO(thd, stage_binlog_stopping_background_thread); /* No need to use mutex as thd is not linked into other threads */ + THD_count::count++; delete thd; my_thread_end(); diff --git a/sql/mysqld.cc b/sql/mysqld.cc index 3d1ba5bbea7..09841a75f5a 100644 --- a/sql/mysqld.cc +++ b/sql/mysqld.cc @@ -1534,6 +1534,8 @@ static my_bool kill_thread_phase_1(THD *thd, int *n_threads_awaiting_ack) if (DBUG_EVALUATE_IF("only_kill_system_threads", !thd->system_thread, 0)) return 0; + if (DBUG_EVALUATE_IF("only_kill_system_threads_no_loop", !thd->system_thread, 0)) + return 0; thd->set_killed(KILL_SERVER_HARD); MYSQL_CALLBACK(thread_scheduler, post_kill_notification, (thd)); @@ -1755,7 +1757,6 @@ static void close_connections(void) Events::deinit(); slave_prepare_for_shutdown(); - mysql_bin_log.stop_background_thread(); ack_receiver.stop(); /* @@ -1776,7 +1777,8 @@ static void close_connections(void) for (int i= 0; (THD_count::value() - binlog_dump_thread_count - n_threads_awaiting_ack) && - i < 1000; + i < 1000 && + DBUG_EVALUATE_IF("only_kill_system_threads_no_loop", 0, 1); i++) my_sleep(20000); @@ -1795,9 +1797,12 @@ static void close_connections(void) THD_count::value() - binlog_dump_thread_count - n_threads_awaiting_ack)); - while (THD_count::value() - binlog_dump_thread_count - - n_threads_awaiting_ack) + while ((THD_count::value() - binlog_dump_thread_count - + n_threads_awaiting_ack) && + DBUG_EVALUATE_IF("only_kill_system_threads_no_loop", 0, 1)) + { my_sleep(1000); + } /* Kill phase 2 */ server_threads.iterate(kill_thread_phase_2); From fb70bb44d096f4117e9454740aa4fa0651a1a69e Mon Sep 17 00:00:00 2001 From: Vladislav Vaintroub Date: Mon, 12 Sep 2022 12:10:10 +0200 Subject: [PATCH 3/3] MDEV-29513 avoid useless os_thread_sleep() during srv_purge_shutdown() use waitable_task.wait() function to wait for the end of previous purge --- storage/innobase/srv/srv0srv.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/storage/innobase/srv/srv0srv.cc b/storage/innobase/srv/srv0srv.cc index a5857f7d653..a33d34c5654 100644 --- a/storage/innobase/srv/srv0srv.cc +++ b/storage/innobase/srv/srv0srv.cc @@ -2052,7 +2052,7 @@ void srv_purge_shutdown() while(!srv_purge_should_exit()) { ut_a(!purge_sys.paused()); srv_wake_purge_thread_if_not_active(); - os_thread_sleep(1000); + purge_coordinator_task.wait(); } purge_sys.coordinator_shutdown(); srv_shutdown_purge_tasks();