[MDEV-21502] Server hang or ASAN heap-use-after-free in maria_write upon INSERT after failed ALTER under lock Created: 2020-01-16  Updated: 2021-03-02  Resolved: 2021-03-02

Status: Closed
Project: MariaDB Server
Component/s: Locking, Storage Engine - Aria
Affects Version/s: 10.2, 10.3
Fix Version/s: 10.5.4, 10.2.33, 10.3.24, 10.4.14

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

Issue Links:
Relates
relates to MDEV-25038 Server crash or ASAN errors in _ma_re... Closed
relates to MDEV-21398 Deadlock (server hang) or assertion f... Closed

 Description    

CREATE TABLE t1 (a INT) ENGINE=Aria;
 
CREATE VIEW v1 AS SELECT * FROM t1;
 
LOCK TABLE t1 WRITE, v1 READ;
 
 
 
--error ER_ALTER_OPERATION_NOT_SUPPORTED_REASON
 
ALTER TABLE t1 CHANGE COLUMN a b INT, ALGORITHM=COPY, LOCK=NONE;
 
INSERT INTO t1 VALUES (1);
 
 
 
# Cleanup
 
UNLOCK TABLES;
 
DROP VIEW v1;
 
DROP TABLE t1;

10.3 ASAN d531b4ee

 
==9167==ERROR: AddressSanitizer: heap-use-after-free on address 0x61100000c8f0 at pc 0x55d180d7e98d bp 0x7f2d079a3e50 sp 0x7f2d079a3e48
 
READ of size 4 at 0x61100000c8f0 thread T5
 
    #0 0x55d180d7e98c in maria_write /data/src/10.3/storage/maria/ma_write.c:286
 
    #1 0x55d180c3ed7f in ha_maria::write_row(unsigned char*) /data/src/10.3/storage/maria/ha_maria.cc:1211
 
    #2 0x55d17ff2201f in handler::ha_write_row(unsigned char*) /data/src/10.3/sql/handler.cc:6447
 
    #3 0x55d17f773c05 in write_record(THD*, TABLE*, st_copy_info*) /data/src/10.3/sql/sql_insert.cc:2034
 
    #4 0x55d17f76c9ab in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool) /data/src/10.3/sql/sql_insert.cc:1072
 
    #5 0x55d17f807974 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:4455
 
    #6 0x55d17f81de4a in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:7818
 
    #7 0x55d17f7f8b9e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1856
 
    #8 0x55d17f7f5a7d in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1401
 
    #9 0x55d17fb6ba08 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #10 0x55d17fb6b3cf in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #11 0x55d180fd6629 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1862
 
    #12 0x7f2d137f84a3 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x74a3)
 
    #13 0x7f2d1192cd0e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe8d0e)
 
 
 
0x61100000c8f0 is located 176 bytes inside of 252-byte region [0x61100000c840,0x61100000c93c)
 
freed by thread T5 here:
 
    #0 0x7f2d13acfa10 in free (/usr/lib/x86_64-linux-gnu/libasan.so.3+0xc1a10)
 
    #1 0x55d1811072d0 in free_memory /data/src/10.3/mysys/safemalloc.c:279
 
    #2 0x55d1811069b9 in sf_free /data/src/10.3/mysys/safemalloc.c:197
 
    #3 0x55d1810d8b4b in my_free /data/src/10.3/mysys/my_malloc.c:223
 
    #4 0x55d180c15f8c in _ma_remove_table_from_trnman /data/src/10.3/storage/maria/ma_state.c:594
 
    #5 0x55d180cfcd26 in maria_extra /data/src/10.3/storage/maria/ma_extra.c:410
 
    #6 0x55d180c4a2e2 in ha_maria::extra(ha_extra_function) /data/src/10.3/storage/maria/ha_maria.cc:2547
 
    #7 0x55d17f6acbbe in Locked_tables_list::reopen_tables(THD*, bool) /data/src/10.3/sql/sql_base.cc:2497
 
    #8 0x55d17f812ffd in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:6061
 
    #9 0x55d17f81de4a in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:7818
 
    #10 0x55d17f7f8b9e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1856
 
    #11 0x55d17f7f5a7d in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1401
 
    #12 0x55d17fb6ba08 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #13 0x55d17fb6b3cf in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #14 0x55d180fd6629 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1862
 
    #15 0x7f2d137f84a3 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x74a3)
 
 
 
