[MDEV-18046] Assortment of crashes, assertion failures and ASAN errors in mysql_show_binlog_events - Jira

XML

Word

Printable

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.1, 10.2, 10.3, 10.4
Fix Version/s: 10.1.44, 10.2.31, 10.3.22, 10.4.12
Component/s: Replication
Labels:
- show_binlog_event

Description

SHOW BINLOG EVENTS FROM <pos> causes a variety of failures, some of which are listed below. It is not a race condition issue, but there is some non-determinism in it, I can't figure the cause of it.

The following test case is a bit ugly, but it is a self-contained proof of concept, it shows that the failures happen without any tampering with the binary log:

--source include/have_log_bin.inc

--source include/have_binlog_format_mixed.inc

--source include/have_innodb.inc

DROP TABLE /*! IF EXISTS*/ t1;

CREATE TABLE `t1` (

`col_int` int,

pk integer auto_increment,

`col_char_12_key` char(12),

`col_int_key` int,

`col_char_12` char(12),

primary key (pk),

key (`col_char_12_key` ),

key (`col_int_key` )) ENGINE=InnoDB;

INSERT /*! IGNORE */ INTO t1 VALUES  (183173120, NULL, 'abcd', 1, 'efghijk'),  (1, NULL, 'lmno', 2, 'p');

ALTER TABLE `t1` ENABLE KEYS;

--let $max_pos= query_get_value(SHOW MASTER STATUS,Position,1)

--let $pos= 1

while ($pos <= $max_pos)

  --error 0,1220

  eval SHOW BINLOG EVENTS FROM $pos;

  --inc $pos

10.1 ASAN 1b471face8
=================================================================
==15715==ERROR: AddressSanitizer: unknown-crash on address 0x61200019074b at pc 0x55abe4db87f7 bp 0x7ffa25838fc0 sp 0x7ffa25838fb8
READ of size 511 at 0x61200019074b thread T28
#0 0x55abe4db87f6 in my_strndup /data/src/10.2/mysys/my_malloc.c:253
#1 0x55abe4032bbe in Rotate_log_event::Rotate_log_event(char const, unsigned int, Format_description_log_event const) /data/src/10.2/sql/log_event.cc:7239
#2 0x55abe40166d8 in Log_event::read_log_event(char const, unsigned int, char const, Format_description_log_event const, char) /data/src/10.2/sql/log_event.cc:2094
#3 0x55abe4015929 in Log_event::read_log_event(st_io_cache, st_mysql_mutex, Format_description_log_event const*, char) /data/src/10.2/sql/log_event.cc:1923
#4 0x55abe3800fe2 in mysql_show_binlog_events(THD*) /data/src/10.2/sql/sql_repl.cc:3965
#5 0x55abe377686c in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:3598
#6 0x55abe3792125 in mysql_parse(THD, char, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:8014
#7 0x55abe376cb0f in dispatch_command(enum_server_command, THD, char, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1825
#8 0x55abe3769bb3 in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1379
#9 0x55abe3aaf558 in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
#10 0x55abe3aaef6d in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
#11 0x55abe44c9f9d in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
#12 0x7ffa36053493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
#13 0x7ffa3465493e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)

0x6120001907cc is located 0 bytes to the right of 268-byte region [0x6120001906c0,0x6120001907cc)
allocated by thread T28 here:
#0 0x7ffa362bd73f in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x5473f)
#1 0x55abe4de85b9 in sf_malloc /data/src/10.2/mysys/safemalloc.c:118
#2 0x55abe4db7810 in my_malloc /data/src/10.2/mysys/my_malloc.c:101
#3 0x55abe394e199 in String::realloc_raw(unsigned long) /data/src/10.2/sql/sql_string.cc:102
#4 0x55abe35aab08 in String::realloc_with_extra(unsigned long) /data/src/10.2/sql/sql_string.h:376
#5 0x55abe3955048 in String::realloc_with_extra_if_needed(unsigned long) /data/src/10.2/sql/sql_string.h:388
#6 0x55abe3950ace in String::append(char const*, unsigned long) /data/src/10.2/sql/sql_string.cc:499
#7 0x55abe4014bf4 in Log_event::read_log_event(st_io_cache, String, Format_description_log_event const*, enum_binlog_checksum_alg) /data/src/10.2/sql/log_event.cc:1795
#8 0x55abe401581e in Log_event::read_log_event(st_io_cache, st_mysql_mutex, Format_description_log_event const*, char) /data/src/10.2/sql/log_event.cc:1892
#9 0x55abe3800fe2 in mysql_show_binlog_events(THD*) /data/src/10.2/sql/sql_repl.cc:3965
#10 0x55abe377686c in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:3598
#11 0x55abe3792125 in mysql_parse(THD, char, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:8014
#12 0x55abe376cb0f in dispatch_command(enum_server_command, THD, char, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1825
#13 0x55abe3769bb3 in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1379
#14 0x55abe3aaf558 in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
#15 0x55abe3aaef6d in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
#16 0x55abe44c9f9d in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
#17 0x7ffa36053493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)

