[MDEV-31764] ASAN use-after-poison in trace_engine_stats upon ANALYZE FORMAT=JSON Created: 2023-07-22  Updated: 2023-09-20  Resolved: 2023-08-02

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.6
Fix Version/s: 10.6.15, 10.9.8, 10.10.6, 10.11.5, 11.0.3, 11.1.2, 11.2.1

Type: Bug Priority: Blocker
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Fixed Votes: 1
Labels: regression

Issue Links:
Problem/Incident
is caused by MDEV-31577 Make ANALYZE FORMAT=JSON print innodb... Closed

 Description    

ANALYZE FORMAT=JSON SELECT * FROM information_schema.GLOBAL_STATUS;

or without I_S:

CREATE TABLE t1 (a INT);
 
INSERT INTO t1 VALUES (1),(2);
 
CREATE TABLE t2 (s INT);
 
INSERT INTO t2 VALUES (2),(3);
 
ANALYZE FORMAT=JSON SELECT * FROM t1 WHERE a IN (SELECT s FROM t2);
 
 
 
# Cleanup
 
DROP TABLE t1, t2;

10.6 6e484c3b

 
==1465818==ERROR: AddressSanitizer: use-after-poison on address 0x61b00003c0b0 at pc 0x55b546a9d5ef bp 0x7f8d01b01ce0 sp 0x7f8d01b01cd8
 
READ of size 8 at 0x61b00003c0b0 thread T5
 
    #0 0x55b546a9d5ee in trace_engine_stats /data/src/10.6/sql/sql_explain.cc:1714
 
    #1 0x55b546a9e684 in Explain_table_access::print_explain_json(Explain_query*, Json_writer*, bool) /data/src/10.6/sql/sql_explain.cc:1873
 
    #2 0x55b546a99adb in Explain_basic_join::print_explain_json_interns(Explain_query*, Json_writer*, bool) /data/src/10.6/sql/sql_explain.cc:1128
 
    #3 0x55b546a99063 in Explain_select::print_explain_json(Explain_query*, Json_writer*, bool) /data/src/10.6/sql/sql_explain.cc:1027
 
    #4 0x55b546a93c00 in Explain_query::print_explain_json(select_result_sink*, bool) /data/src/10.6/sql/sql_explain.cc:247
 
    #5 0x55b546a932f6 in Explain_query::send_explain(THD*, bool) /data/src/10.6/sql/sql_explain.cc:175
 
    #6 0x55b5465a94f5 in execute_sqlcom_select /data/src/10.6/sql/sql_parse.cc:6287
 
    #7 0x55b5465978e1 in mysql_execute_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:3949
 
    #8 0x55b5465b4180 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.6/sql/sql_parse.cc:8041
 
    #9 0x55b546589fc7 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/src/10.6/sql/sql_parse.cc:1896
 
    #10 0x55b546586cfb in do_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:1409
 
    #11 0x55b5469f4a9f in do_handle_one_connection(CONNECT*, bool) /data/src/10.6/sql/sql_connect.cc:1416
 
    #12 0x55b5469f4460 in handle_one_connection /data/src/10.6/sql/sql_connect.cc:1318
 
    #13 0x55b54764c35d in pfs_spawn_thread /data/src/10.6/storage/perfschema/pfs.cc:2201
 
    #14 0x7f8d092a7fd3 in start_thread nptl/pthread_create.c:442
 
    #15 0x7f8d093285bb in clone3 ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
 
 
 
0x61b00003c0b0 is located 304 bytes inside of 1416-byte region [0x61b00003bf80,0x61b00003c508)
 
