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

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.1(EOL), 10.2(EOL), 10.3(EOL), 10.4(EOL)
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

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

Activity

Ascending order - Click to sort in descending order

View 8 older comments

Andrei Elkin added a comment - 2019-12-17 18:45

Sujatha, thanks for this piece of work! Approved.

Andrei Elkin added a comment - 2019-12-17 18:45 Sujatha, thanks for this piece of work! Approved.

Sujatha Sivakumar (Inactive) added a comment - 2019-12-31 07:12

Hello Andrei,

Please review the 10.2 specific final set of changes.
Implemented a macro to check reading out of buffer.

https://github.com/MariaDB/server/commit/736c686a76c9858aeb977085c78d23d2ea9bb7a2

Sujatha Sivakumar (Inactive) added a comment - 2019-12-31 07:12 Hello Andrei, Please review the 10.2 specific final set of changes. Implemented a macro to check reading out of buffer. https://github.com/MariaDB/server/commit/736c686a76c9858aeb977085c78d23d2ea9bb7a2

Elena Stepanova added a comment - 2020-01-03 15:04

Another one:

10.4 2cff807d
mysqld: /data/src/10.4/sql/log_event.cc:10941: Rows_log_event::Rows_log_event(const char, uint, const Format_description_log_event): Assertion `(end - pos) >= EXTRA_ROW_INFO_HDR_BYTES' failed.
200103 16:59:49 [ERROR] mysqld got signal 6 ;

# 2020-01-03T17:00:01 [4364] #7 0x00007fd89f3e9f12 in __GI___assert_fail (assertion=0x56033f2e1c50 "(end - pos) >= EXTRA_ROW_INFO_HDR_BYTES", file=0x56033f2de580 "/data/src/10.4/sql/log_event.cc", line=10941, function=0x56033f2e4c80 <Rows_log_event::Rows_log_event(char const, unsigned int, Format_description_log_event const)::__PRETTY_FUNCTION__> "Rows_log_event::Rows_log_event(const char, uint, const Format_description_log_event)") at assert.c:101
# 2020-01-03T17:00:01 [4364] #8 0x000056033e8c28ad in Rows_log_event::Rows_log_event (this=0x7fd8040bc450, buf=0x7fd8041d49a0 "\201f\344\230\037B", event_len=16923, description_event=0x7fd8042743d0) at /data/src/10.4/sql/log_event.cc:10941
# 2020-01-03T17:00:01 [4364] #9 0x000056033e8cbdb2 in Update_rows_log_event::Update_rows_log_event (this=0x7fd8040bc450, buf=0x7fd8041d49a0 "\201f\344\230\037B", event_len=16923, description_event=0x7fd8042743d0) at /data/src/10.4/sql/log_event.cc:14558
# 2020-01-03T17:00:01 [4364] #10 0x000056033e8af67d in Log_event::read_log_event (buf=0x7fd8041d49a0 "\201f\344\230\037B", event_len=16923, error=0x7fd8893f8f00, fdle=0x7fd8042743d0, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:2192
# 2020-01-03T17:00:01 [4364] #11 0x000056033e8aec06 in Log_event::read_log_event (file=0x7fd8893f9060, fdle=0x7fd8042743d0, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:1950
# 2020-01-03T17:00:01 [4364] #12 0x000056033e4466c5 in mysql_show_binlog_events (thd=0x7fd804000af0) at /data/src/10.4/sql/sql_repl.cc:4109
# 2020-01-03T17:00:01 [4364] #13 0x000056033e405c3d in mysql_execute_command (thd=0x7fd804000af0) at /data/src/10.4/sql/sql_parse.cc:4010
# 2020-01-03T17:00:01 [4364] #14 0x000056033e414237 in mysql_parse (thd=0x7fd804000af0, rawbuf=0x7fd804011e68 "SHOW BINLOG EVENTS FROM 26466 LIMIT 23624 /* QNO 6981 CON_ID 17 */", length=66, parser_state=0x7fd8893fa1b0, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7901
# 2020-01-03T17:00:01 [4364] #15 0x000056033e3ff3dc in dispatch_command (command=COM_QUERY, thd=0x7fd804000af0, packet=0x7fd8040083a1 "", packet_length=67, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
# 2020-01-03T17:00:01 [4364] #16 0x000056033e3fda69 in do_command (thd=0x7fd804000af0) at /data/src/10.4/sql/sql_parse.cc:1360
# 2020-01-03T17:00:01 [4364] #17 0x000056033e5869df in do_handle_one_connection (connect=0x560343d3cb80) at /data/src/10.4/sql/sql_connect.cc:1412
# 2020-01-03T17:00:01 [4364] #18 0x000056033e58672e in handle_one_connection (arg=0x560343d3cb80) at /data/src/10.4/sql/sql_connect.cc:1316
# 2020-01-03T17:00:01 [4364] #19 0x00007fd8a13724a4 in start_thread (arg=0x7fd8893fb700) at pthread_create.c:456
# 2020-01-03T17:00:01 [4364] #20 0x00007fd89f4a6d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Binary logs: EXTRA_ROW_INFO_HDR_BYTES_binary_logs.tar.gz

Elena Stepanova added a comment - 2020-01-03 15:04 Another one: 10.4 2cff807d mysqld: /data/src/10.4/sql/log_event.cc:10941: Rows_log_event::Rows_log_event(const char*, uint, const Format_description_log_event*): Assertion `(end - pos) >= EXTRA_ROW_INFO_HDR_BYTES' failed. 200103 16:59:49 [ERROR] mysqld got signal 6 ; # 2020-01-03T17:00:01 [4364] #7 0x00007fd89f3e9f12 in __GI___assert_fail (assertion=0x56033f2e1c50 "(end - pos) >= EXTRA_ROW_INFO_HDR_BYTES", file=0x56033f2de580 "/data/src/10.4/sql/log_event.cc", line=10941, function=0x56033f2e4c80 <Rows_log_event::Rows_log_event(char const*, unsigned int, Format_description_log_event const*)::__PRETTY_FUNCTION__> "Rows_log_event::Rows_log_event(const char*, uint, const Format_description_log_event*)") at assert.c:101 # 2020-01-03T17:00:01 [4364] #8 0x000056033e8c28ad in Rows_log_event::Rows_log_event (this=0x7fd8040bc450, buf=0x7fd8041d49a0 "\201f\344\230\037B", event_len=16923, description_event=0x7fd8042743d0) at /data/src/10.4/sql/log_event.cc:10941 # 2020-01-03T17:00:01 [4364] #9 0x000056033e8cbdb2 in Update_rows_log_event::Update_rows_log_event (this=0x7fd8040bc450, buf=0x7fd8041d49a0 "\201f\344\230\037B", event_len=16923, description_event=0x7fd8042743d0) at /data/src/10.4/sql/log_event.cc:14558 # 2020-01-03T17:00:01 [4364] #10 0x000056033e8af67d in Log_event::read_log_event (buf=0x7fd8041d49a0 "\201f\344\230\037B", event_len=16923, error=0x7fd8893f8f00, fdle=0x7fd8042743d0, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:2192 # 2020-01-03T17:00:01 [4364] #11 0x000056033e8aec06 in Log_event::read_log_event (file=0x7fd8893f9060, fdle=0x7fd8042743d0, crc_check=0 '\000') at /data/src/10.4/sql/log_event.cc:1950 # 2020-01-03T17:00:01 [4364] #12 0x000056033e4466c5 in mysql_show_binlog_events (thd=0x7fd804000af0) at /data/src/10.4/sql/sql_repl.cc:4109 # 2020-01-03T17:00:01 [4364] #13 0x000056033e405c3d in mysql_execute_command (thd=0x7fd804000af0) at /data/src/10.4/sql/sql_parse.cc:4010 # 2020-01-03T17:00:01 [4364] #14 0x000056033e414237 in mysql_parse (thd=0x7fd804000af0, rawbuf=0x7fd804011e68 "SHOW BINLOG EVENTS FROM 26466 LIMIT 23624 /* QNO 6981 CON_ID 17 */", length=66, parser_state=0x7fd8893fa1b0, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7901 # 2020-01-03T17:00:01 [4364] #15 0x000056033e3ff3dc in dispatch_command (command=COM_QUERY, thd=0x7fd804000af0, packet=0x7fd8040083a1 "", packet_length=67, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842 # 2020-01-03T17:00:01 [4364] #16 0x000056033e3fda69 in do_command (thd=0x7fd804000af0) at /data/src/10.4/sql/sql_parse.cc:1360 # 2020-01-03T17:00:01 [4364] #17 0x000056033e5869df in do_handle_one_connection (connect=0x560343d3cb80) at /data/src/10.4/sql/sql_connect.cc:1412 # 2020-01-03T17:00:01 [4364] #18 0x000056033e58672e in handle_one_connection (arg=0x560343d3cb80) at /data/src/10.4/sql/sql_connect.cc:1316 # 2020-01-03T17:00:01 [4364] #19 0x00007fd8a13724a4 in start_thread (arg=0x7fd8893fb700) at pthread_create.c:456 # 2020-01-03T17:00:01 [4364] #20 0x00007fd89f4a6d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97 Binary logs: EXTRA_ROW_INFO_HDR_BYTES_binary_logs.tar.gz

