BUG#22245619 SERVER ABORT AFTER SYNC STAGE OF THE COMMIT FAILS

Problem:

The binary log group commit sync is failing when committing a group of
transactions into a non-transactional storage engine while other thread
is rotating the binary log.

Analysis:

The binary log group commit procedure (ordered_commit) acquires LOCK_log
during the #1 stage (flush). As it holds the LOCK_log, a binary log
rotation will have to wait until this flush stage to finish before
actually rotating the binary log.

For the percona#2 stage (sync), the binary log group commit only holds the
LOCK_log if sync_binlog=1. In this case, the rotation has to wait also
for the sync stage to finish.

When sync_binlog>1, the sync stage releases the LOCK_log (to let other
groups to enter the flush stage), holding only the LOCK_sync. In this
case, the rotation can acquire the LOCK_log in parallel with the sync
stage.

For commits into transactional storage engine, the binary log rotation
checks a counter of "flushed but not yet committed" transactions,
waiting until this counter to be zeroed before closing the current
binary log file.  As the commit of the transactions happen in the percona#3
stage of the binary log group commit, the sync of the binary log in
stage percona#2 always succeed.

For commits into non-transactional storage engine, the binary log
rotation is checking the "flushed but not yet committed" transactions
counter, but it is zero because it only counts transactions that
contains XIDs. So, the rotation is allowed to take place in parallel
with the percona#2 stage of the binary log group commit. When the sync is
called at the same time that the rotation has closed the old binary log
file but didn't open the new file yet, the sync is failing with the
following error: 'Can't sync file 'UNOPENED' to disk (Errcode: 9 - Bad
file descriptor)'.

Fix:

For non-transactional only workload, binary log group commit will keep
the LOCK_log when entering percona#2 stage (sync) if the current group is
supposed to be synced to the binary log file.

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

@@ -0,0 +1,42 @@
+SET @saved_binlog_error_action= @@GLOBAL.binlog_error_action;
+SET GLOBAL binlog_error_action= ABORT_SERVER;
+SET @saved_sync_binlog= @@GLOBAL.sync_binlog;
+SET GLOBAL sync_binlog= 2;
+[connection conn1]
+CREATE TABLE t1 (c1 INT) ENGINE=MyISAM;
+SET DEBUG_SYNC= 'before_sync_binlog_file SIGNAL holding_before_bgc_sync_binlog_file WAIT_FOR continue_bgc_sync_binlog_file';
+INSERT INTO t1 VALUES (1);
+[connection conn2]
+SET DEBUG_SYNC= 'NOW WAIT_FOR holding_before_bgc_sync_binlog_file';
+SET DEBUG_SYNC= 'before_rotate_binlog_file SIGNAL holding_before_rotate_binlog_file WAIT_FOR continue_rotate_binlog_file';
+FLUSH LOGS;
+[connection default]
+SET DEBUG_SYNC= 'now WAIT_FOR holding_before_rotate_binlog_file TIMEOUT 3';
+SET DEBUG_SYNC= 'now SIGNAL continue_bgc_sync_binlog_file';
+SET DEBUG_SYNC= 'before_rotate_binlog_file CLEAR';
+SET DEBUG_SYNC = 'now SIGNAL continue_rotate_binlog_file';
+[connection conn1]
+[connection conn2]
+[connection default]
+DROP TABLE t1;
+SET DEBUG_SYNC= 'RESET';
+[connection conn1]
+CREATE TABLE t1 (c1 INT) ENGINE=InnoDB;
+SET DEBUG_SYNC= 'before_sync_binlog_file SIGNAL holding_before_bgc_sync_binlog_file WAIT_FOR continue_bgc_sync_binlog_file';
+INSERT INTO t1 VALUES (1);
+[connection conn2]
+SET DEBUG_SYNC= 'NOW WAIT_FOR holding_before_bgc_sync_binlog_file';
+SET DEBUG_SYNC= 'before_rotate_binlog_file SIGNAL holding_before_rotate_binlog_file WAIT_FOR continue_rotate_binlog_file';
+FLUSH LOGS;
+[connection default]
+SET DEBUG_SYNC= 'now WAIT_FOR holding_before_rotate_binlog_file TIMEOUT 3';
+SET DEBUG_SYNC= 'now SIGNAL continue_bgc_sync_binlog_file';
+SET DEBUG_SYNC= 'before_rotate_binlog_file CLEAR';
+SET DEBUG_SYNC = 'now SIGNAL continue_rotate_binlog_file';
+[connection conn1]
+[connection conn2]
+[connection default]
+DROP TABLE t1;
+SET DEBUG_SYNC= 'RESET';
+SET GLOBAL binlog_error_action= @saved_binlog_error_action;
+SET GLOBAL sync_binlog= @saved_sync_binlog;

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

