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>

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 #

mysql-test/suite/binlog/r/binlog_bug23533.result

+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;

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
 #

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

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
 #

mysql-test/suite/binlog_encryption/rpl_mixed_binlog_max_cache_size.result

 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;

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);

mysql-test/suite/rpl/r/rpl_mixed_binlog_max_cache_size.result

 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;

mysql-test/suite/rpl/r/rpl_stm_binlog_max_cache_size.result

 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;

sql/handler.cc

@@ -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.

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()
@@ -5721,9 +5722,15 @@ binlog_start_consistent_snapshot(handlerton *hton, THD *thd)
   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.
 */
@@ -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;
   }
+  DBUG_EXECUTE_IF("table_map_write_error",
+    {
+      if (is_transactional)
+      {
+        my_errno= EFBIG;
+        error= 1;
+        goto write_err;
       }
-  if (unlikely((error= writer.write(&the_event))))
-    DBUG_RETURN(error);
+    });
+  if ((error= writer.write(&the_event)))
+    goto write_err;
 
 	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);
 }