[MDEV-30014] heap-use-after-free in ha_spider::lock_tables(), highly sporadic SIGSEGV in intern_close_table Created: 2022-11-15  Updated: 2023-11-28  Resolved: 2023-11-17

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - Spider
Affects Version/s: 10.4, 10.5, 10.6, 10.9, 10.10, 10.11, 11.0, 11.1
Fix Version/s: 10.4.33, 10.5.24, 10.6.17, 10.11.7, 11.0.5, 11.1.4, 11.2.3

Type: Bug Priority: Critical
Reporter: Roel Van de Paar Assignee: Yuchen Pei
Resolution: Fixed Votes: 0
Labels: ASAN, locking, memory_corruption

Issue Links:
Blocks
blocks MDEV-29456 Spider hangs in 'Waiting for table me... Closed
blocks MDEV-29667 Server hangs on DROP DATABASE after f... Closed
blocks MDEV-30049 Thread hang in 'Waiting for table met... Closed
PartOf
includes MDEV-29456 Spider hangs in 'Waiting for table me... Closed
includes MDEV-29667 Server hangs on DROP DATABASE after f... Closed
includes MDEV-30049 Thread hang in 'Waiting for table met... Closed
Problem/Incident
causes MDEV-32849 Spider tests failing in asan/valgrind... Closed
Relates
relates to MDEV-29484 Assertion `!trx_free || !trx->locked_... Closed
relates to MDEV-28352 Spider: heap-use-after-free in ha_spi... Closed

 Description   

The following testcase - whilst having been succesfully reduced for the stack displayed below it - is hard to reproduce 'manually', as the bug looks to be highly sporadic. Instead, I executed the testcase under an ASAN-only debug build which immediately results in a heap-use-after-free in ha_spider::lock_tables, which looks similar to MDEV-28352. The fix for that bug is already included (trunk build as of today), so it is possible that this testcase highlights one possible codepath not covered in the MDEV-28352 fix.

# mysqld options used (not all required):  --max_allowed_packet=33554432 --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode= 
INSTALL PLUGIN spider SONAME 'ha_spider.so';
 
CREATE USER spider@localhost IDENTIFIED BY 'PWD123';
 
CREATE server srv FOREIGN DATA wrapper mysql options (socket '../socket.sock', DATABASE 'test', USER 'spider', PASSWORD 'PWD123');
 
CREATE TABLE t (c INT PRIMARY KEY,c1 BLOB, c2 TEXT) ENGINE=InnoDB;
 
CREATE TABLE t1(col1 CHAR (255), col2 CHAR (255), col3 CHAR(255),col4 CHAR(255), col5 CHAR(255), col6 CHAR(255), col7 CHAR(255), col8 CHAR(255), col9 CHAR(255),col10 CHAR(255), col11 CHAR(255), col12 CHAR(255), col13 CHAR(255),col14 CHAR(255),col15 CHAR(255),col16 CHAR(255), col17 CHAR(255), col18 CHAR(255),col19 CHAR(255),col20 CHAR(255),col21 CHAR(255),col22 CHAR(255), col23 CHAR(255), col24 CHAR(255),col25 CHAR(255),col26 CHAR(255),col27 CHAR(255),col28 CHAR(255), col29 CHAR(255), col30 CHAR(255),col31 CHAR(255),col32 CHAR(255),col33 CHAR(255),col34 CHAR(255), col35 CHAR(255), col36 CHAR(255),col37 CHAR(255),col38 CHAR(255),col39 CHAR(255),col40 CHAR(255), col41 CHAR(255), col42 CHAR(255),col43 CHAR(255),col44 CHAR(255),col45 CHAR(255),col46 CHAR(255), col47 CHAR(255), col48 CHAR(255),col49 CHAR(255),col50 CHAR(255),col51 CHAR(255),col52 CHAR(255), col53 CHAR(255), col54 CHAR(255),col55 CHAR(255),col56 CHAR(255),col57 CHAR(255),col58 CHAR(255), col59 CHAR(255), col60 CHAR(255),col61 CHAR(255),col62 CHAR(255),col63 CHAR(255),col64 CHAR(255), col65 CHAR(255)) ENGINE=Spider COMMENT='WRAPPER "mysql", srv "srv", TABLE "t"' COMMENT='WRAPPER "mysql", srv "srv", TABLE "t"' ROW_FORMAT= COMPACT;
 
SELECT HEX(c1+0),HEX(c2+1),HEX(c3+2) FROM t1 ;
 
LOCK TABLES t1 WRITE CONCURRENT, t1 AS t2 READ;
 
UNLOCK TABLES;
 
DROP TABLE IF EXISTS t1;

Leads to:

10.11.1 d186cb180e424fb4e166959145b3bccb5e7f5164 (Debug, ASAN)

 
==3079971==ERROR: AddressSanitizer: heap-use-after-free on address 0x61f00004b5ec at pc 0x147364428ed9 bp 0x147364645aa0 sp 0x147364645a90
 
READ of size 4 at 0x61f00004b5ec thread T14
 
    #0 0x147364428ed8 in ha_spider::lock_tables() /test/10.11_dbg_san/storage/spider/ha_spider.cc:12182
 
    #1 0x1473644295c9 in ha_spider::external_lock(THD*, int) /test/10.11_dbg_san/storage/spider/ha_spider.cc:921
 
    #2 0x55957b0152b6 in handler::ha_external_lock(THD*, int) /test/10.11_dbg_san/sql/handler.cc:7076
 
    #3 0x55957b4e2da0 in handler::ha_external_unlock(THD*) /test/10.11_dbg_san/sql/handler.h:3448
 
    #4 0x55957b4e2da0 in unlock_external /test/10.11_dbg_san/sql/lock.cc:744
 
    #5 0x55957b4e33b9 in mysql_unlock_tables(THD*, st_mysql_lock*, bool) /test/10.11_dbg_san/sql/lock.cc:435
 
    #6 0x55957b4e4180 in mysql_unlock_tables(THD*, st_mysql_lock*) /test/10.11_dbg_san/sql/lock.cc:418
 
    #7 0x55957a4e3a77 in close_thread_tables(THD*) /test/10.11_dbg_san/sql/sql_base.cc:953
 
    #8 0x55957a4e6d7d in Locked_tables_list::unlock_locked_tables(THD*) /test/10.11_dbg_san/sql/sql_base.cc:2568
 
    #9 0x55957a6b75e8 in mysql_execute_command(THD*, bool) /test/10.11_dbg_san/sql/sql_parse.cc:5066
 
    #10 0x55957a674671 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/10.11_dbg_san/sql/sql_parse.cc:7998
 
    #11 0x55957a6a1d6e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/10.11_dbg_san/sql/sql_parse.cc:1894
 
    #12 0x55957a6a8969 in do_command(THD*, bool) /test/10.11_dbg_san/sql/sql_parse.cc:1407
 
    #13 0x55957ab545b0 in do_handle_one_connection(CONNECT*, bool) /test/10.11_dbg_san/sql/sql_connect.cc:1416
 
    #14 0x55957ab550b3 in handle_one_connection /test/10.11_dbg_san/sql/sql_connect.cc:1318
 
    #15 0x147385da0608 in start_thread /build/glibc-SzIz7B/glibc-2.31/nptl/pthread_create.c:477
 
    #16 0x147385982132 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x11f132)
 
 
 
0x61f00004b5ec is located 364 bytes inside of 3200-byte region [0x61f00004b480,0x61f00004c100)
 
freed by thread T14 here:
 
    #0 0x55957a29ed2f in __interceptor_free (/test/ASAN_SPIDER_MD151122-mariadb-10.11.1-linux-x86_64-dbg/bin/mariadbd+0xd57d2f)
 
    #1 0x55957c497541 in my_free /test/10.11_dbg_san/mysys/my_malloc.c:211
 
    #2 0x1473643cccff in spider_free_mem(st_spider_transaction*, void*, unsigned long) /test/10.11_dbg_san/storage/spider/spd_malloc.cc:183
 
    #3 0x14736433716a in spider_free_conn(st_spider_conn*) /test/10.11_dbg_san/storage/spider/spd_conn.cc:857
 
    #4 0x1473643479f1 in spider_free_conn_from_trx(st_spider_transaction*, st_spider_conn*, bool, bool, int*) /test/10.11_dbg_san/storage/spider/spd_conn.cc:373
 
    #5 0x1473642c4688 in spider_free_trx_conn(st_spider_transaction*, bool) /test/10.11_dbg_san/storage/spider/spd_trx.cc:114
 
    #6 0x1473642d0ad6 in spider_rollback(handlerton*, THD*, bool) /test/10.11_dbg_san/storage/spider/spd_trx.cc:3276
 
    #7 0x55957aff505d in ha_rollback_trans(THD*, bool) /test/10.11_dbg_san/sql/handler.cc:2179
 
    #8 0x55957ab95ac9 in trans_rollback_stmt(THD*) /test/10.11_dbg_san/sql/transaction.cc:535
 
    #9 0x55957a6bdb24 in mysql_execute_command(THD*, bool) /test/10.11_dbg_san/sql/sql_parse.cc:6052
 
    #10 0x55957a674671 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/10.11_dbg_san/sql/sql_parse.cc:7998
 
    #11 0x55957a6a1d6e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/10.11_dbg_san/sql/sql_parse.cc:1894
 
    #12 0x55957a6a8969 in do_command(THD*, bool) /test/10.11_dbg_san/sql/sql_parse.cc:1407
 
    #13 0x55957ab545b0 in do_handle_one_connection(CONNECT*, bool) /test/10.11_dbg_san/sql/sql_connect.cc:1416
 
    #14 0x55957ab550b3 in handle_one_connection /test/10.11_dbg_san/sql/sql_connect.cc:1318
 
    #15 0x147385da0608 in start_thread /build/glibc-SzIz7B/glibc-2.31/nptl/pthread_create.c:477
 
 
 
previously allocated by thread T14 here:
 
    #0 0x55957a29f128 in __interceptor_malloc (/test/ASAN_SPIDER_MD151122-mariadb-10.11.1-linux-x86_64-dbg/bin/mariadbd+0xd58128)
 
    #1 0x55957c497301 in my_malloc /test/10.11_dbg_san/mysys/my_malloc.c:90
 
    #2 0x1473643cd075 in spider_bulk_alloc_mem(st_spider_transaction*, unsigned int, char const*, char const*, unsigned long, unsigned long, ...) /test/10.11_dbg_san/storage/spider/spd_malloc.cc:231
 
    #3 0x147364341e24 in spider_create_conn(st_spider_share*, ha_spider*, int, int, unsigned int, int*) /test/10.11_dbg_san/storage/spider/spd_conn.cc:414
 
    #4 0x147364346582 in spider_get_conn(st_spider_share*, int, char*, st_spider_transaction*, ha_spider*, bool, bool, unsigned int, int*) /test/10.11_dbg_san/storage/spider/spd_conn.cc:764
 
    #5 0x14736439bf00 in spider_get_share(char const*, TABLE*, THD*, ha_spider*, int*) /test/10.11_dbg_san/storage/spider/spd_table.cc:4931
 
    #6 0x147364415a79 in ha_spider::open(char const*, int, unsigned int) /test/10.11_dbg_san/storage/spider/ha_spider.cc:313
 
    #7 0x55957aff953e in handler::ha_open(TABLE*, char const*, int, unsigned int, st_mem_root*, List<String>*) /test/10.11_dbg_san/sql/handler.cc:3331
 
    #8 0x55957aa84332 in open_table_from_share(THD*, TABLE_SHARE*, st_mysql_const_lex_string const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, List<String>*) /test/10.11_dbg_san/sql/table.cc:4434
 
    #9 0x55957a4ec26e in open_table(THD*, TABLE_LIST*, Open_table_context*) /test/10.11_dbg_san/sql/sql_base.cc:2178
 
    #10 0x55957a4f8f64 in open_and_process_table /test/10.11_dbg_san/sql/sql_base.cc:4108
 
    #11 0x55957a4f8f64 in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /test/10.11_dbg_san/sql/sql_base.cc:4595
 
    #12 0x55957a4fbbf7 in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /test/10.11_dbg_san/sql/sql_base.cc:5569
 
    #13 0x55957a686892 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /test/10.11_dbg_san/sql/sql_base.h:510
 
    #14 0x55957a686892 in execute_sqlcom_select /test/10.11_dbg_san/sql/sql_parse.cc:6183
 
    #15 0x55957a6af21a in mysql_execute_command(THD*, bool) /test/10.11_dbg_san/sql/sql_parse.cc:3947
 
    #16 0x55957a674671 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/10.11_dbg_san/sql/sql_parse.cc:7998
 
    #17 0x55957a6a1d6e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/10.11_dbg_san/sql/sql_parse.cc:1894
 
    #18 0x55957a6a8969 in do_command(THD*, bool) /test/10.11_dbg_san/sql/sql_parse.cc:1407
 
    #19 0x55957ab545b0 in do_handle_one_connection(CONNECT*, bool) /test/10.11_dbg_san/sql/sql_connect.cc:1416
 
    #20 0x55957ab550b3 in handle_one_connection /test/10.11_dbg_san/sql/sql_connect.cc:1318
 
    #21 0x147385da0608 in start_thread /build/glibc-SzIz7B/glibc-2.31/nptl/pthread_create.c:477
 
 
 
Thread T14 created by T0 here:
 
    #0 0x55957a1cc165 in pthread_create (/test/ASAN_SPIDER_MD151122-mariadb-10.11.1-linux-x86_64-dbg/bin/mariadbd+0xc85165)
 
    #1 0x55957a2eb54b in create_thread_to_handle_connection(CONNECT*) /test/10.11_dbg_san/sql/mysqld.cc:6102
 
    #2 0x55957a2f3838 in create_new_thread(CONNECT*) /test/10.11_dbg_san/sql/mysqld.cc:6161
 
    #3 0x55957a2f3d0d in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /test/10.11_dbg_san/sql/mysqld.cc:6223
 
    #4 0x55957a2f4d39 in handle_connections_sockets() /test/10.11_dbg_san/sql/mysqld.cc:6347
 
    #5 0x55957a2faa94 in mysqld_main(int, char**) /test/10.11_dbg_san/sql/mysqld.cc:5997
 
    #6 0x55957a2e06ea in main /test/10.11_dbg_san/sql/main.cc:34
 
    #7 0x147385887082 in __libc_start_main ../csu/libc-start.c:308
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /test/10.11_dbg_san/storage/spider/ha_spider.cc:12182 in ha_spider::lock_tables()
 
Shadow bytes around the buggy address:
 
  0x0c3e80001660: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c3e80001670: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c3e80001680: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c3e80001690: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3e800016a0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c3e800016b0: fd fd fd fd fd fd fd fd fd fd fd fd fd[fd]fd fd
 
  0x0c3e800016c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3e800016d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3e800016e0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3e800016f0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3e80001700: 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
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  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
 
  Shadow gap:              cc
 
==3079971==ABORTING

When the crash happens (hard to reproduce as indicated above), this is the stack:

10.11.1 50c5743adc87e1cdec1431a02558f6540fe5a6d5 (Optimized)

 
Core was generated by `/test/MD221022-mariadb-10.11.1-linux-x86_64-opt/bin/mysqld --no-defaults --max_'.
 
