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).

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);