MySQL Bugs: #37317: Could not execute Delete_rows event on table handler error HA_ERR_KEY_NOT

Bug #37317	Could not execute Delete_rows event on table handler error HA_ERR_KEY_NOT_FOUND
Submitted:	10 Jun 2008 21:21	Modified:	2 Sep 2008 20:27
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S2 (Serious)
Version:	5.1.26	OS:	Any
Assigned to:	Assigned Account	CPU Architecture:	Any

Description:
simple replication between two 5.1.26 servers dies with this:

080610 23:18:39 [ERROR] Slave SQL: Could not execute Delete_rows event on table test.t2; Can't find record in 't2', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log box1-bin.000001, end_log_pos 334780, Error_code: 1032
080610 23:18:39 [Warning] Slave: Can't find record in 't2' Error_code: 1032
080610 23:18:39 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'box1-bin.000001' position 334425

Seems to happen when deadlocks happen on the master.

How to repeat:
master runs with :  --binlog_format=row --server-id=1 --log-bin
setup replication by pointing slave to the master.
point the testcase uploaded to the master and watch replication break
after some deadlocks are seen

point to master server and run. monitor show slave status for errors

Attachment: bug37317.c (text/plain), 9.00 KiB.

Test case spawns three threads that insert/delete/update two InnoDB tables. There are frequent deadlocks during the execution.

Master is running with repeatable-read transaction isolation level and AUTOCOMMIT is set.

We are seeing this same bug replicating from a 5.1.25 master to a 5.1.26 slave.  Does this issue only affect 5.1.26?  Would downgrading the 5.1.26 to 5.1.25 resolve the issue?  This is breaking our replication at least once a day.

In our case, there is a delete followed by an insert occurring from a trigger on a different table.  The table in question is a summary table that is updated on activity to the base table:

CREATE TRIGGER accounted_barcodes_after_insert AFTER INSERT ON accounted_barcodes
FOR EACH ROW
BEGIN
    DELETE FROM accounting_results_m_v WHERE id = NEW.id;
    INSERT INTO accounting_results_m_v SELECT * FROM accounting_results_v WHERE id = NEW.id;
    DELETE FROM intwh.accounting_status_mv WHERE id = NEW.id;
    INSERT INTO intwh.accounting_status_mv SELECT * FROM international.accounting_status_v WHERE id = NEW.id;
END //

Completion date moved one month since other more urgent issues took priority.

The bug is triggered only when using a transactional table, and update statement that fails, and is followed by an insert.

1. The update is executed, but fails (in this particular case due to a deadlock
   on the master).
2. The binary log is rolled back, but the binlog_table_map counter is not reset.
3. An insert statement is started and write_locked_table_maps() is called.
   It checks if binlog_table_map > 0, and skips writing table maps.
4. Since there are no table maps for the statement, the record is not written
   to the table.
5. Later, a delete of the row comes by and tries to delete a row that doesn't
   exist.

This bug is a duplicate of BUG#32709, which is waiting for approval.

So does the patch in http://bugs.mysql.com/bug.php?id=32709 apply to this case as well?

Yes, the bug is fixed by the same patch as BUG#32709.

Getting a similar issue with the binlogs using those settings: Could not execute Delete_rows event on table [schema.table]_transaction; Can't find record in '[table]', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log mysql-bin.000129, end_log_pos 78218889

using 5.1.33-0.rhel5 on x86_64

We are also getting the same error in 3 way circular replication.
If one slave fails after some time the whole replication fails.
We are using MySQL Community server 5.1.44.

Am also getting this on MySQL 5.1.41-community-log:

Could not execute Delete_rows event on table foo.bar; Can't find record in 'bar', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log mysql-bin.004009, end_log_pos 760660166

Editing to add -- the 5.1.41 server in question has:

no triggers
READ-COMMITTED isolation level
MIXED binlog format
AUTOCOMMIT on

and the table itself is indeed InnoDB.

Hi Sheeri and shishu,

I'm sorry to here that there are still problems in this area, but it can be hard to see what the problem is without more information.

Could you provide us with part of the binary log where the slave stops (so we know what row that is not found) and also the table definition that is being used? For the binary log, it is sufficient to have a --hexdump from mysqlbinlog for the events where the error occurs.

I see similar failures on 5.1.47 + InnoDB Plugin.
When the load increases and the server gets more deadlocks, RBR stops on HA_ERR_KEY_NOT_FOUND while doing INSERT/DELETE. The INSERT/DELETE statements work with a single row and are always run from inside a trigger.
I'm not able to find a reproducible testcase though.
TX isolation level is REPEATABLE-READ, only InnoDB tables are involved in the problematic tranactions.

It happens for us on 5.1.47 - both master and slave have exactly the same version. 

Some data about our MySQL settings:
binlog_format = ROW 			(The bug happens only when using ROW IIUC ?)
innodb_flush_log_at_trx_commit = 0 	(but it matters only in case of mysql crash, right ? And there was no crash)
innodb_locks_unsafe_for_binlog = OFF
tx_isolation = REPEATABLE-READ

But the intriguing information is that this happened only on 2 slaves which are generally idle, and didn't happen on identical slave which is used for production read traffic. All of them have excactly the same my.cnf (excluding server_id naturally).

The same bug never occured for us on other clusters that have the same schemas but still run with MySQL 5.0.

The transaction that didn't happen because of replication error was a 331 of deletes like:
DELETE FROM `roguesurvivor`.`recentchanges` WHERE `rc_id`=369 LIMIT 1;
DELETE FROM `roguesurvivor`.`recentchanges` WHERE `rc_id`=370 LIMIT 1;
DELETE FROM `roguesurvivor`.`recentchanges` WHERE `rc_id`=371 LIMIT 1;

Error message:

100910  0:48:41 [ERROR] Slave SQL: Could not execute Delete_rows event on table roguesurvivor.recentchanges; Can't find record in 'recentchanges', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log db-sc1_bin.000281, end_log_pos 446308080, Error_code: 1032
100910  0:48:41 [Warning] Slave: Can't find record in 'recentchanges' Error_code: 1032

Related part of binary log:

BINLOG '
ZYCJTBMtAQAAQwAAAHcOmhoAALHrMQEAAAEADXJvZ3Vlc3Vydml2b3IAEHBhZ2Vfd2lraWFfcHJv
cHMAAwMD/AECAA==
ZYCJTBctAQAARQAAALwOmhoQALHrMQEAAAEAA//4vQEAAAAAAAAdAGE6MTp7aTowO3M6MTE6IlBs
YWNlaG9sZGVyIjt9
'/*!*/;
# at 446303932
# at 446304040
# at 446305068
# at 446306025
# at 446307040
# at 446308080
# at 446309065
(...)
#100910  0:48:37 server id 301  end_log_pos 446304040   Table_map: `roguesurvivor`.`recentchanges` mapped to number 20048808
#100910  0:48:37 server id 301  end_log_pos 446305068   Delete_rows: table id 20048808
#100910  0:48:37 server id 301  end_log_pos 446306025   Delete_rows: table id 20048808
#100910  0:48:37 server id 301  end_log_pos 446307040   Delete_rows: table id 20048808
#100910  0:48:37 server id 301  end_log_pos 446308080   Delete_rows: table id 20048808
#100910  0:48:37 server id 301  end_log_pos 446309065   Delete_rows: table id 20048808
(...)

Create Table: CREATE TABLE `recentchanges` (
  `rc_id` int(11) NOT NULL AUTO_INCREMENT,
  `rc_timestamp` varbinary(14) NOT NULL DEFAULT '',
  `rc_cur_time` varbinary(14) NOT NULL DEFAULT '',
  `rc_user` int(10) unsigned NOT NULL DEFAULT '0',
  `rc_user_text` varchar(255) CHARACTER SET latin1 COLLATE latin1_bin NOT NULL,
  `rc_namespace` int(11) NOT NULL DEFAULT '0',
  `rc_title` varchar(255) CHARACTER SET latin1 COLLATE latin1_bin NOT NULL DEFAULT '',
  `rc_comment` varchar(255) CHARACTER SET latin1 COLLATE latin1_bin NOT NULL DEFAULT '',
  `rc_minor` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `rc_bot` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `rc_new` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `rc_cur_id` int(10) unsigned NOT NULL DEFAULT '0',
  `rc_this_oldid` int(10) unsigned NOT NULL DEFAULT '0',
  `rc_last_oldid` int(10) unsigned NOT NULL DEFAULT '0',
  `rc_type` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `rc_moved_to_ns` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `rc_moved_to_title` varchar(255) CHARACTER SET latin1 COLLATE latin1_bin NOT NULL DEFAULT '',
  `rc_patrolled` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `rc_ip` varbinary(40) NOT NULL DEFAULT '',
  `rc_old_len` int(11) DEFAULT NULL,
  `rc_new_len` int(11) DEFAULT NULL,
  `rc_deleted` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `rc_logid` int(10) unsigned NOT NULL DEFAULT '0',
  `rc_log_type` varbinary(255) DEFAULT NULL,
  `rc_log_action` varbinary(255) DEFAULT NULL,
  `rc_params` blob,
  PRIMARY KEY (`rc_id`),
  KEY `rc_timestamp` (`rc_timestamp`),
  KEY `rc_namespace_title` (`rc_namespace`,`rc_title`),
  KEY `rc_cur_id` (`rc_cur_id`),
  KEY `new_name_timestamp` (`rc_new`,`rc_namespace`,`rc_timestamp`),
  KEY `rc_ip` (`rc_ip`),
  KEY `rc_ns_usertext` (`rc_namespace`,`rc_user_text`),
  KEY `rc_user_text` (`rc_user_text`,`rc_timestamp`)
) ENGINE=InnoDB AUTO_INCREMENT=625 DEFAULT CHARSET=latin1

Ran into the similar replication issue. as below.  We had event enabled to purge records older than 90 days. BTW disabled on slave.

Last_Errno: 1032
Last_Error: Could not execute Delete_rows event on table inv001.invitation; Can't find record in 'invitation', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log binary-logs.000252, end_log_pos 22879378