[MDEV-17998] Deadlock and eventual Assertion `!table->pos_in_locked_tables' failed in tc_release_table on KILL_TIMEOUT Created: 2018-12-13  Updated: 2019-08-08  Resolved: 2019-08-08

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Locking, Views
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.2.27, 10.3.18, 10.4.8, 10.5.0

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-17717 Assertion `!table->pos_in_locked_tabl... Closed
relates to MDEV-18154 Deadlock and assertion upon no-op ALT... Closed

 Description    

SET max_statement_time= 2;
 
 
 
CREATE TABLE t1 (a INT);
 
CREATE VIEW v1 AS SELECT * FROM t1;
 
CREATE TABLE t2 (b INT, c INT);
 
 
 
LOCK TABLES v1 READ, t2 WRITE, t1 WRITE;
 
--error ER_BAD_FIELD_ERROR
 
ALTER TABLE t1 CHANGE f1 f2 DOUBLE;
 
ALTER TABLE t2 DROP c;
 
 
 
# Cleanup
 
UNLOCK TABLES;
 
DROP VIEW v1;
 
DROP TABLE t1, t2;

Execution hangs on the 2nd ALTER, which eventually gets interrupted due to max_statement_time, at which point the assertion failure happens:

10.2 4ca20791

 
mysqld: /data/src/10.2/sql/table_cache.cc:453: void tc_release_table(TABLE*): Assertion `!table->pos_in_locked_tables' failed.
 
190304 16:49:17 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007fe272366ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x000055c7d1435bdd in tc_release_table (table=0x7fe22008fdc0) at /data/src/10.2/sql/table_cache.cc:453
 
#9  0x000055c7d11cd312 in close_thread_table (thd=0x7fe220000b00, table_ptr=0x7fe220000be0) at /data/src/10.2/sql/sql_base.cc:903
 
#10 0x000055c7d11cfd8f in Locked_tables_list::unlink_all_closed_tables (this=0x7fe220004568, thd=0x7fe220000b00, lock=0x0, reopen_count=1) at /data/src/10.2/sql/sql_base.cc:2367
 
#11 0x000055c7d11d015c in Locked_tables_list::reopen_tables (this=0x7fe220004568, thd=0x7fe220000b00, need_reopen=false) at /data/src/10.2/sql/sql_base.cc:2464
 
#12 0x000055c7d131a0b0 in mysql_alter_table (thd=0x7fe220000b00, new_db=0x7fe220012b50 "test", new_name=0x0, create_info=0x7fe26478ee50, table_list=0x7fe220012540, alter_info=0x7fe26478eda0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9765
 
#13 0x000055c7d13947e9 in Sql_cmd_alter_table::execute (this=0x7fe220012b80, thd=0x7fe220000b00) at /data/src/10.2/sql/sql_alter.cc:329
 
#14 0x000055c7d124aeb4 in mysql_execute_command (thd=0x7fe220000b00) at /data/src/10.2/sql/sql_parse.cc:6231
 
#15 0x000055c7d124fd15 in mysql_parse (thd=0x7fe220000b00, rawbuf=0x7fe220012468 "ALTER TABLE t2 DROP c", length=21, parser_state=0x7fe264790200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:8018
 
#16 0x000055c7d123d64f in dispatch_command (command=COM_QUERY, thd=0x7fe220000b00, packet=0x7fe220096191 "", packet_length=21, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1829
 
#17 0x000055c7d123bf5a in do_command (thd=0x7fe220000b00) at /data/src/10.2/sql/sql_parse.cc:1379
 
#18 0x000055c7d138f480 in do_handle_one_connection (connect=0x55c7d387bee0) at /data/src/10.2/sql/sql_connect.cc:1336
 
#19 0x000055c7d138f20d in handle_one_connection (arg=0x55c7d387bee0) at /data/src/10.2/sql/sql_connect.cc:1242
 
#20 0x000055c7d17b7200 in pfs_spawn_thread (arg=0x55c7d389f0f0) at /data/src/10.2/storage/perfschema/pfs.cc:1862
 
#21 0x00007fe27403d494 in start_thread (arg=0x7fe264791700) at pthread_create.c:333
 
#22 0x00007fe27242393f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Non-debug doesn't crash, but ALTER still hangs.

 Comments   
Comment by Sergey Vojtovich [ 2018-12-13 ]

Just for the record: assertion was added in 327b2717219aaa8f9033895a2351a6ccd4655116, when fixing MDEV-14410.

Comment by Elena Stepanova [ 2019-02-21 ]

Similar occurrence on 10.3, on server shutdown:
https://dev.azure.com/elenst/MariaDB%20tests/_build/results?buildId=862 [036.1]

mysqld: /home/vsts/src/sql/table_cache.cc:466: void tc_release_table(TABLE*): Assertion `!table->pos_in_locked_tables' failed.
 
