[MDEV-24571] ASAN failure during KILL CONNECTION Created: 2021-01-11  Updated: 2022-10-04

Status: Open
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.2.37
Fix Version/s: 10.2

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Sergei Golubchik
Resolution: Unresolved Votes: 0
Labels: None

Attachments: File MDEV-17092.sql     File MDEV-17092.yy     File MDEV-24571.sh    
Issue Links:
Relates
relates to MDEV-26014 Race condition between KILL and clien... Closed

 Description    

ASAN failure hit during RQG testing
 
 
 
==3700361==ERROR: AddressSanitizer: heap-use-after-free on address 0x6020000e92d8 at pc 0x7fff1ce310ad bp 0x714242b3eb80 sp 0x714242b3e328
 
READ of size 5 at 0x6020000e92d8 thread T37
 
    #0 0x7fff1ce310ac  (/lib/x86_64-linux-gnu/libasan.so.5+0x6b0ac)
 
    #1 0x560160120d4b in process_str_arg /Server/bb-10.2-serg/strings/my_vsnprintf.c:259
 
    #2 0x560160124f3a in my_vsnprintf_ex /Server/bb-10.2-serg/strings/my_vsnprintf.c:696
 
    #3 0x56016012607f in my_vsnprintf /Server/bb-10.2-serg/strings/my_vsnprintf.c:781
 
    #4 0x56015f049999 in vprint_msg_to_log(loglevel, char const*, __va_list_tag*) /Server/bb-10.2-serg/sql/log.cc:8755
 
    #5 0x56015f01ca35 in Log_to_file_event_handler::log_error(loglevel, char const*, __va_list_tag*) /Server/bb-10.2-serg/sql/log.cc:1028
 
    #6 0x56015f01d440 in LOGGER::error_log_print(loglevel, char const*, __va_list_tag*) /Server/bb-10.2-serg/sql/log.cc:1136
 
    #7 0x56015f03cafe in error_log_print(loglevel, char const*, __va_list_tag*) /Server/bb-10.2-serg/sql/log.cc:6483
 
    #8 0x56015f049e8b in sql_print_warning(char const*, ...) /Server/bb-10.2-serg/sql/log.cc:8786
 
    #9 0x56015e518e2f in THD::print_aborted_warning(unsigned int, char const*) (/data/Server_bin/bb-10.2-serg_asan/bin/mysqld+0xc2ce2f)
 
...
 
    #10 0x56015e699b67 in THD::awake(killed_state) /Server/bb-10.2-serg/sql/sql_class.cc:1698
 
    #11 0x56015e77e969 in kill_one_thread(THD*, long long, killed_state, killed_type) /Server/bb-10.2-serg/sql/sql_parse.cc:8929
 
    #12 0x56015e77f472 in sql_kill /Server/bb-10.2-serg/sql/sql_parse.cc:9035
 
    #13 0x56015e766c88 in mysql_execute_command(THD*) /Server/bb-10.2-serg/sql/sql_parse.cc:5246
 
    #14 0x56015e7775f5 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /Server/bb-10.2-serg/sql/sql_parse.cc:7763
 
    #15 0x56015e75063a in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /Server/bb-10.2-serg/sql/sql_parse.cc:1827
 
    #16 0x56015e74d3f9 in do_command(THD*) /Server/bb-10.2-serg/sql/sql_parse.cc:1381
 
Query : KILL CONNECTION ...
 
Status: KILL_CONNECTION
 
 
 
RQG
 
===
 
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
 
 
perl rqg.pl \              
--duration=300 \
 
--queries=10000000 \
 
--no_mask \
 
--seed=random \
 
--gendata=conf/mariadb/table_stress.zz \
 
--rpl_mode=none \
 
--gendata_sql=MDEV-17092.sql \
 
--engine=InnoDB \
 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
 
--mysqld=--interactive_timeout=28800 \
 
--mysqld=--innodb-lock-wait-timeout=50 \
 
--mysqld=--innodb_stats_persistent=off \
 
--mysqld=--loose-idle_write_transaction_timeout=0 \
 
--mysqld=--loose-table_lock_wait_timeout=50 \
 
--mysqld=--log_bin_trust_function_creators=1 \
 
