Bug #77095 Incorrect binlog order for concurrent CREATE TRIGGER and DROP TRIGGER
Submitted: 19 May 2015 13:59 Modified: 4 Apr 2017 10:27
Reporter: Elena Stepanova Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: DDL Severity:S3 (Non-critical)
Version:5.7/5.6 OS:Any
Assigned to: CPU Architecture:Any

[19 May 2015 13:59] Elena Stepanova 
Description:
Initially reported as https://mariadb.atlassian.net/browse/MDEV-8181

The output shows wrong binlog order:

Log_name	Pos	Event_type	Server_id	End_log_pos	Info
master-bin.000001	4	Format_desc	1	123	Server ver: 5.7.7-rc-debug-log, Binlog ver: 4
master-bin.000001	123	Previous_gtids	1	154	
master-bin.000001	154	Anonymous_Gtid	1	219	SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001	219	Query	1	328	use `test`; CREATE TABLE t1 (a INT PRIMARY KEY)
master-bin.000001	328	Anonymous_Gtid	1	393	SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001	393	Query	1	502	use `test`; CREATE TABLE t2 (a INT PRIMARY KEY)
master-bin.000001	502	Anonymous_Gtid	1	567	SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001	567	Query	1	676	use `test`; CREATE TABLE t3 (a INT PRIMARY KEY)
master-bin.000001	676	Anonymous_Gtid	1	741	SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001	741	Query	1	850	use `test`; CREATE TABLE t4 (a INT PRIMARY KEY)
master-bin.000001	850	Anonymous_Gtid	1	915	SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001	915	Query	1	1112	use `test`; CREATE DEFINER=`root`@`localhost` TRIGGER trigger_1 AFTER INSERT ON t1 FOR EACH ROW UPDATE t3 SET a=a+1
master-bin.000001	1112	Anonymous_Gtid	1	1177	SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001	1177	Query	1	1374	use `test`; CREATE DEFINER=`root`@`localhost` TRIGGER trigger_1 AFTER INSERT ON t2 FOR EACH ROW UPDATE t4 SET a=a+1
master-bin.000001	1374	Anonymous_Gtid	1	1439	SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001	1439	Query	1	1535	use `test`; DROP TRIGGER trigger_1
DROP TRIGGER trigger_1;
DROP TABLE t1,t2,t3,t4;

This will make the slave fail with "trigger already exists", as the DROP
TRIGGER is logged after the second CREATE TRIGGER, while it ran before (and
needs to run before) on the master.

More code analysis in https://mariadb.atlassian.net/browse/MDEV-8181.

Most likely it is also true for previous versions of MySQL, but I didn't check.

How to repeat:
# MySQL flavor of the test case:

--source include/have_log_bin.inc
--source include/have_debug.inc

CREATE TABLE t1 (a INT PRIMARY KEY);
CREATE TABLE t2 (a INT PRIMARY KEY);
CREATE TABLE t3 (a INT PRIMARY KEY);
CREATE TABLE t4 (a INT PRIMARY KEY);

CREATE TRIGGER trigger_1 AFTER INSERT ON t1 FOR EACH ROW UPDATE t3 SET a=a+1;
connect(con1,localhost,root,,);
SET SESSION debug="+d,inject_drop_trigger_sleep_before_binlog";
send DROP TRIGGER trigger_1;
--connection default
--sleep 1
CREATE TRIGGER trigger_1 AFTER INSERT ON t2 FOR EACH ROW UPDATE t4 SET a=a+1;
--connection con1
reap;
--disconnect con1
--connection default

SHOW BINLOG EVENTS;

DROP TRIGGER trigger_1;
DROP TABLE t1,t2,t3,t4;

# End of test case

# MySQL 5.7 flavor of the patch with the debug injection:

diff --git a/sql/sql_trigger.cc b/sql/sql_trigger.cc
index 98df6e8..2cc5e4e 100644
--- a/sql/sql_trigger.cc
+++ b/sql/sql_trigger.cc
@@ -283,6 +283,10 @@ end:
   {
     if (tables)
       thd->add_to_binlog_accessed_dbs(tables->db);
+      DBUG_EXECUTE_IF("inject_drop_trigger_sleep_before_binlog", {
+        if (!create)
+          my_sleep(5000000);
+      });
     result= write_bin_log(thd, TRUE, stmt_query.ptr(), stmt_query.length());
   }
[19 May 2015 16:32] MySQL Verification Team 
c:\Temp\2015may04\mysql-5.7\mysql-test>perl mysql-test-run.pl bug77095
Logging: mysql-test-run.pl  bug77095
MySQL Version 5.7.8
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory 'c:/Temp/2015may04/mysql-5.7/mysql-test/var'...
Installing system database...

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

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

