[MDEV-10748] Server crashes in ha_maria::implicit_commit upon ALTER TABLE Created: 2016-09-05  Updated: 2020-03-04  Resolved: 2019-10-15

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Locking, Storage Engine - Aria
Affects Version/s: 10.2, 10.3
Fix Version/s: 10.2.28, 10.3.19

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

Issue Links:
Duplicate
is duplicated by MDEV-18088 Assertion `share->in_trans == 0' fail... Closed
Relates
relates to MDEV-21830 Server crash in ha_maria::implicit_co... Confirmed

 Description   

Note: It fails every time for me on ASAN/debug builds, and intermittently on non-debug builds. But it still uses a race condition, so run with --repeat=N if it doesn't fail right away, and use the ASAN build.

CREATE TABLE t1 (a INT, b INT) ENGINE=Aria;
 
SELECT * FROM t1;
 
CREATE TABLE t2 (c INT) ENGINE=Aria;
 
 
 
--connect (con1,localhost,root,,test)
 
--send
 
  SELECT * FROM t1;
 
 
 
--connection default
 
--error ER_NO_SUCH_TABLE
 
SELECT * FROM t1, non_existing_table;
 
LOCK TABLE t2 READ, t1 WRITE;
 
--error ER_DUP_FIELDNAME
 
ALTER TABLE t1 CHANGE b a INT;
 
 
 
# Cleanup
 
--connection con1
 
--reap
 
--disconnect con1
 
--connection default
 
UNLOCK TABLES;
 
DROP TABLE t1, t2;

10.2 3fb6d25 ASAN

 
==6037==ERROR: AddressSanitizer: heap-use-after-free on address 0x6290000eb280 at pc 0x55c7aa144408 bp 0x7f5dd69277c0 sp 0x7f5dd69277b8
 
READ of size 8 at 0x6290000eb280 thread T5
 
    #0 0x55c7aa144407 in ha_maria::implicit_commit(THD*, bool) /data/src/10.2/storage/maria/ha_maria.cc:2936
 
    #1 0x55c7a9c43444 in ha_commit_trans(THD*, bool) /data/src/10.2/sql/handler.cc:1356
 
    #2 0x55c7a99b8dd2 in trans_commit_implicit(THD*) /data/src/10.2/sql/transaction.cc:368
 
    #3 0x55c7a965e753 in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:6341
 
    #4 0x55c7a9668a0d in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:8015
 
    #5 0x55c7a96433fa in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1826
 
    #6 0x55c7a964048f in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1379
 
    #7 0x55c7a9986a7c in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
 
    #8 0x55c7a9986491 in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
 
    #9 0x55c7aa3a1683 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
 
    #10 0x7f5de2d9c493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #11 0x7f5de118293e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
0x6290000eb280 is located 128 bytes inside of 18412-byte region [0x6290000eb200,0x6290000ef9ec)
 
freed by thread T5 here:
 
    #0 0x7f5de3006527 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x54527)
 
    #1 0x55c7aacc256f in free_memory /data/src/10.2/mysys/safemalloc.c:279
 
    #2 0x55c7aacc1b75 in sf_free /data/src/10.2/mysys/safemalloc.c:197
 
    #3 0x55c7aac90e04 in my_free /data/src/10.2/mysys/my_malloc.c:217
 
    #4 0x55c7aa2979d1 in maria_close /data/src/10.2/storage/maria/ma_close.c:269
 
    #5 0x55c7aa137e03 in ha_maria::close() /data/src/10.2/storage/maria/ha_maria.cc:1274
 
    #6 0x55c7a9c4b7bf in handler::ha_close() /data/src/10.2/sql/handler.cc:2567
 
    #7 0x55c7a98dd75b in closefrm(TABLE*) /data/src/10.2/sql/table.cc:3452
 
    #8 0x55c7a9aea0e5 in intern_close_table /data/src/10.2/sql/table_cache.cc:222
 
    #9 0x55c7a9aea34b in tc_remove_table /data/src/10.2/sql/table_cache.cc:260
 
    #10 0x55c7a9aeb1d7 in tc_release_table(TABLE*) /data/src/10.2/sql/table_cache.cc:461
 
    #11 0x55c7a95340d8 in close_thread_table(THD*, TABLE**) /data/src/10.2/sql/sql_base.cc:903
 
    #12 0x55c7a9532e24 in close_all_tables_for_name(THD*, TABLE_SHARE*, ha_extra_function, TABLE*) /data/src/10.2/sql/sql_base.cc:677
 
    #13 0x55c7a953a8aa in Locked_tables_list::reopen_tables(THD*, bool) /data/src/10.2/sql/sql_base.cc:2422
 
    #14 0x55c7a965e027 in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:6258
 
    #15 0x55c7a9668a0d in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:8015
 
    #16 0x55c7a96433fa in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1826
 
    #17 0x55c7a964048f in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1379
 
    #18 0x55c7a9986a7c in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
 
    #19 0x55c7a9986491 in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
 
    #20 0x55c7aa3a1683 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
 
    #21 0x7f5de2d9c493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
previously allocated by thread T5 here:
 
    #0 0x7f5de300673f in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x5473f)
 
    #1 0x55c7aacc12e5 in sf_malloc /data/src/10.2/mysys/safemalloc.c:118
 
    #2 0x55c7aac9053c in my_malloc /data/src/10.2/mysys/my_malloc.c:101
 
    #3 0x55c7aac6f576 in my_multi_malloc /data/src/10.2/mysys/mulalloc.c:51
 
    #4 0x55c7aa1cc1d2 in maria_clone_internal /data/src/10.2/storage/maria/ma_open.c:117
 
    #5 0x55c7aa1d55e2 in maria_open /data/src/10.2/storage/maria/ma_open.c:1056
 
    #6 0x55c7aa136f54 in ha_maria::open(char const*, int, unsigned int) /data/src/10.2/storage/maria/ha_maria.cc:1200
 
    #7 0x55c7a9c4a9ce in handler::ha_open(TABLE*, char const*, int, unsigned int) /data/src/10.2/sql/handler.cc:2502
 
    #8 0x55c7a98dc879 in open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool) /data/src/10.2/sql/table.cc:3351
 
    #9 0x55c7a9538246 in open_table(THD*, TABLE_LIST*, Open_table_context*) /data/src/10.2/sql/sql_base.cc:1923
 
    #10 0x55c7a953ebff in open_and_process_table /data/src/10.2/sql/sql_base.cc:3488
 
    #11 0x55c7a95413f0 in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /data/src/10.2/sql/sql_base.cc:4011
 
    #12 0x55c7a95450fc in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /data/src/10.2/sql/sql_base.cc:4767
 
    #13 0x55c7a9526504 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /data/src/10.2/sql/sql_base.h:506
 
    #14 0x55c7a965f3a9 in execute_sqlcom_select /data/src/10.2/sql/sql_parse.cc:6402
 
    #15 0x55c7a964ca0b in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:3487
 
    #16 0x55c7a9668a0d in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:8015
 
    #17 0x55c7a96433fa in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1826
 
    #18 0x55c7a964048f in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1379
 
    #19 0x55c7a9986a7c in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
 
    #20 0x55c7a9986491 in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
 
    #21 0x55c7aa3a1683 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
 
    #22 0x7f5de2d9c493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
Thread T5 created by T0 here:
 
    #0 0x7f5de2fd5bba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
 
    #1 0x55c7aa3a1c4b in spawn_thread_v1 /data/src/10.2/storage/perfschema/pfs.cc:1912
 
    #2 0x55c7a943ccce in inline_mysql_thread_create /data/src/10.2/include/mysql/psi/mysql_thread.h:1239
 
    #3 0x55c7a9451c6b in create_thread_to_handle_connection(CONNECT*) /data/src/10.2/sql/mysqld.cc:6466
 
    #4 0x55c7a9452370 in create_new_thread /data/src/10.2/sql/mysqld.cc:6536
 
    #5 0x55c7a9453387 in handle_connections_sockets() /data/src/10.2/sql/mysqld.cc:6811
 
    #6 0x55c7a94511c0 in mysqld_main(int, char**) /data/src/10.2/sql/mysqld.cc:6085
 
    #7 0x55c7a943b06f in main /data/src/10.2/sql/main.cc:25
 
    #8 0x7f5de10ba2b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.2/storage/maria/ha_maria.cc:2936 ha_maria::implicit_commit(THD*, bool)
 
Shadow bytes around the buggy address:
 
  0x0c5280015600: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5280015610: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5280015620: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5280015630: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5280015640: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c5280015650:[fd]fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5280015660: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5280015670: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5280015680: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5280015690: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c52800156a0: fd fd fd fd fd fd fd fd fd fd fd fd 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
 
==6037==ABORTING

10.2 3fb6d25 debug

 
#3  <signal handler called>
 
#4  0x000055a081d10aeb in ha_maria::implicit_commit (thd=0x7ff498000b00, new_trn=true) at /data/src/10.2/storage/maria/ha_maria.cc:2937
 
#5  0x000055a081b031b7 in ha_commit_trans (thd=0x7ff498000b00, all=true) at /data/src/10.2/sql/handler.cc:1356
 
#6  0x000055a0819e9e0b in trans_commit_implicit (thd=0x7ff498000b00) at /data/src/10.2/sql/transaction.cc:368
 
#7  0x000055a0818906a7 in mysql_execute_command (thd=0x7ff498000b00) at /data/src/10.2/sql/sql_parse.cc:6341
 
#8  0x000055a0818950b3 in mysql_parse (thd=0x7ff498000b00, rawbuf=0x7ff498012448 "ALTER TABLE t1 CHANGE b a INT", length=29, parser_state=0x7ff4aa39d200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:8015
 
#9  0x000055a0818829ed in dispatch_command (command=COM_QUERY, thd=0x7ff498000b00, packet=0x7ff49808d631 "ALTER TABLE t1 CHANGE b a INT", packet_length=29, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1826
 
#10 0x000055a081881344 in do_command (thd=0x7ff498000b00) at /data/src/10.2/sql/sql_parse.cc:1379
 
#11 0x000055a0819d42cf in do_handle_one_connection (connect=0x55a084dac7e0) at /data/src/10.2/sql/sql_connect.cc:1335
 
#12 0x000055a0819d405c in handle_one_connection (arg=0x55a084dac7e0) at /data/src/10.2/sql/sql_connect.cc:1241
 
#13 0x000055a081df9f92 in pfs_spawn_thread (arg=0x55a084d0fe50) at /data/src/10.2/storage/perfschema/pfs.cc:1862
 
#14 0x00007ff4b1d98494 in start_thread (arg=0x7ff4aa39e700) at pthread_create.c:333
 
#15 0x00007ff4b017e93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

10.2 3fb6d25 RelWithDebInfo

 
#3  0x0000000000000000 in ?? ()
 
#4  0x000055aea6c44f60 in close_thread_tables (thd=thd@entry=0x7f6bc40009a8) at /data/src/10.2/sql/sql_base.cc:745
 
#5  0x000055aea6c45cb0 in Locked_tables_list::unlock_locked_tables (this=0x7f6bc4004240, thd=0x7f6bc40009a8) at /data/src/10.2/sql/sql_base.cc:2211
 
#6  0x000055aea6c8eedd in mysql_execute_command (thd=0x7f6bc40009a8) at /data/src/10.2/sql/sql_parse.cc:4877
 
#7  0x000055aea6c91e3a in mysql_parse (thd=0x7f6bc40009a8, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.2/sql/sql_parse.cc:8015
 
#8  0x000055aea6c959b4 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f6bc40009a8, packet=packet@entry=0x7f6bc4006ce9 "UNLOCK TABLES", packet_length=packet_length@entry=13, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:1826
 
#9  0x000055aea6c963e9 in do_command (thd=0x7f6bc40009a8) at /data/src/10.2/sql/sql_parse.cc:1379
 
#10 0x000055aea6d5fa14 in do_handle_one_connection (connect=connect@entry=0x55aea8f6a4c8) at /data/src/10.2/sql/sql_connect.cc:1335
 
#11 0x000055aea6d5fbb4 in handle_one_connection (arg=arg@entry=0x55aea8f6a4c8) at /data/src/10.2/sql/sql_connect.cc:1241
 
#12 0x000055aea7024664 in pfs_spawn_thread (arg=0x55aea8f322e8) at /data/src/10.2/storage/perfschema/pfs.cc:1862
 
#13 0x00007f6bdca92494 in start_thread (arg=0x7f6bd5096700) at pthread_create.c:333
 
#14 0x00007f6bdae7893f in clone () from /lib/x86_64-linux-gnu/libc.so.6

10.3 3b1b665 RelWithDebInfo

 
#2  <signal handler called>
 
#3  start_mutex_wait_v1 (state=0x7fb8b93cb530, mutex=0xffffffffffffffff, op=PSI_MUTEX_LOCK, src_file=0x55c91ab4ba98 "/data/src/10.3/storage/maria/ma_state.c", src_line=88) at /data/src/10.3/storage/perfschema/pfs.cc:2215
 
#4  0x000055c91a65f7f2 in inline_mysql_mutex_lock (src_file=0x55c91ab4ba98 "/data/src/10.3/storage/maria/ma_state.c", src_line=88, that=0x7fb8a8000ff8) at /data/src/10.3/include/mysql/psi/mysql_thread.h:690
 
#5  _ma_setup_live_state (info=0x7fb8a80aec28) at /data/src/10.3/storage/maria/ma_state.c:88
 
#6  0x000055c91a66f17a in ha_maria::implicit_commit (thd=thd@entry=0x7fb8a80009a8, new_trn=new_trn@entry=true) at /data/src/10.3/storage/maria/ha_maria.cc:2953
 
#7  0x000055c91a5107e7 in ha_commit_trans (thd=thd@entry=0x7fb8a80009a8, all=all@entry=true) at /data/src/10.3/sql/handler.cc:1361
 
#8  0x000055c91a423ecc in trans_commit_implicit (thd=0x7fb8a80009a8) at /data/src/10.3/sql/transaction.cc:376
 
#9  0x000055c91a33b91d in mysql_execute_command (thd=0x7fb8a80009a8) at /data/src/10.3/sql/sql_parse.cc:6406
 
#10 0x000055c91a342309 in mysql_parse (thd=0x7fb8a80009a8, rawbuf=<optimized out>, length=29, parser_state=0x7fb8b93cd630, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.3/sql/sql_parse.cc:8092
 
#11 0x000055c91a34565e in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fb8a80009a8, packet=packet@entry=0x7fb8a8009319 "ALTER TABLE t1 CHANGE b a INT", packet_length=packet_length@entry=29, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.3/sql/sql_parse.cc:1851
 
#12 0x000055c91a345d00 in do_command (thd=0x7fb8a80009a8) at /data/src/10.3/sql/sql_parse.cc:1396
 
#13 0x000055c91a417a84 in do_handle_one_connection (connect=connect@entry=0x55c91d2e5b18) at /data/src/10.3/sql/sql_connect.cc:1402
 
#14 0x000055c91a417c24 in handle_one_connection (arg=arg@entry=0x55c91d2e5b18) at /data/src/10.3/sql/sql_connect.cc:1308
 
#15 0x000055c91a6fad84 in pfs_spawn_thread (arg=0x55c91d356958) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#16 0x00007fb8c0eff494 in start_thread (arg=0x7fb8b93ce700) at pthread_create.c:333
 
#17 0x00007fb8bf2e593f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Couldn't reproduce on 10.1 and 10.4.

Slight variations in the test case make it start failing with MDEV-18088 instead.

 Comments   
Comment by Michael Widenius [ 2019-10-15 ]

Problem was in a combination of LOCK TABLES on several Aria
tables followed by an ALTER TABLE. After the ALTER TABLE there
was a force close + reopen of the alter table. The close failed
because the table was still part of a transaction.

Fixed by calling extra(HA_EXTRA_PREPARE_FOR_FORCED_CLOSE) as
part of closing the table, which ensures that the table is not
anymore part of the current transaction.

Comment by Ian Gilfillan [ 2019-10-28 ]

This has been pushed into the 10.2 and 10.3 trees already, so shouldn't the fix versions be 10.3.19 and 10.2.28?

Comment by Elena Stepanova [ 2019-10-28 ]

Right, I guess it was a typo. I've changed it now.

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