MDEV-4322: Race in binlog checkpointing during server shutdown.

During server shutdown, we need to wait for binlog checkpointing to
finish in the binlog background thread before closing the binlog.

This was not done, so we could get assert and failure to finish the
final binlog checkpoint if shutdown happened in the middle.

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

@@ -89,6 +89,22 @@ Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 master-bin.000003	#	Format_desc	#	#	SERVER_VERSION, BINLOG_VERSION
 master-bin.000003	#	Binlog_checkpoint	#	#	master-bin.000001
 master-bin.000003	#	Binlog_checkpoint	#	#	master-bin.000003
+*** MDEV-4322: Broken XID counting during binlog rotation ***
+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));
+show binary logs;
+Log_name	File_size
+master-bin.000001	#
+master-bin.000002	#
+master-bin.000003	#
+master-bin.000004	#
+master-bin.000005	#
+master-bin.000006	#
 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;

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

@@ -113,8 +113,33 @@ connection default;
 --source include/show_binlog_events.inc
 
 
-# Cleanup
+--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
+
+
 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;

sql/log.cc

@@ -2952,6 +2952,19 @@ void MYSQL_BIN_LOG::cleanup()
   {
     xid_count_per_binlog *b;
 
+    /* Wait for the binlog background thread to stop. */
+    if (!is_relay_log && binlog_background_thread_started)
+    {
+      mysql_mutex_lock(&LOCK_binlog_background_thread);
+      binlog_background_thread_stop= true;
+      mysql_cond_signal(&COND_binlog_background_thread);
+      while (binlog_background_thread_stop)
+        mysql_cond_wait(&COND_binlog_background_thread_end,
+                        &LOCK_binlog_background_thread);
+      mysql_mutex_unlock(&LOCK_binlog_background_thread);
+      binlog_background_thread_started= false;
+    }
+
     inited= 0;
     close(LOG_CLOSE_INDEX|LOG_CLOSE_STOP_EVENT);
     delete description_event_for_queue;
@@ -2968,19 +2981,6 @@ void MYSQL_BIN_LOG::cleanup()
       my_free(b);
     }
 
-    /* Wait for the binlog background thread to stop. */
-    if (!is_relay_log && binlog_background_thread_started)
-    {
-      mysql_mutex_lock(&LOCK_binlog_background_thread);
-      binlog_background_thread_stop= true;
-      mysql_cond_signal(&COND_binlog_background_thread);
-      while (binlog_background_thread_stop)
-        mysql_cond_wait(&COND_binlog_background_thread_end,
-                        &LOCK_binlog_background_thread);
-      mysql_mutex_unlock(&LOCK_binlog_background_thread);
-      binlog_background_thread_started= false;
-    }
-
     mysql_mutex_destroy(&LOCK_log);
     mysql_mutex_destroy(&LOCK_index);
     mysql_mutex_destroy(&LOCK_xid_list);
@@ -3702,17 +3702,10 @@ bool MYSQL_BIN_LOG::reset_logs(THD* thd, bool create_new_log)
 
     /* Now wait for all checkpoint requests and pending unlog() to complete. */
     mysql_mutex_lock(&LOCK_xid_list);
-    xid_count_per_binlog *b;
     for (;;)
     {
-      I_List_iterator<xid_count_per_binlog> it(binlog_xid_count_list);
-      while ((b= it++))
-      {
-        if (b->xid_count > 0)
-          break;
-      }
-      if (!b)
-        break;                                  /* No more pending XIDs */
+      if (is_xidlist_idle_nolock())
+        break;
       /*
         Wait until signalled that one more binlog dropped to zero, then check
         again.
@@ -4490,6 +4483,32 @@ MYSQL_BIN_LOG::can_purge_log(const char *log_file_name)
 #endif /* HAVE_REPLICATION */
 
 
+bool
+MYSQL_BIN_LOG::is_xidlist_idle()
+{
+  bool res;
+  mysql_mutex_lock(&LOCK_xid_list);
+  res= is_xidlist_idle_nolock();
+  mysql_mutex_unlock(&LOCK_xid_list);
+  return res;
+}
+
+
+bool
+MYSQL_BIN_LOG::is_xidlist_idle_nolock()
+{
+  xid_count_per_binlog *b;
+
+  I_List_iterator<xid_count_per_binlog> it(binlog_xid_count_list);
+  while ((b= it++))
+  {
+    if (b->xid_count > 0)
+      return false;
+  }
+  return true;
+}
+
+
 /**
   Create a new log file name.
 
@@ -8216,6 +8235,13 @@ binlog_background_thread(void *arg __attribute__((unused)))
     {
       stop= binlog_background_thread_stop;
       queue= binlog_background_thread_queue;
+      if (stop && !mysql_bin_log.is_xidlist_idle())
+      {
+        /*
+          Delay stop until all pending binlog checkpoints have been processed.
+        */
+        stop= false;
+      }
       if (stop || queue)
         break;
       mysql_cond_wait(&mysql_bin_log.COND_binlog_background_thread,
@@ -8226,9 +8252,18 @@ binlog_background_thread(void *arg __attribute__((unused)))
     mysql_mutex_unlock(&mysql_bin_log.LOCK_binlog_background_thread);
 
     /* Process any incoming commit_checkpoint_notify() calls. */
+    DBUG_EXECUTE_IF("inject_binlog_background_thread_before_mark_xid_done",
+      DBUG_ASSERT(!debug_sync_set_action(
+        thd,
+        STRING_WITH_LEN("binlog_background_thread_before_mark_xid_done "
+                        "SIGNAL injected_binlog_background_thread "
+                        "WAIT_FOR something_that_will_never_happen "
+                        "TIMEOUT 2")));
+      );
     while (queue)
     {
       thd_proc_info(thd, "Processing binlog checkpoint notification");
+      DEBUG_SYNC(current_thd, "binlog_background_thread_before_mark_xid_done");
       /* Grab next pointer first, as mark_xid_done() may free the element. */
       next= queue->next_in_queue;
       mysql_bin_log.mark_xid_done(queue->binlog_id, true);

sql/log.h

@@ -526,6 +526,7 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG
   int write_transaction_or_stmt(group_commit_entry *entry);
   bool write_transaction_to_binlog_events(group_commit_entry *entry);
   void trx_group_commit_leader(group_commit_entry *leader);
+  bool is_xidlist_idle_nolock();
 
 public:
   /*
@@ -771,6 +772,7 @@ public:
   inline IO_CACHE *get_index_file() { return &index_file;}
   inline uint32 get_open_count() { return open_count; }
   void set_status_variables(THD *thd);
+  bool is_xidlist_idle();
 };
 
 class Log_event_handler