[MDEV-32850] MariaDB got crash when call procedure Created: 2023-11-21  Updated: 2023-11-21  Resolved: 2023-11-21

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Procedure
Affects Version/s: 10.4, 10.5, 10.6, 10.9, 10.10, 10.11, 11.0, 11.1, 11.2, 10.6.16
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Shawn Yan Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: stored_procedures
Environment:

mariadb in docker
10.6.16-MariaDB-1:10.6.16+maria~ubu2004


Issue Links:
Duplicate
duplicates MDEV-26115 Crash when calling stored function in... Confirmed
Relates
relates to MDEV-23902 MariaDB crash on calling function Closed

 Description   

we notice one old issue was fixed in the latest release version,
https://jira.mariadb.org/browse/MDEV-23902

but when I bring up docker and set general_log=1, the bug trigger again.

steps:

docker pull mariadb:10.6.16
docker run --name m616 -e MYSQL_ROOT_PASSWORD=123456 -d mariadb:10.6.16
docker exec -it m616 mysql -uroot -p123456
 
create schema test;
use test;
set global general_log=1;
 
delimiter |
CREATE OR REPLACE FUNCTION cnt()
RETURNS INTEGER
NO SQL
BEGIN
   RETURN 1;
END;|
CREATE OR REPLACE PROCEDURE p1()
NO SQL
BEGIN
   DECLARE i INTEGER;
   FOR i IN 1..cnt() DO
      SELECT i;
   END FOR;
END;|
delimiter ;
 
CALL p1(); -- OK
CALL p1(); -- Crash

logs:

2023-11-21  1:03:06 0 [Note] mariadbd: ready for connections.
Version: '10.6.16-MariaDB-1:10.6.16+maria~ubu2004'  socket: '/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
231121  1:03:33 [ERROR] mysqld got signal 11 ;
Sorry, we probably made a mistake, and this is a bug.
 
Your assistance in bug reporting will enable us to fix this for the next release.
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.6.16-MariaDB-1:10.6.16+maria~ubu2004-log source revision: b83c379420a8846ae4b28768d3c81fa354cca056
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 468005 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7f44d4000c58
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 = 0x7f451813cd18 thread_stack 0x49000
Printing to addr2line failed
mariadbd(my_print_stacktrace+0x32)[0x5611310288c2]
mariadbd(handle_fatal_signal+0x475)[0x561130ae0075]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x14420)[0x7f4519281420]
mariadbd(_ZN7Item_sp7cleanupEv+0x1f)[0x561130b0287f]
mariadbd(_ZN12Item_func_sp7cleanupEv+0x1c)[0x561130b504cc]
mariadbd(_Z13cleanup_itemsP4Item+0x21)[0x5611308938c1]
mariadbd(_ZN7sp_head7executeEP3THDb+0xb2d)[0x5611307e9a3d]
mariadbd(_ZN7sp_head17execute_procedureEP3THDP4ListI4ItemE+0x67a)[0x5611307eb27a]
mariadbd(+0x7b8d37)[0x561130892d37]
mariadbd(_ZN12Sql_cmd_call7executeEP3THD+0x166)[0x561130897a26]
mariadbd(_Z21mysql_execute_commandP3THDb+0x1016)[0x56113089e0f6]
mariadbd(_Z11mysql_parseP3THDPcjP12Parser_state+0x1e7)[0x56113088d847]
mariadbd(_Z16dispatch_command19enum_server_commandP3THDPcjb+0x1085)[0x56113089a025]
mariadbd(_Z10do_commandP3THDb+0x13e)[0x56113089c26e]
mariadbd(_Z24do_handle_one_connectionP7CONNECTb+0x3b7)[0x5611309b4297]
mariadbd(handle_one_connection+0x5d)[0x5611309b45ed]
mariadbd(+0xc5ba16)[0x561130d35a16]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8609)[0x7f4519275609]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x43)[0x7f4518e61133]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f44d4010990): CALL p1()
 
