MySQL Bugs: #71859: Replication broken after creation of scheduled events

Bug #71859	Replication broken after creation of scheduled events
Submitted:	27 Feb 2014 9:49	Modified:	4 Dec 2015 17:23
Reporter:	shahid hussain	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	Mysql 5.6.16, 5.6.21, 5.7.5	OS:	Linux (RHEL6)
Assigned to:		CPU Architecture:	Any

Description:
Hi,
Below Event has been successfully replicated in Row based Replication and Statement based replication but master-slave connection got broken when i execute same event in  MIXED replication.
[
DELIMITER $$
DROP EVENT IF EXISTS `MIS_CUMULATIVE_REV_EVENT`
$$

CREATE EVENT IF NOT EXISTS `MIS_CUMULATIVE_REV_EVENT`
ON SCHEDULE EVERY 30 MINUTE STARTS sysdate()
ON COMPLETION PRESERVE
DO BEGIN
DECLARE EXIT HANDLER FOR SQLEXCEPTION
SELECT CONCAT('SQL EXCEPTION - TERMINATING EVENT FOR STORED PROCEDURE CALL');

END
$$
]
The reason is when we create any scheduled event,it inserts mysql.event table with information about created event which can be seen invoking 'SHOW EVENT' query.
My issue is ,
1. when i use ROW  based replication(RBR) ,(since it replicates transactions to slave  only if it is affecting any table) i created a scheduled event,which inserted event information into mysql.event table,then i observed following (which is fine for me).
 a. it has not replicated insert event to slave 
 b. it has replicated scheduled event creation procedure to slave
 c. Slave executed scheduled event.

2. When i use Statement based replication,here it just replicates event procedure to slave.

3. But when i used MIXED replication since above scheduled event having sysdate() which is nondeterministic function ,so master converts it into RBR but it is replication the insert statement of "mysql.event" also to slave and i m getting below error at slave
[ Last_SQL_Error: Error 'Cannot execute statements with implicit commit inside a transaction when @@SESSION.GTID_NEXT != AUTOMATIC.' on query. Default database: 'gtid_test']

This issue can be resolved by setting sysdate-is-now configuration, but since above insert statement is not being replicated in RBR but it is being replicated when replication format is MIXED.

How to repeat:
Run below procedure by configuring binlog-format as RBR,SBR and MIXED. Replication will get broken during mixed replication.
DELIMITER $$
DROP EVENT IF EXISTS `MIS_CUMULATIVE_REV_EVENT`
$$

CREATE EVENT IF NOT EXISTS `MIS_CUMULATIVE_REV_EVENT`
ON SCHEDULE EVERY 30 MINUTE STARTS sysdate()
ON COMPLETION PRESERVE
DO BEGIN
DECLARE EXIT HANDLER FOR SQLEXCEPTION
SELECT CONCAT('SQL EXCEPTION - TERMINATING EVENT FOR STORED PROCEDURE CALL');

END
$$

Him This issue cant even be solved by configuring sysdate-is-now=1
 in my.cnf file.. Please let me know how to execute mentioned event with sysdate in MIXED replication.

Thank you for the report.

Verified as described. Debug server crashes with "mysqld: /home/sveta/src/mysql-5.6/sql/sql_base.cc:1355: void close_thread_tables(THD*): Assertion `thd->transaction.stmt.is_empty() || thd->in_sub_stmt || (thd->state_flags & Open_tables_state::BACKUPS_AVAIL)' failed."

Backtrace:

before_slave_tt_close released, name: /home/sveta/src/mysql-5.6/mysql-test/var/tmp/mysqld.1/#sql_4545_0
mysqld: /home/sveta/src/mysql-5.6/sql/sql_base.cc:1355: void close_thread_tables(THD*): Assertion `thd->transaction.stmt.is_empty() || thd->in_sub_stmt || (thd->state_flags & Open_tables_state::BACKUPS_AVAIL)' failed.
17:29:19 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=6
max_threads=151
thread_count=6
connection_count=6
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61111 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x361ce20
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f05376aade0 thread_stack 0x40000
/home/sveta/src/mysql-5.6/sql/mysqld(my_print_stacktrace+0x35)[0xac4314]
/home/sveta/src/mysql-5.6/sql/mysqld(handle_fatal_signal+0x3f3)[0x735143]
/lib64/libpthread.so.0[0x38f3e0f710]
/lib64/libc.so.6(gsignal+0x35)[0x38f3232925]
/lib64/libc.so.6(abort+0x175)[0x38f3234105]
/lib64/libc.so.6[0x38f322ba4e]
/lib64/libc.so.6(__assert_perror_fail+0x0)[0x38f322bb10]
/home/sveta/src/mysql-5.6/sql/mysqld(_Z19close_thread_tablesP3THD+0xba)[0x774217]
/home/sveta/src/mysql-5.6/sql/mysqld(_ZN19Event_db_repository12create_eventEP3THDP16Event_parse_databPb+0x514)[0x9fb622]
/home/sveta/src/mysql-5.6/sql/mysqld(_ZN6Events12create_eventEP3THDP16Event_parse_datab+0x224)[0x8d7720]
/home/sveta/src/mysql-5.6/sql/mysqld(_Z21mysql_execute_commandP3THD+0x4491)[0x7e9831]
/home/sveta/src/mysql-5.6/sql/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x421)[0x7ef902]
/home/sveta/src/mysql-5.6/sql/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xc1e)[0x7e3098]
/home/sveta/src/mysql-5.6/sql/mysqld(_Z10do_commandP3THD+0x33e)[0x7e2227]
/home/sveta/src/mysql-5.6/sql/mysqld(_Z24do_handle_one_connectionP3THD+0x1b6)[0x7a84e1]
/home/sveta/src/mysql-5.6/sql/mysqld(handle_one_connection+0x33)[0x7a7ff7]
/home/sveta/src/mysql-5.6/sql/mysqld(pfs_spawn_thread+0x159)[0xdf3af0]
/lib64/libpthread.so.0[0x38f3e079d1]
/lib64/libc.so.6(clone+0x6d)[0x38f32e8b6d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f04f4004c90): CREATE EVENT IF NOT EXISTS `MIS_CUMULATIVE_REV_EVENT` ON SCHEDULE EVERY 30 MINUTE STARTS sysdate() ON COMPLETION PRESERVE DO BEGIN DECLARE EXIT HANDLER FOR SQLEXCEPTION SELECT CONCAT('SQL EXCEPTION - TERMINATING EVENT FOR STORED PROCEDURE CALL'); END
Connection ID (thread ID): 6

test case for MTR

Attachment: rpl_bug71859.test (application/octet-stream, text), 460 bytes.

option file for master

Attachment: rpl_bug71859-master.opt (application/octet-stream, text), 99 bytes.

option file for slave

Attachment: rpl_bug71859-slave.opt (application/octet-stream, text), 98 bytes.

This fix has been reverted because it was found to cause other issues. Therefore the changelog entry is removed and the status is changed so that we continue to track it.

Thanks for your feedback. This has been fixed in upcoming versions and the following was noted in the 5.6.29 and 5.7.11 change logs:

Irrespective of the current binlog_format setting, DDL that changes metadata on a master is always identified as unsafe and written to the binary log in STATEMENT format. Such DDL could occur from event based SQL statements, such as CREATE EVENT or DROP EVENT, or transactions that had unsafe functions such as sysdate(). When binlog_format=MIXED and attempting to replicate such DDL, it was not being correctly identified as unsafe and therefore was not being correctly replicated.