MySQL Bugs: #47067: DELETE logged as statement even though binlog

Bug #47067	DELETE logged as statement even though binlog_format=ROW
Submitted:	2 Sep 2009 15:06	Modified:	28 Jul 2011 9:15
Reporter:	Matthias Leich	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S3 (Non-critical)
Version:	5.1, next bzr	OS:	Any
Assigned to:	Mats Kindahl	CPU Architecture:	Any

Description:
Please excuse if this is no error. I found this
effect when running RQG tests with replication.
Maybe that I simply used the wrong options or
some similar "user error".

My script:
----------
--source include/master-slave.inc

--disable_warnings
DROP TABLE IF EXISTS t1;
DROP TABLE IF EXISTS t2;
DROP FUNCTION IF EXISTS func_1;
--enable_warnings

let $initial_binlog_format = @@global.binlog_format;
SET GLOBAL BINLOG_FORMAT = 'row';
CREATE TABLE t1 ( f1 INTEGER); INSERT IGNORE INTO t1 VALUES (1);
CREATE TEMPORARY TABLE t2 AS SELECT f1 FROM t1;
delimiter |; CREATE FUNCTION func_1  () RETURNS INTEGER BEGIN RETURN 1 ; END| delimiter ;|
SET AUTOCOMMIT=OFF;
START TRANSACTION;
# This is the critical statement.
DELETE A,B FROM t1 AS A NATURAL JOIN t2 B;

# Here I get:
# sync_slave_with_master failed: 'select master_pos_wait('master-bin.000001', 933, 300)'
#                                 returned NULL indicating slave SQL thread failure
# which points to
# master-bin.000001 829 Query 1 933 use `test`; DELETE A,B FROM t1 AS A NATURAL JOIN t2 B
# SHOW SLAVE STATUS contains
# .....
# Last_SQL_Errno  1146
# Last_SQL_Error  Error 'Table 'test.t2' doesn't exist' on query.#
#      Default database: 'test'. Query: 'DELETE A,B FROM t1 AS A NATURAL JOIN t2 B'
#
--sync_slave_with_master

My command line:
----------------
./mysql-test-run --mem --mysqld=--binlog-format=row \
  --no-check-testcases rpl_ml1101

Some strange observations:
--------------------------
The effect disappears if I
- remove the CREATE FUNCTION      or
- make t2 a non temporary table

My environment:
---------------
- mysql-next-bugfixing 2009-09-02
- BUILD/compile-pentium64-debug-max
- Linux OpenSuSE 11.0 (64 Bit)

How to repeat:
See above

Thank you for the report.

Bug is not repeatable with latest 5.1 and next trees although I could repeat it with update from September, 1. So I close this as "Can't repeat". Please check if mysql-next-bugfixing has this changes and if yes reopen the report.

Not repeatable for me with today update of mysql-next-bugfixing as well

mysql-next-bugfixing revno: 2809
committer: Roy Lyseng <roy.lyseng@sun.com>
branch nick: mysql-reeng
timestamp: Thu 2009-09-03 11:09:27 +0200
./BUILD/compile-pentium64-debug-max
----------------------------------------

/mysql-test-run --mem --mysqld=--binlog-format=row \
   --no-check-testcases <testcase>

CURRENT_TEST: main.bug47067
=== SHOW MASTER STATUS ===
---- 1. ----
File    slave-bin.000001
Position        829
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     933
Relay_Log_File  slave-relay-bin.000003
Relay_Log_Pos   976
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      1146
Last_Error      Error 'Table 'test.t2' doesn't exist' on query. Default database: 'test'. Query: 'DELETE A,B FROM t1 AS A NATURAL JOIN t2 B'
Skip_Counter    0
Exec_Master_Log_Pos     829
Relay_Log_Space 1236
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  1146
Last_SQL_Error  Error 'Table 'test.t2' doesn't exist' on query. Default database: 'test'. Query: 'DELETE A,B FROM t1 AS A NATURAL JOIN t2 B'
Replicate_Ignore_Server_Ids
Master_Server_Id        1
=========================
SHOW BINLOG EVENTS IN 'master-bin.000001';
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
master-bin.000001       4       Format_desc     1       107     Server ver: 5.4.4-alpha-debug-log, Binlog ver: 4
master-bin.000001       107     Query   1       193     use `test`; DROP TABLE IF EXISTS t1
master-bin.000001       193     Query   1       279     use `test`; DROP TABLE IF EXISTS t2
master-bin.000001       279     Query   1       372     use `test`; DROP FUNCTION IF EXISTS func_1
master-bin.000001       372     Query   1       464     use `test`; CREATE TABLE t1 ( f1 INTEGER)
master-bin.000001       464     Query   1       532     BEGIN
master-bin.000001       532     Table_map       1       573     table_id: 17 (test.t1)
master-bin.000001       573     Write_rows      1       607     table_id: 17 flags: STMT_END_F
master-bin.000001       607     Query   1       676     COMMIT
master-bin.000001       676     Query   1       829     use `test`; CREATE DEFINER=`root`@`localhost` FUNCTION `func_1`() RETURNS int(11)
BEGIN RETURN 1
; END
master-bin.000001       829     Query   1       933     use `test`; DELETE A,B FROM t1 AS A NATURAL JOIN t2 B
master-bin.000001       933     Query   1       1050    use `test`; DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `test`.`t2`