Program terminated with signal SIGSEGV, Segmentation fault.
 
#0  closefrm (table=table@entry=0x147c2425c478)
 
    at /test/10.11_opt/sql/table.cc:4563
 
[Current thread is 1 (Thread 0x147c99605700 (LWP 3520279))]
 
(gdb) bt
 
#0  closefrm (table=table@entry=0x147c2425c478) at /test/10.11_opt/sql/table.cc:4563
 
#1  0x0000559d053d1e25 in intern_close_table (table=0x147c2425c478) at /test/10.11_opt/sql/table_cache.cc:225
 
#2  TDC_element::flush_unused (this=0x147c242351e8, mark_flushed=mark_flushed@entry=true) at /test/10.11_opt/sql/table_cache.cc:1298
 
#3  0x0000559d053d1e73 in tdc_remove_referenced_share (thd=thd@entry=0x147c24000c58, share=0x147c241aaca0) at /test/10.11_opt/sql/table_cache.cc:1009
 
#4  0x0000559d053d1fdc in tdc_remove_table (thd=thd@entry=0x147c24000c58, db=<optimized out>, table_name=<optimized out>) at /test/10.11_opt/sql/table_cache.cc:1067
 
#5  0x0000559d052b277e in mysql_rm_table_no_locks (thd=0x147c24000c58, tables=<optimized out>, current_db=<optimized out>, ddl_log_state=<optimized out>, if_exists=<optimized out>, drop_temporary=<optimized out>, drop_view=<optimized out>, drop_sequence=<optimized out>, dont_log_query=<optimized out>, dont_free_locks=<optimized out>) at /test/10.11_opt/sql/sql_table.cc:1653
 
