Bug #93196 DD crashes on assert if ha_commit_trans() returns error
Submitted: 14 Nov 2018 14:35 Modified: 12 Feb 2019 20:22
Reporter: Vlad Lesin Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: DDL Severity:S6 (Debug Builds)
Version:8.0 OS:Any
Assigned to: CPU Architecture:Any

[14 Nov 2018 14:35] Vlad Lesin
Description:
If we look into trans_commit_implicit() function, we will see that thd->dd_client()->commit_modified_objects() is being invoked ignoring the error, returned by ha_commit_trans(). As a result, the following crash takes place on debug build if ha_commit_trans() returns error:

=====
#0  0x00007ffff5ca1428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#1  0x00007ffff5ca302a in __GI_abort () at abort.c:89
#2  0x00007ffff5c99bd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x5a8b9a3 "stored_object == nullptr", 
    file=file@entry=0x5a8b518 "./sql/dd/impl/cache/dictionary_client.cc", line=line@entry=2648, 
    function=function@entry=0x5a90f80 <void dd::cache::Dictionary_client::remove_uncommitted_objects<dd::Abstract_table>(bool)::__PRETTY_FUNCTION__> "void dd::cache::Dictionary_client::remove_uncommitted_objects(bool) [with T = dd::Abstract_table]") at assert.c:92
#3  0x00007ffff5c99c82 in __GI___assert_fail (assertion=0x5a8b9a3 "stored_object == nullptr", 
    file=0x5a8b518 "./sql/dd/impl/cache/dictionary_client.cc", line=2648, 
    function=0x5a90f80 <void dd::cache::Dictionary_client::remove_uncommitted_objects<dd::Abstract_table>(bool)::__PRETTY_FUNCTION__> "void dd::cache::Dictionary_client::remove_uncommitted_objects(bool) [with T = dd::Abstract_table]") at assert.c:101
#4  0x000000000424504c in dd::cache::Dictionary_client::remove_uncommitted_objects<dd::Abstract_table> (this=0x7fff3c01c1c0, commit_to_shared_cache=true)
    at ./sql/dd/impl/cache/dictionary_client.cc:2648
#5  0x000000000423fc7d in dd::cache::Dictionary_client::commit_modified_objects (this=0x7fff3c01c1c0)
    at ./sql/dd/impl/cache/dictionary_client.cc:2741
#6  0x000000000315c3b2 in trans_commit_implicit (thd=0x7fff3c1182a0, ignore_global_read_lock=false) at ./sql/transaction.cc:349
#7  0x00000000030991b3 in mysql_rm_table_no_locks (thd=0x7fff3c1182a0, tables=0x7fff3c18f528, if_exists=false, drop_temporary=false, drop_database=false, 
    dropped_non_atomic_flag=0x7fffe89fdf11, post_ddl_htons=0x7fffe89fdf80, fk_invalidator=0x7fffe89fdfb0, safe_to_release_mdl=0x7fffe89fdf40)
    at ./sql/sql_table.cc:3179
#8  0x0000000003094b82 in mysql_rm_table (thd=0x7fff3c1182a0, tables=0x7fff3c18f528, if_exists=false, drop_temporary=false)
    at ./sql/sql_table.cc:1467
#9  0x0000000002ff89ec in mysql_execute_command (thd=0x7fff3c1182a0, first_level=true) at ./sql/sql_parse.cc:3336
#10 0x0000000002ffe4c4 in mysql_parse (thd=0x7fff3c1182a0, parser_state=0x7fffe89ff380, force_primary_storage_engine=false)
    at ./sql/sql_parse.cc:5041
#11 0x0000000002ff3e0c in dispatch_command (thd=0x7fff3c1182a0, com_data=0x7fffe89ffcf0, command=COM_QUERY)
    at ./sql/sql_parse.cc:1687
#12 0x0000000002ff246e in do_command (thd=0x7fff3c1182a0) at ./sql/sql_parse.cc:1260
#13 0x000000000319fe59 in handle_connection (arg=0x7037f60) at ./sql/conn_handler/connection_handler_per_thread.cc:308
#14 0x0000000004c263d0 in pfs_spawn_thread (arg=0x72ce310) at ./storage/perfschema/pfs.cc:2836
#15 0x00007ffff79be6ba in start_thread (arg=0x7fffe8a00700) at pthread_create.c:333
#16 0x00007ffff5d7341d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
=====