Connection ID (thread ID): 3
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on,not_null_range_scan=off,hash_join_cardinality=off,cset_narrowing=off
 
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mariadbd/ contains
information that should help you find out what is causing the crash.
Writing a core file...
Working directory at /var/lib/mysql
Resource Limits:
Limit                     Soft Limit           Hard Limit           Units
Max cpu time              unlimited            unlimited            seconds
Max file size             unlimited            unlimited            bytes
Max data size             unlimited            unlimited            bytes
Max stack size            8388608              unlimited            bytes
Max core file size        unlimited            unlimited            bytes
Max resident set          unlimited            unlimited            bytes
Max processes             unlimited            unlimited            processes
Max open files            10485760             10485760             files
Max locked memory         65536                65536                bytes
Max address space         unlimited            unlimited            bytes
Max file locks            unlimited            unlimited            locks
Max pending signals       14938                14938                signals
Max msgqueue size         819200               819200               bytes
Max nice priority         0                    0
Max realtime priority     0                    0
Max realtime timeout      unlimited            unlimited            us
Core pattern: |abrt-hook-ccpp %s %c %p %u %g %t %e %P %I %h
 
Kernel version: Linux version 3.10.0-1160.99.1.el7.x86_64 (mockbuild@kbuilder.bsys.centos.org) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-44) (GCC) ) #1 SMP Wed Sep 13 14:19:20 UTC 2023



 Comments   
Comment by Marko Mäkelä [ 2023-11-21 ]

The stack trace contains _ZN7Item_sp7cleanupEv+0x1f, which is near the start of the following function:

void
Item_sp::cleanup()
{
  delete sp_result_field;
  sp_result_field= NULL;
  m_sp= NULL;
  delete func_ctx;
  func_ctx= NULL;
  free_root(&sp_mem_root, MYF(0));
  dummy_table->alias.free();
}

Without seeing the compiled code, I can only guess, but I think that it is plausible that this crashes in one of the delete statements when invoking an inlined destructor. Could it be that this=nullptr here? A full stack trace of the crash would help a lot. I’m not deeply familiar with Docker or the pre-made MariaDB containers. You may need https://quay.io/repository/mariadb-foundation/mariadb-debug which should allow you to obtain a resolved stack trace from GDB.

Comment by Alice Sherepa [ 2023-11-21 ]

Thank you for the report!
I repeated as described on 10.4-11.2. This is the same as MDEV-26115

Version: '10.4.33-MariaDB-debug-log'  0381197855c58e339ab5034b871ea9c0c2d61522
=================================================================
==1304488==ERROR: AddressSanitizer: heap-use-after-free on address 0x625000179cf8 at pc 0x55c63ff39140 bp 0x7f5d6f5b9780 sp 0x7f5d6f5b9770
READ of size 8 at 0x625000179cf8 thread T31
    #0 0x55c63ff3913f in Item_sp::cleanup() /10.4/src/sql/item.cc:2727
    #1 0x55c640072ebf in Item_func_sp::cleanup() /10.4/src/sql/item_func.cc:6419
    #2 0x55c63f6fad40 in cleanup_items(Item*) /10.4/src/sql/sql_parse.cc:1135
    #3 0x55c63f4b196f in sp_head::execute(THD*, bool) /10.4/src/sql/sp_head.cc:1445
    #4 0x55c63f4b75c7 in sp_head::execute_procedure(THD*, List<Item>*) /10.4/src/sql/sp_head.cc:2407
    #5 0x55c63f706e3f in do_execute_sp /10.4/src/sql/sql_parse.cc:3064
    #6 0x55c63f708a39 in Sql_cmd_call::execute(THD*) /10.4/src/sql/sql_parse.cc:3306
    #7 0x55c63f71db9b in mysql_execute_command(THD*) /10.4/src/sql/sql_parse.cc:6218
    #8 0x55c63f729786 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /10.4/src/sql/sql_parse.cc:8014
    #9 0x55c63f6ffb12 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /10.4/src/sql/sql_parse.cc:1857
    #10 0x55c63f6fc63d in do_command(THD*) /10.4/src/sql/sql_parse.cc:1378
    #11 0x55c63fb10f65 in do_handle_one_connection(CONNECT*) /10.4/src/sql/sql_connect.cc:1419
    #12 0x55c63fb10809 in handle_one_connection /10.4/src/sql/sql_connect.cc:1323
    #13 0x55c6407ae5eb in pfs_spawn_thread /10.4/src/storage/perfschema/pfs.cc:1869
    #14 0x7f5d86526608 in start_thread /build/glibc-BHL3KM/glibc-2.31/nptl/pthread_create.c:477
    #15 0x7f5d860f7132 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x11f132)
 
