diff --git a/extra/mariabackup/backup_mysql.cc b/extra/mariabackup/backup_mysql.cc index 453e9bb052ece..ffca4a64ad705 100644 --- a/extra/mariabackup/backup_mysql.cc +++ b/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) { diff --git a/extra/mariabackup/backup_mysql.h b/extra/mariabackup/backup_mysql.h index 76f4bc666b3f8..5bdd34c71602c 100644 --- a/extra/mariabackup/backup_mysql.h +++ b/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 */ diff --git a/extra/mariabackup/xtrabackup.cc b/extra/mariabackup/xtrabackup.cc index 345624fcbf9f2..cecaaf5c28df6 100644 --- a/extra/mariabackup/xtrabackup.cc +++ b/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 (;;) { diff --git a/mysql-test/suite/galera/r/galera_log_bin_ext_mariabackup.result b/mysql-test/suite/galera/r/galera_log_bin_ext_mariabackup.result index 9d7ea47324165..5f63c971ec912 100644 --- a/mysql-test/suite/galera/r/galera_log_bin_ext_mariabackup.result +++ b/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 diff --git a/mysql-test/suite/galera_3nodes/r/MDEV-38147.result b/mysql-test/suite/galera_3nodes/r/MDEV-38147.result new file mode 100644 index 0000000000000..2150b39cdec7a --- /dev/null +++ b/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; diff --git a/mysql-test/suite/galera_3nodes/r/MDEV-40179.result b/mysql-test/suite/galera_3nodes/r/MDEV-40179.result new file mode 100644 index 0000000000000..9d8d43bbd7345 --- /dev/null +++ b/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; diff --git a/mysql-test/suite/galera_3nodes/r/MDEV-40179_nobinlog.result b/mysql-test/suite/galera_3nodes/r/MDEV-40179_nobinlog.result new file mode 100644 index 0000000000000..6ca4480ce03dd --- /dev/null +++ b/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; diff --git a/mysql-test/suite/galera_3nodes/t/MDEV-38147.cnf b/mysql-test/suite/galera_3nodes/t/MDEV-38147.cnf new file mode 100644 index 0000000000000..3393252e28723 --- /dev/null +++ b/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 diff --git a/mysql-test/suite/galera_3nodes/t/MDEV-38147.test b/mysql-test/suite/galera_3nodes/t/MDEV-38147.test new file mode 100644 index 0000000000000..4dcc8b4995eb4 --- /dev/null +++ b/mysql-test/suite/galera_3nodes/t/MDEV-38147.test @@ -0,0 +1,195 @@ +# +# MDEV-38147 - Mariadb error 1950 after SST +# +# Here a single transaction is frozen on the donor in the 2PC window between +# the binary log write (step 2) and the engine commit (step 3), while a +# mariabackup SST to a joiner is paused just before it fixes its redo-log +# copy point. That makes the copied binary log carry a Gtid_list ahead of +# the copied engine snapshot - exactly the condition the bug is about. +# +# The bug: +# +# BACKUP STAGE BLOCK_COMMIT fixes the InnoDB redo copy point but does not stop +# a wsrep transaction from having its GTID written to the binary log before it +# commits in the engine. So the copied binary log can carry a Gtid_list ahead +# of the copied engine snapshot. After the SST the joiner reports the +# (committed, behind) engine position, IST resends the missing transaction, and +# re-binlogging it under gtid_strict_mode=ON collides with the ahead Gtid_list +# -> ER_GTID_STRICT_OUT_OF_ORDER (error 1950), and the joiner never reaches +# synced state. (The same snapshot also captures the transaction in the InnoDB +# XA-prepared state, i.e. the MDEV-40179 condition.) +# +# The fix makes the joiner discard the received binary log and seed its GTID +# position from the engine checkpoint, so re-binlogging over IST stays in +# lockstep with the cluster and node_3 rejoins cleanly. +# + +--source include/galera_cluster.inc +--source include/have_innodb.inc +--source include/have_mariabackup.inc +--source include/have_debug_sync.inc + +--let $galera_connection_name = node_3 +--let $galera_server_number = 3 +--source include/galera_connect.inc + +# Save original auto_increment_offset values so that MTR's post-check is +# happy after node_3 has been restarted. +--let $node_1=node_1 +--let $node_2=node_2 +--let $node_3=node_3 +--source ../galera/include/auto_increment_offset_save.inc + +--echo # gtid_strict_mode must be enabled on all nodes +SELECT @@global.gtid_strict_mode AS gtid_strict_mode; + +--connection node_1 +--disable_query_log +CREATE TABLE t1 (pk BIGINT AUTO_INCREMENT PRIMARY KEY, val INT) ENGINE=InnoDB; +--enable_query_log + +# Make sure the schema reached all nodes before we purge node_3. +--connection node_2 +--let $wait_condition = SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'test' AND TABLE_NAME = 't1'; +--source include/wait_condition.inc +--connection node_3 +--let $wait_condition = SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'test' AND TABLE_NAME = 't1'; +--source include/wait_condition.inc + +# +# Stop node_3 and purge its data directory so that rejoining forces a full +# mariabackup SST. +# +--connection node_3 +--source include/shutdown_mysqld.inc + +--connection node_1 +--let $wait_condition = SELECT VARIABLE_VALUE = 2 FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_size'; +--source include/wait_condition.inc + +--remove_files_wildcard $MYSQLTEST_VARDIR/mysqld.3/data/test +--remove_files_wildcard $MYSQLTEST_VARDIR/mysqld.3/data/mysql +--remove_files_wildcard $MYSQLTEST_VARDIR/mysqld.3/data/performance_schema +--remove_files_wildcard $MYSQLTEST_VARDIR/mysqld.3/data/mtr +--remove_files_wildcard $MYSQLTEST_VARDIR/mysqld.3/data + +# +# Arm the donor-side backup sync point: mariabackup will pause after +# BACKUP STAGE BLOCK_DDL, before BLOCK_COMMIT (which fixes the redo copy point). +# +--connection node_1 +SET SESSION wsrep_sync_wait = 0; +SET GLOBAL debug_dbug = '+d,sync.after_mdl_block_ddl'; + +# +# Start node_3 WITHOUT waiting for it to become ready: it rejoins via a +# mariabackup SST from node_1, whose donor backup pauses at the sync point armed +# above. We must not block on node_3 here, because releasing that pause (and +# everything that lets node_3 finish) happens below on the node_1 connection. +# So just trigger the restart via the expect file and continue. +# +--let $_expect_file_name= $MYSQLTEST_VARDIR/tmp/mysqld.3.expect +--write_line restart $_expect_file_name + +--connection node_1 +SET DEBUG_SYNC = 'now WAIT_FOR sync.after_mdl_block_ddl_reached'; + +# +# Freeze one transaction between binary log write and engine commit. +# commit_before_get_LOCK_commit_ordered is reached after the GTID/Xid events +# have been written and fsync'd to the binary log but before the engine commit. +# +--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'; +--send INSERT INTO t1 (val) VALUES (1) + +--connection node_1 +SET DEBUG_SYNC = 'now WAIT_FOR t_frozen'; + +# +# Let mariabackup continue. It fixes the redo copy point at BLOCK_COMMIT with +# the frozen transaction still in-doubt (so it is excluded from the engine +# snapshot), then issues "FLUSH BINARY LOGS" while shipping the binary log, +# which blocks on the in-doubt transaction's binary log checkpoint. +# +SET DEBUG_SYNC = 'now SIGNAL signal.after_mdl_block_ddl_continue'; + +--let $wait_condition = SELECT COUNT(*) >= 1 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE INFO LIKE 'FLUSH BINARY LOGS%' +--source include/wait_condition.inc + +# +# Release the frozen transaction. Its engine commit happens now - after the +# redo copy point was fixed - so it is absent from the copied engine snapshot +# while present in the shipped binary log's Gtid_list. +# +SET DEBUG_SYNC = 'now SIGNAL t_go'; + +--connection node_1_freeze +--reap +--connection node_1 +SET DEBUG_SYNC = 'RESET'; +SET GLOBAL debug_dbug = ''; + +# +# node_3 must rejoin and the cluster must reconverge to three nodes. +# +--connection node_1 +--let $wait_condition = SELECT VARIABLE_VALUE = 3 FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_size'; +--source include/wait_condition.inc + +# Re-establish the node_3 client connection (it was started without waiting). +--connection node_3 +--enable_reconnect +--source include/wait_until_connected_again.inc +--disable_reconnect + +--connection node_1 +--source include/galera_wait_ready.inc +--connection node_2 +--source include/galera_wait_ready.inc +--connection node_3 +--source include/galera_wait_ready.inc + +# +# Verify data / GTID consistency across all nodes. node_1 is the origin of the +# highest GTID, so node_2 and node_3 are waited *up* to node_1's position. +# +--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'; + +--let $expect_count = `SELECT COUNT(*) FROM t1` +--let $expect_sum = `SELECT COALESCE(SUM(pk), 0) + COALESCE(SUM(val), 0) FROM t1` +# Compare only the wsrep domain (wsrep_gtid_domain_id) of gtid_binlog_pos - that +# is the part the whole cluster shares; other domains are node-local. +--let $wsrep_dom = `SELECT @@global.wsrep_gtid_domain_id` +--let $expect_gtid = `SELECT REGEXP_SUBSTR(@@global.gtid_binlog_pos, '(? 1) leave one or more such writesets +# prepared-but-not-yet-committed, and the snapshot captures them. On a freshly +# SST'd joiner nothing resolves these prepared transactions: binlog crash +# recovery does not run (the joiner has no in-use binlog to recover from), and +# the wsrep continuity-based commit is inactive because wsrep_emulate_bin_log +# is FALSE when log_bin is ON. The leftover prepared transactions then abort +# startup with "Found prepared transactions!". Note this does not depend on +# the prepared set being non-contiguous - even a contiguous run aborts, because +# nothing commits or rolls it back. +# +# The log_bin=OFF variant is coverage only: with a single (InnoDB) read-write +# engine and no binary log, commits use one-phase commit, so transactions never +# enter the XA-prepared state and the snapshot has nothing in doubt. It simply +# verifies that mariabackup SST and reconvergence keep working with log_bin=OFF. +# +# To maximize parallel apply on the donor (and thus the chance of catching +# prepared transactions in the snapshot) each client thread writes to its own +# table: there are no certification conflicts between writers, so all of them +# apply concurrently. $writers client threads load on each of node_1 and node_2 +# while node_3 is repeatedly stopped, has its data directory purged and is +# started again, forcing a full mariabackup SST on every rejoin. At the end the +# cluster must reconverge to three nodes and all three nodes must hold identical +# data (and, with log_bin, identical GTID positions). +# +# Parameters set by the including .test: +# $restarts - number of stop/purge/start cycles for node_3 +# $writers - number of concurrent loader threads per node (each gets its +# own table to avoid certification conflicts) +# $check_gtid - 1 to also compare @@global.gtid_binlog_pos across nodes +# (only meaningful with log_bin), 0 otherwise +# + +--source include/big_test.inc +--source include/galera_cluster.inc +--source include/have_innodb.inc +--source include/have_mariabackup.inc + +--let $galera_connection_name = node_3 +--let $galera_server_number = 3 +--source include/galera_connect.inc + +# Save original auto_increment_offset values so that MTR's post-check is +# happy after node_3 has been restarted multiple times. +--let $node_1=node_1 +--let $node_2=node_2 +--let $node_3=node_3 +--source ../galera/include/auto_increment_offset_save.inc + +# Total number of data tables: one per writer thread across both nodes. +--let $ntables = `SELECT 2 * $writers` + +# +# Schema: t1_1 .. t1_$ntables hold the load (one table per writer thread), +# ctrl carries the stop flag for the loaders. +# +--connection node_1 +--disable_query_log +CREATE TABLE ctrl (id INT PRIMARY KEY, stop INT) ENGINE=InnoDB; +INSERT INTO ctrl VALUES (1, 0); + +--let $t = 1 +while ($t <= $ntables) +{ + --eval CREATE TABLE t1_$t (pk BIGINT AUTO_INCREMENT PRIMARY KEY, val INT) ENGINE=InnoDB + --inc $t +} + +DELIMITER |; +CREATE PROCEDURE p_load(IN tname VARCHAR(64)) +BEGIN + DECLARE v_stop INT DEFAULT 0; + DECLARE v_i INT; + # Keep the loop alive across transient cluster errors (BF aborts, + # certification failures, donor desync timeouts, ...). + DECLARE CONTINUE HANDLER FOR SQLEXCEPTION + BEGIN + ROLLBACK; + END; + SET @ins_sql = CONCAT('INSERT INTO ', tname, ' (pk, val) VALUES (DEFAULT, 1)'); + PREPARE ins FROM @ins_sql; + WHILE v_stop = 0 DO + START TRANSACTION; + SET v_i = 0; + WHILE v_i < 16 DO + EXECUTE ins; + SET v_i = v_i + 1; + END WHILE; + COMMIT; + # Throttle slightly between transactions so that a freshly joined node can + # catch up its replication queue instead of being starved by the load. + DO SLEEP(0.01); + SELECT stop INTO v_stop FROM ctrl WHERE id = 1; + END WHILE; + DEALLOCATE PREPARE ins; +END| +DELIMITER ;| +--enable_query_log + +# Make sure the schema reached the other nodes before starting the load. +--connection node_2 +--let $wait_condition = SELECT COUNT(*) = $ntables FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'test' AND TABLE_NAME LIKE 't1\_%'; +--source include/wait_condition.inc +--connection node_3 +--let $wait_condition = SELECT COUNT(*) = $ntables FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'test' AND TABLE_NAME LIKE 't1\_%'; +--source include/wait_condition.inc + +# +# Start the continuous load: $writers threads on node_1 (tables t1_1..t1_W) +# and $writers threads on node_2 (tables t1_(W+1)..t1_2W). +# +--disable_query_log +--let $w = 1 +while ($w <= $writers) +{ + --connect (n1_load_$w, 127.0.0.1, root, , test, $NODE_MYPORT_1) + --connect (n2_load_$w, 127.0.0.1, root, , test, $NODE_MYPORT_2) + --inc $w +} +--enable_query_log + +--let $w = 1 +--let $n2 = $writers +while ($w <= $writers) +{ + --connection n1_load_$w + --send_eval CALL p_load('t1_$w') + --inc $n2 + --connection n2_load_$w + --send_eval CALL p_load('t1_$n2') + --inc $w +} + +# +# While the load is running, repeatedly stop node_3, purge its data +# directory and start it again. An empty data directory forces a full +# mariabackup SST on every rejoin. +# +--disable_query_log +--let $i = $restarts +while ($i) +{ + --connection node_3 + --source include/shutdown_mysqld.inc + --disable_query_log + + # Wait until node_3 has actually left the cluster. + # (shutdown_mysqld.inc / wait_condition.inc / start_mysqld.inc / + # galera_wait_ready.inc each re-enable the query log, so re-disable it after + # every such include to keep the loop output out of the result file.) + --connection node_1 + --let $wait_condition = SELECT VARIABLE_VALUE = 2 FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_size'; + --source include/wait_condition.inc + --disable_query_log + + # Purge node_3's data directory. + --remove_files_wildcard $MYSQLTEST_VARDIR/mysqld.3/data/test + --remove_files_wildcard $MYSQLTEST_VARDIR/mysqld.3/data/mysql + --remove_files_wildcard $MYSQLTEST_VARDIR/mysqld.3/data/performance_schema + --remove_files_wildcard $MYSQLTEST_VARDIR/mysqld.3/data/mtr + --remove_files_wildcard $MYSQLTEST_VARDIR/mysqld.3/data + + # Start node_3 again (rejoins via mariabackup SST). + --connection node_3 + --let $restart_noprint = 2 + --source include/start_mysqld.inc + --disable_query_log + --source include/galera_wait_ready.inc + --disable_query_log + + # Wait until the cluster is back to three nodes before the next cycle. + --connection node_1 + --let $wait_condition = SELECT VARIABLE_VALUE = 3 FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_size'; + --source include/wait_condition.inc + --disable_query_log + + --dec $i +} +--enable_query_log + +# +# Make sure the whole cluster is healthy before stopping the load, so that +# any donor that desynced during SST has resynced and the loaders can read +# the stop flag without blocking. +# +--connection node_1 +--source include/galera_wait_ready.inc +--connection node_2 +--source include/galera_wait_ready.inc +--connection node_3 +--source include/galera_wait_ready.inc + +# +# Signal the loaders to stop and collect them. +# +--connection node_1 +UPDATE ctrl SET stop = 1 WHERE id = 1; + +--disable_query_log +--let $w = 1 +while ($w <= $writers) +{ + --connection n1_load_$w + --reap + --connection n2_load_$w + --reap + --inc $w +} +--enable_query_log + +# +# Build the aggregate count / checksum expressions over all data tables. +# +--let $count_expr = 0 +--let $sum_expr = 0 +--let $t = 1 +while ($t <= $ntables) +{ + --let $count_expr = $count_expr + (SELECT COUNT(*) FROM t1_$t) + --let $sum_expr = $sum_expr + (SELECT COALESCE(SUM(pk),0)+COALESCE(SUM(val),0) FROM t1_$t) + --inc $t +} + +# +# Verify reconvergence and data / GTID consistency across all nodes. +# +--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'; + +# The load has stopped; issue one final transaction from node_1 (sync_wait is +# on, so node_1 first applies everything else). This makes node_1 the origin of +# the cluster's highest GTID, so the checks below can wait for node_2/node_3 to +# converge *up* to node_1's position instead of comparing a single snapshot: +# @@gtid_binlog_pos is a system variable, so reading it is not covered by +# wsrep_sync_wait and a plain read can otherwise sample a position before the +# node has finished applying (a race that grows with accumulated load, e.g. +# under --repeat). +--disable_query_log +UPDATE ctrl SET stop = 2 WHERE id = 1; +--enable_query_log + +--let $expect_count = `SELECT $count_expr` +--let $expect_sum = `SELECT $sum_expr` +if ($check_gtid) +{ + # Compare only the wsrep domain (wsrep_gtid_domain_id) of gtid_binlog_pos. + # That is the part the whole cluster shares. Other domains in the position + # are node-local and legitimately differ: e.g. CALL mtr.add_suppression() + # below writes to the non-replicated 'mtr' database, which each node binlogs + # under its own gtid_domain_id/server_id - so those entries accumulate + # per-node across runs (visible under --repeat) and must not be compared. + --let $wsrep_dom = `SELECT @@global.wsrep_gtid_domain_id` + --let $expect_gtid = `SELECT REGEXP_SUBSTR(@@global.gtid_binlog_pos, '(? prepared transactions!". (gtid_strict_mode is enabled so any +# binlog/engine position inconsistency would also be caught.) +# +# See MDEV-40179.inc for the shared test body. +# + +--let $restarts = 8 +--let $writers = 4 +--let $check_gtid = 1 +--source MDEV-40179.inc diff --git a/mysql-test/suite/galera_3nodes/t/MDEV-40179_nobinlog.cnf b/mysql-test/suite/galera_3nodes/t/MDEV-40179_nobinlog.cnf new file mode 100644 index 0000000000000..38740c2ec8702 --- /dev/null +++ b/mysql-test/suite/galera_3nodes/t/MDEV-40179_nobinlog.cnf @@ -0,0 +1,27 @@ +!include ../galera_3nodes.cnf + +[mysqld] +wsrep_sst_method=mariabackup +wsrep_sst_auth="root:" +# No log_bin: Galera uses its emulated binlog (wsrep_emulate_bin_log), so the +# wsrep XID continuity check is what resolves prepared transactions on a joiner. +# Parallel apply so that prepared transactions can be committed out of order, +# producing a non-contiguous prepared set on the donor. +wsrep_slave_threads=8 +# Slow, durable commits widen the window during which transactions sit in the +# prepared state, so the backup's BLOCK_COMMIT snapshot is more likely to +# capture in-doubt transactions. +innodb_flush_log_at_trx_commit=1 + +[mysqld.1] +server_id=11 + +[mysqld.2] +server_id=12 + +[mysqld.3] +server_id=13 + +[sst] +transferfmt=@ENV.MTR_GALERA_TFMT +streamfmt=mbstream diff --git a/mysql-test/suite/galera_3nodes/t/MDEV-40179_nobinlog.test b/mysql-test/suite/galera_3nodes/t/MDEV-40179_nobinlog.test new file mode 100644 index 0000000000000..3eb96d3defd1c --- /dev/null +++ b/mysql-test/suite/galera_3nodes/t/MDEV-40179_nobinlog.test @@ -0,0 +1,16 @@ +# +# MDEV-40179 - prepared transactions left behind by a mariabackup SST. +# +# log_bin=OFF variant: coverage only. With a single InnoDB read-write engine +# and no binary log, commits use one-phase commit, so transactions never enter +# the XA-prepared state and a mariabackup snapshot has nothing in doubt - the +# bug cannot occur here. This variant just exercises the same load and repeated +# mariabackup SST with log_bin=OFF and checks the cluster reconverges. +# +# See MDEV-40179.inc for the shared test body. +# + +--let $restarts = 8 +--let $writers = 4 +--let $check_gtid = 0 +--source MDEV-40179.inc diff --git a/scripts/wsrep_sst_mariabackup.sh b/scripts/wsrep_sst_mariabackup.sh index f290c9b7e7a79..8d267be22d480 100644 --- a/scripts/wsrep_sst_mariabackup.sh +++ b/scripts/wsrep_sst_mariabackup.sh @@ -1454,37 +1454,49 @@ else # joiner if [ -n "$WSREP_SST_OPT_BINLOG" ]; then cd "$DATA" + # + # MDEV-38147: do NOT move the donor's binary log into + # place on the joiner. + # + # The donor still ships its (freshly rotated) current binary log so + # that an old joiner keeps working and a new joiner can identify + # exactly which file was sent. That file, however, only carries a + # Gtid_list, and its position can be ahead of the engine snapshot + # (BACKUP STAGE BLOCK_COMMIT does not pause commits if mariabackup + # is used for SST). With gtid_strict_mode=ON that ahead position + # makes the joiner raise error 1950 when it re-binlogs transactions + # during IST, and keeping the file could also collide with the + # joiner's own binary log numbering. + # + # Therefore the joiner removes the received binary log file(s) and + # starts a fresh binary log, seeding its GTID position from the + # storage-engine checkpoint during recovery (see + # wsrep_seed_binlog_gtid_state() in sql/log.cc) - the exact position + # from which IST resumes, which keeps the joiner's binary log in + # lockstep with the rest of the cluster. + # binlogs="" if [ -f 'xtrabackup_binlog_info' ]; then - NL=$'\n' while read bin_string || [ -n "$bin_string" ]; do bin_file=$(echo "$bin_string" | cut -f1) - if [ -f "$bin_file" ]; then - binlogs="$binlogs${binlogs:+$NL}$bin_file" + if [ -n "$bin_file" -a -f "$bin_file" ]; then + binlogs="$binlogs${binlogs:+ }$bin_file" fi done < 'xtrabackup_binlog_info' else binlogs=$(ls -d -1 "$binlog_base".[0-9]* 2>/dev/null || :) fi - cd "$DATA_DIR" - if [ -n "$binlog_dir" -a "$binlog_dir" != '.' -a \ - "$binlog_dir" != "$DATA_DIR" ] - then - [ ! -d "$binlog_dir" ] && mkdir -p "$binlog_dir" - fi - index_dir=$(dirname "$binlog_index"); - if [ -n "$index_dir" -a "$index_dir" != '.' -a \ - "$index_dir" != "$DATA_DIR" ] - then - [ ! -d "$index_dir" ] && mkdir -p "$index_dir" - fi if [ -n "$binlogs" ]; then - wsrep_log_info "Moving binary logs to $binlog_dir" - echo "$binlogs" | \ - while read bin_file || [ -n "$bin_file" ]; do - mv "$DATA/$bin_file" "$binlog_dir" - echo "$binlog_dir${binlog_dir:+/}$bin_file" >> "$binlog_index" + wsrep_log_info "Removing received binary log(s) so the joiner" \ + "starts a fresh binary log seeded from the" \ + "storage-engine checkpoint" + for bin_file in $binlogs; do + rm -f "$DATA/$bin_file" done + else + wsrep_log_info "No binary log received from donor; the joiner" \ + "will start a fresh binary log seeded from the" \ + "storage-engine checkpoint" fi cd "$OLD_PWD" fi diff --git a/sql/handler.cc b/sql/handler.cc index af27370e26133..8eeffd0082777 100644 --- a/sql/handler.cc +++ b/sql/handler.cc @@ -2556,7 +2556,7 @@ static my_xid wsrep_order_and_check_continuity(XID *list, int len) if (!wsrep_is_wsrep_xid(list + i) || wsrep_xid_seqno(list + i) != cur_seqno + 1) { - WSREP_WARN("Discovered discontinuity in recovered wsrep " + WSREP_INFO("Discovered discontinuity in recovered wsrep " "transaction XIDs. Truncating the recovery list to " "%d entries", i); break; @@ -2843,6 +2843,48 @@ static my_bool xarecover_handlerton(THD *unused, plugin_ref plugin, x <= wsrep_limit) && info->dry_run, info->dry_run)) { +#ifdef WITH_WSREP + /* + MDEV-40179: a wsrep transaction still in the prepared state at the + final recovery pass (the dry run, commit_list == 0) is past the + storage-engine checkpoint and will be re-delivered by IST. + After recovering from SST without binlogs in place the joiner runs + no binlog XA recovery to commit or roll back such transactions, so + without this they would abort startup with "Found N prepared + transactions!". Roll them back here; the cluster re-applies them + from the donor. Non-wsrep (e.g. user XA) prepared transactions are + left untouched and still reported. + + The guard is WSREP_PROVIDER_EXISTS ("a Galera provider is loaded"): + a node configured with a provider will rejoin and receive + these transactions; a standalone node (no provider) cannot, so + there we keep the conservative default and still report them. + */ + if (WSREP_PROVIDER_EXISTS && wsrep_is_wsrep_xid(info->list + i)) + { + int rc= hton->rollback_by_xid(hton, info->list + i); + if (rc == 0) + { + sql_print_information("Rolled back orphan prepared wsrep " + "transaction %lld", (longlong) x); + continue; + } + /* + A failed rollback is critical: the storage engine is left with + a transaction in the prepared state, which blocks purge and will + re-surface at the next recovery. We cannot safely continue, so + flag the error and abort startup (ha_recover() returns non-zero, + which makes the caller unireg_abort()). + */ + sql_print_error("Failed to roll back orphan prepared wsrep " + "transaction %lld during recovery (error %d). " + "The storage engine is left with a transaction in " + "the prepared state; aborting startup.", + (longlong) x, rc); + info->error= true; + break; + } +#endif /* WITH_WSREP */ info->found_my_xids++; continue; } @@ -2892,7 +2934,7 @@ static my_bool xarecover_handlerton(THD *unused, plugin_ref plugin, } } } - if (got < info->len) + if (got < info->len || info->error) break; } } diff --git a/sql/log.cc b/sql/log.cc index d70fe6b9170f7..17221b4623fbc 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -64,6 +64,7 @@ #ifdef WITH_WSREP #include "wsrep_trans_observer.h" #include "wsrep_status.h" +#include "wsrep_xid.h" #endif /* WITH_WSREP */ #ifdef HAVE_REPLICATION @@ -12014,6 +12015,57 @@ int TC_LOG_BINLOG::recover(LOG_INFO *linfo, const char *last_log_name, +#if defined(WITH_WSREP) && defined(HAVE_REPLICATION) +/* + MDEV-38147: A Galera mariabackup SST no longer ships the donor's binary log + (the only thing it carried was a Gtid_list whose position was ahead of the + snapshot, causing error 1950). Instead the joiner starts a fresh binary log, + so its Gtid_list / @@gtid_binlog_pos must be seeded from the recovered wsrep + position - otherwise the joiner would report an empty binlog position until + it re-binlogs new transactions, which breaks its use as an async master. + + The wsrep cluster position lives in the storage-engine checkpoint (restored + by the SST). Async-replica source positions live in mysql.gtid_slave_pos + (also restored from the engine) and are handled separately, so they are not + seeded here. + + The whole cluster binlogs cluster writes under one consistent stream (the + seqno stays in lockstep because every node applies in the same total order). + The domain of that stream depends on the mode: + - wsrep_gtid_mode=ON : wsrep_gtid_domain_id (cluster writes are re-tagged + to it); this is the domain in the checkpoint. + - wsrep_gtid_mode=OFF: gtid_domain_id (cluster writes keep the node's + configured domain, no re-tag). + In both modes the committed cluster seqno is the SE checkpoint seqno, so we + seed that domain's binlog state to the checkpoint position. This is also the + exact position from which IST will resume re-binlogging, so the joiner stays + in lockstep with the rest of the cluster (and, in ON mode, avoids error 1950 + from re-binlogging over an ahead position). +*/ +static void wsrep_seed_binlog_gtid_state() +{ + wsrep_server_gtid_t const eng= wsrep_get_SE_checkpoint(); + if (eng.seqno <= 0) + return; /* not a wsrep node / no position */ + + rpl_gtid eng_gtid; + eng_gtid.domain_id= wsrep_gtid_mode ? eng.domain_id + : global_system_variables.gtid_domain_id; + eng_gtid.server_id= eng.server_id; + eng_gtid.seq_no= eng.seqno; + + rpl_gtid *cur= rpl_global_gtid_binlog_state.find_most_recent(eng_gtid.domain_id); + if (cur && cur->seq_no >= eng_gtid.seq_no) + return; /* binlog state already at or ahead of the checkpoint */ + + sql_print_information("WSREP: seeding binlog GTID state to %u-%u-%llu " + "from the storage-engine checkpoint", + eng_gtid.domain_id, eng_gtid.server_id, + (unsigned long long) eng_gtid.seq_no); + rpl_global_gtid_binlog_state.update_nolock(&eng_gtid, false); +} +#endif /* WITH_WSREP && HAVE_REPLICATION */ + int MYSQL_BIN_LOG::do_binlog_recovery(const char *opt_name, bool do_xa_recovery) { @@ -12048,6 +12100,10 @@ MYSQL_BIN_LOG::do_binlog_recovery(const char *opt_name, bool do_xa_recovery) error= 0; } } +#if defined(WITH_WSREP) && defined(HAVE_REPLICATION) + if (!error && WSREP_PROVIDER_EXISTS) + wsrep_seed_binlog_gtid_state(); +#endif return error; } diff --git a/sql/wsrep_sst.cc b/sql/wsrep_sst.cc index 0e19276835702..b0a0b2cf56668 100644 --- a/sql/wsrep_sst.cc +++ b/sql/wsrep_sst.cc @@ -402,9 +402,6 @@ static bool wsrep_sst_complete (THD* thd, Wsrep_server_state& server_state= Wsrep_server_state::instance(); enum wsrep::server_state::state state= server_state.state(); bool failed= false; - char start_pos_buf[FN_REFLEN]; - ssize_t len= wsrep::print_to_c_str(sst_gtid, start_pos_buf, FN_REFLEN-1); - start_pos_buf[len]='\0'; // Do not call sst_received if we are not in joiner or // initialized state on server. This is because it @@ -419,14 +416,31 @@ static bool wsrep_sst_complete (THD* thd, } else { - WSREP_INFO("SST succeeded for position %s", start_pos_buf); + /* + Note: sst_received() does NOT use sst_gtid (the position reported by + the SST script). It determines the position internally from storage via + Wsrep_server_service::get_position(). + For physical SST methods these two may differ (e.g. the joiner's storage + recovers to an earlier position than the script reported). Log the + position actually adopted, not the script-reported one, to avoid + confusion. + */ + wsrep::gtid const received_gtid= wsrep_get_SE_checkpoint(); + char recv_pos_buf[FN_REFLEN]; + ssize_t const recv_len= + wsrep::print_to_c_str(received_gtid, recv_pos_buf, FN_REFLEN-1); + recv_pos_buf[recv_len > 0 ? recv_len : 0]= '\0'; + WSREP_INFO("SST succeeded for position %s", recv_pos_buf); } } else { + char start_pos_buf[FN_REFLEN]; + ssize_t const len= wsrep::print_to_c_str(sst_gtid, start_pos_buf, FN_REFLEN - 1); + start_pos_buf[len > 0 ? len : 0]= '\0'; + WSREP_ERROR("SST failed for position %s initialized %d server_state %s", - start_pos_buf, - server_state.is_initialized(), + start_pos_buf, server_state.is_initialized(), wsrep::to_c_string(state)); failed= true; }