[MDEV-30924] Server crashes in MYSQL_LOG::is_open upon ALTER vs FUNCTION Created: 2023-03-24  Updated: 2023-08-16  Resolved: 2023-08-16

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Stored routines
Affects Version/s: N/A
Fix Version/s: 11.2.1

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Nikita Malyavin
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Problem/Incident
is caused by MDEV-16329 Engine-independent online ALTER TABLE Closed
Relates
relates to MDEV-28808 Test MDEV-16329 (ALTER ONLINE TABLE) ... Stalled

 Description   

It fails for me every time, but it should be non-deterministic due to the presence of --send, so run with --repeat=N if it doesn't fail right away.

CREATE TABLE t (a INT);
 
INSERT INTO t VALUES (1),(2);
 
 
 
--delimiter $
 
CREATE FUNCTION f () RETURNS INT
 
BEGIN
 
  UPDATE t SET a = 10;
 
  RETURN 0;
 
END $
 
--delimiter ;
 
 
 
--connect (con1,localhost,root,,)
 
--send
 
  ALTER TABLE t FORCE, ALGORITHM=COPY;
 
 
 
--connection default
 
SELECT f();
 
 
 
# Cleanup
 
--connection con1
 
--reap
 
DROP TABLE t;
 
DROP FUNCTION f;
 
--disconnect con1

bb-11.0-oalter fd06124e66

 
#3  <signal handler called>
 
#4  0x000055c025640498 in MYSQL_LOG::is_open (this=0x8f8f8f8f8f8f8f8f) at /data/src/bb-11.0-oalter-gcov/sql/log.h:323
 
#5  0x000055c026234f66 in Event_log::flush_and_set_pending_rows_event (this=0x8f8f8f8f8f8f8f8f, thd=0x7fb174000dc8, event=0x0, cache_data=0x7fb174071ad0, is_transactional=true) at /data/src/bb-11.0-oalter-gcov/sql/log.cc:6528
 
#6  0x000055c026234cc0 in binlog_flush_pending_rows_event (thd=0x7fb174000dc8, stmt_end=false, is_transactional=true, bin_log=0x8f8f8f8f8f8f8f8f, cache_data=0x7fb174071ad0) at /data/src/bb-11.0-oalter-gcov/sql/log.cc:6482
 
#7  0x000055c02623c758 in binlog_online_alter_end_trans (thd=0x7fb174000dc8, all=false, commit=true) at /data/src/bb-11.0-oalter-gcov/sql/log.cc:7708
 
#8  0x000055c02621ac81 in binlog_commit (thd=0x7fb174000dc8, all=false, ro_1pc=true) at /data/src/bb-11.0-oalter-gcov/sql/log.cc:2333
 
#9  0x000055c025f9b2e6 in commit_one_phase_2 (thd=0x7fb174000dc8, all=false, trans=0x7fb1740047c0, is_real_trans=true) at /data/src/bb-11.0-oalter-gcov/sql/handler.cc:2116
 
#10 0x000055c025f9aee1 in ha_commit_one_phase (thd=0x7fb174000dc8, all=false) at /data/src/bb-11.0-oalter-gcov/sql/handler.cc:2078
 
#11 0x000055c025f98c7b in ha_commit_trans (thd=0x7fb174000dc8, all=false) at /data/src/bb-11.0-oalter-gcov/sql/handler.cc:1872
 
#12 0x000055c025c0b6d2 in trans_commit_stmt (thd=0x7fb174000dc8) at /data/src/bb-11.0-oalter-gcov/sql/transaction.cc:472
 
#13 0x000055c02585f29c in mysql_execute_command (thd=0x7fb174000dc8, is_called_from_prepared_stmt=false) at /data/src/bb-11.0-oalter-gcov/sql/sql_parse.cc:6061
 
#14 0x000055c02586a489 in mysql_parse (thd=0x7fb174000dc8, rawbuf=0x7fb1740154d0 "SELECT f()", length=10, parser_state=0x7fb18b581370) at /data/src/bb-11.0-oalter-gcov/sql/sql_parse.cc:8000
 
