[MDEV-22134] handle_fatal_signal (sig=11) in __strlen_avx2 on START SLAVE | Assertion `global_system_variables.session_track_system_variables' failed in Session_sysvars_tracker::init | *** buffer overflow detected *** (on optimized builds) Created: 2020-04-03  Updated: 2021-04-23  Resolved: 2020-07-23

Status: Closed
Project: MariaDB Server
Component/s: OTHER
Affects Version/s: 10.3, 10.4, 10.5
Fix Version/s: 10.3.24, 10.4.14, 10.5.5

Type: Bug Priority: Critical
Reporter: Roel Van de Paar Assignee: Oleksandr Byelkin
Resolution: Fixed Votes: 0
Labels: affects-tests, not-10.1, not-10.2, threadpool

Issue Links:
Relates
relates to MDEV-25237 crash after setting global session_tr... Closed
relates to MDEV-25499 SIGSEGV in Sys_var_sesvartrack::sessi... Closed

 Description   

CHANGE MASTER TO MASTER_HOST='h', MASTER_USER='u';
SET @@GLOBAL.session_track_system_variables=NULL;
START SLAVE IO_THREAD;

Leads to:

10.5.3 e8351934b68d6d3ee273292eaa2ece203bb2b846

Core was generated by `/data/MD020420-mariadb-10.5.3-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:57
[Current thread is 1 (Thread 0x7f2c18bea700 (LWP 2364))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x00005559193b1d47 in my_write_core (sig=sig@entry=11) at /data/10.5_opt/mysys/stacktrace.c:518
#2  0x0000555918d7387a in handle_fatal_signal (sig=11) at /data/10.5_opt/sql/signal_handler.cc:325
#3  <signal handler called>
#4  __strlen_avx2 () at ../sysdeps/x86_64/multiarch/strlen-avx2.S:62
#5  0x00005559193ae49c in my_strdup (key=key@entry=0, from=0x0, my_flags=my_flags@entry=65552) at /data/10.5_opt/mysys/my_malloc.c:228
#6  0x0000555918acc766 in Session_sysvars_tracker::init (this=<optimized out>, thd=0x7f2bbdc12018) at /data/10.5_opt/sql/session_tracker.cc:330
#7  0x0000555918b9018b in plugin_thdvar_init (thd=thd@entry=0x7f2bbdc12018) at /data/10.5_opt/sql/sql_plugin.cc:3216
#8  0x0000555918b3225c in THD::init (this=this@entry=0x7f2bbdc12018) at /data/10.5_opt/sql/sql_class.cc:1248
#9  0x0000555918b375d9 in THD::THD (this=0x7f2bbdc12018, id=<optimized out>, is_wsrep_applier=<optimized out>) at /data/10.5_opt/sql/sql_class.cc:844
#10 0x0000555918ade8c7 in handle_slave_io (arg=arg@entry=0x7f2bf77f4000) at /data/10.5_opt/sql/slave.cc:4727
#11 0x0000555918fd99da in pfs_spawn_thread (arg=0x7f2beac62218) at /data/10.5_opt/storage/perfschema/pfs.cc:2201
#12 0x00007f2c1805c6db in start_thread (arg=0x7f2c18bea700) at pthread_create.c:463
#13 0x00007f2c1745a88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.3.23 (dbg), 10.3.23 (opt), 10.4.13 (dbg), 10.4.13 (opt), 10.5.3 (dbg), 10.5.3 (opt)

Bug confirmed not present in:
MariaDB: 10.1.45 (dbg), 10.1.45 (opt), 10.2.32 (dbg), 10.2.32 (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-04-04 ]

Additional testcase:

SET @@GLOBAL.session_track_system_variables=NULL;
SET @@SESSION.session_track_system_variables=default;
SELECT 1;

Leads to:

10.5.3 e8351934b68d6d3ee273292eaa2ece203bb2b846

Core was generated by `/data/MD020420-mariadb-10.5.3-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:57
[Current thread is 1 (Thread 0x7fb659b59700 (LWP 19103))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x000055827922fd47 in my_write_core (sig=sig@entry=11) at /data/10.5_opt/mysys/stacktrace.c:518
#2  0x0000558278bf187a in handle_fatal_signal (sig=11) at /data/10.5_opt/sql/signal_handler.cc:325
#3  <signal handler called>
#4  __strlen_avx2 () at ../sysdeps/x86_64/multiarch/strlen-avx2.S:62
#5  0x0000558278b01902 in Sys_var_sesvartrack::session_save_default (this=<optimized out>, thd=0x7fb629c12018, var=0x7fb629c47130) at /data/10.5_opt/sql/sys_vars.ic:675
#6  0x000055827894c283 in sys_var::set_default (this=0x558279d9c500 <Sys_track_session_sys_vars>, thd=0x7fb629c12018, var=0x7fb629c47130) at /data/10.5_opt/sql/set_var.cc:291
#7  0x000055827894c2c5 in set_var::update (this=<optimized out>, thd=<optimized out>) at /data/10.5_opt/sql/set_var.cc:859
#8  0x000055827894d5c9 in sql_set_variables (thd=thd@entry=0x7fb629c12018, var_list=var_list@entry=0x7fb629c16d70, free=free@entry=true) at /data/10.5_opt/sql/set_var.cc:746
#9  0x00005582789fe3a1 in mysql_execute_command (thd=thd@entry=0x7fb629c12018) at /data/10.5_opt/sql/sql_parse.cc:4976
#10 0x0000558278a03a6c in mysql_parse (thd=thd@entry=0x7fb629c12018, rawbuf=<optimized out>, length=52, parser_state=parser_state@entry=0x7fb659b584d0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/10.5_opt/sql/sql_parse.cc:7953
#11 0x00005582789f88e0 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fb629c12018, packet=packet@entry=0x7fb629c3a019 "SET @@SESSION.session_track_system_variables=default", packet_length=packet_length@entry=52, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/10.5_opt/sql/sql_parse.cc:1839
#12 0x00005582789f6bff in do_command (thd=0x7fb629c12018) at /data/10.5_opt/sql/sql_parse.cc:1358
#13 0x0000558278aeb92e in do_handle_one_connection (connect=<optimized out>, connect@entry=0x7fb6578329b8, put_in_cache=put_in_cache@entry=true) at /data/10.5_opt/sql/sql_connect.cc:1422
#14 0x0000558278aebad4 in handle_one_connection (arg=arg@entry=0x7fb6578329b8) at /data/10.5_opt/sql/sql_connect.cc:1319
#15 0x0000558278e579da in pfs_spawn_thread (arg=0x7fb65784b018) at /data/10.5_opt/storage/perfschema/pfs.cc:2201
#16 0x00007fb658f806db in start_thread (arg=0x7fb659b59700) at pthread_create.c:463
#17 0x00007fb65837e88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.2.32 (dbg), 10.2.32 (opt), 10.3.23 (dbg), 10.3.23 (opt), 10.4.13 (dbg), 10.4.13 (opt), 10.5.3 (dbg), 10.5.3 (opt)

Bug confirmed not present in:
MariaDB: 10.1.45 (dbg), 10.1.45 (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)

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

And another:

SET @@global.session_track_system_variables=NULL;
INSERT DELAYED INTO t VALUES(0);

Leads to:

10.5.3 98003440c2f8d20164a191ced1b7d92b283bb68f

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

10.5.3 98003440c2f8d20164a191ced1b7d92b283bb68f

Core was generated by `/test/MD210420-mariadb-10.5.3-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:57
[Current thread is 1 (Thread 0x7f4ceaa05700 (LWP 900372))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x000055b39a32803d in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
#2  0x000055b399acdd7b in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:329
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x00007f4ce9149801 in __GI_abort () at abort.c:79
#6  0x00007f4ce913939a in __assert_fail_base (fmt=0x7f4ce92c07d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55b39a479598 "global_system_variables.session_track_system_variables", file=file@entry=0x55b39a4793b0 "/test/10.5_dbg/sql/session_tracker.cc", line=line@entry=328, function=function@entry=0x55b39a4799c0 <Session_sysvars_tracker::init(THD*)::__PRETTY_FUNCTION__> "void Session_sysvars_tracker::init(THD*)") at assert.c:92
#7  0x00007f4ce9139412 in __GI___assert_fail (assertion=assertion@entry=0x55b39a479598 "global_system_variables.session_track_system_variables", file=file@entry=0x55b39a4793b0 "/test/10.5_dbg/sql/session_tracker.cc", line=line@entry=328, function=function@entry=0x55b39a4799c0 <Session_sysvars_tracker::init(THD*)::__PRETTY_FUNCTION__> "void Session_sysvars_tracker::init(THD*)") at assert.c:101
#8  0x000055b39973a250 in Session_sysvars_tracker::init (this=<optimized out>, thd=0x7f4cc04810a8) at /test/10.5_dbg/sql/session_tracker.cc:328
#9  0x000055b39983bc30 in plugin_thdvar_init (thd=thd@entry=0x7f4cc04810a8) at /test/10.5_dbg/sql/sql_plugin.cc:3216
#10 0x000055b3997c1fae in THD::init (this=this@entry=0x7f4cc04810a8) at /test/10.5_dbg/sql/sql_class.cc:1248
#11 0x000055b3997ca1b1 in THD::THD (this=0x7f4cc04810a8, id=<optimized out>, is_wsrep_applier=<optimized out>) at /test/10.5_dbg/sql/sql_class.cc:844
#12 0x000055b3997eab18 in Delayed_insert::Delayed_insert (current_select=0x7f4cc0474860, this=0x7f4cc0481088) at /test/10.5_dbg/sql/sql_insert.cc:2244
#13 delayed_get_table (table_list=0x7f4cc0474188, grl_protection_request=0x7f4ceaa03690, thd=0x7f4cc0415088) at /test/10.5_dbg/sql/sql_insert.cc:2431
#14 open_and_lock_for_insert_delayed (thd=thd@entry=0x7f4cc0415088, table_list=table_list@entry=0x7f4cc0474188) at /test/10.5_dbg/sql/sql_insert.cc:575
#15 0x000055b3997ec4d6 in mysql_insert (thd=thd@entry=0x7f4cc0415088, table_list=0x7f4cc0474188, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /test/10.5_dbg/sql/sql_insert.cc:751
#16 0x000055b399825308 in mysql_execute_command (thd=thd@entry=0x7f4cc0415088) at /test/10.5_dbg/sql/sql_parse.cc:4515
#17 0x000055b399830f2b in mysql_parse (thd=thd@entry=0x7f4cc0415088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f4ceaa04450, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7957
#18 0x000055b39981cc45 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f4cc0415088, packet=packet@entry=0x7f4cc0467089 "INSERT DELAYED INTO t VALUES(0)", packet_length=packet_length@entry=31, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1839
#19 0x000055b39981b49b in do_command (thd=0x7f4cc0415088) at /test/10.5_dbg/sql/sql_parse.cc:1358
#20 0x000055b399976415 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x7f4cc8bc53a8, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1422
#21 0x000055b399976744 in handle_one_connection (arg=arg@entry=0x7f4cc8bc53a8) at /test/10.5_dbg/sql/sql_connect.cc:1319
#22 0x000055b399dd6fb0 in pfs_spawn_thread (arg=0x7f4ce8445b08) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#23 0x00007f4ce9e2c6db in start_thread (arg=0x7f4ceaa05700) at pthread_create.c:463
#24 0x00007f4ce922a88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.3.23 (dbg), 10.3.23 (opt), 10.4.13 (dbg), 10.4.13 (opt), 10.5.2 (dbg), 10.5.2 (opt), 10.5.3 (dbg), 10.5.3 (opt)

Bug confirmed not present in:
MariaDB: 10.1.45 (dbg), 10.1.45 (opt), 10.2.32 (dbg), 10.2.32 (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)

Yet without DELAYED clause it works;

10.5.3>INSERT INTO t VALUES(0);
ERROR 1146 (42S02): Table 'test.t' doesn't exist

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

Unique bug ID's

SIGSEGV|__strlen_avx2|my_strdup|Session_sysvars_tracker::init|plugin_thdvar_init  ## OPT |MDEV-22134
SIGABRT|__strlen_avx2|my_strdup|Session_sysvars_tracker::init|plugin_thdvar_init  ## OPT |MDEV-22134
SIGSEGV|__strlen_avx2|Sys_var_sesvartrack::session_save_default|sys_var::set_default|set_var::update  ## OPT |MDEV-22134
global_system_variables.session_track_system_variables|SIGABRT|Session_sysvars_tracker::init|plugin_thdvar_init|THD::init|THD::THD   ## OPT |MDEV-22134
SIGSEGV|Sys_var_sesvartrack::session_save_default|sys_var::set_default|set_var::update|sql_set_variables  ## OPT |MDEV-22134

Comment by Roel Van de Paar [ 2020-06-12 ]

New unique bug ID added above for latest 10.5.4 created with this testcase:

10.5.4 07d1c8567cbfe94398a9857c47fb9919cad42651

SET GLOBAL session_track_system_variables=NULL;
SET SESSION session_track_system_variables=DEFAULT;

Comment by Roel Van de Paar [ 2020-06-12 ]

One more testcase to test fix against

USE test;
SET GLOBAL EVENT_SCHEDULER=ON;
CREATE EVENT e ON SCHEDULE EVERY 1 SECOND DO INSERT INTO execution_log VALUE('a');
SET GLOBAL session_track_system_variables=NULL;
SET GLOBAL session_track_system_variables=NULL;

Comment by Roel Van de Paar [ 2020-07-21 ]

This testcase:

# mysqld options required for replay: --log-bin --thread_handling=pool-of-threads --thread-pool-size=2047
CHANGE MASTER TO MASTER_DELAY=10, MASTER_HOST='a';
SET GLOBAL session_track_system_variables=NULL;
START SLAVE SQL_THREAD;

Produces a buffer overflow on both debug and optimized builds:

10.5.5 30e7a0a866dce530d8328c6d614e48d39a264f9b (Debug)

10.5.5>CHANGE MASTER TO MASTER_DELAY=10, MASTER_HOST='a';
Query OK, 0 rows affected (0.018 sec)
 
10.5.5>SET GLOBAL session_track_system_variables=NULL;
Query OK, 0 rows affected (0.000 sec)
 
10.5.5>START SLAVE SQL_THREAD;
*** buffer overflow detected ***: /test/MD140720-mariadb-10.5.5-linux-x86_64-dbg/bin/mysqld terminated
ERROR 2013 (HY000): Lost connection to MySQL server during query

10.5.5 30e7a0a866dce530d8328c6d614e48d39a264f9b (Optimized)

10.5.5>CHANGE MASTER TO MASTER_DELAY=10, MASTER_HOST='a';
Query OK, 0 rows affected (0.018 sec)
 
10.5.5>SET GLOBAL session_track_system_variables=NULL;
Query OK, 0 rows affected (0.000 sec)
 
10.5.5>START SLAVE SQL_THREAD;
*** buffer overflow detected ***: /test/MD140720-mariadb-10.5.5-linux-x86_64-opt/bin/mysqld terminated
ERROR 2013 (HY000): Lost connection to MySQL server during query

The debug build reports the following in the error log besides the crash:

10.5.5 30e7a0a866dce530d8328c6d614e48d39a264f9b (Optimized)

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

Comment by Oleksandr Byelkin [ 2020-07-21 ]

It just do not start with parameters mentioned in the last comment:

sanja@sanja-laptop:~/maria/git/10.3/mysql-test$ ./mysql-test-run --start --mysqld="--log-bin --thread_handling=pool-of-threads --thread-pool-size=2047"
Logging: ./mysql-test-run  --start --mysqld=--log-bin --thread_handling=pool-of-threads --thread-pool-size=2047
vardir: /home/sanja/maria/git/10.3/mysql-test/var
Checking leftover processes...
Removing old var directory...
 - WARNING: Using the 'mysql-test/var' symlink
Creating var directory '/home/sanja/maria/git/10.3/mysql-test/var'...
Checking supported features...
MariaDB Version 10.3.24-MariaDB-debug
 - SSL connections supported
 - binaries are debug compiled
 - binaries built with wsrep patch
Using suites: main-,archive-,binlog-,binlog_encryption-,csv-,compat/oracle-,encryption-,federated-,funcs_1-,funcs_2-,gcol-,handler-,heap-,innodb-,innodb_fts-,innodb_gis-,innodb_zip-,json-,maria-,mariabackup-,multi_source-,optimizer_unfixed_bugs-,parts-,perfschema-,plugins-,roles-,rpl-,stress-,sys_vars-,sql_sequence-,unit-,vcol-,versioning-,connect,sequence,sql_discovery,disks,metadata_lock_info,query_response_time,user_variables
Collecting tests...
Installing system database...
 
==============================================================================
 
TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 82812, winpid: 82812, exit: 1792] died after mysql-test-run waited 0.3 seconds for /home/sanja/maria/git/10.3/mysql-test/var/run/mysqld.1.pid to be created.
main.connect                             [ fail ]
        Test ended at 2020-07-21 14:42:56
 
CURRENT_TEST: main.connect
 
 
Failed to start mysqld.1
mysqltest failed but provided no output
 
 
 - saving '/home/sanja/maria/git/10.3/mysql-test/var/log/main.connect/' to '/home/sanja/maria/git/10.3/mysql-test/var/log/main.connect/'
 
Only  230  of 5198 completed.

the same if put it in .opt file for the test suite. So report it as separate bug (actually above was at least two bugs) if it will be repeating after the fix

Comment by Oleksandr Byelkin [ 2020-07-21 ]

commit 1350fc3d6c2252929d3d12b98de710bdbad82235 (HEAD > bb-10.3MDEV-22134, origin/bb-10.3-MDEV-22134)
Author: Oleksandr Byelkin <sanja@mariadb.com>
Date: Tue Jul 21 14:56:47 2020 +0200

MDEV-22134: handle_fatal_signal (sig=11) in __strlen_avx2 on START SLAVE | Assertion `global_system_variables.session_track_system_variables' failed in Session_sysvars_tracker::init | *** buffer overflow detected *** (on optimized builds)

Be aware about posibility for tracking variables list be empty.

Comment by Alexander Barkov [ 2020-07-22 ]

Perhaps we could disallow setting NULL value for session_track_system_variables.

Comment by Oleksandr Byelkin [ 2020-07-22 ]

commit b7ad9baf501c8a208b370da755f330f280fdd680 (HEAD > bb-10.3MDEV-22134, origin/bb-10.3-MDEV-22134)
Author: Oleksandr Byelkin <sanja@mariadb.com>
Date: Tue Jul 21 14:56:47 2020 +0200

MDEV-22134: handle_fatal_signal (sig=11) in __strlen_avx2 on START SLAVE | Assertion `global_system_variables.session_track_system_variables' failed in Session_sysvars_tracker::init | *** buffer overflow detected *** (on optimized builds)

Prohibit assigning NULL as for other system variables.

Comment by Alexander Barkov [ 2020-07-22 ]

This patch:
https://github.com/MariaDB/server/commit/b7ad9baf501c8a208b370da755f330f280fdd680

is OK to push.

Comment by Roel Van de Paar [ 2021-03-31 ]

Confirmed that the patch for the moment seems to resolve all testcases. mysqld from the command line works with --log-bin --thread_handling=pool-of-threads --thread-pool-size=2047 so that is likely an MTR related thing.

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