MySQL Bugs: #72788: HASH_SCAN seems broken: Can't find record in 't1' Error

Bug #72788	HASH_SCAN seems broken: Can't find record in 't1' Error_code: 1032
Submitted:	28 May 2014 14:33	Modified:	28 Aug 2014 10:36
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S2 (Serious)
Version:	5.6.17, 5.6.19, 5.7.5, 5.6.20	OS:	Windows
Assigned to:		CPU Architecture:	Any

Description:
without a PK, we enable slave batching mode to enhance performance, but this causes breakages on simple queries:

[ERROR] Slave SQL: Could not execute Delete_rows event on table test.t1; Can't find record in 't1', Error_code: 1032; Can't find record in 't1', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log i7-bin.000001, end_log_pos 786, Error_code: 1032
[Warning] Slave: Can't find record in 't1' Error_code: 1032
[Warning] Slave: Can't find record in 't1' Error_code: 1032

How to repeat:
Setup a working RBR master/slave.   But on slave, use these additional options:
--slave_allow_batching=1 --slave_rows_search_algorithms="INDEX_SCAN,HASH_SCAN"

On master run this SQL:

-------
drop table if exists `t1`;
create table `t1` (`z` int,`a` int,key(`a`)) engine=innodb;
insert into `t1` values(1,1),(2,0),(3,1),(4,4);
delete from `t1` order by `z`;
-------

This also happens when:

slave1 [localhost] {msandbox} (test) > SHOW VARIABLES LIKE '%algorithms%';
+------------------------------+----------------------+
| Variable_name                | Value                |
+------------------------------+----------------------+
| slave_rows_search_algorithms | TABLE_SCAN,HASH_SCAN |
+------------------------------+----------------------+ 

So it seems HASH_SCAN is the problem.

WORKAROUND:
Replication can be resumed by setting slave_rows_search_algorithms back to the default:
=====
 Master_Log_File: mysql-bin.000004
          Read_Master_Log_Pos: 1514
               Relay_Log_File: mysql_sandbox20285-relay-bin.000012
                Relay_Log_Pos: 760
        Relay_Master_Log_File: mysql-bin.000004
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
...
                   Last_Errno: 1032
                   Last_Error: Could not execute Delete_rows event on table test.t1; Can't find record in 't1', Error_code: 1032; Can't find record in 't1', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log mysql-bin.000004, end_log_pos 786
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 597

slave2 [localhost] {msandbox} ((none)) > SET GLOBAL slave_rows_search_algorithms = "TABLE_SCAN,INDEX_SCAN";
Query OK, 0 rows affected (0.02 sec)

slave2 [localhost] {msandbox} ((none)) > START SLAVE;
Query OK, 0 rows affected (0.01 sec)

          Connect_Retry: 60
              Master_Log_File: mysql-bin.000004
          Read_Master_Log_Pos: 1514
               Relay_Log_File: mysql_sandbox20285-relay-bin.000013
                Relay_Log_Pos: 933
        Relay_Master_Log_File: mysql-bin.000004
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
                         ...
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 1514
=====
Note however that this implies table scans for tables without a primary/unique key, which can be slow/problematic on larger tables.

Hello Shane,

Thank you for the bug report and test case.
Verified as described on 5.6.17/19.

Thanks,
Umesh

// 5.6.19

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: master-bin.000003
          Read_Master_Log_Pos: 1510
               Relay_Log_File: slave-relay-bin.000002
                Relay_Log_Pos: 761
        Relay_Master_Log_File: master-bin.000003
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1032
                   Last_Error: Could not execute Delete_rows event on table test.t1; Can't find record in 't1', Error_code: 1032; Can't find record in 't1', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log master-bin.000003, end_log_pos 1479
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 1290
              Relay_Log_Space: 1154
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1032
               Last_SQL_Error: Could not execute Delete_rows event on table test.t1; Can't find record in 't1', Error_code: 1032; Can't find record in 't1', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log master-bin.000003, end_log_pos 1479
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: a142eac7-e832-11e3-acfb-00163e44510c
             Master_Info_File: /tmp/slave/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State:
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp: 140531 01:15:44
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
1 row in set (0.00 sec)

// 5.7.5 is also affected

Post By developer:
==================
The same issue is reproduced just with Hash_scan alone ( without slave batching).
Changing the title to reflect the actual issue.

The following was added to the 5.6.21 and 5.7.5 changelog with commit 4069:
When using row-based replication, setting a slave's slave_rows_search_algorithms variable to HASH_SCAN caused an ER_RECORD_NOT_FOUND error even though that record existed in the storage layer. This fix ensures that the unique key for each record is correctly maintained and such a situation does not occur.

revno: 6096
committer: Venkatesh Duggirala<venkatesh.duggirala@oracle.com>
branch nick: mysql-5.6
timestamp: Mon 2014-07-28 18:41:22 +0530
message:
Bug#18860225 HASH_SCAN SEEMS BROKEN: CAN'T FIND RECORD IN 'T1' ERROR_CODE: 1032

Problem: In RBR, on slave setting slave_search_algorithm to HASH_SCAN causes "Can't find
record" error even though that record exists in storage layer.

Analysis: When slave's slave_search_algorithm is set to Hash_scan, it prepares
a unique key list in add_key_to_distinct_keyset() for all the rows in a
particular Row_event.
For eg: Lets say a table 't1(c1,c2, key(c2))' contains 4 tuples
(1,10), (2,20), (3,10), (4,40). And lets say on Master a delete
is executed to delete all these four tuples. Received Rows_log_event on slave
contains all these 4 tuples. Slave should prepare a unique key list(i.e., 10,20,40).
Later, the same unique key list will be used to retrieve all tuples associated
to each key in the list from storage engine. In the old code, there was a problem
while preparing this unique key list in add_key_to_distinct_keyset. Before
inserting an element in to the unique list, instead of searching the entire list whether an
element is there or not, it was comparing only with the last inserted element.
This can create problem when the processing list is not a sorted array.
For eg: While processing 10,20,10,40 list, add_key_to_distinct_keyset() list
thinks that the third 10 is unique as it compares with last inserted key which
is 20. Hence unique key list prepared will be 10,20,10,40 instead of 10,20,40.

Later in Rows_log_event::do_apply_event, we retrieve all the tuples with the first
key in the list (10) and will apply the event on those tuples (which is delete in
this example). When the logic retrieves '10' again from wrongly formed unique list,
it tries to find the tuples from storage engine using the key value '10'. Thus
storage engine returns 'ER_RECORD_NOT_FOUND' error.

Fix: Correcting add_key_to_distinct_keyset() logic to maintain unique key list
i.e., instead of comparing the newly inserted value with only last inserted key,
now the list (unique list) will be maintained by std::set. To compare two keys,
We have a compare class which will be supplied to std::set. This compare class
compares two given keys using key_cmp2 function which is added in key.cc file.

revno: 6097
committer: Venkatesh Duggirala<venkatesh.duggirala@oracle.com>
branch nick: mysql-5.6
timestamp: Tue 2014-07-29 19:04:33 +0530
message:
  Bug#18860225 HASH_SCAN SEEMS BROKEN: CAN'T FIND RECORD IN 'T1' ERROR_CODE: 1032
  
  Fixing windows build failure

Posted by developer:
 
Reopened by fix, no new changelog entries needed. Set back to Closed.

Hello,

I get the following error, could somebody give me a clue of how to fix it?
thanks

 Could not execute Delete_rows event on table radi                                                           us.radacct; Can't find record in 'radacct', Error_code: 1032; handler error HA_E                                                           RR_KEY_NOT_FOUND; the event's master log mysql-bin.000287, end_log_pos 1210226