Bug #82283 main.mysqlbinlog_debug fails with a LeakSanitizer error
Submitted: 19 Jul 2016 15:13 Modified: 14 Jul 2017 14:27
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.6,5.7, 5.7.13 OS:Any
Assigned to: CPU Architecture:Any
Tags: asan, lsan, mysqlbinlog

[19 Jul 2016 15:13] Laurynas Biveinis
Description:
On a system with AddressSanitizer support that includes LeakSanitizer, -DWITH_ASAN=ON -DCMAKE_BUILD_TYPE=Debug configured server will give

$ ./mtr --debug-server mysqlbinlog_debug
...
main.mysqlbinlog_debug                   [ fail ]
        Test ended at 2016-07-19 18:09:31

CURRENT_TEST: main.mysqlbinlog_debug
mysqltest: At line 14: command "$MYSQL_BINLOG -#d,simulate_result_file_write_error_for_FD_event --raw --read-from-remote-server --user=root --host=127.0.0.1 --port=$MASTER_MYPORT -r$MYSQLTEST_VARDIR/tmp/ master-bin.000001 2>&1" failed with wrong error: 42

The result from queries just before the failure was:
#
# Bug#18742916 : MYSQLBINLOG --RAW DOES NOT CHECK FOR ERRORS
#
safe_process[939]: Child process: 940, exit: 1

If "2>&1" is removed, then the output contains

URRENT_TEST: main.mysqlbinlog_debug
ERROR: Could not write into log file '/home/laurynas/obj-5.7-asan-debug/mysql-test/var/tmp/master-bin.000001'

=================================================================
==1117==ERROR: LeakSanitizer: detected memory leaks

Direct leak of 336 byte(s) in 1 object(s) allocated from:
    #0 0x7fd08b154602 in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x98602)
    #1 0x4e9004 in my_raw_malloc /home/laurynas/mysql-server/mysys/my_malloc.c:191
    #2 0x4e9004 in my_malloc /home/laurynas/mysql-server/mysys/my_malloc.c:54
    #3 0x4168c2 in Log_event::operator new(unsigned long) /home/laurynas/mysql-server/sql/log_event.cc:737
    #4 0x42cdb7 in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /home/laurynas/mysql-server/sql/log_event.cc:1592
    #5 0x449231 in dump_remote_log_entries /home/laurynas/mysql-server/client/mysqlbinlog.cc:2692
    #6 0x449231 in dump_single_log /home/laurynas/mysql-server/client/mysqlbinlog.cc:2328
    #7 0x449231 in dump_multiple_logs /home/laurynas/mysql-server/client/mysqlbinlog.cc:2368
    #8 0x44a6de in main /home/laurynas/mysql-server/client/mysqlbinlog.cc:3430
    #9 0x7fd08a05182f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

