[MDEV-17260] Memory leaks in mysqlbinlog Created: 2018-09-21  Updated: 2019-04-28  Resolved: 2019-04-26

Status: Closed
Project: MariaDB Server
Component/s: Scripts & Clients
Affects Version/s: 5.5.62, 10.2, 10.3, 10.4
Fix Version/s: 10.2.24, 5.5.64, 10.3.15, 10.4.5

Type: Bug Priority: Major
Reporter: Marko Mäkelä Assignee: Sujatha Sivakumar (Inactive)
Resolution: Fixed Votes: 0
Labels: ASAN, Memory_leak, valgrind

Attachments: File mdev-17260-wip.patch    
Issue Links:
Relates
relates to MDEV-10570 Integrate existing DML only “Flashbac... Closed

 Description   

The mysqlbinlog tool is leaking memory, causing failures in various tests when compiling and testing with AddressSanitizer or LeakSanitizer like this:

cmake -DCMAKE_BUILD_TYPE=Debug -DWITH_ASAN:BOOL=ON /path/to/source
 
make -j$(nproc)
 
cd mysql-test
 
ASAN_OPTIONS=abort_on_error=1 ./mtr --parallel=auto

5.5 e07118946a82af60c7cc3804c321d3fd9a49f128

 
CURRENT_TEST: rpl.rpl_row_mysqlbinlog
 
 
 
=================================================================
 
==8988==ERROR: LeakSanitizer: detected memory leaks
 
 
 
Direct leak of 112 byte(s) in 1 object(s) allocated from:
 
    #0 0x4eff87 in __interceptor_malloc (/dev/shm/5.5/client/mysqlbinlog+0x4eff87)
 
    #1 0x60eaab in my_malloc /mariadb/5.5/mysys/my_malloc.c:41:10
 
    #2 0x5300dd in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /mariadb/5.5/sql/log_event.cc:1568:12
 
    #3 0x564a9c in dump_remote_log_entries(st_print_event_info*, char const*) /mariadb/5.5/client/mysqlbinlog.cc:1978:17
 
    #4 0x536408 in dump_log_entries(char const*) /mariadb/5.5/client/mysqlbinlog.cc:1794:21
 
    #5 0x535e4b in main /mariadb/5.5/client/mysqlbinlog.cc:2505:18
 
    #6 0x7f71ea0a1b16 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x22b16)



 Comments   
Comment by Marko Mäkelä [ 2019-01-25 ]

In 10.3, this affects the following tests:

binlog_encryption.binlog_row_annotate
binlog_encryption.rpl_skip_replication
binlog.binlog_row_annotate
binlog.binlog_row_mysqlbinlog_options

Easy to repeat with:

cmake -DWITH_ASAN:BOOL=ON …
 
ASAN_OPTIONS=abort_on_error=1 ./mtr --parallel=auto --force --retry=0 binlog_encryption.binlog_row_annotate binlog_encryption.rpl_skip_replication binlog.binlog_row_annotate binlog.binlog_row_mysqlbinlog_options

Comment by Marko Mäkelä [ 2019-01-25 ]

More failures in 10.2:

10.2 fab531a150ec588f87e8a636d2ba1ecbfffdb08e

 
encryption.tempfiles 'cbc,crc32,innodb'  w2 [ fail ]
 
        Test ended at 2019-01-25 13:23:01
 
 
 
CURRENT_TEST: encryption.tempfiles
 
 
 
=================================================================
 
==26545==ERROR: LeakSanitizer: detected memory leaks
 
 
 
