[MDEV-25237] crash after setting global session_track_system_variables to an invalid value Created: 2021-03-24  Updated: 2023-07-20  Resolved: 2023-07-20

Status: Closed
Project: MariaDB Server
Component/s: Variables
Affects Version/s: 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10, 10.11, 11.0, 11.1
Fix Version/s: 10.4.31, 10.5.22, 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: Roel Van de Paar Assignee: Oleksandr Byelkin
Resolution: Fixed Votes: 0
Labels: affects-tests

Issue Links:
Duplicate
is duplicated by MDEV-31534 Wrong value assigned to session_track... Closed
Relates
relates to MDEV-22134 handle_fatal_signal (sig=11) in __str... Closed

 Description   

SET sql_mode='';  # Also try with ONLY_FULL_GROUP_BY
SET 'a';
SET collation_connection=utf6_unicode_520_ci;
SET GLOBAL session_track_system_variables='a';
SET GLOBAL event_scheduler=1;

Leads to:

10.6.0 cb545f11169d2425316d96feafc78ac841950e43 (Debug)

mysqld: /data/10.6_dbg/sql/session_tracker.cc:334: void Session_sysvars_tracker::init(THD*): Assertion `global_system_variables.session_track_system_variables' failed.

10.6.0 cb545f11169d2425316d96feafc78ac841950e43 (Debug)

Core was generated by `/test/MD240321-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
[Current thread is 1 (Thread 0x1549d06ca700 (LWP 1961238))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x0000559464766dd1 in my_write_core (sig=sig@entry=6) at /data/10.6_dbg/mysys/stacktrace.c:424
#2  0x0000559463f07d31 in handle_fatal_signal (sig=6) at /data/10.6_dbg/sql/signal_handler.cc:331
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  0x00001549dbb2f859 in __GI_abort () at abort.c:79
#6  0x00001549dbb2f729 in __assert_fail_base (fmt=0x1549dbcc5588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5594648b3758 "global_system_variables.session_track_system_variables", file=0x5594648b3498 "/data/10.6_dbg/sql/session_tracker.cc", line=334, function=<optimized out>) at assert.c:92
#7  0x00001549dbb40f36 in __GI___assert_fail (assertion=assertion@entry=0x5594648b3758 "global_system_variables.session_track_system_variables", file=file@entry=0x5594648b3498 "/data/10.6_dbg/sql/session_tracker.cc", line=line@entry=334, function=function@entry=0x5594648b36c0 "void Session_sysvars_tracker::init(THD*)") at assert.c:101
#8  0x0000559463b4929e in Session_sysvars_tracker::init (this=<optimized out>, thd=0x15498001df98) at /data/10.6_dbg/sql/session_tracker.cc:334
#9  0x0000559463c53b95 in plugin_thdvar_init (thd=thd@entry=0x15498001df98) at /data/10.6_dbg/sql/sql_plugin.cc:3251
#10 0x0000559463bd4e9a in THD::init (this=this@entry=0x15498001df98) at /data/10.6_dbg/sql/sql_class.cc:1255
#11 0x0000559463bde05b in THD::THD (this=0x15498001df98, id=<optimized out>, is_wsrep_applier=<optimized out>) at /data/10.6_dbg/sql/sql_class.cc:858
#12 0x000055946412c7d3 in Event_scheduler::start (this=0x5594667ddc50, err_no=err_no@entry=0x1549d06c8d7c) at /data/10.6_dbg/sql/sql_list.h:680
#13 0x0000559463d79695 in Events::start (err_no=err_no@entry=0x1549d06c8d7c) at /data/10.6_dbg/sql/events.cc:1128
#14 0x0000559463db8b75 in event_scheduler_update (self=<optimized out>, thd=<optimized out>, type=<optimized out>) at /data/10.6_dbg/sql/sys_vars.cc:1125
#15 0x0000559463b4af30 in sys_var::update (this=0x559465237da0 <Sys_event_scheduler>, thd=0x154980000db8, var=0x154980013cf8) at /data/10.6_dbg/sql/set_var.cc:207
#16 0x0000559463b4b447 in set_var::update (this=<optimized out>, thd=<optimized out>) at /data/10.6_dbg/sql/set_var.cc:859
#17 0x0000559463b4c792 in sql_set_variables (thd=thd@entry=0x154980000db8, var_list=var_list@entry=0x154980005eb8, free=free@entry=true) at /data/10.6_dbg/sql/set_var.cc:746
#18 0x0000559463c4aeab in mysql_execute_command (thd=thd@entry=0x154980000db8) at /data/10.6_dbg/sql/sql_parse.cc:5017
#19 0x0000559463c34264 in mysql_parse (thd=thd@entry=0x154980000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1549d06c9410) at /data/10.6_dbg/sql/sql_parse.cc:8004
#20 0x0000559463c42e6a in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x154980000db8, packet=packet@entry=0x15498000b359 "SET GLOBAL event_scheduler=1", packet_length=packet_length@entry=28, blocking=blocking@entry=true) at /data/10.6_dbg/sql/sql_class.h:1331
#21 0x0000559463c46245 in do_command (thd=0x154980000db8, blocking=blocking@entry=true) at /data/10.6_dbg/sql/sql_parse.cc:1399
#22 0x0000559463d9f466 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5594667b5888, put_in_cache=put_in_cache@entry=true) at /data/10.6_dbg/sql/sql_connect.cc:1410
#23 0x0000559463d9fa6b in handle_one_connection (arg=arg@entry=0x5594667b5888) at /data/10.6_dbg/sql/sql_connect.cc:1312
#24 0x0000559464249eb9 in pfs_spawn_thread (arg=0x5594666d9f28) at /data/10.6_dbg/storage/perfschema/pfs.cc:2201
#25 0x00001549dc03d609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#26 0x00001549dbc2c293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.6.0 cb545f11169d2425316d96feafc78ac841950e43 (Optimized)

Core was generated by `/test/MD240321-mariadb-10.6.0-linux-x86_64-opt/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:56
[Current thread is 1 (Thread 0x151620d52700 (LWP 2158236))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x000055771cb353bf in my_write_core (sig=sig@entry=11) at /data/10.6_opt/mysys/stacktrace.c:424
#2  0x000055771c5ba830 in handle_fatal_signal (sig=11) at /data/10.6_opt/sql/signal_handler.cc:331
#3  <signal handler called>
#4  __strlen_avx2 () at ../sysdeps/x86_64/multiarch/strlen-avx2.S:65
#5  0x000055771cb31b71 in my_strdup (key=key@entry=0, from=0x0, my_flags=my_flags@entry=65552) at /data/10.6_opt/mysys/my_malloc.c:230
#6  0x000055771c2f677a in Session_sysvars_tracker::init (this=<optimized out>, thd=0x1515d001a278) at /data/10.6_opt/sql/session_tracker.cc:335
#7  0x000055771c35db00 in THD::init (this=this@entry=0x1515d001a278) at /data/10.6_opt/sql/sql_class.cc:1255
#8  0x000055771c3631ec in THD::THD (this=0x1515d001a278, id=<optimized out>, is_wsrep_applier=<optimized out>) at /data/10.6_opt/sql/sql_class.cc:858
#9  0x000055771c748f82 in Event_scheduler::start (this=0x55771f56a540, err_no=err_no@entry=0x151620d50e5c) at /data/10.6_opt/sql/sql_list.h:680
#10 0x000055771c49a676 in Events::start (err_no=err_no@entry=0x151620d50e5c) at /data/10.6_opt/sql/events.cc:1128
#11 0x000055771c4c6bf9 in event_scheduler_update (self=<optimized out>, thd=<optimized out>, type=<optimized out>) at /data/10.6_opt/sql/sys_vars.cc:1141
#12 0x000055771c2f7d3a in sys_var::update (this=0x55771d4c8f60 <Sys_event_scheduler>, thd=0x1515d0000c58, var=0x1515d0010608) at /data/10.6_opt/include/mysql/psi/mysql_thread.h:795
#13 0x000055771c2f81bb in set_var::update (this=<optimized out>, thd=<optimized out>) at /data/10.6_opt/sql/set_var.cc:859
#14 0x000055771c2f9369 in sql_set_variables (thd=thd@entry=0x1515d0000c58, var_list=var_list@entry=0x1515d0005b98, free=free@entry=true) at /data/10.6_opt/sql/set_var.cc:746
#15 0x000055771c3b509f in mysql_execute_command (thd=0x1515d0000c58) at /data/10.6_opt/sql/sql_parse.cc:5017
#16 0x000055771c3a4074 in mysql_parse (thd=0x1515d0000c58, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /data/10.6_opt/sql/sql_parse.cc:8004
#17 0x000055771c3aff95 in dispatch_command (command=COM_QUERY, thd=0x1515d0000c58, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /data/10.6_opt/sql/sql_class.h:1331
#18 0x000055771c3b1fe0 in do_command (thd=0x1515d0000c58, blocking=blocking@entry=true) at /data/10.6_opt/sql/sql_parse.cc:1399
#19 0x000055771c4b3f27 in do_handle_one_connection (connect=<optimized out>, put_in_cache=true) at /data/10.6_opt/sql/sql_connect.cc:1410
#20 0x000055771c4b428d in handle_one_connection (arg=arg@entry=0x55771f569698) at /data/10.6_opt/sql/sql_connect.cc:1312
#21 0x000055771c833239 in pfs_spawn_thread (arg=0x55771f4e5298) at /data/10.6_opt/storage/perfschema/pfs.cc:2201
#22 0x000015162b68b609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#23 0x000015162b27a293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.3.29 7d5ec9f1aeec1ea8d00a0aa5bfec521948cfb8be (Optimized)

Core was generated by `/test/MD240321-mariadb-10.3.29-linux-x86_64-opt/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:56
[Current thread is 1 (Thread 0x147a3415c700 (LWP 2176807))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x000055613b70eb7f in my_write_core (sig=sig@entry=11) at /data/10.3_opt/mysys/stacktrace.c:386
#2  0x000055613b1a7eb8 in handle_fatal_signal (sig=11) at /data/10.3_opt/sql/signal_handler.cc:343
#3  <signal handler called>
#4  __strlen_avx2 () at ../sysdeps/x86_64/multiarch/strlen-avx2.S:65
#5  0x000055613b70b2bd in my_strdup (from=0x0, my_flags=my_flags@entry=65552) at /data/10.3_opt/mysys/my_malloc.c:243
#6  0x000055613af038f8 in Session_sysvars_tracker::init (this=<optimized out>, thd=0x1479e0018f48) at /data/10.3_opt/sql/session_tracker.cc:335
#7  0x000055613afbc683 in plugin_thdvar_init (thd=thd@entry=0x1479e0018f48) at /data/10.3_opt/sql/sql_plugin.cc:3177
#8  0x000055613af64800 in THD::init (this=this@entry=0x1479e0018f48) at /data/10.3_opt/sql/sql_class.cc:1179
#9  0x000055613af657cb in THD::THD (this=0x1479e0018f48, id=<optimized out>, is_wsrep_applier=<optimized out>) at /data/10.3_opt/sql/sql_class.cc:803
#10 0x000055613b310ee0 in Event_scheduler::start (this=0x55613d997230, err_no=err_no@entry=0x147a34159bfc) at /data/10.3_opt/sql/sql_list.h:622
#11 0x000055613b0878a6 in Events::start (err_no=err_no@entry=0x147a34159bfc) at /data/10.3_opt/sql/events.cc:1111
#12 0x000055613b0b09b1 in event_scheduler_update (self=<optimized out>, thd=<optimized out>, type=<optimized out>) at /data/10.3_opt/sql/sys_vars.cc:1058
#13 0x000055613af04ee2 in sys_var::update (this=0x55613bef4660 <Sys_event_scheduler>, thd=0x1479e0000c48, var=0x1479e000f7c0) at /data/10.3_opt/include/mysql/psi/mysql_thread.h:788
#14 0x000055613af053cb in set_var::update (this=<optimized out>, thd=<optimized out>) at /data/10.3_opt/sql/set_var.cc:837
#15 0x000055613af06649 in sql_set_variables (thd=thd@entry=0x1479e0000c48, var_list=var_list@entry=0x1479e0005778, free=free@entry=true) at /data/10.3_opt/sql/set_var.cc:740
#16 0x000055613afae786 in mysql_execute_command (thd=<optimized out>) at /data/10.3_opt/sql/sql_parse.cc:4936
#17 0x000055613afb2f57 in mysql_parse (thd=0x1479e0000c48, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/10.3_opt/sql/sql_parse.cc:7871
#18 0x000055613afb52f5 in dispatch_command (command=COM_QUERY, thd=0x1479e0000c48, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/10.3_opt/sql/sql_class.h:1152
#19 0x000055613afb730d in do_command (thd=0x1479e0000c48) at /data/10.3_opt/sql/sql_parse.cc:1398
#20 0x000055613b09e986 in do_handle_one_connection (connect=connect@entry=0x55613d9c2388) at /data/10.3_opt/sql/sql_connect.cc:1403
#21 0x000055613b09eb5f in handle_one_connection (arg=0x55613d9c2388) at /data/10.3_opt/sql/sql_connect.cc:1308
#22 0x0000147a3e02f609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#23 0x0000147a3dc26293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.3.29 (dbg), 10.3.29 (opt), 10.4.19 (dbg), 10.4.19 (opt), 10.5.10 (dbg), 10.5.10 (opt), 10.6.0 (dbg), 10.6.0 (opt)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.38 (dbg), 10.2.38 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.33 (dbg), 5.7.33 (opt), 8.0.23 (dbg), 8.0.23 (opt)



 Comments   
Comment by Roel Van de Paar [ 2021-03-24 ]

Unique ID's seen so far:

SIGSEGV|__strlen_avx2|my_strdup|Session_sysvars_tracker::init|THD::init
SIGSEGV|__strlen_avx2|my_strdup|Session_sysvars_tracker::init|plugin_thdvar_init
global_system_variables.session_track_system_variables|SIGABRT|Session_sysvars_tracker::init|plugin_thdvar_init|THD::init|THD::THD

Comment by Roel Van de Paar [ 2021-11-13 ]

SET GLOBAL session_track_system_variables='a';
SET GLOBAL event_scheduler=TRUE;

Leads to:

10.8.0 bc57ff7cf79504a198d4752b4748340a4afd886c (Debug)

mysqld: /test/10.8_dbg/sql/session_tracker.cc:334: void Session_sysvars_tracker::init(THD*): Assertion `global_system_variables.session_track_system_variables' failed.

10.8.0 bc57ff7cf79504a198d4752b4748340a4afd886c (Debug)

Core was generated by `/test/MD121121-mariadb-10.8.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
[Current thread is 1 (Thread 0x146ba85ed700 (LWP 2002561))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000146ba9a72859 in __GI_abort () at abort.c:79
#2  0x0000146ba9a72729 in __assert_fail_base (fmt=0x146ba9c08588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55cd70de2878 "global_system_variables.session_track_system_variables", file=0x55cd70de25e0 "/test/10.8_dbg/sql/session_tracker.cc", line=334, function=<optimized out>) at assert.c:92
#3  0x0000146ba9a83f36 in __GI___assert_fail (assertion=assertion@entry=0x55cd70de2878 "global_system_variables.session_track_system_variables", file=file@entry=0x55cd70de25e0 "/test/10.8_dbg/sql/session_tracker.cc", line=line@entry=334, function=function@entry=0x55cd70de27e0 "void Session_sysvars_tracker::init(THD*)") at assert.c:101
#4  0x000055cd70034904 in Session_sysvars_tracker::init (this=<optimized out>, thd=0x146b6401c658) at /test/10.8_dbg/sql/session_tracker.cc:334
#5  0x000055cd7015ae89 in plugin_thdvar_init (thd=thd@entry=0x146b6401c658) at /test/10.8_dbg/sql/sql_plugin.cc:3255
#6  0x000055cd700c3222 in THD::init (this=this@entry=0x146b6401c658) at /test/10.8_dbg/sql/sql_class.cc:1234
#7  0x000055cd700cc523 in THD::THD (this=0x146b6401c658, id=<optimized out>, is_wsrep_applier=<optimized out>) at /test/10.8_dbg/sql/sql_class.cc:849
#8  0x000055cd70626ce7 in Event_scheduler::start (this=0x55cd74470170, err_no=err_no@entry=0x146ba85ebd2c) at /test/10.8_dbg/sql/sql_list.h:680
#9  0x000055cd7028dee5 in Events::start (err_no=err_no@entry=0x146ba85ebd2c) at /test/10.8_dbg/sql/events.cc:1133
#10 0x000055cd702cee89 in event_scheduler_update (self=<optimized out>, thd=<optimized out>, type=<optimized out>) at /test/10.8_dbg/sql/sys_vars.cc:1142
#11 0x000055cd700366ce in sys_var::update (this=0x55cd7179b700 <Sys_event_scheduler>, thd=0x146b64000db8, var=0x146b64013f00) at /test/10.8_dbg/sql/set_var.cc:207
#12 0x000055cd70036bdb in set_var::update (this=<optimized out>, thd=<optimized out>) at /test/10.8_dbg/sql/set_var.cc:863
#13 0x000055cd70037f21 in sql_set_variables (thd=thd@entry=0x146b64000db8, var_list=var_list@entry=0x146b640060d8, free=free@entry=true) at /test/10.8_dbg/sql/set_var.cc:745
#14 0x000055cd7013e8f4 in mysql_execute_command (thd=thd@entry=0x146b64000db8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.8_dbg/sql/sql_parse.cc:5034
#15 0x000055cd70127cad in mysql_parse (thd=thd@entry=0x146b64000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x146ba85ec400) at /test/10.8_dbg/sql/sql_parse.cc:8028
#16 0x000055cd70136949 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x146b64000db8, packet=packet@entry=0x146b6400b879 "SET GLOBAL event_scheduler=TRUE", packet_length=packet_length@entry=31, blocking=blocking@entry=true) at /test/10.8_dbg/sql/sql_class.h:1360
#17 0x000055cd70139d83 in do_command (thd=0x146b64000db8, blocking=blocking@entry=true) at /test/10.8_dbg/sql/sql_parse.cc:1402
#18 0x000055cd702b3e2a in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55cd74468f38, put_in_cache=put_in_cache@entry=true) at /test/10.8_dbg/sql/sql_connect.cc:1418
#19 0x000055cd702b442f in handle_one_connection (arg=arg@entry=0x55cd74468f38) at /test/10.8_dbg/sql/sql_connect.cc:1312
#20 0x000055cd707344ce in pfs_spawn_thread (arg=0x55cd7437d568) at /test/10.8_dbg/storage/perfschema/pfs.cc:2201
#21 0x0000146ba9f81609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#22 0x0000146ba9b6f293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.2 Does not seem to crash but there is:

10.2.42 (Debug)

2021-11-13 18:55:32 23054982145792 [Note] /test/MD121121-mariadb-10.2.42-linux-x86_64-dbg/bin/mysqld: Shutdown complete
Warning: Memory not freed: 8
Warning:    8 bytes lost at 0x14f79c008b80, allocated by T@0 at mysys/my_malloc.c:229, sql/sys_vars.ic:527, sql/set_var.cc:208, sql/set_var.cc:837, sql/set_var.cc:738, sql/sql_parse.cc:4641, sql/sql_parse.cc:7793, sql/sql_parse.cc:1827
Memory lost: 8 bytes in 1 chunks
Warning:    8 bytes lost at 0x14f79c008b80, allocated by T@0 at mysys/my_malloc.c:229, sql/sys_vars.ic:527, sql/set_var.cc:208, sql/set_var.cc:837, sql/set_var.cc:738, sql/sql_parse.cc:4641, sql/sql_parse.cc:7793, sql/sql_parse.cc:1827
Memory lost: 8 bytes in 1 chunks

Bug confirmed present in:
MariaDB: 10.2.42 (dbg), 10.3.33 (dbg), 10.3.33 (opt), 10.4.23 (dbg), 10.4.23 (opt), 10.5.14 (dbg), 10.5.14 (opt), 10.6.6 (dbg), 10.6.6 (opt), 10.7.2 (dbg), 10.7.2 (opt), 10.8.0 (dbg), 10.8.0 (opt)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.42 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.36 (dbg), 5.7.36 (opt), 8.0.27 (dbg), 8.0.27 (opt)

Comment by Roel Van de Paar [ 2022-04-22 ]

New additional testcase with an partially new stack.

SET 'a';
SET collation_connection='a';
CHANGE MASTER TO master_host='a';
SET GLOBAL session_track_system_variables='a';

Leads to:

10.9.0 ef930dcad58ae6c3f334a32bd63e26c65fd66fa6 (Debug)

mysqld: /test/10.9_dbg/sql/session_tracker.cc:334: void Session_sysvars_tracker::init(THD*): Assertion `global_system_variables.session_track_system_variables' failed.

10.9.0 ef930dcad58ae6c3f334a32bd63e26c65fd66fa6 (Debug)

Core was generated by `/test/MD050422-mariadb-10.9.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
[Current thread is 1 (Thread 0x1521c41b3700 (LWP 358034))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00001521dc859859 in __GI_abort () at abort.c:79
#2  0x00001521dc859729 in __assert_fail_base (fmt=0x1521dc9ef588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x559905bfa978 "global_system_variables.session_track_system_variables", file=0x559905bfa6e0 "/test/10.9_dbg/sql/session_tracker.cc", line=334, function=<optimized out>) at assert.c:92
#3  0x00001521dc86b006 in __GI___assert_fail (assertion=assertion@entry=0x559905bfa978 "global_system_variables.session_track_system_variables", file=file@entry=0x559905bfa6e0 "/test/10.9_dbg/sql/session_tracker.cc", line=line@entry=334, function=function@entry=0x559905bfa8e0 "void Session_sysvars_tracker::init(THD*)") at assert.c:101
#4  0x0000559904e35522 in Session_sysvars_tracker::init (this=<optimized out>, thd=0x15218c000db8) at /test/10.9_dbg/sql/session_tracker.cc:334
#5  0x0000559904f5ce41 in plugin_thdvar_init (thd=thd@entry=0x15218c000db8) at /test/10.9_dbg/sql/sql_plugin.cc:3256
#6  0x0000559904ec48e0 in THD::init (this=this@entry=0x15218c000db8) at /test/10.9_dbg/sql/sql_class.cc:1235
#7  0x0000559904ec4ef7 in THD::change_user (this=this@entry=0x15218c000db8) at /test/10.9_dbg/sql/sql_class.cc:1433
#8  0x0000559904ec5109 in THD::reset_for_reuse (this=this@entry=0x15218c000db8) at /test/10.9_dbg/sql/sql_class.cc:1637
#9  0x00005599050b890e in CONNECT::create_thd (this=this@entry=0x559907a0b978, thd=0x15218c000db8) at /test/10.9_dbg/sql/sql_connect.cc:1527
#10 0x00005599050b9075 in do_handle_one_connection (connect=0x559907a0b978, connect@entry=0x5599079c4a58, put_in_cache=put_in_cache@entry=true) at /test/10.9_dbg/sql/sql_connect.cc:1438
#11 0x00005599050b932f in handle_one_connection (arg=arg@entry=0x5599079c4a58) at /test/10.9_dbg/sql/sql_connect.cc:1312
#12 0x00005599055437a5 in pfs_spawn_thread (arg=0x559907904e68) at /test/10.9_dbg/storage/perfschema/pfs.cc:2201
#13 0x00001521dcd6a609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#14 0x00001521dc956163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.2.44 (dbg), 10.2.44 (opt), 10.3.35 (dbg), 10.3.35 (opt), 10.4.25 (dbg), 10.4.25 (opt), 10.5.16 (dbg), 10.5.16 (opt), 10.6.8 (dbg), 10.6.8 (opt), 10.7.4 (dbg), 10.7.4 (opt), 10.8.3 (dbg), 10.8.3 (opt), 10.9.0 (dbg), 10.9.0 (opt)

Bug (or feature/syntax) confirmed not present in:
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.37 (dbg), 5.7.37 (opt), 8.0.28 (dbg), 8.0.28 (opt)

UniqueID's seen with this testcase:

SIGSEGV|__strlen_avx2|my_strdup|Session_sysvars_tracker::init|THD::init
SIGSEGV|__strlen_avx2|my_strdup|Session_sysvars_tracker::init|plugin_thdvar_init
global_system_variables.session_track_system_variables|SIGABRT|Session_sysvars_tracker::init|plugin_thdvar_init|THD::init|THD::change_user

Comment by Roel Van de Paar [ 2022-04-22 ]

UBSAN for same testcase from the last comment:

SET 'a';
SET collation_connection='a';
CHANGE MASTER TO master_host='a';
SET GLOBAL session_track_system_variables='a';

Leads to:

10.9.0 161fd2d29cc2f8390fa3bf7e739c52bc8d5c39df (Optimized)

/test/10.9_opt_san/mysys/my_malloc.c:230:18: runtime error: null pointer passed as argument 1, which is declared to never be null

10.9.0 161fd2d29cc2f8390fa3bf7e739c52bc8d5c39df (Optimized)

    #0 0x555836d65fde in my_strdup /test/10.9_opt_san/mysys/my_malloc.c:230
    #1 0x5558372cd19c in Session_sysvars_tracker::init(THD*) /test/10.9_opt_san/sql/session_tracker.cc:336
    #2 0x5558375f00d3 in THD::init() /test/10.9_opt_san/sql/sql_class.cc:1235
    #3 0x5558375f21a3 in THD::change_user() /test/10.9_opt_san/sql/sql_class.cc:1433
    #4 0x5558375f2c23 in THD::reset_for_reuse() /test/10.9_opt_san/sql/sql_class.cc:1637
    #5 0x5558382210a6 in CONNECT::create_thd(THD*) /test/10.9_opt_san/sql/sql_connect.cc:1527
    #6 0x555838223448 in do_handle_one_connection(CONNECT*, bool) /test/10.9_opt_san/sql/sql_connect.cc:1438
    #7 0x555838226834 in handle_one_connection /test/10.9_opt_san/sql/sql_connect.cc:1312
    #8 0x55583a3241f9 in pfs_spawn_thread /test/10.9_opt_san/storage/perfschema/pfs.cc:2201
    #9 0x14e4465f7608 in start_thread /build/glibc-sMfBJT/glibc-2.31/nptl/pthread_create.c:477
    #10 0x14e44586c162 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x11f162)

Setup:

Compiled with GCC >=7.5.0 (I use GCC 9.4.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=1:detect_invalid_pointer_pairs=3:dump_instruction_bytes=1:abort_on_error=1
    export UBSAN_OPTIONS=print_stacktrace=1

10.2.44 (opt) does not produce the same UBSAN stack, but does report:

Warning: Memory not freed: 16

Bug confirmed present in:
MariaDB: 10.2.44 (opt), 10.3.35 (opt), 10.4.25 (opt), 10.5.16 (opt), 10.6.8 (opt), 10.8.3 (opt), 10.9.0 (opt)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.44 (dbg), 10.3.35 (dbg), 10.4.25 (dbg), 10.5.16 (dbg), 10.6.8 (dbg), 10.7.4 (dbg), 10.7.4 (opt), 10.8.3 (dbg), 10.9.0 (dbg)

Comment by Oleksandr Byelkin [ 2022-06-23 ]

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
SET sql_mode='';
SET 'a';
main.test                                [ fail ]
        Test ended at 2022-06-23 12:35:48
 
CURRENT_TEST: main.test
mysqltest: At line 2: query 'SET 'a'' failed: 1064: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near ''a'' at line 1

Comment by Roel Van de Paar [ 2022-06-24 ]

Please use CLI. It crashes fine.

10.10.0 081a284712bb661349e2e3802077b12211cede3e (Debug)

10.10.0-dbg>SET sql_mode='';  # Also try with ONLY_FULL_GROUP_BY
Query OK, 0 rows affected (0.000 sec)
 
10.10.0-dbg>SET 'a';
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near ''a'' at line 1
10.10.0-dbg>SET collation_connection=utf6_unicode_520_ci;
ERROR 1273 (HY000): Unknown collation: 'utf6_unicode_520_ci'
10.10.0-dbg>SET GLOBAL session_track_system_variables='a';
ERROR 1193 (HY000): Unknown system variable 'a'
10.10.0-dbg>SET GLOBAL event_scheduler=1;
ERROR 2013 (HY000): Lost connection to server during query
10.10.0-dbg>

Comment by Alexander Barkov [ 2022-08-18 ]

Confirmed that this script crashes a 10.3 debug build. No ASAN build is needed.

SET GLOBAL session_track_system_variables='a';
SET GLOBAL event_scheduler=TRUE;

After the "Unknown system variable" failure, the variable global_system_variables.session_track_system_variables gets assigned to NULL, which makes it further crash on DBUG_ASSERT inside Session_sysvars_tracker::init.

Possibly, global_system_variables.session_track_system_variables should preserve its previous value in case of an unknown variable on the list.

Reassigning back to sanja.

Comment by Roel Van de Paar [ 2023-01-10 ]

Addititional testcase

SET sql_mode='';
CREATE TABLE t (a INT,b INT,c INT,d INT,e INT,f INT GENERATED ALWAYS AS (a+b) VIRTUAL,g INT,h BLOB,i INT,UNIQUE KEY(d,h)) ENGINE=InnoDB;
INSERT INTO t VALUES (0,0,0,0,0,0,0,0,0);
SET GLOBAL session_track_system_variables='a';
INSERT INTO t SET c=CONCAT (REPEAT (0,0),0,0);

Bug confirmed present in:
MariaDB: 10.3.38 (dbg), 10.3.38 (opt), 10.4.28 (dbg), 10.4.28 (opt), 10.5.19 (dbg), 10.5.19 (opt), 10.6.12 (dbg), 10.6.12 (opt), 10.7.8 (dbg), 10.7.8 (opt), 10.8.7 (dbg), 10.8.7 (opt), 10.9.5 (dbg), 10.9.5 (opt), 10.10.3 (dbg), 10.10.3 (opt), 10.11.2 (dbg), 10.11.2 (opt), 11.0.1 (dbg), 11.0.1 (opt)

Comment by Roel Van de Paar [ 2023-02-04 ]

Additional testcase (10.3-10.11, dbg+opt)

CREATE TABLE t (c INT,KEY(c)) ENGINE=InnoDB;
SET @@autocommit=0;
SET GLOBAL session_track_system_variables='a';
INSERT INTO t (c) VALUES (1);

This produces a somewhat different UBSAN stack/UniqueID:

10.11.2 70be59913c90e93fe5136d6f6df03c4254aa515d (Optimized, UBASAN)

UBSAN|null pointer passed as argument 1, which is declared to never be null|mysys/my_malloc.c|my_strdup|Session_sysvars_tracker::init|THD::init|THD::THD

Comment by Alice Sherepa [ 2023-06-26 ]

MDEV-31534, also repeatable on 11.0, non-debug:

230626  9:48:06 [ERROR] mysqld got signal 11 ;
 
Server version: 10.11.2-MariaDB source revision: cafba8761af55ae16cc69c9b53a341340a845b36
 
mysys/stacktrace.c:213(my_print_stacktrace)[0x5589a1492bde]
sql/signal_handler.cc:238(handle_fatal_signal)[0x5589a0e72067]
sigaction.c:0(__restore_rt)[0x7fb82fffa420]
??:0(__nss_database_lookup)[0x7fb82fc436e5]
mysys/my_malloc.c:232(my_strdup)[0x5589a148f20c]
sql/session_tracker.cc:338(Session_sysvars_tracker::init(THD*))[0x5589a0b6ee06]
sql/sql_class.cc:1237(THD::init())[0x5589a0bd9cad]
sql/sql_class.cc:1427(THD::change_user())[0x5589a0bda15e]
sql/sql_class.cc:1627(THD::reset_for_reuse())[0x5589a0bda359]
sql/sql_connect.cc:1531(CONNECT::create_thd(THD*))[0x5589a0d3ff66]
sql/sql_connect.cc:1436(do_handle_one_connection(CONNECT*, bool))[0x5589a0d40365]
sql/sql_connect.cc:1324(handle_one_connection)[0x5589a0d40554]
perfschema/pfs.cc:2204(pfs_spawn_thread)[0x5589a10c4b2c]
nptl/pthread_create.c:478(start_thread)[0x7fb82ffee609]
??:0(clone)[0x7fb82fbda133]

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

I tested the patch on 10.4 and 11.1. On 10.4, the crash does not appear anymore, however there is a memory leak:

10.4.31 d214628af47b2335a9da03a3f7ae54d7ea3241f0 (Debug, UBASAN)

==1197614==ERROR: LeakSanitizer: detected memory leaks
 
Direct leak of 16 byte(s) in 1 object(s) allocated from:
    #0 0x559bcdcd6207 in malloc (/test/UBASAN_MD280623-mariadb-10.4.31-linux-x86_64-dbg/bin/mysqld+0x733f207)
    #1 0x559bd208a4bc in my_malloc /test/10.4_dbg_san/mysys/my_malloc.c:101
    #2 0x559bd208ac5f in my_memdup /test/10.4_dbg_san/mysys/my_malloc.c:233
    #3 0x559bced60624 in Sys_var_charptr_base::global_update_prepare(THD*, set_var*) /test/10.4_dbg_san/sql/sys_vars.inl:535
    #4 0x559bced60624 in Sys_var_sesvartrack::global_update(THD*, set_var*) /test/10.4_dbg_san/sql/sys_vars.inl:618
    #5 0x559bcddbc24d in sys_var::update(THD*, set_var*) /test/10.4_dbg_san/sql/set_var.cc:208
    #6 0x559bcddbf013 in set_var::update(THD*) /test/10.4_dbg_san/sql/set_var.cc:837
    #7 0x559bcddc69ae in sql_set_variables(THD*, List<set_var_base>*, bool) /test/10.4_dbg_san/sql/set_var.cc:740
    #8 0x559bce40add2 in mysql_execute_command(THD*) /test/10.4_dbg_san/sql/sql_parse.cc:5045
    #9 0x559bce431a55 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /test/10.4_dbg_san/sql/sql_parse.cc:8008
    #10 0x559bce4417ae in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /test/10.4_dbg_san/sql/sql_parse.cc:1857
    #11 0x559bce44fb9a in do_command(THD*) /test/10.4_dbg_san/sql/sql_parse.cc:1378
    #12 0x559bcec8a8dc in do_handle_one_connection(CONNECT*) /test/10.4_dbg_san/sql/sql_connect.cc:1420
    #13 0x559bcec8aeac in handle_one_connection /test/10.4_dbg_san/sql/sql_connect.cc:1324
    #14 0x147932694b42 in start_thread nptl/pthread_create.c:442
 
SUMMARY: AddressSanitizer: 16 byte(s) leaked in 1 allocation(s).

On 11.1, after applying I see the following build issue:

11.1.2 3883eb63dc5e663558571c33d086c9fd3aa0cf8f (Debug, during build)

In file included from /test/11.1_dbg/sql/sys_vars.cc:37:
/test/11.1_dbg/sql/sys_vars.inl: In member function ‘virtual bool Sys_var_sesvartrack::global_update(THD*, set_var*)’:
/test/11.1_dbg/sql/sys_vars.inl:75:27: error: invalid conversion from ‘const char*’ to ‘PSI_memory_key’ {aka ‘unsigned int’} [-fpermissive]
   75 | #define global_var(TYPE) (*(TYPE*)global_var_ptr())
      |                          ~^~~~~~~~~~~~~~~~~~~~~~~~~
      |                           |
      |                           const char*
/test/11.1_dbg/sql/sys_vars.inl:670:35: note: in expansion of macro ‘global_var’
  670 |         new_val= (char*)my_strdup(global_var(const char*), MYF(MY_WME));
      |                                   ^~~~~~~~~~
In file included from /test/11.1_dbg/sql/mariadb.h:29,
                 from /test/11.1_dbg/sql/sql_plugin.h:30,
                 from /test/11.1_dbg/sql/sys_vars.cc:34:
/test/11.1_dbg/include/my_global.h:994:25: error: invalid conversion from ‘myf’ {aka ‘long unsigned int’} to ‘const char*’ [-fpermissive]
  994 | #define MYF(v)          (myf) (v)
      |                         ^~~~~~~~~
      |                         |
      |                         myf {aka long unsigned int}
/test/11.1_dbg/sql/sys_vars.inl:670:60: note: in expansion of macro ‘MYF’
  670 |         new_val= (char*)my_strdup(global_var(const char*), MYF(MY_WME));
      |                                                            ^~~
In file included from /test/11.1_dbg/sql/sys_vars.cc:37:
/test/11.1_dbg/sql/sys_vars.inl:670:34: error: too few arguments to function ‘char* my_strdup(PSI_memory_key, const char*, myf)’
  670 |         new_val= (char*)my_strdup(global_var(const char*), MYF(MY_WME));
      |                         ~~~~~~~~~^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
In file included from /test/11.1_dbg/sql/sql_plugin.h:45,
                 from /test/11.1_dbg/sql/sys_vars.cc:34:
/test/11.1_dbg/include/my_sys.h:173:14: note: declared here
  173 | extern char *my_strdup(PSI_memory_key key, const char *from,myf MyFlags);
      |              ^~~~~~~~~

Comment by Oleksandr Byelkin [ 2023-07-03 ]

sanja@SanjasLaptop:~/maria/git/10.4/mysql-test$ git log
commit d8e04ef367b7b80104a59634aca9ca101add59db (HEAD -> bb-10.4-MDEV-25237, origin/bb-10.4-MDEV-25237)
Author: Oleksandr Byelkin <sanja@mariadb.com>
Date:   Tue Jun 27 12:10:48 2023 +0200
 
    MDEV-25237 Assertion `global_system_variables.session_track_system_variables' failed in Session_sysvars_tracker::init | SIGSEGV's in __strlen_avx2 | UBSAN: runtime error: null pointer passed as argument 1, which is declared to never be null in my_strdup
    
    Restore old value of the variable in case of error

Comment by Oleksandr Byelkin [ 2023-07-10 ]

commit 8e9c68b49dd82cfda2ac22949666c9d1adae2db7 (HEAD -> bb-10.4-MDEV-25237, origin/bb-10.4-MDEV-25237)
Author: Oleksandr Byelkin <sanja@mariadb.com>
Date:   Tue Jun 27 12:10:48 2023 +0200
 
    MDEV-25237 Assertion `global_system_variables.session_track_system_variables' failed in Session_sysvars_tracker::init | SIGSEGV's in __strlen_avx2 | UBSAN: runtime error: null pointer passed as argument 1, which is declared to never be null in my_strdup
    
    Fix of typo in checking variable list corectness.
    
    Fix of error handling in case of variable list parse error

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