[MDEV-23097] heap-use-after-free in mysqlimport Created: 2020-07-05  Updated: 2022-09-05  Resolved: 2022-08-02

Status: Closed
Project: MariaDB Server
Component/s: Scripts & Clients
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.3.36, 10.4.26, 10.5.17, 10.6.9, 10.7.5, 10.8.4

Type: Bug Priority: Major
Reporter: Marko Mäkelä Assignee: Sergei Golubchik
Resolution: Fixed Votes: 1
Labels: ASAN, corruption, race, rr-profile

Issue Links:
Relates
relates to MDEV-29463 mysqlimport occasionally fails to fai... Closed

 Description   

The test main.mysqldump occasionally fails like this on ASAN, suggesting that mysqlimport is accessing freed memory:

10.5 90d5d906409025d64a4ab8eff3e5704c13c256a4

 
CURRENT_TEST: main.mysqldump
 
mysqldump: Couldn't find table: "non_existing"
 
mysqldump: Got error: 1356: "View 'test.v1' references invalid table(s) or column(s) or function(s) or definer/invoker of view lack rights to use them" when using LOCK TABLES
 
mysqldump: Couldn't execute 'SHOW FIELDS FROM `v1`': View 'test.v1' references invalid table(s) or column(s) or function(s) or definer/invoker of view lack rights to use them (1356)
 
mysqldump: Got error: 1083: "Field separator argument is not what is expected; check the manual" when executing 'SELECT INTO OUTFILE'
 
mysqldump: Got error: 1083: "Field separator argument is not what is expected; check the manual" when executing 'SELECT INTO OUTFILE'
 
mysqldump: Got error: 1083: "Field separator argument is not what is expected; check the manual" when executing 'SELECT INTO OUTFILE'
 
mysqldump: user2 has insufficient privileges to SHOW CREATE PROCEDURE `sp1`!
 
mysqldump: Got error: 1146: "Table 'test.???????????????????????' doesn't exist" when using LOCK TABLES
 
/dev/shm/10.5a/client/mysqlimport: Error: 1146, Table 'test.words' doesn't exist, when using table: words
 
=================================================================
 
==126464==ERROR: AddressSanitizer: heap-use-after-free on address 0x61500000020f at pc 0x000000485417 bp 0x7ff7af1fb4f0 sp 0x7ff7af1facb0
 
READ of size 5 at 0x61500000020f thread T4
 
    #0 0x485416 in strdup (/dev/shm/10.5a/client/mariadb-import+0x485416)
 
    #1 0x4d8bc4 in mthd_my_real_connect /mariadb/10.5m/libmariadb/libmariadb/mariadb_lib.c:1535:21
 
    #2 0x4d79d1 in mysql_real_connect /mariadb/10.5m/libmariadb/libmariadb/mariadb_lib.c:1295:10
 
    #3 0x4cb629 in db_connect /mariadb/10.5m/client/mysqlimport.c:473:9
 
    #4 0x4cb184 in worker_thread /mariadb/10.5m/client/mysqlimport.c:605:16
 
    #5 0x7ff7b464af26 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x8f26)
 
    #6 0x7ff7b3ea331e in clone (/lib/x86_64-linux-gnu/libc.so.6+0xfd31e)
 
 
 
0x61500000020f is located 399 bytes inside of 496-byte region [0x615000000080,0x615000000270)
 
freed by thread T3 here:
 
    #0 0x498e7d in free (/dev/shm/10.5a/client/mariadb-import+0x498e7d)
 
    #1 0x57654b in my_free /mariadb/10.5m/mysys/my_malloc.c:209:3
 
    #2 0x567ce6 in free_root /mariadb/10.5m/mysys/my_alloc.c:416:7
 
    #3 0x55ffe9 in free_defaults /mariadb/10.5m/mysys/my_default.c:500:3
 
    #4 0x4cc18b in safe_exit /mariadb/10.5m/client/mysqlimport.c:518:3
 
    #5 0x4cc18b in db_error_with_table /mariadb/10.5m/client/mysqlimport.c:533:3
 
    #6 0x4cc18b in write_to_table /mariadb/10.5m/client/mysqlimport.c:384:5
 
    #7 0x4cb1ae in worker_thread /mariadb/10.5m/client/mysqlimport.c:619:14
 
 
 