#15 0x000055c025840a3d in dispatch_command (command=COM_QUERY, thd=0x7fb174000dc8, packet=0x7fb17400ba59 "", packet_length=10, blocking=true) at /data/src/bb-11.0-oalter-gcov/sql/sql_parse.cc:1894
 
#16 0x000055c02583db82 in do_command (thd=0x7fb174000dc8, blocking=true) at /data/src/bb-11.0-oalter-gcov/sql/sql_parse.cc:1407
 
#17 0x000055c025bd1395 in do_handle_one_connection (connect=0x55c02bc0c818, put_in_cache=true) at /data/src/bb-11.0-oalter-gcov/sql/sql_connect.cc:1416
 
#18 0x000055c025bd0dc0 in handle_one_connection (arg=0x55c02bc59788) at /data/src/bb-11.0-oalter-gcov/sql/sql_connect.cc:1318
 
#19 0x000055c02650baf7 in pfs_spawn_thread (arg=0x55c02bc0c388) at /data/src/bb-11.0-oalter-gcov/storage/perfschema/pfs.cc:2201
 
#20 0x00007fb194aa7fd4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#21 0x00007fb194b2866c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81



 Comments   
Comment by Nikita Malyavin [ 2023-03-25 ]

Moreover, ASAN reports use-after-free:

==1178012==ERROR: AddressSanitizer: heap-use-after-free on address 0x6250001a2028 at pc 0x557484b55e70 bp 0x7f4b46927f10 sp 0x7f4b46927f08
 
READ of size 8 at 0x6250001a2028 thread T5
 
    #0 0x557484b55e6f in binlog_online_alter_end_trans(THD*, bool, bool) /home/nik/mariadb/sql/log.cc:7700:25
 
    #1 0x557484b539f2 in binlog_commit(THD*, bool, bool) /home/nik/mariadb/sql/log.cc:2333:10
 
    #2 0x557484bba809 in commit_one_phase_2(THD*, bool, THD_TRANS*, bool) /home/nik/mariadb/sql/handler.cc:2116:15
 
    #3 0x557484bbae2f in ha_commit_one_phase(THD*, bool) /home/nik/mariadb/sql/handler.cc:2078:8
 
    #4 0x557484bb8dcc in ha_commit_trans(THD*, bool) /home/nik/mariadb/sql/handler.cc:1872:12
 
    #5 0x557485cdaeef in trans_commit_stmt(THD*) /home/nik/mariadb/sql/transaction.cc:472:10
 
    #6 0x55748572317e in mysql_execute_command(THD*, bool) /home/nik/mariadb/sql/sql_parse.cc:6061:7
 
    #7 0x5574857027be in mysql_parse(THD*, char*, unsigned int, Parser_state*) /home/nik/mariadb/sql/sql_parse.cc:8000:18
 
    #8 0x5574856fcff1 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /home/nik/mariadb/sql/sql_parse.cc:1894:7
 
    #9 0x557485703ab4 in do_command(THD*, bool) /home/nik/mariadb/sql/sql_parse.cc:1407:17
 
    #10 0x557485c91684 in do_handle_one_connection(CONNECT*, bool) /home/nik/mariadb/sql/sql_connect.cc:1416:11
 
    #11 0x557485c90e3e in handle_one_connection /home/nik/mariadb/sql/sql_connect.cc:1318:5
 
    #12 0x557486421238 in pfs_spawn_thread /home/nik/mariadb/storage/perfschema/pfs.cc:2201:3
 
    #13 0x7f4b4f09ebb4  (/usr/lib/libc.so.6+0x85bb4) (BuildId: 4a4bec3d95a1804443e852958fe59ed461135ce9)
 
    #14 0x7f4b4f120cb3 in clone (/usr/lib/libc.so.6+0x107cb3) (BuildId: 4a4bec3d95a1804443e852958fe59ed461135ce9)
 
 
 