#6  0x0000559d052b316e in mysql_rm_table (thd=thd@entry=0x147c24000c58, tables=tables@entry=0x147c24012ee0, if_exists=<optimized out>, drop_temporary=<optimized out>, drop_sequence=<optimized out>, dont_log_query=dont_log_query@entry=false) at /test/10.11_opt/sql/sql_table.cc:1187
 
#7  0x0000559d0521040d in mysql_execute_command (thd=0x147c24000c58, is_called_from_prepared_stmt=<optimized out>) at /test/10.11_opt/sql/structs.h:569
 
#8  0x0000559d05200335 in mysql_parse (rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, thd=0x147c24000c58) at /test/10.11_opt/sql/sql_parse.cc:8023
 
#9  mysql_parse (thd=0x147c24000c58, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /test/10.11_opt/sql/sql_parse.cc:7945
 
#10 0x0000559d0520c0ea in dispatch_command (command=COM_QUERY, thd=0x147c24000c58, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /test/10.11_opt/sql/sql_class.h:1346
 
#11 0x0000559d0520dee2 in do_command (thd=0x147c24000c58, blocking=blocking@entry=true) at /test/10.11_opt/sql/sql_parse.cc:1407
 
#12 0x0000559d05327fbf in do_handle_one_connection (connect=<optimized out>, connect@entry=0x559d088d2638, put_in_cache=put_in_cache@entry=true) at /test/10.11_opt/sql/sql_connect.cc:1416
 