Direct leak of 1920 byte(s) in 6 object(s) allocated from:
 
    #0 0x4c8a13 in __interceptor_malloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8a13)
 
    #1 0x6171e6 in my_malloc /mariadb/10.2/mysys/my_malloc.c:101:10
 
    #2 0x4fb637 in Log_event::operator new(unsigned long) /mariadb/10.2/sql/log_event.h:1326:20
 
    #3 0x4fb637 in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:2150
 
    #4 0x528d02 in Log_event::read_log_event(st_io_cache*, st_mysql_mutex*, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:1923:13
 
    #5 0x507407 in dump_local_log_entries(st_print_event_info*, char const*) /mariadb/10.2/client/mysqlbinlog.cc:2895:21
 
    #6 0x507407 in dump_log_entries(char const*) /mariadb/10.2/client/mysqlbinlog.cc:2147
 
    #7 0x507407 in main /mariadb/10.2/client/mysqlbinlog.cc:3082
 
    #8 0x7f0706ed509a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2409a)
 
 
 
Indirect leak of 48672 byte(s) in 6 object(s) allocated from:
 
    #0 0x4c8e32 in realloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8e32)
 
    #1 0x617805 in my_realloc /mariadb/10.2/mysys/my_malloc.c:165:15
 
    #2 0x54e4fb in String::realloc_raw(unsigned long) /mariadb/10.2/sql/sql_string.cc:96:30
 
 
 
Indirect leak of 46160 byte(s) in 6 object(s) allocated from:
 
    #0 0x4c8a13 in __interceptor_malloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8a13)
 
    #1 0x6171e6 in my_malloc /mariadb/10.2/mysys/my_malloc.c:101:10
 
    #2 0x547dac in Rows_log_event::Rows_log_event(char const*, unsigned int, Format_description_log_event const*) /mariadb/10.2/sql/log_event.cc:10452:24
 
    #3 0x4fb64e in Write_rows_log_event::Write_rows_log_event(char const*, unsigned int, Format_description_log_event const*) /mariadb/10.2/sql/log_event.cc:12321:3
 
    #4 0x4fb64e in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:2150
 
    #5 0x528d02 in Log_event::read_log_event(st_io_cache*, st_mysql_mutex*, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:1923:13
 
    #6 0x507407 in dump_local_log_entries(st_print_event_info*, char const*) /mariadb/10.2/client/mysqlbinlog.cc:2895:21
 
    #7 0x507407 in dump_log_entries(char const*) /mariadb/10.2/client/mysqlbinlog.cc:2147
 
    #8 0x507407 in main /mariadb/10.2/client/mysqlbinlog.cc:3082
 
    #9 0x7f0706ed509a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2409a)
 
 
 
SUMMARY: AddressSanitizer: 96752 byte(s) leaked in 18 allocation(s).
 
Aborted
 
ERROR 1064 (42000) at line 1012: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near ''
 
lPFKXBMBAAAALgAAAAbKAAAAACcAAAAAAAEABHRlc3QAAnQyAAH8AQIBfIAF/w==
 
lPFKXBcBAAAAb' at line 1
 
mysqltest: At line 80: exec of '/dev/shm/10.2/client/mysqlbinlog --defaults-file=/dev/shm/10.2/mysql-test/var/2/my.cnf --local-load=/dev/shm/10.2/mysql-test/var/tmp/2 /dev/shm/10.2/mysql-test/var/2/mysqld.1/data//master-bin.000001 | /dev/shm/10.2/client/mysql --defaults-file=/dev/shm/10.2/mysql-test/var/2/my.cnf' failed, error: 256, status: 1, errno: 11

10.2 fab531a150ec588f87e8a636d2ba1ecbfffdb08e

 
CURRENT_TEST: binlog.flashback
 
 
 
=================================================================
 
==35011==ERROR: LeakSanitizer: detected memory leaks
 
 
 