190221 15:35:48 [ERROR] 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.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
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.
 
Server version: 10.3.13-MariaDB-debug-log
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=8
 
max_threads=153
 
thread_count=7
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467475 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x62a000066270
 
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 = 0x7f3775ce2e40 thread_stack 0x49000
 
/usr/lib/x86_64-linux-gnu/libasan.so.2(+0x4a077)[0x7f37a5644077]
 
/home/vsts/server/bin/mysqld(my_print_stacktrace+0xb3)[0x55d8a013e505]
 
mysys/stacktrace.c:269(my_print_stacktrace)[0x55d89f08dd65]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f37a3df7390]
 
linux/raise.c:54(__GI_raise)[0x7f37a31b0428]
 
stdlib/abort.c:91(__GI_abort)[0x7f37a31b202a]
 
assert/assert.c:92(__assert_fail_base)[0x7f37a31a8bd7]
 
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7f37a31a8c82]
 
sql/table_cache.cc:468(tc_release_table(TABLE*))[0x55d89ee9b965]
 
sql/sql_base.cc:913(close_thread_table(THD*, TABLE**))[0x55d89e85f2af]
 
sql/sql_base.cc:2416(Locked_tables_list::unlink_all_closed_tables(THD*, st_mysql_lock*, unsigned long))[0x55d89e865af6]
 
sql/sql_base.cc:2527(Locked_tables_list::reopen_tables(THD*, bool))[0x55d89e866544]
 
sql/sql_table.cc:10080(mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x55d89ebc8c27]
 
sql/sql_alter.cc:497(Sql_cmd_alter_table::execute(THD*))[0x55d89ed0689e]
 
sql/sql_parse.cc:6288(mysql_execute_command(THD*))[0x55d89e9c1156]
 
sql/sql_parse.cc:8095(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x55d89e9cbddb]
 
sql/sql_parse.cc:1856(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x55d89e9a68a0]
 
sql/sql_parse.cc:1396(do_command(THD*))[0x55d89e9a39c2]
 
sql/sql_connect.cc:1403(do_handle_one_connection(CONNECT*))[0x55d89ecf802e]
 
sql/sql_connect.cc:1310(handle_one_connection)[0x55d89ecf7a0b]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f37a3ded6ba]
 
x86_64/clone.S:111(clone)[0x7f37a328241d]
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x62b00000e288): ALTER IGNORE TABLE `non_existing_table` /*!100301 NOWAIT */ MODIFY COLUMN IF EXISTS u GEOMETRYCOLLECTION /*!100201 DEFAULT ST_GEOMFROMTEXT('Point(1 1)') */ /*!100303 INVISIBLE */ FIRST, ALGORITHM=DEFAULT, LOCK=DEFAULT  /* QNO 1643 CON_ID 15 */
 
Connection ID (thread ID): 15
 
Status: KILL_SERVER

Comment by Elena Stepanova [ 2019-03-27 ]

A slightly different test case which fails with the same assertion on a debug build, and with a different ASAN error on a non-debug ASAN build:

SET max_statement_time= 2;
 
 
 
CREATE TABLE t (a INT);
 
LOCK TABLE t READ, t AS t2 WRITE;
 
ALTER TABLE t CHANGE IF EXISTS b c INT;
 
--error ER_STATEMENT_TIMEOUT
 
ALTER TABLE t MODIFY IF EXISTS d INT FIRST, LOCK=SHARED;
 
ALTER TABLE t;

10.3 non-debug ASAN dbc0d576

 
==678==ERROR: AddressSanitizer: heap-use-after-free on address 0x606000001f68 at pc 0x55b15f0b96b9 bp 0x7faee51fec50 sp 0x7faee51fec48
 