#13 0x0000559d0532829d in handle_one_connection (arg=0x559d088d2638) at /test/10.11_opt/sql/sql_connect.cc:1318
 
#14 0x0000147ccc757609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#15 0x0000147ccc343133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95



 Comments   
Comment by Roel Van de Paar [ 2023-06-08 ]

I found a simpler testcase. which deterministically reproduces the ASAN heap-use-after-free) issue:

INSTALL PLUGIN Spider SONAME 'ha_spider.so';
 
CREATE SERVER srv FOREIGN DATA WRAPPER MYSQL OPTIONS (SOCKET '../socket.sock',DATABASE'',USER'',PASSWORD'');
 
CREATE TABLE t1 (c INT KEY) ENGINE=InnoDB;
 
CREATE TABLE t2 (c INT KEY) ENGINE=Spider COMMENT='WRAPPER "mysql",srv "srv",TABLE "t1"';
 
CREATE TABLE t3 (c INT KEY) ENGINE=Spider;
 
LOCK TABLE t2 WRITE,t3 WRITE;
 
CREATE TABLE t4 (c INT) ENGINE=Spider;
 
FLUSH NO_WRITE_TO_BINLOG TABLES t4 WITH READ LOCK;
 
UNLOCK TABLES;

Leads to:

11.0.2 368dd22a816f3b437bccd0b9ff28b9de9b1abf0a (Debug)

 
==3956704==ERROR: AddressSanitizer: heap-use-after-free on address 0x61f0000429e4 at pc 0x1481fe333d03 bp 0x1481fed492e0 sp 0x1481fed492d0
 
