[MDEV-25612] Assertion `to <= end' failed in process_args & *** stack smashing detected *** Created: 2021-05-07  Updated: 2021-05-19  Resolved: 2021-05-09

Status: Closed
Project: MariaDB Server
Component/s: Server
Affects Version/s: N/A
Fix Version/s: N/A

Type: Bug Priority: Blocker
Reporter: Roel Van de Paar Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: regression


 Description   

This issue only happens in bb-10.6-monty

SET SESSION default_master_connection=REPEAT('a',190),lc_messages=ru_ru;
CHANGE MASTER TO master_host='dummy';
START SLAVE sql_thread;
CHANGE MASTER TO master_user='user',master_password='pwd';

Leads to:

10.6.1 90c8467341b8244e92e826e76c7697c88ca75cd2 (Debug)

mysqld: /test/bb-10.6-monty_dbg/strings/my_vsnprintf.c:614: process_args: Assertion `to <= end' failed.

10.6.1 90c8467341b8244e92e826e76c7697c88ca75cd2 (Debug)

Core was generated by `/test/MONTY_MD030521-mariadb-10.6.1-linux-x86_64-dbg/bin/mysqld --no-defaults -'.
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 0x14edb8164700 (LWP 4175185))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000014edccde1859 in __GI_abort () at abort.c:79
#2  0x000014edccde1729 in __assert_fail_base (fmt=0x14edccf77588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x563a1f86cbe4 "to <= end", file=0x563a1f86c1a8 "/test/bb-10.6-monty_dbg/strings/my_vsnprintf.c", line=614, function=<optimized out>) at assert.c:92
#3  0x000014edccdf2f36 in __GI___assert_fail (assertion=assertion@entry=0x563a1f86cbe4 "to <= end", file=file@entry=0x563a1f86c1a8 "/test/bb-10.6-monty_dbg/strings/my_vsnprintf.c", line=line@entry=614, function=function@entry=0x563a1f86cf50 <__PRETTY_FUNCTION__.16260> "process_args") at assert.c:101
#4  0x0000563a1f1dca3f in process_args (cs=cs@entry=0x563a1fc2fea0 <my_charset_utf8mb3_general_ci>, to=0x14edb81623de "", to@entry=0x14edb8162231 'a' <repeats 190 times>, ". Снач"..., end=end@entry=0x14edb816239f 'a' <repeats 62 times>, "'", fmt=<optimized out>, fmt@entry=0x14ed8002500e "*1$s. Сначала выполните STOP SLAVE '%2$*1$s'", arg_index=<optimized out>, ap=ap@entry=0x14edb8162168) at /test/bb-10.6-monty_dbg/strings/my_vsnprintf.c:614
#5  0x0000563a1f1dcca3 in my_vsnprintf_ex (cs=0x563a1fc2fea0 <my_charset_utf8mb3_general_ci>, to=0x14edb8162231 'a' <repeats 190 times>, ". Снач"..., to@entry=0x14edb81621a0 "Эту операцию невозможно выполнить при работающем потоке подчиненного сервера ", 'a' <repeats 55 times>..., n=n@entry=512, fmt=0x14ed8002500d "$*1$s. Сначала выполните STOP SLAVE '%2$*1$s'", ap=ap@entry=0x14edb8162168) at /test/bb-10.6-monty_dbg/strings/my_vsnprintf.c:681
#6  0x0000563a1f17cbf6 in my_error (nr=nr@entry=1198, MyFlags=MyFlags@entry=0) at /test/bb-10.6-monty_dbg/mysys/my_error.c:120
#7  0x0000563a1e682c24 in change_master (thd=thd@entry=0x14ed80000db8, mi=mi@entry=0x14ed80038190, master_info_added=master_info_added@entry=0x14edb8162fd0) at /test/bb-10.6-monty_dbg/sql/sql_repl.cc:3604
#8  0x0000563a1e659a25 in mysql_execute_command (thd=thd@entry=0x14ed80000db8) at /test/bb-10.6-monty_dbg/sql/sql_parse.cc:4125
#9  0x0000563a1e645806 in mysql_parse (thd=thd@entry=0x14ed80000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14edb8163410) at /test/bb-10.6-monty_dbg/sql/sql_parse.cc:8019
#10 0x0000563a1e6542f5 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14ed80000db8, packet=packet@entry=0x14ed8000b759 "CHANGE MASTER TO master_user='user',master_password='pwd'", packet_length=packet_length@entry=57, blocking=blocking@entry=true) at /test/bb-10.6-monty_dbg/sql/sql_class.h:1333
#11 0x0000563a1e6576e0 in do_command (thd=0x14ed80000db8, blocking=blocking@entry=true) at /test/bb-10.6-monty_dbg/sql/sql_parse.cc:1406
#12 0x0000563a1e7bae0e in do_handle_one_connection (connect=<optimized out>, connect@entry=0x563a20dd7728, put_in_cache=put_in_cache@entry=true) at /test/bb-10.6-monty_dbg/sql/sql_connect.cc:1410
#13 0x0000563a1e7bb413 in handle_one_connection (arg=arg@entry=0x563a20dd7728) at /test/bb-10.6-monty_dbg/sql/sql_connect.cc:1312
#14 0x0000563a1ec65da4 in pfs_spawn_thread (arg=0x563a20cc0148) at /test/bb-10.6-monty_dbg/storage/perfschema/pfs.cc:2201
#15 0x000014edcd2ef609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#16 0x000014edccede293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.6.1 90c8467341b8244e92e826e76c7697c88ca75cd2 (Optimized)

Core was generated by `/test/MONTY_MD030521-mariadb-10.6.1-linux-x86_64-opt/bin/mysqld --no-defaults -'.
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 0x14999c62f700 (LWP 4011058))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000014999f1b3859 in __GI_abort () at abort.c:79
#2  0x000014999f21e3ee in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x14999f34807c "*** %s ***: terminated\n") at ../sysdeps/posix/libc_fatal.c:155
#3  0x000014999f2c0b4a in __GI___fortify_fail (msg=msg@entry=0x14999f348064 "stack smashing detected") at fortify_fail.c:26
#4  0x000014999f2c0b16 in __stack_chk_fail () at stack_chk_fail.c:24
#5  0x00005614204d013f in my_error (nr=1198, MyFlags=0) at /test/bb-10.6-monty_opt/mysys/my_error.c:116
#6  0x000056141fd5c1b4 in change_master (thd=thd@entry=0x14993c000c58, mi=mi@entry=0x14993c034620, master_info_added=master_info_added@entry=0x14999c62e080) at /test/bb-10.6-monty_opt/sql/sql_repl.cc:3604
#7  0x000056141fd3ff1e in mysql_execute_command (thd=0x14993c000c58) at /test/bb-10.6-monty_opt/sql/sql_parse.cc:4125
#8  0x000056141fd2ecc4 in mysql_parse (thd=0x14993c000c58, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /test/bb-10.6-monty_opt/sql/sql_parse.cc:8019
#9  0x000056141fd3aac5 in dispatch_command (command=COM_QUERY, thd=0x14993c000c58, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /test/bb-10.6-monty_opt/sql/sql_class.h:1333
#10 0x000056141fd3ca37 in do_command (thd=0x14993c000c58, blocking=blocking@entry=true) at /test/bb-10.6-monty_opt/sql/sql_parse.cc:1406
#11 0x000056141fe49f67 in do_handle_one_connection (connect=<optimized out>, put_in_cache=true) at /test/bb-10.6-monty_opt/sql/sql_connect.cc:1410
#12 0x000056141fe4a2cd in handle_one_connection (arg=arg@entry=0x561421d32b78) at /test/bb-10.6-monty_opt/sql/sql_connect.cc:1312
#13 0x00005614201d1a78 in pfs_spawn_thread (arg=0x561421ccea58) at /test/bb-10.6-monty_opt/storage/perfschema/pfs.cc:2201
#14 0x000014999f6c1609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#15 0x000014999f2b0293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.6.1 90c8467341b8244e92e826e76c7697c88ca75cd2 (Optimized)