allocated by thread T5 here:
 
    #0 0x7f8d09eb89cf in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:69
 
    #1 0x55b548249618 in my_malloc /data/src/10.6/mysys/my_malloc.c:91
 
    #2 0x55b548225f82 in alloc_root /data/src/10.6/mysys/my_alloc.c:249
 
    #3 0x55b54629a8a9 in Sql_alloc::operator new(unsigned long, st_mem_root*) /data/src/10.6/sql/sql_alloc.h:37
 
    #4 0x55b5477faa09 in heap_create_handler /data/src/10.6/storage/heap/ha_heap.cc:65
 
    #5 0x55b546dfed20 in get_new_handler(TABLE_SHARE*, st_mem_root*, handlerton*) /data/src/10.6/sql/handler.cc:382
 
    #6 0x55b5466d8842 in Create_tmp_table::choose_engine(THD*, TABLE*, TMP_TABLE_PARAM*) /data/src/10.6/sql/sql_select.cc:19658
 
    #7 0x55b5466d8fff in Create_tmp_table::finalize(THD*, TABLE*, TMP_TABLE_PARAM*, bool, bool) /data/src/10.6/sql/sql_select.cc:19691
 
    #8 0x55b5466e0433 in create_tmp_table_for_schema(THD*, TMP_TABLE_PARAM*, st_schema_table const&, long long, st_mysql_const_lex_string const&, bool, bool) /data/src/10.6/sql/sql_select.cc:20218
 
    #9 0x55b5467a1b6f in create_schema_table(THD*, TABLE_LIST*) /data/src/10.6/sql/sql_show.cc:8262
 
    #10 0x55b5467a4275 in mysql_schema_table(THD*, LEX*, TABLE_LIST*) /data/src/10.6/sql/sql_show.cc:8470
 
    #11 0x55b5463fc2bf in open_and_process_table /data/src/10.6/sql/sql_base.cc:3722
 
    #12 0x55b5463ffb6d in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /data/src/10.6/sql/sql_base.cc:4335
 
    #13 0x55b546404cc0 in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /data/src/10.6/sql/sql_base.cc:5308
 
    #14 0x55b54635bdad in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /data/src/10.6/sql/sql_base.h:509
 
    #15 0x55b5465a86cc in execute_sqlcom_select /data/src/10.6/sql/sql_parse.cc:6194
 
    #16 0x55b5465978e1 in mysql_execute_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:3949
 
    #17 0x55b5465b4180 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.6/sql/sql_parse.cc:8041
 
    #18 0x55b546589fc7 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/src/10.6/sql/sql_parse.cc:1896
 
    #19 0x55b546586cfb in do_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:1409
 
    #20 0x55b5469f4a9f in do_handle_one_connection(CONNECT*, bool) /data/src/10.6/sql/sql_connect.cc:1416
 
    #21 0x55b5469f4460 in handle_one_connection /data/src/10.6/sql/sql_connect.cc:1318
 
    #22 0x55b54764c35d in pfs_spawn_thread /data/src/10.6/storage/perfschema/pfs.cc:2201
 
    #23 0x7f8d092a7fd3 in start_thread nptl/pthread_create.c:442
 
 
 
Thread T5 created by T0 here:
 
    #0 0x7f8d09e49726 in __interceptor_pthread_create ../../../../src/libsanitizer/asan/asan_interceptors.cpp:207
 
    #1 0x55b547648098 in my_thread_create /data/src/10.6/storage/perfschema/my_thread.h:52
 
    #2 0x55b54764c74c in pfs_spawn_thread_v1 /data/src/10.6/storage/perfschema/pfs.cc:2252
 
    #3 0x55b54627784b in inline_mysql_thread_create /data/src/10.6/include/mysql/psi/mysql_thread.h:1139
 
    #4 0x55b54628ea94 in create_thread_to_handle_connection(CONNECT*) /data/src/10.6/sql/mysqld.cc:5991
 
    #5 0x55b54628f0a5 in create_new_thread(CONNECT*) /data/src/10.6/sql/mysqld.cc:6050
 
    #6 0x55b54628f390 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /data/src/10.6/sql/mysqld.cc:6112
 
    #7 0x55b54628fd20 in handle_connections_sockets() /data/src/10.6/sql/mysqld.cc:6236
 
    #8 0x55b54628e311 in mysqld_main(int, char**) /data/src/10.6/sql/mysqld.cc:5886
 
    #9 0x55b546276958 in main /data/src/10.6/sql/main.cc:34
 
    #10 0x7f8d09246189 in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58
 
 
 
SUMMARY: AddressSanitizer: use-after-poison /data/src/10.6/sql/sql_explain.cc:1714 in trace_engine_stats
 
Shadow bytes around the buggy address:
 
  0x0c367ffff7c0: fd fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c367ffff7d0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c367ffff7e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c367ffff7f0: 00 00 00 00 00 00 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c367ffff800: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
=>0x0c367ffff810: f7 f7 f7 f7 f7 f7[f7]f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c367ffff820: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c367ffff830: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c367ffff840: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c367ffff850: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c367ffff860: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
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
 
==1465818==ABORTING

The failure started happening after this commit in 10.6

commit 6e484c3bd99a6709e3554f32a99167042ea88496 (HEAD -> 10.6, origin/bb-10.11-mdev31577-v3, origin/HEAD, origin/10.6)
 