previously allocated by thread T0 here:
 
    #0 0x4990fd in malloc (/dev/shm/10.5a/client/mariadb-import+0x4990fd)
 
    #1 0x575bfc in my_malloc /mariadb/10.5m/mysys/my_malloc.c:88:29
 
    #2 0x567002 in alloc_root /mariadb/10.5m/mysys/my_alloc.c:243:30
 
    #3 0x55fb2f in init_default_directories /mariadb/10.5m/mysys/my_default.c:1016:24
 
    #4 0x55e8eb in my_load_defaults /mariadb/10.5m/mysys/my_default.c:414:14
 
    #5 0x4cc3b7 in main /mariadb/10.5m/client/mysqlimport.c:643:3
 
    #6 0x7ff7b3dcce0a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x26e0a)
 
 
 
Thread T4 created by T0 here:
 
    #0 0x483eaa in pthread_create (/dev/shm/10.5a/client/mariadb-import+0x483eaa)
 
    #1 0x4cc999 in main /mariadb/10.5m/client/mysqlimport.c:693:11
 
    #2 0x7ff7b3dcce0a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x26e0a)
 
 
 
Thread T3 created by T0 here:
 
    #0 0x483eaa in pthread_create (/dev/shm/10.5a/client/mariadb-import+0x483eaa)
 
    #1 0x4cc999 in main /mariadb/10.5m/client/mysqlimport.c:693:11
 
    #2 0x7ff7b3dcce0a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x26e0a)
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free (/dev/shm/10.5a/client/mariadb-import+0x485416) in strdup
 
Shadow bytes around the buggy address:
 
  0x0c2a7fff7ff0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0c2a7fff8000: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c2a7fff8010: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c2a7fff8020: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c2a7fff8030: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c2a7fff8040: fd[fd]fd fd fd fd fd fd fd fd fd fd fd fd fa fa
 
  0x0c2a7fff8050: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c2a7fff8060: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c2a7fff8070: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c2a7fff8080: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c2a7fff8090: fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa
 
Shadow byte legend (one shadow byte represents 8 application bytes):
 
  Addressable:           00
 
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack after return:      f5
 
  Stack use after scope:   f8
 
  Global redzone:          f9
 
  Global init order:       f6
 
  Poisoned by user:        f7
 
  Container overflow:      fc
 
  Array cookie:            ac
 
  Intra object redzone:    bb
 
  ASan internal:           fe
 
  Left alloca redzone:     ca
 
  Right alloca redzone:    cb
 
  Shadow gap:              cc
 
==126464==ABORTING
 
Aborted
 
mysqltest: At line 1785: command "$MYSQL_IMPORT --silent --use-threads=2 test $MYSQLTEST_VARDIR/tmp/t1.txt $MYSQLTEST_VARDIR/tmp/t2.txt $MYSQLTEST_VARDIR/std_data/words.dat $MYSQLTEST_VARDIR/std_data/words2.dat" failed with wrong error: 134

Cross-reference finds at least 2 occurrences of this on 10.1 (back when we still had kvm-asan running on 10.1). The newest kvm-asan occurrence seems to be on 10.5 424dc49d415ae27345cc3b9548329da4 (sorry, no logs available outside cross-reference).

Over the past few days, I have repeated a failure twice when running an ASAN build of 10.5 locally. WIth the following invocation, I can repeat it after a few tries:

ASAN_OPTIONS=abort_on_error=1 ./mtr --repeat=10 --parallel=auto main.mysqldump{,,,,,,,,,,,,,}