0x625000179cf8 is located 1016 bytes inside of 8268-byte region [0x625000179900,0x62500017b94c)
freed by thread T31 here:
    #0 0x7f5d86b2440f in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cc:122
    #1 0x55c641335f0b in free_memory /10.4/src/mysys/safemalloc.c:279
    #2 0x55c6413354c7 in sf_free /10.4/src/mysys/safemalloc.c:197
    #3 0x55c6413040bf in my_free /10.4/src/mysys/my_malloc.c:222
    #4 0x55c6412e0e05 in free_root /10.4/src/mysys/my_alloc.c:437
    #5 0x55c63f4b1a68 in sp_head::execute(THD*, bool) /10.4/src/sql/sp_head.cc:1459
    #6 0x55c63f4b75c7 in sp_head::execute_procedure(THD*, List<Item>*) /10.4/src/sql/sp_head.cc:2407
    #7 0x55c63f706e3f in do_execute_sp /10.4/src/sql/sql_parse.cc:3064
    #8 0x55c63f708a39 in Sql_cmd_call::execute(THD*) /10.4/src/sql/sql_parse.cc:3306
    #9 0x55c63f71db9b in mysql_execute_command(THD*) /10.4/src/sql/sql_parse.cc:6218
    #10 0x55c63f729786 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /10.4/src/sql/sql_parse.cc:8014
    #11 0x55c63f6ffb12 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /10.4/src/sql/sql_parse.cc:1857
    #12 0x55c63f6fc63d in do_command(THD*) /10.4/src/sql/sql_parse.cc:1378
    #13 0x55c63fb10f65 in do_handle_one_connection(CONNECT*) /10.4/src/sql/sql_connect.cc:1419
    #14 0x55c63fb10809 in handle_one_connection /10.4/src/sql/sql_connect.cc:1323
    #15 0x55c6407ae5eb in pfs_spawn_thread /10.4/src/storage/perfschema/pfs.cc:1869
    #16 0x7f5d86526608 in start_thread /build/glibc-BHL3KM/glibc-2.31/nptl/pthread_create.c:477
 