READ of size 4 at 0x61f0000429e4 thread T21
 
    #0 0x1481fe333d02 in ha_spider::lock_tables() /test/11.0_dbg_san/storage/spider/ha_spider.cc:12124
 
    #1 0x1481fe3369a7 in ha_spider::external_lock(THD*, int) /test/11.0_dbg_san/storage/spider/ha_spider.cc:905
 
    #2 0x557a92cb3c2e in handler::ha_external_lock(THD*, int) /test/11.0_dbg_san/sql/handler.cc:7302
 
    #3 0x557a93aa9f16 in handler::ha_external_unlock(THD*) /test/11.0_dbg_san/sql/handler.h:3477
 
    #4 0x557a93aa9f16 in unlock_external /test/11.0_dbg_san/sql/lock.cc:744
 
    #5 0x557a93aaae49 in mysql_unlock_tables(THD*, st_mysql_lock*, bool) /test/11.0_dbg_san/sql/lock.cc:435
 
    #6 0x557a93aad39a in mysql_unlock_tables(THD*, st_mysql_lock*) /test/11.0_dbg_san/sql/lock.cc:418
 
    #7 0x557a910f3da2 in close_thread_tables(THD*) /test/11.0_dbg_san/sql/sql_base.cc:953
 
    #8 0x557a910fa71e in Locked_tables_list::unlock_locked_tables(THD*) /test/11.0_dbg_san/sql/sql_base.cc:2568
 
    #9 0x557a915629a6 in mysql_execute_command(THD*, bool) /test/11.0_dbg_san/sql/sql_parse.cc:5082
 
    #10 0x557a9157b973 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/11.0_dbg_san/sql/sql_parse.cc:8014
 
    #11 0x557a9158b707 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/11.0_dbg_san/sql/sql_parse.cc:1894
 
    #12 0x557a91599542 in do_command(THD*, bool) /test/11.0_dbg_san/sql/sql_parse.cc:1407
 
    #13 0x557a91f6e8b5 in do_handle_one_connection(CONNECT*, bool) /test/11.0_dbg_san/sql/sql_connect.cc:1416
 
    #14 0x557a91f6fdd0 in handle_one_connection /test/11.0_dbg_san/sql/sql_connect.cc:1318
 
    #15 0x148222094b42 in start_thread nptl/pthread_create.c:442
 
    #16 0x1482221269ff  (/lib/x86_64-linux-gnu/libc.so.6+0x1269ff)
 
 
 
0x61f0000429e4 is located 356 bytes inside of 3200-byte region [0x61f000042880,0x61f000043500)
 
freed by thread T21 here:
 
    #0 0x557a90bfffe7 in __interceptor_free (/test/UBASAN_MD120523-mariadb-11.0.2-linux-x86_64-dbg/bin/mariadbd+0x7963fe7)
 
    #1 0x557a95317a61 in my_free /test/11.0_dbg_san/mysys/my_malloc.c:213
 
    #2 0x1481fe252150 in spider_free_mem(st_spider_transaction*, void*, unsigned long) /test/11.0_dbg_san/storage/spider/spd_malloc.cc:183
 
    #3 0x1481fe16464b in spider_free_conn(st_spider_conn*) /test/11.0_dbg_san/storage/spider/spd_conn.cc:860
 
    #4 0x1481fe1830d5 in spider_free_conn_from_trx(st_spider_transaction*, st_spider_conn*, bool, bool, int*) /test/11.0_dbg_san/storage/spider/spd_conn.cc:372
 
    #5 0x1481fe0764da in spider_free_trx_conn(st_spider_transaction*, bool) /test/11.0_dbg_san/storage/spider/spd_trx.cc:114
 
    #6 0x1481fe08e073 in spider_commit(handlerton*, THD*, bool) /test/11.0_dbg_san/storage/spider/spd_trx.cc:3236
 
    #7 0x557a92c60d21 in commit_one_phase_2 /test/11.0_dbg_san/sql/handler.cc:2138
 
    #8 0x557a92c617f1 in ha_commit_one_phase(THD*, bool) /test/11.0_dbg_san/sql/handler.cc:2091
 
    #9 0x557a92cda31e in ha_commit_trans(THD*, bool) /test/11.0_dbg_san/sql/handler.cc:1885
 
    #10 0x557a920045ec in trans_commit_stmt(THD*) /test/11.0_dbg_san/sql/transaction.cc:472
 
    #11 0x557a9157422c in mysql_execute_command(THD*, bool) /test/11.0_dbg_san/sql/sql_parse.cc:6075
 
    #12 0x557a9157b973 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/11.0_dbg_san/sql/sql_parse.cc:8014
 
    #13 0x557a9158b707 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/11.0_dbg_san/sql/sql_parse.cc:1894
 
    #14 0x557a91599542 in do_command(THD*, bool) /test/11.0_dbg_san/sql/sql_parse.cc:1407
 
    #15 0x557a91f6e8b5 in do_handle_one_connection(CONNECT*, bool) /test/11.0_dbg_san/sql/sql_connect.cc:1416
 
    #16 0x557a91f6fdd0 in handle_one_connection /test/11.0_dbg_san/sql/sql_connect.cc:1318
 
    #17 0x148222094b42 in start_thread nptl/pthread_create.c:442
 
 
 
