Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-18046

Assortment of crashes, assertion failures and ASAN errors in mysql_show_binlog_events

    XMLWordPrintable

    Details

      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

        1. binevent.yy
          35 kB
          Elena Stepanova
        2. binlogs_2019-08-23.tar.gz
          2.14 MB
          Elena Stepanova
        3. EXTRA_ROW_INFO_HDR_BYTES_binary_logs.tar.gz
          832 kB
          Elena Stepanova
        4. mysql-bin.000001
          77 kB
          Elena Stepanova
        5. mysql-bin.000001.2019-09-05
          97 kB
          Elena Stepanova

          Activity

            People

            Assignee:
            sujatha.sivakumar Sujatha Sivakumar
            Reporter:
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: