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:Microsoft Windows
Assigned to: CPU Architecture:Any

[28 May 2014 14:33] Shane Bester
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`;
-------
[28 May 2014 15:57] Leandro Morgado
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.
[29 May 2014 5:08] MySQL Verification Team
Hello Shane,

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

Thanks,
Umesh
[29 May 2014 5:09] MySQL Verification Team
// 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)
[29 May 2014 5:49] MySQL Verification Team
// 5.7.5 is also affected
[11 Jul 2014 4:35] Venkatesh Duggirala
Post By developer:
==================
The same issue is reproduced just with Hash_scan alone ( without slave batching).
Changing the title to reflect the actual issue.
[28 Aug 2014 10:36] David Moss
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.
[25 Sep 2014 12:06] Laurynas Biveinis
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.
[25 Sep 2014 12:06] Laurynas Biveinis
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
[30 Sep 2014 12:16] David Moss
Posted by developer:
 
Reopened by fix, no new changelog entries needed. Set back to Closed.
[3 Jan 2017 11:09] Javier Escalante
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