Direct leak of 640 byte(s) in 2 object(s) allocated from:
 
    #0 0x4c8a13 in __interceptor_malloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8a13)
 
    #1 0x6171e6 in my_malloc /mariadb/10.2/mysys/my_malloc.c:101:10
 
    #2 0x4fb5ab in Log_event::operator new(unsigned long) /mariadb/10.2/sql/log_event.h:1326:20
 
    #3 0x4fb5ab in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:2158
 
    #4 0x528d02 in Log_event::read_log_event(st_io_cache*, st_mysql_mutex*, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:1923:13
 
    #5 0x507407 in dump_local_log_entries(st_print_event_info*, char const*) /mariadb/10.2/client/mysqlbinlog.cc:2895:21
 
    #6 0x507407 in dump_log_entries(char const*) /mariadb/10.2/client/mysqlbinlog.cc:2147
 
    #7 0x507407 in main /mariadb/10.2/client/mysqlbinlog.cc:3082
 
    #8 0x7f984ccc209a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2409a)
 
 
 
Direct leak of 320 byte(s) in 1 object(s) allocated from:
 
    #0 0x4c8a13 in __interceptor_malloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8a13)
 
    #1 0x6171e6 in my_malloc /mariadb/10.2/mysys/my_malloc.c:101:10
 
    #2 0x4fb637 in Log_event::operator new(unsigned long) /mariadb/10.2/sql/log_event.h:1326:20
 
    #3 0x4fb637 in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:2150
 
    #4 0x528d02 in Log_event::read_log_event(st_io_cache*, st_mysql_mutex*, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:1923:13
 
    #5 0x507407 in dump_local_log_entries(st_print_event_info*, char const*) /mariadb/10.2/client/mysqlbinlog.cc:2895:21
 
    #6 0x507407 in dump_log_entries(char const*) /mariadb/10.2/client/mysqlbinlog.cc:2147
 
    #7 0x507407 in main /mariadb/10.2/client/mysqlbinlog.cc:3082
 
    #8 0x7f984ccc209a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2409a)
 
 
 
Indirect leak of 480 byte(s) in 3 object(s) allocated from:
 
    #0 0x4c8a13 in __interceptor_malloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8a13)
 
    #1 0x6171e6 in my_malloc /mariadb/10.2/mysys/my_malloc.c:101:10
 
    #2 0x54e538 in String::realloc_raw(unsigned long) /mariadb/10.2/sql/sql_string.cc:102:32
 
 
 
Indirect leak of 48 byte(s) in 2 object(s) allocated from:
 
    #0 0x4c8a13 in __interceptor_malloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8a13)
 
    #1 0x6171e6 in my_malloc /mariadb/10.2/mysys/my_malloc.c:101:10
 
    #2 0x547dac in Rows_log_event::Rows_log_event(char const*, unsigned int, Format_description_log_event const*) /mariadb/10.2/sql/log_event.cc:10452:24
 
    #3 0x4fb5c2 in Delete_rows_log_event::Delete_rows_log_event(char const*, unsigned int, Format_description_log_event const*) /mariadb/10.2/sql/log_event.cc:13395:5
 
    #4 0x4fb5c2 in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:2158
 
    #5 0x528d02 in Log_event::read_log_event(st_io_cache*, st_mysql_mutex*, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:1923:13
 
    #6 0x507407 in dump_local_log_entries(st_print_event_info*, char const*) /mariadb/10.2/client/mysqlbinlog.cc:2895:21
 
    #7 0x507407 in dump_log_entries(char const*) /mariadb/10.2/client/mysqlbinlog.cc:2147
 
    #8 0x507407 in main /mariadb/10.2/client/mysqlbinlog.cc:3082
 
    #9 0x7f984ccc209a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2409a)
 
 
 
Indirect leak of 24 byte(s) in 1 object(s) allocated from:
 
    #0 0x4c8a13 in __interceptor_malloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8a13)
 
    #1 0x6171e6 in my_malloc /mariadb/10.2/mysys/my_malloc.c:101:10
 
    #2 0x547dac in Rows_log_event::Rows_log_event(char const*, unsigned int, Format_description_log_event const*) /mariadb/10.2/sql/log_event.cc:10452:24
 
    #3 0x4fb64e in Write_rows_log_event::Write_rows_log_event(char const*, unsigned int, Format_description_log_event const*) /mariadb/10.2/sql/log_event.cc:12321:3
 
    #4 0x4fb64e in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:2150
 
    #5 0x528d02 in Log_event::read_log_event(st_io_cache*, st_mysql_mutex*, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:1923:13
 
    #6 0x507407 in dump_local_log_entries(st_print_event_info*, char const*) /mariadb/10.2/client/mysqlbinlog.cc:2895:21
 
    #7 0x507407 in dump_log_entries(char const*) /mariadb/10.2/client/mysqlbinlog.cc:2147
 
    #8 0x507407 in main /mariadb/10.2/client/mysqlbinlog.cc:3082
 
    #9 0x7f984ccc209a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2409a)
 
 
 
