MySQL Bugs: #65428: Wrong binlog order on concurrent DROP schema and CREATE function

Bug #65428	Wrong binlog order on concurrent DROP schema and CREATE function
Submitted:	26 May 2012 14:41	Modified:	31 Jul 2012 2:14
Reporter:	Elena Stepanova	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.5, 5.6	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Concurrent execution of DROP DATABASE and CREATE FUNCTION | PROCEDURE | EVENT causes a wrong order of events in the binary log and, consequently, replication failure.

Provided MTR test case is non-deterministic, so I am also adding an RQG grammar to reproduce.
The problem is that on master CREATE FUNCTION gets executed without an error, but in the binlog DROP DATABASE is written before CREATE FUNCTION:

Log_name	Pos	Event_type	Server_id	End_log_pos	Info
master-bin.000001	4	Format_desc	1	107	Server ver: 5.5.25-debug-log, Binlog ver: 4
master-bin.000001	107	Query	1	196	DROP DATABASE IF EXISTS db1
master-bin.000001	196	Query	1	277	CREATE DATABASE db1
master-bin.000001	277	Query	1	436	use `test`; CREATE DEFINER=`root`@`localhost` FUNCTION `db1`.`f1`() RETURNS int(11)
RETURN 1
master-bin.000001	436	Query	1	515	DROP DATABASE db1
master-bin.000001	515	Query	1	674	use `test`; CREATE DEFINER=`root`@`localhost` FUNCTION `db1`.`f2`() RETURNS int(11)
RETURN 1

How to repeat:
# MTR test case t1.test
# run as perl ./mtr --mysqld=--binlog-format=mixed t1

--source include/master-slave.inc

DROP DATABASE IF EXISTS db1;

CREATE DATABASE db1;
CREATE FUNCTION db1.f1() RETURNS INT RETURN 1;
--send
DROP DATABASE db1;

--connection master1
--error 0,ER_BAD_DB_ERROR
CREATE FUNCTION db1.f2() RETURNS INT RETURN 1;

--connection master
--reap
SHOW BINLOG EVENTS;

--sync_slave_with_master

# End of MTR test case

# RQG grammar t1.yy

query:
     CREATE DATABASE IF NOT EXISTS db1; CREATE FUNCTION db1.f1() RETURNS INT RETURN 1; DROP DATABASE db1;

thread1:
     CREATE FUNCTION db1.f2() RETURNS INT RETURN 1; DROP FUNCTION db1.f2;

# End of RQG grammar

# RQG command line:

perl runall.pl \
--queries=100M \
--threads=2 \
--duration=600 \
--grammar=t1.yy \
--rpl_mode=mixed \
--basedir1=<your basedir> \
--vardir1=<your vardir>

Thank you for the bug report. Verified with 5.5.26 using your test case for mtr:

macbook-pro:mysql-test openxs$ ./mtr --mysqld=--binlog-format=mixed bug65428
Logging: ./mtr  --mysqld=--binlog-format=mixed bug65428
120526 19:14:53 [Warning] Setting lower_case_table_names=2 because file system for /var/folders/dX/dXCzvuSlHX4Op1g-o1jIWk+++TI/-Tmp-/z4SmxNOWKk/ is case insensitive
120526 19:14:53 [Note] Plugin 'FEDERATED' is disabled.
MySQL Version 5.5.26
Using binlog format 'mixed'
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 49754

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

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

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.bug65428                            [ fail ]
        Test ended at 2012-05-26 19:15:09

CURRENT_TEST: main.bug65428
=== SHOW MASTER STATUS ===
---- 1. ----
File	slave-bin.000001
Position	499
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	674
Relay_Log_File	slave-relay-bin.000002
Relay_Log_Pos	662
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	1049
Last_Error	Error 'Unknown database 'db1'' on query. Default database: 'test'. Query: 'CREATE DEFINER=`root`@`localhost` FUNCTION `db1`.`f2`() RETURNS int(11)
RETURN 1'
Skip_Counter	0
Exec_Master_Log_Pos	515
Relay_Log_Space	977
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	1049
Last_SQL_Error	Error 'Unknown database 'db1'' on query. Default database: 'test'. Query: 'CREATE DEFINER=`root`@`localhost` FUNCTION `db1`.`f2`() RETURNS int(11)
RETURN 1'
Replicate_Ignore_Server_Ids	
Master_Server_Id	1
=========================

=== SHOW PROCESSLIST ===
---- 1. ----
Id	2
User	root
Host	localhost:49766
db	test
Command	Sleep
Time	0
State	
Info	
---- 2. ----
Id	3
User	root
Host	localhost:49767
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:49773
db	test
Command	Query
Time	0
State	
Info	SHOW PROCESSLIST
---- 5. ----
Id	7
User	root
Host	localhost:49774
db	test
Command	Sleep
Time	0
State	
Info	
========================

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

The result from queries just before the failure was:
< snip >
Warnings:
Note	1008	Can't drop database 'db1'; database doesn't exist
CREATE DATABASE db1;
CREATE FUNCTION db1.f1() RETURNS INT RETURN 1;
DROP DATABASE db1;
CREATE FUNCTION db1.f2() RETURNS INT RETURN 1;
SHOW BINLOG EVENTS;
Log_name	Pos	Event_type	Server_id	End_log_pos	Info
master-bin.000001	4	Format_desc	1	107	Server ver: 5.5.26-debug-log, Binlog ver: 4
master-bin.000001	107	Query	1	196	DROP DATABASE IF EXISTS db1
master-bin.000001	196	Query	1	277	CREATE DATABASE db1
master-bin.000001	277	Query	1	436	use `test`; CREATE DEFINER=`root`@`localhost` FUNCTION `db1`.`f1`() RETURNS int(11)
RETURN 1
master-bin.000001	436	Query	1	515	DROP DATABASE db1
master-bin.000001	515	Query	1	674	use `test`; CREATE DEFINER=`root`@`localhost` FUNCTION `db1`.`f2`() RETURNS int(11)
RETURN 1

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

Noted in 5.7.0 changelog.

Concurrent execution of DROP DATABASE and any of CREATE FUNCTION,
CREATE PROCEDURE, or CREATE EVENT could be written to the binary log
in the wrong order, causing replication failure.