0x6250001a2028 is located 1832 bytes inside of 8208-byte region [0x6250001a1900,0x6250001a3910)
 
freed by thread T5 here:
 
    #0 0x557484aa8ea2 in __interceptor_free.part.0 (/home/nik/mariadb/bld/sql/mariadbd+0x1f37ea2) (BuildId: c39e11a9b9b66482)
 
    #1 0x557487260669 in my_free /home/nik/mariadb/mysys/my_malloc.c:213:3
 
    #2 0x557487236a62 in root_free /home/nik/mariadb/mysys/my_alloc.c:78:5
 
    #3 0x5574872386d6 in free_root /home/nik/mariadb/mysys/my_alloc.c:501:7
 
    #4 0x5574852e345a in sp_head::execute(THD*, bool) /home/nik/mariadb/sql/sp_head.cc:1548:5
 
    #5 0x5574852e9c4a in sp_head::execute_function(THD*, Item**, unsigned int, Field*, sp_rcontext**, Query_arena*) /home/nik/mariadb/sql/sp_head.cc:2191:3
 
    #6 0x557484d8e5b4 in Item_sp::execute_impl(THD*, Item**, unsigned int) /home/nik/mariadb/sql/item.cc:2928:26
 
    #7 0x557484d8d7b6 in Item_sp::execute(THD*, bool*, Item**, unsigned int) /home/nik/mariadb/sql/item.cc:2842:7
 
    #8 0x557484e595c6 in Item_func_sp::execute() /home/nik/mariadb/sql/item_func.cc:6654:19
 
    #9 0x557484e7c478 in Item_func_sp::val_int() /home/nik/mariadb/sql/item_func.h:3891:9
 
    #10 0x557485f1dbc5 in Type_handler::Item_send_long(Item*, Protocol*, st_value*) const /home/nik/mariadb/sql/sql_type.cc:7487:22
 
    #11 0x557485f47a2c in Type_handler_long::Item_send(Item*, Protocol*, st_value*) const /home/nik/mariadb/sql/sql_type.h:5701:12
 
    #12 0x557484b2ead1 in Item::send(Protocol*, st_value*) /home/nik/mariadb/sql/item.h:1235:28
 
    #13 0x5574852441bb in Protocol::send_result_set_row(List<Item>*) /home/nik/mariadb/sql/protocol.cc:1332:15
 
    #14 0x55748544bb48 in select_send::send_data(List<Item>&) /home/nik/mariadb/sql/sql_class.cc:3102:17
 
    #15 0x557485948212 in select_result_sink::send_data_with_check(List<Item>&, st_select_lex_unit*, unsigned long long) /home/nik/mariadb/sql/sql_class.h:5747:12
 
    #16 0x557485892433 in JOIN::exec_inner() /home/nik/mariadb/sql/sql_select.cc:4754:22
 
    #17 0x557485890ac2 in JOIN::exec() /home/nik/mariadb/sql/sql_select.cc:4666:3
 
    #18 0x55748581d13e 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/nik/mariadb/sql/sql_select.cc:5146:9
 
    #19 0x55748581c42c in handle_select(THD*, LEX*, select_result*, unsigned long long) /home/nik/mariadb/sql/sql_select.cc:608:10
 
    #20 0x557485726b39 in execute_sqlcom_select(THD*, TABLE_LIST*) /home/nik/mariadb/sql/sql_parse.cc:6265:12
 
    #21 0x55748571272c in mysql_execute_command(THD*, bool) /home/nik/mariadb/sql/sql_parse.cc:3949:12
 
    #22 0x5574857027be in mysql_parse(THD*, char*, unsigned int, Parser_state*) /home/nik/mariadb/sql/sql_parse.cc:8000:18
 
    #23 0x5574856fcff1 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /home/nik/mariadb/sql/sql_parse.cc:1894:7
 
    #24 0x557485703ab4 in do_command(THD*, bool) /home/nik/mariadb/sql/sql_parse.cc:1407:17
 
    #25 0x557485c91684 in do_handle_one_connection(CONNECT*, bool) /home/nik/mariadb/sql/sql_connect.cc:1416:11
 
    #26 0x557485c90e3e in handle_one_connection /home/nik/mariadb/sql/sql_connect.cc:1318:5
 
    #27 0x557486421238 in pfs_spawn_thread /home/nik/mariadb/storage/perfschema/pfs.cc:2201:3
 
    #28 0x7f4b4f09ebb4  (/usr/lib/libc.so.6+0x85bb4) (BuildId: 4a4bec3d95a1804443e852958fe59ed461135ce9)
 
 
 