SUMMARY: AddressSanitizer: 1512 byte(s) leaked in 9 allocation(s).
 
Aborted
 
mysqltest: At line 203: exec of '/dev/shm/10.2/client/mysqlbinlog --defaults-file=/dev/shm/10.2/mysql-test/var/39/my.cnf --local-load=/dev/shm/10.2/mysql-test/var/tmp/39 -vv /dev/shm/10.2/mysql-test/var/39/mysqld.1/data//master-bin.000001 > /dev/shm/10.2/mysql-test/var/39/tmp/mysqlbinlog_row_flashback_original_4.sql' failed, error: 34304, status: 134, errno: 11

10.2 fab531a150ec588f87e8a636d2ba1ecbfffdb08e

 
binlog.binlog_mysqlbinlog_base64 'row'   w3 [ fail ]
 
        Test ended at 2019-01-25 13:23:20
 
 
 
CURRENT_TEST: binlog.binlog_mysqlbinlog_base64
 
 
 
=================================================================
 
==982==ERROR: LeakSanitizer: detected memory leaks
 
 
 
Direct leak of 12160 byte(s) in 38 object(s) allocated from:
 
    #0 0x4c8a13 in __interceptor_malloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8a13)
 
    #1 0x6171e6 in my_malloc /mariadb/10.2/mysys/my_malloc.c:101:10
 
    #2 0x4fb637 in Log_event::operator new(unsigned long) /mariadb/10.2/sql/log_event.h:1326:20
 
    #3 0x4fb637 in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:2150
 
    #4 0x528d02 in Log_event::read_log_event(st_io_cache*, st_mysql_mutex*, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:1923:13
 
    #5 0x507407 in dump_local_log_entries(st_print_event_info*, char const*) /mariadb/10.2/client/mysqlbinlog.cc:2895:21
 
    #6 0x507407 in dump_log_entries(char const*) /mariadb/10.2/client/mysqlbinlog.cc:2147
 
    #7 0x507407 in main /mariadb/10.2/client/mysqlbinlog.cc:3082
 
    #8 0x7f079822009a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2409a)
 
 
 
Indirect leak of 327024 byte(s) in 38 object(s) allocated from:
 
    #0 0x4c8e32 in realloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8e32)
 
    #1 0x617805 in my_realloc /mariadb/10.2/mysys/my_malloc.c:165:15
 
    #2 0x54e4fb in String::realloc_raw(unsigned long) /mariadb/10.2/sql/sql_string.cc:96:30
 
 
 
Indirect leak of 311168 byte(s) in 38 object(s) allocated from:
 
    #0 0x4c8a13 in __interceptor_malloc (/dev/shm/10.2/client/mysqlbinlog+0x4c8a13)
 
    #1 0x6171e6 in my_malloc /mariadb/10.2/mysys/my_malloc.c:101:10
 
    #2 0x547dac in Rows_log_event::Rows_log_event(char const*, unsigned int, Format_description_log_event const*) /mariadb/10.2/sql/log_event.cc:10452:24
 
    #3 0x4fb64e in Write_rows_log_event::Write_rows_log_event(char const*, unsigned int, Format_description_log_event const*) /mariadb/10.2/sql/log_event.cc:12321:3
 
    #4 0x4fb64e in Log_event::read_log_event(char const*, unsigned int, char const**, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:2150
 
    #5 0x528d02 in Log_event::read_log_event(st_io_cache*, st_mysql_mutex*, Format_description_log_event const*, char) /mariadb/10.2/sql/log_event.cc:1923:13
 
    #6 0x507407 in dump_local_log_entries(st_print_event_info*, char const*) /mariadb/10.2/client/mysqlbinlog.cc:2895:21
 
    #7 0x507407 in dump_log_entries(char const*) /mariadb/10.2/client/mysqlbinlog.cc:2147
 
    #8 0x507407 in main /mariadb/10.2/client/mysqlbinlog.cc:3082
 
    #9 0x7f079822009a in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2409a)
 
 
 