Indirect leak of 78 byte(s) in 1 object(s) allocated from:
    #0 0x7fd08b155532 in operator new(unsigned long) (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x99532)
    #1 0x5be727 in __gnu_cxx::new_allocator<unsigned char>::allocate(unsigned long, void const*) /usr/include/c++/5/ext/new_allocator.h:104
    #2 0x5be727 in __gnu_cxx::__alloc_traits<std::allocator<unsigned char> >::allocate(std::allocator<unsigned char>&, unsigned long) /usr/include/c++/5/ext/alloc_traits.h:182
    #3 0x5be727 in std::_Vector_base<unsigned char, std::allocator<unsigned char> >::_M_allocate(unsigned long) /usr/include/c++/5/bits/stl_vector.h:170
    #4 0x5be727 in void std::vector<unsigned char, std::allocator<unsigned char> >::_M_range_insert<char const*>(__gnu_cxx::__normal_iterator<unsigned char*, std::vector<unsigned char, std::allocator<unsigned char> > >, char const*, char const*, std::forward_iterator_tag) /usr/include/c++/5/bits/vector.tcc:659
    #5 0x5bc215 in void std::vector<unsigned char, std::allocator<unsigned char> >::_M_insert_dispatch<char const*>(__gnu_cxx::__normal_iterator<unsigned char*, std::vector<unsigned char, std::allocator<unsigned char> > >, char const*, char const*, std::__false_type) /usr/include/c++/5/bits/stl_vector.h:1377
    #6 0x5bc215 in void std::vector<unsigned char, std::allocator<unsigned char> >::insert<char const*>(__gnu_cxx::__normal_iterator<unsigned char*, std::vector<unsigned char, std::allocator<unsigned char> > >, char const*, char const*) /usr/include/c++/5/bits/stl_vector.h:1125
    #7 0x5bc215 in binary_log::Format_description_event::Format_description_event(char const*, unsigned int, binary_log::Format_description_event const*) /home/laurynas/mysql-server/libbinlogevents/src/control_events.cpp:345
    #8 0x41ae85 in Format_description_log_event::Format_description_log_event(char const*, unsigned int, binary_log::Format_description_event const*) /home/laurynas/mysql-server/sql/log_event.cc:5242
    #9 0x42cdd2 in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /home/laurynas/mysql-server/sql/log_event.cc:1592
    #10 0x449231 in dump_remote_log_entries /home/laurynas/mysql-server/client/mysqlbinlog.cc:2692
    #11 0x449231 in dump_single_log /home/laurynas/mysql-server/client/mysqlbinlog.cc:2328
    #12 0x449231 in dump_multiple_logs /home/laurynas/mysql-server/client/mysqlbinlog.cc:2368
    #13 0x44a6de in main /home/laurynas/mysql-server/client/mysqlbinlog.cc:3430
    #14 0x7fd08a05182f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

SUMMARY: AddressSanitizer: 414 byte(s) leaked in 2 allocation(s).
mysqltest: At line 14: command "$MYSQL_BINLOG -#d,simulate_result_file_write_error_for_FD_event --raw --read-from-remote-server --user=root --host=127.0.0.1 --port=$MASTER_MYPORT -r$MYSQLTEST_VARDIR/tmp/ master-bin.000001" failed with wrong error: 42

The result from queries just before the failure was:
#
# Bug#18742916 : MYSQLBINLOG --RAW DOES NOT CHECK FOR ERRORS
#
safe_process[1109]: Child process: 1110, exit: 1

How to repeat:
CMake options -DWITH_ASAN=ON -DCMAKE_BUILD_TYPE=Debug
$ ./mtr --debug-server mysqlbinlog_debug
[19 Jul 2016 16:54] Miguel Solorzano
Thank you for the bug repoprt. Which version of 5.7.X you tested? I couldn't repeat with 5.7.13 on MAC OSX:

iguel:mysql-5.7.13 miguel$ cd mysql-test/
miguel:mysql-test miguel$ ./mtr --debug-server mysqlbinlog_debug
Logging: ./mtr  --debug-server mysqlbinlog_debug
MySQL Version 5.7.13
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Removing old var directory...
Creating var directory '/Users/miguel/Downloads/mysql-5.7.13/mysql-test/var'...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.mysqlbinlog_debug                   [ pass ]    924
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.924 of 48 seconds executing testcases

Completed: All 1 tests were successful.

miguel:mysql-test miguel$ cmake -DWITH_ASAN=ON -DCMAKE_BUILD_TYPE=Debug -DWITH_BOOST=./boost/boost_1_59_0/
[20 Jul 2016 4:36] Laurynas Biveinis
This is not on on Mac, as its AddressSanitizer does not contain LeakSanitizer. I have tested latest 5.6 and 5.7 on Ubuntu Xenial.
[20 Jul 2016 7:09] Umesh Shastry
Thank you for the details.
[20 Jul 2016 7:09] Umesh Shastry
test results

Attachment: 82283.log (text/x-log), 2.88 MiB.

[22 Jul 2016 7:08] Laurynas Biveinis
Bug 82283 fix for 5.7

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug82283-5.7.patch (application/octet-stream, text), 1.28 KiB.

[19 Apr 2017 2:28] Laurynas Biveinis
Same issue seen with Valgrind on 8.0.1:

==1066== 78 bytes in 1 blocks are indirectly lost in loss record 573 of 636
==1066==    at 0x4C2E19F: operator new(unsigned long) (vg_replace_malloc.c:334)
==1066==    by 0x2910FB: __gnu_cxx::new_allocator<unsigned char>::allocate(unsigned long, void const*) (new_allocator.h:104)
==1066==    by 0x290BF7: std::allocator_traits<std::allocator<unsigned char> >::allocate(std::allocator<unsigned char>&, unsigned long) (alloc_traits.h:436)
==1066==    by 0x2903D5: std::_Vector_base<unsigned char, std::allocator<unsigned char> >::_M_allocate(unsigned long) (stl_vector.h:170)
==1066==    by 0x29067F: void std::vector<unsigned char, std::allocator<unsigned char> >::_M_range_insert<unsigned char const*>(__gnu_cxx::__normal_iterator<unsigned char*, std::vector<unsigned char, std::allocator<unsigned char> > >, unsigned char const*, unsigned char const*, std::forward_iterator_tag) (vector.tcc:659)
==1066==    by 0x28F8A0: void std::vector<unsigned char, std::allocator<unsigned char> >::_M_insert_dispatch<unsigned char const*>(__gnu_cxx::__normal_iterator<unsigned char*, std::vector<unsigned char, std::allocator<unsigned char> > >, unsigned char const*, unsigned char const*, std::__false_type) (stl_vector.h:1375)
==1066==    by 0x28F1AD: __gnu_cxx::__normal_iterator<unsigned char*, std::vector<unsigned char, std::allocator<unsigned char> > > std::vector<unsigned char, std::allocator<unsigned char> >::insert<unsigned char const*, void>(__gnu_cxx::__normal_iterator<unsigned char const*, std::vector<unsigned char, std::allocator<unsigned char> > >, unsigned char const*, unsigned char const*) (stl_vector.h:1100)
==1066==    by 0x28D03F: binary_log::Format_description_event::Format_description_event(char const*, unsigned int, binary_log::Format_description_event const*) (control_events.cpp:339)
==1066==    by 0x196EE6: Format_description_log_event::Format_description_log_event(char const*, unsigned int, binary_log::Format_description_event const*) (log_event.cc:5585)
==1066==    by 0x1905EB: Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, bool) (log_event.cc:1717)
==1066==    by 0x188B39: dump_remote_log_entries(st_print_event_info*, char const*) (mysqlbinlog.cc:2377)
==1066==    by 0x18803E: dump_single_log(st_print_event_info*, char const*) (mysqlbinlog.cc:2069)
==1066==    by 0x188240: dump_multiple_logs(int, char**) (mysqlbinlog.cc:2110)
==1066==    by 0x18A5A5: main (mysqlbinlog.cc:3088)
==1066== 
==1066== 382 (304 direct, 78 indirect) bytes in 1 blocks are definitely lost in loss record 592 of 636
==1066==    at 0x212C35: my_malloc (my_malloc.cc:80)
==1066==    by 0x18F8C3: Log_event::operator new(unsigned long) (log_event.cc:872)
==1066==    by 0x1905CF: Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, bool) (log_event.cc:1717)
==1066==    by 0x188B39: dump_remote_log_entries(st_print_event_info*, char const*) (mysqlbinlog.cc:2377)
==1066==    by 0x18803E: dump_single_log(st_print_event_info*, char const*) (mysqlbinlog.cc:2069)
==1066==    by 0x188240: dump_multiple_logs(int, char**) (mysqlbinlog.cc:2110)
==1066==    by 0x18A5A5: main (mysqlbinlog.cc:3088)
==1066==
[6 Jun 2017 10:55] Laurynas Biveinis
Bug 82283 fix for 8.0.1

Attachment: bug82283-8.0.1.patch (application/octet-stream, text), 1.75 KiB.

[14 Jul 2017 14:27] Margaret Fisher
Posted by developer:
 
Changelog entry added for MySQL 8.0.2, 5.7.19, and 5.6.37:
        A memory leak in <command>mysqlbinlog</command> was fixed. The
        leak happened when processing fake rotate events, or when using
        <literal>--raw</literal> and the destination log file could not
        be created. The leak only occurred when processing events from a
        remote server. Thanks to Laurynas Biveinis for his contribution
        to fixing this bug.