[MDEV-21443] Donot report INCIDENT_EVENT in binary log for transactional changes which are safely rolledback Created: 2020-01-08  Updated: 2022-08-16  Resolved: 2022-07-26

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.3.36, 10.4.26, 10.5.17, 10.6.9, 10.7.5, 10.8.4, 10.9.2

Type: Bug Priority: Critical
Reporter: Sujatha Sivakumar (Inactive) Assignee: Brandon Nesterenko
Resolution: Fixed Votes: 1
Labels: None

Issue Links:
Relates
relates to MDEV-21087 ER_SLAVE_INCIDENT arrives at slave wi... Closed

 Description   

# Configure max_binlog_cache_size=4096
# Generate a multi statement transaction such that the binlog cache size
# exceeds the configured "max_binlog_cache_size=4096" limit. Observe that
# an INCIDENT event is written to the binary log even though the statement 
# was safely rolled back. This INCIDENT event will stop the slave applier thread.
 
--source include/have_binlog_format_row.inc
--source include/have_innodb.inc
--source include/master-slave.inc
 
SET @old_max_binlog_cache_size= @@global.max_binlog_cache_size;
SET @old_binlog_cache_size= @@global.binlog_cache_size;
SET GLOBAL binlog_cache_size=4096;
SET GLOBAL max_binlog_cache_size=4096;
 
CREATE TABLE t( f INT) ENGINE=INNODB;
BEGIN;
let $counter=72;
--disable_query_log
while ($counter) {
--error 0,1534
INSERT INTO t VALUES (1);
dec $counter;
}
--enable_query_log
COMMIT;
SELECT COUNT(*) from t;
SHOW BINLOG EVENTS;
DROP TABLE t;
eval SET GLOBAL max_binlog_cache_size= @old_max_binlog_cache_size;
eval SET GLOBAL binlog_cache_size= @old_binlog_cache_size;
 
--source include/rpl_end.inc

Part of "SHOW BINLOG EVENTS" output:

master-bin.000001	9288	Annotate_rows	1	9335	INSERT INTO t VALUES (1)
master-bin.000001	9335	Table_map	1	9379	table_id: 31 (test.t)
master-bin.000001	9379	Write_rows_v1	1	9417	table_id: 31 flags: STMT_END_F
master-bin.000001	9417	Annotate_rows	1	9464	INSERT INTO t VALUES (1)
master-bin.000001	9464	Table_map	1	9508	table_id: 31 (test.t)
master-bin.000001	9508	Write_rows_v1	1	9546	table_id: 31 flags: STMT_END_F
master-bin.000001	9546	Xid	1	9577	COMMIT /* xid=140 */
master-bin.000001	9577	Incident	1	9634	#1 (LOST_EVENTS)
master-bin.000001	9634	Gtid	1	9676	GTID 0-1-3
master-bin.000001	9676	Query	1	9783	use `test`; DROP TABLE `t` /* generated by server */

Slave reports following error:

Last_SQL_Errno	1590
Last_SQL_Error	The incident LOST_EVENTS occurred on the master. Message: error writing to the binary log

Report INCIDENT event only in a case where safe rollback is not possible.



 Comments   
Comment by Sujatha Sivakumar (Inactive) [ 2020-01-10 ]

Hello Andrei,

Please review additional changes in 10.3.

sql/log.cc
Line numbers: 2104 - 21112.

http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.3-sujatha

https://github.com/MariaDB/server/commit/014f752826899a0b83fe7cc2e5106fb2aa73ef12

Thank you

Comment by Sujatha Sivakumar (Inactive) [ 2020-06-17 ]

Hello Andrei,

I have tested the patch once again on latest 10.2 and 10.3.

10.2 Changes: https://github.com/MariaDB/server/commit/4432e80a722fd70aa704a65d10237e8450387943

I tried to upmerge my fix in higher versions and observed that the following test
case doesn't report incident event in 10.3.

Test name: mysql-test/suite/rpl/t/rpl_mdev-11092.test
==========

--echo "#######################################################################"
--echo "# Test Case4: Table_map event write failure for mixed engine UPDATE #"
--echo "#######################################################################"
--connection master
SET debug_dbug="+d,table_map_write_error";
--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;

  1. Incident event
  2. 1590=ER_SLAVE_INCIDENT
    --let $slave_sql_errno= 1590
    --source include/wait_for_slave_sqMDEV-21443l_error_and_skip.inc

Analysis:
========
Aim of test case: A transaction is trying to update both trans/non trans table
in single update. It failed while writing table map event into transaction cache.
Since mixed engines are present in update 'set_incident' is invoked to alert slave
regarding partial update to database. But the incident event never gets into binary
log in 10.3. Hence slave never gets an incident. Upon debugging I observed that
the transaction cache is being reset in the following lines.

function: static int binlog_rollback(handlerton *hton, THD *thd, bool all)

  if (cache_mngr->trx_cache.empty())
  {
    /*
      we're here because cache_log was flushed in MYSQL_BIN_LOG::log_xid()
    */
    cache_mngr->reset(false, true);
    DBUG_RETURN(error);
  }

With debugger I observed that the 'trx_cache' is not actually empty, as it has
annotate event. But it still reports 'trx_cache' as empty. MDEV-8203 added
following code. If there are no row events in trans cache only
'annotate'/'table_map' are present then report 'trx_cache' as empty and
reset the cache.

  /*
    Return 1 if there is no relevant entries in the cache
 
    This is:
    - Cache is empty
    - There are row or critical (DDL?) events in the cache
 
    The status test is needed to avoid writing entries with only
    a table map entry, which would crash in do_apply_event() on the slave
    as it assumes that there is always a row entry after a table map.
  */
  bool empty() const
  {
    return (pending() == NULL &&
            (my_b_write_tell(&cache_log) == 0 ||
             ((status & (LOGGED_ROW_EVENT | LOGGED_CRITICAL)) == 0)));
  }

Because of this fix transaction cache is getting reset and the incident
event gets lost.

Hence I added a check for the presence of incident event in 'binlog_rollback'.
These are additional changes required for 10.3 along with 10.2 changes.

  /*
     An incident event would have been set if a multi statement transaction
     which tried to update both trans/non-trans table failed to write an event
     to cache. In this case partial updates would have been done in non
     transactional storage engine and safe rollback is not possible. In this
     case don't reset the cache, proceed further for cache write error handling
     part.
  */
  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()
    */
    cache_mngr->reset(false, true);
    DBUG_RETURN(error);
  }

Patch: https://github.com/MariaDB/server/commit/ac6ea253a0c4b08e9d121569c992f9d986f85c71#diff-a30b13c03c8d01a5301c20c921105ae4L2105-R2113
Please review them.

Comment by Andrei Elkin [ 2022-07-25 ]

[ Approved ] as PR-2190.

Comment by Brandon Nesterenko [ 2022-07-26 ]

Pushed into 10.3 as 555c12a.

There will be merge conflicts in 10.4 (git), 10.5 (git), and 10.7 (compilation only).

A branch exists for each conflict:
bb-10.4-21087-merge
bb-10.5-21087-merge
bb-10.7-21087-merge

Generated at Thu Feb 08 09:07:10 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.