Thread T28 created by T0 here:
#0 0x7ffa3628cbba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
#1 0x55abe44ca565 in spawn_thread_v1 /data/src/10.2/storage/perfschema/pfs.cc:1912
#2 0x55abe356650e in inline_mysql_thread_create /data/src/10.2/include/mysql/psi/mysql_thread.h:1239
#3 0x55abe357b4ab in create_thread_to_handle_connection(CONNECT*) /data/src/10.2/sql/mysqld.cc:6466
#4 0x55abe357bbb0 in create_new_thread /data/src/10.2/sql/mysqld.cc:6536
#5 0x55abe357cbc7 in handle_connections_sockets() /data/src/10.2/sql/mysqld.cc:6811
#6 0x55abe357aa00 in mysqld_main(int, char**) /data/src/10.2/sql/mysqld.cc:6085
#7 0x55abe35648af in main /data/src/10.2/sql/main.cc:25
#8 0x7ffa3458c2b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)

SUMMARY: AddressSanitizer: unknown-crash /data/src/10.2/mysys/my_malloc.c:253 my_strndup
Shadow bytes around the buggy address:
0x0c248002a090: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c248002a0a0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c248002a0b0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c248002a0c0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c248002a0d0: fa fa fa fa fa fa fa fa 00 00 00 00 00 00 00 00
=>0x0c248002a0e0: 00 00 00 00 00 00 00 00 00[00]00 00 00 00 00 00
0x0c248002a0f0: 00 00 00 00 00 00 00 00 00 04 fa fa fa fa fa fa
0x0c248002a100: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
0x0c248002a110: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
0x0c248002a120: fd fd fd fd fd fd fd fd fd fd fa fa fa fa fa fa
0x0c248002a130: fa fa fa fa fa fa fa fa 00 00 00 00 00 00 00 00
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
Heap right redzone: fb
Freed heap region: fd
Stack left redzone: f1
Stack mid redzone: f2
Stack right redzone: f3
Stack partial redzone: f4
Stack after return: f5
Stack use after scope: f8
Global redzone: f9
Global init order: f6
Poisoned by user: f7
Contiguous container OOB:fc
ASan internal: fe
==15715==ABORTING

However, since the whole thing is rather unreliable, it might happen that it's not reproducible on a different machine.

A wider variety of problems can be observed while running SHOW BINLOG EVENTS FROM ... with different positions on the attached mysql-bin.000001. The log was produced by MariaDB 10.4, so start 10.4 server with all defaults and log-bin=mysql-bin.000001 with the attached log in the datadir, and run SHOW BINLOG EVENTS FROM ... with various positions.

I've got the following for the first 8000 positions (didn't go further):

SHOW BINLOG EVENTS FROM 365;

-- or

SHOW BINLOG EVENTS FROM 491;

-- or

SHOW BINLOG EVENTS FROM 2327;

-- or

SHOW BINLOG EVENTS FROM 4264;