10.5 90d5d906409025d64a4ab8eff3e5704c13c256a4

 
main.mysqldump 'innodb'                  w11 [ 2 pass ]  14034
 
main.mysqldump 'innodb'                  w11 [ 3 fail ]



 Comments   
Comment by Marko Mäkelä [ 2021-03-12 ]

This failed on 10.5 kvm-asan again. I was able to repeat this locally with the following patch:

diff --git a/mysql-test/main/mysqldump.test b/mysql-test/main/mysqldump.test
 
index 799f24665ee..a68f3b2871d 100644
 
--- a/mysql-test/main/mysqldump.test
 
+++ b/mysql-test/main/mysqldump.test
 
@@ -1768,7 +1768,7 @@ drop table words;
 
 --replace_regex /.*mysqlimport(\.exe)*/mysqlimport/
 
 --replace_result mysqldump.exe mysqldump
 
 --error 1
 
---exec $MYSQL_IMPORT --silent --use-threads=2 test $MYSQLTEST_VARDIR/tmp/t1.txt $MYSQLTEST_VARDIR/tmp/t2.txt $MYSQLTEST_VARDIR/std_data/words.dat $MYSQLTEST_VARDIR/std_data/words2.dat
 
+--exec rr record $MYSQL_IMPORT --silent --use-threads=2 test $MYSQLTEST_VARDIR/tmp/t1.txt $MYSQLTEST_VARDIR/tmp/t2.txt $MYSQLTEST_VARDIR/std_data/words.dat $MYSQLTEST_VARDIR/std_data/words2.dat
 
 
 drop table t1;
 
 drop table t2;

and with the following invocation:

ASAN_OPTIONS=abort_on_error=1 _RR_TRACE_DIR=/dev/shm/rr ./mtr --repeat=100 --parallel=auto main.mysqldump{,,,,,,,,,,,,,,,}

Due to the parallel invocation, it took some time to find the trace. But I got it:

10.5 4c2b6be38e7c62d585b137ab9b3af4907a08a737

 
/dev/shm/10.5a/client/mysqlimport: Error: 1146, Table 'test.words' doesn't exist, when using table: words
 
=================================================================
 
==234496==ERROR: AddressSanitizer: heap-use-after-free on address 0x6150000001bd at pc 0x0000004ce5d9 bp 0x7f42b0dfbd70 sp 0x7f42b0dfbd68
 
READ of size 1 at 0x6150000001bd thread T4
 
    #0 0x4ce5d8 in db_connect /mariadb/10.5m/client/mysqlimport.c:467:25
 
    #1 0x4cdf94 in worker_thread /mariadb/10.5m/client/mysqlimport.c:610:16
 
    #2 0x7f42b67e0ea6 in start_thread nptl/pthread_create.c:477:8
 
    #3 0x7f42b602fdee in clone misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
 
 
0x6150000001bd is located 317 bytes inside of 496-byte region [0x615000000080,0x615000000270)
 
freed by thread T3 here:
 
    #0 0x49b75d in free (/dev/shm/10.5a/client/mariadb-import+0x49b75d)
 
    #1 0x56b097 in free_root /mariadb/10.5m/mysys/my_alloc.c:416:7
 
    #2 0x4cedcb in safe_exit /mariadb/10.5m/client/mysqlimport.c:523:3
 
    #3 0x4cedcb in db_error_with_table /mariadb/10.5m/client/mysqlimport.c:538:3
 
    #4 0x4cedcb in write_to_table /mariadb/10.5m/client/mysqlimport.c:389:5
 
    #5 0x4cdfbe in worker_thread /mariadb/10.5m/client/mysqlimport.c:624:14
 
…
 
Shadow bytes around the buggy address:
 
…
 
=>0x0c2a7fff8030: fd fd fd fd fd fd fd[fd]fd fd fd fd fd fd fd fd
 