2021-05-07 10:20:16 0 [Note] InnoDB: Buffer pool(s) load completed at 210507 10:20:16
2021-05-07 10:21:35 4 [Note] Master connection name: 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa'  Master_info_file: 'master-aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.info'  Relay_info_file: 'relay-log-aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.info'
2021-05-07 10:21:35 4 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--log-basename=#' or '--relay-log=qa-roel-2-relay-bin' to avoid this problem.
2021-05-07 10:21:35 4 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='dummy', master_port='3306', master_log_file='', master_log_pos='4'.
2021-05-07 10:21:35 5 [Note] Master 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaSlave SQL thread initialized, starting replication in log 'FIRST' at position 0, relay log './qa-roel-2-relay-bin-aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.000001' position: 4
*** stack smashing detected ***: terminated

Debug build has similar output, but assertion instead of stack smashing notice.

Bug confirmed present in:
MariaDB (bb-10.6-monty branch): 10.6.1 (dbg), 10.6.1 (opt)

Bug (or feature/syntax) confirmed not present in:
MariaDB (trunk): 10.2.38 (dbg), 10.2.38 (opt), 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.1 (dbg), 10.6.1 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.34 (dbg), 5.7.34 (opt), 8.0.24 (dbg), 8.0.24 (opt)



 Comments   