previously allocated by thread T31 here:
    #0 0x7f5d86b24808 in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cc:144
    #1 0x55c641334e7b in sf_malloc /10.4/src/mysys/safemalloc.c:118
    #2 0x55c6413035c8 in my_malloc /10.4/src/mysys/my_malloc.c:101
    #3 0x55c6412dfc0b in alloc_root /10.4/src/mysys/my_alloc.c:258
    #4 0x55c63f41b733 in Query_arena::alloc(unsigned long) /10.4/src/sql/sql_class.h:1122
    #5 0x55c63f582e84 in lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int) /10.4/src/sql/sql_base.cc:5557
    #6 0x55c63f581c8b in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /10.4/src/sql/sql_base.cc:5353
    #7 0x55c63f4d8cfa in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /10.4/src/sql/sql_base.h:503
    #8 0x55c63f59b004 in open_system_tables_for_read(THD*, TABLE_LIST*, Open_tables_backup*) /10.4/src/sql/sql_base.cc:9199
    #9 0x55c640328209 in open_proc_table_for_read(THD*, Open_tables_backup*) /10.4/src/sql/sp.cc:487
    #10 0x55c640329ee8 in Sp_handler::db_find_routine(THD*, Database_qualified_name const*, sp_head**) const /10.4/src/sql/sp.cc:697
    #11 0x55c64032aa08 in Sp_handler::db_find_and_cache_routine(THD*, Database_qualified_name const*, sp_head**) const /10.4/src/sql/sp.cc:768
    #12 0x55c640339943 in Sp_handler::sp_cache_routine(THD*, Database_qualified_name const*, bool, sp_head**) const /10.4/src/sql/sp.cc:2795
    #13 0x55c6403394cd in Sroutine_hash_entry::sp_cache_routine(THD*, bool, sp_head**) const /10.4/src/sql/sp.cc:2748
    #14 0x55c63f577fd2 in open_and_process_routine /10.4/src/sql/sql_base.cc:3562
    #15 0x55c63f57cce5 in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /10.4/src/sql/sql_base.cc:4469
    #16 0x55c63f581b6f in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /10.4/src/sql/sql_base.cc:5344
    #17 0x55c63f4d8cfa in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /10.4/src/sql/sql_base.h:503
    #18 0x55c63f4bfa60 in sp_instr::exec_open_and_lock_tables(THD*, TABLE_LIST*) /10.4/src/sql/sp_head.cc:3609
    #19 0x55c63f4bef1a in sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) /10.4/src/sql/sp_head.cc:3487
    #20 0x55c63f4c0b50 in sp_instr_set::execute(THD*, unsigned int*) /10.4/src/sql/sp_head.cc:3778
    #21 0x55c63f4b13a2 in sp_head::execute(THD*, bool) /10.4/src/sql/sp_head.cc:1372
    #22 0x55c63f4b75c7 in sp_head::execute_procedure(THD*, List<Item>*) /10.4/src/sql/sp_head.cc:2407
    #23 0x55c63f706e3f in do_execute_sp /10.4/src/sql/sql_parse.cc:3064
    #24 0x55c63f708a39 in Sql_cmd_call::execute(THD*) /10.4/src/sql/sql_parse.cc:3306
    #25 0x55c63f71db9b in mysql_execute_command(THD*) /10.4/src/sql/sql_parse.cc:6218
    #26 0x55c63f729786 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /10.4/src/sql/sql_parse.cc:8014
    #27 0x55c63f6ffb12 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /10.4/src/sql/sql_parse.cc:1857
    #28 0x55c63f6fc63d in do_command(THD*) /10.4/src/sql/sql_parse.cc:1378
    #29 0x55c63fb10f65 in do_handle_one_connection(CONNECT*) /10.4/src/sql/sql_connect.cc:1419
 
Thread T31 created by T0 here:
    #0 0x7f5d86a51815 in __interceptor_pthread_create ../../../../src/libsanitizer/asan/asan_interceptors.cc:208
    #1 0x55c6407ae9dc in spawn_thread_v1 /10.4/src/storage/perfschema/pfs.cc:1919
    #2 0x55c63f3f4f71 in inline_mysql_thread_create /10.4/src/include/mysql/psi/mysql_thread.h:1275
    #3 0x55c63f40d161 in create_thread_to_handle_connection(CONNECT*) /10.4/src/sql/mysqld.cc:6296
    #4 0x55c63f40d8fc in create_new_thread(CONNECT*) /10.4/src/sql/mysqld.cc:6366
    #5 0x55c63f40dde2 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /10.4/src/sql/mysqld.cc:6464
    #6 0x55c63f40ec9e in handle_connections_sockets() /10.4/src/sql/mysqld.cc:6622
    #7 0x55c63f40c866 in mysqld_main(int, char**) /10.4/src/sql/mysqld.cc:5954
    #8 0x55c63f3f2f3c in main /10.4/src/sql/main.cc:25
    #9 0x7f5d85ffc082 in __libc_start_main ../csu/libc-start.c:308
 