previously allocated by thread T5 here:
 
    #0 0x7f2d13acfd28 in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.3+0xc1d28)
 
    #1 0x55d1811063d1 in sf_malloc /data/src/10.3/mysys/safemalloc.c:118
 
    #2 0x55d1810d825a in my_malloc /data/src/10.3/mysys/my_malloc.c:101
 
    #3 0x55d180c128fd in _ma_setup_live_state /data/src/10.3/storage/maria/ma_state.c:81
 
    #4 0x55d180c4c3b9 in ha_maria::implicit_commit(THD*, bool) /data/src/10.3/storage/maria/ha_maria.cc:2893
 
    #5 0x55d17fefbe0c in ha_commit_trans(THD*, bool) /data/src/10.3/sql/handler.cc:1387
 
    #6 0x55d17fb9a200 in trans_commit_implicit(THD*) /data/src/10.3/sql/transaction.cc:361
 
    #7 0x55d17f803730 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:3669
 
    #8 0x55d17f81de4a in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:7818
 
    #9 0x55d17f7f8b9e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1856
 
    #10 0x55d17f7f5a7d in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1401
 
    #11 0x55d17fb6ba08 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #12 0x55d17fb6b3cf in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #13 0x55d180fd6629 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1862
 
    #14 0x7f2d137f84a3 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x74a3)
 
 
 
Thread T5 created by T0 here:
 
    #0 0x7f2d13a3ef59 in __interceptor_pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.3+0x30f59)
 
    #1 0x55d180fd6a65 in spawn_thread_v1 /data/src/10.3/storage/perfschema/pfs.cc:1912
 
    #2 0x55d17f562e80 in inline_mysql_thread_create /data/src/10.3/include/mysql/psi/mysql_thread.h:1268
 
    #3 0x55d17f57818c in create_thread_to_handle_connection(CONNECT*) /data/src/10.3/sql/mysqld.cc:6600
 
    #4 0x55d17f57886f in create_new_thread /data/src/10.3/sql/mysqld.cc:6670
 
    #5 0x55d17f579887 in handle_connections_sockets() /data/src/10.3/sql/mysqld.cc:6945
 
    #6 0x55d17f57765c in mysqld_main(int, char**) /data/src/10.3/sql/mysqld.cc:6222
 
    #7 0x55d17f56159f in main /data/src/10.3/sql/main.cc:25
 
    #8 0x7f2d118642e0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202e0)
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.3/storage/maria/ma_write.c:286 in maria_write
 
Shadow bytes around the buggy address:
 
  0x0c227fff98c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0c227fff98d0: 04 fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c227fff98e0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c227fff98f0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c227fff9900: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
 
=>0x0c227fff9910: fd fd fd fd fd fd fd fd fd fd fd fd fd fd[fd]fd
 
  0x0c227fff9920: fd fd fd fd fd fd fd fd fa fa fa fa fa fa fa fa
 
  0x0c227fff9930: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c227fff9940: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c227fff9950: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
 
  0x0c227fff9960: 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
 
  Container overflow:      fc
 
  Array cookie:            ac
 
  Intra object redzone:    bb
 
  ASan internal:           fe
 
  Left alloca redzone:     ca
 
  Right alloca redzone:    cb

Reproducible with 10.2, 10.3.
Couldn't reproduce with 10.1, 10.4.
No visible effect on a non-ASAN build; however, the variation below makes the server hang on non-debug builds as well:

CREATE TABLE t1 (a INT) ENGINE=Aria;
 
LOCK TABLE t1 WRITE, t1 t1a READ;
 
 
 
SET lock_wait_timeout= 1;
 
 
 
--error ER_ALTER_OPERATION_NOT_SUPPORTED_REASON
 
ALTER TABLE t1 CHANGE COLUMN a b INT, ALGORITHM=COPY, LOCK=NONE;
 
INSERT INTO t1 VALUES (1);
 
 
 
# Cleanup
 