previously allocated by thread T5 here:
 
    #0 0x557484aa9eb9 in malloc (/home/nik/mariadb/bld/sql/mariadbd+0x1f38eb9) (BuildId: c39e11a9b9b66482)
 
    #1 0x55748725fa86 in my_malloc /home/nik/mariadb/mysys/my_malloc.c:91:29
 
    #2 0x557487235f65 in root_alloc /home/nik/mariadb/mysys/my_alloc.c:66:10
 
    #3 0x557487237339 in alloc_root /home/nik/mariadb/mysys/my_alloc.c:332:29
 
    #4 0x55748573e0a1 in Query_arena::memdup_w_gap(void const*, unsigned long, unsigned long) /home/nik/mariadb/sql/sql_class.h:1236:9
 
    #5 0x557485705b99 in alloc_query(THD*, char const*, unsigned long) /home/nik/mariadb/sql/sql_parse.cc:2727:30
 
    #6 0x5574852f63d0 in sp_instr_stmt::execute(THD*, unsigned int*) /home/nik/mariadb/sql/sp_head.cc:3750:14
 
    #7 0x5574852e30ff in sp_head::execute(THD*, bool) /home/nik/mariadb/sql/sp_head.cc:1459:20
 
    #8 0x5574852e9c4a in sp_head::execute_function(THD*, Item**, unsigned int, Field*, sp_rcontext**, Query_arena*) /home/nik/mariadb/sql/sp_head.cc:2191:3
 
    #9 0x557484d8e5b4 in Item_sp::execute_impl(THD*, Item**, unsigned int) /home/nik/mariadb/sql/item.cc:2928:26
 
    #10 0x557484d8d7b6 in Item_sp::execute(THD*, bool*, Item**, unsigned int) /home/nik/mariadb/sql/item.cc:2842:7
 
    #11 0x557484e595c6 in Item_func_sp::execute() /home/nik/mariadb/sql/item_func.cc:6654:19
 
    #12 0x557484e7c478 in Item_func_sp::val_int() /home/nik/mariadb/sql/item_func.h:3891:9
 
    #13 0x557485f1dbc5 in Type_handler::Item_send_long(Item*, Protocol*, st_value*) const /home/nik/mariadb/sql/sql_type.cc:7487:22
 
    #14 0x557485f47a2c in Type_handler_long::Item_send(Item*, Protocol*, st_value*) const /home/nik/mariadb/sql/sql_type.h:5701:12
 
    #15 0x557484b2ead1 in Item::send(Protocol*, st_value*) /home/nik/mariadb/sql/item.h:1235:28
 
    #16 0x5574852441bb in Protocol::send_result_set_row(List<Item>*) /home/nik/mariadb/sql/protocol.cc:1332:15
 
    #17 0x55748544bb48 in select_send::send_data(List<Item>&) /home/nik/mariadb/sql/sql_class.cc:3102:17
 
    #18 0x557485948212 in select_result_sink::send_data_with_check(List<Item>&, st_select_lex_unit*, unsigned long long) /home/nik/mariadb/sql/sql_class.h:5747:12
 
    #19 0x557485892433 in JOIN::exec_inner() /home/nik/mariadb/sql/sql_select.cc:4754:22
 
    #20 0x557485890ac2 in JOIN::exec() /home/nik/mariadb/sql/sql_select.cc:4666:3
 
    #21 0x55748581d13e 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/nik/mariadb/sql/sql_select.cc:5146:9
 
    #22 0x55748581c42c in handle_select(THD*, LEX*, select_result*, unsigned long long) /home/nik/mariadb/sql/sql_select.cc:608:10
 
    #23 0x557485726b39 in execute_sqlcom_select(THD*, TABLE_LIST*) /home/nik/mariadb/sql/sql_parse.cc:6265:12
 
    #24 0x55748571272c in mysql_execute_command(THD*, bool) /home/nik/mariadb/sql/sql_parse.cc:3949:12
 
    #25 0x5574857027be in mysql_parse(THD*, char*, unsigned int, Parser_state*) /home/nik/mariadb/sql/sql_parse.cc:8000:18
 
    #26 0x5574856fcff1 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /home/nik/mariadb/sql/sql_parse.cc:1894:7
 
    #27 0x557485703ab4 in do_command(THD*, bool) /home/nik/mariadb/sql/sql_parse.cc:1407:17
 
    #28 0x557485c91684 in do_handle_one_connection(CONNECT*, bool) /home/nik/mariadb/sql/sql_connect.cc:1416:11
 
    #29 0x557485c90e3e in handle_one_connection /home/nik/mariadb/sql/sql_connect.cc:1318:5
 
 
 