SUMMARY: AddressSanitizer: 650352 byte(s) leaked in 114 allocation(s).
 
Aborted
 
mysqltest: At line 60: exec of '/dev/shm/10.2/client/mysqlbinlog --defaults-file=/dev/shm/10.2/mysql-test/var/3/my.cnf --local-load=/dev/shm/10.2/mysql-test/var/tmp/3 --hexdump /dev/shm/10.2/mysql-test/var/3/mysqld.1/data//master-bin.000003 > /dev/shm/10.2/mysql-test/var/3/tmp/mysqlbinlog_base64.sql' failed, error: 34304, status: 134, errno: 11

Comment by Marko Mäkelä [ 2019-02-01 ]

One more failure, without any ASAN instrumentation:

10.2 7c7161a1bd150e61f530933f096a8035932071af with a merge from 10.1 a193c5720ea461ce82390af3fe9c292581242223

 
binlog.binlog_mysqlbinlog_row_frag 'row' w29 [ fail ]
 
        Test ended at 2019-02-01 13:01:55
 
 
 
CURRENT_TEST: binlog.binlog_mysqlbinlog_row_frag
 
realloc(): invalid next size
 
Aborted
 
mysqltest: At line 14: exec of '/dev/shm/10.2/client/mysqlbinlog --defaults-file=/dev/shm/10.2/mysql-test/var/29/my.cnf --local-load=/dev/shm/10.2/mysql-test/var/tmp/29 --debug-binlog-row-event-max-encoded-size=256 /dev/shm/10.2/mysql-test/var/29/mysqld.1/data//master-bin.000001 > /dev/shm/10.2/mysql-test/var/29/tmp/mysqlbinlog.sql' failed, error: 34304, status: 134, errno: 11
 
Output from before failure:
 
DELETE FROM t;

Comment by Andrei Elkin [ 2019-02-01 ]

The latest failure has been introduced by 10.2 merge of MDEV-10963 fixes which required to build
a MDEV-10362 at the same time to satisfy the 10.2 {{ --flashback }}. It must've been fixed already in bb-10.2-merge.

Comment by Marko Mäkelä [ 2019-04-09 ]

I had a short try at fixing the leaks for

cmake -DCMAKE_BUILD_TYPE=Debug -DWITH_ASAN=ON -DWITH_SAFEMALLOC=OFF ..
 
make -j$(nproc)
 
cd mysql-test
 
ASAN_OPTIONS=abort_on_error=1 ./mtr binlog.flashback

The key points of mdev-17260-wip.patch are:

  1. Assignments of ev to other pointers should follow std::unique_ptr semantics (set the original pointer to NULL, so that there is only one ‘owner’ pointer)
  2. delete NULL is explicitly allowed by the standard
  3. After delete of global variables, it is good practice to set those variables to NULL, to avoid ’still reachable’ warnings from Valgrind. (I hope that you will validate the fix not only with AddressSanitizer but also by manually replacing mysqlbinlog with a wrapper that invokes Valgrind.)

The patch does not leak memory, but will cause output differences in 10 of the 11 tests where leaks were reported:

binlog.binlog_row_annotate binlog_encryption.binlog_row_annotate encryption.tempfiles binlog.binlog_mysqlbinlog_row binlog.binlog_mysqlbinlog_row_myisam binlog.binlog_mysqlbinlog_row_innodb binlog.binlog_mysqlbinlog_base64 binlog.binlog_row_mysqlbinlog_verbose

