Marko Mäkelä
added a comment - 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
#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 ''
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;
Marko Mäkelä
added a comment - 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;
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.
Andrei Elkin
added a comment - 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.
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)
delete NULL is explicitly allowed by the standard
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:
Note: While my patch is based on 10.2, I believe that the final fix should be ported to 5.5.
Marko Mäkelä
added a comment - - edited 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:
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)
delete NULL is explicitly allowed by the standard
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.
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.
Marko Mäkelä
added a comment - 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.
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.
Marko Mäkelä
added a comment - 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 .
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
Sujatha Sivakumar (Inactive)
added a comment - 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
Sujatha Sivakumar (Inactive)
added a comment - 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
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
Sujatha Sivakumar (Inactive)
added a comment - 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.
Sujatha Sivakumar (Inactive)
added a comment - 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
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