previously allocated by thread T21 here:
 
    #0 0x557a90c00337 in __interceptor_malloc (/test/UBASAN_MD120523-mariadb-11.0.2-linux-x86_64-dbg/bin/mariadbd+0x7964337)
 
    #1 0x557a95317703 in my_malloc /test/11.0_dbg_san/mysys/my_malloc.c:91
 
    #2 0x1481fe252583 in spider_bulk_alloc_mem(st_spider_transaction*, unsigned int, char const*, char const*, unsigned long, unsigned long, ...) /test/11.0_dbg_san/storage/spider/spd_malloc.cc:231
 
    #3 0x1481fe17840c in spider_create_conn(st_spider_share*, ha_spider*, int, int, int*) /test/11.0_dbg_san/storage/spider/spd_conn.cc:412
 
    #4 0x1481fe17f18a in spider_get_conn(st_spider_share*, int, char*, st_spider_transaction*, ha_spider*, bool, bool, int*) /test/11.0_dbg_san/storage/spider/spd_conn.cc:767
 
    #5 0x1481fe1977cf in spider_share_get_conns(ha_spider*, st_spider_share*, int*) /test/11.0_dbg_san/storage/spider/spd_table.cc:4868
 
    #6 0x1481fe20505c in spider_init_share(char const*, TABLE*, THD*, ha_spider*, int*, st_spider_share*, TABLE_SHARE*, bool) /test/11.0_dbg_san/storage/spider/spd_table.cc:5138
 
    #7 0x1481fe206475 in spider_get_share(char const*, TABLE*, THD*, ha_spider*, int*) /test/11.0_dbg_san/storage/spider/spd_table.cc:5252
 
    #8 0x1481fe305021 in ha_spider::open(char const*, int, unsigned int) /test/11.0_dbg_san/storage/spider/ha_spider.cc:312
 
    #9 0x557a92c6c235 in handler::ha_open(TABLE*, char const*, int, unsigned int, st_mem_root*, List<String>*) /test/11.0_dbg_san/sql/handler.cc:3487
 
    #10 0x557a91db5885 in open_table_from_share(THD*, TABLE_SHARE*, st_mysql_const_lex_string const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, List<String>*) /test/11.0_dbg_san/sql/table.cc:4540
 
    #11 0x557a911043e3 in open_table(THD*, TABLE_LIST*, Open_table_context*) /test/11.0_dbg_san/sql/sql_base.cc:2178
 
    #12 0x557a9111bf14 in open_and_process_table /test/11.0_dbg_san/sql/sql_base.cc:4108
 
    #13 0x557a9111bf14 in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /test/11.0_dbg_san/sql/sql_base.cc:4595
 
    #14 0x557a91122dbe in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /test/11.0_dbg_san/sql/sql_base.cc:5570
 
    #15 0x557a920ab64f in open_and_lock_tables /test/11.0_dbg_san/sql/sql_base.h:279
 
    #16 0x557a920ab64f in flush_tables_with_read_lock(THD*, TABLE_LIST*) /test/11.0_dbg_san/sql/sql_reload.cc:590
 
    #17 0x557a9156836a in mysql_execute_command(THD*, bool) /test/11.0_dbg_san/sql/sql_parse.cc:5430
 
    #18 0x557a9157b973 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/11.0_dbg_san/sql/sql_parse.cc:8014
 
    #19 0x557a9158b707 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/11.0_dbg_san/sql/sql_parse.cc:1894
 
    #20 0x557a91599542 in do_command(THD*, bool) /test/11.0_dbg_san/sql/sql_parse.cc:1407
 
    #21 0x557a91f6e8b5 in do_handle_one_connection(CONNECT*, bool) /test/11.0_dbg_san/sql/sql_connect.cc:1416
 
    #22 0x557a91f6fdd0 in handle_one_connection /test/11.0_dbg_san/sql/sql_connect.cc:1318
 
    #23 0x148222094b42 in start_thread nptl/pthread_create.c:442
 
 
 
Thread T21 created by T0 here:
 
    #0 0x557a90ba4175 in pthread_create (/test/UBASAN_MD120523-mariadb-11.0.2-linux-x86_64-dbg/bin/mariadbd+0x7908175)
 
    #1 0x557a90c5a98b in create_thread_to_handle_connection(CONNECT*) /test/11.0_dbg_san/sql/mysqld.cc:6129
 
    #2 0x557a90c67e67 in create_new_thread(CONNECT*) /test/11.0_dbg_san/sql/mysqld.cc:6191
 
    #3 0x557a90c686e7 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /test/11.0_dbg_san/sql/mysqld.cc:6253
 
    #4 0x557a90c69738 in handle_connections_sockets() /test/11.0_dbg_san/sql/mysqld.cc:6377
 
    #5 0x557a90c70ee7 in mysqld_main(int, char**) /test/11.0_dbg_san/sql/mysqld.cc:6024
 
    #6 0x557a90c45eca in main /test/11.0_dbg_san/sql/main.cc:34
 
    #7 0x148222029d8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /test/11.0_dbg_san/storage/spider/ha_spider.cc:12124 in ha_spider::lock_tables()
 