--mysqld=--net_read_timeout=30 \
 
--mysqld=--log-bin \
 
--mysqld=--connect_timeout=60 \
 
--mysqld=--wait_timeout=28800 \
 
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
--mysqld=--net_write_timeout=60 \
 
--mysqld=--loose-idle_transaction_timeout=0 \
 
--mysqld=--slave_net_timeout=60 \
 
--mysqld=--lock-wait-timeout=86400 \
 
--mysqld=--log-output=none \
 
--reporters=Backtrace,Deadlock1,ErrorLog \
 
--validators=None \
 
--grammar=MDEV-17092.yy \
 
--threads=10 \
 
--workdir=<local settings> \
 
--vardir=<local settings> \
 
--mtr-build-thread=<local settings> \
 
--basedir1=<local settings> \
 
--script_debug=_nix_ \
 
--rr=Extended \
 
--rr_options=--chaos 
 
 
pluto:/data/Results/1610378376/MDEV-24571/dev/shm/vardir/1610378376/18/1/rr
 
_RR_TRACE_DIR="." rr replay --mark-stdio
 
 
 
(rr) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x00001d45073a7859 in __GI_abort () at abort.c:79
 
#2  0x00007fff1cef16a2 in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
 
#3  0x00007fff1cefc24c in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
 
#4  0x00007fff1cedd8ec in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
 
#5  0x00007fff1cedd363 in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
 
#6  0x00007fff1ce310cc in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
 
#7  0x0000560160120d4c in process_str_arg (cs=0x560161518ec0 <my_charset_latin1>, to=0x714242b3ef6e "", end=0x714242b3f34f "", width=192, par=0x6020000e92d8 "test", print_type=0, nice_cut=0 '\000')
 
    at /Server/bb-10.2-serg/strings/my_vsnprintf.c:259
 
#8  0x0000560160124f3b in my_vsnprintf_ex (cs=0x560161518ec0 <my_charset_latin1>, to=0x714242b3ef6e "", n=1024, fmt=0x560160425ee6 "s' user: '%-.48s' host: '%-.64s' (%-.64s)", ap=0x714242b3f540) at /Server/bb-10.2-serg/strings/my_vsnprintf.c:696
 
#9  0x0000560160126080 in my_vsnprintf (to=0x714242b3ef50 "Aborted connection 71 to db: '", n=1024, fmt=0x560160425ec0 "Aborted connection %lld to db: '%-.192s' user: '%-.48s' host: '%-.64s' (%-.64s)", ap=0x714242b3f540)
 
    at /Server/bb-10.2-serg/strings/my_vsnprintf.c:781
 
#10 0x000056015f04999a in vprint_msg_to_log (level=WARNING_LEVEL, format=0x560160425ec0 "Aborted connection %lld to db: '%-.192s' user: '%-.48s' host: '%-.64s' (%-.64s)", args=0x714242b3f540) at /Server/bb-10.2-serg/sql/log.cc:8755
 
#11 0x000056015f01ca36 in Log_to_file_event_handler::log_error (this=0x61e000000080, level=WARNING_LEVEL, format=0x560160425ec0 "Aborted connection %lld to db: '%-.192s' user: '%-.48s' host: '%-.64s' (%-.64s)", args=0x714242b3f540)
 
    at /Server/bb-10.2-serg/sql/log.cc:1028
 
#12 0x000056015f01d441 in LOGGER::error_log_print (this=0x560161691220 <logger>, level=WARNING_LEVEL, format=0x560160425ec0 "Aborted connection %lld to db: '%-.192s' user: '%-.48s' host: '%-.64s' (%-.64s)", args=0x714242b3f540)
 
    at /Server/bb-10.2-serg/sql/log.cc:1136
 
#13 0x000056015f03caff in error_log_print (level=WARNING_LEVEL, format=0x560160425ec0 "Aborted connection %lld to db: '%-.192s' user: '%-.48s' host: '%-.64s' (%-.64s)", args=0x714242b3f540) at /Server/bb-10.2-serg/sql/log.cc:6483
 
