Bug #89129 create table+DML on innodb_ddl_log table=crash in lock0lock.cc:7414:release_lock
Submitted: 8 Jan 2018 4:08 Modified: 1 Mar 2018 17:54
Reporter: Ramana Yeruva Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:8.0.4 OS:Any
Assigned to: CPU Architecture:Any

[8 Jan 2018 4:08] Ramana Yeruva
Description:
Currently DML(SELECT,UPDATE) operations are allowed on mysql.innodb_ddl_log system table. Not sure, why those operations are allowed which is meant for system to be used.It would be better to restrict any operations on that table by user other than by system. For truncate and Alter i get below errors but for DELETE,SELECT, no errors:

mysql> alter table mysql.innodb_ddl_log add column x int;
ERROR 1148 (42000): The used command is not allowed with this MySQL version
mysql> truncate table mysql.innodb_ddl_log add column x int;
ERROR 3554 (HY000): Access to system table 'mysql.innodb_ddl_log' is rejected.
mysql> delete from mysql.innodb_ddl_log;
Query OK, 0 rows affected (0.00 sec)

mysql> select *from mysql.innodb_ddl_log;
Empty set (0.00 sec)

Because, DELETE allowed, so i tried to create table in loop and performing SELECT and DELETE from this table in loop, this caused crash in innodb with error:[ERROR] [MY-000000] InnoDB: Assertion failure: lock0lock.cc:7414:release_lock

How to repeat:
./mysqld -uroot --basedir=../ --datadir=./data --gdb --log-error=$PWD/mysql.err --gdb --initialize-insecure --log_error_verbosity=3

./mysqld --no-defaults -uroot --basedir=../ --datadir=./data --gdb --log-error=$PWD/mysql.err --gdb --log_error_verbosity=3 &

run below shell script with "source create_database_table.sh"
cat create_database_table.sh
for i in {1..100}
do
    echo "output: $i"
    ./mysql -uroot -e "create database test$i;use test$i;source
create_1000cols_20ktables.sql;"
done

-->above script creates 100 databases and 200 tables in each database.
-->create_1000cols_20ktables.sql attached in the bug report

cat se.tcl 
package require Expect
spawn ./mysql -uroot --socket=/tmp/mysql.sock -hlocalhost
expect "mysql> "
for {set x 1} {$x<=200000} {set x [expr {$x + 1}]} {
send "select * from mysql.innodb_ddl_log;\r"
expect "mysql> "
send "delete from mysql.innodb_ddl_log;\r"
expect "mysql> "
send "truncate mysql.innodb_ddl_log;\r"
expect "mysql> "
}

Wait for some time and see the crash:

2018-01-08T03:18:28.606551Z 4 [Note] [MY-010051] Event Scheduler: scheduler thread started with id 4
2018-01-08T03:18:28.606587Z 0 [System] [MY-010931] /export/home2/tmp/Ramana/8.0.4/mysql-commercial/bin/mysqld: ready for connections. Version: '8.0.4-rc-enterprise-commercial-advanced-log'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Enterprise Server - Advanced Edition (Commercial).
2018-01-08T03:25:22.956739Z 15 [Note] [MY-010914] Aborted connection 15 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets).
2018-01-08T03:35:43.713006Z 31 [ERROR] [MY-000000] InnoDB: Assertion failure: lock0lock.cc:7414:release_lock
InnoDB: thread 139774949627648
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
^C
[1]+  Aborted                 (core dumped) ./mysqld --no-defaults -uroot --basedir=../ --datadir=./data --gdb --log-error=$PWD/mysql.err --gdb --log_error_verbosity=3

