MySQL Bugs: #96414: CREATE TABLE events in wrong order in a binary log.

Bug #96414	CREATE TABLE events in wrong order in a binary log.
Submitted:	2 Aug 2019 13:17	Modified:	7 Aug 2019 13:24
Reporter:	Iwo P	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.7, 5.7.27	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
When an application is concurrently creating tables, the tables can be logged into a binary log in a wrong order. This causes replication to break if foreign keys are used.

How to repeat:
1. 
Add extra DBUG_EXECUTE_IF condition into function:
bool mysql_create_table(THD *thd, TABLE_LIST *create_table,
                        HA_CREATE_INFO *create_info,
                        Alter_info *alter_info)

    ...
    if (create_info->options & HA_LEX_CREATE_TMP_TABLE)
      thd->get_transaction()->mark_created_temp_table(Transaction_ctx::STMT);

    if (!thd->is_current_stmt_binlog_format_row() ||
        (thd->is_current_stmt_binlog_format_row() &&
         !(create_info->options & HA_LEX_CREATE_TMP_TABLE)))
    {
      thd->add_to_binlog_accessed_dbs(create_table->db);

         **
         DBUG_EXECUTE_IF("inject_create_table_sleep_before_binlog", {
         my_sleep(5000000);
 });
         **
      result= write_bin_log(thd, true,
                            thd->query().str, thd->query().length, is_trans);
    }
  }
  ...

2. Start two sessions.

first> SET SESSION debug='d,inject_create_table_sleep_before_binlog';
first> CREATE TABLE testa(
    ->    cat_id int not null auto_increment primary key,
    ->    cat_name varchar(255) not null,
    ->    cat_description text
    -> ) ENGINE=InnoDB;
second> CREATE TABLE testb (prd_id int not null auto_increment primary key, prd_name varchar(355) not null, prd_price decimal, cat_id int not null, FOREIGN KEY fk_cat(cat_id) REFERENCES testa(cat_id) ON UPDATE CASCADE ON DELETE RESTRICT);

3. MySQL will write events in the following order to the binary log:

# at 1439
#190802 15:05:28 server id 1  end_log_pos 1741 CRC32 0x796b725f 	Query	thread_id=6	exec_time=0	error_code=0
SET TIMESTAMP=1564751128/*!*/;
CREATE TABLE testb (prd_id int not null auto_increment primary key, prd_name varchar(355) not null, prd_price decimal, cat_id int not null, FOREIGN KEY fk_cat(cat_id) REFERENCES testa(cat_id) ON UPDATE CASCADE ON DELETE RESTRICT)
/*!*/;
# at 1741
# at 1806
#190802 15:05:27 server id 1  end_log_pos 2025 CRC32 0xb1415a89 	Query	thread_id=7	exec_time=5	error_code=0
SET TIMESTAMP=1564751127/*!*/;
CREATE TABLE testa(
   cat_id int not null auto_increment primary key,
   cat_name varchar(255) not null,
   cat_description text
) ENGINE=InnoDB
/*!*/;
DELIMITER ;
# End of log file

Suggested fix:
Child table DDL statement should be written to a binary log after parent table.

Hello Iwo P,

Thank you for the report and test case.
Verified as described with patched 5.7.27 source build.

regards,
Umesh

Test results - 5.7.27

Attachment: 96414_5.7.27.results (application/octet-stream, text), 248.94 KiB.

- Haven't checked other GAs, shall do it tomorrow or later on

Posted by developer:
 
Note that the problem is not repeatable in modern 8.0 versions (I've used 8.0.18-git) to verify.
This is thanks to WL#6049 "Meta-data locking for FOREIGN KEY tables" which was introduced in
release 8.0.3. The second CREATE TABLE statement now acquires metadata lock on parent table
in FK so has to wait until the first CREATE TABLE completes (since the latter holds conflicting
MDL on it).

I think it is a general problem of non atomic DDLs, and a duplicate of https://bugs.mysql.com/bug.php?id=58787 ?