Author: Sergei Petrunia
 
Date:   Thu Jul 6 10:41:46 2023 +0300
 
 
 
    MDEV-31577: Make ANALYZE FORMAT=JSON print innodb stats



 Comments   
Comment by Sergei Petrunia [ 2023-07-24 ]

The original 11.0 patch is also affected, it is not a backport error...

Comment by Sergei Petrunia [ 2023-07-24 ]

Debugging the 

ANALYZE FORMAT=JSON SELECT * FROM information_schema.GLOBAL_STATUS;

statement. The calls occur in this order:

  Thread 18 "mysqld" hit Breakpoint 5, ha_heap::ha_heap (this=0x61b00002fc28, hton=0x616000009a08, table_arg=0x6200...)
 
  Thread 18 "mysqld" hit Breakpoint 1, trace_engine_stats (file=0x61b00002fc28, writer=0x7fffc8f3dec0) 
  Thread 18 "mysqld" hit Breakpoint 8, Explain_query::notify_tables_are_closed (this=0x62900004d210) 
  Thread 18 "mysqld" hit Breakpoint 7, free_tmp_table (thd=0x62b00016c288, entry=0x620000010128)

which matches the idea which was used when developing this patch: trace_engine_stats() is called before before temp. tables are freed...
But ASAN shows this is not the case?

Comment by Sergei Petrunia [ 2023-07-25 ]

Ok, the cause of ANALYZE FORMAT=JSON is as follows:

  • Explain data structure stores a pointer to the temp. table
  • Eventually, in get_schema_tables_result(), create_internal_tmp_table_from_heap() is called, which frees the ha_heap table and creates ha_maria one instead.
    However, the Explain data structure still has the old pointer.
Comment by Sergei Petrunia [ 2023-07-25 ]

In the case of

 
ANALYZE FORMAT=JSON SELECT * FROM t1 WHERE a IN (SELECT s FROM t2);

it is different (note: the stack trace is from a modified tree):

=================================================================
 
==26461==ERROR: AddressSanitizer: heap-use-after-free on address 0x61b000024720 at pc 0x55c6ae7231ae bp 0x7fd0d42eace0 sp 0x7fd0d42eacd0
 
READ of size 8 at 0x61b000024720 thread T5
 
    #0 0x55c6ae7231ad in Explain_table_access::verify() /home/psergey/dev-git2/10.11-look/sql/sql_explain.cc:2152
 
    #1 0x55c6ae71ca35 in Explain_select::verify() /home/psergey/dev-git2/10.11-look/sql/sql_explain.cc:1163
 
    #2 0x55c6ae71bd98 in Explain_select::print_explain_json(Explain_query*, Json_writer*, bool, bool) /home/psergey/dev-git2/10.11-look/sql/sql_explain.cc:1032
 
    #3 0x55c6ae7173de in Explain_query::print_query_blocks_json(Json_writer*, bool, bool) /home/psergey/dev-git2/10.11-look/sql/sql_explain.cc:342
 
    #4 0x55c6ae717036 in Explain_query::print_explain_json(select_result_sink*, bool, bool, unsigned long long) /home/psergey/dev-git2/10.11-look/sql/sql_explain.cc:303 
    #5 0x55c6ae7167cd in Explain_query::send_explain(THD*, bool) /home/psergey/dev-git2/10.11-look/sql/sql_explain.cc:205
 
    #6 0x55c6ae1dc79b in execute_sqlcom_select /home/psergey/dev-git2/10.11-look/sql/sql_parse.cc:6297
 
    #7 0x55c6ae1cab5d in mysql_execute_command(THD*, bool) /home/psergey/dev-git2/10.11-look/sql/sql_parse.cc:3953
 
    #8 0x55c6ae1e7026 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /home/psergey/dev-git2/10.11-look/sql/sql_parse.cc:8021
 
    #9 0x55c6ae1bd1f6 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /home/psergey/dev-git2/10.11-look/sql/sql_parse.cc:1896
 
    #10 0x55c6ae1b9eb3 in do_command(THD*, bool) /home/psergey/dev-git2/10.11-look/sql/sql_parse.cc:1407
 
    #11 0x55c6ae67c23e in do_handle_one_connection(CONNECT*, bool) /home/psergey/dev-git2/10.11-look/sql/sql_connect.cc:1416
 
    #12 0x55c6ae67bb90 in handle_one_connection /home/psergey/dev-git2/10.11-look/sql/sql_connect.cc:1318
 
    #13 0x55c6af2910bd in pfs_spawn_thread /home/psergey/dev-git2/10.11-look/storage/perfschema/pfs.cc:2201
 
    #14 0x7fd0ddcb96da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
 
    #15 0x7fd0dce9f61e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x12161e)