Andrei Elkin added a comment - 2020-01-07 12:29

The last patch 736c686a76c9858aeb977085c78d23d2ea9bb7a2 looks quite good.
Could you please uppercase all the arg:s of the new macro:
--------------------------------------------------------------------------------V
+#define VALIDATE_BYTES_READ(CUR_POS, START, event_len) \

Thanks for a good work!

Andrei Elkin added a comment - 2020-01-07 12:29 The last patch 736c686a76c9858aeb977085c78d23d2ea9bb7a2 looks quite good. Could you please uppercase all the arg:s of the new macro: --------------------------------------------------------------------------------V +#define VALIDATE_BYTES_READ(CUR_POS, START, event_len) \ Thanks for a good work!

Sujatha Sivakumar (Inactive) added a comment - 2020-01-08 06:21

Fix for this issue is pushed into 10.1.44. The patch is implemented as 10 different commits in 10.1. 10.2 and higher versions will require one more additional fix because of an issue in binlog uncompress code. 10.1 changes are merged into 10.2 and the binlog uncompress fix is added as "Part 11" of fix. It is pushed into 10.2 branch.

Sujatha Sivakumar (Inactive) added a comment - 2020-01-08 06:21 Fix for this issue is pushed into 10.1.44. The patch is implemented as 10 different commits in 10.1. 10.2 and higher versions will require one more additional fix because of an issue in binlog uncompress code. 10.1 changes are merged into 10.2 and the binlog uncompress fix is added as "Part 11" of fix. It is pushed into 10.2 branch.

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.

MariaDB Server

Details

Description

Attachments

Attachments

Activity

People

Dates

Git Integration