MDEV-38147 Mariadb error 1950 after SST

extra/mariabackup/backup_mysql.cc

@@ -88,6 +88,14 @@ static mysql_cond_t kill_query_thread_stop;
 bool sql_thread_started = false;
 char *mysql_slave_position = NULL;
 char *mysql_binlog_position = NULL;
+/*
+  MDEV-38147: the exact binary log file name that
+  write_current_binlog_file() rotated to and shipped into the backup under
+  --galera-info. Remembered here so that write_binlog_info() records the very
+  same file name in xtrabackup_binlog_info, i.e. the file the SST joiner looks
+  for is guaranteed to be the file that was actually sent (no rotation race).
+*/
+char *mysql_binlog_file = NULL;
 char *buffer_pool_filename = NULL;
 
 /* History on server */
@@ -1528,6 +1536,23 @@ write_galera_info(ds_ctxt *datasink, MYSQL *connection)
       domain_id ? domain_id : domain_id55);
   }
 
+  /*
+    MDEV-38147: Flush and copy the donor's current binary log into
+    the backup so that it is shipped to the SST joiner.
+
+    A new joiner discards this file and starts a fresh binary log seeded from
+    the storage-engine checkpoint (see wsrep_seed_binlog_gtid_state() in
+    sql/log.cc and the joiner code in scripts/wsrep_sst_mariabackup.sh), which
+    avoids error 1950 with gtid_strict_mode=ON. The file is still shipped for
+    backward compatibility with an old joiner that expects it, and so that a
+    new joiner can deterministically identify and remove exactly the file that
+    was sent instead of colliding with it.
+
+    write_current_binlog_file() remembers the rotated file name in
+    mysql_binlog_file so that write_binlog_info() records the same file in
+    xtrabackup_binlog_info - closing the old race where a concurrent rotation
+    could make the shipped file and the recorded file diverge.
+  */
   if (result)
     write_current_binlog_file(datasink, connection);
 
@@ -1548,7 +1573,16 @@ write_galera_info(ds_ctxt *datasink, MYSQL *connection)
 
 /*********************************************************************//**
 Flush and copy the current binary log file into the backup,
-if GTID is enabled */
+if GTID is enabled.
+
+MDEV-38147: the file name that FLUSH BINARY LOGS rotates to is
+remembered in the global mysql_binlog_file. write_binlog_info() then records
+that exact name in xtrabackup_binlog_info, so the file the SST joiner looks
+for is guaranteed to be the file that was shipped. Previously the shipped file
+(determined here) and the recorded file (determined independently later by
+write_binlog_info()) were read by two separate SHOW MASTER STATUS calls; a
+binary log rotation happening in between made them diverge and the wrong file
+was sent. */
 bool
 write_current_binlog_file(ds_ctxt *datasink, MYSQL *connection)
 {
@@ -1601,6 +1635,22 @@ write_current_binlog_file(ds_ctxt *datasink, MYSQL *connection)
 			log_bin_dir = strdup("./");
 		}
 
+		if (log_bin_dir == NULL || log_bin_file == NULL) {
+			msg("Failed to get master binlog coordinates from "
+				"SHOW MASTER STATUS");
+			result = false;
+			goto cleanup;
+		}
+
+		/*
+		  Remember the file we just rotated to (before any further
+		  rotation can happen) so that write_binlog_info() records this
+		  very file in xtrabackup_binlog_info and the joiner looks for
+		  exactly the file that is shipped below.
+		*/
+		free(mysql_binlog_file);
+		mysql_binlog_file = strdup(log_bin_file);
+
 		dirname_part(log_bin_dir, log_bin_dir, &log_bin_dir_length);
 
 		/* strip final slash if it is not the only path component */
@@ -1609,13 +1659,6 @@ write_current_binlog_file(ds_ctxt *datasink, MYSQL *connection)
 			log_bin_dir[log_bin_dir_length - 1] = 0;
 		}
 
-		if (log_bin_dir == NULL || log_bin_file == NULL) {
-			msg("Failed to get master binlog coordinates from "
-				"SHOW MASTER STATUS");
-			result = false;
-			goto cleanup;
-		}
-
 		snprintf(filepath, sizeof(filepath), "%s%c%s",
 			 log_bin_dir, FN_LIBCHAR, log_bin_file);
 		result = datasink->copy_file(filepath, log_bin_file, 0);
@@ -1637,6 +1680,7 @@ bool
 write_binlog_info(ds_ctxt *datasink, MYSQL *connection)
 {
 	char *filename = NULL;
+	const char *out_filename;
 	char *position = NULL;
 	char *gtid_mode = NULL;
 	char *gtid_current_pos = NULL;
@@ -1669,6 +1713,24 @@ write_binlog_info(ds_ctxt *datasink, MYSQL *connection)
 		goto cleanup;
 	}
 