…
 
(rr) watch -l *(char*)0x0c2a7fff8037
 
Hardware watchpoint 1: -location *(char*)0x0c2a7fff8037
 
(rr) rc
 
Continuing.
 
 
 
Thread 3 received signal SIGABRT, Aborted.
 
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
50	in ../sysdeps/unix/sysv/linux/raise.c
 
(rr) 
Continuing.
 
[Switching to Thread 234496.234743]
 
 
 
Thread 4 hit Hardware watchpoint 1: -location *(char*)0x0c2a7fff8037
 
 
 
Old value = -3 '\375'
 
New value = -9 '\367'
 
__memset_avx2_unaligned_erms ()
 
    at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:178
 
178	../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S: Tiedostoa tai hakemistoa ei ole.
 
(rr) bt
 
#0  __memset_avx2_unaligned_erms ()
 
    at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:178
 
#1  0x00000000004273bd in __asan::Allocator::QuarantineChunk(__asan::AsanChunk*, void*, __sanitizer::BufferedStackTrace*) ()
 
#2  0x000000000049b7e2 in free ()
 
#3  0x00000000005772e0 in my_free (ptr=<optimized out>)
 
    at /mariadb/10.5m/mysys/my_malloc.c:211
 
#4  0x000000000056b098 in free_root (root=root@entry=0x7f42b15fa1a0, 
    MyFlags=<optimized out>, MyFlags@entry=0)
 
    at /mariadb/10.5m/mysys/my_alloc.c:416
 
#5  0x000000000056081a in free_defaults (argv=<optimized out>)
 
    at /mariadb/10.5m/mysys/my_default.c:500
 
#6  0x00000000004cedcc in safe_exit (error=1, mysql=0x61a00001fe80)
 
    at /mariadb/10.5m/client/mysqlimport.c:523
 
#7  db_error_with_table (mysql=0x61a00001fe80, table=<optimized out>)
 
    at /mariadb/10.5m/client/mysqlimport.c:538
 
#8  write_to_table (filename=<optimized out>, mysql=<optimized out>)
 
    at /mariadb/10.5m/client/mysqlimport.c:389
 
#9  0x00000000004cdfbf in worker_thread (arg=0x7ffdba3512d4)
 
    at /mariadb/10.5m/client/mysqlimport.c:624

At the time the memory is freed, the thread that catches the error is blocked in a system call (I guess, being created):

(rr) thread apply 3 backtrace
 
 
 
Thread 3 (Thread 234496.234752 (mmap_copy_4_mar)):
 
#0  0x0000000070000002 in ?? ()
 
#1  0x00007f42b68272f3 in _raw_syscall () at /build/rr-7fqooc/rr-5.4.0/src/preload/raw_syscall.S:120
 
#2  0x00007f42b68252f7 in traced_raw_syscall (call=0x7f42b18fdfa0) at ./src/preload/syscallbuf.c:272
 
#3  syscall_hook_internal (call=0x7f42b18fdfa0) at ./src/preload/syscallbuf.c:3295
 
#4  syscall_hook (call=0x7f42b18fdfa0) at ./src/preload/syscallbuf.c:3329
 
#5  0x00007f42b6822270 in _syscall_hook_trampoline () at /build/rr-7fqooc/rr-5.4.0/src/preload/syscall_hook.S:313
 
#6  0x00007f42b68222cf in __morestack () at /build/rr-7fqooc/rr-5.4.0/src/preload/syscall_hook.S:458
 
#7  0x00007f42b682237a in _syscall_hook_trampoline_c3_nop () at /build/rr-7fqooc/rr-5.4.0/src/preload/syscall_hook.S:527
 
#8  0x0000000000000000 in ?? ()

Finally, this thread will trip ASAN:

#6  0x00000000004a1be8 in __asan_report_load1 ()
 
