MySQL Bugs: #60964: row based relay log events are lost from mysqlbinlog output

Bug #60964	row based relay log events are lost from mysqlbinlog output
Submitted:	24 Apr 2011 7:51	Modified:	21 Jan 2013 14:42
Reporter:	Yoshinori Matsunobu (OCA)	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S3 (Non-critical)
Version:	5.1.56, 5.6.3	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
mysqlbinlog might print "### Row event for unknown table" even though transactions succeeded on both master and slave.

How to repeat:
1) mysql -hslave_host
set global max_relay_log_size=4096;
set global relay_log_purge=0;

2) mysql -hmaster_host
set binlog_format=row;

# run long transaction 
CREATE TABLE t1 (id int primary key, value int, value2 text) engine=innodb;
begin;
insert into t1 values (1,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (2,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (3,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (4,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (5,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (6,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (7,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (8,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (9,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (10,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (11,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (12,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (13,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (14,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (15,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (16,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (17,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (18,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (19,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (20,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (21,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (22,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (23,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (24,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (25,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (26,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (27,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (28,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (29,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (30,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (31,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (32,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (33,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (34,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (35,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (36,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (37,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (38,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (39,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (40,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (41,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (42,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (43,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (44,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (45,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (46,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (47,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (48,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (49,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (50,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (51,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (52,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (53,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (54,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (55,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (56,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (57,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (58,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (59,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t1 values (60,1,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
commit;

Both master and slave should succeed the above transaction.

3) parsing relay logs on slave host
$ mysqlbinlog --base64-output=decode-rows --verbose mysqld-relay-bin.000005 | more
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#110424 16:32:22 server id 1307  end_log_pos 106        Start: binlog v 4, serve
r v 5.1.56-log created 110424 16:32:22
# at 106
#110424 16:32:22 server id 1306  end_log_pos 0  Start: binlog v 4, server v 5.1.
56-log created 110424 16:32:22
# at 208
#110424 16:33:37 server id 1306  end_log_pos 11925      Write_rows: table id 16
flags: STMT_END_F
### Row event for unknown table #16# at 292
# at 337
#110424 16:33:37 server id 1306  end_log_pos 11970      Table_map: `test`.`t1`
mapped to number 16
#110424 16:33:37 server id 1306  end_log_pos 12054      Write_rows: table id 16
flags: STMT_END_F
### INSERT INTO test.t1
### SET
###   @1=47
###   @2=1
###   @3='aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa'
.....

$ mysqlbinlog --base64-output=decode-rows --verbose mysqld-relay-bin.000004
.....
# at 3949
# at 3994
#110424 16:33:37 server id 1306  end_log_pos 11712      Table_map: `test`.`t1` mapped to number 16
#110424 16:33:37 server id 1306  end_log_pos 11796      Write_rows: table id 16 flags: STMT_END_F
### INSERT INTO test.t1
### SET
###   @1=45
###   @2=1
###   @3='aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa'
# at 4078
# at 4123
#110424 16:32:22 server id 1307  end_log_pos 4173       Rotate to mysqld-relay-bin.000005  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

mysqld-relay-bin.000004 ends with id=45, mysqld-relay-bin.000005 begins with id=47, so id=46 is lost.

Table_map event for id=46 was actually written in the tail of mysqld-relay-bin.000004, not in the beginning of mysqld-relay-bin.000005. So mysqlbinlog could not identify which table id=46 belongs to.

"mysqlbinlog .... mysqld-relay-bin.000004 mysqld-relay-bin.000005" was not helpful, either.

Thank you for the report.

Verified as described. I could not repeat it with 5.1, but can with 5.6.3. In test case attached row with id=29 is missed.

MTR test case

Attachment: rpl_bug60964.test (application/octet-stream, text), 6.69 KiB.

Master option file

Attachment: rpl_bug60964-master.opt (application/octet-stream, text), 20 bytes.

Slave option file

Attachment: rpl_bug60964-slave.opt (application/octet-stream, text), 75 bytes.

Internal analysis (Sven Sandberg):

[14 Jan 2013 7:53] 

Transactions are written to the binary log as events. Events from the end of the transaction may depend on events at the beginning of the transaction. Transactions cannot span multiple binary logs, however transactions can span multiple relay logs. This is all by design. Unfortunately this means that mysqlbinlog generates errors like the one in this bug report, when it reads a relay log that begins with a half transaction. There is not much we can do about this. Note, there are many other possible errors that can be generated for the same reason, for instance if the relay log is rotated between a User_var_log_event and a Query_log_event, the output from mysqlbinlog will cause wrong values to be inserted on the slave; in 5.6 the GTID event can be missing, etc.

In the future we should make mysqlbinlog accept GTIDs and only the basename of the binary log (or relay log), then it will use GTIDs to figure out which file(s) to read from. This is for post-5.6 though.

I don't think there is much we can do about this bug other than mark it as not a bug.

Just putting for someone who lands on this page after google search “Row event for unknown table”

This can happen on master binary log as well when you’re using a --start-position. If you extract complete binary log, that error goes away.