Shadow bytes around the buggy address:
 
  0x0c3e800004e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c3e800004f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c3e80000500: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c3e80000510: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3e80000520: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c3e80000530: fd fd fd fd fd fd fd fd fd fd fd fd[fd]fd fd fd
 
  0x0c3e80000540: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3e80000550: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3e80000560: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3e80000570: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3e80000580: 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
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  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
 
  Shadow gap:              cc
 
==3956704==ABORTING

Setup:

Compiled with GCC >=7.5.0 (I use GCC 11.3.0) and:
 
    -DWITH_ASAN=ON -DWITH_ASAN_SCOPE=ON -DWITH_UBSAN=ON -DWITH_RAPID=OFF -DWSREP_LIB_WITH_ASAN=ON
 
Set before execution:
 
    export ASAN_OPTIONS=quarantine_size_mb=512:atexit=0:detect_invalid_pointer_pairs=3:dump_instruction_bytes=1:abort_on_error=1:allocator_may_return_null=1

Bug confirmed present in:
MariaDB: 10.5.21 (dbg), 10.5.21 (opt), 10.6.14 (dbg), 10.6.14 (opt), 10.9.7 (dbg), 10.9.7 (opt), 10.10.5 (dbg), 10.10.5 (opt), 10.11.4 (dbg), 10.11.4 (opt), 11.0.2 (dbg), 11.0.2 (opt), 11.1.0 (dbg), 11.1.0 (opt)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.4.30 (dbg), 10.4.30 (opt)

Comment by Roel Van de Paar [ 2023-06-08 ]

MTR Testcase:

IF (`SELECT NOT(COUNT(*)) FROM information_schema.system_variables WHERE variable_name='have_sanitizer' AND global_value like "%ASAN%"`)
 
{
 
--skip test needs to be run with ASAN
 
}
 
--source include/have_innodb.inc
 
--let $SOCKET= `SELECT @@global.socket`
 
INSTALL PLUGIN Spider SONAME 'ha_spider.so';
 
CREATE USER spider@localhost IDENTIFIED BY 'pwd';
 
GRANT ALL ON test.* TO spider@localhost;
 
eval CREATE SERVER s FOREIGN DATA WRAPPER MYSQL OPTIONS (SOCKET "$SOCKET",DATABASE 'test',USER 'spider',PASSWORD 'pwd');
 
CREATE TABLE t1 (c INT KEY) ENGINE=InnoDB;
 
CREATE TABLE t2 (c INT KEY) ENGINE=Spider COMMENT='WRAPPER "mysql",SERVER "s",TABLE "t1"';
 
CREATE TABLE t3 (c INT KEY) ENGINE=Spider;
 
--error ER_CONNECT_TO_FOREIGN_DATA_SOURCE
 
LOCK TABLE t2 WRITE,t3 WRITE;
 
CREATE TABLE t4 (c INT) ENGINE=Spider;
 
FLUSH NO_WRITE_TO_BINLOG TABLES t4 WITH READ LOCK;
 
UNLOCK TABLES;

Leads to same ASAN issue on an ASAN (or UB/ASAN) build.

Comment by Yuchen Pei [ 2023-10-09 ]

We will try to fix this issue together with other hangs / asan
failures related to locking spider tables, including:

When reverting the commit for MDEV-29484
(2154a1fc3566e994601a05875fdb65bd6f6d7133) which partially reverted
the commit for MDEV-28352, the ASAN failure disappears, but we get
hangs when trying to drop tables in the test cleanup.

The same happens if we try to recreate a conn with the following patch

modified   storage/spider/ha_spider.cc
 
@@ -900,6 +900,10 @@ int ha_spider::external_lock(
 
     }
 
   }
 
 
+  if ((error_num= spider_check_trx_and_get_conn(thd, this)))
 