Core was generated by `./mysqld --no-defaults -uroot --basedir=../ --datadir=./data --gdb --log-error='.
Program terminated with signal 6, Aborted.
#0  0x00007f1ff336a1f7 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install glibc-2.17-196.el7.x86_64 libaio-0.3.109-12.el7.x86_64 libgcc-4.8.2-16.2.el7_0.x86_64 libstdc++-4.8.2-16.2.el7_0.x86_64 nss-softokn-freebl-3.16.2.3-1.el7_0.x86_64 numactl-libs-2.0.9-2.el7.x86_64
(gdb) bt
#0  0x00007f1ff336a1f7 in raise () from /lib64/libc.so.6
#1  0x00007f1ff336b8e8 in abort () from /lib64/libc.so.6
#2  0x0000000000a8a724 in ut_dbg_assertion_failed (expr=expr@entry=0x24a8b1c "release_lock", 
    file=file@entry=0x2472b18 "../../../mysqlcom-pro-8.0.4-rc/storage/innobase/lock/lock0lock.cc", line=line@entry=7414)
    at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/ut/ut0dbg.cc:83
#3  0x0000000001a3e06e in lock_trx_release_locks (trx=trx@entry=0x7f1fe6824228) at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/lock/lock0lock.cc:7414
#4  0x0000000001b629c3 in trx_commit_in_memory (serialised=false, mtr=0x7f1fe437f4a0, trx=0x7f1fe6824228) at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/trx/trx0trx.cc:1989
#5  trx_commit_low (trx=trx@entry=0x7f1fe6824228, mtr=0x7f1fe437f4a0) at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/trx/trx0trx.cc:2211
#6  0x0000000001b6305d in trx_commit (trx=trx@entry=0x7f1fe6824228) at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/trx/trx0trx.cc:2238
#7  0x0000000001b64327 in trx_commit_for_mysql (trx=trx@entry=0x7f1fe6824228) at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/trx/trx0trx.cc:2458
#8  0x0000000001a661c6 in Log_DDL::insert_delete_space_log (this=this@entry=0x7f1fe0787de8, trx=<optimized out>, trx@entry=0x0, id=id@entry=14147, thread_id=<optimized out>, 
    space_id=space_id@entry=4362, file_path=file_path@entry=0x7f1f78730458 "./test22/xx_161.ibd", dict_locked=<optimized out>)
    at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/log/log0ddl.cc:1128
#9  0x0000000001a688c0 in Log_DDL::write_delete_space_log (this=0x7f1fe0787de8, trx=trx@entry=0x7f1fe6823760, table=table@entry=0x7f1f789d39b8, space_id=4362, 
    file_path=file_path@entry=0x7f1f78730458 "./test22/xx_161.ibd", is_drop=is_drop@entry=false, dict_locked=true)
    at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/log/log0ddl.cc:1068
#10 0x0000000001c0a133 in dict_build_tablespace_for_table (table=table@entry=0x7f1f789d39b8, trx=trx@entry=0x7f1fe6823760)
    at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/dict/dict0crea.cc:264
#11 0x0000000001c0a5c8 in dict_build_table_def (table=table@entry=0x7f1f789d39b8, trx=trx@entry=0x7f1fe6823760)
    at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/dict/dict0crea.cc:94
#12 0x0000000001ad4587 in row_create_table_for_mysql (table=table@entry=0x7f1f789d39b8, compression=compression@entry=0x0, trx=0x7f1fe6823760)
    at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/row/row0mysql.cc:2981
#13 0x00000000019c8bb3 in create_table_info_t::create_table_def (this=this@entry=0x7f1fe4380d00, dd_table=dd_table@entry=0x7f1f785e65f0)
    at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/handler/ha_innodb.cc:11384
#14 0x00000000019dd34c in create_table_info_t::create_table (this=this@entry=0x7f1fe4380d00, dd_table=dd_table@entry=0x7f1f785e65f0)
    at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/handler/ha_innodb.cc:13335
#15 0x00000000019ddcf5 in innobase_basic_ddl::create_impl<dd::Table> (thd=0x7f1f78a9a2f0, name=name@entry=0x7f1fe4384300 "./test22/xx_161", form=form@entry=0x7f1fe4381870, 
    create_info=create_info@entry=0x7f1fe4386550, dd_tab=dd_tab@entry=0x7f1f785e65f0, file_per_table=file_per_table@entry=true, evictable=true, skip_strict=false, old_flags=0, 
    old_flags2=0) at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/handler/ha_innodb.cc:13787
#16 0x00000000019de023 in ha_innobase::create (this=0x7f1f787ea0c0, name=0x7f1fe4384300 "./test22/xx_161", form=0x7f1fe4381870, create_info=0x7f1fe4386550, 
    table_def=0x7f1f785e65f0) at ../../../mysqlcom-pro-8.0.4-rc/storage/innobase/handler/ha_innodb.cc:14523
#17 0x0000000000f13a80 in ha_create_table (thd=thd@entry=0x7f1f78a9a2f0, path=path@entry=0x7f1fe4384300 "./test22/xx_161", db=db@entry=0x7f1f795f9358 "test22", 
    table_name=table_name@entry=0x7f1f780877d0 "xx_161", create_info=create_info@entry=0x7f1fe4386550, update_create_info=update_create_info@entry=false, is_temp_table=false, 
    table_def=0x7f1f785e65f0) at ../../mysqlcom-pro-8.0.4-rc/sql/handler.cc:5413
#18 0x0000000000a81846 in rea_create_base_table (thd=thd@entry=0x7f1f78a9a2f0, path=path@entry=0x7f1fe4384300 "./test22/xx_161", sch_obj=..., 
    db=db@entry=0x7f1f795f9358 "test22", table_name=table_name@entry=0x7f1f780877d0 "xx_161", create_info=create_info@entry=0x7f1fe4386550, create_fields=..., keys=0, 
    key_info=0x7f1f79596950, keys_onoff=Alter_info::ENABLE, fk_keys=0, fk_key_info=0x7f1f79596950, file=0x7f1f795952c8, no_ha_table=false, part_info=0x0, 
    binlog_to_trx_cache=0x7f1fe43854c9, post_ddl_ht=0x7f1fe4385528) at ../../mysqlcom-pro-8.0.4-rc/sql/sql_table.cc:1050
#19 0x0000000000be0e01 in create_table_impl (thd=thd@entry=0x7f1f78a9a2f0, schema=..., db=db@entry=0x7f1f795f9358 "test22", table_name=table_name@entry=0x7f1f780877d0 "xx_161", 
    error_table_name=error_table_name@entry=0x7f1f780877d0 "xx_161", path=path@entry=0x7f1fe4384300 "./test22/xx_161", create_info=0x7f1fe4386550, alter_info=0x7f1fe4386640, 
    internal_tmp_table=false, select_field_count=0, find_parent_keys=true, no_ha_table=false, is_trans=0x7f1fe43854c9, key_info=0x7f1fe43842d0, key_count=0x7f1fe43842b8, 
    keys_onoff=Alter_info::ENABLE, fk_key_info=0x7f1fe43842d8, fk_key_count=0x7f1fe43842bc, existing_fk_info=0x0, existing_fk_count=0, tmp_table_def=0x7f1fe43842e0, 
    post_ddl_ht=0x7f1fe4385528) at ../../mysqlcom-pro-8.0.4-rc/sql/sql_table.cc:6808
#20 0x0000000000be11bf in mysql_create_table_no_lock (thd=thd@entry=0x7f1f78a9a2f0, db=0x7f1f795f9358 "test22", table_name=0x7f1f780877d0 "xx_161", 
    create_info=create_info@entry=0x7f1fe4386550, alter_info=alter_info@entry=0x7f1fe4386640, select_field_count=select_field_count@entry=0, find_parent_keys=true, 
    is_trans=0x7f1fe43854c9, post_ddl_ht=0x7f1fe4385528) at ../../mysqlcom-pro-8.0.4-rc/sql/sql_table.cc:6905
#21 0x0000000000be8083 in mysql_create_table (thd=thd@entry=0x7f1f78a9a2f0, create_table=create_table@entry=0x7f1f795f8dd0, create_info=create_info@entry=0x7f1fe4386550, 
    alter_info=alter_info@entry=0x7f1fe4386640) at ../../mysqlcom-pro-8.0.4-rc/sql/sql_table.cc:7457
#22 0x000000000106e023 in Sql_cmd_create_table::execute (this=0x7f1f78ce9dd8, thd=0x7f1f78a9a2f0) at ../../mysqlcom-pro-8.0.4-rc/sql/sql_cmd_ddl_table.cc:364
#23 0x0000000000b7e9c2 in mysql_execute_command (thd=thd@entry=0x7f1f78a9a2f0, first_level=first_level@entry=true) at ../../mysqlcom-pro-8.0.4-rc/sql/sql_parse.cc:3498
#24 0x0000000000b80f40 in mysql_parse (thd=thd@entry=0x7f1f78a9a2f0, parser_state=parser_state@entry=0x7f1fe4388600) at ../../mysqlcom-pro-8.0.4-rc/sql/sql_parse.cc:5440
#25 0x0000000000b82ec1 in dispatch_command (thd=thd@entry=0x7f1f78a9a2f0, com_data=com_data@entry=0x7f1fe4388d00, command=COM_QUERY)
    at ../../mysqlcom-pro-8.0.4-rc/sql/sql_parse.cc:1730
#26 0x0000000000b83990 in do_command (thd=thd@entry=0x7f1f78a9a2f0) at ../../mysqlcom-pro-8.0.4-rc/sql/sql_parse.cc:1310
---Type <return> to continue, or q <return> to quit---
#27 0x0000000000e230d8 in handle_connection (arg=arg@entry=0x6ebcaf0) at ../../mysqlcom-pro-8.0.4-rc/sql/conn_handler/connection_handler_per_thread.cc:335
#28 0x000000000192c72f in pfs_spawn_thread (arg=0x6eb3860) at ../../../mysqlcom-pro-8.0.4-rc/storage/perfschema/pfs.cc:2994
#29 0x00007f1ff4fc5e25 in start_thread () from /lib64/libpthread.so.0
#30 0x00007f1ff342d34d in clone () from /lib64/libc.so.6

I used optimized build with below commit details:
cat ../docs/INFO_SRC 
commit: 876a72f83457403c5165623fd7a31699563d08ef
date: 2018-01-04 15:02:58 +0100
build-date: 2018-01-04 15:05:59 +0100
short: 876a72f
branch: mysql-8.0.4-rc-release

MySQL source 8.0.4
[11 Jan 2018 8:43] Bin Su
Posted by developer:
 
We should disable this table(mysql.innodb_ddl_log) and mysql.innodb_dynamic_metadata for users completely. So users can't see them and can't operate on them at all.

As discussed with Sivert, re-assign this to him.
[1 Mar 2018 17:54] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 8.0.5 release, and here's the changelog entry:

        The mysql.innodb_ddl_log and
        mysql.innodb_dynamic_metadata tables, which
        are used internally by the InnoDB storage
        engine, are now protected. DDL and DML operations on these
        tables are no longer permitted, and the tables no longer appear
        in INFORMATION_SCHEMA query results.