#14 0x000056015f049e8c in sql_print_warning (format=0x560160425ec0 "Aborted connection %lld to db: '%-.192s' user: '%-.48s' host: '%-.64s' (%-.64s)") at /Server/bb-10.2-serg/sql/log.cc:8786
 
#15 0x000056015e518e30 in THD::print_aborted_warning (this=0x62a000270208, threshold=3, reason=0x56016022fb40 "KILLED") at /Server/bb-10.2-serg/sql/sql_class.h:4220
 
#16 0x000056015e699b68 in THD::awake (this=0x62a000270208, state_to_set=KILL_CONNECTION_HARD) at /Server/bb-10.2-serg/sql/sql_class.cc:1698
 
#17 0x000056015e77e96a in kill_one_thread (thd=0x62a00021c208, id=71, kill_signal=KILL_CONNECTION_HARD, type=KILL_TYPE_ID) at /Server/bb-10.2-serg/sql/sql_parse.cc:8929
 
#18 0x000056015e77f473 in sql_kill (thd=0x62a00021c208, id=71, state=KILL_CONNECTION_HARD, type=KILL_TYPE_ID) at /Server/bb-10.2-serg/sql/sql_parse.cc:9035
 
#19 0x000056015e766c89 in mysql_execute_command (thd=0x62a00021c208) at /Server/bb-10.2-serg/sql/sql_parse.cc:5246
 
#20 0x000056015e7775f6 in mysql_parse (thd=0x62a00021c208, rawbuf=0x62b0000e0228 "KILL CONNECTION @kill_id /* E_R Thread5 QNO 52 CON_ID 89 */", length=59, parser_state=0x714242b40ce0, is_com_multi=false, is_next_command=false)
 
    at /Server/bb-10.2-serg/sql/sql_parse.cc:7763
 
#21 0x000056015e75063b in dispatch_command (command=COM_QUERY, thd=0x62a00021c208, packet=0x629000f5a209 " KILL CONNECTION @kill_id /* E_R Thread5 QNO 52 CON_ID 89 */ ", packet_length=61, is_com_multi=false, is_next_command=false)
 
    at /Server/bb-10.2-serg/sql/sql_parse.cc:1827
 
#22 0x000056015e74d3fa in do_command (thd=0x62a00021c208) at /Server/bb-10.2-serg/sql/sql_parse.cc:1381
 
#23 0x000056015ead5239 in do_handle_one_connection (connect=0x6080000011a8) at /Server/bb-10.2-serg/sql/sql_connect.cc:1336
 
#24 0x000056015ead4afc in handle_one_connection (arg=0x6080000011a8) at /Server/bb-10.2-serg/sql/sql_connect.cc:1241
 
#25 0x00007fe8e982d609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#26 0x00001d45074a4293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
(rr)



 Comments   
Comment by Matthias Leich [ 2021-01-11 ]

Please try some
cd <top directory of RQG installation>
./MDEV-24571.sh <path to your MariaDB binaries>

You might need several attempts.

I apologize in advance in case my RQG version has maybe trouble with some
in source or out of source builds because I use all time
build out of source with some install directory assigned and than install.
<RQG top level directory>/util/bld_asan.sh gives an example of how I build+install.

Comment by Matthias Leich [ 2021-04-09 ] 

The rr profile mentioned in the bug description became invalid.
 
The problem was hit again
 
- on origin/bb-10.2-MDEV-24719-last-skipped-lsn-check 3ff15ca16d86ef422187e2e0f4a0245cc31782fb 2021-03-01T16:44:14+03:00
 
- unfortunately with some fat test (not the simplified one)
 
- pluto:/data/Results/1614680153/TBR-819-MDEV-24571/dev/shm/vardir/1614680153/100/1/rr
 
  _RR_TRACE_DIR="." rr replay --mark-stdio
 
  In case you dislike the rr trace than please show up and I will try again with the simplified test.
 
 
 
Error pattern for RQG
 
[ 'TBR-819', 'ERROR: AddressSanitizer: heap-use-after-free on address.+in process_str_arg.{1,10000}my_vsnprintf_ex.{1,10000}my_vsnprintf.{1,10000}vprint_msg_to_log.{1,10000}Log_to_file_event_handler::log_error.{1,10000}LOGGER::error_log_print' ],

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