10.4 30641f9df77
mysqld: /data/src/10.4/sql/log_event.cc:10863: Rows_log_event::Rows_log_event(const char, uint, const Format_description_log_event): Assertion `var_header_len >= 2' failed.
181220 15:27:02 [ERROR] mysqld got signal 6 ;

#7 0x00007fa0d96abee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#8 0x000055e744ef82de in Rows_log_event::Rows_log_event (this=0x7fa05800d390, buf=0x7fa05800d080 "", event_len=254, description_event=0x7fa058006d60) at /data/src/10.4/sql/log_event.cc:10863
#9 0x000055e744f00cf8 in Update_rows_log_event::Update_rows_log_event (this=0x7fa05800d390, buf=0x7fa05800d080 "", event_len=254, description_event=0x7fa058006d60) at /data/src/10.4/sql/log_event.cc:14240
#10 0x000055e744ee5fb3 in Log_event::read_log_event (buf=0x7fa05800d080 "", event_len=254, error=0x7fa0d8134550, fdle=0x7fa058006d60, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:2168
#11 0x000055e744ee55fb in Log_event::read_log_event (file=0x7fa0d81346b0, fdle=0x7fa058006d60, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:1939
#12 0x000055e744ad9d55 in mysql_show_binlog_events (thd=0x7fa058000b00) at /data/src/10.4/sql/sql_repl.cc:4004
#13 0x000055e744a9d505 in mysql_execute_command (thd=0x7fa058000b00) at /data/src/10.4/sql/sql_parse.cc:3887
#14 0x000055e744aaa8e4 in mysql_parse (thd=0x7fa058000b00, rawbuf=0x7fa058013be8 "SHOW BINLOG EVENTS FROM 365", length=27, parser_state=0x7fa0d8135650, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:8104
#15 0x000055e744a97b0e in dispatch_command (command=COM_QUERY, thd=0x7fa058000b00, packet=0x7fa05801be11 "", packet_length=27, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1851
#16 0x000055e744a96532 in do_command (thd=0x7fa058000b00) at /data/src/10.4/sql/sql_parse.cc:1396
#17 0x000055e744c026de in do_handle_one_connection (connect=0x55e748a968b0) at /data/src/10.4/sql/sql_connect.cc:1402
#18 0x000055e744c02462 in handle_one_connection (arg=0x55e748a968b0) at /data/src/10.4/sql/sql_connect.cc:1308
#19 0x00007fa0db167494 in start_thread (arg=0x7fa0d8136700) at pthread_create.c:333
#20 0x00007fa0d976893f in clone () from /lib/x86_64-linux-gnu/libc.so.6

SHOW BINLOG EVENTS FROM 1366;

-- or

SHOW BINLOG EVENTS FROM 3576;

-- or

SHOW BINLOG EVENTS FROM 4380;

-- or

SHOW BINLOG EVENTS FROM 4394;

-- or

SHOW BINLOG EVENTS FROM 7992;

10.4 30641f9df77
mysqld: /data/src/10.4/sql/log_event.cc:1055: uint32 binlog_get_uncompress_len(const char*): Assertion `(buf[0] & 0xe0) == 0x80' failed.
181220 15:33:56 [ERROR] mysqld got signal 6 ;

#7 0x00007f77fd57aee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#8 0x0000559995bf8f32 in binlog_get_uncompress_len (buf=0x7f779000d560 "") at /data/src/10.4/sql/log_event.cc:1055
#9 0x0000559995c0ea9f in Rows_log_event::uncompress_buf (this=0x7f779000d390) at /data/src/10.4/sql/log_event.cc:10990
#10 0x0000559995c1395d in Write_rows_compressed_log_event::Write_rows_compressed_log_event (this=0x7f779000d390, buf=0x7f779000d080 "", event_len=254, description_event=0x7f7790006cd0) at /data/src/10.4/sql/log_event.cc:12897
#11 0x0000559995bfc00b in Log_event::read_log_event (buf=0x7f779000d080 "", event_len=254, error=0x7f77e5d80550, fdle=0x7f7790006cd0, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:2177
#12 0x0000559995bfb5fb in Log_event::read_log_event (file=0x7f77e5d806b0, fdle=0x7f7790006cd0, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:1939
#13 0x00005599957efd55 in mysql_show_binlog_events (thd=0x7f7790000b00) at /data/src/10.4/sql/sql_repl.cc:4004
#14 0x00005599957b3505 in mysql_execute_command (thd=0x7f7790000b00) at /data/src/10.4/sql/sql_parse.cc:3887
#15 0x00005599957c08e4 in mysql_parse (thd=0x7f7790000b00, rawbuf=0x7f7790013be8 "SHOW BINLOG EVENTS FROM 1366", length=28, parser_state=0x7f77e5d81650, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:8104
#16 0x00005599957adb0e in dispatch_command (command=COM_QUERY, thd=0x7f7790000b00, packet=0x7f779001be11 "", packet_length=28, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1851
#17 0x00005599957ac532 in do_command (thd=0x7f7790000b00) at /data/src/10.4/sql/sql_parse.cc:1396
#18 0x00005599959186de in do_handle_one_connection (connect=0x559999441700) at /data/src/10.4/sql/sql_connect.cc:1402
#19 0x0000559995918462 in handle_one_connection (arg=0x559999441700) at /data/src/10.4/sql/sql_connect.cc:1308
#20 0x00007f77ff036494 in start_thread (arg=0x7f77e5d82700) at pthread_create.c:333
#21 0x00007f77fd63793f in clone () from /lib/x86_64-linux-gnu/libc.so.6