UNLOCK TABLES;
 
DROP TABLE t1;

Stack trace from the running (hanging) server:

10.3 debug d531b4ee

 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x000055d922966014 in safe_cond_timedwait (cond=0x7fcda80008c8, mp=0x7fcda8097710, abstime=0x7fcdb94579f0, file=0x55d922da6590 "/data/src/10.3/include/mysql/psi/mysql_thread.h", line=1204) at /data/src/10.3/mysys/thr_mutex.c:546
 
#2  0x000055d922962512 in inline_mysql_cond_timedwait (that=0x7fcda80008c8, mutex=0x7fcda8097710, abstime=0x7fcdb94579f0, src_file=0x55d922da65c0 "/data/src/10.3/mysys/thr_lock.c", src_line=576) at /data/src/10.3/include/mysql/psi/mysql_thread.h:1204
 
#3  0x000055d922962c0b in wait_for_lock (wait=0x7fcda80977e0, data=0x7fcda807e818, in_wait_list=0 '\000', lock_wait_timeout=31536000) at /data/src/10.3/mysys/thr_lock.c:576
 
#4  0x000055d922963764 in thr_lock (data=0x7fcda807e818, owner=0x7fcda8002600, lock_wait_timeout=31536000) at /data/src/10.3/mysys/thr_lock.c:1014
 
#5  0x000055d922964053 in thr_multi_lock (data=0x7fcda804a5a8, count=1, owner=0x7fcda8002600, lock_wait_timeout=31536000) at /data/src/10.3/mysys/thr_lock.c:1295
 
#6  0x000055d922220677 in mysql_lock_tables (thd=0x7fcda8000af0, sql_lock=0x7fcda804a580, flags=18539) at /data/src/10.3/sql/lock.cc:347
 
#7  0x000055d922220479 in mysql_lock_tables (thd=0x7fcda8000af0, tables=0x7fcda8045018, count=1, flags=18539) at /data/src/10.3/sql/lock.cc:299
 
#8  0x000055d921d3a468 in Locked_tables_list::reopen_tables (this=0x7fcda8004800, thd=0x7fcda8000af0, need_reopen=true) at /data/src/10.3/sql/sql_base.cc:2538
 
#9  0x000055d921dd8897 in mysql_execute_command (thd=0x7fcda8000af0) at /data/src/10.3/sql/sql_parse.cc:6061
 
#10 0x000055d921dddb73 in mysql_parse (thd=0x7fcda8000af0, rawbuf=0x7fcda8012818 "ALTER TABLE t1 CHANGE COLUMN a b INT, ALGORITHM=COPY, LOCK=NONE", length=63, parser_state=0x7fcdb94585e0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7818
 
#11 0x000055d921dca6e7 in dispatch_command (command=COM_QUERY, thd=0x7fcda8000af0, packet=0x7fcda8008c71 "ALTER TABLE t1 CHANGE COLUMN a b INT, ALGORITHM=COPY, LOCK=NONE", packet_length=63, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1856
 
#12 0x000055d921dc902f in do_command (thd=0x7fcda8000af0) at /data/src/10.3/sql/sql_parse.cc:1401
 
#13 0x000055d921f4098e in do_handle_one_connection (connect=0x55d924eedc90) at /data/src/10.3/sql/sql_connect.cc:1403
 
#14 0x000055d921f406f0 in handle_one_connection (arg=0x55d924eedc90) at /data/src/10.3/sql/sql_connect.cc:1308
 
#15 0x000055d9228eff52 in pfs_spawn_thread (arg=0x55d924f08d40) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#16 0x00007fcdc11e24a4 in start_thread (arg=0x7fcdb9459700) at pthread_create.c:456
 
#17 0x00007fcdbf316d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97



 Comments   
Comment by Elena Stepanova [ 2021-03-02 ]

The failure stopped happening after this commit in 10.2:

commit be647ff14d6196af825f05020acee8f18af4773d
 
Author: Monty
 
Date:   Fri May 22 18:02:24 2020 +0300
 
 
 
    Fixed deadlock with LOCK TABLES and ALTER TABLE
 
    
    MDEV-21398 Deadlock (server hang) or assertion failure in

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