| 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: | |
| 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 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.
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)