@@ -0,0 +1,110 @@
+# ==== Purpose ====
+#
+# This test will try to rotate the binary log of the server while binary log
+# group commit sync stage tries to sync the recently flushed binary log group.
+#
+# As binary log group commit releases the binary log's LOCK_log right after
+# finishing the flush stage and entering the sync stage, the rotate procedure
+# (executed by MYSQL_BIN_LOG::new_file_impl) will be able take LOCK_log, but
+# it will delay the binary log rotation until the amount of prepared
+# transactions not yet committed be zero or the binary log group commit sync
+# stage has finished.
+#
+# ==== Related Bugs and Worklogs ====
+#
+# BUG#22245619 SERVER ABORT AFTER SYNC STAGE OF THE COMMIT FAILS
+#
+
+# This test case is binary log format agnostic
+--source include/have_binlog_format_row.inc
+--source include/have_debug_sync.inc
+
+# Set the options to hit the issue
+SET @saved_binlog_error_action= @@GLOBAL.binlog_error_action;
+SET GLOBAL binlog_error_action= ABORT_SERVER;
+SET @saved_sync_binlog= @@GLOBAL.sync_binlog;
+SET GLOBAL sync_binlog= 2;
+
+# Create two additional connections
+# conn1 will do the binary log group commit
+# conn2 will rotate the binary log
+# the default connection will coordinate the test case activity
+--connect(conn1,localhost,root,,test)
+--connect(conn2,localhost,root,,test)
+
+--let $engine= MyISAM
+
+while ($engine)
+{
+  --let $rpl_connection_name= conn1
+  --source include/rpl_connection.inc
+  # Create a new table
+  --eval CREATE TABLE t1 (c1 INT) ENGINE=$engine
+
+  # Make the server to hold before syncing the binary log group
+  SET DEBUG_SYNC= 'before_sync_binlog_file SIGNAL holding_before_bgc_sync_binlog_file WAIT_FOR continue_bgc_sync_binlog_file';
+  --send INSERT INTO t1 VALUES (1)
+
+  --let $rpl_connection_name= conn2
+  --source include/rpl_connection.inc
+  # Wait until it reached the sync binary log group
+  SET DEBUG_SYNC= 'NOW WAIT_FOR holding_before_bgc_sync_binlog_file';
+
+  # Make the server to hold while rotating the binary log
+  # It can hold in two places:
+  # a) waiting before all flushed transactions with Xid to be committed;
+  # b) after closing the old and before opening the new binary log file;
+  #
+  # The debug sync will happen at (a) if there are transactions for a
+  # transactional storage engine or at (b) if there are no transactions
+  # for a transactional storage engine in the group to be committed.
+  SET DEBUG_SYNC= 'before_rotate_binlog_file SIGNAL holding_before_rotate_binlog_file WAIT_FOR continue_rotate_binlog_file';
+  # Rotate the binary log
+  --send FLUSH LOGS
+
+  # Wait until the server reaches the debug sync point while rotating the
+  # binary log
+  --let $rpl_connection_name= default
+  --source include/rpl_connection.inc
+  --disable_warnings
+  SET DEBUG_SYNC= 'now WAIT_FOR holding_before_rotate_binlog_file TIMEOUT 3';
+  --enable_warnings
+
+  # Let the binary log group commit to sync and continue
+  SET DEBUG_SYNC= 'now SIGNAL continue_bgc_sync_binlog_file';
+  # Clear the binary log rotate debug sync point to avoid it to stop twice
+  SET DEBUG_SYNC= 'before_rotate_binlog_file CLEAR';
+  # Let the binary log rotate to continue
+  SET DEBUG_SYNC = 'now SIGNAL continue_rotate_binlog_file';
+
+  --let $rpl_connection_name= conn1
+  --source include/rpl_connection.inc
+  --reap
+
+  --let $rpl_connection_name= conn2
+  --source include/rpl_connection.inc
+  --reap
+
+  --let $rpl_connection_name= default
+  --source include/rpl_connection.inc
+
+  # Cleanup
+  DROP TABLE t1;
+  SET DEBUG_SYNC= 'RESET';
+
+  if ($engine == InnoDB)
+  {
+    --let $engine=
+  }
+  if ($engine == MyISAM)
+  {
+    --let $engine= InnoDB
+  }
+}
+
+# Disconnect the additional connections
+--disconnect conn1
+--disconnect conn2
+
+SET GLOBAL binlog_error_action= @saved_binlog_error_action;
+SET GLOBAL sync_binlog= @saved_sync_binlog;

