revision-id: fb963a7fd3b3e0733fb7ad9ece6256aebd8c176c (mariadb-10.1.43-112-gfb963a7fd3b) parent(s): ad4b70562bb94dd063eebde5189c6e730d3120a2 author: Sujatha committer: Sujatha timestamp: 2020-04-21 18:19:34 +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. If recovery is initiated based on last committed transaction specific binary log name and position, and there is failure during recovery, then recovery may be retried by remove the source of the failure. i.e --tc-heuristic-recover=rollback may be retried. Retry will not be successful if recovery is based on checkpoint file. As at the end of tc-heuristic-recover a new binary log file is created which will change the checkpoint file. Appropriate error message is written to error log for each case. --- .../r/binlog_heuristic_rollback_active_log.result | 18 + .../binlog/r/binlog_truncate_multi_log.result | 33 ++ .../r/binlog_truncate_multi_log_unsafe.result | 30 ++ .../suite/binlog/r/binlog_truncate_none.result | 42 ++ .../binlog/r/binlog_truncate_retry_success.result | 28 + .../t/binlog_heuristic_rollback_active_log.test | 75 +++ .../suite/binlog/t/binlog_truncate_multi_log.test | 87 +++ .../binlog/t/binlog_truncate_multi_log_unsafe.test | 106 ++++ .../suite/binlog/t/binlog_truncate_none.test | 130 +++++ .../binlog/t/binlog_truncate_retry_success.test | 84 +++ .../suite/rpl/r/rpl_heuristic_fail_over.result | 53 ++ .../suite/rpl/t/rpl_heuristic_fail_over.test | 160 ++++++ sql/log.cc | 589 ++++++++++++++++++++- sql/log.h | 7 +- sql/mysqld.h | 3 +- storage/innobase/handler/ha_innodb.cc | 7 + storage/innobase/log/log0recv.cc | 5 +- storage/xtradb/handler/ha_innodb.cc | 7 + storage/xtradb/log/log0recv.cc | 5 +- 19 files changed, 1457 insertions(+), 12 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..1a3d49b5463 --- /dev/null +++ b/mysql-test/suite/binlog/r/binlog_truncate_multi_log.result @@ -0,0 +1,33 @@ +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; +FLUSH LOGS; +"List of binary logs before rotation" +show binary logs; +Log_name File_size +master-bin.000001 # +master-bin.000002 # +SET DEBUG_SYNC= "commit_after_release_LOCK_log SIGNAL con1_ready WAIT_FOR con1_go"; +INSERT INTO t1 VALUES (2, REPEAT("x", 4100)); +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; +"List of binary logs after rotation" +show binary logs; +Log_name File_size +master-bin.000001 # +master-bin.000002 # +master-bin.000003 # +# 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_multi_log_unsafe.result b/mysql-test/suite/binlog/r/binlog_truncate_multi_log_unsafe.result new file mode 100644 index 00000000000..5b7d45d81de --- /dev/null +++ b/mysql-test/suite/binlog/r/binlog_truncate_multi_log_unsafe.result @@ -0,0 +1,30 @@ +SET @old_max_binlog_size= @@global.max_binlog_size; +SET GLOBAL max_binlog_size= 4096; +call mtr.add_suppression("Table '.*tm' is marked as crashed and should be repaired"); +call mtr.add_suppression("Got an error from unknown thread"); +call mtr.add_suppression("Checking table: '.*tm'"); +call mtr.add_suppression("Recovering table: '.*tm'"); +call mtr.add_suppression("tc-heuristic-recover cannot trim the binary log to"); +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); +RESET MASTER; +CREATE TABLE ti (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +CREATE TABLE tm (f INT) ENGINE=MYISAM; +SET DEBUG_SYNC= "commit_before_get_LOCK_commit_ordered SIGNAL con1_ready WAIT_FOR con1_go"; +INSERT INTO ti VALUES (2, REPEAT("x", 4100)); +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; +INSERT INTO tm VALUES (30);; +# Kill the server +FOUND /tc-heuristic-recover cannot trim the binary log to File/ in mysqld.1.err +"Zero rows shoule be present in 'ti' table." +SELECT COUNT(*) FROM ti; +COUNT(*) +0 +"One row must be present in 'tm' table." +SELECT COUNT(*) FROM tm; +COUNT(*) +1 +SELECT @@GLOBAL.gtid_current_pos; +@@GLOBAL.gtid_current_pos +0-1-4 +DROP TABLE ti, tm; 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/r/binlog_truncate_retry_success.result b/mysql-test/suite/binlog/r/binlog_truncate_retry_success.result new file mode 100644 index 00000000000..cd0c4c23d05 --- /dev/null +++ b/mysql-test/suite/binlog/r/binlog_truncate_retry_success.result @@ -0,0 +1,28 @@ +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,'dummy'); +SET DEBUG_SYNC= "commit_after_release_LOCK_log SIGNAL con1_ready WAIT_FOR con1_go"; +INSERT INTO t1 VALUES (2,'dummy'); +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; +"List of binary logs" +show binary logs; +Log_name File_size +master-bin.000001 # +# Kill the server +TEST 1: Recovery with error +TEST 2: Recovery without error +"One row shoule be present in table" +SELECT COUNT(*) FROM t1; +COUNT(*) +1 +"Two gtids should be present 0-1-2" +SELECT @@GLOBAL.gtid_current_pos; +@@GLOBAL.gtid_current_pos +0-1-2 +"Two gtids should be present 0-1-3" +DROP TABLE t1; +SELECT @@GLOBAL.gtid_binlog_state; +@@GLOBAL.gtid_binlog_state +0-1-3 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..0a6e011627e --- /dev/null +++ b/mysql-test/suite/binlog/t/binlog_truncate_multi_log.test @@ -0,0 +1,87 @@ +# ==== Purpose ==== +# +# Test verifies truncation of multiple binary logs. +# +# ==== Implementation ==== +# +# Steps: +# 0 - Create a table in innodb engine and execute FLUSH LOGS command to +# generate a new binary log. +# 1 - Set max_binlog_size= 4096. Insert a row such that the max_binlog_size +# is reached and binary log gets rotated. +# 2 - Using debug simulation make the server crash at a point where the DML +# transaction is written to binary log but not committed in engine. +# 3 - At the time of crash three binary logs will be there +# master-bin.0000001, master-bin.000002 and master-bin.000003. +# 4 - Restart server with --tc-heuristic-recover=ROLLBACK +# 5 - Since the prepared DML in master-bin.000002 the binary log will be +# truncated and master-bin.000003 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; +FLUSH LOGS; +connect(master1,localhost,root,,); +connect(master2,localhost,root,,); + +--connection master1 +# Hold insert after write to binlog and before "run_commit_ordered" in engine. +# Use "commit_after_release_LOCK_log" sync point. This point is reached after +# the binary log end position is updated which actually triggers binlog to be +# rotated. +--echo "List of binary logs before rotation" +--source include/show_binary_logs.inc +SET DEBUG_SYNC= "commit_after_release_LOCK_log 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"; +--echo "List of binary logs after rotation" +--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 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_multi_log_unsafe.test b/mysql-test/suite/binlog/t/binlog_truncate_multi_log_unsafe.test new file mode 100644 index 00000000000..cf4f3d34a24 --- /dev/null +++ b/mysql-test/suite/binlog/t/binlog_truncate_multi_log_unsafe.test @@ -0,0 +1,106 @@ +# ==== Purpose ==== +# +# Test verifies truncation of multiple binary logs will report an error on +# unsafe scenario. +# +# ==== Implementation ==== +# +# Steps: +# 0 - Set max_binlog_size= 4096. Create a table 'ti' using transactional +# storage engine. Do an insert such that the max_binlog_size is reached +# and binary log gets rotated. Hold this thread at a position where +# transaction is written to binary log but not committed in engine. +# 1 - Create a table named 'tm' using non transactional storage engine. +# 2 - Insert a row in 'tm' table. The DML will reach the engine and it is +# also written to binary log. +# 3 - Kill and restart the server with --tc-heuristic-recover=ROLLBACK +# 4 - Check for binary log truncation unsafe message in error log. +# 5 - No rows should be present in 'ti' table. One row should be present in +# 'tm' table. +# +# ==== 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("Table '.*tm' is marked as crashed and should be repaired"); +call mtr.add_suppression("Got an error from unknown thread"); +call mtr.add_suppression("Checking table: '.*tm'"); +call mtr.add_suppression("Recovering table: '.*tm'"); +call mtr.add_suppression("tc-heuristic-recover cannot trim the binary log to"); +call mtr.add_suppression("Can't init tc log"); +call mtr.add_suppression("Aborting"); + +RESET MASTER; + +CREATE TABLE ti (a INT PRIMARY KEY, b MEDIUMTEXT) ENGINE=Innodb; +CREATE TABLE tm (f INT) ENGINE=MYISAM; + +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_get_LOCK_commit_ordered SIGNAL con1_ready WAIT_FOR con1_go"; +--send INSERT INTO ti VALUES (2, REPEAT("x", 4100)) + +--connection master2 +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; +--send INSERT INTO tm VALUES (30); + +--connection default +--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 + +# 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=tc-heuristic-recover cannot trim the binary log to File +--source include/search_pattern_in_file.inc + +--echo "Zero rows shoule be present in 'ti' table." +SELECT COUNT(*) FROM ti; +--echo "One row must be present in 'tm' table." +--replace_regex /Table '.*tm/Table 'tm/ +--disable_warnings +SELECT COUNT(*) FROM tm; +--enable_warnings +SELECT @@GLOBAL.gtid_current_pos; + +DROP TABLE ti, tm; 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/binlog/t/binlog_truncate_retry_success.test b/mysql-test/suite/binlog/t/binlog_truncate_retry_success.test new file mode 100644 index 00000000000..6e92667c9b4 --- /dev/null +++ b/mysql-test/suite/binlog/t/binlog_truncate_retry_success.test @@ -0,0 +1,84 @@ +# ==== Purpose ==== +# +# Test verifies that tc-heuristic-recover=ROLLBACK can be retried. +# +# ==== Implementation ==== +# +# Steps: +# 0 - Create a table in Innodb storage engine. Insert a row into the table. +# During the commit of this DML engine will persist last committed +# transaction specific binary log file name and position. +# 1 - Do an another DML into the table, and simulate a crash in the middle +# of DML commit, so that DML is present in binary log but not committed in +# the storage engine. +# 2 - Restart the server using --tc-heuristic-recover=ROLLBACK. Simulate an +# error during the binary log rollback operation. Verify appropriate +# error is reported in the error log. +# 3 - Retry the --tc-heuristic-recver=ROLLBACK operation. Verify that +# binary log gets truncated as expected. +# 4 - Verify that global gtid state is according to the rolled back +# transaction. +# ==== References ==== +# +# MDEV-21117: --tc-heuristic-recover=rollback is not replication safe + + +--source include/have_innodb.inc +--source include/not_embedded.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 + +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,'dummy'); +connect(master1,localhost,root,,); +connect(master2,localhost,root,,); + +--connection master1 +SET DEBUG_SYNC= "commit_after_release_LOCK_log SIGNAL con1_ready WAIT_FOR con1_go"; +send INSERT INTO t1 VALUES (2,'dummy'); + +--connection master2 +SET DEBUG_SYNC= "now WAIT_FOR con1_ready"; +--echo "List of binary logs" +--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 +# +--echo TEST 1: Recovery with error +--error 1 +--exec $MYSQLD_LAST_CMD --tc-heuristic-recover=ROLLBACK --debug-dbug=d,fault_injection_opening_binlog > $MYSQLTEST_VARDIR/log/mysqld.1.err 2>&1 +--source include/wait_until_disconnected.inc + +--echo TEST 2: Recovery without error +--error 1 +--exec $MYSQLD_LAST_CMD --tc-heuristic-recover=ROLLBACK > $MYSQLTEST_VARDIR/log/mysqld.1.err 2>&1 +--source include/wait_until_disconnected.inc + +--source include/start_mysqld.inc + +--echo "One row shoule be present in table" +SELECT COUNT(*) FROM t1; + +--echo "Two gtids should be present 0-1-2" +SELECT @@GLOBAL.gtid_current_pos; + +--echo "Two gtids should be present 0-1-3" +DROP TABLE t1; +SELECT @@GLOBAL.gtid_binlog_state; + +--disconnect master1 +--disconnect master2 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..02fc47def41 --- /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 /tc-heuristic-recover: Truncated binlog File: \.\/master\-bin\.000001 of Size:[0-9]*, to Position */ 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..39b1f7545d0 --- /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=tc-heuristic-recover: Truncated binlog File: \.\/master\-bin\.000001 of Size:[0-9]*, to Position * +--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..66445944b40 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)); } @@ -4576,8 +4578,8 @@ int MYSQL_BIN_LOG::open_purge_index_file(bool destroy) 0, 0, MYF(MY_WME | MY_NABP | MY_WAIT_IF_FULL))) { error= 1; - sql_print_error("MYSQL_BIN_LOG::open_purge_index_file failed to open register " - " file."); + sql_print_error("MYSQL_BIN_LOG::open_purge_index_file failed to open " + "register file."); } } DBUG_RETURN(error); @@ -4742,7 +4744,7 @@ int MYSQL_BIN_LOG::purge_index_entry(THD *thd, ulonglong *reclaimed_space, } goto err; } - + error= 0; DBUG_PRINT("info",("purging %s",log_info.log_file_name)); @@ -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,40 @@ 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"); + } + + 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("tc-heuristic-recover failed in find_log_pos(). " + "Error: %d", error); + } + else + { + if ((error= heuristic_binlog_rollback())) + { + sql_print_error("Heuristic crash recovery of binary log failed."); + return 1; + } + } + } + sql_print_information("Please restart mysqld without --tc-heuristic-recover"); return 1; } @@ -9512,6 +9541,554 @@ 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; + IO_CACHE cache; + MY_STAT s; + my_off_t binlog_size; + + if ((error= find_log_pos(&log_info, truncate_file, 1))) + { + sql_print_error("tc-heuristic-recover: Failed to locate binary log file:%s." + "Error:%d", truncate_file, error); + goto end; + } + + while (!(error= find_next_log(&log_info, 1))) + { + if (!index_file_offset) + { + index_file_offset= log_info.index_file_start_offset; + if ((error= open_purge_index_file(TRUE))) + { + sql_print_error("tc-heuristic-recover: Failed to open purge index " + "file:%s. Error:%d", purge_index_file_name, error); + goto end; + } + } + if ((error= register_purge_index_entry(log_info.log_file_name))) + { + sql_print_error("tc-heuristic-recover: Failed to copy %s to purge index" + " file. Error:%d", log_info.log_file_name, error); + goto end; + } + } + + if (error != LOG_INFO_EOF) + { + sql_print_error("tc-heuristic-recover: Failed to find the next binlog to " + "add to purge index register. Error:%d", error); + goto end; + } + + if (is_inited_purge_index_file()) + { + if (!index_file_offset) + index_file_offset= log_info.index_file_start_offset; + + if ((error= sync_purge_index_file())) + { + sql_print_error("tc-heuristic-recover: Failed to flush purge index " + "file. Error:%d", error); + goto end; + } + + // Trim index file + if ((error= + mysql_file_chsize(index_file.file, index_file_offset, '\n', + MYF(MY_WME))) || + (error= + mysql_file_sync(index_file.file, MYF(MY_WME|MY_SYNC_FILESIZE)))) + { + sql_print_error("tc-heuristic-recover: Failed to trim binlog index " + "file:%s to offset:%llu. Error:%d", index_file_name, + index_file_offset); + mysql_file_close(index_file.file, MYF(MY_WME)); + goto end; + } + + /* Reset data in old index cache */ + if ((error= reinit_io_cache(&index_file, READ_CACHE, (my_off_t) 0, 0, 1))) + { + sql_print_error("tc-heuristic-recover: Failed to reinit binlog index " + "file. Error:%d", error); + mysql_file_close(index_file.file, MYF(MY_WME)); + goto end; + } + + /* Read each entry from purge_index_file and delete the file. */ + if ((error= purge_index_entry(thd, NULL, TRUE))) + { + sql_print_error("tc-heuristic-recover: Failed to process registered " + "files that would be purged."); + goto end; + } + } + + DBUG_ASSERT(truncate_pos); + + if ((file= mysql_file_open(key_file_binlog, truncate_file, + O_RDWR | O_BINARY, MYF(MY_WME))) < 0) + { + error= 1; + sql_print_error("tc-heuristic-recover: Failed to open binlog file:%s for " + "truncation.", truncate_file); + goto end; + } + my_stat(truncate_file, &s, MYF(0)); + binlog_size= s.st_size; + + /* Change binlog file size to truncate_pos */ + if ((error= + mysql_file_chsize(file, truncate_pos, 0, MYF(MY_WME))) || + (error= mysql_file_sync(file, MYF(MY_WME|MY_SYNC_FILESIZE)))) + { + sql_print_error("tc-heuristic-recover: Failed to trim the " + "binlog file:%s to size:%llu. Error:%d", + truncate_file, truncate_pos, error); + goto end; + } + else + { + sql_print_information("tc-heuristic-recover: Truncated binlog " + "File: %s of Size:%llu, to Position:%llu.", + truncate_file, binlog_size, truncate_pos); + } + if (!(error= init_io_cache(&cache, file, IO_SIZE, WRITE_CACHE, + (my_off_t) truncate_pos, 0, MYF(MY_WME|MY_NABP)))) + { + /* + Write Stop_log_event to ensure clean end point for the binary log being + truncated. + */ + Stop_log_event se; + se.checksum_alg= (enum_binlog_checksum_alg) binlog_checksum_options; + if ((error= write_event(&se, &cache))) + { + sql_print_error("tc-heuristic-recover: Failed to write stop event to " + "binary log. Errno:%d", + (cache.error == -1) ? my_errno : error); + goto end; + } + if ((error= flush_io_cache(&cache)) || + (error= mysql_file_sync(file, MYF(MY_WME|MY_SYNC_FILESIZE)))) + { + sql_print_error("tc-heuristic-recover: Faild to write stop event to " + "binary log. Errno:%d", + (cache.error == -1) ? my_errno : error); + } + } + else + sql_print_error("tc-heuristic-recover: Failed to initialize binary log " + "cache for writing stop event. Errno:%d", + (cache.error == -1) ? my_errno : error); + +end: + if (file >= 0) + { + end_io_cache(&cache); + mysql_file_close(file, MYF(MY_WME)); + } + error= error || close_purge_index_file(); +#endif + return error > 0; +} + +/** + 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("tc-heuristic-recover: find_log_pos() failed to read first " + "binary log entry from index file.(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("tc-heuristic-recover: find_next_log() failed " + "(error: %d)", error); + return error; + } + if ((file= open_binlog(&log, log_name, &errmsg)) < 0) + { + sql_print_error("tc-heuristic-recover failed to open the binlog:%s for " + "reading checkpoint file name. Error: %s", + log_info.log_file_name, 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) + { + size_t dir_len; + Binlog_checkpoint_log_event *cev= (Binlog_checkpoint_log_event *)ev; + if (cev->binlog_file_len >= FN_REFLEN) + { + sql_print_error("tc-heuristic-recover: 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; + + 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=-1; + 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; + bool is_checkpoint_based_recovery= false; + + + 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; + sql_print_information("tc-heuristic-recover: Initialising heuristic " + "rollback of binary log using last committed " + "transaction specific binary log name:%s and " + "position:%llu", last_commit_pos_file, + last_commit_pos_offset); + } + else + { + if ((error= get_binlog_checkpoint_file(checkpoint_file))) + { + is_checkpoint_based_recovery= true; + sql_print_error("tc-heuristic-recover: Failed to read latest checkpoint " + "binary log name."); + goto end; + } + strmake_buf(engine_commit_file, checkpoint_file); + sql_print_information("tc-heuristic-recover: Initialising heuristic " + "rollback of binary log using last checkpoint " + "file:%s.", engine_commit_file); + /* + If there is no engine specific commit file we are doing checkpoint file + based recovery. Hence we mark "found_engine_commit_pos" true, and start + looking for the first transactional event group with is the candidate for + rollback. + */ + found_engine_commit_pos= true; + } + + if ((error= find_log_pos(&log_info, engine_commit_file, 1))) + { + sql_print_error("tc-heuristic-recover: Failed to locate binary log file:%s " + "in index file. Error:%d", engine_commit_file, error); + goto end; + } + if ((file= open_binlog(&log, log_info.log_file_name, &errmsg)) < 0 || + DBUG_EVALUATE_IF("fault_injection_opening_binlog", (errmsg="Unknown"), + FALSE)) + { + error= 1; + sql_print_error("tc-heuristic-recover: Failed to open the binlog:%s for " + "recovery. Error:%s", log_info.log_file_name, errmsg); + goto end; + } + + + error= read_state_from_file(); + if (error && error != 2) + { + sql_print_error("tc-heuristic-recover: Failed to load global gtid binlog " + "state from file"); + goto end; + } + if (!fdle.is_valid()) + { + error= 1; + sql_print_error("tc-heuristic-recover: Failed due to invalid format " + "description log event."); + goto end; + } + + 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)) + { + error= 1; + sql_print_error("tc-heuristic-recover: Failed to read GTID List " + "event."); + goto end; + } + } + 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 ((error= rpl_global_gtid_binlog_state.update_nolock(&last_gtid, + false))) + { + sql_print_error("tc-heuristic-recover: Failed to update GTID within " + "global gtid state."); + goto end; + } + 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 + if (file >= 0) + { + 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("tc-heuristic-recover: Failed to read next binary " + "log during recovery."); + goto end; + } + else + { + error= 0; // LOG_INFO_EOF= -1 is not an error. + break; + } + } + if ((file= open_binlog(&log, log_info.log_file_name, &errmsg)) < 0) + { + error= 1; + sql_print_error("tc-heuristic-recover: Failed to open the binlog:%s for " + "recovery. Error:%s", log_info.log_file_name, errmsg); + goto end; + } + } + else + break; + } //end of for(;;) + sql_print_information("tc-heuristic-recover: Binary log to be truncated " + "File:%s Pos:%llu.", binlog_truncate_file_name, + binlog_truncate_pos); + if (!found_truncate_pos) + goto end; // Nothing to truncate + else + DBUG_ASSERT(binlog_truncate_pos > 0); + + if (is_safe) + { + if ((error= truncate_and_remove_binlogs(binlog_truncate_file_name, + binlog_truncate_pos))) + { + sql_print_error("tc-heuristic-recover: Failed to trim the binary log to " + "File:%s Pos:%llu.", binlog_truncate_file_name, + binlog_truncate_pos); + goto end; + } + } + else + { + sql_print_error("tc-heuristic-recover cannot trim the binary log to " + "File:%s Pos:%llu as unsafe statements (non-trans/DDL) " + "statements are found beyond the truncation position.", + binlog_truncate_file_name, binlog_truncate_pos); + } + if ((error= write_state_to_file())) + { + sql_print_error("tc-heuristic-recover: Failed to write global gtid state " + "to file"); + goto end; + } + +end: + if (file >= 0) + { + end_io_cache(&log); + mysql_file_close(file, MYF(MY_WME)); + } + if (error) + { + if (is_checkpoint_based_recovery) + { + sql_print_error("tc-heuristic-recover failed during binary log rollback." + "Further retry attemps won't succeed."); + } + else + sql_print_error("tc-heuristic-recover failed during binary log rollback. " + "After removing the source of the failure " + "--tc-heuristic-recover=rollback may be retried."); + } + +#endif + return error; +} + int TC_LOG_BINLOG::open(const char *opt_name) { int error= 1; @@ -9526,7 +10103,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..84c0a457b52 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/sql/mysqld.h b/sql/mysqld.h index e939524dbff..515d5f39c3d 100644 --- a/sql/mysqld.h +++ b/sql/mysqld.h @@ -94,6 +94,7 @@ extern "C" MYSQL_PLUGIN_IMPORT CHARSET_INFO *system_charset_info; extern MYSQL_PLUGIN_IMPORT CHARSET_INFO *files_charset_info ; extern MYSQL_PLUGIN_IMPORT CHARSET_INFO *national_charset_info; extern MYSQL_PLUGIN_IMPORT CHARSET_INFO *table_alias_charset; +extern MYSQL_PLUGIN_IMPORT bool opt_bin_log; /** Character set of the buildin error messages loaded from errmsg.sys. @@ -104,7 +105,7 @@ extern CHARSET_INFO *character_set_filesystem; extern MY_BITMAP temp_pool; extern bool opt_large_files, server_id_supplied; -extern bool opt_update_log, opt_bin_log, opt_error_log; +extern bool opt_update_log, opt_error_log; extern my_bool opt_log, opt_bootstrap; extern my_bool opt_backup_history_log; extern my_bool opt_backup_progress_log; diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc index 4de2cdbeaec..552348ee2c5 100644 --- a/storage/innobase/handler/ha_innodb.cc +++ b/storage/innobase/handler/ha_innodb.cc @@ -16493,6 +16493,13 @@ innobase_xa_recover( { DBUG_ASSERT(hton == innodb_hton_ptr); + if (opt_bin_log) + { + 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/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc index 3b3c7c23224..c8a742d95e9 100644 --- a/storage/innobase/log/log0recv.cc +++ b/storage/innobase/log/log0recv.cc @@ -2,7 +2,7 @@ Copyright (c) 1997, 2017, Oracle and/or its affiliates. All Rights Reserved. Copyright (c) 2012, Facebook Inc. -Copyright (c) 2013, 2019, MariaDB Corporation. +Copyright (c) 2013, 2020, MariaDB Corporation. This program is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software @@ -3301,7 +3301,8 @@ void recv_recovery_from_checkpoint_finish(void) /*======================================*/ { - if (recv_needed_recovery) { + extern MYSQL_PLUGIN_IMPORT bool opt_bin_log; + if (opt_bin_log) { trx_sys_print_mysql_master_log_pos(); trx_sys_print_mysql_binlog_offset(); } diff --git a/storage/xtradb/handler/ha_innodb.cc b/storage/xtradb/handler/ha_innodb.cc index 2aafb1a44ee..a966f726a03 100644 --- a/storage/xtradb/handler/ha_innodb.cc +++ b/storage/xtradb/handler/ha_innodb.cc @@ -17165,6 +17165,13 @@ innobase_xa_recover( { DBUG_ASSERT(hton == innodb_hton_ptr); + if (opt_bin_log) + { + 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/log/log0recv.cc b/storage/xtradb/log/log0recv.cc index dd55d31218a..a4844507328 100644 --- a/storage/xtradb/log/log0recv.cc +++ b/storage/xtradb/log/log0recv.cc @@ -2,7 +2,7 @@ Copyright (c) 1997, 2017, Oracle and/or its affiliates. All Rights Reserved. Copyright (c) 2012, Facebook Inc. -Copyright (c) 2013, 2019, MariaDB Corporation. +Copyright (c) 2013, 2020, MariaDB Corporation. This program is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software @@ -3397,7 +3397,8 @@ void recv_recovery_from_checkpoint_finish(void) /*======================================*/ { - if (recv_needed_recovery) { + extern MYSQL_PLUGIN_IMPORT bool opt_bin_log; + if (opt_bin_log) { trx_sys_print_mysql_master_log_pos(); trx_sys_print_mysql_binlog_offset(); }