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

Failing assertion: list.count > 0 in ut_list_remove or Assertion `lock->trx == this' failed in dberr_t trx_t::drop_table

Details

    Description

      Note: The test case is non-deterministic, run with --repeat=N. It usually fails for me within 1-2 attempts.

      --source include/have_innodb.inc
       
      CREATE TABLE t1 (pk INT PRIMARY KEY) ENGINE=InnoDB;
      INSERT INTO t1 VALUES (1);
       
      CREATE TABLE t2 (pk INT PRIMARY KEY, FOREIGN KEY(pk) REFERENCES t1(pk)) ENGINE=InnoDB;
       
      --connect (con1,localhost,root,,test)
      SET FOREIGN_KEY_CHECKS= OFF;
      --send
        CREATE OR REPLACE TABLE t1 (b INT) ENGINE=InnoDB;
       
      --connection default
      --error 0,ER_NO_REFERENCED_ROW_2
      INSERT INTO t2 VALUES (1);
       
      --connection con1
      --error 0,ER_CANT_CREATE_TABLE
      --reap
       
      # Cleanup
      --disconnect con1
      --connection default
      DROP TABLE IF EXISTS t2, t1;
      

      10.6 f43370ba debug

      mariadbd: /data/src/10.6/storage/innobase/dict/drop.cc:161: dberr_t trx_t::drop_table(const dict_table_t&): Assertion `lock->trx == this' failed.
      210722 20:47:20 [ERROR] mysqld got signal 6 ;
       
      #7  0x00007f90122e5f36 in __GI___assert_fail (assertion=0x5570e43f93cf "lock->trx == this", file=0x5570e43f9088 "/data/src/10.6/storage/innobase/dict/drop.cc", line=161, function=0x5570e43f9318 "dberr_t trx_t::drop_table(const dict_table_t&)") at assert.c:101
      #8  0x00005570e3d8cc45 in trx_t::drop_table (this=0x7f900c7da540, table=...) at /data/src/10.6/storage/innobase/dict/drop.cc:161
      #9  0x00005570e3a314b1 in ha_innobase::delete_table (this=0x7f8fd0014e10, name=0x7f900c4e1820 "./test/t1") at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:13491
      #10 0x00005570e35aac20 in hton_drop_table (hton=0x5570e75953f8, path=0x7f900c4e1820 "./test/t1") at /data/src/10.6/sql/handler.cc:576
      #11 0x00005570e35b0fbe in ha_delete_table (thd=0x7f8fd0000db8, hton=0x5570e75953f8, path=0x7f900c4e1820 "./test/t1", db=0x7f900c4e15f0, alias=0x7f900c4e1600, generate_warning=false) at /data/src/10.6/sql/handler.cc:3086
      #12 0x00005570e33042d5 in mysql_rm_table_no_locks (thd=0x7f8fd0000db8, tables=0x7f900c4e1d70, current_db=0x7f8fd0000e50, ddl_log_state=0x7f900c4e2810, if_exists=false, drop_temporary=false, drop_view=false, drop_sequence=false, dont_log_query=true, dont_free_locks=true) at /data/src/10.6/sql/sql_table.cc:1469
      #13 0x00005570e330d272 in create_table_impl (thd=0x7f8fd0000db8, ddl_log_state_create=0x7f900c4e27f0, ddl_log_state_rm=0x7f900c4e2810, orig_db=..., orig_table_name=..., db=..., table_name=..., path=..., options=..., create_info=0x7f900c4e2ac0, alter_info=0x7f900c4e29d0, create_table_mode=0, is_trans=0x7f900c4e27ce, key_info=0x7f900c4e2530, key_count=0x7f900c4e2524, frm=0x7f900c4e2550) at /data/src/10.6/sql/sql_table.cc:4308
      #14 0x00005570e330de17 in mysql_create_table_no_lock (thd=0x7f8fd0000db8, ddl_log_state_create=0x7f900c4e27f0, ddl_log_state_rm=0x7f900c4e2810, db=0x7f8fd0014298, table_name=0x7f8fd00142a8, create_info=0x7f900c4e2ac0, alter_info=0x7f900c4e29d0, is_trans=0x7f900c4e27ce, create_table_mode=0, table_list=0x7f8fd0014280) at /data/src/10.6/sql/sql_table.cc:4546
      #15 0x00005570e330e3a8 in mysql_create_table (thd=0x7f8fd0000db8, create_table=0x7f8fd0014280, create_info=0x7f900c4e2ac0, alter_info=0x7f900c4e29d0) at /data/src/10.6/sql/sql_table.cc:4658
      #16 0x00005570e332402f in Sql_cmd_create_table_like::execute (this=0x7f8fd0014220, thd=0x7f8fd0000db8) at /data/src/10.6/sql/sql_table.cc:11778
      #17 0x00005570e321ab52 in mysql_execute_command (thd=0x7f8fd0000db8, is_called_from_prepared_stmt=false) at /data/src/10.6/sql/sql_parse.cc:5993
      #18 0x00005570e3220cfd in mysql_parse (thd=0x7f8fd0000db8, rawbuf=0x7f8fd0014160 "CREATE OR REPLACE TABLE t1 (b INT) ENGINE=InnoDB", length=48, parser_state=0x7f900c4e3480) at /data/src/10.6/sql/sql_parse.cc:8026
      #19 0x00005570e320d165 in dispatch_command (command=COM_QUERY, thd=0x7f8fd0000db8, packet=0x7f8fd000b879 "CREATE OR REPLACE TABLE t1 (b INT) ENGINE=InnoDB", packet_length=48, blocking=true) at /data/src/10.6/sql/sql_parse.cc:1896
      #20 0x00005570e320bb01 in do_command (thd=0x7f8fd0000db8, blocking=true) at /data/src/10.6/sql/sql_parse.cc:1404
      #21 0x00005570e33c921b in do_handle_one_connection (connect=0x5570e7b36db8, put_in_cache=true) at /data/src/10.6/sql/sql_connect.cc:1410
      #22 0x00005570e33c8f77 in handle_one_connection (arg=0x5570e7b36db8) at /data/src/10.6/sql/sql_connect.cc:1312
      #23 0x00005570e39391a5 in pfs_spawn_thread (arg=0x5570e7b36e98) at /data/src/10.6/storage/perfschema/pfs.cc:2201
      #24 0x00007f90127fe609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #25 0x00007f90123d1293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      10.6 f43370ba non-debug

      2021-07-22 20:49:26 0x7f15f40de700  InnoDB: Assertion failure in file /data/src/10.6/storage/innobase/include/ut0lst.h line 334
      InnoDB: Failing assertion: list.count > 0
       
      #6  0x0000558744e04e4e in ut_dbg_assertion_failed (expr=expr@entry=0x5587459f3f91 "list.count > 0", file=file@entry=0x5587459f3f60 "/data/src/10.6/storage/innobase/include/ut0lst.h", line=line@entry=334) at /data/src/10.6/storage/innobase/ut/ut0dbg.cc:60
      #7  0x0000558744de45ef in ut_list_remove<ut_list_base<ib_lock_t, ut_list_node<ib_lock_t> ib_lock_t::*>, GenericGetNode<ib_lock_t> > (get_node=..., node=..., list=...) at /data/src/10.6/storage/innobase/lock/lock0lock.cc:3236
      #8  ut_list_remove<ut_list_base<ib_lock_t, ut_list_node<ib_lock_t> ib_lock_t::*> > (elem=<optimized out>, list=...) at /data/src/10.6/storage/innobase/include/ut0lst.h:386
      #9  lock_table_remove_low (lock=0x7f15eec5dcc8) at /data/src/10.6/storage/innobase/lock/lock0lock.cc:3291
      #10 lock_table_dequeue (in_lock=0x7f15eec5dcc8, owns_wait_mutex=false) at /data/src/10.6/storage/innobase/lock/lock0lock.cc:3529
      #11 0x00005587454c63c4 in lock_release_try (trx=<optimized out>) at /data/src/10.6/storage/innobase/lock/lock0lock.cc:3770
      #12 lock_release (trx=trx@entry=0x7f15eec5d130) at /data/src/10.6/storage/innobase/lock/lock0lock.cc:3806
      #13 0x0000558745581050 in trx_t::release_locks (this=0x7f15eec5d130) at /data/src/10.6/storage/innobase/trx/trx0trx.cc:490
      #14 trx_t::commit_in_memory (this=this@entry=0x7f15eec5d130, mtr=mtr@entry=0x0) at /data/src/10.6/storage/innobase/trx/trx0trx.cc:1297
      #15 0x000055874557fdd7 in trx_t::commit_low (mtr=<optimized out>, this=0x7f15eec5d130) at /data/src/10.6/storage/innobase/trx/trx0trx.cc:1453
      #16 trx_t::commit_persist (this=0x7f15eec5d130) at /data/src/10.6/storage/innobase/trx/trx0trx.cc:1467
      #17 0x000055874557ff06 in trx_t::commit (this=0x7f15eec5d130) at /data/src/10.6/storage/innobase/trx/trx0trx.cc:1473
      #18 0x0000558745572656 in trx_t::rollback_finish (this=0x7f15eec5d130) at /data/src/10.6/storage/innobase/trx/trx0roll.cc:66
      #19 trx_t::rollback_low (this=this@entry=0x7f15eec5d130, savept=savept@entry=0x0) at /data/src/10.6/storage/innobase/trx/trx0roll.cc:133
      #20 0x0000558745571510 in trx_rollback_for_mysql_low (trx=0x7f15eec5d130) at /data/src/10.6/storage/innobase/trx/trx0roll.cc:190
      #21 trx_rollback_for_mysql (trx=trx@entry=0x7f15eec5d130) at /data/src/10.6/storage/innobase/trx/trx0roll.cc:259
      #22 0x000055874546d592 in innobase_rollback (hton=<optimized out>, thd=0x7f15c4000c58, rollback_trx=<optimized out>) at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:4563
      #23 0x0000558745168900 in ha_rollback_trans (thd=thd@entry=0x7f15c4000c58, all=all@entry=false) at /data/src/10.6/sql/handler.cc:2153
      #24 0x0000558745057fb9 in trans_rollback_stmt (thd=thd@entry=0x7f15c4000c58) at /data/src/10.6/sql/transaction.cc:535
      #25 0x0000558744f39ea1 in mysql_execute_command (thd=0x7f15c4000c58, is_called_from_prepared_stmt=<optimized out>) at /data/src/10.6/sql/sql_parse.cc:6046
      #26 0x0000558744f2ac77 in mysql_parse (thd=0x7f15c4000c58, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /data/src/10.6/sql/sql_parse.cc:8026
      #27 0x0000558744f36bdd in dispatch_command (command=COM_QUERY, thd=0x7f15c4000c58, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /data/src/10.6/sql/sql_class.h:1340
      #28 0x0000558744f38af8 in do_command (thd=0x7f15c4000c58, blocking=blocking@entry=true) at /data/src/10.6/sql/sql_parse.cc:1404
      #29 0x0000558745047db7 in do_handle_one_connection (connect=<optimized out>, put_in_cache=true) at /data/src/10.6/sql/sql_connect.cc:1410
      #30 0x000055874504811d in handle_one_connection (arg=arg@entry=0x5587472c2148) at /data/src/10.6/sql/sql_connect.cc:1312
      #31 0x00005587453cfadd in pfs_spawn_thread (arg=0x558747251018) at /data/src/10.6/storage/perfschema/pfs.cc:2201
      #32 0x00007f15f9009609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #33 0x00007f15f8bf7293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      More variations of the failure from the same test case

      10.6 f43370ba ASAN non-debug

      2021-07-22 21:11:39 0x7f99ce43e300  InnoDB: Assertion failure in file /data/src/10.6/storage/innobase/dict/dict0dict.cc line 1891
      InnoDB: Failing assertion: table->n_rec_locks == 0
       
      #6  0x000055ed0a795cf0 in ut_dbg_assertion_failed (expr=expr@entry=0x55ed0cabdae0 "table->n_rec_locks == 0", file=file@entry=0x55ed0cabc360 "/data/src/10.6/storage/innobase/dict/dict0dict.cc", line=line@entry=1891) at /data/src/10.6/storage/innobase/ut/ut0dbg.cc:60
      #7  0x000055ed0a7b2050 in dict_sys_t::remove (this=<optimized out>, table=table@entry=0x617000071988, lru=lru@entry=false, keep=keep@entry=false) at /data/src/10.6/storage/innobase/dict/dict0dict.cc:1891
      #8  0x000055ed0c2ecd03 in trx_t::commit (this=this@entry=0x7f99d4df3b20, deleted=std::vector of length 0, capacity 0) at /data/src/10.6/storage/innobase/dict/drop.cc:251
      #9  0x000055ed0bdbcd1e in ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:13496
      #10 0x000055ed0b33ce49 in hton_drop_table (hton=<optimized out>, path=<optimized out>) at /data/src/10.6/sql/handler.cc:576
      #11 0x000055ed0b3531c7 in ha_delete_table (thd=thd@entry=0x62b00010a218, hton=hton@entry=0x615000002898, path=path@entry=0x7f99ce438b80 "./test/t1", db=db@entry=0x7f99ce438000, alias=alias@entry=0x7f99ce438020, generate_warning=generate_warning@entry=false) at /data/src/10.6/sql/handler.cc:3086
      #12 0x000055ed0add3835 in mysql_rm_table_no_locks (thd=0x62b00010a218, tables=<optimized out>, current_db=<optimized out>, ddl_log_state=<optimized out>, if_exists=<optimized out>, drop_temporary=<optimized out>, drop_view=<optimized out>, drop_sequence=<optimized out>, dont_log_query=<optimized out>, dont_free_locks=<optimized out>) at /data/src/10.6/sql/sql_table.cc:1469
      #13 0x000055ed0ae0fce3 in create_table_impl (thd=thd@entry=0x62b00010a218, ddl_log_state_create=ddl_log_state_create@entry=0x7f99ce43a730, ddl_log_state_rm=ddl_log_state_rm@entry=0x7f99ce43a770, orig_db=..., orig_table_name=..., db=..., table_name=..., path=..., options=..., create_info=<optimized out>, alter_info=<optimized out>, create_table_mode=<optimized out>, is_trans=<optimized out>, key_info=<optimized out>, key_count=<optimized out>, frm=<optimized out>) at /data/src/10.6/sql/sql_table.cc:4308
      #14 0x000055ed0ae10a41 in mysql_create_table_no_lock (thd=thd@entry=0x62b00010a218, ddl_log_state_create=ddl_log_state_create@entry=0x7f99ce43a730, ddl_log_state_rm=ddl_log_state_rm@entry=0x7f99ce43a770, db=db@entry=0x62b0001113a8, table_name=table_name@entry=0x62b0001113b8, create_info=create_info@entry=0x7f99ce43ab90, alter_info=<optimized out>, is_trans=<optimized out>, create_table_mode=<optimized out>, table_list=<optimized out>) at /data/src/10.6/sql/sql_table.cc:4546
      #15 0x000055ed0ae1141c in mysql_create_table (thd=thd@entry=0x62b00010a218, create_table=create_table@entry=0x62b000111390, create_info=create_info@entry=0x7f99ce43ab90, alter_info=alter_info@entry=0x7f99ce43aa60) at /data/src/10.6/sql/sql_table.cc:4658
      #16 0x000055ed0ae16a6f in Sql_cmd_create_table_like::execute (this=<optimized out>, thd=0x62b00010a218) at /data/src/10.6/sql/sql_table.cc:11778
      #17 0x000055ed0abbaac4 in mysql_execute_command (thd=0x62b00010a218, is_called_from_prepared_stmt=<optimized out>) at /data/src/10.6/sql/sql_parse.cc:5993
      #18 0x000055ed0ab81e94 in mysql_parse (thd=0x62b00010a218, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /data/src/10.6/sql/sql_parse.cc:8026
      #19 0x000055ed0abae1b8 in dispatch_command (command=COM_QUERY, thd=0x62b00010a218, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /data/src/10.6/sql/sql_class.h:1340
      #20 0x000055ed0abb4787 in do_command (thd=0x62b00010a218, blocking=blocking@entry=true) at /data/src/10.6/sql/sql_parse.cc:1404
      #21 0x000055ed0af73a3c in do_handle_one_connection (connect=<optimized out>, put_in_cache=<optimized out>) at /data/src/10.6/sql/sql_connect.cc:1410
      #22 0x000055ed0af74295 in handle_one_connection (arg=arg@entry=0x608000002f38) at /data/src/10.6/sql/sql_connect.cc:1312
      #23 0x000055ed0bb9c3a0 in pfs_spawn_thread (arg=0x61700000a898) at /data/src/10.6/storage/perfschema/pfs.cc:2201
      #24 0x00007f99de38b609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #25 0x00007f99ddf5e293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      10.6 f43370ba ASAN non-debug

      ==4176551==ERROR: AddressSanitizer: heap-use-after-free on address 0x61600009c720 at pc 0x55ae52a25d28 bp 0x7f1d0def83c0 sp 0x7f1d0def83b0
      READ of size 8 at 0x61600009c720 thread T12
          #0 0x55ae52a25d27 in lock_rec_dequeue_from_page /data/src/10.6/storage/innobase/lock/lock0lock.cc:1933
          #1 0x55ae52a2b561 in lock_release_try /data/src/10.6/storage/innobase/lock/lock0lock.cc:3755
          #2 0x55ae52a2b561 in lock_release(trx_t*) /data/src/10.6/storage/innobase/lock/lock0lock.cc:3806
          #3 0x55ae52cacb1f in trx_t::release_locks() /data/src/10.6/storage/innobase/trx/trx0trx.cc:490
          #4 0x55ae52cacb1f in trx_t::commit_in_memory(mtr_t const*) /data/src/10.6/storage/innobase/trx/trx0trx.cc:1297
          #5 0x55ae52cab240 in trx_t::commit_persist() /data/src/10.6/storage/innobase/trx/trx0trx.cc:1467
          #6 0x55ae52cabc40 in trx_t::commit() /data/src/10.6/storage/innobase/trx/trx0trx.cc:1473
          #7 0x55ae52cabc40 in trx_commit_for_mysql(trx_t*) /data/src/10.6/storage/innobase/trx/trx0trx.cc:1589
          #8 0x55ae52905a95 in innobase_commit_low(trx_t*) /data/src/10.6/storage/innobase/handler/ha_innodb.cc:4258
          #9 0x55ae52905d1a in innobase_commit_ordered_2 /data/src/10.6/storage/innobase/handler/ha_innodb.cc:4364
          #10 0x55ae52906131 in innobase_commit /data/src/10.6/storage/innobase/handler/ha_innodb.cc:4468
          #11 0x55ae51eb59b8 in commit_one_phase_2 /data/src/10.6/sql/handler.cc:2041
          #12 0x55ae51eb7fe9 in ha_commit_trans(THD*, bool) /data/src/10.6/sql/handler.cc:1788
          #13 0x55ae51b29150 in trans_commit_stmt(THD*) /data/src/10.6/sql/transaction.cc:472
          #14 0x55ae51739d91 in mysql_execute_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:6053
          #15 0x55ae51701e93 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.6/sql/sql_parse.cc:8026
          #16 0x55ae5172e1b7 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/src/10.6/sql/sql_parse.cc:1896
          #17 0x55ae51734786 in do_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:1404
          #18 0x55ae51af3a3b in do_handle_one_connection(CONNECT*, bool) /data/src/10.6/sql/sql_connect.cc:1410
          #19 0x55ae51af4294 in handle_one_connection /data/src/10.6/sql/sql_connect.cc:1312
          #20 0x55ae5271c39f in pfs_spawn_thread /data/src/10.6/storage/perfschema/pfs.cc:2201
          #21 0x7f1d1d28d608 in start_thread /build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477
          #22 0x7f1d1ce60292 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x122292)
      

      Reproducible on 10.6 debug and non-debug as described above.
      Not reproducible on 10.5.

      Attachments

        Issue Links

          Activity

            elenst Elena Stepanova added a comment - - edited

            A slightly different test case which produces similar failures as above on a non-ASAN build, but a different one on ASAN build:

            --source include/have_innodb.inc
             
            CREATE TABLE t1 (pk INT PRIMARY KEY) ENGINE=InnoDB;
            CREATE TABLE t2 (pk INT PRIMARY KEY) ENGINE=InnoDB;
             
            --connect (con1,localhost,root,,test)
            ALTER TABLE t2 ADD CONSTRAINT FOREIGN KEY(pk) REFERENCES t1(pk);
             
            SET innodb_lock_wait_timeout= 0;
            --send
              ALTER TABLE t1 FORCE;
             
            --connection default
             
            START TRANSACTION;
            --error 0,ER_LOCK_WAIT_TIMEOUT,ER_NO_REFERENCED_ROW_2
            INSERT INTO t2 VALUES (1),(2),(3),(4),(5),(6);
             
            --connection con1
            --error 0,ER_LOCK_WAIT_TIMEOUT
            --reap
             
            # Cleanup
            --disconnect con1
            --connection default
            DROP TABLE t2, t1;
            

            10.6 f43370ba non-debug ASAN

            ==34056==ERROR: AddressSanitizer: heap-use-after-free on address 0x61700005bd7c at pc 0x55ac857c0b6c bp 0x7f4565706550 sp 0x7f4565706540
            WRITE of size 4 at 0x61700005bd7c thread T12
                #0 0x55ac857c0b6b in std::__atomic_base<unsigned int>::compare_exchange_strong(unsigned int&, unsigned int, std::memory_order, std::memory_order) /usr/include/c++/9/bits/atomic_base.h:502
                #1 0x55ac857c0b6b in srw_mutex::wr_lock_try() /data/src/10.6/storage/innobase/include/srw_lock.h:65
                #2 0x55ac857c0b6b in dict_table_t::lock_mutex_trylock() /data/src/10.6/storage/innobase/include/dict0mem.h:1991
                #3 0x55ac857c0b6b in lock_release_try /data/src/10.6/storage/innobase/lock/lock0lock.cc:3766
                #4 0x55ac857c0b6b in lock_release(trx_t*) /data/src/10.6/storage/innobase/lock/lock0lock.cc:3806
                #5 0x55ac85a41b1f in trx_t::release_locks() /data/src/10.6/storage/innobase/trx/trx0trx.cc:490
                #6 0x55ac85a41b1f in trx_t::commit_in_memory(mtr_t const*) /data/src/10.6/storage/innobase/trx/trx0trx.cc:1297
                #7 0x55ac85a40240 in trx_t::commit_persist() /data/src/10.6/storage/innobase/trx/trx0trx.cc:1467
                #8 0x55ac85a40c40 in trx_t::commit() /data/src/10.6/storage/innobase/trx/trx0trx.cc:1473
                #9 0x55ac85a40c40 in trx_commit_for_mysql(trx_t*) /data/src/10.6/storage/innobase/trx/trx0trx.cc:1589
                #10 0x55ac8569aa95 in innobase_commit_low(trx_t*) /data/src/10.6/storage/innobase/handler/ha_innodb.cc:4258
                #11 0x55ac8569ad1a in innobase_commit_ordered_2 /data/src/10.6/storage/innobase/handler/ha_innodb.cc:4364
                #12 0x55ac8569b131 in innobase_commit /data/src/10.6/storage/innobase/handler/ha_innodb.cc:4468
                #13 0x55ac84c4a9b8 in commit_one_phase_2 /data/src/10.6/sql/handler.cc:2041
                #14 0x55ac84c4cfe9 in ha_commit_trans(THD*, bool) /data/src/10.6/sql/handler.cc:1788
                #15 0x55ac848bdc34 in trans_commit_implicit(THD*) /data/src/10.6/sql/transaction.cc:329
                #16 0x55ac844ce397 in mysql_execute_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:3750
                #17 0x55ac84496e93 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.6/sql/sql_parse.cc:8026
                #18 0x55ac844c31b7 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/src/10.6/sql/sql_parse.cc:1896
                #19 0x55ac844c9786 in do_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:1404
                #20 0x55ac84888a3b in do_handle_one_connection(CONNECT*, bool) /data/src/10.6/sql/sql_connect.cc:1410
                #21 0x55ac84889294 in handle_one_connection /data/src/10.6/sql/sql_connect.cc:1312
                #22 0x55ac854b139f in pfs_spawn_thread /data/src/10.6/storage/perfschema/pfs.cc:2201
                #23 0x7f4574a91608 in start_thread /build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477
                #24 0x7f4574664292 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x122292)
            

            It is also non-deterministic, and fails more reluctantly than the one in description, usually in 10-20 attempts.

            elenst Elena Stepanova added a comment - - edited A slightly different test case which produces similar failures as above on a non-ASAN build, but a different one on ASAN build: --source include/have_innodb.inc   CREATE TABLE t1 (pk INT PRIMARY KEY ) ENGINE=InnoDB; CREATE TABLE t2 (pk INT PRIMARY KEY ) ENGINE=InnoDB;   --connect (con1,localhost,root,,test) ALTER TABLE t2 ADD CONSTRAINT FOREIGN KEY (pk) REFERENCES t1(pk);   SET innodb_lock_wait_timeout= 0; --send ALTER TABLE t1 FORCE ;   --connection default   START TRANSACTION ; --error 0,ER_LOCK_WAIT_TIMEOUT,ER_NO_REFERENCED_ROW_2 INSERT INTO t2 VALUES (1),(2),(3),(4),(5),(6);   --connection con1 --error 0,ER_LOCK_WAIT_TIMEOUT --reap   # Cleanup --disconnect con1 --connection default DROP TABLE t2, t1; 10.6 f43370ba non-debug ASAN ==34056==ERROR: AddressSanitizer: heap-use-after-free on address 0x61700005bd7c at pc 0x55ac857c0b6c bp 0x7f4565706550 sp 0x7f4565706540 WRITE of size 4 at 0x61700005bd7c thread T12 #0 0x55ac857c0b6b in std::__atomic_base<unsigned int>::compare_exchange_strong(unsigned int&, unsigned int, std::memory_order, std::memory_order) /usr/include/c++/9/bits/atomic_base.h:502 #1 0x55ac857c0b6b in srw_mutex::wr_lock_try() /data/src/10.6/storage/innobase/include/srw_lock.h:65 #2 0x55ac857c0b6b in dict_table_t::lock_mutex_trylock() /data/src/10.6/storage/innobase/include/dict0mem.h:1991 #3 0x55ac857c0b6b in lock_release_try /data/src/10.6/storage/innobase/lock/lock0lock.cc:3766 #4 0x55ac857c0b6b in lock_release(trx_t*) /data/src/10.6/storage/innobase/lock/lock0lock.cc:3806 #5 0x55ac85a41b1f in trx_t::release_locks() /data/src/10.6/storage/innobase/trx/trx0trx.cc:490 #6 0x55ac85a41b1f in trx_t::commit_in_memory(mtr_t const*) /data/src/10.6/storage/innobase/trx/trx0trx.cc:1297 #7 0x55ac85a40240 in trx_t::commit_persist() /data/src/10.6/storage/innobase/trx/trx0trx.cc:1467 #8 0x55ac85a40c40 in trx_t::commit() /data/src/10.6/storage/innobase/trx/trx0trx.cc:1473 #9 0x55ac85a40c40 in trx_commit_for_mysql(trx_t*) /data/src/10.6/storage/innobase/trx/trx0trx.cc:1589 #10 0x55ac8569aa95 in innobase_commit_low(trx_t*) /data/src/10.6/storage/innobase/handler/ha_innodb.cc:4258 #11 0x55ac8569ad1a in innobase_commit_ordered_2 /data/src/10.6/storage/innobase/handler/ha_innodb.cc:4364 #12 0x55ac8569b131 in innobase_commit /data/src/10.6/storage/innobase/handler/ha_innodb.cc:4468 #13 0x55ac84c4a9b8 in commit_one_phase_2 /data/src/10.6/sql/handler.cc:2041 #14 0x55ac84c4cfe9 in ha_commit_trans(THD*, bool) /data/src/10.6/sql/handler.cc:1788 #15 0x55ac848bdc34 in trans_commit_implicit(THD*) /data/src/10.6/sql/transaction.cc:329 #16 0x55ac844ce397 in mysql_execute_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:3750 #17 0x55ac84496e93 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.6/sql/sql_parse.cc:8026 #18 0x55ac844c31b7 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/src/10.6/sql/sql_parse.cc:1896 #19 0x55ac844c9786 in do_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:1404 #20 0x55ac84888a3b in do_handle_one_connection(CONNECT*, bool) /data/src/10.6/sql/sql_connect.cc:1410 #21 0x55ac84889294 in handle_one_connection /data/src/10.6/sql/sql_connect.cc:1312 #22 0x55ac854b139f in pfs_spawn_thread /data/src/10.6/storage/perfschema/pfs.cc:2201 #23 0x7f4574a91608 in start_thread /build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477 #24 0x7f4574664292 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x122292) It is also non-deterministic, and fails more reluctantly than the one in description, usually in 10-20 attempts.

            The second test case did not fail for me in several thousand attempts, neither with or without ASAN, possibly thanks to MDEV-26554. The first one does fail, both with and without ASAN:

            10.6 d1edb011eead8401bf14c8d1e90a6fb3f2a4d6e9

            mysqltest: At line 15: query 'INSERT INTO t2 VALUES (1)' failed with wrong errno <Unknown> (2013): 'Lost connection to server during query', instead of  (0)...
            …
            mariadbd: /mariadb/10.6/storage/innobase/dict/drop.cc:159: dberr_t trx_t::drop_table(const dict_table_t&): Assertion `lock->trx == this' failed.
            …
            #19 0x0000564872f0a049 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f75e0000d48, packet=packet@entry=0x7f75e000ace9 "CREATE OR REPLACE TABLE t1 (b INT) ENGINE=InnoDB", packet_length=packet_length@entry=48, blocking=blocking@entry=true) at /mariadb/10.6/sql/sql_parse.cc:1912
            

            marko Marko Mäkelä added a comment - The second test case did not fail for me in several thousand attempts, neither with or without ASAN, possibly thanks to MDEV-26554 . The first one does fail, both with and without ASAN: 10.6 d1edb011eead8401bf14c8d1e90a6fb3f2a4d6e9 mysqltest: At line 15: query 'INSERT INTO t2 VALUES (1)' failed with wrong errno <Unknown> (2013): 'Lost connection to server during query', instead of (0)... … mariadbd: /mariadb/10.6/storage/innobase/dict/drop.cc:159: dberr_t trx_t::drop_table(const dict_table_t&): Assertion `lock->trx == this' failed. … #19 0x0000564872f0a049 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f75e0000d48, packet=packet@entry=0x7f75e000ace9 "CREATE OR REPLACE TABLE t1 (b INT) ENGINE=InnoDB", packet_length=packet_length@entry=48, blocking=blocking@entry=true) at /mariadb/10.6/sql/sql_parse.cc:1912

            I was not able to reproduce the failure with rr record. From a core dump, I could tell that lock->trx belongs to another thread:

            10.6 d1edb011eead8401bf14c8d1e90a6fb3f2a4d6e9

            [Current thread is 1 (Thread 0x7f8564452640 (LWP 1163113))]
            (gdb) frame 8
            #8  0x000055b7c60ddef0 in trx_t::drop_table (this=this@entry=0x7f856c639c80, 
            …
            (gdb) p lock.trx.id
            $1 = 30
            (gdb) p lock.trx.state
            $2 = {m = {_M_i = TRX_STATE_ACTIVE}}
            (gdb) p/x lock.trx.mysql_thd.real_id
            $3 = 0x7f856c063640
            (gdb) thread find 0x7f856c063640
            Thread 19 has target id 'Thread 0x7f856c063640 (LWP 1163050)'
            (gdb) thread apply 19 backtrace
             
            Thread 19 (Thread 0x7f856c063640 (LWP 1163050)):
            …
            #4  0x000055b7c61a1280 in safe_cond_timedwait (cond=0x7f856c637c10, mp=0x55b7c73977c0 <lock_sys+192>, abstime=0x7f856c061110, file=0x55b7c644e3e0 "/mariadb/10.6/storage/innobase/lock/lock0lock.cc", line=1823) at /mariadb/10.6/mysys/thr_mutex.c:546
            #5  0x000055b7c5f36849 in lock_wait (thr=thr@entry=0x7f851000c890) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:1823
            #6  0x000055b7c5fb7c92 in row_ins_check_foreign_constraint (check_ref=check_ref@entry=1, foreign=foreign@entry=0x7f85100c0340, table=table@entry=0x7f851004b370, entry=entry@entry=0x7f8510036e10, thr=thr@entry=0x7f851000c890) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1824
            #7  0x000055b7c5fb7e74 in row_ins_check_foreign_constraints (table=0x7f851004b370, index=index@entry=0x7f851004cab0, pk=pk@entry=true, entry=entry@entry=0x7f8510036e10, thr=thr@entry=0x7f851000c890) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1951
            #8  0x000055b7c5fb9473 in row_ins_clust_index_entry (index=index@entry=0x7f851004cab0, entry=entry@entry=0x7f8510036e10, thr=thr@entry=0x7f851000c890, n_ext=n_ext@entry=0) at /mariadb/10.6/storage/innobase/row/row0ins.cc:3184
            …
            #20 0x000055b7c5a59049 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f8510000d48, packet=packet@entry=0x7f8510087069 "INSERT INTO t2 VALUES (1)", packet_length=packet_length@entry=25, blocking=blocking@entry=true) at /mariadb/10.6/sql/sql_parse.cc:1912
            

            The INSERT INTO t2 is waiting for a IS lock on the table test.t1 that is being dropped. MDEV-26554 worked around insufficient metadata locking in exactly this type of scenarios, but only in ha_innobase::truncate() and ha_innobase::rename_table(), not ha_innobase::delete_table().

            After I added exclusive child table locking to ha_innobase::delete_table(), the test would occasionally trigger an assertion failure table->n_rec_locks == 0 in dict_sys_t::remove(), with the count actually being 1. The interesting part of the culprit’s stack trace (INSERT INTO t2) is as follows:

            #5  0x000055bba7673ac8 in lock_sys_t::wr_lock (this=this@entry=0x55bba8b32700 <lock_sys>) at /mariadb/10.6/storage/innobase/include/lock0lock.h:753
            #6  0x000055bba76ca84e in lock_rec_queue_validate (locked_lock_trx_sys=locked_lock_trx_sys@entry=false, id=id@entry={m_id = 21474836483}, rec=rec@entry=0x7f1eaac7407d "\200", index=index@entry=0x7f1e5418bec0, offsets=offsets@entry=0x7f1eaa4261f0) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:4567
            #7  0x000055bba76cd380 in lock_clust_rec_read_check_and_lock (flags=flags@entry=0, block=block@entry=0x7f1eaa7b1560, rec=rec@entry=0x7f1eaac7407d "\200", index=index@entry=0x7f1e5418bec0, offsets=offsets@entry=0x7f1eaa4261f0, mode=mode@entry=LOCK_S, gap_mode=1024, thr=0x7f1e5404fc70) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:5513
            #8  0x000055bba774ce6a in row_ins_set_shared_rec_lock (type=type@entry=1024, block=block@entry=0x7f1eaa7b1560, rec=rec@entry=0x7f1eaac7407d "\200", index=index@entry=0x7f1e5418bec0, offsets=offsets@entry=0x7f1eaa4261f0, thr=thr@entry=0x7f1e5404fc70) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1398
            #9  0x000055bba7752b0b in row_ins_check_foreign_constraint (check_ref=check_ref@entry=1, foreign=foreign@entry=0x7f1e540c0340, table=table@entry=0x7f1e5404b370, entry=entry@entry=0x7f1e5404c750, thr=thr@entry=0x7f1e5404fc70) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1706
            #10 0x000055bba7752f30 in row_ins_check_foreign_constraints (table=0x7f1e5404b370, index=index@entry=0x7f1e5404cab0, pk=pk@entry=true, entry=entry@entry=0x7f1e5404c750, thr=thr@entry=0x7f1e5404fc70) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1951
            

            marko Marko Mäkelä added a comment - I was not able to reproduce the failure with rr record . From a core dump, I could tell that lock->trx belongs to another thread: 10.6 d1edb011eead8401bf14c8d1e90a6fb3f2a4d6e9 [Current thread is 1 (Thread 0x7f8564452640 (LWP 1163113))] (gdb) frame 8 #8 0x000055b7c60ddef0 in trx_t::drop_table (this=this@entry=0x7f856c639c80, … (gdb) p lock.trx.id $1 = 30 (gdb) p lock.trx.state $2 = {m = {_M_i = TRX_STATE_ACTIVE}} (gdb) p/x lock.trx.mysql_thd.real_id $3 = 0x7f856c063640 (gdb) thread find 0x7f856c063640 Thread 19 has target id 'Thread 0x7f856c063640 (LWP 1163050)' (gdb) thread apply 19 backtrace   Thread 19 (Thread 0x7f856c063640 (LWP 1163050)): … #4 0x000055b7c61a1280 in safe_cond_timedwait (cond=0x7f856c637c10, mp=0x55b7c73977c0 <lock_sys+192>, abstime=0x7f856c061110, file=0x55b7c644e3e0 "/mariadb/10.6/storage/innobase/lock/lock0lock.cc", line=1823) at /mariadb/10.6/mysys/thr_mutex.c:546 #5 0x000055b7c5f36849 in lock_wait (thr=thr@entry=0x7f851000c890) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:1823 #6 0x000055b7c5fb7c92 in row_ins_check_foreign_constraint (check_ref=check_ref@entry=1, foreign=foreign@entry=0x7f85100c0340, table=table@entry=0x7f851004b370, entry=entry@entry=0x7f8510036e10, thr=thr@entry=0x7f851000c890) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1824 #7 0x000055b7c5fb7e74 in row_ins_check_foreign_constraints (table=0x7f851004b370, index=index@entry=0x7f851004cab0, pk=pk@entry=true, entry=entry@entry=0x7f8510036e10, thr=thr@entry=0x7f851000c890) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1951 #8 0x000055b7c5fb9473 in row_ins_clust_index_entry (index=index@entry=0x7f851004cab0, entry=entry@entry=0x7f8510036e10, thr=thr@entry=0x7f851000c890, n_ext=n_ext@entry=0) at /mariadb/10.6/storage/innobase/row/row0ins.cc:3184 … #20 0x000055b7c5a59049 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f8510000d48, packet=packet@entry=0x7f8510087069 "INSERT INTO t2 VALUES (1)", packet_length=packet_length@entry=25, blocking=blocking@entry=true) at /mariadb/10.6/sql/sql_parse.cc:1912 The INSERT INTO t2 is waiting for a IS lock on the table test.t1 that is being dropped. MDEV-26554 worked around insufficient metadata locking in exactly this type of scenarios, but only in ha_innobase::truncate() and ha_innobase::rename_table() , not ha_innobase::delete_table() . After I added exclusive child table locking to ha_innobase::delete_table() , the test would occasionally trigger an assertion failure table->n_rec_locks == 0 in dict_sys_t::remove() , with the count actually being 1. The interesting part of the culprit’s stack trace ( INSERT INTO t2 ) is as follows: #5 0x000055bba7673ac8 in lock_sys_t::wr_lock (this=this@entry=0x55bba8b32700 <lock_sys>) at /mariadb/10.6/storage/innobase/include/lock0lock.h:753 #6 0x000055bba76ca84e in lock_rec_queue_validate (locked_lock_trx_sys=locked_lock_trx_sys@entry=false, id=id@entry={m_id = 21474836483}, rec=rec@entry=0x7f1eaac7407d "\200", index=index@entry=0x7f1e5418bec0, offsets=offsets@entry=0x7f1eaa4261f0) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:4567 #7 0x000055bba76cd380 in lock_clust_rec_read_check_and_lock (flags=flags@entry=0, block=block@entry=0x7f1eaa7b1560, rec=rec@entry=0x7f1eaac7407d "\200", index=index@entry=0x7f1e5418bec0, offsets=offsets@entry=0x7f1eaa4261f0, mode=mode@entry=LOCK_S, gap_mode=1024, thr=0x7f1e5404fc70) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:5513 #8 0x000055bba774ce6a in row_ins_set_shared_rec_lock (type=type@entry=1024, block=block@entry=0x7f1eaa7b1560, rec=rec@entry=0x7f1eaac7407d "\200", index=index@entry=0x7f1e5418bec0, offsets=offsets@entry=0x7f1eaa4261f0, thr=thr@entry=0x7f1e5404fc70) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1398 #9 0x000055bba7752b0b in row_ins_check_foreign_constraint (check_ref=check_ref@entry=1, foreign=foreign@entry=0x7f1e540c0340, table=table@entry=0x7f1e5404b370, entry=entry@entry=0x7f1e5404c750, thr=thr@entry=0x7f1e5404fc70) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1706 #10 0x000055bba7752f30 in row_ins_check_foreign_constraints (table=0x7f1e5404b370, index=index@entry=0x7f1e5404cab0, pk=pk@entry=true, entry=entry@entry=0x7f1e5404c750, thr=thr@entry=0x7f1e5404fc70) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1951

            mleich provided an rr replay trace. It turns out that the DDL operation is releasing the exclusive table lock on the referencing table t2:

            10.6 fae0ccad6ec391bf85c39070f784589d48e11951 with a patch

            #2  0x0000558285f80823 in lock_table_remove_low (lock=0x7fdba8d01e98) at /data/Server/10.6A/storage/innobase/lock/lock0lock.cc:3345
            #3  0x0000558285f81d91 in lock_table_dequeue (in_lock=0x7fdba8d01e98, owns_wait_mutex=false) at /data/Server/10.6A/storage/innobase/lock/lock0lock.cc:3579
            #4  0x0000558285f84222 in lock_release_try (trx=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/lock/lock0lock.cc:3846
            #5  0x0000558285f846bb in lock_release (trx=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/lock/lock0lock.cc:3879
            #6  0x00005582862d7325 in trx_t::release_locks (this=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:489
            #7  0x00005582862cfbb1 in trx_t::commit_in_memory (mtr=0x7fdba0bb4c10, this=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1292
            #8  trx_t::commit_low (this=0x7fdba8d01940, mtr=0x7fdba0bb4c10) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1448
            #9  0x00005582862d083f in trx_t::commit_persist (this=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1462
            #10 0x00005582864b9927 in trx_t::commit (this=0x7fdba8d01940, deleted=std::vector of length 0, capacity 0) at /data/Server/10.6A/storage/innobase/dict/drop.cc:233
            #11 0x0000558285e1bc58 in ha_innobase::delete_table (this=0x62b0000e7f98, name=0x7fdba0bb7260 "./test/t1") at /data/Server/10.6A/storage/innobase/handler/ha_innodb.cc:13746
            …
            #20 0x0000558284d42880 in mysql_parse (thd=0x62b0000e0218, rawbuf=0x62b0000e7238 "CREATE OR REPLACE TABLE t1 (b INT) ENGINE=InnoDB", length=48, parser_state=0x7fdba0bb9b20)
            

            At this point, the execution of INSERT INTO t2 VALUES(1) was blocked in lock_wait(), waiting for a lock on the table t2, which is referencing the table t1 that is being dropped and created. While the ha_innobase::delete_table() is waiting for the redo log to be persisted, the INSERT will succeed in acquiring the table lock and a record lock, which will later on cause the assertion failure during ha_innobase::delete_table():

            10.6 fae0ccad6ec391bf85c39070f784589d48e11951 with a patch

            #15 0x0000558285fb25d1 in log_write_up_to (lsn=125203, flush_to_disk=true, rotate_key=false, callback=0x7fdba0bb4800) at /data/Server/10.6A/storage/innobase/log/log0log.cc:852
            #16 0x00005582862cd797 in trx_flush_log_if_needed_low (lsn=125203, trx=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1152
            #17 0x00005582862cd84f in trx_flush_log_if_needed (lsn=125203, trx=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1170
            #18 0x00005582862d02c6 in trx_t::commit_in_memory (mtr=0x7fdba0bb4c10, this=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1354
            #19 trx_t::commit_low (this=0x7fdba8d01940, mtr=0x7fdba0bb4c10) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1448
            #20 0x00005582862d083f in trx_t::commit_persist (this=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1462
            #21 0x00005582864b9927 in trx_t::commit (this=0x7fdba8d01940, deleted=std::vector of length 0, capacity 0) at /data/Server/10.6A/storage/innobase/dict/drop.cc:233
            …
            (rr) c
            Continuing.
             
            Thread 2 received signal SIGABRT, Aborted.
            [Switching to Thread 3066115.3071712]
            __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
            50	../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
            (rr) bt
            #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
            #1  0x00007fdbacaac859 in __GI_abort () at abort.c:79
            #2  0x00005582862f1663 in ut_dbg_assertion_failed (expr=0x55828756f7e0 "table->n_rec_locks == 0", file=0x55828756d8a0 "/data/Server/10.6A/storage/innobase/dict/dict0dict.cc", line=1853)
                at /data/Server/10.6A/storage/innobase/ut/ut0dbg.cc:60
            #3  0x000055828643b51e in dict_sys_t::remove (this=0x55828846c680 <dict_sys>, table=0x618000003d08, lru=false, keep=false) at /data/Server/10.6A/storage/innobase/dict/dict0dict.cc:1853
            #4  0x00005582864b9d0f in trx_t::commit (this=0x7fdba8d01940, deleted=std::vector of length 0, capacity 0) at /data/Server/10.6A/storage/innobase/dict/drop.cc:249
            #5  0x0000558285e1bc58 in ha_innobase::delete_table (this=0x62b0000e7f98, name=0x7fdba0bb7260 "./test/t1") at /data/Server/10.6A/storage/innobase/handler/ha_innodb.cc:13746
            

            The fix should be to release any locks atomically with invoking dict_sys_t::remove() to remove the table definition.

            marko Marko Mäkelä added a comment - mleich provided an rr replay trace. It turns out that the DDL operation is releasing the exclusive table lock on the referencing table t2 : 10.6 fae0ccad6ec391bf85c39070f784589d48e11951 with a patch #2 0x0000558285f80823 in lock_table_remove_low (lock=0x7fdba8d01e98) at /data/Server/10.6A/storage/innobase/lock/lock0lock.cc:3345 #3 0x0000558285f81d91 in lock_table_dequeue (in_lock=0x7fdba8d01e98, owns_wait_mutex=false) at /data/Server/10.6A/storage/innobase/lock/lock0lock.cc:3579 #4 0x0000558285f84222 in lock_release_try (trx=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/lock/lock0lock.cc:3846 #5 0x0000558285f846bb in lock_release (trx=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/lock/lock0lock.cc:3879 #6 0x00005582862d7325 in trx_t::release_locks (this=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:489 #7 0x00005582862cfbb1 in trx_t::commit_in_memory (mtr=0x7fdba0bb4c10, this=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1292 #8 trx_t::commit_low (this=0x7fdba8d01940, mtr=0x7fdba0bb4c10) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1448 #9 0x00005582862d083f in trx_t::commit_persist (this=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1462 #10 0x00005582864b9927 in trx_t::commit (this=0x7fdba8d01940, deleted=std::vector of length 0, capacity 0) at /data/Server/10.6A/storage/innobase/dict/drop.cc:233 #11 0x0000558285e1bc58 in ha_innobase::delete_table (this=0x62b0000e7f98, name=0x7fdba0bb7260 "./test/t1") at /data/Server/10.6A/storage/innobase/handler/ha_innodb.cc:13746 … #20 0x0000558284d42880 in mysql_parse (thd=0x62b0000e0218, rawbuf=0x62b0000e7238 "CREATE OR REPLACE TABLE t1 (b INT) ENGINE=InnoDB", length=48, parser_state=0x7fdba0bb9b20) At this point, the execution of INSERT INTO t2 VALUES(1) was blocked in lock_wait() , waiting for a lock on the table t2 , which is referencing the table t1 that is being dropped and created. While the ha_innobase::delete_table() is waiting for the redo log to be persisted, the INSERT will succeed in acquiring the table lock and a record lock, which will later on cause the assertion failure during ha_innobase::delete_table() : 10.6 fae0ccad6ec391bf85c39070f784589d48e11951 with a patch #15 0x0000558285fb25d1 in log_write_up_to (lsn=125203, flush_to_disk=true, rotate_key=false, callback=0x7fdba0bb4800) at /data/Server/10.6A/storage/innobase/log/log0log.cc:852 #16 0x00005582862cd797 in trx_flush_log_if_needed_low (lsn=125203, trx=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1152 #17 0x00005582862cd84f in trx_flush_log_if_needed (lsn=125203, trx=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1170 #18 0x00005582862d02c6 in trx_t::commit_in_memory (mtr=0x7fdba0bb4c10, this=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1354 #19 trx_t::commit_low (this=0x7fdba8d01940, mtr=0x7fdba0bb4c10) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1448 #20 0x00005582862d083f in trx_t::commit_persist (this=0x7fdba8d01940) at /data/Server/10.6A/storage/innobase/trx/trx0trx.cc:1462 #21 0x00005582864b9927 in trx_t::commit (this=0x7fdba8d01940, deleted=std::vector of length 0, capacity 0) at /data/Server/10.6A/storage/innobase/dict/drop.cc:233 … (rr) c Continuing.   Thread 2 received signal SIGABRT, Aborted. [Switching to Thread 3066115.3071712] __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00007fdbacaac859 in __GI_abort () at abort.c:79 #2 0x00005582862f1663 in ut_dbg_assertion_failed (expr=0x55828756f7e0 "table->n_rec_locks == 0", file=0x55828756d8a0 "/data/Server/10.6A/storage/innobase/dict/dict0dict.cc", line=1853) at /data/Server/10.6A/storage/innobase/ut/ut0dbg.cc:60 #3 0x000055828643b51e in dict_sys_t::remove (this=0x55828846c680 <dict_sys>, table=0x618000003d08, lru=false, keep=false) at /data/Server/10.6A/storage/innobase/dict/dict0dict.cc:1853 #4 0x00005582864b9d0f in trx_t::commit (this=0x7fdba8d01940, deleted=std::vector of length 0, capacity 0) at /data/Server/10.6A/storage/innobase/dict/drop.cc:249 #5 0x0000558285e1bc58 in ha_innobase::delete_table (this=0x62b0000e7f98, name=0x7fdba0bb7260 "./test/t1") at /data/Server/10.6A/storage/innobase/handler/ha_innodb.cc:13746 The fix should be to release any locks atomically with invoking dict_sys_t::remove() to remove the table definition.

            With a more complex fix that would hold the exclusive table locks until the point of eviction, AddressSanitizer would report heap-use-after-free or I would get other trouble, because at the time we are dropping the table, the FOREIGN KEY check is attempting to lock the table without holding a reference to it:

            10.6 fae0ccad6ec391bf85c39070f784589d48e11951 with some changes

            #13 0x000055f4caf57303 in ssux_lock_impl<true>::rd_wait (this=this@entry=0x55f4cd1000c0 <lock_sys+64>) at /mariadb/10.6/storage/innobase/sync/srw_lock.cc:392
            #14 0x000055f4cacf5945 in ssux_lock_impl<true>::rd_lock (this=this@entry=0x55f4cd1000c0 <lock_sys+64>) at /mariadb/10.6/storage/innobase/include/srw_lock.h:247
            #15 0x000055f4cad25a18 in lock_sys_t::rd_lock (this=this@entry=0x55f4cd100080 <lock_sys>) at /mariadb/10.6/storage/innobase/include/lock0lock.h:774
            #16 0x000055f4cad19871 in lock_table (table=table@entry=0x618000045108, mode=mode@entry=LOCK_IS, thr=thr@entry=0x620000034868) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:3509
            #17 0x000055f4cae6a529 in row_ins_check_foreign_constraint (check_ref=check_ref@entry=1, foreign=foreign@entry=0x616000988f08, table=table@entry=0x618000046508, entry=entry@entry=0x6160009c5b08, thr=thr@entry=0x620000034868) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1608
            

            The table pointer was simply obtained from a cached object:

            		check_table = foreign->referenced_table;
            

            That pointer would be reset by dict_sys_t::remove(), which in my patch is protected by exclusive lock_sys.latch. As far as I can tell, the problem occurs at this step in lock_table():

            	lock_sys.rd_lock(SRW_LOCK_CALL);
            	table->lock_mutex_lock();
            

            After acquiring the lock_sys.latch, lock_table() should validate the table pointer without dereferencing it.

            marko Marko Mäkelä added a comment - With a more complex fix that would hold the exclusive table locks until the point of eviction, AddressSanitizer would report heap-use-after-free or I would get other trouble, because at the time we are dropping the table, the FOREIGN KEY check is attempting to lock the table without holding a reference to it: 10.6 fae0ccad6ec391bf85c39070f784589d48e11951 with some changes #13 0x000055f4caf57303 in ssux_lock_impl<true>::rd_wait (this=this@entry=0x55f4cd1000c0 <lock_sys+64>) at /mariadb/10.6/storage/innobase/sync/srw_lock.cc:392 #14 0x000055f4cacf5945 in ssux_lock_impl<true>::rd_lock (this=this@entry=0x55f4cd1000c0 <lock_sys+64>) at /mariadb/10.6/storage/innobase/include/srw_lock.h:247 #15 0x000055f4cad25a18 in lock_sys_t::rd_lock (this=this@entry=0x55f4cd100080 <lock_sys>) at /mariadb/10.6/storage/innobase/include/lock0lock.h:774 #16 0x000055f4cad19871 in lock_table (table=table@entry=0x618000045108, mode=mode@entry=LOCK_IS, thr=thr@entry=0x620000034868) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:3509 #17 0x000055f4cae6a529 in row_ins_check_foreign_constraint (check_ref=check_ref@entry=1, foreign=foreign@entry=0x616000988f08, table=table@entry=0x618000046508, entry=entry@entry=0x6160009c5b08, thr=thr@entry=0x620000034868) at /mariadb/10.6/storage/innobase/row/row0ins.cc:1608 The table pointer was simply obtained from a cached object: check_table = foreign->referenced_table; That pointer would be reset by dict_sys_t::remove() , which in my patch is protected by exclusive lock_sys.latch . As far as I can tell, the problem occurs at this step in lock_table() : lock_sys.rd_lock(SRW_LOCK_CALL); table->lock_mutex_lock(); After acquiring the lock_sys.latch , lock_table() should validate the table pointer without dereferencing it.

            I added a parameter to lock_table(). After lock_sys.latch has been acquired, and if that parameter is not NULL and not pointing to table, DB_DEADLOCK will be returned. The parameter table must not be dereferenced before that check. I got over 50×1000 runs of the test passing with that final fix. I had to adjust the test in the Description, to account for the added error code:

            --error 0,ER_NO_REFERENCED_ROW_2,ER_LOCK_DEADLOCK
            INSERT INTO t2 VALUES (1);
            

            marko Marko Mäkelä added a comment - I added a parameter to lock_table() . After lock_sys.latch has been acquired, and if that parameter is not NULL and not pointing to table , DB_DEADLOCK will be returned. The parameter table must not be dereferenced before that check. I got over 50×1000 runs of the test passing with that final fix. I had to adjust the test in the Description, to account for the added error code: --error 0,ER_NO_REFERENCED_ROW_2,ER_LOCK_DEADLOCK INSERT INTO t2 VALUES (1);

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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