READ of size 4 at 0x606000001f68 thread T5
 
    #0 0x55b15f0b96b8 in find_table_for_mdl_upgrade(THD*, char const*, char const*, int*) /data/src/10.4/sql/sql_base.cc:2258
 
    #1 0x55b15f0c51a1 in open_tables_check_upgradable_mdl /data/src/10.4/sql/sql_base.cc:4103
 
    #2 0x55b15f0c51a1 in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /data/src/10.4/sql/sql_base.cc:4213
 
    #3 0x55b15f3c983c in open_tables /data/src/10.4/sql/sql_base.h:257
 
    #4 0x55b15f3c983c in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /data/src/10.4/sql/sql_table.cc:9086
 
    #5 0x55b15f4c6bee in Sql_cmd_alter_table::execute(THD*) /data/src/10.4/sql/sql_alter.cc:497
 
    #6 0x55b15f1ee1ed in mysql_execute_command(THD*) /data/src/10.4/sql/sql_parse.cc:6302
 
    #7 0x55b15f205bdd in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.4/sql/sql_parse.cc:8104
 
    #8 0x55b15f20eced in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.4/sql/sql_parse.cc:1851
 
    #9 0x55b15f211695 in do_command(THD*) /data/src/10.4/sql/sql_parse.cc:1396
 
    #10 0x55b15f4bd7b7 in do_handle_one_connection(CONNECT*) /data/src/10.4/sql/sql_connect.cc:1402
 
    #11 0x55b15f4bdcba in handle_one_connection /data/src/10.4/sql/sql_connect.cc:1308
 
    #12 0x55b15fe7f296 in pfs_spawn_thread /data/src/10.4/storage/perfschema/pfs.cc:1862
 
    #13 0x7faef1529493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #14 0x7faeefb2a93e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
0x606000001f68 is located 40 bytes inside of 64-byte region [0x606000001f40,0x606000001f80)
 
freed by thread T5 here:
 
    #0 0x7faef1794477 in operator delete(void*) (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x55477)
 
    #1 0x55b15f4d540c in MDL_context::release_all_locks_for_name(MDL_ticket*) /data/src/10.4/sql/mdl.cc:2911
 
 
 
previously allocated by thread T5 here:
 
    #0 0x7faef179423f in operator new(unsigned long, std::nothrow_t const&) (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x5523f)
 
    #1 0x55b15f4ce4eb in MDL_ticket::create(MDL_context*, enum_mdl_type) /data/src/10.4/sql/mdl.cc:1011
 
 
 
Thread T5 created by T0 here:
 
    #0 0x7faef1762bba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
 
    #1 0x55b15fe879b6 in spawn_thread_v1 /data/src/10.4/storage/perfschema/pfs.cc:1912
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.4/sql/sql_base.cc:2258 find_table_for_mdl_upgrade(THD*, char const*, char const*, int*)
 
Shadow bytes around the buggy address:
 
  0x0c0c7fff8390: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c0c7fff83a0: fa fa fa fa fa fa fa fa fa fa fa fa fd fd fd fd
 
  0x0c0c7fff83b0: fd fd fd fd fa fa fa fa 00 00 00 00 00 00 00 00
 
  0x0c0c7fff83c0: fa fa fa fa fd fd fd fd fd fd fd fd fa fa fa fa
 
  0x0c0c7fff83d0: 00 00 00 00 00 00 00 00 fa fa fa fa 00 00 00 00
 
=>0x0c0c7fff83e0: 00 00 00 00 fa fa fa fa fd fd fd fd fd[fd]fd fd
 
  0x0c0c7fff83f0: fa fa fa fa 00 00 00 00 00 00 00 00 fa fa fa fa
 
  0x0c0c7fff8400: fd fd fd fd fd fd fd fd fa fa fa fa fd fd fd fd
 
  0x0c0c7fff8410: fd fd fd fd fa fa fa fa fd fd fd fd fd fd fd fd
 
  0x0c0c7fff8420: fa fa fa fa fd fd fd fd fd fd fd fd fa fa fa fa
 
  0x0c0c7fff8430: fd fd fd fd fd fd fd fd fa fa fa fa fd fd fd fd
 
Shadow byte legend (one shadow byte represents 8 application bytes):
 
  Addressable:           00
 
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
 
  Heap right redzone:      fb
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack partial redzone:   f4
 
  Stack after return:      f5
 
  Stack use after scope:   f8
 
  Global redzone:          f9
 
  Global init order:       f6
 
  Poisoned by user:        f7
 
  Contiguous container OOB:fc
 
  ASan internal:           fe
 
==678==ABORTING

Comment by Michael Widenius [ 2019-08-08 ]

This crash happens in debug builds when using LOCK TABLE together with ALTER TABLE or FLUSH TABLES and the command aborts, which causes a call to unlink_all_closed_tables()

The bug was that unlink_all_closed_tables() didn't reset thd->open_tables->pos_in_locked_tables

Generated at Thu Feb 08 08:40:44 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.