Bug #60091 RBR + no PK + update NULL value --> slave break with error HA_ERR_END_OF_FILE
Submitted: 10 Feb 2011 14:33 Modified: 29 Mar 2011 12:20
Reporter: Santo Leto Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Row Based Replication ( RBR ) Severity:S3 (Non-critical)
Version:5.1.56, 5.5.8, 5.5.10 OS:Any
Assigned to: Luis Soares CPU Architecture:Any
Tags: break, null, RBR, UPDATE

[10 Feb 2011 14:33] Santo Leto
Description:
Row based replication breaks when trying to update a null value from a table without PK.

How to repeat:
* On Master:

CREATE DATABASE rbrBUG;
USE rbrBUG;

CREATE TABLE `t` (
`a` int(11) NOT NULL,
`b` int(11) NOT NULL,
`c` int(11) DEFAULT '-1'
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

INSERT INTO `t` VALUES (1,1,1), (1,2,NULL), (1,3,0), (2,4,0);

SELECT * FROM rbrBUG.t;

UPDATE t SET a=1, b=2, c=-1 WHERE a=1 AND b=2 AND ISNULL(c);

SELECT * FROM rbrBUG.t;

* On Slave:

SELECT * FROM rbrBUG.t;

SHOW SLAVE STATUS\G

* Output from Master:
mysql> CREATE DATABASE rbrBUG;
Query OK, 1 row affected (0.05 sec)

mysql> USE rbrBUG;
Database changed
mysql>
mysql> CREATE TABLE `t` (
    -> `a` int(11) NOT NULL,
    -> `b` int(11) NOT NULL,
    -> `c` int(11) DEFAULT '-1'
    -> ) ENGINE=InnoDB DEFAULT CHARSET=latin1;
Query OK, 0 rows affected (0.28 sec)

mysql>
mysql> INSERT INTO `t` VALUES (1,1,1), (1,2,NULL), (1,3,0), (2,4,0);
Query OK, 4 rows affected (0.23 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql>
mysql> SELECT * FROM rbrBUG.t;
+---+---+------+
| a | b | c    |
+---+---+------+
| 1 | 1 |    1 |
| 1 | 2 | NULL |
| 1 | 3 |    0 |
| 2 | 4 |    0 |
+---+---+------+
4 rows in set (0.00 sec)

mysql>
mysql> UPDATE t SET a=1, b=2, c=-1 WHERE a=1 AND b=2 AND ISNULL(c);
Query OK, 1 row affected (0.37 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql>
mysql> SELECT * FROM rbrBUG.t;
+---+---+------+
| a | b | c    |
+---+---+------+
| 1 | 1 |    1 |
| 1 | 2 |   -1 |
| 1 | 3 |    0 |
| 2 | 4 |    0 |
+---+---+------+
4 rows in set (0.00 sec)

* Output from Slave:

mysql> SELECT * FROM rbrBUG.t;
+---+---+------+
| a | b | c    |
+---+---+------+
| 1 | 1 |    1 |
| 1 | 2 | NULL |
| 1 | 3 |    0 |
| 2 | 4 |    0 |
+---+---+------+
4 rows in set (0.00 sec)

mysql>
mysql> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: localhost
                  Master_User: root
                  Master_Port: 55081
                Connect_Retry: 10
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 970
               Relay_Log_File: meredith-relay-bin.000002
                Relay_Log_Pos: 923
        Relay_Master_Log_File: mysql-bin.000001
             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 Update_rows event on table rbrb
ug.t; Can't find record in 't', Error_code: 1032; handler error HA_ERR_END_OF_FI
LE; the event's master log mysql-bin.000001, end_log_pos 943
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 777
              Relay_Log_Space: 1275
              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 Update_rows event on table rbrb
ug.t; Can't find record in 't', Error_code: 1032; handler error HA_ERR_END_OF_FI
LE; the event's master log mysql-bin.000001, end_log_pos 943
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
1 row in set (0.00 sec)
[10 Feb 2011 16:56] Valeriy Kravchuk
Verified with current mysql-5.5 on Mac OS X:

macbook-pro:mysql-test openxs$ ./mtr --mysqld=--binlog-format="row" bug60091
Logging: ./mtr  --mysqld=--binlog-format=row bug60091
110210 18:51:44 [Warning] Setting lower_case_table_names=2 because file system for /var/folders/dX/dXCzvuSlHX4Op1g-o1jIWk+++TI/-Tmp-/A5QbrfhVe6/ is case insensitive
110210 18:51:44 [Note] Plugin 'FEDERATED' is disabled.
MySQL Version 5.5.10
Using binlog format 'row'
Checking supported features...
 - skipping ndbcluster
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
vardir: /Users/openxs/dbs/5.5/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/Users/openxs/dbs/5.5/mysql-test/var'...
Installing system database...
Using server port 64789

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.bug60091                            [ fail ]
        Test ended at 2011-02-10 18:52:06

CURRENT_TEST: main.bug60091
=== SHOW MASTER STATUS ===
---- 1. ----
File	slave-bin.000001
Position	592
Binlog_Do_DB	
Binlog_Ignore_DB	
==========================

=== SHOW SLAVE STATUS ===
---- 1. ----
Slave_IO_State	Waiting for master to send event
Master_Host	127.0.0.1
Master_User	root
Master_Port	13000
Connect_Retry	1
Master_Log_File	master-bin.000001
Read_Master_Log_Pos	796
Relay_Log_File	slave-relay-bin.000002
Relay_Log_Pos	750
Relay_Master_Log_File	master-bin.000001
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 Update_rows event on table rbrbug.t; Can't find record in 't', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log master-bin.000001, end_log_pos 769
Skip_Counter	0
Exec_Master_Log_Pos	603
Relay_Log_Space	1099
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	
Master_SSL_Verify_Server_Cert	No
Last_IO_Errno	0
Last_IO_Error	
Last_SQL_Errno	1032
Last_SQL_Error	Could not execute Update_rows event on table rbrbug.t; Can't find record in 't', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log master-bin.000001, end_log_pos 769
Replicate_Ignore_Server_Ids	
Master_Server_Id	1
=========================

=== SHOW PROCESSLIST ===
---- 1. ----
Id	2
User	root
Host	localhost:64801
db	test
Command	Sleep
Time	0
State	
Info	
---- 2. ----
Id	3
User	root
Host	localhost:64802
db	test
Command	Sleep
Time	3
State	
Info	
---- 3. ----
Id	4
User	system user
Host	
db	
Command	Connect
Time	1
State	Waiting for master to send event
Info	
---- 4. ----
Id	6
User	root
Host	localhost:64808
db	test
Command	Query
Time	0
State	
Info	SHOW PROCESSLIST
---- 5. ----
Id	7
User	root
Host	localhost:64809
db	test
Command	Sleep
Time	0
State	
Info	
========================

analyze: sync_with_master
mysqltest: At line 21: sync_slave_with_master failed: 'select master_pos_wait('master-bin.000001', 796, 300)' returned NULL indicating slave SQL thread failure

The result from queries just before the failure was:
< snip >
CREATE TABLE `t` (
`a` int(11) NOT NULL,
`b` int(11) NOT NULL,
`c` int(11) DEFAULT '-1'
) ENGINE=InnoDB DEFAULT CHARSET=latin1;
INSERT INTO `t` VALUES (1,1,1), (1,2,NULL), (1,3,0), (2,4,0);
SELECT * FROM rbrBUG.t;
a	b	c
1	1	1
1	2	NULL
1	3	0
2	4	0
UPDATE t SET a=1, b=2, c=-1 WHERE a=1 AND b=2 AND ISNULL(c);
SELECT * FROM rbrBUG.t;
a	b	c
1	1	1
1	2	-1
1	3	0
2	4	0

More results from queries before failure can be found in /Users/openxs/dbs/5.5/mysql-test/var/log/bug60091.log

...

**** SHOW RELAYLOG EVENTS on default ****
relaylog_name = 'slave-relay-bin.000002'
SHOW RELAYLOG EVENTS IN 'slave-relay-bin.000002';
Log_name	Pos	Event_type	Server_id	End_log_pos	Info
slave-relay-bin.000002	4	Format_desc	2	107	Server ver: 5.5.10-debug-log, Binlog ver: 4
slave-relay-bin.000002	107	Rotate	1	0	master-bin.000001;pos=4
slave-relay-bin.000002	151	Format_desc	1	107	Server ver: 5.5.10-debug-log, Binlog ver: 4
slave-relay-bin.000002	254	Query	1	194	CREATE DATABASE rbrBUG
slave-relay-bin.000002	341	Query	1	385	use `rbrbug`; CREATE TABLE `t` (
`a` int(11) NOT NULL,
`b` int(11) NOT NULL,
`c` int(11) DEFAULT '-1'
) ENGINE=InnoDB DEFAULT CHARSET=latin1
slave-relay-bin.000002	532	Query	1	455	BEGIN
slave-relay-bin.000002	602	Table_map	1	499	table_id: 41 (rbrbug.t)
slave-relay-bin.000002	646	Write_rows	1	576	table_id: 41 flags: STMT_END_F
slave-relay-bin.000002	723	Xid	1	603	COMMIT /* xid=125 */
slave-relay-bin.000002	750	Query	1	673	BEGIN
slave-relay-bin.000002	820	Table_map	1	717	table_id: 41 (rbrbug.t)
slave-relay-bin.000002	864	Update_rows	1	769	table_id: 41 flags: STMT_END_F
slave-relay-bin.000002	916	Xid	1	796	COMMIT /* xid=127 */

 - saving '/Users/openxs/dbs/5.5/mysql-test/var/log/main.bug60091/' to '/Users/openxs/dbs/5.5/mysql-test/var/log/main.bug60091/'
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 23 seconds executing testcases

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): main.bug60091
[18 Feb 2011 14:20] Valeriy Kravchuk
It does not break this way in 5.1.56, so this looks like a regression...
[18 Feb 2011 14:53] Valeriy Kravchuk
Ignore my previous comment. 5.1.56 is also affected in the very same way:

macbook-pro:mysql-test openxs$  ./mtr --mysqld=--binlog-format="row" bug60091
Logging: ./mtr  --mysqld=--binlog-format=row bug60091
110218 16:49:55 [Warning] Setting lower_case_table_names=2 because file system for /var/folders/dX/dXCzvuSlHX4Op1g-o1jIWk+++TI/-Tmp-/1CfAZcb2b2/ is case insensitive
110218 16:49:55 [Note] Plugin 'FEDERATED' is disabled.
110218 16:49:55 [Note] Plugin 'ndbcluster' is disabled.
MySQL Version 5.1.56
Using binlog format 'row'
Checking supported features...
 - skipping ndbcluster
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
vardir: /Users/openxs/dbs/5.1/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/Users/openxs/dbs/5.1/mysql-test/var'...
Installing system database...
Using server port 50237

==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.bug60091                            [ fail ]
        Test ended at 2011-02-18 16:50:09

CURRENT_TEST: main.bug60091
=== SHOW MASTER STATUS ===
---- 1. ----
File	slave-bin.000001
Position	591
Binlog_Do_DB	
Binlog_Ignore_DB	
==========================

=== SHOW SLAVE STATUS ===
---- 1. ----
Slave_IO_State	Waiting for master to send event
Master_Host	127.0.0.1
Master_User	root
Master_Port	13000
Connect_Retry	1
Master_Log_File	master-bin.000001
Read_Master_Log_Pos	795
Relay_Log_File	slave-relay-bin.000002
Relay_Log_Pos	748
Relay_Master_Log_File	master-bin.000001
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 Update_rows event on table rbrbug.t; Can't find record in 't', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log master-bin.000001, end_log_pos 768
Skip_Counter	0
Exec_Master_Log_Pos	602
Relay_Log_Space	1096
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	
Master_SSL_Verify_Server_Cert	No
Last_IO_Errno	0
Last_IO_Error	
Last_SQL_Errno	1032
Last_SQL_Error	Could not execute Update_rows event on table rbrbug.t; Can't find record in 't', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log master-bin.000001, end_log_pos 768
...

The following line

-- source include/have_innodb.inc

was missed in the test and, while for 5.5 it is OK as InnoDB is used by default, for 5.1 this forced table to be created as MyISAM. This break does NOT happen with MyISAM tables.
[18 Feb 2011 14:55] Luis Soares
The following (narrowed down) test case breaks 5.1+ (tested with latest
binaries from PB2):

--source include/master-slave.inc
--source include/have_binlog_format_row.inc
--source include/have_innodb.inc

CREATE TABLE t1 (c1 int(11) NOT NULL,
                 c2 int(11) NOT NULL,
                 c3 int(11) DEFAULT '-1')
               ENGINE=InnoDB DEFAULT CHARSET=latin1;

INSERT INTO t1 VALUES (1,2,NULL);
UPDATE t1 SET c1=1, c2=2, c3=-1;

--sync_slave_with_master

--let $diff_tables=master:test.t1, slave:test.t1
--source include/diff_tables.inc

--connection master
DROP TABLE t1;
--sync_slave_with_master
--exit

This bug seems to be specific on tables that are using the InnoDB storage
engine.

Valeriy, note the need for include/have_innodb.inc when testing in 5.1, 
whereas in 5.5, InnoDB is the default engine, so there is no need to
include such file. If the include is not done in 5.1, then the test will 
succeed because MyISAM storage engine would be used instead...

[ls229627@fimafeng11]/export/home/tmp/ls229627/bzr/tmp/mysql-5.1.57-linux-x86_64/mysql-test: perl mtr --mem rpl_60091
Logging: mtr  --mem rpl_60091
110218 15:50:11 [Note] Plugin 'FEDERATED' is disabled.
110218 15:50:11 [Note] Plugin 'ndbcluster' is disabled.
MySQL Version 5.1.57
Checking supported features...
 - skipping ndbcluster
 - SSL connections supported
Collecting tests...
 - adding combinations for rpl
vardir: /export/home/tmp/ls229627/bzr/tmp/mysql-5.1.57-linux-x86_64/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/export/home/tmp/ls229627/bzr/tmp/mysql-5.1.57-linux-x86_64/mysql-test/var'...
 - symlinking 'var' to '/dev/shm/var_auto_oaa2'
Installing system database...
Using server port 59693

==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
rpl.rpl_60091 'mix'                      [ skipped ]  Doesn't support --binlog-format='mixed'
include/master-slave.inc
[connection master]
CREATE TABLE t1 (c1 int(11) NOT NULL,
c2 int(11) NOT NULL,
c3 int(11) DEFAULT '-1')
ENGINE=InnoDB DEFAULT CHARSET=latin1;
INSERT INTO t1 VALUES (1,2,NULL);
UPDATE t1 SET c1=1, c2=2, c3=-1;
rpl.rpl_60091 'row'                      [ fail ]
        Test ended at 2011-02-18 15:50:11

CURRENT_TEST: rpl.rpl_60091
=== SHOW MASTER STATUS ===
---- 1. ----
File    slave-bin.000001
Position        456
Binlog_Do_DB
Binlog_Ignore_DB
==========================

=== SHOW SLAVE STATUS ===
---- 1. ----
Slave_IO_State  Waiting for master to send event
Master_Host     127.0.0.1
Master_User     root
Master_Port     13000
Connect_Retry   1
Master_Log_File master-bin.000001
Read_Master_Log_Pos     655
Relay_Log_File  slave-relay-bin.000002
Relay_Log_Pos   611
Relay_Master_Log_File   master-bin.000001
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 Update_rows event on table test.t1; Can't find record in 't1', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log master-bin.000001, end_log_pos 628
Skip_Counter    0
Exec_Master_Log_Pos     465
Relay_Log_Space 956
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   
Master_SSL_Verify_Server_Cert   No
Last_IO_Errno   0
Last_IO_Error   
Last_SQL_Errno  1032
Last_SQL_Error  Could not execute Update_rows event on table test.t1; Can't find record in 't1', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log master-bin.000001, end_log_pos 628
[29 Mar 2011 12:20] Jon Stephens
Documented bugfix in the 5.1.57, 5.5.12, and 5.6.3 changelogs, as follows:

        Trying to update a column, previously set to NULL, of an InnoDB
        table with no primary key caused replication to fail with Can't
        find record in 'table' on the slave.

Closed.