Thread T5 created by T0 here:
 
    #0 0x557484a1da58 in pthread_create (/home/nik/mariadb/bld/sql/mariadbd+0x1eaca58) (BuildId: c39e11a9b9b66482)
 
    #1 0x55748642180c in my_thread_create(unsigned long*, pthread_attr_t const*, void* (*)(void*), void*) /home/nik/mariadb/storage/perfschema/my_thread.h:52:10
 
    #2 0x55748642179b in pfs_spawn_thread_v1 /home/nik/mariadb/storage/perfschema/pfs.cc:2252:15
 
    #3 0x557484af6282 in inline_mysql_thread_create(unsigned int, unsigned long*, pthread_attr_t const*, void* (*)(void*), void*) /home/nik/mariadb/include/mysql/psi/mysql_thread.h:1139:11
 
    #4 0x557484b03171 in create_thread_to_handle_connection(CONNECT*) /home/nik/mariadb/sql/mysqld.cc:6125:19
 
    #5 0x557484b0355a in create_new_thread(CONNECT*) /home/nik/mariadb/sql/mysqld.cc:6184:3
 
    #6 0x557484b03a57 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /home/nik/mariadb/sql/mysqld.cc:6246:5
 
    #7 0x557484b023e8 in handle_connections_sockets() /home/nik/mariadb/sql/mysqld.cc:6370:9
 
    #8 0x557484af9489 in mysqld_main(int, char**) /home/nik/mariadb/sql/mysqld.cc:6020:3
 
    #9 0x557484af0cf1 in main /home/nik/mariadb/sql/main.cc:34:10
 
    #10 0x7f4b4f03c78f  (/usr/lib/libc.so.6+0x2378f) (BuildId: 4a4bec3d95a1804443e852958fe59ed461135ce9)
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /home/nik/mariadb/sql/log.cc:7700:25 in binlog_online_alter_end_trans(THD*, bool, bool)
 
Shadow bytes around the buggy address:
 
  0x0c4a8002c3b0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c4a8002c3c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c4a8002c3d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c4a8002c3e0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c4a8002c3f0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c4a8002c400: fd fd fd fd fd[fd]fd fd fd fd fd fd fd fd fd fd
 
  0x0c4a8002c410: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c4a8002c420: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c4a8002c430: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c4a8002c440: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c4a8002c450: 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
 
==1178012==ABORTING
 
----------SERVER LOG END-------------

A funny thing is, it doesn't fail under -rr=-chaos at all

Comment by Sergei Golubchik [ 2023-05-02 ]

0df42d9229f is ok to push. But please edit the commit comment to avoid calling stored functions "UDF". UDF is in sql_udf.cc and udf.test.

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