| Bug #113702 | Test binlog.binlog_error_action fails under Sanitizer build | ||
|---|---|---|---|
| Submitted: | 22 Jan 2024 10:20 | Modified: | 4 Jul 2024 8:11 |
| Reporter: | Laurynas Biveinis (OCA) | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Tests | Severity: | S7 (Test Cases) |
| Version: | 8.0.37, 8.3.0 | OS: | MacOS (12.4.1) |
| Assigned to: | CPU Architecture: | Any | |
[22 Jan 2024 10:20]
Laurynas Biveinis
Typo in a title
[22 Jan 2024 12:06]
MySQL Verification Team
Hello Laurynas, Thank you for the report and feedback! regards, Umesh
[24 Jan 2024 10:02]
Laurynas Biveinis
Same on 8.3.0
[5 May 2024 17:37]
Laurynas Biveinis
Same on 8.0.37.
[25 Jun 2024 15:17]
Magnus Blåudd
Posted by developer: This build is done with ASAN + UBSAN and debug binaries. The test requires debug binaries and otherwise it will be skipped. Looking in CI system where we build with ASAN and debug binairies, the test passes: [ 93%] binlog.binlog_error_action 'row' w16 [ pass ] 301637 Please note that it takes quite long time to run. Looking in CI system where we build with UBSA and debug binaries, the test passes: [ 43%] binlog.binlog_error_action 'row' w8 [ pass ] 190144 Normally we don't test binaries built with both UBSAN and ASAN at the same time. Would be good to know if there is anything in the MySQL Server logs or any other indicator why process terminated?
[26 Jun 2024 9:53]
Laurynas Biveinis
Re-testing again on macOS with 8.4.0, using LLVM 16 from Homebrew (bug 113123). The issue reproduces for me without -DWITH_UBSAN=ON and -DWITH_ASAN_SCOPE=ON options, so only -DWITH_ASAN=ON is enough. After a run, var/tmp/binlog_error_action.err contains ... 2024-06-26T09:45:17.905914Z 10 [ERROR] [MY-011072] [Server] Binary logging not possible. Message: Can't open file: './binlog.index' (errno: 1 - Operation not permitted), while rotating the binlog. Aborting the server. 2024-06-26T09:45:17Z UTC - mysqld got signal 6 ; Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware. Thread pointer: 0x6270004e5100 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 16efeae80 thread_stack 0x100000 0 mysqld 0x00000001053e8ca4 my_print_stacktrace(unsigned char const*, unsigned long) + 236 1 mysqld 0x00000001037e0a80 print_fatal_signal(int, __siginfo*) + 1076 2 mysqld 0x00000001037e0f44 my_server_abort() + 392 3 mysqld 0x00000001053d5fbc my_abort() + 20 4 mysqld 0x0000000104ae684c exec_binlog_error_action_abort(char const*) + 440 ... 2024-06-26T09:45:18.398554Z 0 [Warning] [MY-010159] [Server] Setting lower_case_table_names=2 because file system for /Users/laurynas/vilniusdb/mysql-8.4.0/_build-llvm-16-debug-asan-no-scope/mysql-test/var/mysqld.1/data/ is case insensitive ================================================================= ==42204==ERROR: AddressSanitizer: stack-use-after-scope on address 0x00016bc953c0 at pc 0x000116886a84 bp 0x00016bc923c0 sp 0x00016bc91b70 READ of size 27 at 0x00016bc953c0 thread T0 #0 0x116886a80 in wrap_memcpy+0x3f8 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x1aa80) (BuildId: 659e51693d513860a7842c99051e0a4b32000000200000000100000000000b00) #1 0x18f255e10 in __sfvwrite+0x144 (libsystem_c.dylib:arm64+0x4e10) (BuildId: 05b44e93dffc3bd890abfd97cb73f17132000000200000000100000000050e00) #2 0xc1400018f254b3c (<unknown module>) #3 0x9a4b80018f27db20 (<unknown module>) #4 0xac0080011688ea14 (<unknown module>) #5 0x11688f550 in wrap_snprintf+0x4c (libclang_rt.asan_osx_dynamic.dylib:arm64+0x23550) (BuildId: 659e51693d513860a7842c99051e0a4b32000000200000000100000000000b00) #6 0x108925894 in log_sink_trad(void*, _log_line*) log_sink_trad.cc:327 #7 0x104ab4c3c in setup_error_log_components() mysqld.cc:7654 #8 0x104a9b23c in init_server_components() mysqld.cc:7850 #9 0x104a95758 in mysqld_main(int, char**) mysqld.cc:9490 #10 0x18f0320dc (<unknown module>) #11 0x2e1e7ffffffffffc (<unknown module>) Address 0x00016bc953c0 is located in stack of thread T0 at offset 8480 in frame #0 0x1089252a8 in log_sink_trad(void*, _log_line*) log_sink_trad.cc:193 This frame has 2 object(s): [32, 8224) 'internal_buff' (line 289) [8480, 8513) 'buff_local_time' (line 300) <== Memory access at offset 8480 is inside this variable HINT: this may be a false positive if your program uses some custom stack unwind mechanism, swapcontext or vfork (longjmp and C++ exceptions *are* supported) SUMMARY: AddressSanitizer: stack-use-after-scope (libclang_rt.asan_osx_dynamic.dylib:arm64+0x1aa80) (BuildId: 659e51693d513860a7842c99051e0a4b32000000200000000100000000000b00) in wrap_memcpy+0x3f8 Shadow bytes around the buggy address: 0x00016bc95100: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0x00016bc95180: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0x00016bc95200: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0x00016bc95280: 00 00 00 00 00 00 00 00 f2 f2 f2 f2 f2 f2 f2 f2 0x00016bc95300: f2 f2 f2 f2 f2 f2 f2 f2 f2 f2 f2 f2 f2 f2 f2 f2 =>0x00016bc95380: f2 f2 f2 f2 f2 f2 f2 f2[f8]f8 f8 f8 f8 f3 f3 f3 0x00016bc95400: f3 f3 f3 f3 00 00 00 00 00 00 00 00 00 00 00 00 0x00016bc95480: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0x00016bc95500: 00 00 00 00 00 00 00 00 f1 f1 f1 f1 f8 f2 f2 f2 0x00016bc95580: f8 f8 f8 f2 f2 f2 f2 f2 f8 f8 f8 f8 f2 f2 f2 f2 0x00016bc95600: f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 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 ==42204==ABORTING 2024-06-26T09:45:18Z UTC - mysqld got signal 6 ; Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware. Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0 thread_stack 0x100000 0 mysqld 0x0000000106ff4ca4 my_print_stacktrace(unsigned char const*, unsigned long) + 236 1 mysqld 0x00000001053eca80 print_fatal_signal(int, __siginfo*) + 1076 2 mysqld 0x00000001053ec5a8 handle_fatal_signal(int, __siginfo*, void*) + 124 3 libsystem_platform.dylib 0x000000018f3eb584 _sigtramp + 56 4 libsystem_pthread.dylib 0x000000018f3bac20 pthread_kill + 288 5 libsystem_c.dylib 0x000000018f2c7a30 abort + 180 6 libclang_rt.asan_osx_dynamic.dylib 0x00000001168e0bd8 __sanitizer::Atexit(void (*)()) + 0 7 libclang_rt.asan_osx_dynamic.dylib 0x00000001168e0344 __sanitizer::SetCheckUnwindCallback(void (*)()) + 0 8 libclang_rt.asan_osx_dynamic.dylib 0x00000001168c5878 __asan::ErrorDescription::Print() + 0 9 libclang_rt.asan_osx_dynamic.dylib 0x00000001168c4bbc __asan::ReportGenericError(unsigned long, unsigned long, unsigned long, unsigned long, bool, unsigned long, unsigned int, bool) + 1452 10 libclang_rt.asan_osx_dynamic.dylib 0x0000000116886aa4 wrap_memcpy + 1052 11 libsystem_c.dylib 0x000000018f255e14 __sfvwrite + 328 12 libsystem_c.dylib 0x000000018f254b40 __vfprintf + 7288 13 libsystem_c.dylib 0x000000018f27db24 _vsnprintf + 224 14 libclang_rt.asan_osx_dynamic.dylib 0x000000011688ea18 wrap_vsnprintf + 176 15 libclang_rt.asan_osx_dynamic.dylib 0x000000011688f554 wrap_snprintf + 80 16 mysqld 0x0000000108925898 log_sink_trad(void*, _log_line*) + 1532 17 mysqld 0x0000000104ab4c40 setup_error_log_components() + 1520 18 mysqld 0x0000000104a9b240 init_server_components() + 1332 19 mysqld 0x0000000104a9575c mysqld_main(int, char**) + 4988 20 dyld 0x000000018f0320e0 start + 2360 The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains information that should help you find out what is causing the crash.
[4 Jul 2024 8:11]
Laurynas Biveinis
Could not reproduce under 8.0.38 / 8.4.1 / 9.0.0
Description: If the server is compiled with sanitizer options, then the test binlog.binlog_error_action fails: $ mtr binlog.binlog_error_action ... [ 25%] binlog.binlog_error_action 'mix' [ skipped ] Doesn't support --binlog-format = 'mixed' [ 50%] binlog.binlog_error_action 'row' [ skipped ] Doesn't support --binlog-format = 'row' [ 75%] binlog.binlog_error_action 'stmt' [ fail ] Test ended at 2024-01-22 12:15:11 CURRENT_TEST: binlog.binlog_error_action 2024-01-22 13:15:10.513 defaults[39598:57064389] The domain/default pair of (com.apple.CrashReporter, DialogType) does not exist WARNING: MYSQL_OPT_RECONNECT is deprecated and will be removed in a future version. safe_process[39592]: Child process: 39594, killed by signal: 9 Server [mysqld.1 - pid: 39603, winpid: 39603, exit: 512] failed during test run Server log from this test: ----------SERVER LOG START----------- safe_process[39575]: Child process: 39576, exit: 2 safe_process[39603]: Child process: 39604, exit: 2 ----------SERVER LOG END------------- How to repeat: The CMake options I used for build were -DCMAKE_EXPORT_COMPILE_COMMANDS=ON -DCMAKE_BUILD_TYPE=Debug -DWITH_DEBUG=ON -DMYSQL_MAINTAINER_MODE=ON -DDOWNLOAD_BOOST=ON -DWITH_BOOST=~/vilniusdb/mysql-boost/ -DWITH_SYSTEM_LIBS=ON -DFORCE_COLORED_OUTPUT=ON -DCMAKE_C_FLAGS_DEBUG=-g -DCMAKE_CXX_FLAGS_DEBUG=-g -DCMAKE_CXX_FLAGS_RELEASE=-O2 -g -DNDEBUG -Wno-unused-variable -DWITH_ASAN=ON -DWITH_ASAN_SCOPE=ON -DWITH_UBSAN=ON