How to repeat:
Execute the following sequence of queries on debug build:

CREATE TABLE t_innodb(a INT NOT NULL, KEY (a)) ENGINE=InnoDB;
SET @@GLOBAL.DEBUG= '+d,simulate_failure_in_before_commit_hook';
DROP TABLE t_innodb;

Suggested fix:
Check the result of ha_commit_trans() at the end of trans_commit_implicit() function and invoke thd->dd_client()->rollback_modified_objects() on error.
[14 Nov 2018 15:50] MySQL Verification Team
Thank you for the bug report.

Enter password:
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 8
Server version: 8.0.14-debug Source distribution BUILD: 2018-NOV-11

Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql 8.0 > create database test;
Query OK, 1 row affected (0,43 sec)

mysql 8.0 > use test
Database changed
mysql 8.0 > CREATE TABLE t_innodb(a INT NOT NULL, KEY (a)) ENGINE=InnoDB;
DROP TABLE t_innodb;
Query OK, 0 rows affected (2,37 sec)

mysql 8.0 > SET @@GLOBAL.DEBUG= '+d,simulate_failure_in_before_commit_hook';
Query OK, 0 rows affected (0,00 sec)

mysql 8.0 > DROP TABLE t_innodb;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql 8.0 >

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 = 7f0a8c1a7cd8 thread_stack 0x46000
/home/miguel/dbsd/8.0/bin/mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x55) [0x55f5c9f2ab19]
/home/miguel/dbsd/8.0/bin/mysqld(handle_fatal_signal+0x3f2) [0x55f5c8be2dc3]
/usr/lib/libpthread.so.0(+0x123c0) [0x7f0ab9c083c0]
/usr/lib/libc.so.6(gsignal+0x10f) [0x7f0ab917fd7f]
/usr/lib/libc.so.6(abort+0x125) [0x7f0ab916a672]
/usr/lib/libc.so.6(+0x22548) [0x7f0ab916a548]
/usr/lib/libc.so.6(+0x30396) [0x7f0ab9178396]
/home/miguel/dbsd/8.0/bin/mysqld(void dd::cache::Dictionary_client::remove_uncommitted_objects<dd::Abstract_table>(bool)+0x1e1) [0x55f5c9c700f5]
/home/miguel/dbsd/8.0/bin/mysqld(dd::cache::Dictionary_client::commit_modified_objects()+0x1d) [0x55f5c9c6b31f]
/home/miguel/dbsd/8.0/bin/mysqld(trans_commit_implicit(THD*, bool)+0x368) [0x55f5c8b89957]
/home/miguel/dbsd/8.0/bin/mysqld(mysql_rm_table_no_locks(THD*, TABLE_LIST*, bool, bool, bool, bool*, std::set<handlerton*, std::less<handlerton*>, std::allocator<handlerton*> >*, Foreign_key_parents_invalidator*, std::vector<MDL_ticket*, std::allocator<MDL_ticket*> >*)+0x103f) [0x55f5c8ac3325]
/home/miguel/dbsd/8.0/bin/mysqld(mysql_rm_table(THD*, TABLE_LIST*, bool, bool)+0x57f) [0x55f5c8abec3e]
/home/miguel/dbsd/8.0/bin/mysqld(mysql_execute_command(THD*, bool)+0x24a1) [0x55f5c8a230f3]
/home/miguel/dbsd/8.0/bin/mysqld(mysql_parse(THD*, Parser_state*, bool)+0x696) [0x55f5c8a28be9]
/home/miguel/dbsd/8.0/bin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0x14c9) [0x55f5c8a1e411]
/home/miguel/dbsd/8.0/bin/mysqld(do_command(THD*)+0x487) [0x55f5c8a1c974]
/home/miguel/dbsd/8.0/bin/mysqld(+0x2e2e47b) [0x55f5c8bce47b]
/home/miguel/dbsd/8.0/bin/mysqld(+0x48782f4) [0x55f5ca6182f4]
/usr/lib/libpthread.so.0(+0x7a9d) [0x7f0ab9bfda9d]
/usr/lib/libc.so.6(clone+0x43) [0x7f0ab9243b23]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f0a24190b68): DROP TABLE t_innodb
Connection ID (thread ID): 8
Status: NOT_KILLED
[14 Nov 2018 18:41] Vlad Lesin
BTW, the same issue is in trans_commit() function. For example, the following queries sequence:

CREATE DATABASE test1;
SET @@GLOBAL.DEBUG= '+d,simulate_failure_in_before_commit_hook';
DROP DATABASE test;

leads to the following crash:

===
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
62      ../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7f21ccd6d700 (LWP 26036))]
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1  0x0000000004530a69 in my_write_core (sig=6) at ./mysys/stacktrace.cc:278
#2  0x00000000031b430d in handle_fatal_signal (sig=6) at ./sql/signal_handler.cc:249
#3  <signal handler called>
#4  0x00007f21d86d9428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#5  0x00007f21d86db02a in __GI_abort () at abort.c:89
#6  0x00007f21d86d1bd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x5a8b9a3 "stored_object == nullptr", file=file@entry=0x5a8b518 "./sql/dd/impl/cache/dictionary_client.cc", line=line@entry=2648, function=function@entry=0x5a93860 <void dd::cache::Dictionary_client::remove_uncommitted_objects<dd::Schema>(bool)::__PRETTY_FUNCTION__> "void dd::cache::Dictionary_client::remove_uncommitted_objects(bool) [with T = dd::Schema]") at assert.c:92
#7  0x00007f21d86d1c82 in __GI___assert_fail (assertion=0x5a8b9a3 "stored_object == nullptr", file=0x5a8b518 "./sql/dd/impl/cache/dictionary_client.cc", line=2648, function=0x5a93860 <void dd::cache::Dictionary_client::remove_uncommitted_objects<dd::Schema>(bool)::__PRETTY_FUNCTION__> "void dd::cache::Dictionary_client::remove_uncommitted_objects(bool) [with T = dd::Schema]") at assert.c:101
#8  0x000000000424a9a0 in dd::cache::Dictionary_client::remove_uncommitted_objects<dd::Schema> (this=0x7f212c01c1c0, commit_to_shared_cache=true) at ./sql/dd/impl/cache/dictionary_client.cc:2648
#9  0x000000000423fc8e in dd::cache::Dictionary_client::commit_modified_objects (this=0x7f212c01c1c0) at ./sql/dd/impl/cache/dictionary_client.cc:2742
#10 0x000000000315bfe0 in trans_commit (thd=0x7f212c027680, ignore_global_read_lock=false) at ./sql/transaction.cc:281
#11 0x0000000002f82b48 in mysql_rm_db (thd=0x7f212c027680, db=..., if_exists=false) at ./sql/sql_db.cc:643
#12 0x0000000002ff932e in mysql_execute_command (thd=0x7f212c027680, first_level=true) at ./sql/sql_parse.cc:3504
#13 0x0000000002ffe4c4 in mysql_parse (thd=0x7f212c027680, parser_state=0x7f21ccd6c380, force_primary_storage_engine=false) at ./sql/sql_parse.cc:5041
#14 0x0000000002ff3e0c in dispatch_command (thd=0x7f212c027680, com_data=0x7f21ccd6ccf0, command=COM_QUERY) at ./sql/sql_parse.cc:1687
#15 0x0000000002ff246e in do_command (thd=0x7f212c027680) at ./sql/sql_parse.cc:1260
#16 0x000000000319fe59 in handle_connection (arg=0x768dcf0) at ./sql/conn_handler/connection_handler_per_thread.cc:308
#17 0x0000000004c263d0 in pfs_spawn_thread (arg=0x7660270) at ./storage/perfschema/pfs.cc:2836
#18 0x00007f21da3f66ba in start_thread (arg=0x7f21ccd6d700) at pthread_create.c:333
#19 0x00007f21d87ab41d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
===
[12 Feb 2019 20:22] Paul DuBois
Posted by developer:
 
Fixed in 8.0.16.

The data dictionary cache could become out of sync with data
dictionary contents due to failure to check the result of a
transaction-related operation.