== /work2/6.0/mysql-next-bugfixing/mysql-test/var/tmp/analyze-sync_with_master-mysqld.2.err ==
SHOW PROCESSLIST;
Id      User    Host    db      Command Time    State   Info
3       system user             NULL    Connect 0       Waiting for master to send event        NULL
5       root    localhost       NULL    Query   0       NULL    SHOW PROCESSLIST
SHOW BINLOG EVENTS IN 'slave-bin.000001';
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
slave-bin.000001        4       Format_desc     2       107     Server ver: 5.4.4-alpha-debug-log, Binlog ver: 4
slave-bin.000001        107     Query   1       193     use `test`; DROP TABLE IF EXISTS t1
slave-bin.000001        193     Query   1       279     use `test`; DROP TABLE IF EXISTS t2
slave-bin.000001        279     Query   1       372     use `test`; DROP FUNCTION IF EXISTS func_1
slave-bin.000001        372     Query   1       464     use `test`; CREATE TABLE t1 ( f1 INTEGER)
slave-bin.000001        464     Query   1       532     BEGIN
slave-bin.000001        532     Table_map       1       573     table_id: 17 (test.t1)
slave-bin.000001        573     Write_rows      1       607     table_id: 17 flags: STMT_END_F
slave-bin.000001        607     Query   1       676     COMMIT
slave-bin.000001        676     Query   1       829     use `test`; CREATE DEFINER=`root`@`localhost` FUNCTION `func_1`() RETURNS int(11)
BEGIN RETURN 1
; END

var/log/main.bug47067/mysqld.2/data/mysql/general_log.CSV:
   I assume this log is from the slave
----------------------------------------------------------
[127.0.0.1]",1,2,"Connect","root@localhost on test"
[127.0.0.1]",2,2,"Connect","root@localhost on test"
[127.0.0.1]",1,2,"Query","stop slave"
[127.0.0.1]",1,2,"Query","CHANGE MASTER TO MASTER_USER='root',\nMASTER_CONNECT_RETRY=1,\nMASTER_HOST='127.0.0.1',\nMASTER_PORT=13000"
[127.0.0.1]",1,2,"Query","SHOW SLAVE STATUS"
[127.0.0.1]",1,2,"Query","SELECT 'No' != 'No such row'"
[127.0.0.1]",1,2,"Query","SELECT '' = ''"
[127.0.0.1]",1,2,"Query","SHOW SLAVE STATUS"
[127.0.0.1]",1,2,"Query","SELECT NOT('No' = 'No') AND 3000 > 0"
[127.0.0.1]",1,2,"Query","SELECT '' = ''"
[127.0.0.1]",1,2,"Query","SHOW SLAVE STATUS"
[127.0.0.1]",1,2,"Query","SELECT NOT('No' = 'No') AND 3000 > 0"
[127.0.0.1]",1,2,"Query","reset slave"
[127.0.0.1]",1,2,"Query","drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9"
[127.0.0.1]",1,2,"Query","reset master"
[127.0.0.1]",1,2,"Query","start slave"
"2009-09-03 19:38:10","[] @  []",3,2,"Connect Out","root@127.0.0.1:13000"
[127.0.0.1]",1,2,"Query","SELECT '' = ''"
[127.0.0.1]",1,2,"Query","SHOW SLAVE STATUS"
[127.0.0.1]",1,2,"Query","SELECT NOT('Yes' = 'Yes') AND 3000 > 0"
[127.0.0.1]",1,2,"Query","SELECT '' = ''"
[127.0.0.1]",1,2,"Query","SHOW SLAVE STATUS"
[127.0.0.1]",1,2,"Query","SELECT NOT('Yes' = 'Yes') AND 3000 > 0"
[127.0.0.1]",1,2,"Query","select master_pos_wait('master-bin.000001', 107, 300)"
","[] @  []",4,2,"Query","DROP TABLE IF EXISTS t1"
","[] @  []",4,2,"Query","DROP TABLE IF EXISTS t2"
","[] @  []",4,2,"Query","DROP FUNCTION IF EXISTS func_1"
","[] @  []",4,2,"Query","CREATE TABLE t1 ( f1 INTEGER)"
","[] @  []",4,2,"Query","BEGIN"
","[] @  []",4,2,"Query","COMMIT"
","[] @  []",4,2,"Query","CREATE DEFINER=`root`@`localhost` FUNCTION `func_1`() RETURNS int(11)\nBEGIN RETURN 1\n; END"
" ,"[] @  []",4,2,"Query","DELETE A,B FROM t1 AS A NATURAL JOIN t2 B"
[127.0.0.1]",1,2,"Query","select master_pos_wait('master-bin.000001', 933, 300)"
[127.0.0.1]",1,2,"Query","SHOW MASTER STATUS"
[127.0.0.1]",1,2,"Query","SHOW SLAVE STATUS"
[127.0.0.1]",1,2,"Query","SHOW PROCESSLIST"
[127.0.0.1]",1,2,"Query","SHOW WARNINGS"
[127.0.0.1]",1,2,"Quit",""
[127.0.0.1]",2,2,"Quit",""
[]",5,2,"Connect","root@localhost on "
[]",5,2,"Query","SHOW PROCESSLIST"
[]",5,2,"Query","SHOW MASTER STATUS"
[]",5,2,"Query","SHOW BINLOG EVENTS IN 'slave-bin.000001'"
[]",5,2,"Quit",""

1. This is a run with RBR.
   So why do I see here
   "DELETE A,B FROM t1 AS A NATURAL JOIN t2 B"   ?
2. Even if 1. is intended.
   The permanent table t1 was created.
   But where is the creation of t2?
   general_log.CSV of the master shows a:
   "CREATE TEMPORARY TABLE t2 AS SELECT f1 FROM t1"
   just before the CREATE FUNCTION.

Sorry: forgot options.

Verified as described with option --mysqld=--binlog-format=row