SHOW BINLOG EVENTS FROM 3876;

10.4 30641f9df77
mysqld: /data/src/10.4/sql/log_event.cc:12376: Table_map_log_event::Table_map_log_event(const char, uint, const Format_description_log_event): Assertion `m_field_metadata_size <= (m_colcnt * 2)' failed.
181220 15:36:33 [ERROR] mysqld got signal 6 ;

#7 0x00007f611f6c6ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#8 0x0000560a9e1cd75b in Table_map_log_event::Table_map_log_event (this=0x7f60a8013a50, buf=0x7f60a800d080 "", event_len=254, description_event=0x7f60a8006cd0) at /data/src/10.4/sql/log_event.cc:12376
#9 0x0000560a9e1b70c8 in Log_event::read_log_event (buf=0x7f60a800d080 "", event_len=254, error=0x7f611c1f4550, fdle=0x7f60a8006cd0, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:2200
#10 0x0000560a9e1b65fb in Log_event::read_log_event (file=0x7f611c1f46b0, fdle=0x7f60a8006cd0, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:1939
#11 0x0000560a9ddaad55 in mysql_show_binlog_events (thd=0x7f60a8000b00) at /data/src/10.4/sql/sql_repl.cc:4004
#12 0x0000560a9dd6e505 in mysql_execute_command (thd=0x7f60a8000b00) at /data/src/10.4/sql/sql_parse.cc:3887
#13 0x0000560a9dd7b8e4 in mysql_parse (thd=0x7f60a8000b00, rawbuf=0x7f60a8013be8 "SHOW BINLOG EVENTS FROM 3876", length=28, parser_state=0x7f611c1f5650, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:8104
#14 0x0000560a9dd68b0e in dispatch_command (command=COM_QUERY, thd=0x7f60a8000b00, packet=0x7f60a801be11 "", packet_length=28, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1851
#15 0x0000560a9dd67532 in do_command (thd=0x7f60a8000b00) at /data/src/10.4/sql/sql_parse.cc:1396
#16 0x0000560a9ded36de in do_handle_one_connection (connect=0x560aa0b1c700) at /data/src/10.4/sql/sql_connect.cc:1402
#17 0x0000560a9ded3462 in handle_one_connection (arg=0x560aa0b1c700) at /data/src/10.4/sql/sql_connect.cc:1308
#18 0x00007f6121182494 in start_thread (arg=0x7f611c1f6700) at pthread_create.c:333
#19 0x00007f611f78393f in clone () from /lib/x86_64-linux-gnu/libc.so.6

SHOW BINLOG EVENTS FROM 6191;

-- or

SHOW BINLOG EVENTS FROM 6367;

-- or

SHOW BINLOG EVENTS FROM 7951;

10.4 30641f9df77
181220 15:29:56 [ERROR] mysqld got signal 11 ;

#3 <signal handler called>
#4 0x0000556cb316374b in inline_mysql_mutex_destroy (that=0xa5a5a5a5a5a5a5a5, src_file=0x556cb35eb5e8 "/data/src/10.4/mysys/my_bitmap.c", src_line=214) at /data/src/10.4/include/mysql/psi/mysql_thread.h:662
#5 0x0000556cb3163f25 in my_bitmap_free (map=0x7fbc1811bb90) at /data/src/10.4/mysys/my_bitmap.c:214
#6 0x0000556cb2b11c76 in Update_rows_log_event::~Update_rows_log_event (this=0x7fbc1811baf0, __in_chrg=<optimized out>) at /data/src/10.4/sql/log_event.cc:14228
#7 0x0000556cb2b11cb6 in Update_rows_log_event::~Update_rows_log_event (this=0x7fbc1811baf0, __in_chrg=<optimized out>) at /data/src/10.4/sql/log_event.cc:14229
#8 0x0000556cb2af7332 in Log_event::read_log_event (buf=0x7fbc180e30f0 "", event_len=27, error=0x7fbc8c2c7550, fdle=0x7fbc1811b970, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:2267
#9 0x0000556cb2af65fb in Log_event::read_log_event (file=0x7fbc8c2c76b0, fdle=0x7fbc1811b970, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:1939
#10 0x0000556cb26ead55 in mysql_show_binlog_events (thd=0x7fbc18000b00) at /data/src/10.4/sql/sql_repl.cc:4004
#11 0x0000556cb26ae505 in mysql_execute_command (thd=0x7fbc18000b00) at /data/src/10.4/sql/sql_parse.cc:3887
#12 0x0000556cb26bb8e4 in mysql_parse (thd=0x7fbc18000b00, rawbuf=0x7fbc18013be8 "SHOW BINLOG EVENTS FROM 7951", length=28, parser_state=0x7fbc8c2c8650, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:8104
#13 0x0000556cb26a8b0e in dispatch_command (command=COM_QUERY, thd=0x7fbc18000b00, packet=0x7fbc1801be11 "", packet_length=28, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1851
#14 0x0000556cb26a7532 in do_command (thd=0x7fbc18000b00) at /data/src/10.4/sql/sql_parse.cc:1396
#15 0x0000556cb28136de in do_handle_one_connection (connect=0x556cb67b0700) at /data/src/10.4/sql/sql_connect.cc:1402
#16 0x0000556cb2813462 in handle_one_connection (arg=0x556cb67b0700) at /data/src/10.4/sql/sql_connect.cc:1308
#17 0x00007fbc90a54494 in start_thread (arg=0x7fbc8c2c9700) at pthread_create.c:333
#18 0x00007fbc8f05593f in clone () from /lib/x86_64-linux-gnu/libc.so.6

For the record, this is the basic concurrent test that I ran (not sure if it can reproduce all the above failures, but it can surely reproduce some):

https://github.com/MariaDB/randgen elenst-dev 89b8fe94565

perl ./runall-new.pl --basedir=/home/travis/server/10.4  --duration=350 --threads=2  --mysqld=--log_output=FILE --mysqld=--loose-max-statement-time=5 --mysqld=--lock-wait-timeout=2 --mysqld=--loose-innodb-lock-wait-timeout=1 --mysqld=--loose-debug_assert_on_not_freed_memory=0  --grammar=binevent.yy --gendata=conf/engines/engine_stress.zz --mysqld=--log_bin_trust_function_creators=1 --mysqld=--log-bin --vardir=/home/travis/logs/vardir

The grammar is attached. It's very big and probably essentially excessive, but I don't expect it to be needed anyway, probably the binlog will be much easier to analyze.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

mysql-bin.000001.2019-09-05
97 kB
2019-09-05 16:20
mysql-bin.000001
77 kB
2018-12-20 16:47
EXTRA_ROW_INFO_HDR_BYTES_binary_logs.tar.gz
832 kB
2020-01-03 15:04
binlogs_2019-08-23.tar.gz
2.14 MB
2019-09-19 10:43
binevent.yy
35 kB
2018-12-20 17:03

Activity

People

Assignee:: Sujatha Sivakumar (Inactive)

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 2018-12-20 17:03

Updated:: 2020-09-16 08:33

Resolved:: 2020-01-08 06:21

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.