#7  0x00000000004ce5d9 in db_connect (host=<optimized out>, 
    database=<optimized out>, user=<optimized out>, passwd=<optimized out>)
 
    at /mariadb/10.5m/client/mysqlimport.c:467
 
#8  0x00000000004cdf95 in worker_thread (arg=0x7ffdba351307)
 
    at /mariadb/10.5m/client/mysqlimport.c:610
 
#9  0x00007f42b67e0ea7 in start_thread (arg=<optimized out>)
 
    at pthread_create.c:477
 
#10 0x00007f42b602fdef in clone ()
 
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

As far as I understand, safe_exit() isn’t, because it does not wait for all worker_thread to exit. At the time of the crash, the exiting thread is still executing an atexit() handler that was installed for AddressSanitizer:

(rr) thread apply 4 backtrace
 
 
 
Thread 4 (Thread 234496.234743 (mmap_copy_4_mar)):
 
#0  0x00000000004b1f70 in __sanitizer::BlockingMutex::Lock() ()
 
#1  0x00000000004c5229 in __lsan::LockStuffAndStopTheWorldCallback(dl_phdr_info*, unsigned long, void*) ()
 
#2  0x00007f42b60691e5 in __GI___dl_iterate_phdr (
 
    callback=0x4c5220 <__lsan::LockStuffAndStopTheWorldCallback(dl_phdr_info*, unsigned long, void*)>, data=0x7f42b15fa148) at dl-iteratephdr.c:75
 
#3  0x00000000004c520f in __lsan::LockStuffAndStopTheWorld(void (*)(__sanitizer::SuspendedThreadsList const&, void*), __lsan::CheckForLeaksParam*) ()
 
#4  0x00000000004c29d8 in __lsan::CheckForLeaks() ()
 
#5  0x00000000004c2942 in __lsan::DoLeakCheck() ()
 
#6  0x00007f42b5f704d7 in __run_exit_handlers (status=1, 
    listp=0x7f42b60f0718 <__exit_funcs>, 
    run_list_atexit=run_list_atexit@entry=true, run_dtors=run_dtors@entry=true)
 
    at exit.c:108
 
#7  0x00007f42b5f7067a in __GI_exit (status=<optimized out>) at exit.c:139
 
#8  0x00000000004cef3d in write_to_table (filename=<optimized out>, 
    mysql=<optimized out>) at /mariadb/10.5m/client/mysqlimport.c:368
 
#9  0x00000000004cdfbf in worker_thread (arg=0x7ffdba3512d4)

As far as I understand, even if this atexit handler did not exist, there is a race condition between other worker_thread and this code in safe_exit():

  free_defaults(argv_to_free);
 
  my_free(opt_password);
 
  if (error)
 
    sf_leaking_memory= 1; /* dirty exit, some threads are still running */
 
  else
 
    my_end(my_end_arg); /* clean exit */
 
  exit(error);

Before all threads are actually terminated, they can access the freed memory. Here is the start of worker_thread():

  if (mysql_thread_init())
 
    goto error;
 
  
  if (!(mysql= db_connect(current_host,current_db,current_user,opt_password)))

We crashed inside db_connect(), for accessing opt_plugin_dir. Note that also opt_password had been explicitly freed by safe_exit().

It seems to me that to fix this race condition, the scope of init_mutex or counter_mutex must be extended, and possibly a condition variable would be needed so that safe_exit() can wait for all worker_thread to exit.

Comment by Michael Widenius [ 2021-11-16 ]

I increase the level to critical as it happens often enough on buildbot and also at my desktop when running the mtr test suite

Comment by Oleksandr Byelkin [ 2022-06-22 ]

I tried to repeat, 150 times run with no problem.

Comment by Oleksandr Byelkin [ 2022-06-22 ]

(I will be thankful for any idea how to repeat, while I am trying to fix it by looking on sources)

Comment by Oleksandr Byelkin [ 2022-06-22 ]

I do not see how it is possible, will return to it later

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