The following test, which previously leaked memory, does pass:

binlog.binlog_row_mysqlbinlog_db_filter 'innodb,row'

The patch also causes numerous other test failures, such as this one:

CURRENT_TEST: rpl.rpl_timezone
 
--- /mariadb/10.2/mysql-test/suite/rpl/r/rpl_timezone.result	2019-01-24 01:01:18.946939895 +0800
 
+++ /mariadb/10.2/mysql-test/suite/rpl/r/rpl_timezone.reject	2019-04-10 00:33:19.013638879 +0800
 
@@ -158,8 +158,6 @@
 
 connection master1;
 
 select * from t1 order by a;
 
 date	a
 
-2008-12-23 20:39:39	1
 
-2008-12-23 19:39:39	2
 
 DROP TABLE t1;
 
 SET @@session.time_zone = default;
 
 include/rpl_end.inc
 
 
 
mysqltest: Result length mismatch

I hope that mdev-17260-wip.patch is a viable starting point for a fix.

Note: While my patch is based on 10.2, I believe that the final fix should be ported to 5.5.

Comment by Marko Mäkelä [ 2019-04-09 ]

While testing my patch, I found a heap-use-after-free in all 3 combinations of the test binlog.flashback. I think that that one should be fixed first, before trying to fix the output differences.

Comment by Marko Mäkelä [ 2019-04-15 ]

For some reason, today I was unable to repeat any LeakSanitizer warnings on 10.1 when using cmake -DWITH_ASAN=ON -DWITH_SAFEMALLOC=OFF. But I was able to repeat the leaks on 10.2.

I see that I initially reported the leaks on 5.5. I do not see any related fixes to the files since then, so I would expect the leaks to remain present.

Some leaks seem to be related to the flashback changes that were introduced in MariaDB 10.2.4 by MDEV-10570.

Comment by Sujatha Sivakumar (Inactive) [ 2019-04-17 ]

In the above report there are three different kinds of leaks were observed.

In 5.5:
=====
CURRENT_TEST: rpl.rpl_row_mysqlbinlog
================================================================
==8988==ERROR: LeakSanitizer: detected memory leaks
Direct leak of 112 byte(s) in 1 object(s) allocated from:
#0 0x4eff87 in __interceptor_malloc (/dev/shm/5.5/client/mysqlbinlog+0x4eff87)
#1 0x60eaab in my_malloc /mariadb/5.5/mysys/my_malloc.c:41:10
#2 0x5300dd in Log_event::read_log_event(char const*, unsigned int, char const*, Format_description_log_event const, char) /mariadb/5.5/sql/log_event.cc:1568:12
#3 0x564a9c in dump_remote_log_entries(st_print_event_info*, char const*) /mariadb/5.5/client/mysqlbinlog.cc:1978:17
#4 0x536408 in dump_log_entries(char const*) /mariadb/5.5/client/mysqlbinlog.cc:1794:21
#5 0x535e4b in main /mariadb/5.5/client/mysqlbinlog.cc:2505:18
#6 0x7f71ea0a1b16 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x22b16)

This issue exists only in 5.5. It is specific to fake rotate events while reading binary log from a remote server.
This issues is already fixed in MariaDB 10.0.23 and higher versions as part of
commit c3018b0ff4fb02c029787d03867adf0530607bab

10.2 and above:
=============
1) Leak in Log_event::read_log_event(char const*, unsigned int, char const**,
Format_description_log_event const*, char)
File: sql/log_event.cc:2150
2) read_remote_annotate_event(unsigned char*, unsigned long, char const**)
File: client/mysqlbinlog.cc:194

These were caused because of flashback feature and its related bug fixes.

To reproduce the failures use:

ASAN_OPTIONS=abort_on_error=1 ./mtr --parallel=auto binlog.binlog_row_mysqlbinlog_verbose binlog_encryption.binlog_row_annotate binlog.binlog_row_mysqlbinlog_options binlog.binlog_row_annotate encryption.tempfiles binlog.binlog_mysqlbinlog_row_myisam binlog.binlog_mysqlbinlog_row binlog.binlog_mysqlbinlog_base64 binlog_encryption.rpl_skip_replication binlog.binlog_mysqlbinlog_row_innodb binlog.flashback

Comment by Sujatha Sivakumar (Inactive) [ 2019-04-17 ]

Hello Andrei,

Can you please review two different patches for MDEV-17260 fix.

For 5.5:
======
http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-5.5-sujatha
https://github.com/MariaDB/server/commit/8b066a3d234e17249ca638a76cdd48a279633d34

For 10.2:
=======
http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.2-sujatha
https://github.com/MariaDB/server/commit/fdf298c036fa0bb68fe3e2f0bfd28bf3b3f466d1

Thank you

Comment by Sujatha Sivakumar (Inactive) [ 2019-04-24 ]

Hello Andrei,

Thank you for the review comments.
I have added a test case which covers flashback and remote options.

I verified that the newly added test case fails without fix as shown below.

CURRENT_TEST: binlog.flashback

=================================================================
==26328==ERROR: LeakSanitizer: detected memory leaks

Direct leak of 48 byte(s) in 1 object(s) allocated from:
#0 0x7f496b046b50 in __interceptor_malloc (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xdeb50)
#1 0x55a508dd102b in my_malloc /home/sujatha/bug_repo/MDEV-17260-10.2/mysys/my_malloc.c:101
#2 0x55a508c8d57e in read_remote_annotate_event(unsigned char*, unsigned long, char const**) /home/sujatha/bug_repo/MDEV-17260-10.2/client/mysqlbinlog.cc:194
#3 0x55a508c93c69 in handle_event_text_mode /home/sujatha/bug_repo/MDEV-17260-10.2/client/mysqlbinlog.cc:2285
#4 0x55a508c95fcf in dump_remote_log_entries /home/sujatha/bug_repo/MDEV-17260-10.2/client/mysqlbinlog.cc:2608
#5 0x55a508c9351b in dump_log_entries /home/sujatha/bug_repo/MDEV-17260-10.2/client/mysqlbinlog.cc:2162
#6 0x55a508c97b5b in main /home/sujatha/bug_repo/MDEV-17260-10.2/client/mysqlbinlog.cc:3098
#7 0x7f49698b4b96 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x21b96)

SUMMARY: AddressSanitizer: 48 byte(s) leaked in 1 allocation(s).
Aborted (core dumped)
mysqltest: At line 355: exec of '/home/sujatha/bug_repo/MDEV-17260-10.2/bld/client/mysqlbinlog --defaults-file=/home/sujatha/bug_repo/MDEV-17260-10.2/bld/mysql-test/var/2/my.cnf --local-load=/home/sujatha/bug_repo/MDEV-17260-10.2/bld/mysql-test/var/tmp/2 -vv -B --read-from-remote-server --user=root --host=127.0.0.1 --port=16020 master-bin.000002> /home/sujatha/bug_repo/MDEV-17260-10.2/bld/mysql-test/var/2/tmp/mysqlbinlog_row_flashback_4.sql' failed, error: 34304, status: 134, errno: 11
Output from before failure:
f

With fix it passes.

http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.2-sujatha
https://github.com/MariaDB/server/commit/8ae7a5eb03725441393c353e4e203f80b666c035

Please review the new set of changes.

Comment by Sujatha Sivakumar (Inactive) [ 2019-04-26 ]

At the time for merging 10.2 patch into 10.3 please consider the following patch.

10.3: Changes.
https://github.com/MariaDB/server/commit/ddfd6297f8f7cf2009d326ae825c75c918fe8ef3

Comment by Marko Mäkelä [ 2019-04-28 ]

Merged to 10.3

Generated at Thu Feb 08 08:35:07 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.