SUMMARY: AddressSanitizer: heap-use-after-free /10.4/src/sql/item.cc:2727 in Item_sp::cleanup()
Shadow bytes around the buggy address:
  0x0c4a80027340: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a80027350: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a80027360: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a80027370: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a80027380: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
=>0x0c4a80027390: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd[fd]
  0x0c4a800273a0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a800273b0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a800273c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a800273d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a800273e0: 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
==1304488==ABORTING
----------SERVER LOG END-------------

Comment by Shawn Yan [ 2023-11-21 ]

hi, Alice,
plz note that, when I send "call p1()" in 10.6.16, DB runs normal,
but, when I send "set global general_log=1" first, then "call p1", db got crash,
that's not exactly the same。

Comment by Alice Sherepa [ 2023-11-21 ]

shawn2016 It is also repeatable without setting general_log=1, just after the second execution of the procedure. But sure after MDEV-26115 will be patched - this test should be checked again.

MariaDB [test]> select version();
+-----------------+
| version()       |
+-----------------+
| 10.6.16-MariaDB |
+-----------------+
1 row in set (0,000 sec)
 
MariaDB [test]> delimiter |
MariaDB [test]> CREATE OR REPLACE FUNCTION cnt()
    -> RETURNS INTEGER
    -> NO SQL
    -> BEGIN
    ->    RETURN 1;
    -> END;|
Query OK, 0 rows affected (0,014 sec)
 
MariaDB [test]> CREATE OR REPLACE PROCEDURE p1()
    -> NO SQL
    -> BEGIN
    ->    DECLARE i INTEGER;
    ->    FOR i IN 1..cnt() DO
    ->       SELECT i;
    ->    END FOR;
    -> END;|
Query OK, 0 rows affected (0,020 sec)
 
MariaDB [test]> CALL p1()|
+---+
| i |
+---+
| 1 |
+---+
1 row in set (0,001 sec)
 
Query OK, 0 rows affected (0,001 sec)
 
MariaDB [test]> CALL p1()|
ERROR 2013 (HY000): Lost connection to server during query

231121 12:26:33 [ERROR] mysqld got signal 11 ;
 
Server version: 10.6.16-MariaDB source revision: b83c379420a8846ae4b28768d3c81fa354cca056
 
sql/signal_handler.cc:238(handle_fatal_signal)[0x55bd6f81ed67]
sigaction.c:0(__restore_rt)[0x7fa891416420]
sql/item.cc:2815(Item_sp::cleanup())[0x55bd6f83f90b]
sql/item_func.h:141(Item_func::cleanup())[0x55bd6f88d068]
sql/sql_parse.cc:1127(cleanup_items(Item*))[0x55bd6f5e6631]
sql/sp_head.cc:1528(sp_head::execute(THD*, bool))[0x55bd6f54c2dc]
psi/mysql_sp.h:79(sp_head::execute_procedure(THD*, List<Item>*))[0x55bd6f54db5f]
sql/sql_parse.cc:3041(do_execute_sp(THD*, sp_head*))[0x55bd6f5e597a]
sql/sql_parse.cc:3284(Sql_cmd_call::execute(THD*))[0x55bd6f5e81ba]
sql/sql_parse.cc:6026(mysql_execute_command(THD*, bool))[0x55bd6f5ef95a]
sql/sql_parse.cc:8052(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x55bd6f5f371b]
sql/sql_parse.cc:1957(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool))[0x55bd6f5f5b50]
sql/sql_parse.cc:1411(do_command(THD*, bool))[0x55bd6f5f7073]
sql/sql_connect.cc:1416(do_handle_one_connection(CONNECT*, bool))[0x55bd6f6f4f87]
sql/sql_connect.cc:1324(handle_one_connection)[0x55bd6f6f5224]
perfschema/pfs.cc:2204(pfs_spawn_thread)[0x55bd6fa97c8c]
nptl/pthread_create.c:478(start_thread)[0x7fa89140a609]
 
Query (0x7fa8400131a0): CALL p1()

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