[MDEV-23467] SIGSEGV in fill_record/fill_record_n_invoke_before_triggers on INSERT DELAYED Created: 2020-08-13  Updated: 2020-10-06  Resolved: 2020-08-25

Status: Closed
Project: MariaDB Server
Component/s: Data Manipulation - Insert
Affects Version/s: 10.3, 10.4
Fix Version/s: 10.3.26, 10.4.16

Type: Bug Priority: Critical
Reporter: Roel Van de Paar Assignee: Aleksey Midenkov
Resolution: Fixed Votes: 0
Labels: affects-tests, not-10.1, not-10.2, not-10.5

Issue Links:
Relates
relates to MDEV-14871 Server crashes in fill_record / fill_... Closed

 Description   

Though there are many other bugs with similar frames in their stack, I could not locate any open bug that matched this scenario. Closest one was MDEV-14871 (closed)

USE test;
 
CREATE TABLE t (a INT, KEY(a)) ENGINE=MEMORY WITH SYSTEM VERSIONING;
 
INSERT DELAYED INTO t VALUES (1);

Leads to:

10.4.15 eae968f62d285de97ed607c87bc131cd863d5d03 (Debug)

 
Core was generated by `/test/MD110820-mariadb-10.4.15-linux-x86_64-dbg/bin/mysqld --no-defaults --core'.
 
Program terminated with signal SIGSEGV, Segmentation fault.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
[Current thread is 1 (Thread 0x14d032a7f700 (LWP 1335577))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055b3f0e5c8a6 in my_write_core (sig=sig@entry=11) at /test/10.4_dbg/mysys/stacktrace.c:482
 
#2  0x000055b3f05d8cdc in handle_fatal_signal (sig=11) at /test/10.4_dbg/sql/signal_handler.cc:343
 
#3  <signal handler called>
 
#4  fill_record (thd=thd@entry=0x14d00b015070, table=table@entry=0x14d00b06e748, ptr=0x14d00b06f528, ptr@entry=0x14d00b06f518, values=@0x14d00b06dca8: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14d00b06dd58, last = 0x14d00b06dd58, elements = 1}, <No data fields>}, ignore_errors=ignore_errors@entry=false, use_value=use_value@entry=false) at /test/10.4_dbg/sql/sql_base.cc:8798
 
#5  0x000055b3f02afdd5 in fill_record_n_invoke_before_triggers (thd=thd@entry=0x14d00b015070, table=table@entry=0x14d00b06e748, ptr=0x14d00b06f518, values=@0x14d00b06dca8: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14d00b06dd58, last = 0x14d00b06dd58, elements = 1}, <No data fields>}, ignore_errors=ignore_errors@entry=false, event=event@entry=TRG_EVENT_INSERT) at /test/10.4_dbg/sql/sql_base.cc:8862
 
#6  0x000055b3f02f089f in mysql_insert (thd=thd@entry=0x14d00b015070, table_list=0x14d00b06d178, fields=@0x14d00b019e48: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x55b3f1aa5000 <end_of_list>, last = 0x14d00b019e48, elements = 0}, <No data fields>}, values_list=@0x14d00b019e90: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14d00b06dd68, last = 0x14d00b06dd68, elements = 1}, <No data fields>}, update_fields=@0x14d00b019e78: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x55b3f1aa5000 <end_of_list>, last = 0x14d00b019e78, elements = 0}, <No data fields>}, update_values=@0x14d00b019e60: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x55b3f1aa5000 <end_of_list>, last = 0x14d00b019e60, elements = 0}, <No data fields>}, duplic=<optimized out>, ignore=<optimized out>) at /test/10.4_dbg/sql/sql_insert.cc:1020
 
#7  0x000055b3f0328a63 in mysql_execute_command (thd=thd@entry=0x14d00b015070) at /test/10.4_dbg/sql/sql_parse.cc:4519
 
#8  0x000055b3f0330090 in mysql_parse (thd=thd@entry=0x14d00b015070, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14d032a7e460, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_parse.cc:7896
 
#9  0x000055b3f0332920 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14d00b015070, packet=packet@entry=0x14d00b057071 "INSERT DELAYED INTO t VALUES (1)", packet_length=packet_length@entry=32, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_parse.cc:1834
 
#10 0x000055b3f033635b in do_command (thd=0x14d00b015070) at /test/10.4_dbg/sql/sql_parse.cc:1352
 
#11 0x000055b3f04628b6 in do_handle_one_connection (connect=connect@entry=0x14d02f835790) at /test/10.4_dbg/sql/sql_connect.cc:1412
 
#12 0x000055b3f04629d6 in handle_one_connection (arg=0x14d02f835790) at /test/10.4_dbg/sql/sql_connect.cc:1316
 
#13 0x000014d031c7d6db in start_thread (arg=0x14d032a7f700) at pthread_create.c:463
 
#14 0x000014d030df7a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.3.25 (dbg), 10.3.25 (opt), 10.4.15 (dbg), 10.4.15 (opt)

Bug confirmed not present in:
MariaDB: 10.1.47 (dbg), 10.1.47 (opt), 10.2.34 (dbg), 10.2.34 (opt), 10.5.6 (dbg), 10.5.6 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

 Comments   
Comment by Roel Van de Paar [ 2020-08-13 ]

InnoDB outcome

10.4.15 eae968f62d285de97ed607c87bc131cd863d5d03 (Debug)

 
10.4.15>USE test;
 
Database changed
 
10.4.15>CREATE TABLE t (a INT, KEY(a)) ENGINE=InnoDB WITH SYSTEM VERSIONING;
 
Query OK, 0 rows affected (0.018 sec)
 
10.4.15>INSERT DELAYED INTO t VALUES (1);
 
ERROR 1616 (HY000): DELAYED option not supported for table 't'

Aria gives the same ERROR 1616.

MyISAM also crashes:

10.4.15 eae968f62d285de97ed607c87bc131cd863d5d03 (Debug)

 
10.4.15>USE test;
 
Database changed
 
10.4.15>CREATE TABLE t (a INT, KEY(a)) ENGINE=MyISAM WITH SYSTEM VERSIONING;
 
Query OK, 0 rows affected (0.005 sec)
 
10.4.15>INSERT DELAYED INTO t VALUES (1);
 
ERROR 2013 (HY000): Lost connection to MySQL server during query

Comment by Roel Van de Paar [ 2020-08-13 ]

This bug is seen very frequently in my runs

Comment by Aleksey Midenkov [ 2020-08-24 ]

Roel Did you try to reproduce under ASAN/Valgrind?

Comment by Aleksey Midenkov [ 2020-08-24 ]

The question is applicable to MDEV-23455 as well.

Comment by Aleksey Midenkov [ 2020-08-24 ]

Roel Can you please link to similar traces bugs?

"(in optimized builds)" in title is not true anymore?

Comment by Roel Van de Paar [ 2020-08-24 ]

ASAN on 10.4.14, relevant output (original testcase):

10.4.14 ed1434df88270ebe70ae412b5b723920b6b4e0e8 (Optimized)

 
/test/10.4_opt/sql/sql_base.cc:8793:46: runtime error: member call on null pointer of type 'struct Item'
 
    #0 0x5598963769ef in fill_record(THD*, TABLE*, Field**, List<Item>&, bool, bool) /test/10.4_opt/sql/sql_base.cc:8793
 
    #1 0x559896376d1c in fill_record_n_invoke_before_triggers(THD*, TABLE*, Field**, List<Item>&, bool, trg_event_type) /test/10.4_opt/sql/sql_base.cc:8857
 
    #2 0x5598964ed8b4 in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool) /test/10.4_opt/sql/sql_insert.cc:1020
 
    #3 0x55989662fd0c in mysql_execute_command(THD*) /test/10.4_opt/sql/sql_parse.cc:4528
 
    #4 0x55989665f39b in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /test/10.4_opt/sql/sql_parse.cc:7901
 
    #5 0x55989666cefd in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /test/10.4_opt/sql/sql_parse.cc:1841
 
    #6 0x559896676937 in do_command(THD*) /test/10.4_opt/sql/sql_parse.cc:1359
 
    #7 0x559896c814ae in do_handle_one_connection(CONNECT*) /test/10.4_opt/sql/sql_connect.cc:1412
 
    #8 0x559896c81d92 in handle_one_connection /test/10.4_opt/sql/sql_connect.cc:1316
 
    #9 0x1493f76536da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
 
    #10 0x1493f526ca3e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x121a3e)
 
 
 
ASAN:DEADLYSIGNAL
 
=================================================================
 
==2375337==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000000 (pc 0x559896375893 bp 0x1493d0f7c090 sp 0x1493d0f7bf20 T31)
 
==2375337==The signal is caused by a READ memory access.
 
==2375337==Hint: address points to the zero page.
 
    #0 0x559896375892 in fill_record(THD*, TABLE*, Field**, List<Item>&, bool, bool) /test/10.4_opt/sql/sql_base.cc:8793
 
    #1 0x559896376d1c in fill_record_n_invoke_before_triggers(THD*, TABLE*, Field**, List<Item>&, bool, trg_event_type) /test/10.4_opt/sql/sql_base.cc:8857
 
    #2 0x5598964ed8b4 in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool) /test/10.4_opt/sql/sql_insert.cc:1020
 
    #3 0x55989662fd0c in mysql_execute_command(THD*) /test/10.4_opt/sql/sql_parse.cc:4528
 
    #4 0x55989665f39b in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /test/10.4_opt/sql/sql_parse.cc:7901
 
    #5 0x55989666cefd in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /test/10.4_opt/sql/sql_parse.cc:1841
 
    #6 0x559896676937 in do_command(THD*) /test/10.4_opt/sql/sql_parse.cc:1359
 
    #7 0x559896c814ae in do_handle_one_connection(CONNECT*) /test/10.4_opt/sql/sql_connect.cc:1412
 
    #8 0x559896c81d92 in handle_one_connection /test/10.4_opt/sql/sql_connect.cc:1316
 
    #9 0x1493f76536da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
 
    #10 0x1493f526ca3e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x121a3e)
 
 
 
AddressSanitizer can not provide additional info.
 
SUMMARY: AddressSanitizer: SEGV /test/10.4_opt/sql/sql_base.cc:8793 in fill_record(THD*, TABLE*, Field**, List<Item>&, bool, bool)
 
Thread T31 created by T0 here:
 
    #0 0x559895fe220f in __interceptor_pthread_create (/test/ASAN_MD290520-mariadb-10.4.14-linux-x86_64-opt/bin/mysqld+0x4e6020f)
 
    #1 0x5598960dd43b in inline_mysql_thread_create /test/10.4_opt/include/mysql/psi/mysql_thread.h:1275
 
    #2 0x5598960dd43b in create_thread_to_handle_connection(CONNECT*) /test/10.4_opt/sql/mysqld.cc:6261
 
    #3 0x5598960efe29 in create_new_thread(CONNECT*) /test/10.4_opt/sql/mysqld.cc:6329
 
    #4 0x5598960f0688 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /test/10.4_opt/sql/mysqld.cc:6427
 
    #5 0x5598960f1d0b in handle_connections_sockets() /test/10.4_opt/sql/mysqld.cc:6585
 
    #6 0x5598960f42a4 in mysqld_main(int, char**) /test/10.4_opt/sql/mysqld.cc:5917
 
    #7 0x1493f516cb96 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x21b96)
 
 
 
==2375337==ABORTING

Comment by Roel Van de Paar [ 2020-08-25 ]
Comment by Aleksey Midenkov [ 2020-08-25 ]

If it is applicable to any build type the notice about optimized builds in title is misleading. Removing it. Please test ASAN debug first before optimized. This is important if it is not reproducible in debug build.

Comment by Roel Van de Paar [ 2020-08-25 ]

The output on ASAN debug is similar.

10.4.14 ed1434df88270ebe70ae412b5b723920b6b4e0e8 (Debug)

 
/test/10.4_dbg/sql/sql_base.cc:8793:46: runtime error: member call on null pointer of type 'struct Item'
 
    #0 0x55563f1adb4f in fill_record(THD*, TABLE*, Field**, List<Item>&, bool, bool) /test/10.4_dbg/sql/sql_base.cc:8793
 
    #1 0x55563f1aee52 in fill_record_n_invoke_before_triggers(THD*, TABLE*, Field**, List<Item>&, bool, trg_event_type) /test/10.4_dbg/sql/sql_base.cc:8857
 
    #2 0x55563f3635bf in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool) /test/10.4_dbg/sql/sql_insert.cc:1020
 
    #3 0x55563f4f87a7 in mysql_execute_command(THD*) /test/10.4_dbg/sql/sql_parse.cc:4528
 
    #4 0x55563f526c84 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /test/10.4_dbg/sql/sql_parse.cc:7901
 
    #5 0x55563f539cf9 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /test/10.4_dbg/sql/sql_parse.cc:1841
 
    #6 0x55563f5507e2 in do_command(THD*) /test/10.4_dbg/sql/sql_parse.cc:1359
 
    #7 0x55563fc852cc in do_handle_one_connection(CONNECT*) /test/10.4_dbg/sql/sql_connect.cc:1412
 
    #8 0x55563fc859f0 in handle_one_connection /test/10.4_dbg/sql/sql_connect.cc:1316
 
    #9 0x14638f0256da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
 
    #10 0x14638cc3ea3e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x121a3e)
 
 
 
ASAN:DEADLYSIGNAL
 
=================================================================
 
==547290==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000000 (pc 0x55563f1ae814 bp 0x146368741db0 sp 0x146368741c00 T31)
 
==547290==The signal is caused by a READ memory access.
 
==547290==Hint: address points to the zero page.
 
    #0 0x55563f1ae813 in fill_record(THD*, TABLE*, Field**, List<Item>&, bool, bool) /test/10.4_dbg/sql/sql_base.cc:8793
 
    #1 0x55563f1aee52 in fill_record_n_invoke_before_triggers(THD*, TABLE*, Field**, List<Item>&, bool, trg_event_type) /test/10.4_dbg/sql/sql_base.cc:8857
 
    #2 0x55563f3635bf in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool) /test/10.4_dbg/sql/sql_insert.cc:1020
 
    #3 0x55563f4f87a7 in mysql_execute_command(THD*) /test/10.4_dbg/sql/sql_parse.cc:4528
 
    #4 0x55563f526c84 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /test/10.4_dbg/sql/sql_parse.cc:7901
 
    #5 0x55563f539cf9 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /test/10.4_dbg/sql/sql_parse.cc:1841
 
    #6 0x55563f5507e2 in do_command(THD*) /test/10.4_dbg/sql/sql_parse.cc:1359
 
    #7 0x55563fc852cc in do_handle_one_connection(CONNECT*) /test/10.4_dbg/sql/sql_connect.cc:1412
 
    #8 0x55563fc859f0 in handle_one_connection /test/10.4_dbg/sql/sql_connect.cc:1316
 
    #9 0x14638f0256da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
 
    #10 0x14638cc3ea3e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x121a3e)
 
 
 
AddressSanitizer can not provide additional info.
 
SUMMARY: AddressSanitizer: SEGV /test/10.4_dbg/sql/sql_base.cc:8793 in fill_record(THD*, TABLE*, Field**, List<Item>&, bool, bool)
 
Thread T31 created by T0 here:
 
    #0 0x55563ed7edbf in pthread_create (/test/ASAN_MD290520-mariadb-10.4.14-linux-x86_64-dbg/bin/mysqld+0x5977dbf)
 
    #1 0x555642e4e89e in spawn_thread_noop /test/10.4_dbg/mysys/psi_noop.c:187
 
    #2 0x55563ee8049c in inline_mysql_thread_create /test/10.4_dbg/include/mysql/psi/mysql_thread.h:1275
 
    #3 0x55563ee8049c in create_thread_to_handle_connection(CONNECT*) /test/10.4_dbg/sql/mysqld.cc:6261
 
    #4 0x55563ee9387a in create_new_thread(CONNECT*) /test/10.4_dbg/sql/mysqld.cc:6329
 
    #5 0x55563ee93e38 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /test/10.4_dbg/sql/mysqld.cc:6427
 
    #6 0x55563ee95b51 in handle_connections_sockets() /test/10.4_dbg/sql/mysqld.cc:6585
 
    #7 0x55563ee993b9 in mysqld_main(int, char**) /test/10.4_dbg/sql/mysqld.cc:5917
 
    #8 0x55563ee663ac in main /test/10.4_dbg/sql/main.cc:25
 
    #9 0x14638cb3eb96 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x21b96)
 
 
 
==547290==ABORTING

Comment by Aleksey Midenkov [ 2020-08-25 ]

Thanks! I just wanted to stress that optimized stacks are unimportant when it is reproducible on debug. Reproduces for me.

Comment by Aleksey Midenkov [ 2020-08-25 ]

Reproducible without System Versioning:

create table t (a int, b int invisible);
 
insert delayed into t values (1);
 
drop table t;

Comment by Aleksey Midenkov [ 2020-08-25 ]

Correction, please forget this:

I just wanted to stress that optimized stacks are unimportant when it is reproducible on debug.

And take into accout this:

When debug and non-debug builds indeed fail the exact same way, with the debug stack trace being just fuller and better resolved, then of course, it is sufficient to paste only the best one available.

© elenst

For me as a developer it is important to know whether it is reproducible or not on debug.

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