sql/binlog.cc

@@ -4904,7 +4904,10 @@ int MYSQL_BIN_LOG::new_file_impl(bool need_lock_log, Format_description_log_even
       written to the binary log.
    */
   while (get_prep_xids() > 0)
+  {
+    DEBUG_SYNC(current_thd, "before_rotate_binlog_file");
     mysql_cond_wait(&m_prep_xids_cond, &LOCK_xids);
+  }
   mysql_mutex_unlock(&LOCK_xids);
 
   mysql_mutex_lock(&LOCK_index);
@@ -4979,6 +4982,7 @@ int MYSQL_BIN_LOG::new_file_impl(bool need_lock_log, Format_description_log_even
      Note that at this point, log_state != LOG_CLOSED (important for is_open()).
   */
 
+  DEBUG_SYNC(current_thd, "before_rotate_binlog_file");
   /*
      new_file() is only used for rotation (in FLUSH LOGS or because size >
      max_binlog_size or max_relay_log_size).
@@ -7093,6 +7097,7 @@ int MYSQL_BIN_LOG::ordered_commit(THD *thd, bool all, bool skip_commit)
   mysql_mutex_t *leave_mutex_before_commit_stage= NULL;
   my_off_t flush_end_pos= 0;
   bool need_LOCK_log;
+  unsigned int sync_period;
   if (unlikely(!is_open()))
   {
     final_queue= stage_manager.fetch_queue_for(Stage_manager::FLUSH_STAGE);
@@ -7144,11 +7149,18 @@ int MYSQL_BIN_LOG::ordered_commit(THD *thd, bool all, bool skip_commit)
   /*
     Stage #2: Syncing binary log file to disk
   */
-  need_LOCK_log= (get_sync_period() == 1);
+  sync_period= get_sync_period();
+  need_LOCK_log= (sync_period == 1) ||
+                 (sync_counter + 1 >= sync_period && get_prep_xids() == 0);
 
   /*
     LOCK_log is not released when sync_binlog is 1. It guarantees that the
     events are not be replicated by dump threads before they are synced to disk.
+
+    LOCK_log is not released also when we are about to sync the binary log and
+    there is no transactional storage engine prepared transactions. This will
+    guarantee that the binary log rotation will not take place before syncing
+    the binary log file.
   */
   if (change_stage(thd, Stage_manager::SYNC_STAGE, wait_queue,
                    need_LOCK_log ? NULL : &LOCK_log, &LOCK_sync))