| 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: | |
| 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 16:54]
MySQL Verification Team
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]
MySQL Verification Team
Thank you for the details.
[20 Jul 2016 7:09]
MySQL Verification Team
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.
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