+	/*
+	  MDEV-38147: if write_current_binlog_file() already rotated
+	  and shipped a binary log under --galera-info, record that exact file
+	  name here rather than whatever SHOW MASTER STATUS reports now. The two
+	  are normally identical, but a binary log rotation between the two
+	  SHOW MASTER STATUS calls would otherwise make xtrabackup_binlog_info
+	  name a file different from the one that was shipped, so the SST joiner
+	  would look for a file that is not there. Use a separate pointer so the
+	  string owned by the status[] array is still freed at cleanup.
+	*/
+	out_filename = filename;
+	if (mysql_binlog_file != NULL && strcmp(filename, mysql_binlog_file)) {
+		msg("Binary log rotated to '%s' after '%s' was shipped; "
+		    "recording the shipped file in " XTRABACKUP_BINLOG_INFO,
+		    filename, mysql_binlog_file);
+		out_filename = mysql_binlog_file;
+	}
+
 	mysql_gtid = ((gtid_mode != NULL) && (strcmp(gtid_mode, "ON") == 0));
 	mariadb_gtid = (gtid_current_pos != NULL);
 
@@ -1678,16 +1740,16 @@ write_binlog_info(ds_ctxt *datasink, MYSQL *connection)
 		ut_a(asprintf(&mysql_binlog_position,
 			"filename '%s', position '%s', "
 			"GTID of the last change '%s'",
-			filename, position, gtid) != -1);
+			out_filename, position, gtid) != -1);
 		result = datasink->backup_file_printf(XTRABACKUP_BINLOG_INFO,
-					    "%s\t%s\t%s\n", filename, position,
+					    "%s\t%s\t%s\n", out_filename, position,
 					    gtid);
 	} else {
 		ut_a(asprintf(&mysql_binlog_position,
 			"filename '%s', position '%s'",
-			filename, position) != -1);
+			out_filename, position) != -1);
 		result = datasink->backup_file_printf(XTRABACKUP_BINLOG_INFO,
-					    "%s\t%s\n", filename, position);
+					    "%s\t%s\n", out_filename, position);
 	}
 
 cleanup:
@@ -2021,6 +2083,7 @@ backup_cleanup()
 {
 	free(mysql_slave_position);
 	free(mysql_binlog_position);
+	free(mysql_binlog_file);
 	free(buffer_pool_filename);
 
 	if (mysql_connection) {

extra/mariabackup/backup_mysql.h

@@ -27,6 +27,7 @@ extern time_t history_lock_time;
 extern bool sql_thread_started;
 extern char *mysql_slave_position;
 extern char *mysql_binlog_position;
+extern char *mysql_binlog_file;
 extern char *buffer_pool_filename;
 
 /** connection to mysql server */

extra/mariabackup/xtrabackup.cc

@@ -3750,6 +3750,19 @@ static void log_copying_thread()
     return;
   }
 
+  /*
+    This thread polls Innodb_lsn_flushed via SHOW STATUS on its own connection.
+    On a Galera donor wsrep_sync_wait may include SHOW, which would make that
+    poll wait until the node has applied the latest cluster transactions. During
+    a backup the donor's commit position can legitimately lag (e.g. a transaction
+    sitting between its binary log write and engine commit), so the poll could
+    block indefinitely and stall the redo log copier - failing the backup with a
+    misleading "Was only able to copy log ..." error. The main backup connection
+    already disables wsrep_sync_wait for the same reason, so do the same here.
+  */
+  if (have_galera_enabled)
+    xb_mysql_query(limit_con, "SET SESSION wsrep_sync_wait=0", false);
+
   mysql_mutex_lock(&recv_sys.mutex);
   for (;;)
   {

mysql-test/suite/galera/r/galera_log_bin_ext_mariabackup.result

@@ -58,8 +58,6 @@ SELECT COUNT(*) = 2 FROM INFORMATION_SCHEMA.COLUMNS WHERE TABLE_NAME = 't1';
 COUNT(*) = 2
 1
 include/show_binlog_events.inc
-Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-hostname1-bin.000002	#	Binlog_checkpoint	#	#	hostname1-bin.000002
 DROP TABLE t1;
 DROP TABLE t2;
 #cleanup

mysql-test/suite/galera_3nodes/r/MDEV-38147.result

@@ -0,0 +1,52 @@
+connection node_2;
+connection node_1;
+connection node_1;
+connection node_2;
+connection node_3;
+# gtid_strict_mode must be enabled on all nodes
+SELECT @@global.gtid_strict_mode AS gtid_strict_mode;
+gtid_strict_mode
+1
+connection node_1;
+connection node_2;
+connection node_3;
+connection node_3;
+connection node_1;
+connection node_1;
+SET SESSION wsrep_sync_wait = 0;
+SET GLOBAL debug_dbug = '+d,sync.after_mdl_block_ddl';
+connection node_1;
+SET DEBUG_SYNC = 'now WAIT_FOR sync.after_mdl_block_ddl_reached';
+connect node_1_freeze, 127.0.0.1, root, , test, $NODE_MYPORT_1;
+connection node_1_freeze;
+SET DEBUG_SYNC = 'commit_before_get_LOCK_commit_ordered SIGNAL t_frozen WAIT_FOR t_go';
+INSERT INTO t1 (val) VALUES (1);
+connection node_1;
+SET DEBUG_SYNC = 'now WAIT_FOR t_frozen';
+SET DEBUG_SYNC = 'now SIGNAL signal.after_mdl_block_ddl_continue';
+SET DEBUG_SYNC = 'now SIGNAL t_go';
+connection node_1_freeze;
+connection node_1;
+SET DEBUG_SYNC = 'RESET';
+SET GLOBAL debug_dbug = '';
+connection node_1;
+connection node_3;
+connection node_1;
+connection node_2;
+connection node_3;
+connection node_1;
+SET SESSION wsrep_sync_wait = 15;
+SELECT VARIABLE_VALUE AS wsrep_cluster_size FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_size';
+wsrep_cluster_size
+3
+connection node_3;
+SET SESSION wsrep_sync_wait = 15;
+count_match	checksum_match	gtid_match
+1	1	1
+connection node_2;
+SET SESSION wsrep_sync_wait = 15;
+count_match	checksum_match	gtid_match
+1	1	1
+DROP TABLE t1;
+disconnect node_2;
+disconnect node_1;

mysql-test/suite/galera_3nodes/r/MDEV-40179.result

@@ -0,0 +1,47 @@
+connection node_2;
+connection node_1;
+connection node_1;
+connection node_2;
+connection node_3;
+connection node_1;
+connection node_2;
+connection node_3;
+connection n1_load_1;
+CALL p_load('t1_1');
+connection n2_load_1;
+CALL p_load('t1_5');
+connection n1_load_2;
+CALL p_load('t1_2');
+connection n2_load_2;
+CALL p_load('t1_6');
+connection n1_load_3;
+CALL p_load('t1_3');
+connection n2_load_3;
+CALL p_load('t1_7');
+connection n1_load_4;
+CALL p_load('t1_4');
+connection n2_load_4;
+CALL p_load('t1_8');
+connection node_1;
+connection node_2;
+connection node_3;
+connection node_1;
+UPDATE ctrl SET stop = 1 WHERE id = 1;
+connection node_1;
+SET SESSION wsrep_sync_wait = 15;
+SELECT VARIABLE_VALUE AS wsrep_cluster_size FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_size';
+wsrep_cluster_size
+3
+connection node_2;
+SET SESSION wsrep_sync_wait = 15;
+count_match	checksum_match	gtid_match
+1	1	1
+connection node_3;
+SET SESSION wsrep_sync_wait = 15;
+count_match	checksum_match	gtid_match
+1	1	1
+connection node_1;
+connection node_2;
+connection node_3;
+disconnect node_2;
+disconnect node_1;

mysql-test/suite/galera_3nodes/r/MDEV-40179_nobinlog.result

@@ -0,0 +1,47 @@
+connection node_2;
+connection node_1;
+connection node_1;
+connection node_2;
+connection node_3;
+connection node_1;
+connection node_2;
+connection node_3;
+connection n1_load_1;
+CALL p_load('t1_1');
+connection n2_load_1;
+CALL p_load('t1_5');
+connection n1_load_2;
+CALL p_load('t1_2');
+connection n2_load_2;
+CALL p_load('t1_6');
+connection n1_load_3;
+CALL p_load('t1_3');
+connection n2_load_3;
+CALL p_load('t1_7');
+connection n1_load_4;
+CALL p_load('t1_4');
+connection n2_load_4;
+CALL p_load('t1_8');
+connection node_1;
+connection node_2;
+connection node_3;
+connection node_1;
+UPDATE ctrl SET stop = 1 WHERE id = 1;
+connection node_1;
+SET SESSION wsrep_sync_wait = 15;
+SELECT VARIABLE_VALUE AS wsrep_cluster_size FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_size';
+wsrep_cluster_size
+3
+connection node_2;
+SET SESSION wsrep_sync_wait = 15;
+count_match	checksum_match
+1	1
+connection node_3;
+SET SESSION wsrep_sync_wait = 15;
+count_match	checksum_match
+1	1
+connection node_1;
+connection node_2;
+connection node_3;
+disconnect node_2;
+disconnect node_1;

mysql-test/suite/galera_3nodes/t/MDEV-38147.cnf

@@ -0,0 +1,31 @@
+!include ../galera_3nodes.cnf
+
+[mysqld]
+wsrep_sst_method=mariabackup
+wsrep_sst_auth="root:"
+gtid_strict_mode=ON
+wsrep_gtid_mode=ON
+wsrep_gtid_domain_id=100
+gtid_domain_id=10
+log_bin
+log_slave_updates=ON
+innodb_flush_log_at_trx_commit=1
+sync_binlog=1
+wsrep_sync_wait=6 # allow SHOW to workaround MDEV-39468 and reproduce "error 1950"
+
+[mysqld.1]
+server_id=11
+
+[mysqld.2]
+server_id=12
+
+[mysqld.3]
+server_id=13
+# Force node_3 to always SST from node_1 (the node on which we freeze a
+# transaction between binary log write and engine commit), so the snapshot
+# node_3 receives is the one whose binary log is ahead of its engine checkpoint.
+wsrep_sst_donor=node1
+
+[sst]
+transferfmt=@ENV.MTR_GALERA_TFMT
+streamfmt=mbstream