MySQL Bugs: #37137: Func/proc calling func/proc written incorrectly to binlog

Bug #37137	Func/proc calling func/proc written incorrectly to binlog
Submitted:	2 Jun 2008 11:14	Modified:	29 Aug 2008 9:25
Reporter:	Sven Sandberg	Email Updates:
Status:	Won't fix	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.1, 6.0	OS:	Any
Assigned to:	Zhenxing He	CPU Architecture:	Any
Tags:	binlog, CALL, FUNCTION, PROCEDURE, RBR, recursive, table map, table_map_log_event, transaction

Description:
When a function or procedure modifies a table and calls another function or procedure that modifies the same table, then it is written incorrectly to the binlog:

 (1) A procedure that calls another function or procedure generates two transactions in the binlog.

 (2) A function that calls another function or procedure generates an extra Table_map_log_event in the binlog. The two Table_map_log_events map the same table to the same id.

I've seen this in both 5.1 and 6.0.

Problem (1) looks especially bad. It can probably be used to cause the slave to be out of sync in some situations (e.g., if the statement generates an error, e.g., duplicate key error, and rolls back). I can try to find such a case.

Problem (2) is probably harmless, but we should investigate why it happens since it is not what one would expect.

How to repeat:
Run the following test:

==== begin rpl_bug.test ====
source include/master-slave.inc;

CREATE TABLE t1 (a INT);

DELIMITER |;

CREATE PROCEDURE proc()
BEGIN
  INSERT INTO t1 VALUES (1);
END|

CREATE FUNCTION func() RETURNS INT
BEGIN
  INSERT INTO t1 VALUES (2);
  RETURN 100;
END|

CREATE function func_func() RETURNS INT
BEGIN
  DECLARE x INT;
  INSERT INTO t1 VALUES (3);
  SET x = func();
  RETURN 101;
END|

CREATE function func_proc() RETURNS INT
BEGIN
  INSERT INTO t1 VALUES (4);
  CALL proc();
  RETURN 102;
END|

CREATE PROCEDURE proc_func()
BEGIN
  DECLARE x INT;
  INSERT INTO t1 VALUES (5);
  SET x = func();
END|

CREATE PROCEDURE proc_proc()
BEGIN
  INSERT INTO t1 VALUES (6);
  CALL proc();
END|

DELIMITER ;|

# Logged with an extra Table_map_log_event.
SELECT func_func();

# Logged with an extra Table_map_log_event.
SELECT func_proc();

# Logged as two transactions.
CALL proc_func();

# Logged as two transactions.
CALL proc_proc();

SHOW BINLOG EVENTS;

#SELECT * FROM t1;
#
#sync_slave_with_master;
#
#SELECT * FROM t1;
==== end rpl_bug.test ====

The relevant part of the output of SHOW BINLOG EVENTS is:

==== begin SHOW BINLOG EVENTS ====
master-bin.000001	1270	Query	1	1338	use `test`; BEGIN
master-bin.000001	1338	Table_map	1	1379	table_id: 25 (test.t1)
master-bin.000001	1379	Table_map	1	1420	table_id: 25 (test.t1)
master-bin.000001	1420	Write_rows	1	1459	table_id: 25 flags: STMT_END_F
master-bin.000001	1459	Query	1	1528	use `test`; COMMIT
master-bin.000001	1528	Query	1	1596	use `test`; BEGIN
master-bin.000001	1596	Table_map	1	1637	table_id: 25 (test.t1)
master-bin.000001	1637	Table_map	1	1678	table_id: 25 (test.t1)
master-bin.000001	1678	Write_rows	1	1717	table_id: 25 flags: STMT_END_F
master-bin.000001	1717	Query	1	1786	use `test`; COMMIT
master-bin.000001	1786	Query	1	1854	use `test`; BEGIN
master-bin.000001	1854	Table_map	1	1895	table_id: 25 (test.t1)
master-bin.000001	1895	Write_rows	1	1929	table_id: 25 flags: STMT_END_F
master-bin.000001	1929	Query	1	1998	use `test`; COMMIT
master-bin.000001	1998	Query	1	2066	use `test`; BEGIN
master-bin.000001	2066	Table_map	1	2107	table_id: 25 (test.t1)
master-bin.000001	2107	Write_rows	1	2141	table_id: 25 flags: STMT_END_F
master-bin.000001	2141	Query	1	2210	use `test`; COMMIT
master-bin.000001	2210	Query	1	2278	use `test`; BEGIN
master-bin.000001	2278	Table_map	1	2319	table_id: 25 (test.t1)
master-bin.000001	2319	Write_rows	1	2353	table_id: 25 flags: STMT_END_F
master-bin.000001	2353	Query	1	2422	use `test`; COMMIT
master-bin.000001	2422	Query	1	2490	use `test`; BEGIN
master-bin.000001	2490	Table_map	1	2531	table_id: 25 (test.t1)
master-bin.000001	2531	Write_rows	1	2565	table_id: 25 flags: STMT_END_F
master-bin.000001	2565	Query	1	2634	use `test`; COMMIT
==== end SHOW BINLOG EVENTS ====

Thank you for the report.

I see only

master-bin.000001       1294    Query   1       1384    use `test`; SELECT `test`.`func_func`()
master-bin.000001       1384    Query   1       1474    use `test`; SELECT `test`.`func_proc`()
master-bin.000001       1474    Query   1       1562    use `test`; INSERT INTO t1 VALUES (5)
master-bin.000001       1562    Query   1       1647    use `test`; SELECT `test`.`func`()
master-bin.000001       1647    Query   1       1735    use `test`; INSERT INTO t1 VALUES (6)
master-bin.000001       1735    Query   1       1823    use `test`; INSERT INTO t1 VALUES (1)

in my environment. Do you use any options?

Right, I can only repeat with row-based logging. In statement mode, I can not repeat it. In mixed mode, it is repeatable if

INSERT INTO t1 VALUES (<constant number>)

is replaced by, e.g.,

INSERT INTO t1 VALUES (@@binlog_format)

since that will turn on row-based logging.

Thank you for the report.

func_func, func_proc and proc_proc verified as described. With proc_func only 1 commit in my environment.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/52275

2661 He Zhenxing	2008-08-22
      BUG#37137 Func/proc calling func/proc written incorrectly to binlog
      
      In RBL, when a function calls other functions or procedures that modifies
      the same table, Table_map event of the same table was written several
      times.
      
      This patch fixed it by check if the Table_map event of given table
      map id has been written before and skip writeing Table_map event of
      current table map id if it has been written.

When executed on the master, the "CALL proc_proc()" statement will execute each statement individually, i.e., lock tables before each statement and unlock them after. In other words, the "CALL proc_proc()" statement does not behave as a transactional entity. Hence it is correct to log each statement as a separate group in the binary log, which means that 1 is expected behavior.

1 is not a bug.  2 is harmless.

Closing bug as "won't fix".