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

SIGSEGV, ASAN use-after-poison, Assertion `next_insert_id == 0' in handler::ha_external_lock

    XMLWordPrintable

    Details

      Description

      --source include/have_innodb.inc
       
      CREATE TEMPORARY TABLE tmp (
        a INT,
        b INT,
        c BLOB NOT NULL,
        d INT,
        e INT DEFAULT 0,
        f INT,
        UNIQUE KEY (c)
      ) ENGINE=InnoDB;
       
      CREATE TABLE t2 (x INT);
       
      LOCK TABLE t2 WRITE;
      UPDATE tmp SET c = 'foo';
      START TRANSACTION;
      ALTER TABLE tmp ALTER COLUMN a SET DEFAULT 8;
       
      # Cleanup
      UNLOCK TABLES;
      DROP TABLE t2;
      

      10.5 244ff3e5 non-debug

      #3  <signal handler called>
      #4  0x0000555aac3f5839 in handler::ha_thd (this=this@entry=0x7fea94011160) at /data/src/10.5/sql/handler.cc:2815
      #5  0x0000555aac693dc9 in ha_innobase::table_flags (this=0x7fea94011160) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4935
      #6  0x0000555aac3fbe67 in handler::ha_external_lock (this=0x7fea94011160, thd=0x7fea940009b8, lock_type=lock_type@entry=2) at /data/src/10.5/sql/handler.cc:6479
      #7  0x0000555aac3fbebb in handler::ha_external_lock (this=0x7fea940fb640, thd=thd@entry=0x7fea940009b8, lock_type=lock_type@entry=2) at /data/src/10.5/sql/handler.cc:6486
      #8  0x0000555aac4cd587 in unlock_external (thd=thd@entry=0x7fea940009b8, table=0x7fea940ea638, count=<optimized out>) at /data/src/10.5/sql/lock.cc:709
      #9  0x0000555aac4cd72b in mysql_unlock_tables (thd=0x7fea940009b8, sql_lock=0x7fea940ea618, free_lock=<optimized out>) at /data/src/10.5/sql/lock.cc:430
      #10 0x0000555aac4cdd31 in mysql_unlock_tables (thd=thd@entry=0x7fea940009b8, sql_lock=<optimized out>) at /data/src/10.5/sql/lock.cc:416
      #11 0x0000555aac2a3774 in mysql_alter_table (thd=thd@entry=0x7fea940009b8, new_db=new_db@entry=0x7fea940050a8, new_name=new_name@entry=0x7fea940054b0, create_info=create_info@entry=0x7feac4fc06c0, table_list=<optimized out>, table_list@entry=0x7fea94010408, alter_info=alter_info@entry=0x7feac4fc05f0, order_num=<optimized out>, order=<optimized out>, ignore=false, if_exists=false) at /data/src/10.5/sql/sql_table.cc:10558
      #12 0x0000555aac2f8aeb in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x7fea940009b8) at /data/src/10.5/sql/sql_alter.cc:528
      #13 0x0000555aac21100d in mysql_execute_command (thd=thd@entry=0x7fea940009b8) at /data/src/10.5/sql/sql_parse.cc:5908
      #14 0x0000555aac2186fb in mysql_parse (thd=thd@entry=0x7fea940009b8, rawbuf=<optimized out>, length=44, parser_state=parser_state@entry=0x7feac4fc1550, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.5/sql/sql_parse.cc:7953
      #15 0x0000555aac20dd2f in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fea940009b8, packet=packet@entry=0x7fea94007c69 "", packet_length=packet_length@entry=44, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.5/sql/sql_parse.cc:1840
      #16 0x0000555aac20c19a in do_command (thd=0x7fea940009b8) at /data/src/10.5/sql/sql_parse.cc:1359
      #17 0x0000555aac2f44d4 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x555aaf78e948, put_in_cache=put_in_cache@entry=true) at /data/src/10.5/sql/sql_connect.cc:1422
      #18 0x0000555aac2f47d3 in handle_one_connection (arg=arg@entry=0x555aaf78e948) at /data/src/10.5/sql/sql_connect.cc:1319
      #19 0x0000555aac60e264 in pfs_spawn_thread (arg=0x555aaf78e9b8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
      #20 0x00007feacd9c74a4 in start_thread (arg=0x7feac4fc2700) at pthread_create.c:456
      #21 0x00007feacbafbd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

      10.5 244ff3e5 debug

      #3  <signal handler called>
      #4  0x00005638000ee9f9 in pfs_start_table_lock_wait_v1 (state=0x7f91c490db00, table=0x8f8f8f8f8f8f8f8f, op=PSI_TABLE_EXTERNAL_LOCK, op_flags=2, src_file=0x56380099bd9e "/data/src/10.5/sql/handler.cc", src_line=6472) at /data/src/10.5/storage/perfschema/pfs.cc:3119
      #5  0x00005637ffd801c0 in handler::ha_external_lock (this=0x7f9194014790, thd=0x7f9194000b18, lock_type=2) at /data/src/10.5/sql/handler.cc:6471
      #6  0x00005637ffd80355 in handler::ha_external_lock (this=0x7f91940fa810, thd=0x7f9194000b18, lock_type=2) at /data/src/10.5/sql/handler.cc:6486
      #7  0x00005637ffeb9684 in unlock_external (thd=0x7f9194000b18, table=0x7f91941f4b68, count=1) at /data/src/10.5/sql/lock.cc:709
      #8  0x00005637ffeb8a74 in mysql_unlock_tables (thd=0x7f9194000b18, sql_lock=0x7f91941f4b48, free_lock=true) at /data/src/10.5/sql/lock.cc:430
      #9  0x00005637ffeb89cb in mysql_unlock_tables (thd=0x7f9194000b18, sql_lock=0x7f91941f4b48) at /data/src/10.5/sql/lock.cc:416
      #10 0x00005637ffb1e179 in mysql_alter_table (thd=0x7f9194000b18, new_db=0x7f91940053c8, new_name=0x7f91940057d0, create_info=0x7f91c4910430, table_list=0x7f9194013a38, alter_info=0x7f91c4910360, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/src/10.5/sql/sql_table.cc:10558
      #11 0x00005637ffbc1592 in Sql_cmd_alter_table::execute (this=0x7f9194014228, thd=0x7f9194000b18) at /data/src/10.5/sql/sql_alter.cc:528
      #12 0x00005637ffa23bd2 in mysql_execute_command (thd=0x7f9194000b18) at /data/src/10.5/sql/sql_parse.cc:5908
      #13 0x00005637ffa2a042 in mysql_parse (thd=0x7f9194000b18, rawbuf=0x7f9194013930 "ALTER TABLE tmp ALTER COLUMN a SET DEFAULT 8", length=44, parser_state=0x7f91c4911520, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7953
      #14 0x00005637ffa15893 in dispatch_command (command=COM_QUERY, thd=0x7f9194000b18, packet=0x7f9194008699 "", packet_length=44, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1840
      #15 0x00005637ffa13fc9 in do_command (thd=0x7f9194000b18) at /data/src/10.5/sql/sql_parse.cc:1359
      #16 0x00005637ffbb72a1 in do_handle_one_connection (connect=0x563803bd4bf8, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1422
      #17 0x00005637ffbb6fd0 in handle_one_connection (arg=0x563803bd4bf8) at /data/src/10.5/sql/sql_connect.cc:1319
      #18 0x00005638000ebf4c in pfs_spawn_thread (arg=0x563803b450b8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
      #19 0x00007f91cd3154a4 in start_thread (arg=0x7f91c4912700) at pthread_create.c:456
      #20 0x00007f91cb449d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

      10.5 debug asan 244ff3e5

      mysqld: /data/src/10.5/sql/handler.cc:6438: int handler::ha_external_lock(THD*, int): Assertion `next_insert_id == 0' failed.
      200402  3:56:46 [ERROR] mysqld got signal 6 ;
       
      #7  0x00007ffb83e9d102 in __GI___assert_fail (assertion=0x55fca240b6e0 "next_insert_id == 0", file=0x55fca2406560 "/data/src/10.5/sql/handler.cc", line=6438, function=0x55fca240ffc0 <handler::ha_external_lock(THD*, int)::__PRETTY_FUNCTION__> "int handler::ha_external_lock(THD*, int)") at assert.c:101
      #8  0x000055fca072c029 in handler::ha_external_lock (this=0x62b0000861c0, thd=0x62b00007e288, lock_type=2) at /data/src/10.5/sql/handler.cc:6438
      #9  0x000055fca072c8fa in handler::ha_external_lock (this=0x61d000244b28, thd=0x62b00007e288, lock_type=2) at /data/src/10.5/sql/handler.cc:6486
      #10 0x000055fca0a1773b in unlock_external (thd=0x62b00007e288, table=0x6100000496e8, count=1) at /data/src/10.5/sql/lock.cc:709
      #11 0x000055fca0a150ff in mysql_unlock_tables (thd=0x62b00007e288, sql_lock=0x6100000496c8, free_lock=true) at /data/src/10.5/sql/lock.cc:430
      #12 0x000055fca0a14f50 in mysql_unlock_tables (thd=0x62b00007e288, sql_lock=0x6100000496c8) at /data/src/10.5/sql/lock.cc:414
      #13 0x000055fca01d97df in mysql_alter_table (thd=0x62b00007e288, new_db=0x62b000082b38, new_name=0x62b000082f40, create_info=0x7ffb75884f30, table_list=0x62b0000853e0, alter_info=0x7ffb75884e30, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/src/10.5/sql/sql_table.cc:10558
      #14 0x000055fca0369166 in Sql_cmd_alter_table::execute (this=0x62b000085c10, thd=0x62b00007e288) at /data/src/10.5/sql/sql_alter.cc:522
      #15 0x000055fc9ff51826 in mysql_execute_command (thd=0x62b00007e288) at /data/src/10.5/sql/sql_parse.cc:5908
      #16 0x000055fc9ff5effb in mysql_parse (thd=0x62b00007e288, rawbuf=0x62b0000852a8 "ALTER TABLE tmp ALTER COLUMN a SET DEFAULT 8", length=44, parser_state=0x7ffb75886a50, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7953
      #17 0x000055fc9ff34deb in dispatch_command (command=COM_QUERY, thd=0x62b00007e288, packet=0x6290002b2289 "", packet_length=44, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1839
      #18 0x000055fc9ff31820 in do_command (thd=0x62b00007e288) at /data/src/10.5/sql/sql_parse.cc:1358
      #19 0x000055fca034e8ab in do_handle_one_connection (connect=0x611000030548, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1422
      #20 0x000055fca034e146 in handle_one_connection (arg=0x611000030408) at /data/src/10.5/sql/sql_connect.cc:1319
      #21 0x000055fca0fec01a in pfs_spawn_thread (arg=0x61600000f708) at /data/src/10.5/storage/perfschema/pfs.cc:2201
      #22 0x00007ffb84717fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
      #23 0x00007ffb83f664cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      Similar test case

      --source include/have_innodb.inc
       
      CREATE TEMPORARY TABLE tmp (
        a INT,
        b INT,
        c BLOB NOT NULL,
        d INT,
        e INT DEFAULT 0,
        UNIQUE KEY (c) USING HASH
      ) ENGINE=InnoDB;
       
      CREATE TABLE t2 (x INT);
       
      LOCK TABLE t2 WRITE;
      UPDATE tmp SET c = 'foo';
      START TRANSACTION;
      ALTER TABLE tmp ALTER COLUMN a SET DEFAULT 8;
       
      # Cleanup
      UNLOCK TABLES;
      DROP TABLE t2;
      

      Similar, slightly different effects (same revision):

      #4  0x0000559022568091 in handler::ha_external_lock (this=0x62b0000861c0, thd=0x62b00007e288, lock_type=2) at /data/src/10.5/sql/handler.cc:6440
      #5  0x00005590225688fa in handler::ha_external_lock (this=0x61d000244b28, thd=0x62b00007e288, lock_type=2) at /data/src/10.5/sql/handler.cc:6486
      #6  0x000055902285373b in unlock_external (thd=0x62b00007e288, table=0x6100000496e8, count=1) at /data/src/10.5/sql/lock.cc:709
      #7  0x00005590228510ff in mysql_unlock_tables (thd=0x62b00007e288, sql_lock=0x6100000496c8, free_lock=true) at /data/src/10.5/sql/lock.cc:430
      #8  0x0000559022850f50 in mysql_unlock_tables (thd=0x62b00007e288, sql_lock=0x6100000496c8) at /data/src/10.5/sql/lock.cc:414
      #9  0x00005590220157df in mysql_alter_table (thd=0x62b00007e288, new_db=0x62b000082b38, new_name=0x62b000082f40, create_info=0x7fea5f1bcf30, table_list=0x62b0000853e0, alter_info=0x7fea5f1bce30, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/src/10.5/sql/sql_table.cc:10558
      #10 0x00005590221a5166 in Sql_cmd_alter_table::execute (this=0x62b000085c10, thd=0x62b00007e288) at /data/src/10.5/sql/sql_alter.cc:522
      #11 0x0000559021d8d826 in mysql_execute_command (thd=0x62b00007e288) at /data/src/10.5/sql/sql_parse.cc:5908
      #12 0x0000559021d9affb in mysql_parse (thd=0x62b00007e288, rawbuf=0x62b0000852a8 "ALTER TABLE tmp ALTER COLUMN a SET DEFAULT 8", length=44, parser_state=0x7fea5f1bea50, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7953
      #13 0x0000559021d70deb in dispatch_command (command=COM_QUERY, thd=0x62b00007e288, packet=0x6290002b2289 "", packet_length=44, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1839
      #14 0x0000559021d6d820 in do_command (thd=0x62b00007e288) at /data/src/10.5/sql/sql_parse.cc:1358
      #15 0x000055902218a8ab in do_handle_one_connection (connect=0x611000030548, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1422
      #16 0x000055902218a146 in handle_one_connection (arg=0x611000030408) at /data/src/10.5/sql/sql_connect.cc:1319
      #17 0x0000559022e2801a in pfs_spawn_thread (arg=0x61600000f708) at /data/src/10.5/storage/perfschema/pfs.cc:2201
      #18 0x00007fea6d838fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
      #19 0x00007fea6d0874cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      ==21666==ERROR: AddressSanitizer: use-after-poison on address 0x62b000086640 at pc 0x55f6d7ceb091 bp 0x7f4b505249e0 sp 0x7f4b505249d8
      READ of size 4 at 0x62b000086640 thread T13
          #0 0x55f6d7ceb090 in handler::ha_external_lock(THD*, int) /data/src/10.5/sql/handler.cc:6440
          #1 0x55f6d7ceb8f9 in handler::ha_external_lock(THD*, int) /data/src/10.5/sql/handler.cc:6486
          #2 0x55f6d7fd673a in unlock_external /data/src/10.5/sql/lock.cc:709
          #3 0x55f6d7fd40fe in mysql_unlock_tables(THD*, st_mysql_lock*, bool) /data/src/10.5/sql/lock.cc:430
          #4 0x55f6d7fd3f4f in mysql_unlock_tables(THD*, st_mysql_lock*) /data/src/10.5/sql/lock.cc:414
          #5 0x55f6d77987de in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool, bool) /data/src/10.5/sql/sql_table.cc:10558
          #6 0x55f6d7928165 in Sql_cmd_alter_table::execute(THD*) /data/src/10.5/sql/sql_alter.cc:522
          #7 0x55f6d7510825 in mysql_execute_command(THD*) /data/src/10.5/sql/sql_parse.cc:5908
          #8 0x55f6d751dffa in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.5/sql/sql_parse.cc:7953
          #9 0x55f6d74f3dea in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.5/sql/sql_parse.cc:1839
          #10 0x55f6d74f081f in do_command(THD*) /data/src/10.5/sql/sql_parse.cc:1358
          #11 0x55f6d790d8aa in do_handle_one_connection(CONNECT*, bool) /data/src/10.5/sql/sql_connect.cc:1422
          #12 0x55f6d790d145 in handle_one_connection /data/src/10.5/sql/sql_connect.cc:1319
          #13 0x55f6d85ab019 in pfs_spawn_thread /data/src/10.5/storage/perfschema/pfs.cc:2201
          #14 0x7f4b5f3bafa2 in start_thread /build/glibc-vjB4T1/glibc-2.28/nptl/pthread_create.c:486
          #15 0x7f4b5ec094ce in clone (/lib/x86_64-linux-gnu/libc.so.6+0xf94ce)
       
      0x62b000086640 is located 5184 bytes inside of 24740-byte region [0x62b000085200,0x62b00008b2a4)
      allocated by thread T13 here:
          #0 0x7f4b5f4bd330 in __interceptor_malloc (/lib/x86_64-linux-gnu/libasan.so.5+0xe9330)
          #1 0x55f6d922925a in sf_malloc /data/src/10.5/mysys/safemalloc.c:118
          #2 0x55f6d91f7c23 in my_malloc /data/src/10.5/mysys/my_malloc.c:88
          #3 0x55f6d91d4600 in reset_root_defaults /data/src/10.5/mysys/my_alloc.c:147
          #4 0x55f6d73d6751 in THD::init_for_queries() /data/src/10.5/sql/sql_class.cc:1402
          #5 0x55f6d790caa1 in prepare_new_connection_state(THD*) /data/src/10.5/sql/sql_connect.cc:1246
          #6 0x55f6d790d1c0 in thd_prepare_connection(THD*) /data/src/10.5/sql/sql_connect.cc:1340
          #7 0x55f6d790d7d5 in do_handle_one_connection(CONNECT*, bool) /data/src/10.5/sql/sql_connect.cc:1412
          #8 0x55f6d790d145 in handle_one_connection /data/src/10.5/sql/sql_connect.cc:1319
          #9 0x55f6d85ab019 in pfs_spawn_thread /data/src/10.5/storage/perfschema/pfs.cc:2201
          #10 0x7f4b5f3bafa2 in start_thread /build/glibc-vjB4T1/glibc-2.28/nptl/pthread_create.c:486
       
      Thread T13 created by T0 here:
          #0 0x7f4b5f424db0 in __interceptor_pthread_create (/lib/x86_64-linux-gnu/libasan.so.5+0x50db0)
          #1 0x55f6d85a5f10 in my_thread_create /data/src/10.5/storage/perfschema/my_thread.h:34
          #2 0x55f6d85ab408 in pfs_spawn_thread_v1 /data/src/10.5/storage/perfschema/pfs.cc:2252
          #3 0x55f6d71fdeea in inline_mysql_thread_create /data/src/10.5/include/mysql/psi/mysql_thread.h:1321
          #4 0x55f6d72140d1 in create_thread_to_handle_connection(CONNECT*) /data/src/10.5/sql/mysqld.cc:6113
          #5 0x55f6d721473f in create_new_thread(CONNECT*) /data/src/10.5/sql/mysqld.cc:6172
          #6 0x55f6d7214aa3 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /data/src/10.5/sql/mysqld.cc:6237
          #7 0x55f6d72156e2 in handle_connections_sockets() /data/src/10.5/sql/mysqld.cc:6364
          #8 0x55f6d7213884 in mysqld_main(int, char**) /data/src/10.5/sql/mysqld.cc:5772
          #9 0x55f6d71fc6b4 in main /data/src/10.5/sql/main.cc:25
          #10 0x7f4b5eb3409a in __libc_start_main ../csu/libc-start.c:308
       
      SUMMARY: AddressSanitizer: use-after-poison /data/src/10.5/sql/handler.cc:6440 in handler::ha_external_lock(THD*, int)
      Shadow bytes around the buggy address:
        0x0c5680008c70: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
        0x0c5680008c80: f7 00 00 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c5680008c90: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c5680008ca0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c5680008cb0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
      =>0x0c5680008cc0: f7 f7 f7 f7 f7 f7 f7 f7[f7]f7 f7 f7 f7 f7 f7 f7
        0x0c5680008cd0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c5680008ce0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c5680008cf0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c5680008d00: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c5680008d10: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
      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
        Freed heap region:       fd
        Stack left redzone:      f1
        Stack mid redzone:       f2
        Stack right redzone:     f3
        Stack after return:      f5
        Stack use after scope:   f8
        Global redzone:          f9
        Global init order:       f6
        Poisoned by user:        f7
        Container overflow:      fc
        Array cookie:            ac
        Intra object redzone:    bb
        ASan internal:           fe
        Left alloca redzone:     ca
        Right alloca redzone:    cb
      ==21666==ABORTING
      

      The problems appeared in 10.5 tree after this commit:

      commit 0515577d128318e1b62511846d88d0c56226168d
      Author: Sergei Golubchik
      Date:   Thu Mar 5 19:19:57 2020 +0100
       
          cleanup: prepare "update_handler" for WITHOUT OVERLAPS
      

        Attachments

          Activity

            People

            Assignee:
            serg Sergei Golubchik
            Reporter:
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: