revision-id: 2888a22521475f734b28ed65d199cfe2a754aed7 (mariadb-10.1.43-100-g2888a225214) parent(s): 5720db2b43491e5aec9265bce9637e00c72fa0aa author: Sujatha committer: Sujatha timestamp: 2020-04-07 19:21:45 +0530 message: MDEV-21117: --tc-heuristic-recover=rollback is not replication safe Problem: ======= When run after master server crash --tc-heuristic-recover=rollback produces inconsistent server state with binlog still containing transactions that were rolled back by the option. Such way recovered server may not be used for replication. Fix: === During "--tc-heuristic-recover=ROLLBACK", query the storage engine to get binlog file name and position corresponding to the last committed transaction. This marks the consistent binlog state. If last_commit_file is not set then checkpoint binary log file is considered as starting point. Look for first transactional event beyond the consistent binlog state. This will be the starting point for heuristic rollback. Consider this event specific starting point as binlog truncation position. Now traverse the rest of binlogs beyond this point. During this traversal check for the presence of DDL or non transactional operations, as they cannot be safely rolled back. If such events are found the truncation will not happen it will return an error. If only transactional events are found beyond the binlog truncation position it is safe to truncate binlog. The log gets truncated to the identified position and the GTID state is adjusted accordingly. If there are more binary logs beyond the being truncated file they are all removed. --- .../r/binlog_heuristic_rollback_active_log.result | 18 + .../binlog/r/binlog_truncate_multi_log.result | 21 + .../suite/binlog/r/binlog_truncate_none.result | 42 ++ .../t/binlog_heuristic_rollback_active_log.test | 75 ++++ .../suite/binlog/t/binlog_truncate_multi_log.test | 81 ++++ .../suite/binlog/t/binlog_truncate_none.test | 130 ++++++ .../suite/rpl/r/rpl_heuristic_fail_over.result | 53 +++ .../suite/rpl/t/rpl_heuristic_fail_over.test | 160 +++++++ sql/log.cc | 479 ++++++++++++++++++++- sql/log.h | 7 +- storage/innobase/handler/ha_innodb.cc | 3 + storage/xtradb/handler/ha_innodb.cc | 3 + 12 files changed, 1068 insertions(+), 4 deletions(-) diff --git a/mysql-test/suite/binlog/r/binlog_heuristic_rollback_active_log.result b/mysql-test/suite/binlog/r/binlog_heuristic_rollback_active_log.result new file mode 100644 index 00000000000..eff95d05aac --- /dev/null +++ b/mysql-test/suite/binlog/r/binlog_heuristic_rollback_active_log.result @@ -0,0 +1,18 @@ +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); +RESET MASTER; +CREATE TABLE t ( f INT ) ENGINE=INNODB; +INSERT INTO t VALUES (10); +SET DEBUG_SYNC= "commit_before_update_end_pos SIGNAL con1_ready WAIT_FOR con1_go"; +INSERT INTO t VALUES (20); +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; +# Kill the server +"One row should be present in table 't'" +SELECT COUNT(*) FROM t; +COUNT(*) +1 +"gtid_binlog_state should be 0-1-2 +SELECT @@GLOBAL.gtid_binlog_state; +@@GLOBAL.gtid_binlog_state +0-1-2 +DROP TABLE t; diff --git a/mysql-test/suite/binlog/r/binlog_truncate_multi_log.result b/mysql-test/suite/binlog/r/binlog_truncate_multi_log.result new file mode 100644 index 00000000000..9796a480cca --- /dev/null +++ b/mysql-test/suite/binlog/r/binlog_truncate_multi_log.result @@ -0,0 +1,21 @@ +SET @old_max_binlog_size= @@global.max_binlog_size; +SET GLOBAL max_binlog_size= 4096; +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); +RESET MASTER; +CREATE TABLE t1 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +SET DEBUG_SYNC= "commit_before_update_end_pos SIGNAL con1_ready WAIT_FOR con1_go"; +INSERT INTO t1 VALUES (2, REPEAT("x", 4100)); +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; +# Kill the server +"Zero rows shoule be present in table" +SELECT COUNT(*) FROM t1; +COUNT(*) +0 +SELECT @@GLOBAL.gtid_current_pos; +@@GLOBAL.gtid_current_pos +0-1-1 +DROP TABLE t1; +SELECT @@GLOBAL.gtid_binlog_state; +@@GLOBAL.gtid_binlog_state +0-1-2 diff --git a/mysql-test/suite/binlog/r/binlog_truncate_none.result b/mysql-test/suite/binlog/r/binlog_truncate_none.result new file mode 100644 index 00000000000..bae87985208 --- /dev/null +++ b/mysql-test/suite/binlog/r/binlog_truncate_none.result @@ -0,0 +1,42 @@ +SET @old_max_binlog_size= @@global.max_binlog_size; +SET GLOBAL max_binlog_size= 4096; +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); +RESET MASTER; +CREATE TABLE t1 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +INSERT INTO t1 VALUES (1, REPEAT("x", 4100)); +CREATE TABLE t2 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +show binary logs; +Log_name File_size +master-bin.000001 # +master-bin.000002 # +# Kill the server +"Zero records should be there." +SELECT COUNT(*) FROM t1; +COUNT(*) +1 +show binary logs; +Log_name File_size +master-bin.000001 # +master-bin.000002 # +master-bin.000003 # +master-bin.000004 # +DROP TABLE t1,t2; +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); +RESET MASTER; +CREATE TABLE t1 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +CREATE TABLE t2 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +show binary logs; +Log_name File_size +master-bin.000001 # +# Kill the server +"Zero records should be there." +SELECT COUNT(*) FROM t1; +COUNT(*) +0 +SHOW TABLES; +Tables_in_test +t1 +t2 +DROP TABLE t1,t2; diff --git a/mysql-test/suite/binlog/t/binlog_heuristic_rollback_active_log.test b/mysql-test/suite/binlog/t/binlog_heuristic_rollback_active_log.test new file mode 100644 index 00000000000..87af83a7a92 --- /dev/null +++ b/mysql-test/suite/binlog/t/binlog_heuristic_rollback_active_log.test @@ -0,0 +1,75 @@ +# ==== Purpose ==== +# +# Test verifies the truncation of single binary log file. +# +# ==== Implementation ==== +# +# Steps: +# 0 - Create table t1 and insert a row. +# 1 - Insert an another row such that it gets written to binlog but commit +# in engine fails as server crashed at this point. +# 2 - Restart server with --tc-heuristic-recover=ROLLBACK +# 3 - Upon server start 'master-bin.000001' will be truncated to contain +# only the first insert +# +# ==== References ==== +# +# MDEV-21117: --tc-heuristic-recover=rollback is not replication safe + + +--source include/have_innodb.inc +--source include/have_log_bin.inc +--source include/have_debug.inc +--source include/have_binlog_format_statement.inc + +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); + +connect(master,localhost,root,,); +connect(master1,localhost,root,,); + +--connection master +RESET MASTER; +CREATE TABLE t ( f INT ) ENGINE=INNODB; +INSERT INTO t VALUES (10); + +--connection master1 +# Hold insert after write to binlog and before "run_commit_ordered" in engine +SET DEBUG_SYNC= "commit_before_update_end_pos SIGNAL con1_ready WAIT_FOR con1_go"; +send INSERT INTO t VALUES (20); + +--connection master +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; + +--write_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +wait +EOF + +--source include/kill_mysqld.inc +--source include/wait_until_disconnected.inc +# +# Server restart +# +--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +restart: --tc-heuristic-recover=ROLLBACK +EOF +--source include/wait_until_disconnected.inc + +--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +restart: +EOF + +connection default; +--enable_reconnect +--source include/wait_until_connected_again.inc + +--connection master +--enable_reconnect +--source include/wait_until_connected_again.inc + +--echo "One row should be present in table 't'" +SELECT COUNT(*) FROM t; + +--echo "gtid_binlog_state should be 0-1-2 +SELECT @@GLOBAL.gtid_binlog_state; +DROP TABLE t; diff --git a/mysql-test/suite/binlog/t/binlog_truncate_multi_log.test b/mysql-test/suite/binlog/t/binlog_truncate_multi_log.test new file mode 100644 index 00000000000..976b987d3bc --- /dev/null +++ b/mysql-test/suite/binlog/t/binlog_truncate_multi_log.test @@ -0,0 +1,81 @@ +# ==== Purpose ==== +# +# Test verifies truncation of multiple binary logs. +# +# ==== Implementation ==== +# +# Steps: +# 0 - Set max_binlog_size= 4096. Create a table do an insert such that the +# max_binlog_size is reached and binary log gets rotated. +# 1 - Using debug simulation make the server crash at a point where the DML +# transaction is written to binary log but not committed in engine. +# 2 - At the time of crash two binary logs will be there master-bin.0000001 +# and master-bin.000002. +# 3 - Restart server with --tc-heuristic-recover=ROLLBACK +# 4 - Since the prepared DML in master-bin.000001 is rolled back the first +# binlog will be truncated prior to the DML and master-bin.000002 will be +# removed. +# +# ==== References ==== +# +# MDEV-21117: --tc-heuristic-recover=rollback is not replication safe + + +--source include/have_innodb.inc +--source include/have_log_bin.inc +--source include/have_debug.inc +--source include/have_debug_sync.inc +--source include/have_binlog_format_row.inc + +SET @old_max_binlog_size= @@global.max_binlog_size; +SET GLOBAL max_binlog_size= 4096; + +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); + +RESET MASTER; + +CREATE TABLE t1 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; + +connect(master1,localhost,root,,); +connect(master2,localhost,root,,); + +--connection master1 +# Hold insert after write to binlog and before "run_commit_ordered" in engine +SET DEBUG_SYNC= "commit_before_update_end_pos SIGNAL con1_ready WAIT_FOR con1_go"; +send INSERT INTO t1 VALUES (2, REPEAT("x", 4100)); + +--connection master2 +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; + +--write_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +wait +EOF + +--source include/kill_mysqld.inc +--source include/wait_until_disconnected.inc + +# +# Server restart +# +--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +restart: --tc-heuristic-recover=ROLLBACK --debug-dbug=d,simulate_innodb_forget_commit_pos +EOF +--source include/wait_until_disconnected.inc + +--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +restart: +EOF + +connection default; +--enable_reconnect +--source include/wait_until_connected_again.inc + +--echo "Zero rows shoule be present in table" +SELECT COUNT(*) FROM t1; + +SELECT @@GLOBAL.gtid_current_pos; + +DROP TABLE t1; +SELECT @@GLOBAL.gtid_binlog_state; + diff --git a/mysql-test/suite/binlog/t/binlog_truncate_none.test b/mysql-test/suite/binlog/t/binlog_truncate_none.test new file mode 100644 index 00000000000..cc3fd4f0b37 --- /dev/null +++ b/mysql-test/suite/binlog/t/binlog_truncate_none.test @@ -0,0 +1,130 @@ +# ==== Purpose ==== +# +# Test case verifies no binlog truncation happens when non transactional +# events are found in binlog after the last committed transaction. +# +# ==== Implementation ==== +# +# Steps: +# 0 - Set max_binlog_size= 4096. Create a table and do an insert such that +# the max_binlog_size is reached and binary log gets rotated. +# 1 - Create a table in newly created binary log and crash the server +# 2 - Restart server with --tc-heuristic-recover=ROLLBACK +# 3 - Recovery code will get the last committed DML specific postion and +# will try to check if binlog can be truncated upto this position. +# Since a DDL is present beyond this no truncation will happen. +# ==== References ==== +# +# MDEV-21117: --tc-heuristic-recover=rollback is not replication safe + + +--source include/have_innodb.inc +--source include/have_log_bin.inc +--source include/have_debug.inc +--source include/have_binlog_format_row.inc + +SET @old_max_binlog_size= @@global.max_binlog_size; +SET GLOBAL max_binlog_size= 4096; + +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); + +RESET MASTER; + +CREATE TABLE t1 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +INSERT INTO t1 VALUES (1, REPEAT("x", 4100)); +CREATE TABLE t2 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +--source include/show_binary_logs.inc + +--write_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +wait +EOF + +--source include/kill_mysqld.inc +--source include/wait_until_disconnected.inc + +# +# Server restart +# +--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +restart: --tc-heuristic-recover=ROLLBACK +EOF +--source include/wait_until_disconnected.inc + +--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +restart: +EOF + +connection default; +--enable_reconnect +--source include/wait_until_connected_again.inc + +--echo "Zero records should be there." +SELECT COUNT(*) FROM t1; +--source include/show_binary_logs.inc +DROP TABLE t1,t2; + +# ==== Purpose ==== +# +# Test case verifies no binlog truncation happens when only DDLs are present in +# the binary log. Since none of the DMLs are performed in storage engine, +# Engine will not have last committed transaction file name or position. +# Truncation code should return success. +# +# ==== Implementation ==== +# +# Steps: +# 0 - Create two table t1, t2 +# 1 - Kill and restart server with --tc-heuristic-recover=ROLLBACK +# 2 - Only DDL statements are present in the binary log. Since +# no DML was performed engine will not have last commited transaction +# specific binary log name and position. Since no transactional events +# are found, truncation code should simply return. +# +# ==== References ==== +# +# MDEV-21117: --tc-heuristic-recover=rollback is not replication safe + + +--source include/have_innodb.inc +--source include/have_log_bin.inc +--source include/have_debug.inc +--source include/have_binlog_format_row.inc + +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); + +RESET MASTER; + +CREATE TABLE t1 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +CREATE TABLE t2 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +--source include/show_binary_logs.inc + +--write_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +wait +EOF + +--source include/kill_mysqld.inc +--source include/wait_until_disconnected.inc + +# +# Server restart +# +--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +restart: --tc-heuristic-recover=ROLLBACK --debug-dbug=d,simulate_innodb_forget_commit_pos +EOF +--source include/wait_until_disconnected.inc + +--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +restart: +EOF + +connection default; +--enable_reconnect +--source include/wait_until_connected_again.inc + +--echo "Zero records should be there." +SELECT COUNT(*) FROM t1; +SHOW TABLES; +DROP TABLE t1,t2; + diff --git a/mysql-test/suite/rpl/r/rpl_heuristic_fail_over.result b/mysql-test/suite/rpl/r/rpl_heuristic_fail_over.result new file mode 100644 index 00000000000..8391245ba27 --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_heuristic_fail_over.result @@ -0,0 +1,53 @@ +include/rpl_init.inc [topology=1->2] +include/stop_slave.inc +set global rpl_semi_sync_slave_enabled = 1; +CHANGE MASTER TO master_use_gtid= current_pos; +include/start_slave.inc +ALTER TABLE mysql.gtid_slave_pos ENGINE=InnoDB; +set global rpl_semi_sync_master_enabled = 1; +set global rpl_semi_sync_master_wait_point=AFTER_SYNC; +SET @old_max_binlog_size= @@global.max_binlog_size; +SET GLOBAL max_binlog_size= 4096; +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); +CREATE TABLE t1 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +INSERT INTO t1 VALUES (1, 'dummy1'); +SET DEBUG_SYNC= "commit_before_update_end_pos SIGNAL con1_ready WAIT_FOR con1_go"; +INSERT INTO t1 VALUES (2, REPEAT("x", 4100)); +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; +# Kill the server +include/stop_slave.inc +SELECT @@GLOBAL.gtid_current_pos; +@@GLOBAL.gtid_current_pos +0-1-5 +FOUND /Crashed binlog file \.\/master\-bin\.000001 size is [0-9]*, but truncated to */ in mysqld.1.err +set global rpl_semi_sync_master_enabled = 1; +set global rpl_semi_sync_master_wait_point=AFTER_SYNC; +CHANGE MASTER TO master_host='127.0.0.1', master_port=SERVER_MYPORT_2, master_user='root', master_use_gtid=CURRENT_POS; +set global rpl_semi_sync_slave_enabled = 1; +include/start_slave.inc +INSERT INTO t1 VALUES (3, 'dummy3'); +SELECT COUNT(*) FROM t1; +COUNT(*) +2 +SHOW VARIABLES LIKE 'gtid_current_pos'; +Variable_name Value +gtid_current_pos 0-2-6 +SHOW VARIABLES LIKE 'gtid_current_pos'; +Variable_name Value +gtid_current_pos 0-2-6 +DROP TABLE t1; +set global rpl_semi_sync_master_enabled = 0; +set global rpl_semi_sync_slave_enabled = 0; +set global rpl_semi_sync_master_wait_point=default; +set global rpl_semi_sync_master_enabled = 0; +set global rpl_semi_sync_slave_enabled = 0; +set global rpl_semi_sync_master_wait_point=default; +include/stop_slave.inc +RESET MASTER; +RESET SLAVE; +RESET MASTER; +RESET SLAVE; +CHANGE MASTER TO master_host='127.0.0.1', master_port=SERVER_MYPORT_1, master_user='root', master_use_gtid=no; +include/start_slave.inc +include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_heuristic_fail_over.test b/mysql-test/suite/rpl/t/rpl_heuristic_fail_over.test new file mode 100644 index 00000000000..5e9273de62d --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_heuristic_fail_over.test @@ -0,0 +1,160 @@ +# ==== Purpose ==== +# +# Test verifies replication failover scenario. +# +# ==== Implementation ==== +# +# Steps: +# 0 - Have two servers with id's 1 and 2. Enable semi-sync based +# replication. Have semi sync master wait point as 'after_sync'. +# 1 - Create a table and insert a row. While inserting second row simulate +# a server crash at once the transaction is written to binlog, flushed +# and synced but the binlog position is not updated. +# 2 - Restart the server using tc-heuristic-recover=ROLLBACK +# 3 - Post restart switch the crashed master to slave. Execute CHANGE MASTER +# TO command to connect to server id 2. +# 4 - Slave should be able to connect to master. +# 5 - Execute some DML on new master with server id 2. Ensure that it gets +# replicated to server id 1. +# 6 - Verify the "gtid_current_pos" for correctness. +# 7 - Clean up +# +# ==== References ==== +# +# MDEV-21117: --tc-heuristic-recover=rollback is not replication safe + + +--source include/have_semisync.inc +--source include/have_innodb.inc +--source include/have_log_bin.inc +--source include/have_debug.inc +--source include/have_debug_sync.inc +--source include/have_binlog_format_row.inc +--let $rpl_topology=1->2 +--source include/rpl_init.inc + +--connection server_2 +--source include/stop_slave.inc +set global rpl_semi_sync_slave_enabled = 1; +CHANGE MASTER TO master_use_gtid= current_pos; +--source include/start_slave.inc + + +--connection server_1 +ALTER TABLE mysql.gtid_slave_pos ENGINE=InnoDB; +set global rpl_semi_sync_master_enabled = 1; +set global rpl_semi_sync_master_wait_point=AFTER_SYNC; +SET @old_max_binlog_size= @@global.max_binlog_size; +SET GLOBAL max_binlog_size= 4096; + +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); + +CREATE TABLE t1 (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +INSERT INTO t1 VALUES (1, 'dummy1'); +--save_master_pos + +--connection server_2 +--sync_with_master + +--connection server_1 +connect(master1,localhost,root,,); +connect(master2,localhost,root,,); + +--connection master1 +# Hold insert after write to binlog and before "run_commit_ordered" in engine +SET DEBUG_SYNC= "commit_before_update_end_pos SIGNAL con1_ready WAIT_FOR con1_go"; +send INSERT INTO t1 VALUES (2, REPEAT("x", 4100)); + +--connection master2 +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; +--write_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +wait +EOF + +--source include/kill_mysqld.inc +--source include/wait_until_disconnected.inc + +--connection server_2 +--error 2003 +--source include/stop_slave.inc +SELECT @@GLOBAL.gtid_current_pos; + +--connection server_1 +# +# Server restart +# +--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +restart: --tc-heuristic-recover=ROLLBACK +EOF +--source include/wait_until_disconnected.inc + +--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect +restart: +EOF + +connection default; +--enable_reconnect +--source include/wait_until_connected_again.inc + +--connection server_1 +--enable_reconnect +--source include/wait_until_connected_again.inc + +# Check error log for correct messages. +let $log_error_= `SELECT @@GLOBAL.log_error`; +if(!$log_error_) +{ + # MySQL Server on windows is started with --console and thus + # does not know the location of its .err log, use default location + let $log_error_ = $MYSQLTEST_VARDIR/log/mysqld.1.err; +} +--let SEARCH_FILE=$log_error_ +--let SEARCH_RANGE=-50000 +--let SEARCH_PATTERN=Crashed binlog file \.\/master\-bin\.000001 size is [0-9]*, but truncated to * +--source include/search_pattern_in_file.inc + +--connection server_2 +set global rpl_semi_sync_master_enabled = 1; +set global rpl_semi_sync_master_wait_point=AFTER_SYNC; + +--connection server_1 +--replace_result $SERVER_MYPORT_2 SERVER_MYPORT_2 +eval CHANGE MASTER TO master_host='127.0.0.1', master_port=$SERVER_MYPORT_2, master_user='root', master_use_gtid=CURRENT_POS; +set global rpl_semi_sync_slave_enabled = 1; +--source include/start_slave.inc + +--connection server_2 +INSERT INTO t1 VALUES (3, 'dummy3'); +--save_master_pos + +--connection server_1 +--sync_with_master +SELECT COUNT(*) FROM t1; +SHOW VARIABLES LIKE 'gtid_current_pos'; + +--connection server_2 +SHOW VARIABLES LIKE 'gtid_current_pos'; +DROP TABLE t1; +set global rpl_semi_sync_master_enabled = 0; +set global rpl_semi_sync_slave_enabled = 0; +set global rpl_semi_sync_master_wait_point=default; +--save_master_pos + +--connection server_1 +--sync_with_master +set global rpl_semi_sync_master_enabled = 0; +set global rpl_semi_sync_slave_enabled = 0; +set global rpl_semi_sync_master_wait_point=default; +--source include/stop_slave.inc +RESET MASTER; +RESET SLAVE; + +--connection server_2 +RESET MASTER; +RESET SLAVE; +--replace_result $SERVER_MYPORT_1 SERVER_MYPORT_1 +eval CHANGE MASTER TO master_host='127.0.0.1', master_port=$SERVER_MYPORT_1, master_user='root', master_use_gtid=no; +--source include/start_slave.inc + +--source include/rpl_end.inc diff --git a/sql/log.cc b/sql/log.cc index 0efef6d1e29..f383033e975 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -3164,6 +3164,7 @@ MYSQL_BIN_LOG::MYSQL_BIN_LOG(uint *sync_period) checksum_alg_reset(BINLOG_CHECKSUM_ALG_UNDEF), relay_log_checksum_alg(BINLOG_CHECKSUM_ALG_UNDEF), description_event_for_exec(0), description_event_for_queue(0), + last_commit_pos_offset(0), current_binlog_id(0) { /* @@ -3173,6 +3174,7 @@ MYSQL_BIN_LOG::MYSQL_BIN_LOG(uint *sync_period) before main(). */ index_file_name[0] = 0; + last_commit_pos_file[0]= 0; bzero((char*) &index_file, sizeof(index_file)); bzero((char*) &purge_index_file, sizeof(purge_index_file)); } @@ -7877,6 +7879,7 @@ MYSQL_BIN_LOG::trx_group_commit_leader(group_commit_entry *leader) first= false; } + DEBUG_SYNC(leader->thd, "commit_before_update_end_pos"); /* update binlog_end_pos so it can be read by dump thread * * note: must be _after_ the RUN_HOOK(after_flush) or else @@ -8964,7 +8967,7 @@ int TC_LOG_MMAP::open(const char *opt_name) { if (my_errno != ENOENT) goto err; - if (using_heuristic_recover()) + if (using_heuristic_recover(opt_name)) return 1; if ((fd= mysql_file_create(key_file_tclog, logname, CREATE_MODE, O_RDWR | O_CLOEXEC, MYF(MY_WME))) < 0) @@ -9497,14 +9500,42 @@ TC_LOG_MMAP tc_log_mmap; 1 heuristic recovery was performed */ -int TC_LOG::using_heuristic_recover() +int TC_LOG::using_heuristic_recover(const char* opt_name) { + LOG_INFO log_info; + int error; + if (!tc_heuristic_recover) return 0; sql_print_information("Heuristic crash recovery mode"); + if (ha_recover(0)) + { sql_print_error("Heuristic crash recovery failed"); + } + + /* + Check if TC log is referring to binary log not memory map. Ensure that + tc_heuristic_recover being ROLLBACK". If both match initiate binlog + truncation mechanism. + */ + if (!strcmp(opt_name,opt_bin_logname) && + tc_heuristic_recover == TC_HEURISTIC_RECOVER_ROLLBACK) + { + if ((error= mysql_bin_log.find_log_pos(&log_info, NullS, 1))) + { + if (error != LOG_INFO_EOF) + sql_print_error("find_log_pos() failed (error: %d)", error); + } + else + { + if ((error= heuristic_binlog_rollback())) + sql_print_error("Heuristic crash recovery failed to remove " + "rolled back trancations from binary log"); + } + } + sql_print_information("Please restart mysqld without --tc-heuristic-recover"); return 1; } @@ -9512,6 +9543,448 @@ int TC_LOG::using_heuristic_recover() /****** transaction coordinator log for 2pc - binlog() based solution ******/ #define TC_LOG_BINLOG MYSQL_BIN_LOG +/** + Truncates the current binlog to specified position. Removes the rest of binlogs + which are present after this binlog file. + + @param truncate_file Holds the binlog name to be truncated + @param truncate_pos Position within binlog from where it needs to + truncated. + + @retval true ok + @retval false error + +*/ +bool MYSQL_BIN_LOG::truncate_and_remove_binlogs(const char *truncate_file, + my_off_t truncate_pos) +{ + int error= 0; +#ifdef HAVE_REPLICATION + LOG_INFO log_info; + THD *thd= current_thd; + my_off_t index_file_offset=0; + File file= -1; + MY_STAT s; + my_off_t binlog_size; + + if ((error= open_purge_index_file(TRUE))) + { + sql_print_error("MYSQL_BIN_LOG::purge_logs failed to sync the index file."); + goto err; + } + + if ((error=find_log_pos(&log_info, truncate_file, 1))) + goto err; + + while (!(error= find_next_log(&log_info, 1))) + { + if (!index_file_offset) + index_file_offset= log_info.index_file_start_offset; + if((error= register_purge_index_entry(log_info.log_file_name))) + { + sql_print_error("MYSQL_BIN_LOG::purge_logs failed to copy %s to register file.", + log_info.log_file_name); + goto err; + } + } + + if (error != LOG_INFO_EOF) + { + sql_print_error("Error while looking for next binlog file to be truncated. " + "Error:%d", error); + goto err; + } + + if (!index_file_offset) + index_file_offset= log_info.index_file_start_offset; + + if ((error= sync_purge_index_file())) + { + sql_print_error("MYSQL_BIN_LOG::purge_logs failed to flush register file."); + goto err; + } + + DBUG_ASSERT(index_file_offset != 0); + // Trim index file + if (mysql_file_chsize(index_file.file, index_file_offset, '\n', MYF(MY_WME)) || + mysql_file_sync(index_file.file, MYF(MY_WME|MY_SYNC_FILESIZE))) + { + sql_print_error("Failed to trim binlog index file " + "when master server is recovering it."); + mysql_file_close(index_file.file, MYF(MY_WME)); + goto err; + } + + /* Reset data in old index cache */ + reinit_io_cache(&index_file, READ_CACHE, (my_off_t) 0, 0, 1); + + /* Read each entry from purge_index_file and delete the file. */ + if (is_inited_purge_index_file() && + (error= purge_index_entry(thd, NULL, TRUE))) + { + sql_print_error("MYSQL_BIN_LOG::purge_logs failed to process registered files" + " that would be purged."); + goto err; + } + + if (truncate_pos) + { + if ((file= mysql_file_open(key_file_binlog, truncate_file, + O_RDWR | O_BINARY, MYF(MY_WME))) < 0) + { + sql_print_error("Failed to open binlog file:%s for truncation.", + truncate_file); + error= 1; + goto err; + } + my_stat(truncate_file, &s, MYF(0)); + binlog_size= s.st_size; + + /* Change binlog file size to truncate_pos */ + if (mysql_file_chsize(file, truncate_pos, 0, MYF(MY_WME)) || + mysql_file_sync(file, MYF(MY_WME|MY_SYNC_FILESIZE))) + { + sql_print_error("Failed to trim the crashed binlog file:%s to size:%llu", + truncate_file, truncate_pos); + mysql_file_close(file, MYF(MY_WME)); + error= 1; + goto err; + } + else + { + sql_print_information("Crashed binlog file %s size is %llu, " + "but truncated to %llu.", + truncate_file, binlog_size, truncate_pos); + } + mysql_file_close(file, MYF(MY_WME)); + file= -1; + } + +err: + if (file >= 0) + mysql_file_close(file, MYF(MY_WME)); + close_purge_index_file(); +#endif + return error; +} + +/** + Returns the checkpoint binlog file name found in the lastest binlog file. + + @param checkpoint_file Holds the binlog checkpoint file name. + + @retval 0 ok + @retval 1 error + +*/ +int TC_LOG_BINLOG::get_binlog_checkpoint_file(char* checkpoint_file) +{ + Log_event *ev= NULL; + bool binlog_checkpoint_found= false; + LOG_INFO log_info; + const char *errmsg; + IO_CACHE log; + File file; + Format_description_log_event fdle(BINLOG_VERSION); + char log_name[FN_REFLEN]; + int error=1; + + if (!fdle.is_valid()) + return 1; + + if ((error= find_log_pos(&log_info, NullS, 1))) + { + sql_print_error("find_log_pos() failed (error: %d)", error); + return error; + } + + // Move to the last binary log. + do + { + strmake_buf(log_name, log_info.log_file_name); + } while (!(error= find_next_log(&log_info, 1))); + + if (error != LOG_INFO_EOF) + { + sql_print_error("find_log_pos() failed (error: %d)", error); + return error; + } + if ((file= open_binlog(&log, log_name, &errmsg)) < 0) + { + sql_print_error("%s", errmsg); + return error; + } + while (!binlog_checkpoint_found && + (ev= Log_event::read_log_event(&log, 0, &fdle, + opt_master_verify_checksum)) && + ev->is_valid()) + { + enum Log_event_type typ= ev->get_type_code(); + if (typ == BINLOG_CHECKPOINT_EVENT) + { + uint dir_len; + Binlog_checkpoint_log_event *cev= (Binlog_checkpoint_log_event *)ev; + if (cev->binlog_file_len >= FN_REFLEN) + { + sql_print_error("Incorrect binlog checkpoint event with too " + "long file name found."); + delete ev; + ev= NULL; + end_io_cache(&log); + mysql_file_close(file, MYF(MY_WME)); + return 1; + } + else + { + dir_len= dirname_length(log_name); + strmake(strnmov(checkpoint_file, log_name, dir_len), + cev->binlog_file_name, FN_REFLEN - 1 - dir_len); + binlog_checkpoint_found= true; + } + } + delete ev; + ev= NULL; + } // End of while + end_io_cache(&log); + mysql_file_close(file, MYF(MY_WME)); + file= -1; + /* + Old binary log without checkpoint found, binlog truncation is not + possible. Hence return error. + */ + if (!binlog_checkpoint_found) + return 1; + else + { + // Look for binlog checkpoint file in binlog index file. + if (find_log_pos(&log_info, checkpoint_file, 1)) + { + sql_print_error("Binlog file '%s' not found in binlog index, needed " + "for recovery. Aborting.", checkpoint_file); + return 1; + } + } + return 0; +} + + +/** + Truncates the binary log, according to the transactions that got rolled + back from engine, during heuristic-recover=ROLLBACK. Global GTID state is + adjusted as per the truncated binlog. + + Called from @c TC_LOG::using_heuristic_recover(const char* opt_name) + + @param opt_name The base name of binary log. + + @return indicates success or failure of binlog rollback + @retval 0 success + @retval 1 failure + +*/ +int TC_LOG_BINLOG::heuristic_binlog_rollback() +{ + int error=0; +#ifdef HAVE_REPLICATION + Log_event *ev= NULL; + char engine_commit_file[FN_REFLEN]; + char binlog_truncate_file_name[FN_REFLEN]; + char checkpoint_file[FN_REFLEN]; + my_off_t binlog_truncate_pos= 0; + my_off_t engine_commit_pos= 0; + LOG_INFO log_info; + const char *errmsg; + IO_CACHE log; + File file; + Format_description_log_event fdle(BINLOG_VERSION); + bool found_engine_commit_pos= false; + bool found_truncate_pos= false; + bool is_safe= true; + my_off_t tmp_truncate_pos=0; + rpl_gtid last_gtid; + bool last_gtid_standalone= false; + bool last_gtid_valid= false; + + if (!fdle.is_valid()) + return 1; + + DBUG_EXECUTE_IF("simulate_innodb_forget_commit_pos", + { + last_commit_pos_file[0]= 0; + };); + + // Initialize engine_commit_file/pos + if (last_commit_pos_file[0] != 0) + { + strmake_buf(engine_commit_file, last_commit_pos_file); + engine_commit_pos= last_commit_pos_offset; + } + else + { + if ((error= get_binlog_checkpoint_file(checkpoint_file))) + return error; + strmake_buf(engine_commit_file, checkpoint_file); + } + + // Look for last last_commit_pos_file in binlog index file + if ((error= find_log_pos(&log_info, engine_commit_file, 1))) + { + sql_print_error("find_log_pos() failed (error: %d)", error); + return error; + } + if ((file= open_binlog(&log, log_info.log_file_name, &errmsg)) < 0) + { + sql_print_error("Failed to open the binlog:%s for recovery. Error: %s", + binlog_truncate_file_name, errmsg); + goto err; + } + + /* + If there is no engine specific commit file we are doing checkpoint file + based recovery. Hence we mark "found_engine_commit_pos" true. Next start + looking for the first transactional event group with is the candidate for + rollback. + */ + if (engine_commit_pos == 0) + found_engine_commit_pos= true; + + error= read_state_from_file(); + if (error && error != 2) + { + sql_print_error("Failed to load global gtid binlog state from file"); + goto err; + } + + for(;;) + { + while (is_safe && (ev= Log_event::read_log_event(&log, 0, &fdle, + opt_master_verify_checksum)) && + ev->is_valid()) + { + enum Log_event_type typ= ev->get_type_code(); + switch (typ) + { + case XID_EVENT: + if (ev->log_pos == engine_commit_pos) + { + found_engine_commit_pos= true; + } + break; + case GTID_LIST_EVENT: + { + Gtid_list_log_event *glev= (Gtid_list_log_event *)ev; + /* Initialise the binlog state from the Gtid_list event. */ + if (!found_truncate_pos && glev->count > 0 && + rpl_global_gtid_binlog_state.load(glev->list, glev->count)) + goto err; + } + break; + case GTID_EVENT: + { + Gtid_log_event *gev= (Gtid_log_event *)ev; + + /* Update the binlog state with any GTID logged after Gtid_list. */ + last_gtid.domain_id= gev->domain_id; + last_gtid.server_id= gev->server_id; + last_gtid.seq_no= gev->seq_no; + last_gtid_standalone= + ((gev->flags2 & Gtid_log_event::FL_STANDALONE) ? true : false); + last_gtid_valid= true; + if (gev->flags2 & Gtid_log_event::FL_TRANSACTIONAL && + !found_truncate_pos) + { + if ((engine_commit_pos == 0 || found_engine_commit_pos)) + { + found_truncate_pos=true; + strmake_buf(binlog_truncate_file_name, log_info.log_file_name); + binlog_truncate_pos= tmp_truncate_pos; + } + } + else + { + if (found_truncate_pos) + is_safe=false; + } + } + break; + default: + /* Nothing. */ + break; + }// End switch + if (!found_truncate_pos && last_gtid_valid && + ((last_gtid_standalone && !ev->is_part_of_group(typ)) || + (!last_gtid_standalone && + (typ == XID_EVENT || + (typ == QUERY_EVENT && + (((Query_log_event *)ev)->is_commit() || + ((Query_log_event *)ev)->is_rollback())))))) + { + if (rpl_global_gtid_binlog_state.update_nolock(&last_gtid, false)) + goto err; + last_gtid_valid= false; + } + // Used to identify the last group specific end position. + tmp_truncate_pos= ev->log_pos; + delete ev; + ev= NULL; + }// End While + end_io_cache(&log); + mysql_file_close(file, MYF(MY_WME)); + file= -1; + + if (is_safe) + { + if ((error=find_next_log(&log_info, 1))) + { + if (error != LOG_INFO_EOF) + { + sql_print_error("Error reading binlog files during recovery. Aborting."); + goto err; + } + else + break; + } + + if ((file= open_binlog(&log, log_info.log_file_name, &errmsg)) < 0) + { + sql_print_error("%s", errmsg); + goto err; + } + } + } //end of for(;;) + if (!found_truncate_pos) + { + return 0; // Nothing to truncate + } + else + DBUG_ASSERT(binlog_truncate_pos > 0); + + if (is_safe) + { + if (truncate_and_remove_binlogs(binlog_truncate_file_name, + binlog_truncate_pos)) + goto err; + } + if (write_state_to_file()) + { + sql_print_error("Failed to save binlog GTID state during heuristic " + "binlog rollback. "); + goto err; + } + return 0; + +err: + error= 1; + if (file >= 0) + { + end_io_cache(&log); + mysql_file_close(file, MYF(MY_WME)); + } + sql_print_error("Binlog truncation failed"); +#endif + return error; +} + int TC_LOG_BINLOG::open(const char *opt_name) { int error= 1; @@ -9526,7 +9999,7 @@ int TC_LOG_BINLOG::open(const char *opt_name) return 1; } - if (using_heuristic_recover()) + if (using_heuristic_recover(opt_name)) { mysql_mutex_lock(&LOCK_log); /* generate a new binlog to mask a corrupted one */ diff --git a/sql/log.h b/sql/log.h index 277e5c6f69c..e91bdd94083 100644 --- a/sql/log.h +++ b/sql/log.h @@ -41,7 +41,8 @@ bool stmt_has_updated_non_trans_table(const THD* thd); class TC_LOG { public: - int using_heuristic_recover(); + int using_heuristic_recover(const char* opt_name); + virtual int heuristic_binlog_rollback() { return 0; }; TC_LOG() {} virtual ~TC_LOG() {} @@ -694,6 +695,7 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG void commit_checkpoint_notify(void *cookie); int recover(LOG_INFO *linfo, const char *last_log_name, IO_CACHE *first_log, Format_description_log_event *fdle, bool do_xa); + int heuristic_binlog_rollback(); int do_binlog_recovery(const char *opt_name, bool do_xa_recovery); #if !defined(MYSQL_CLIENT) @@ -794,6 +796,9 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG int purge_first_log(Relay_log_info* rli, bool included); int set_purge_index_file_name(const char *base_file_name); int open_purge_index_file(bool destroy); + bool truncate_and_remove_binlogs(const char *truncate_file, + my_off_t truncate_pos); + int get_binlog_checkpoint_file(char* checkpoint_file); bool is_inited_purge_index_file(); int close_purge_index_file(); int clean_purge_index_file(); diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc index 4de2cdbeaec..42d655ee0e8 100644 --- a/storage/innobase/handler/ha_innodb.cc +++ b/storage/innobase/handler/ha_innodb.cc @@ -16493,6 +16493,9 @@ innobase_xa_recover( { DBUG_ASSERT(hton == innodb_hton_ptr); + mysql_bin_log.last_commit_pos_offset= trx_sys_mysql_bin_log_pos; + strmake_buf(mysql_bin_log.last_commit_pos_file, trx_sys_mysql_bin_log_name); + if (len == 0 || xid_list == NULL) { return(0); diff --git a/storage/xtradb/handler/ha_innodb.cc b/storage/xtradb/handler/ha_innodb.cc index 2aafb1a44ee..dec106cac54 100644 --- a/storage/xtradb/handler/ha_innodb.cc +++ b/storage/xtradb/handler/ha_innodb.cc @@ -17165,6 +17165,9 @@ innobase_xa_recover( { DBUG_ASSERT(hton == innodb_hton_ptr); + mysql_bin_log.last_commit_pos_offset= trx_sys_mysql_bin_log_pos; + strmake_buf(mysql_bin_log.last_commit_pos_file, trx_sys_mysql_bin_log_name); + if (len == 0 || xid_list == NULL) { return(0);