Comment by Roel Van de Paar [ 2021-05-07 ]

Note that the issue may also be present in earlier versions (10.2-10.5) of bb-10.6-monty (not tested, let me know if this would help and will do).
It is not present in trunk in any version.

Comment by Marko Mäkelä [ 2021-05-07 ]

As always for buffer overflows, it is useful to check what cmake -DWITH_ASAN=ON would produce the following for me (when running with ./mtr --rr):

bb-10.6-monty afb1223a74910c09ced32f073cfdf572e1efdf1a

==19674==ERROR: AddressSanitizer: stack-buffer-overflow on address 0x7fe42ba4d370 at pc 0x55d59997a7f7 bp 0x7fe42ba4c010 sp 0x7fe42ba4c008
WRITE of size 1 at 0x7fe42ba4d370 thread T5
    #0 0x55d59997a7f6 in strnmov /mariadb/bb-10.6-monty/strings/strnmov.c:41
    #1 0x55d599973469 in process_str_arg /mariadb/bb-10.6-monty/strings/my_vsnprintf.c:295
    #2 0x55d599975a0b in process_args /mariadb/bb-10.6-monty/strings/my_vsnprintf.c:527
    #3 0x55d5999783b2 in my_vsnprintf_ex /mariadb/bb-10.6-monty/strings/my_vsnprintf.c:681
    #4 0x55d5997f66f9 in my_error /mariadb/bb-10.6-monty/mysys/my_error.c:120
    #5 0x55d5955d61a1 in change_master(THD*, Master_info*, bool*) /mariadb/bb-10.6-monty/sql/sql_repl.cc:3604
    #6 0x55d5954bce3b in mysql_execute_command(THD*) /mariadb/bb-10.6-monty/sql/sql_parse.cc:4125
    #7 0x55d5954e31aa in mysql_parse(THD*, char*, unsigned int, Parser_state*) /mariadb/bb-10.6-monty/sql/sql_parse.cc:8019
    #8 0x55d5954f4aa3 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /mariadb/bb-10.6-monty/sql/sql_parse.cc:1897
    #9 0x55d59550484d in do_command(THD*, bool) /mariadb/bb-10.6-monty/sql/sql_parse.cc:1406
    #10 0x55d595e3972c in do_handle_one_connection(CONNECT*, bool) /mariadb/bb-10.6-monty/sql/sql_connect.cc:1410
    #11 0x55d595e3b0c3 in handle_one_connection /mariadb/bb-10.6-monty/sql/sql_connect.cc:1312
    #12 0x55d59830e42c in pfs_spawn_thread /mariadb/bb-10.6-monty/storage/perfschema/pfs.cc:2201
    #13 0x7fe437a6aea6 in start_thread nptl/pthread_create.c:477
    #14 0x7fe436cfddee in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xfddee)
 
Address 0x7fe42ba4d370 is located in stack of thread T5 at offset 608 in frame
    #0 0x55d5997f658d in my_error /mariadb/bb-10.6-monty/mysys/my_error.c:109
 
  This frame has 2 object(s):
    [32, 56) 'args' (line 111)
    [96, 608) 'ebuff' (line 112) <== Memory access at offset 608 overflows this variable

With the following, we can analyze it a little deeper:

rr replay var/log/mysqld.1.rr/latest-trace

Thread 2 hit Breakpoint 1, strnmov (dst=dst@entry=0x7fe42ba4d32d "", 
    src=src@entry=0x614000010e58 'a' <repeats 190 times>, n=n@entry=128)
    at /mariadb/bb-10.6-monty/strings/strnmov.c:39