The temp. table was freed here:

0x61b000024720 is located 416 bytes inside of 1532-byte region [0x61b000024580,0x61b000024b7c)
 
freed by thread T5 here:
 
    #0 0x7fd0df1eb7a8 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xde7a8)
 
    #1 0x55c6afebe097 in free_memory /home/psergey/dev-git2/10.11-look/mysys/safemalloc.c:297
 
    #2 0x55c6afebd51e in sf_free /home/psergey/dev-git2/10.11-look/mysys/safemalloc.c:203
 
    #3 0x55c6afe8bacd in my_free /home/psergey/dev-git2/10.11-look/mysys/my_malloc.c:213
 
    #4 0x55c6afe65e12 in root_free /home/psergey/dev-git2/10.11-look/mysys/my_alloc.c:83
 
    #5 0x55c6afe685b3 in free_root /home/psergey/dev-git2/10.11-look/mysys/my_alloc.c:507
 
    #6 0x55c6ae3606f9 in free_tmp_table(THD*, TABLE*) /home/psergey/dev-git2/10.11-look/sql/sql_select.cc:21446
 
    #7 0x55c6ae7949c8 in destroy_sj_tmp_tables(JOIN*) /home/psergey/dev-git2/10.11-look/sql/opt_subselect.cc:5340
 
    #8 0x55c6ae2e8809 in JOIN::destroy() /home/psergey/dev-git2/10.11-look/sql/sql_select.cc:4913
 
    #9 0x55c6ae52053f in st_select_lex::cleanup() /home/psergey/dev-git2/10.11-look/sql/sql_union.cc:2802
 
    #10 0x55c6ae2e9cf4 in mysql_select(THD*, TABLE_LIST*, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) /home/psergey/dev-git2/10.11-look/sql/sql_select.cc:5139
 
    #11 0x55c6ae2b93e6 in handle_select(THD*, LEX*, select_result*, unsigned long long) /home/psergey/dev-git2/10.11-look/sql/sql_select.cc:586
 
    #12 0x55c6ae1dc482 in execute_sqlcom_select /home/psergey/dev-git2/10.11-look/sql/sql_parse.cc:6283
 
    #13 0x55c6ae1cab5d in mysql_execute_command(THD*, bool) /home/psergey/dev-git2/10.11-look/sql/sql_parse.cc:3953
 
    #14 0x55c6ae1e7026 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /home/psergey/dev-git2/10.11-look/sql/sql_parse.cc:8021
 
    #15 0x55c6ae1bd1f6 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /home/psergey/dev-git2/10.11-look/sql/sql_parse.cc:1896
 
    #16 0x55c6ae1b9eb3 in do_command(THD*, bool) /home/psergey/dev-git2/10.11-look/sql/sql_parse.cc:1407
 
    #17 0x55c6ae67c23e in do_handle_one_connection(CONNECT*, bool) /home/psergey/dev-git2/10.11-look/sql/sql_connect.cc:1416
 
    #18 0x55c6ae67bb90 in handle_one_connection /home/psergey/dev-git2/10.11-look/sql/sql_connect.cc:1318
 
    #19 0x55c6af2910bd in pfs_spawn_thread /home/psergey/dev-git2/10.11-look/storage/perfschema/pfs.cc:2201
 
    #20 0x7fd0ddcb96da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)

Comment by Sergei Petrunia [ 2023-08-01 ]

The patch is in bb-10.6-mdev31764.

Comment by Oleksandr Byelkin [ 2023-08-01 ]

ok to push

Comment by Roel Van de Paar [ 2023-09-20 ]

Also ran into this one during preview-11.3-preview testing as the patch has not made it to that tree yet. Testcase for completeness:

SET sql_mode='',in_predicate_conversion_threshold=2, max_heap_table_size=16384;
 
CREATE TABLE t1 (a INT) ENGINE=MyISAM;
 
INSERT INTO t1 VALUES (ST_GEOMFROMTEXT ('POINT(1 1)'));
 
ANALYZE FORMAT=JSON (SELECT * FROM t1 tbl1 WHERE a<5) UNION (SELECT * FROM t1 tbl2 WHERE a IN (2,3));

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