MDEV-37541 Race of rolling back and committing transaction to binlog

Two transactions could binlog their completions in opposite to how it
is done in Engine. That is is rare situations ROLLBACK in Engine of
the dependency parent transaction could be scheduled by the
transaction before its binlogging. That give a follower dependency
child one get binlogged ahead of the parent.

For fixing this bug its necessary to ensure the binlogging phase is
always first one in the internal one-phase rollback protocol.

The commit makes sure the binlog handlerton always rollbacks as first
handlerton in no-2pc cases.

An added test demonstrates how the child could otherwise reach binlog
before its parent.

Author: emoonrain

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

@@ -0,0 +1,41 @@
+create table t1 (a int primary key, b text) engine=innodb;
+connect trx1_rollback,localhost,root,,;
+CREATE TABLE t_x (a int) engine=MEMORY;
+SET binlog_format=row;
+CREATE TEMPORARY TABLE tt_tmp ( id INT ) ENGINE = Memory;
+BEGIN;
+insert into t_x values (1);
+drop temporary table tt_tmp;
+insert into t1 values (99, "gotta log first");
+SET DEBUG_SYNC= 'reset';
+SET DEBUG_SYNC= "before_group_commit_queue SIGNAL trx1_at_log WAIT_FOR trx1_go";
+ROLLBACK;
+connect trx2_commit,localhost,root,,;
+insert into t1 values (99, "second best in binlog");
+connection default;
+SET DEBUG_SYNC= "now WAIT_FOR trx1_at_log";
+SET DEBUG_SYNC= "now SIGNAL trx1_go";
+connection trx2_commit;
+select * from t1;
+a	b
+99	second best in binlog
+# Prove the logging order is Trx1, Trx2
+include/show_binlog_events.inc
+Log_name	Pos	Event_type	Server_id	End_log_pos	Info
+master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
+master-bin.000001	#	Annotate_rows	#	#	insert into t_x values (1)
+master-bin.000001	#	Table_map	#	#	table_id: # (test.t_x)
+master-bin.000001	#	Write_rows_v1	#	#	table_id: # flags: STMT_END_F
+master-bin.000001	#	Query	#	#	COMMIT
+master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
+master-bin.000001	#	Annotate_rows	#	#	insert into t1 values (99, "gotta log first")
+master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
+master-bin.000001	#	Write_rows_v1	#	#	table_id: # flags: STMT_END_F
+master-bin.000001	#	Query	#	#	ROLLBACK
+master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
+master-bin.000001	#	Query	#	#	use `test`; insert into t1 values (99, "second best in binlog")
+master-bin.000001	#	Xid	#	#	COMMIT /* XID */
+drop table t_x, t1;
+disconnect trx1_rollback;
+disconnect trx2_commit;
+# end of the tests

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

@@ -0,0 +1,50 @@
+--source include/have_debug_sync.inc
+--source include/have_innodb.inc
+--source include/have_binlog_format_mixed.inc
+
+create table t1 (a int primary key, b text) engine=innodb;
+
+connect(trx1_rollback,localhost,root,,);
+CREATE TABLE t_x (a int) engine=MEMORY;
+
+--let $master_file= query_get_value(SHOW MASTER STATUS, File, 1)
+--let $binlog_start=query_get_value(SHOW MASTER STATUS, Position, 1)
+SET binlog_format=row;
+CREATE TEMPORARY TABLE tt_tmp ( id INT ) ENGINE = Memory;
+BEGIN;
+  insert into t_x values (1);
+  drop temporary table tt_tmp;
+  insert into t1 values (99, "gotta log first");
+
+SET DEBUG_SYNC= 'reset';
+SET DEBUG_SYNC= "before_group_commit_queue SIGNAL trx1_at_log WAIT_FOR trx1_go";
+
+--send ROLLBACK
+
+connect(trx2_commit,localhost,root,,);
+--send insert into t1 values (99, "second best in binlog")
+
+connection default;
+
+# Make sure ROLLBACK is in the binlogging phase ..
+SET DEBUG_SYNC= "now WAIT_FOR trx1_at_log";
+# .. and the contender trx2 in the locking phase ..
+let $wait_condition=
+  select count(*) = 1 from information_schema.innodb_trx
+  where trx_state = "LOCK WAIT" and trx_query like "%insert into t1 values%";
+source include/wait_condition.inc;
+# .. when both provided unfreeze the trx:s ..
+SET DEBUG_SYNC= "now SIGNAL trx1_go";
+
+connection trx2_commit;
+reap;
+select * from t1;
+
+# .. to observe proper binlogging.
+--echo # Prove the logging order is Trx1, Trx2
+--source include/show_binlog_events.inc
+
+drop table t_x, t1;
+disconnect trx1_rollback;
+disconnect trx2_commit;
+--echo # end of the tests

sql/handler.cc

@@ -2308,11 +2308,18 @@ int ha_rollback_trans(THD *thd, bool all)
     if (is_real_trans)                          /* not a statement commit */
       thd->stmt_map.close_transient_cursors();
 
+    int err;
+    if (has_binlog_hton(ha_info) &&
+        (err= binlog_hton->rollback(binlog_hton, thd, all)))
+    {
+      my_error(ER_ERROR_DURING_COMMIT, MYF(0), err);
+      error= 1;
+    }
     for (; ha_info; ha_info= ha_info_next)
     {
-      int err;
       handlerton *ht= ha_info->ht();
-      if ((err= ht->rollback(ht, thd, all)))
+
+      if (ht != binlog_hton && (err= ht->rollback(ht, thd, all)))
       {
         // cannot happen
         my_error(ER_ERROR_DURING_ROLLBACK, MYF(0), err);

sql/log.cc

@@ -8235,6 +8235,7 @@ MYSQL_BIN_LOG::queue_for_group_commit(group_commit_entry *orig_entry)
 bool
 MYSQL_BIN_LOG::write_transaction_to_binlog_events(group_commit_entry *entry)
 {
+  DEBUG_SYNC(entry->thd, "before_group_commit_queue");
   int is_leader= queue_for_group_commit(entry);
 #ifdef WITH_WSREP
   /* commit order was released in queue_for_group_commit() call,