39	{
(rr) p dst+n
$3 = 0x7fe42ba4d3ad ""
(rr) p 0x7fe42ba4d370-0x7fe42ba4d32d
$4 = 67
(rr) bt
#0  strnmov (dst=dst@entry=0x7fe42ba4d32d "", 
    src=src@entry=0x614000010e58 'a' <repeats 190 times>, n=n@entry=128)
    at /mariadb/bb-10.6-monty/strings/strnmov.c:39
#1  0x000055d59997346a in process_str_arg (
    cs=cs@entry=0x55d5a3908280 <my_charset_utf8mb3_general_ci>, 
    to=0x7fe42ba4d32d "", to@entry=0x7fe42ba4d2ef ' ' <repeats 62 times>, 
    end=end@entry=0x7fe42ba4d36f "", length_arg=length_arg@entry=190, 
    width=width@entry=65535, 
    par=par@entry=0x614000010e58 'a' <repeats 190 times>, 
    print_type=<optimized out>, nice_cut=<optimized out>)
    at /mariadb/bb-10.6-monty/strings/my_vsnprintf.c:295
#2  0x000055d599975a0c in process_args (
    cs=cs@entry=0x55d5a3908280 <my_charset_utf8mb3_general_ci>, 
    to=0x7fe42ba4d2ef ' ' <repeats 62 times>, 
    to@entry=0x7fe42ba4d201 'a' <repeats 190 times>, ". Снач"..., 
    end=end@entry=0x7fe42ba4d36f "", fmt=<optimized out>, 
    fmt@entry=0x6330000affbe "*1$s. Сначала выполните STOP SLAVE '%2$*1$s'", arg_index=arg_index@entry=2, ap=ap@entry=0x7fe42ba4d130)
    at /mariadb/bb-10.6-monty/strings/my_vsnprintf.c:527
#3  0x000055d5999783b3 in my_vsnprintf_ex (cs=<optimized out>, 
    to=0x7fe42ba4d201 'a' <repeats 190 times>, ". Снач"..., 
    to@entry=0x7fe42ba4d170 "Эту операцию невозможно выполнить при работающем потоке подчиненного сервера ", 'a' <repeats 55 times>..., n=n@entry=512, 
    fmt=0x6330000affbd "$*1$s. Сначала выполните STOP SLAVE '%2$*1$s'", ap=ap@entry=0x7fe42ba4d130)
    at /mariadb/bb-10.6-monty/strings/my_vsnprintf.c:681
#4  0x000055d5997f66fa in my_error (nr=nr@entry=1198, MyFlags=MyFlags@entry=0)
    at /mariadb/bb-10.6-monty/mysys/my_error.c:120
#5  0x000055d5955d61a2 in change_master (thd=thd@entry=0x62b00007e218, 
    mi=mi@entry=0x62a000036200, 
    master_info_added=master_info_added@entry=0x7fe42ba4fff0)
    at /mariadb/bb-10.6-monty/sql/sql_repl.cc:3604

We can see that deep inside my_vnsprintf(), there is a call to strnmov() with a too large parameter n.
The crash goes away if I revert Add support for minimum field width for strings to my_vsnprintf():

bb-10.6-monty afb1223a74910c09ced32f073cfdf572e1efdf1a without f59557ee13864ebc0b1c2566ad6ce1ee30b1520b

SET SESSION default_master_connection=REPEAT('a',190),lc_messages=ru_ru;
CHANGE MASTER TO master_host='dummy';
START SLAVE sql_thread;
CHANGE MASTER TO master_user='user',master_password='pwd';
rpl.asan-MDEV-25612                      [ fail ]
        Test ended at 2021-05-07 08:08:17
 
CURRENT_TEST: rpl.asan-MDEV-25612
mysqltest: At line 4: query 'CHANGE MASTER TO master_user='user',master_password='pwd'' failed: ER_SLAVE_MUST_STOP (1198): \042D\0442\0443 \043E\043F\0435\0440\0430\0446\0438\044E \043D\0435\0432\043E\0437\043C\043E\0436\043D\043E \0432\044B\043F\043E\043B\043D\0438\0442\044C \043F\0440\0438 \0440\0430\0431\043E\0442\0430\044E\0449\0435\043C \043F\043E\0442\043E\043A\0435 \043F\043E\0434\0447\0438\043D\0435\043D\043D\043E\0433\043E \0441\0435\0440\0432\0435\0440\0430 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa

Comment by Michael Widenius [ 2021-05-09 ]

Fixed in bb-10.6-monty, in the original commit

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