summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorBrandon Nesterenko <brandon.nesterenko@mariadb.com>2019-12-17 15:23:55 +0530
committerBrandon Nesterenko <brandon.nesterenko@mariadb.com>2022-07-25 16:26:53 -0600
commit555c12a541c21ed71dc40ae7d246c150a2d2b06b (patch)
treed3b0aba6745dd5a4c72822cd0f5a0be12c775cf7
parent46ff660883aade25f16abb13588f0a1934e9da56 (diff)
downloadmariadb-git-555c12a541c21ed71dc40ae7d246c150a2d2b06b.tar.gz
MDEV-21087/MDEV-21433: ER_SLAVE_INCIDENT arrives at slave without failure specifics
Problem: ======= This patch addresses two issues: 1. An incident event can be incorrectly reported for transactions which are rolled back successfully. That is, an incident event should only be generated for failed “non-transactional transactions” (i.e., those which modify non-transactional tables) because they cannot be rolled back. 2. When the mariadb slave (error) stops at receiving the incident event there's no description of what led to it. Neither in the event nor in the master's error log. Solution: ======== Before reporting an incident event for a transaction, first validate that it is “non-transactional” (i.e. cannot be safely rolled back). To determine if a transaction is non-transactional, lex->stmt_accessed_table(LEX::STMT_WRITES_NON_TRANS_TABLE) is used because it is set previously in THD::decide_logging_format(). Additionally, when an incident event is written, write an error message to the server’s error log to indicate the underlying issue. Reviewed by: =========== Andrei Elkin <andrei.elkin@mariadb.com>
-rw-r--r--mysql-test/suite/binlog/include/binlog_write_error.inc2
-rw-r--r--mysql-test/suite/binlog/r/binlog_bug23533.result1
-rw-r--r--mysql-test/suite/binlog/r/binlog_write_error.result1
-rw-r--r--mysql-test/suite/binlog/t/binlog_bug23533.test2
-rw-r--r--mysql-test/suite/binlog_encryption/binlog_write_error.result1
-rw-r--r--mysql-test/suite/binlog_encryption/rpl_mixed_binlog_max_cache_size.result2
-rw-r--r--mysql-test/suite/rpl/include/rpl_binlog_max_cache_size.test2
-rw-r--r--mysql-test/suite/rpl/r/rpl_mdev-11092.result211
-rw-r--r--mysql-test/suite/rpl/r/rpl_mixed_binlog_max_cache_size.result2
-rw-r--r--mysql-test/suite/rpl/r/rpl_stm_binlog_max_cache_size.result2
-rw-r--r--mysql-test/suite/rpl/t/rpl_mdev-11092.test498
-rw-r--r--sql/handler.cc8
-rw-r--r--sql/log.cc71
13 files changed, 778 insertions, 25 deletions
diff --git a/mysql-test/suite/binlog/include/binlog_write_error.inc b/mysql-test/suite/binlog/include/binlog_write_error.inc
index fa3ba087a7e..be5e9e0cfea 100644
--- a/mysql-test/suite/binlog/include/binlog_write_error.inc
+++ b/mysql-test/suite/binlog/include/binlog_write_error.inc
@@ -38,6 +38,8 @@ DROP TRIGGER IF EXISTS tr2;
DROP VIEW IF EXISTS v1, v2;
enable_warnings;
+call mtr.add_suppression("Write to binary log failed: Error writing file*");
+
--echo #
--echo # Test injecting binlog write error when executing queries
--echo #
diff --git a/mysql-test/suite/binlog/r/binlog_bug23533.result b/mysql-test/suite/binlog/r/binlog_bug23533.result
index cc9799506c3..aa357b58f2c 100644
--- a/mysql-test/suite/binlog/r/binlog_bug23533.result
+++ b/mysql-test/suite/binlog/r/binlog_bug23533.result
@@ -1,3 +1,4 @@
+call mtr.add_suppression("Write to binary log failed: Multi-statement transaction required more than .max_binlog_cache_size.*");
SET AUTOCOMMIT=0;
CREATE TABLE t1 (a INT NOT NULL AUTO_INCREMENT, b TEXT, PRIMARY KEY(a)) ENGINE=InnoDB;
SELECT COUNT(*) FROM t1;
diff --git a/mysql-test/suite/binlog/r/binlog_write_error.result b/mysql-test/suite/binlog/r/binlog_write_error.result
index 6e8a212035a..7e8e373c797 100644
--- a/mysql-test/suite/binlog/r/binlog_write_error.result
+++ b/mysql-test/suite/binlog/r/binlog_write_error.result
@@ -9,6 +9,7 @@ DROP PROCEDURE IF EXISTS p2;
DROP TRIGGER IF EXISTS tr1;
DROP TRIGGER IF EXISTS tr2;
DROP VIEW IF EXISTS v1, v2;
+call mtr.add_suppression("Write to binary log failed: Error writing file*");
#
# Test injecting binlog write error when executing queries
#
diff --git a/mysql-test/suite/binlog/t/binlog_bug23533.test b/mysql-test/suite/binlog/t/binlog_bug23533.test
index ca610e399e4..a77497115e5 100644
--- a/mysql-test/suite/binlog/t/binlog_bug23533.test
+++ b/mysql-test/suite/binlog/t/binlog_bug23533.test
@@ -6,7 +6,7 @@
--source include/have_innodb.inc
--source include/have_log_bin.inc
--source include/have_binlog_format_row.inc
-
+call mtr.add_suppression("Write to binary log failed: Multi-statement transaction required more than .max_binlog_cache_size.*");
SET AUTOCOMMIT=0;
# Create 1st table
diff --git a/mysql-test/suite/binlog_encryption/binlog_write_error.result b/mysql-test/suite/binlog_encryption/binlog_write_error.result
index 6e8a212035a..7e8e373c797 100644
--- a/mysql-test/suite/binlog_encryption/binlog_write_error.result
+++ b/mysql-test/suite/binlog_encryption/binlog_write_error.result
@@ -9,6 +9,7 @@ DROP PROCEDURE IF EXISTS p2;
DROP TRIGGER IF EXISTS tr1;
DROP TRIGGER IF EXISTS tr2;
DROP VIEW IF EXISTS v1, v2;
+call mtr.add_suppression("Write to binary log failed: Error writing file*");
#
# Test injecting binlog write error when executing queries
#
diff --git a/mysql-test/suite/binlog_encryption/rpl_mixed_binlog_max_cache_size.result b/mysql-test/suite/binlog_encryption/rpl_mixed_binlog_max_cache_size.result
index 388c8e67b68..944ad9331ad 100644
--- a/mysql-test/suite/binlog_encryption/rpl_mixed_binlog_max_cache_size.result
+++ b/mysql-test/suite/binlog_encryption/rpl_mixed_binlog_max_cache_size.result
@@ -1,6 +1,8 @@
include/master-slave.inc
[connection master]
call mtr.add_suppression("Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT");
+call mtr.add_suppression("Write to binary log failed: Multi-row statements required more than .max_binlog_stmt_cache_size");
+call mtr.add_suppression("Write to binary log failed: Multi-statement transaction required more than .max_binlog_cache_size");
SET GLOBAL max_binlog_cache_size = 4096;
SET GLOBAL binlog_cache_size = 4096;
SET GLOBAL max_binlog_stmt_cache_size = 4096;
diff --git a/mysql-test/suite/rpl/include/rpl_binlog_max_cache_size.test b/mysql-test/suite/rpl/include/rpl_binlog_max_cache_size.test
index 4c93ad86209..d750554b4ec 100644
--- a/mysql-test/suite/rpl/include/rpl_binlog_max_cache_size.test
+++ b/mysql-test/suite/rpl/include/rpl_binlog_max_cache_size.test
@@ -22,6 +22,8 @@
#
########################################################################################
call mtr.add_suppression("Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT");
+call mtr.add_suppression("Write to binary log failed: Multi-row statements required more than .max_binlog_stmt_cache_size");
+call mtr.add_suppression("Write to binary log failed: Multi-statement transaction required more than .max_binlog_cache_size");
let $old_max_binlog_cache_size= query_get_value(SHOW VARIABLES LIKE "max_binlog_cache_size", Value, 1);
let $old_binlog_cache_size= query_get_value(SHOW VARIABLES LIKE "binlog_cache_size", Value, 1);
diff --git a/mysql-test/suite/rpl/r/rpl_mdev-11092.result b/mysql-test/suite/rpl/r/rpl_mdev-11092.result
index 8bc8fe4a20b..a685e204e7a 100644
--- a/mysql-test/suite/rpl/r/rpl_mdev-11092.result
+++ b/mysql-test/suite/rpl/r/rpl_mdev-11092.result
@@ -1,7 +1,12 @@
include/master-slave.inc
[connection master]
call mtr.add_suppression("Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT");
-call mtr.add_suppression("Slave SQL: The incident LOST_EVENTS occurred on the master. .*");
+call mtr.add_suppression("Slave SQL: The incident LOST_EVENTS occured on the master. .*");
+call mtr.add_suppression("Write to binary log failed: Multi-row statements required more than .max_binlog_stmt_cache_size.* ");
+call mtr.add_suppression("Write to binary log failed: Multi-statement transaction required more than .max_binlog_cache_size.* ");
+call mtr.add_suppression("Incident event write to the binary log file failed");
+call mtr.add_suppression("handlerton rollback failed");
+"*********** Annotate Event write failure **************"
SET GLOBAL max_binlog_cache_size = 4096;
SET GLOBAL binlog_cache_size = 4096;
SET GLOBAL max_binlog_stmt_cache_size = 4096;
@@ -10,12 +15,212 @@ disconnect master;
connect master,127.0.0.1,root,,test,$MASTER_MYPORT,;
CREATE TABLE t1(a INT PRIMARY KEY, data VARCHAR(30000)) ENGINE=MYISAM;
connection master;
-ERROR HY000: Writing one row to the row-based binary log failed
+"#######################################################################"
+"# Test Case1: Annotate event write failure for MyISAM #"
+"#######################################################################"
+ERROR HY000: Multi-row statements required more than 'max_binlog_stmt_cache_size' bytes of storage; increase this mysqld variable and try again
+# Validating update was not binlogged..
+# ..success
+# Validating that the inserted data was saved on the master..
+# ..success
+connection slave;
include/wait_for_slave_sql_error_and_skip.inc [errno=1590]
+# Validating that the insert was not replicated to the slave..
+# ..success
+"#######################################################################"
+"# Test Case2: Annotate event write failure for INNODB #"
+"#######################################################################"
connection master;
+CREATE TABLE t2(a INT PRIMARY KEY, data VARCHAR(30000)) ENGINE=INNODB;
+ERROR HY000: Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage; increase this mysqld variable and try again
+# Validating binlog GTID position progressed from first insert..
+# ..success
+# Validating that only the first insert into t2 saved..
+# ..success
+include/save_master_gtid.inc
+connection slave;
+include/sync_with_master_gtid.inc
+# Validating the first insert into t2 replicated to slave..
+include/diff_tables.inc [master:test.t2,slave:test.t2]
+# ..success
+"#######################################################################"
+"# Test Case3: Annotate event write failure for mixed engine UPDATE #"
+"#######################################################################"
+connection master;
+ERROR HY000: Multi-row statements required more than 'max_binlog_stmt_cache_size' bytes of storage; increase this mysqld variable and try again
+# Validating update was not binlogged..
+# ..success
+# Validating non-transactional part of update saved..
+# ..success
+# Validating transactional part of update was rolled back..
+# ..success
+include/save_master_gtid.inc
+connection slave;
+include/wait_for_slave_sql_error_and_skip.inc [errno=1590]
+# Validating the rolled-back multi-engine update did not replicate to slave at all..
+# ..success
+connection master;
+"****** Clean up *******"
SET GLOBAL max_binlog_cache_size= ORIGINAL_VALUE;
SET GLOBAL binlog_cache_size= ORIGINAL_VALUE;
SET GLOBAL max_binlog_stmt_cache_size= ORIGINAL_VALUE;
SET GLOBAL binlog_stmt_cache_size= ORIGINAL_VALUE;
-DROP TABLE t1;
+DROP TABLE t1,t2;
+"*********** TABLE MAP Event write failure **************"
+CREATE TABLE tm (f INT) ENGINE=MYISAM;
+CREATE TABLE ti (f INT) ENGINE=INNODB;
+INSERT INTO tm VALUES (10);
+INSERT INTO ti VALUES (20);
+connection slave;
+"#######################################################################"
+"# Test Case4: Table_map event write failure for trans engine UPDATE #"
+"#######################################################################"
+# Transaction should be rolled back without writing incident event
+connection master;
+SET debug_dbug="+d,table_map_write_error";
+UPDATE ti, tm set ti.f=30;
+ERROR HY000: Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage; increase this mysqld variable and try again
+# Validating update was not binlogged..
+# ..success
+# Validating update was rolled back from storage engines..
+# ..success
+include/save_master_gtid.inc
+connection slave;
+include/sync_with_master_gtid.inc
+"#######################################################################"
+"# Test Case5: Table_map event write failure for mixed engine UPDATE #"
+"#######################################################################"
+connection master;
+# In case of mixed engines if non trans table is updated write INCIDENT event
+UPDATE ti,tm SET tm.f=88, ti.f=120;
+ERROR HY000: Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage; increase this mysqld variable and try again
+# Validating update was not binlogged..
+# ..success
+# Validating that only the non-transactional update saved on master..
+# ..success
+connection slave;
+include/wait_for_slave_sql_error_and_skip.inc [errno=1590]
+# Validating that neither of the updates replicated to slave..
+# ..success
+"#######################################################################"
+"# Test Case6: Committing a transaction consisting of two updates:
+"# S1) Update transactional table
+"# S2) Update transactional table
+"# with a table_map event write failure on the second event should
+"# roll-back only the second update without incident
+"#######################################################################"
+connection master;
+SET debug_dbug="";
+BEGIN;
+UPDATE ti, tm set ti.f=40;
+SET debug_dbug="+d,table_map_write_error";
+UPDATE ti, tm set ti.f=50;
+ERROR HY000: Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage; increase this mysqld variable and try again
+COMMIT;
+# Validating binlog GTID position progressed from first update..
+# ..success
+# Validating the first update saved..
+# ..and that the second update did not save..
+# ..success
+# Validating that only the first update replicated to slave without incident
+connection master;
+include/save_master_gtid.inc
+connection slave;
+include/sync_with_master_gtid.inc
+include/diff_tables.inc [master:test.ti,slave:test.ti]
+"#######################################################################"
+"# Test Case7: Rolling back a transaction consisting of two updates:
+"# S1) Update transactional table
+"# S2) Update transactional table
+"# with a table_map event write failure on the second event should
+"# roll-back both updates without incident
+"#######################################################################"
+connection master;
+SET debug_dbug="";
+BEGIN;
+UPDATE ti, tm set ti.f=60;
+SET debug_dbug="+d,table_map_write_error";
+UPDATE ti, tm set ti.f=70;
+ERROR HY000: Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage; increase this mysqld variable and try again
+ROLLBACK;
+# Validating update was not binlogged..
+# ..success
+# Validating that neither update saved on master..
+# ..success
+# Validating the transaction did not replicate to the slave
+connection master;
+include/save_master_gtid.inc
+connection slave;
+include/sync_with_master_gtid.inc
+include/diff_tables.inc [master:test.ti,slave:test.ti]
+"#######################################################################"
+"# Test Case8: Committing a transaction consisting of two updates:
+"# S1) Update transactional table
+"# S2) Update mixed trans/non-trans tables
+"# with a table_map event write failure on the second event should
+"# roll-back only the second update with incident
+"#######################################################################"
+connection master;
+BEGIN;
+SET debug_dbug="";
+UPDATE ti, tm set ti.f=80;
+SET debug_dbug="+d,table_map_write_error";
+UPDATE ti, tm set ti.f=90,tm.f=99;
+ERROR HY000: Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage; increase this mysqld variable and try again
+COMMIT;
+# Validating binlog GTID position progressed from first update..
+# ..success
+# Validating the first update saved..
+# ..and the transactional part of the second update did not save..
+# ..whereas the non-trans part of the second update did save..
+# ..success
+# Validating that the incident propagated to the slave
+connection slave;
+include/wait_for_slave_sql_error_and_skip.inc [errno=1590]
+# Validating that the first update replicated to the slave..
+# ..and neither part of the second update replicated..
+# ..success
+"#######################################################################"
+"# Test Case9: Rolling back a transaction consisting of two updates:
+"# S1) Update transactional table
+"# S2) Update mixed trans/non-trans tables
+"# with a table_map event write failure on the second event should
+"# roll-back both transactional updates, preserve the non-transactional
+"# update on the master (only), and write an incident event
+"#######################################################################"
+connection master;
+SET debug_dbug="";
+BEGIN;
+UPDATE ti, tm set ti.f=100;
+SET debug_dbug="+d,table_map_write_error";
+UPDATE ti, tm set ti.f=110,tm.f=111;
+ERROR HY000: Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage; increase this mysqld variable and try again
+ROLLBACK;
+# Validating update was not binlogged..
+# ..success
+# Validating trans updates rollback, but the non-trans update stays..
+# ..success
+# Validating that the incident propagated to the slave
+connection slave;
+include/wait_for_slave_sql_error_and_skip.inc [errno=1590]
+# Validating that none of the updates replicated to the slave
+include/diff_tables.inc [master:test.ti,slave:test.ti]
+# ..success
+"#######################################################################"
+"# Test Case10: If an incident event fails to write, a specific error
+"# should be logged
+"#
+"# Note: This test case is the same as test case 5, with the caveat of
+"# the incident event failing to write.
+"#######################################################################"
+connection master;
+SET debug_dbug="d,table_map_write_error,incident_event_write_error";
+UPDATE ti, tm set ti.f=120, tm.f=122;
+ERROR HY000: Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage; increase this mysqld variable and try again
+# Validate error message indicating incident event failed to write
+FOUND 1 /Incident event write to the binary log file failed/ in mysqld.1.err
+connection master;
+"******** Clean Up **********"
+SET GLOBAL debug_dbug = '';
+DROP TABLE tm,ti;
include/rpl_end.inc
diff --git a/mysql-test/suite/rpl/r/rpl_mixed_binlog_max_cache_size.result b/mysql-test/suite/rpl/r/rpl_mixed_binlog_max_cache_size.result
index 388c8e67b68..944ad9331ad 100644
--- a/mysql-test/suite/rpl/r/rpl_mixed_binlog_max_cache_size.result
+++ b/mysql-test/suite/rpl/r/rpl_mixed_binlog_max_cache_size.result
@@ -1,6 +1,8 @@
include/master-slave.inc
[connection master]
call mtr.add_suppression("Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT");
+call mtr.add_suppression("Write to binary log failed: Multi-row statements required more than .max_binlog_stmt_cache_size");
+call mtr.add_suppression("Write to binary log failed: Multi-statement transaction required more than .max_binlog_cache_size");
SET GLOBAL max_binlog_cache_size = 4096;
SET GLOBAL binlog_cache_size = 4096;
SET GLOBAL max_binlog_stmt_cache_size = 4096;
diff --git a/mysql-test/suite/rpl/r/rpl_stm_binlog_max_cache_size.result b/mysql-test/suite/rpl/r/rpl_stm_binlog_max_cache_size.result
index 388c8e67b68..944ad9331ad 100644
--- a/mysql-test/suite/rpl/r/rpl_stm_binlog_max_cache_size.result
+++ b/mysql-test/suite/rpl/r/rpl_stm_binlog_max_cache_size.result
@@ -1,6 +1,8 @@
include/master-slave.inc
[connection master]
call mtr.add_suppression("Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT");
+call mtr.add_suppression("Write to binary log failed: Multi-row statements required more than .max_binlog_stmt_cache_size");
+call mtr.add_suppression("Write to binary log failed: Multi-statement transaction required more than .max_binlog_cache_size");
SET GLOBAL max_binlog_cache_size = 4096;
SET GLOBAL binlog_cache_size = 4096;
SET GLOBAL max_binlog_stmt_cache_size = 4096;
diff --git a/mysql-test/suite/rpl/t/rpl_mdev-11092.test b/mysql-test/suite/rpl/t/rpl_mdev-11092.test
index 782d24803c7..0c020386b98 100644
--- a/mysql-test/suite/rpl/t/rpl_mdev-11092.test
+++ b/mysql-test/suite/rpl/t/rpl_mdev-11092.test
@@ -1,3 +1,4 @@
+--source include/have_debug.inc
--source include/have_innodb.inc
--source include/not_embedded.inc
--source include/not_windows.inc
@@ -6,13 +7,19 @@
########################################################################################
call mtr.add_suppression("Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT");
-call mtr.add_suppression("Slave SQL: The incident LOST_EVENTS occurred on the master. .*");
+call mtr.add_suppression("Slave SQL: The incident LOST_EVENTS occured on the master. .*");
+call mtr.add_suppression("Write to binary log failed: Multi-row statements required more than .max_binlog_stmt_cache_size.* ");
+call mtr.add_suppression("Write to binary log failed: Multi-statement transaction required more than .max_binlog_cache_size.* ");
+call mtr.add_suppression("Incident event write to the binary log file failed");
+call mtr.add_suppression("handlerton rollback failed");
let $old_max_binlog_cache_size= query_get_value(SHOW VARIABLES LIKE "max_binlog_cache_size", Value, 1);
let $old_binlog_cache_size= query_get_value(SHOW VARIABLES LIKE "binlog_cache_size", Value, 1);
let $old_max_binlog_stmt_cache_size= query_get_value(SHOW VARIABLES LIKE "max_binlog_stmt_cache_size", Value, 1);
let $old_binlog_stmt_cache_size= query_get_value(SHOW VARIABLES LIKE "binlog_stmt_cache_size", Value, 1);
+--echo "*********** Annotate Event write failure **************"
+
SET GLOBAL max_binlog_cache_size = 4096;
SET GLOBAL binlog_cache_size = 4096;
SET GLOBAL max_binlog_stmt_cache_size = 4096;
@@ -26,19 +33,162 @@ let $data = `select concat('"', repeat('a',2000), '"')`;
connection master;
+# Insert a huge row into MyISAM table. The row will be inserted in engine and a
+# request to write to binary log will be initiated. Since row annotations are
+# enabled the size of the annotate event itself will exceed the
+# "max_binlog_stmt_cache_size". This will result in ER_STMT_CACHE_FULL error
+# and an incident event will be written to the binary log as row update in
+# engine cannot be undone.
+
+--echo "#######################################################################"
+--echo "# Test Case1: Annotate event write failure for MyISAM #"
+--echo "#######################################################################"
+
--disable_query_log
---error ER_BINLOG_ROW_LOGGING_FAILED
+--let $old_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--error ER_STMT_CACHE_FULL
eval INSERT INTO t1 (a, data) VALUES (2,
CONCAT($data, $data, $data, $data, $data, $data));
--enable_query_log
+--let $new_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--echo # Validating update was not binlogged..
+if(`SELECT strcmp("$old_gtid_binlog_pos","$new_gtid_binlog_pos") != 0`)
+{
+ --die Binlog GTID position should have been unchanged after failed update
+}
+--echo # ..success
+
+--echo # Validating that the inserted data was saved on the master..
+if(`SELECT COUNT(*)!=1 FROM t1`)
+{
+ --die The insertion should have saved on a non-transactional table
+}
+--echo # ..success
+
+--connection slave
# Incident event
# 1590=ER_SLAVE_INCIDENT
--let $slave_sql_errno= 1590
--source include/wait_for_slave_sql_error_and_skip.inc
-connection master;
+--echo # Validating that the insert was not replicated to the slave..
+if(`SELECT COUNT(*) FROM t1`)
+{
+ --die The insertion should not have replicated to the slave
+}
+--echo # ..success
+
+# MDEV-21087
+# Insert two huge rows in to transaction cache. Have data such that first row
+# fits inside the binary log cache. While writing the annotate event for the
+# second row the binary log cache size will exceed "max_binlog_cache_size".
+# Hence this statement cannot be written to binary log. As DMLs in Innodb can
+# be safely rolled back only an error will be reported. Slave will continue to
+# work.
+
+--echo "#######################################################################"
+--echo "# Test Case2: Annotate event write failure for INNODB #"
+--echo "#######################################################################"
+
+--connection master
+CREATE TABLE t2(a INT PRIMARY KEY, data VARCHAR(30000)) ENGINE=INNODB;
+--disable_query_log
+--let $old_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+BEGIN;
+eval INSERT INTO t2 (a, data) VALUES (1, CONCAT($data, $data));
+--error ER_TRANS_CACHE_FULL
+eval INSERT INTO t2 (a, data) VALUES (2, CONCAT($data, $data));
+COMMIT;
+--enable_query_log
+
+--let $new_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--echo # Validating binlog GTID position progressed from first insert..
+if(`SELECT strcmp("$old_gtid_binlog_pos","$new_gtid_binlog_pos") = 0`)
+{
+ --die Binlog GTID position should have updated
+}
+--echo # ..success
+
+--echo # Validating that only the first insert into t2 saved..
+if(`SELECT COUNT(*)!=1 FROM t2`)
+{
+ --die Only one row should exist in t2 from the first insert, the second should have rolled back
+}
+--echo # ..success
+--source include/save_master_gtid.inc
+
+--connection slave
+--source include/sync_with_master_gtid.inc
+--echo # Validating the first insert into t2 replicated to slave..
+--let $diff_tables= master:test.t2,slave:test.t2
+--source include/diff_tables.inc
+--echo # ..success
+
+# Testing mixed engine UPDATE statement scenario. In the following multi
+# update query 'ha_update_row' will be invoked for t1 (myisam) table. This
+# intern invokes binlog_write_table_map() function call. While writing a huge
+# annotate event binary log cache size will exceed max_binlog_cache_size.
+# Writing to binary log fails. Since non transactional changes cannot be
+# rolled back incident event will be written to binary log.
+
+--echo "#######################################################################"
+--echo "# Test Case3: Annotate event write failure for mixed engine UPDATE #"
+--echo "#######################################################################"
+
+--connection master
+let $new_data = `select concat('"', repeat('b',2000), '"')`;
+--let $old_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--disable_query_log
+--error ER_STMT_CACHE_FULL
+eval UPDATE t1,t2 SET t1.data="Hello", t2.data=CONCAT($new_data,$new_data,$new_data,$new_data,$new_data);
+--enable_query_log
+
+--let $new_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--echo # Validating update was not binlogged..
+if(`SELECT strcmp("$old_gtid_binlog_pos","$new_gtid_binlog_pos") != 0`)
+{
+ --die Binlog GTID position should have been unchanged after failed update
+}
+--echo # ..success
+
+--echo # Validating non-transactional part of update saved..
+if(`SELECT COUNT(*)!=1 from t1 where data="Hello"`)
+{
+ --die Non-transactional part of update should have saved
+}
+--echo # ..success
+
+--echo # Validating transactional part of update was rolled back..
+if(`SELECT COUNT(*) from t2 where data LIKE "b%"`)
+{
+ --die Transactional part of update should have been rolled back
+}
+--echo # ..success
+--source include/save_master_gtid.inc
+
+--connection slave
+
+# Incident event
+# 1590=ER_SLAVE_INCIDENT
+--let $slave_sql_errno= 1590
+--source include/wait_for_slave_sql_error_and_skip.inc
+
+--echo # Validating the rolled-back multi-engine update did not replicate to slave at all..
+if(`SELECT COUNT(*) from t1 where data="Hello"`)
+{
+ --die Non-transactional part of update should not have replicated
+}
+if(`SELECT COUNT(*) from t2 where data LIKE "b%"`)
+{
+ --die Transactional part of update should not have replicated
+}
+--echo # ..success
+
+--connection master
+
+--echo "****** Clean up *******"
--replace_result $old_max_binlog_cache_size ORIGINAL_VALUE
--eval SET GLOBAL max_binlog_cache_size= $old_max_binlog_cache_size
--replace_result $old_binlog_cache_size ORIGINAL_VALUE
@@ -48,6 +198,346 @@ connection master;
--replace_result $old_binlog_stmt_cache_size ORIGINAL_VALUE
--eval SET GLOBAL binlog_stmt_cache_size= $old_binlog_stmt_cache_size
-DROP TABLE t1;
+DROP TABLE t1,t2;
+
+--echo "*********** TABLE MAP Event write failure **************"
+
+--let $debug_save= `SELECT @@GLOBAL.debug_dbug`
+CREATE TABLE tm (f INT) ENGINE=MYISAM;
+CREATE TABLE ti (f INT) ENGINE=INNODB;
+INSERT INTO tm VALUES (10);
+INSERT INTO ti VALUES (20);
+--sync_slave_with_master
+
+--echo "#######################################################################"
+--echo "# Test Case4: Table_map event write failure for trans engine UPDATE #"
+--echo "#######################################################################"
+--echo # Transaction should be rolled back without writing incident event
+--connection master
+--let $old_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+SET debug_dbug="+d,table_map_write_error";
+--error ER_TRANS_CACHE_FULL
+UPDATE ti, tm set ti.f=30;
+
+--let $new_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--echo # Validating update was not binlogged..
+if(`SELECT strcmp("$old_gtid_binlog_pos","$new_gtid_binlog_pos") != 0`)
+{
+ --die Binlog GTID position should have been unchanged after failed update
+}
+--echo # ..success
+
+--echo # Validating update was rolled back from storage engines..
+if(`SELECT COUNT(*) FROM ti WHERE f=130`)
+{
+ --die Update for InnoDB table should not have saved
+}
+--echo # ..success
+
+--source include/save_master_gtid.inc
+
+--connection slave
+--source include/sync_with_master_gtid.inc
+
+--echo "#######################################################################"
+--echo "# Test Case5: Table_map event write failure for mixed engine UPDATE #"
+--echo "#######################################################################"
+--connection master
+--let $old_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--echo # In case of mixed engines if non trans table is updated write INCIDENT event
+--error ER_TRANS_CACHE_FULL
+UPDATE ti,tm SET tm.f=88, ti.f=120;
+
+--let $new_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--echo # Validating update was not binlogged..
+if(`SELECT strcmp("$old_gtid_binlog_pos","$new_gtid_binlog_pos") != 0`)
+{
+ --die Binlog GTID position should have been unchanged after failed update
+}
+--echo # ..success
+
+--echo # Validating that only the non-transactional update saved on master..
+if(`SELECT COUNT(*)!=1 FROM tm WHERE f=88`)
+{
+ --die Update for MyISAM table should have saved
+}
+if(`SELECT COUNT(*) FROM ti WHERE f=120`)
+{
+ --die Update for InnoDB table should not have saved
+}
+--echo # ..success
+
+
+--connection slave
+# Incident event
+# 1590=ER_SLAVE_INCIDENT
+--let $slave_sql_errno= 1590
+--source include/wait_for_slave_sql_error_and_skip.inc
+
+--echo # Validating that neither of the updates replicated to slave..
+if(`SELECT COUNT(*) FROM tm WHERE f=88`)
+{
+ --die Update for MyISAM table should not have replicated to slave
+}
+if(`SELECT COUNT(*) FROM ti WHERE f=120`)
+{
+ --die Update for InnoDB table should not have replicated to slave
+}
+--echo # ..success
+
+--echo "#######################################################################"
+--echo "# Test Case6: Committing a transaction consisting of two updates:
+--echo "# S1) Update transactional table
+--echo "# S2) Update transactional table
+--echo "# with a table_map event write failure on the second event should
+--echo "# roll-back only the second update without incident
+--echo "#######################################################################"
+--connection master
+--let $old_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+
+SET debug_dbug="";
+BEGIN;
+# successful update
+UPDATE ti, tm set ti.f=40;
+SET debug_dbug="+d,table_map_write_error";
+--error ER_TRANS_CACHE_FULL
+UPDATE ti, tm set ti.f=50;
+COMMIT;
+
+--let $new_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--echo # Validating binlog GTID position progressed from first update..
+if(`SELECT strcmp("$old_gtid_binlog_pos","$new_gtid_binlog_pos") = 0`)
+{
+ --die Binlog GTID position should have updated
+}
+--echo # ..success
+
+--echo # Validating the first update saved..
+if(`SELECT COUNT(*)!=1 FROM ti WHERE f=40`)
+{
+ --die The first update should have saved because it was transactional
+}
+--echo # ..and that the second update did not save..
+if(`SELECT COUNT(*) FROM ti WHERE f=50`)
+{
+ --die The second update should have rolled back because it failed
+}
+--echo # ..success
+
+--echo # Validating that only the first update replicated to slave without incident
+--connection master
+--source include/save_master_gtid.inc
+--connection slave
+--source include/sync_with_master_gtid.inc
+--let $diff_tables= master:test.ti,slave:test.ti
+--source include/diff_tables.inc
+
+
+--echo "#######################################################################"
+--echo "# Test Case7: Rolling back a transaction consisting of two updates:
+--echo "# S1) Update transactional table
+--echo "# S2) Update transactional table
+--echo "# with a table_map event write failure on the second event should
+--echo "# roll-back both updates without incident
+--echo "#######################################################################"
+--connection master
+--let $old_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+
+SET debug_dbug="";
+BEGIN;
+# successful update
+UPDATE ti, tm set ti.f=60;
+SET debug_dbug="+d,table_map_write_error";
+--error ER_TRANS_CACHE_FULL
+UPDATE ti, tm set ti.f=70;
+ROLLBACK;
+
+--let $new_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--echo # Validating update was not binlogged..
+if(`SELECT strcmp("$old_gtid_binlog_pos","$new_gtid_binlog_pos") != 0`)
+{
+ --die Binlog GTID position should have been unchanged after failed update
+}
+--echo # ..success
+
+--echo # Validating that neither update saved on master..
+if(`SELECT COUNT(*) FROM ti WHERE f=60`)
+{
+ --die The first update should not have saved
+}
+if(`SELECT COUNT(*) FROM ti WHERE f=70`)
+{
+ --die The second update should not have saved
+}
+--echo # ..success
+
+--echo # Validating the transaction did not replicate to the slave
+--connection master
+--source include/save_master_gtid.inc
+
+--connection slave
+--source include/sync_with_master_gtid.inc
+--let $diff_tables= master:test.ti,slave:test.ti
+--source include/diff_tables.inc
+
+
+--echo "#######################################################################"
+--echo "# Test Case8: Committing a transaction consisting of two updates:
+--echo "# S1) Update transactional table
+--echo "# S2) Update mixed trans/non-trans tables
+--echo "# with a table_map event write failure on the second event should
+--echo "# roll-back only the second update with incident
+--echo "#######################################################################"
+--connection master
+--let $old_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+
+BEGIN;
+# successful update
+SET debug_dbug="";
+UPDATE ti, tm set ti.f=80;
+SET debug_dbug="+d,table_map_write_error";
+--error ER_TRANS_CACHE_FULL
+UPDATE ti, tm set ti.f=90,tm.f=99;
+COMMIT;
+
+--let $new_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--echo # Validating binlog GTID position progressed from first update..
+if(`SELECT strcmp("$old_gtid_binlog_pos","$new_gtid_binlog_pos") = 0`)
+{
+ --die Binlog GTID position should have updated
+}
+--echo # ..success
+
+--echo # Validating the first update saved..
+if(`SELECT COUNT(*)!=1 FROM ti WHERE f=80`)
+{
+ --die The first update should have saved because it was transactional
+}
+--echo # ..and the transactional part of the second update did not save..
+if(`SELECT COUNT(*) FROM ti WHERE f=90`)
+{
+ --die The transactional part of the second update should have rolled back because it failed
+}
+--echo # ..whereas the non-trans part of the second update did save..
+if(`SELECT COUNT(*)!=1 FROM tm WHERE f=99`)
+{
+ --die The non-trans part from the second update should have saved
+}
+--echo # ..success
+
+--echo # Validating that the incident propagated to the slave
+--connection slave
+# Incident event
+# 1590=ER_SLAVE_INCIDENT
+--let $slave_sql_errno= 1590
+--source include/wait_for_slave_sql_error_and_skip.inc
+
+--echo # Validating that the first update replicated to the slave..
+if(`SELECT COUNT(*)!=1 FROM ti WHERE f=80`)
+{
+ --die The first update should have replicated because it was transactional
+}
+--echo # ..and neither part of the second update replicated..
+if(`SELECT COUNT(*) FROM ti WHERE f=90`)
+{
+ --die The trans part from the second update should not have replicated because it was rolled back
+}
+if(`SELECT COUNT(*) FROM tm WHERE f=99`)
+{
+ --die The non-trans part from the second update should not have replicated because it was not binlogged
+}
+--echo # ..success
+
+
+--echo "#######################################################################"
+--echo "# Test Case9: Rolling back a transaction consisting of two updates:
+--echo "# S1) Update transactional table
+--echo "# S2) Update mixed trans/non-trans tables
+--echo "# with a table_map event write failure on the second event should
+--echo "# roll-back both transactional updates, preserve the non-transactional
+--echo "# update on the master (only), and write an incident event
+--echo "#######################################################################"
+--connection master
+--let $old_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+
+SET debug_dbug="";
+BEGIN;
+# successful update
+UPDATE ti, tm set ti.f=100;
+SET debug_dbug="+d,table_map_write_error";
+--error ER_TRANS_CACHE_FULL
+UPDATE ti, tm set ti.f=110,tm.f=111;
+ROLLBACK;
+
+--let $new_gtid_binlog_pos= query_get_value(SHOW VARIABLES LIKE 'gtid_binlog_pos', Value, 1)
+--echo # Validating update was not binlogged..
+if(`SELECT strcmp("$old_gtid_binlog_pos","$new_gtid_binlog_pos") != 0`)
+{
+ --die Binlog GTID position should have been unchanged after failed update
+}
+--echo # ..success
+
+--echo # Validating trans updates rollback, but the non-trans update stays..
+if(`SELECT COUNT(*) FROM ti WHERE f=100`)
+{
+ --die The first update should not have saved
+}
+if(`SELECT COUNT(*) FROM ti WHERE f=110`)
+{
+ --die The transactional part of the second update should not have saved
+}
+if(`SELECT COUNT(*)!=1 FROM tm WHERE f=111`)
+{
+ --die The non-trans part of the second update should have saved
+}
+--echo # ..success
+
+--echo # Validating that the incident propagated to the slave
+--connection slave
+# Incident event
+# 1590=ER_SLAVE_INCIDENT
+--let $slave_sql_errno= 1590
+--source include/wait_for_slave_sql_error_and_skip.inc
+
+--echo # Validating that none of the updates replicated to the slave
+--let $diff_tables= master:test.ti,slave:test.ti
+--source include/diff_tables.inc
+if(`SELECT COUNT(*) FROM tm WHERE f=111`)
+{
+ --die The non-trans part from the second update should not have replicated because it was not binlogged
+}
+--echo # ..success
+
+
+--echo "#######################################################################"
+--echo "# Test Case10: If an incident event fails to write, a specific error
+--echo "# should be logged
+--echo "#
+--echo "# Note: This test case is the same as test case 5, with the caveat of
+--echo "# the incident event failing to write.
+--echo "#######################################################################"
+
+--connection master
+SET debug_dbug="d,table_map_write_error,incident_event_write_error";
+--error ER_TRANS_CACHE_FULL
+UPDATE ti, tm set ti.f=120, tm.f=122;
+
+--echo # Validate error message indicating incident event failed to write
+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_PATTERN= Incident event write to the binary log file failed
+--let SEARCH_FILE= $log_error_
+--source include/search_pattern_in_file.inc
+
+
+--connection master
+--echo "******** Clean Up **********"
+--eval SET GLOBAL debug_dbug = '$debug_save'
+DROP TABLE tm,ti;
--source include/rpl_end.inc
diff --git a/sql/handler.cc b/sql/handler.cc
index 2048ce137da..66a932cc70e 100644
--- a/sql/handler.cc
+++ b/sql/handler.cc
@@ -6270,7 +6270,7 @@ static int write_locked_table_maps(THD *thd)
continue;
TABLE **const end_ptr= lock->table + lock->table_count;
- for (TABLE **table_ptr= lock->table ;
+ for (TABLE **table_ptr= lock->table ;
table_ptr != end_ptr ;
++table_ptr)
{
@@ -6294,8 +6294,10 @@ static int write_locked_table_maps(THD *thd)
*/
bool const has_trans= thd->lex->sql_command == SQLCOM_CREATE_TABLE ||
table->file->has_transactions();
- int const error= thd->binlog_write_table_map(table, has_trans,
- &with_annotate);
+
+ int const error=
+ thd->binlog_write_table_map(table, has_trans, &with_annotate);
+
/*
If an error occurs, it is the responsibility of the caller to
roll back the transaction.
diff --git a/sql/log.cc b/sql/log.cc
index f6f3879e66d..7ca9b38dc6e 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -2081,7 +2081,8 @@ static int binlog_rollback(handlerton *hton, THD *thd, bool all)
error= binlog_commit_flush_stmt_cache(thd, all, cache_mngr);
}
- if (cache_mngr->trx_cache.empty())
+
+ if (!cache_mngr->trx_cache.has_incident() && cache_mngr->trx_cache.empty())
{
/*
we're here because cache_log was flushed in MYSQL_BIN_LOG::log_xid()
@@ -5713,17 +5714,23 @@ binlog_start_consistent_snapshot(handlerton *hton, THD *thd)
}
/**
- This function writes a table map to the binary log.
+ This function writes a table map to the binary log.
Note that in order to keep the signature uniform with related methods,
we use a redundant parameter to indicate whether a transactional table
was changed or not.
If with_annotate != NULL and
*with_annotate = TRUE write also Annotate_rows before the table map.
-
+
+ If an error occurs while writing events and rollback is not possible, e.g.
+ due to the statement modifying a non-transactional table, an incident event
+ is logged.
+
@param table a pointer to the table.
@param is_transactional @c true indicates a transactional table,
otherwise @c false a non-transactional.
+ @param with_annotate @c true to write an annotate event before writing
+ the table_map event, @c false otherwise.
@return
nonzero if an error pops up when writing the table map event.
*/
@@ -5739,7 +5746,7 @@ int THD::binlog_write_table_map(TABLE *table, bool is_transactional,
/* Ensure that all events in a GTID group are in the same cache */
if (variables.option_bits & OPTION_GTID_BEGIN)
is_transactional= 1;
-
+
/* Pre-conditions */
DBUG_ASSERT(is_current_stmt_binlog_format_row());
DBUG_ASSERT(WSREP_EMULATE_BINLOG(this) || mysql_bin_log.is_open());
@@ -5764,17 +5771,35 @@ int THD::binlog_write_table_map(TABLE *table, bool is_transactional,
/* Annotate event should be written not more than once */
*with_annotate= 0;
if (unlikely((error= writer.write(&anno))))
- {
- if (my_errno == EFBIG)
- cache_data->set_incident();
- DBUG_RETURN(error);
- }
+ goto write_err;
}
- if (unlikely((error= writer.write(&the_event))))
- DBUG_RETURN(error);
+ DBUG_EXECUTE_IF("table_map_write_error",
+ {
+ if (is_transactional)
+ {
+ my_errno= EFBIG;
+ error= 1;
+ goto write_err;
+ }
+ });
+ if ((error= writer.write(&the_event)))
+ goto write_err;
- binlog_table_maps++;
- DBUG_RETURN(0);
+ binlog_table_maps++;
+ DBUG_RETURN(0);
+
+write_err:
+ mysql_bin_log.set_write_error(this, is_transactional);
+ /*
+ For non-transactional engine or multi statement transaction with mixed
+ engines, data is written to table but writing to binary log failed. In
+ these scenarios rollback is not possible. Hence report an incident.
+ */
+ if (mysql_bin_log.check_write_error(this) && cache_data &&
+ lex->stmt_accessed_table(LEX::STMT_WRITES_NON_TRANS_TABLE) &&
+ table->current_lock == F_WRLCK)
+ cache_data->set_incident();
+ DBUG_RETURN(error);
}
/**
@@ -7202,7 +7227,9 @@ bool MYSQL_BIN_LOG::write_incident(THD *thd)
if (likely(is_open()))
{
prev_binlog_id= current_binlog_id;
- if (likely(!(error= write_incident_already_locked(thd))) &&
+ if (likely(
+ !(error= DBUG_EVALUATE_IF("incident_event_write_error", 1,
+ write_incident_already_locked(thd)))) &&
likely(!(error= flush_and_sync(0))))
{
update_binlog_end_pos();
@@ -7248,6 +7275,22 @@ bool MYSQL_BIN_LOG::write_incident(THD *thd)
mysql_mutex_unlock(&LOCK_log);
}
+ /*
+ Upon writing incident event, check for thd->error() and print the
+ relevant error message in the error log.
+ */
+ if (thd->is_error())
+ {
+ sql_print_error("Write to binary log failed: "
+ "%s. An incident event is written to binary log "
+ "and slave will be stopped.\n",
+ thd->get_stmt_da()->message());
+ }
+ if (error)
+ {
+ sql_print_error("Incident event write to the binary log file failed.");
+ }
+
DBUG_RETURN(error);
}