+  {
 
+    DBUG_RETURN(error_num);
 
+  }
 
   if (!partition_handler || !partition_handler->handlers)
 
   {
 
     DBUG_RETURN(lock_tables()); /* Non-partitioned table */

Updated on 2023-10-12: MDEV-29963 is a different problem, so I do
not have it as a part of this ticket.

*: with MDEV-30049, we may also want to fix the confusing error that
happens when a remote table on the local server is locked through
spider, but a separate statement tries to access the table:

query 'INSERT INTO t3 SELECT * FROM t' failed: ER_TABLE_NOT_LOCKED (1100): Table 't3' was not locked with LOCK TABLES

Comment by Yuchen Pei [ 2023-10-09 ]

Here's a simpler version of the test in previous comments, but it is
similar to that of MDEV-29456 and produces a hang without asan like
that ticket:

--echo #
 
--echo # MDEV-29456 Spider hangs in 'Waiting for table metadata lock' state on CREATE TABLE after LOCK TABLES
 
--echo #
 
--disable_query_log
 
--disable_result_log
 
--source ../../t/test_init.inc
 
--enable_result_log
 
--enable_query_log
 
 
 
evalp CREATE SERVER srv FOREIGN DATA WRAPPER mysql
 
OPTIONS (SOCKET "$MASTER_1_MYSOCK", DATABASE 'test',user 'root');
 
 
 
create table t1 (c int);
 
create table t2 (c int) ENGINE=Spider
 
COMMENT='WRAPPER "mysql", srv "srv",TABLE "t1"';
 
CREATE TABLE t3 (c INT KEY) ENGINE=Spider;
 
LOCK TABLE t2 WRITE;
 
--error ER_CONNECT_TO_FOREIGN_DATA_SOURCE
 
LOCK TABLE t3 WRITE;
 
UNLOCK TABLES;
 
 
 
drop table t1, t2, t3;
 
drop server srv;
 
 
 
--disable_query_log
 
--disable_result_log
 
--source ../../t/test_deinit.inc
 
--enable_result_log
 
--enable_query_log
 
--echo #
 
--echo # end of test mdev_29456
 
--echo #

Comment by Yuchen Pei [ 2023-10-12 ]

Here's an initial patch, but it causes strange failures with
spider/bugfix.mdev_31524 as if the --source ../../t/test_init.inc
there was called twice[1].

fc5d7d933ef @ MDEV-30014 Spider should not second guess server when locking / unlocking

[1] https://buildbot.mariadb.org/#grid?branch=bb-11.0-mdev-31524-failure-why

and it is not always mdev_31524 that fails, sometimes it is
mdev_30392, failing in the same way:

https://buildbot.mariadb.org/#grid?branch=bb-11.0-ycp-mdev-30014

Turned out to be something stupid, where the test was skipped on a
non-ASAN build, after sourcing the file:

--disable_query_log
 
--disable_result_log
 
--source ../../t/test_init.inc
 
--enable_result_log
 
--enable_query_log
 
 
 
IF (`SELECT NOT(COUNT(*)) FROM information_schema.system_variables WHERE variable_name='have_sanitizer' AND global_value like "%ASAN%"`)
 
{
 
--skip test needs to be run with ASAN
 
}

Comment by Yuchen Pei [ 2023-10-20 ]

The case in a previous comment[1] also hangs without asan in 10.4
4f5346579a6ac8d13cddf3b2057edd8c4c420bcc.

[1]
https://jira.mariadb.org/browse/MDEV-30014?focusedCommentId=260932&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-260932

MDEV-30049 turned out to be (almost?) a duplicate of
MDEV-29456/MDEV-29667.

And here are the current patches for 11.0 and 10.4 respectively:

f88e810d508 upstream/bb-11.0-ycp-mdev-30014 MDEV-30014 Spider should not second guess server when locking / unlocking

e3410b65c13 upstream/bb-10.4-ycp-mdev-30014 MDEV-30014 Spider should not second guess server when locking / unlocking

Comment by Yuchen Pei [ 2023-10-20 ]

Hi holyfoot, ptal thanks (based on 11.0)

upstream/bb-11.0-ycp-mdev-30014 f88e810d5083b6eb1b0a6b29942ddeec6ecb1e50
 
MDEV-30014 Spider should not second guess server when locking / unlocking
 
 
 
This fixes MDEV-30014, MDEV-29456, MDEV-29667, and MDEV-30049.
 
 
 
The server may ask storage engines to unlock when the original sql
 
command is not UNLOCK. This patch makes sure that spider honours these
 
requests, so that the server has the correct idea which tables are
 
locked and which are not.
 
 
 
MDEV-29456, MDEV-29667, MDEV-30049: a later LOCK statement would, as
 
the first step, unlock locked tables and clear the OPTION_TABLE_LOCK
 
bit in thd->variables.option_bits, as well as locked_tables_list,
 
indicating no tables are locked. If Spider does not unlock because the
 
sql command is not UNLOCK, and if after this the LOCK statement fails
 
to lock any tables, these indications that no tables are locked
 
remains, so a later UNLOCK TABLES; statement would not try to unlock
 
any table. Causing later statements requiring mdl locks to hang on
 
waiting until lock_wait_timeout (default 1h) has passed.
 
 
 
MDEV-30014: when a LOCK statement tries to lock more than one tables,
 
say t2 and t3 as in mdev_30014.test, and t2 succeeds but t3 fails, the
 
sql layer would try to undo by unlocking t2, and again, if Spider does
 
not honour this request, the sql layer would assume t2 has been
 
unlocked, but later actions on t2 or t2's remote table could hang on
 
waiting for the mdl.

See the previous comment for a 10.4 version.

Comment by Alexey Botchkov [ 2023-10-30 ]

ok to push.

Comment by Yuchen Pei [ 2023-11-17 ]

Pushing the following to 10.4

0381197855c upstream/bb-10.4-mdev-30014 MDEV-30014 Spider should not second guess server when locking / unlocking

Conflict only at 10.4->10.5, but nontrivial, with the following
solution

6ee83312185 upstream/bb-10.5-mdev-30014 MDEV-30014 Spider should not second guess server when locking / unlocking

Generated at Thu Feb 08 10:12:59 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.