worker[1] Using MTR_BUILD_THREAD 301, with reserved ports 13010..13019
CREATE TABLE t1 (a INT PRIMARY KEY);
CREATE TABLE t2 (a INT PRIMARY KEY);
CREATE TABLE t3 (a INT PRIMARY KEY);
CREATE TABLE t4 (a INT PRIMARY KEY);
CREATE TRIGGER trigger_1 AFTER INSERT ON t1 FOR EACH ROW UPDATE t3 SET a=a+1;
SET SESSION debug="+d,inject_drop_trigger_sleep_before_binlog";
DROP TRIGGER trigger_1;
CREATE TRIGGER trigger_1 AFTER INSERT ON t2 FOR EACH ROW UPDATE t4 SET a=a+1;
SHOW BINLOG EVENTS;
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
master-bin.000001       4       Format_desc     1       123     Server ver: 5.7.8-rc-debug-log, Binlog ver: 4
master-bin.000001       123     Previous_gtids  1       154
master-bin.000001       154     Anonymous_Gtid  1       219     SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001       219     Query   1       328     use `test`; CREATE TABLE t1 (a INT PRIMARY KEY)
master-bin.000001       328     Anonymous_Gtid  1       393     SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001       393     Query   1       502     use `test`; CREATE TABLE t2 (a INT PRIMARY KEY)
master-bin.000001       502     Anonymous_Gtid  1       567     SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001       567     Query   1       676     use `test`; CREATE TABLE t3 (a INT PRIMARY KEY)
master-bin.000001       676     Anonymous_Gtid  1       741     SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001       741     Query   1       850     use `test`; CREATE TABLE t4 (a INT PRIMARY KEY)
master-bin.000001       850     Anonymous_Gtid  1       915     SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001       915     Query   1       1112    use `test`; CREATE DEFINER=`root`@`localhost` TRIGGER trigger_1 AFTER INSERT ON t1 FOR EACH ROW UPDATE t3 SET a=a+1
master-bin.000001       1112    Anonymous_Gtid  1       1177    SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001       1177    Query   1       1374    use `test`; CREATE DEFINER=`root`@`localhost` TRIGGER trigger_1 AFTER INSERT ON t2 FOR EACH ROW UPDATE t4 SET a=a+1
master-bin.000001       1374    Anonymous_Gtid  1       1439    SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001       1439    Query   1       1535    use `test`; DROP TRIGGER trigger_1
DROP TRIGGER trigger_1;
DROP TABLE t1,t2,t3,t4;
main.bug77095                            [ pass ]  28966
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 28.966 of 182 seconds executing testcases
[19 May 2015 16:39] MySQL Verification Team 
Checking leftover processes...
Removing old var directory...
Creating var directory 'c:/Temp/2015may04/mysql-5.6/mysql-test/var'...
Installing system database...

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

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

worker[1] Using MTR_BUILD_THREAD 301, with reserved ports 13010..13019
CREATE TABLE t1 (a INT PRIMARY KEY);
CREATE TABLE t2 (a INT PRIMARY KEY);
CREATE TABLE t3 (a INT PRIMARY KEY);
CREATE TABLE t4 (a INT PRIMARY KEY);
CREATE TRIGGER trigger_1 AFTER INSERT ON t1 FOR EACH ROW UPDATE t3 SET a=a+1;
SET SESSION debug="+d,inject_drop_trigger_sleep_before_binlog";
DROP TRIGGER trigger_1;
CREATE TRIGGER trigger_1 AFTER INSERT ON t2 FOR EACH ROW UPDATE t4 SET a=a+1;
SHOW BINLOG EVENTS;
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
master-bin.000001       4       Format_desc     1       120     Server ver: 5.6.26-debug-log, Binlog ver: 4
master-bin.000001       120     Query   1       229     use `test`; CREATE TABLE t1 (a INT PRIMARY KEY)
master-bin.000001       229     Query   1       338     use `test`; CREATE TABLE t2 (a INT PRIMARY KEY)
master-bin.000001       338     Query   1       447     use `test`; CREATE TABLE t3 (a INT PRIMARY KEY)
master-bin.000001       447     Query   1       556     use `test`; CREATE TABLE t4 (a INT PRIMARY KEY)
master-bin.000001       556     Query   1       749     use `test`; CREATE DEFINER=`root`@`localhost` TRIGGER trigger_1 AFTER INSERT ON t1 FOR EACH ROW UPDATE t3 SET a=a+1
master-bin.000001       749     Query   1       942     use `test`; CREATE DEFINER=`root`@`localhost` TRIGGER trigger_1 AFTER INSERT ON t2 FOR EACH ROW UPDATE t4 SET a=a+1
master-bin.000001       942     Query   1       1038    use `test`; DROP TRIGGER trigger_1
DROP TRIGGER trigger_1;
DROP TABLE t1,t2,t3,t4;
[19 May 2015 16:53] MySQL Verification Team 
Thank you for the bug report.
[19 Oct 2016 6:33] Dmitry Shulga 
Posted by developer:
 
After WL#7896 was pushed into trunk this bug is no more possible since the
worklog
added acquiring of EXCLUSIVE MDL for trigger name while handling CREATE/DROP
TRIGGER,
DROP DATABASE, DROP TABLE, ALTER TABLE, RENAME TABLE.
[4 Apr 2017 10:27] Erlend Dahl 
[31 Mar 2017 9:10] David Moss
Thank you for your feedback, this has been fixed in upcoming versions and the
following was added to the 8.0.1 changelog:
Concurrent CREATE TRIGGER and DROP TRIGGER statements were not being binary
logged in the correct order, causing slaves to fail.