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

XA: Assertion `!log->same_pk' failed in row_log_table_apply_delete

Details

    Description

      Apparently belongs to the MDEV-14693 family.

      The test is non-deterministic, run with --repeat=N. N=10 is usually enough for me, but it can vary on different machines.

      --source include/have_innodb.inc
      		 
       
      		 
      CREATE TABLE t1 (a INT) ENGINE=InnoDB;
      		 
      INSERT INTO t1 VALUES (1),(2);
      		 
       
      		 
      --connect (con1,localhost,root,,test)
      		 
      XA START 'xid';
      		 
      UPDATE t1 SET a = 5;
      		 
       
      		 
      --connection default
      		 
      SET innodb_lock_wait_timeout= 2, lock_wait_timeout= 2;
      		 
      --error ER_NO_SUCH_TABLE
      		 
      ALTER TABLE non_existing_table1;
      		 
      --send
      		 
        ALTER TABLE t1 FORCE;
      		 
       
      		 
      --connection con1
      		 
      --error ER_XAER_RMFAIL
      		 
      ALTER TABLE non_existing_table2;
      		 
      DELETE FROM t1 LIMIT 1;
      		 
       
      		 
      --connection default
      		 
      --error ER_LOCK_WAIT_TIMEOUT
      		 
      --reap
      		 
       
      		 
      # Cleanup
      		 
      --connection con1
      		 
      XA END 'xid';
      		 
      XA ROLLBACK 'xid';
      		 
      DROP TABLE t1;
      		 
      --disconnect con1

      10.2 a050189773c9

      		 
      mysqld: /data/src/10.2/storage/innobase/row/row0log.cc:1884: dberr_t row_log_table_apply_delete(que_thr_t*, ulint, const mrec_t*, const ulint*, mem_heap_t*, mem_heap_t*, const row_log_t*, const row_ext_t*, ulint): Assertion `!log->same_pk' failed.
      		 
       
      		 
      #7  0x00007fdcdc075ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
      		 
      #8  0x000055fe179772fd in row_log_table_apply_delete (thr=0x7fdc7c0362c0, trx_id_col=1, mrec=0x7fdcd404f007 "", moffsets=0x7fdc7c068600, offsets_heap=0x7fdc7c05e0c0, heap=0x7fdc7c05a030, log=0x7fdc7c039f10, save_ext=0x0, ext_size=0) at /data/src/10.2/storage/innobase/row/row0log.cc:1884
      		 
      #9  0x000055fe17978a00 in row_log_table_apply_op (thr=0x7fdc7c0362c0, trx_id_col=1, new_trx_id_col=1, dup=0x7fdcd44de2e0, error=0x7fdcd44de084, offsets_heap=0x7fdc7c05e0c0, heap=0x7fdc7c05a030, mrec=0x7fdcd404f007 "", mrec_end=0x7fdcd404f01a "", offsets=0x7fdc7c068600) at /data/src/10.2/storage/innobase/row/row0log.cc:2398
      		 
      #10 0x000055fe1797a4bf in row_log_table_apply_ops (thr=0x7fdc7c0362c0, dup=0x7fdcd44de2e0, stage=0x7fdc7c113ce0) at /data/src/10.2/storage/innobase/row/row0log.cc:2909
      		 
      #11 0x000055fe1797a9ca in row_log_table_apply (thr=0x7fdc7c0362c0, old_table=0x7fdc7c067ff8, table=0x7fdc7c11a880, stage=0x7fdc7c113ce0) at /data/src/10.2/storage/innobase/row/row0log.cc:3008
      		 
      #12 0x000055fe178618ae in ha_innobase::inplace_alter_table (this=0x7fdc7c130d08, altered_table=0x7fdc7c11a880, ha_alter_info=0x7fdcd44de610) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:6488
      		 
      #13 0x000055fe173778f7 in handler::ha_inplace_alter_table (this=0x7fdc7c130d08, altered_table=0x7fdc7c11a880, ha_alter_info=0x7fdcd44de610) at /data/src/10.2/sql/handler.h:3775
      		 
      #14 0x000055fe1736e7b1 in mysql_inplace_alter_table (thd=0x7fdc7c000b00, table_list=0x7fdc7c0125d0, table=0x7fdc7c130100, altered_table=0x7fdc7c11a880, ha_alter_info=0x7fdcd44de610, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7fdcd44de680, alter_ctx=0x7fdcd44df240) at /data/src/10.2/sql/sql_table.cc:7332
      		 
      #15 0x000055fe17373de4 in mysql_alter_table (thd=0x7fdc7c000b00, new_db=0x7fdc7c012be0 "test", new_name=0x0, create_info=0x7fdcd44dfe50, table_list=0x7fdc7c0125d0, alter_info=0x7fdcd44dfda0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9353
      		 
      #16 0x000055fe173ed954 in Sql_cmd_alter_table::execute (this=0x7fdc7c012be8, thd=0x7fdc7c000b00) at /data/src/10.2/sql/sql_alter.cc:324
      		 
      #17 0x000055fe172a8c57 in mysql_execute_command (thd=0x7fdc7c000b00) at /data/src/10.2/sql/sql_parse.cc:6208
      		 
      #18 0x000055fe172ad5d1 in mysql_parse (thd=0x7fdc7c000b00, rawbuf=0x7fdc7c0124f8 "ALTER TABLE t1 FORCE", length=20, parser_state=0x7fdcd44e1200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7902
      		 
      #19 0x000055fe1729b4f1 in dispatch_command (command=COM_QUERY, thd=0x7fdc7c000b00, packet=0x7fdc7c008951 "ALTER TABLE t1 FORCE", packet_length=20, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1806
      		 
      #20 0x000055fe17299e54 in do_command (thd=0x7fdc7c000b00) at /data/src/10.2/sql/sql_parse.cc:1360
      		 
      #21 0x000055fe173e8646 in do_handle_one_connection (connect=0x55fe19bc8250) at /data/src/10.2/sql/sql_connect.cc:1335
      		 
      #22 0x000055fe173e83d3 in handle_one_connection (arg=0x55fe19bc8250) at /data/src/10.2/sql/sql_connect.cc:1241
      		 
      #23 0x000055fe178081f8 in pfs_spawn_thread (arg=0x55fe19bd27c0) at /data/src/10.2/storage/perfschema/pfs.cc:1862
      		 
      #24 0x00007fdcddd4c494 in start_thread (arg=0x7fdcd44e2700) at pthread_create.c:333
      		 
      #25 0x00007fdcdc13293f in clone () from /lib/x86_64-linux-gnu/libc.so.6

      Also reproducible on 10.0, 10.1. Could not reproduce on 5.5, 10.3, MySQL 5.6.

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-14693 XA: Assertion `!clust_index->online_log' failed in rollback_inplace_alter_table

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15490 XA: ASAN heap-use-after-free or valgrind Invalid write in trx_update_mod_tables_timestamp

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15518 XA: Server crash or ASAN heap-use-after-free in ha_innobase::delete_table

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15533 Assertion `log->blobs' failed in row_log_table_apply_update

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-22924 Warning InnoDB: Index 'Marvão_idx3' contains 36 entries, should be 37.

          • Blocker - Blocks development and/or testing work, production could not run.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-24225 Long semaphore wait in dict0dict.cc line 943 and semaphore wait >600 sec kill

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-24324 Having an active XA transaction in THD:cleanup will release MDL locks too early.

          • Major - Major loss of function.
          • Open

          Task - A task that needs to be done. MDEV-742 LP:803649 - Xa recovery failed on client disconnection

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-22076 InnoDB: Failing assertion: !cursor->index->is_committed() or Assertion `0' in row_purge_remove_sec_if_poss_leaf after DML/DDL with XA

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            View 4 older comments
            elenst Elena Stepanova added a comment -

            There is also a curious variation of a failure on the non-debug build. I consider it a "garbage in, garbage out" situation and won't report separately, but will add it here for the record.

            Very non-deterministic test case, run with high value of --repeat (hundreds, thousands):

            --source include/have_innodb.inc
            		 
             
            		 
            CREATE TABLE t1 (a INT) ENGINE=InnoDB;
            		 
            INSERT INTO t1 VALUES (NULL);
            		 
            XA BEGIN 'x';
            		 
            UPDATE t1 SET a = 1;
            		 
             
            		 
            --connect (con1,localhost,root,,test)
            		 
            --send
            		 
              ALTER TABLE t1 ADD COLUMN extra INT;
            		 
             
            		 
            --connection default
            		 
            INSERT INTO t1 (a) VALUES (2);
            		 
            --error ER_XAER_RMFAIL
            		 
            ROLLBACK;
            		 
            DELETE FROM t1;
            		 
            INSERT INTO t1 (a) VALUES (2);
            		 
            XA END 'x';
            		 
            XA ROLLBACK 'x';
            		 
            DROP TABLE t1;
            		 
             
            		 
            --connection con1
            		 
            --error 0,ER_DUP_ENTRY
            		 
            --reap
            		 
             
            		 
            # Cleanup
            		 
            --disconnect con1

            10.2 5f1ec5cb non-debug

            		 
            #3  <signal handler called>
            		 
            #4  Field::is_null (row_offset=0, this=0x6) at /data/src/10.2/sql/field.h:1134
            		 
            #5  field_unpack (to=to@entry=0x7fa102f999a0, field=0x6, rec=0x7fa0b4059bf0 "\375\001", max_length=3, prefix_key=false) at /data/src/10.2/sql/key.cc:363
            		 
            #6  0x0000558d590645e5 in key_unpack (to=to@entry=0x7fa102f999a0, table=table@entry=0x7fa0b40da7b8, key=key@entry=0x7fa0b4010498) at /data/src/10.2/sql/key.cc:442
            		 
            #7  0x0000558d58fa95e5 in print_keydup_error (table=table@entry=0x7fa0b40da7b8, key=0x7fa0b4010498, msg=0x558d5964d620 "Duplicate entry '%-.64T' for key '%-.192s'", errflag=errflag@entry=0) at /data/src/10.2/sql/handler.cc:3473
            		 
            #8  0x0000558d58fa9725 in print_keydup_error (table=table@entry=0x7fa0b40da7b8, key=<optimized out>, errflag=errflag@entry=0) at /data/src/10.2/sql/handler.cc:3495
            		 
            #9  0x0000558d5913fb49 in alter_rebuild_apply_log (altered_table=0x7fa0b40da7b8, ha_alter_info=0x7fa102f9b400, ctx=0x7fa0b4010680, this=<optimized out>) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:8142
            		 
            #10 ha_innobase::commit_inplace_alter_table (this=0x7fa0b8049f50, altered_table=0x7fa0b40da7b8, ha_alter_info=0x7fa102f9b400, commit=<optimized out>) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:8316
            		 
            #11 0x0000558d58d3b6e6 in mysql_inplace_alter_table (thd=thd@entry=0x7fa0b40009a8, table_list=0x7fa0b400f2f0, table=table@entry=0x7fa0b8051be8, altered_table=altered_table@entry=0x7fa0b40da7b8, ha_alter_info=ha_alter_info@entry=0x7fa102f9b400, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, alter_ctx=0x7fa102f9bc60, target_mdl_request=0x7fa102f9b490) at /data/src/10.2/sql/sql_table.cc:7480
            		 
            #12 0x0000558d58e92231 in mysql_alter_table (thd=thd@entry=0x7fa0b40009a8, new_db=<optimized out>, new_name=<optimized out>, create_info=create_info@entry=0x7fa102f9c860, table_list=<optimized out>, table_list@entry=0x7fa0b400f2f0, alter_info=alter_info@entry=0x7fa102f9c7b0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9622
            		 
            #13 0x0000558d58ede2d4 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x7fa0b40009a8) at /data/src/10.2/sql/sql_alter.cc:333
            		 
            #14 0x0000558d58e0444a in mysql_execute_command (thd=thd@entry=0x7fa0b40009a8) at /data/src/10.2/sql/sql_parse.cc:5964
            		 
            #15 0x0000558d58e0b70e in mysql_parse (thd=thd@entry=0x7fa0b40009a8, rawbuf=<optimized out>, length=35, parser_state=parser_state@entry=0x7fa102f9e620, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:7733
            		 
            #16 0x0000558d58e0dfa0 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fa0b40009a8, packet=packet@entry=0x7fa0b4006d09 "ALTER TABLE t1 ADD COLUMN extra INT", packet_length=packet_length@entry=35, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:1824
            		 
            #17 0x0000558d58e0ed60 in do_command (thd=0x7fa0b40009a8) at /data/src/10.2/sql/sql_parse.cc:1377
            		 
            #18 0x0000558d58edb682 in do_handle_one_connection (connect=connect@entry=0x558d5b7bdec8) at /data/src/10.2/sql/sql_connect.cc:1336
            		 
            #19 0x0000558d58edb7dd in handle_one_connection (arg=arg@entry=0x558d5b7bdec8) at /data/src/10.2/sql/sql_connect.cc:1241
            		 
            #20 0x0000558d5949cf01 in pfs_spawn_thread (arg=0x558d5b755888) at /data/src/10.2/storage/perfschema/pfs.cc:1869
            		 
            #21 0x00007fa10dbd34a4 in start_thread (arg=0x7fa102f9f700) at pthread_create.c:456
            		 
            #22 0x00007fa10cc51d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

            elenst Elena Stepanova added a comment - There is also a curious variation of a failure on the non-debug build. I consider it a "garbage in, garbage out" situation and won't report separately, but will add it here for the record. Very non-deterministic test case, run with high value of --repeat (hundreds, thousands): --source include/have_innodb.inc   CREATE TABLE t1 (a INT ) ENGINE=InnoDB; INSERT INTO t1 VALUES ( NULL ); XA BEGIN 'x' ; UPDATE t1 SET a = 1;   --connect (con1,localhost,root,,test) --send ALTER TABLE t1 ADD COLUMN extra INT ;   --connection default INSERT INTO t1 (a) VALUES (2); --error ER_XAER_RMFAIL ROLLBACK ; DELETE FROM t1; INSERT INTO t1 (a) VALUES (2); XA END 'x' ; XA ROLLBACK 'x' ; DROP TABLE t1;   --connection con1 --error 0,ER_DUP_ENTRY --reap   # Cleanup --disconnect con1 10.2 5f1ec5cb non-debug #3 <signal handler called> #4 Field::is_null (row_offset=0, this=0x6) at /data/src/10.2/sql/field.h:1134 #5 field_unpack (to=to@entry=0x7fa102f999a0, field=0x6, rec=0x7fa0b4059bf0 "\375\001", max_length=3, prefix_key=false) at /data/src/10.2/sql/key.cc:363 #6 0x0000558d590645e5 in key_unpack (to=to@entry=0x7fa102f999a0, table=table@entry=0x7fa0b40da7b8, key=key@entry=0x7fa0b4010498) at /data/src/10.2/sql/key.cc:442 #7 0x0000558d58fa95e5 in print_keydup_error (table=table@entry=0x7fa0b40da7b8, key=0x7fa0b4010498, msg=0x558d5964d620 "Duplicate entry '%-.64T' for key '%-.192s'", errflag=errflag@entry=0) at /data/src/10.2/sql/handler.cc:3473 #8 0x0000558d58fa9725 in print_keydup_error (table=table@entry=0x7fa0b40da7b8, key=<optimized out>, errflag=errflag@entry=0) at /data/src/10.2/sql/handler.cc:3495 #9 0x0000558d5913fb49 in alter_rebuild_apply_log (altered_table=0x7fa0b40da7b8, ha_alter_info=0x7fa102f9b400, ctx=0x7fa0b4010680, this=<optimized out>) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:8142 #10 ha_innobase::commit_inplace_alter_table (this=0x7fa0b8049f50, altered_table=0x7fa0b40da7b8, ha_alter_info=0x7fa102f9b400, commit=<optimized out>) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:8316 #11 0x0000558d58d3b6e6 in mysql_inplace_alter_table (thd=thd@entry=0x7fa0b40009a8, table_list=0x7fa0b400f2f0, table=table@entry=0x7fa0b8051be8, altered_table=altered_table@entry=0x7fa0b40da7b8, ha_alter_info=ha_alter_info@entry=0x7fa102f9b400, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, alter_ctx=0x7fa102f9bc60, target_mdl_request=0x7fa102f9b490) at /data/src/10.2/sql/sql_table.cc:7480 #12 0x0000558d58e92231 in mysql_alter_table (thd=thd@entry=0x7fa0b40009a8, new_db=<optimized out>, new_name=<optimized out>, create_info=create_info@entry=0x7fa102f9c860, table_list=<optimized out>, table_list@entry=0x7fa0b400f2f0, alter_info=alter_info@entry=0x7fa102f9c7b0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9622 #13 0x0000558d58ede2d4 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x7fa0b40009a8) at /data/src/10.2/sql/sql_alter.cc:333 #14 0x0000558d58e0444a in mysql_execute_command (thd=thd@entry=0x7fa0b40009a8) at /data/src/10.2/sql/sql_parse.cc:5964 #15 0x0000558d58e0b70e in mysql_parse (thd=thd@entry=0x7fa0b40009a8, rawbuf=<optimized out>, length=35, parser_state=parser_state@entry=0x7fa102f9e620, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:7733 #16 0x0000558d58e0dfa0 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fa0b40009a8, packet=packet@entry=0x7fa0b4006d09 "ALTER TABLE t1 ADD COLUMN extra INT", packet_length=packet_length@entry=35, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:1824 #17 0x0000558d58e0ed60 in do_command (thd=0x7fa0b40009a8) at /data/src/10.2/sql/sql_parse.cc:1377 #18 0x0000558d58edb682 in do_handle_one_connection (connect=connect@entry=0x558d5b7bdec8) at /data/src/10.2/sql/sql_connect.cc:1336 #19 0x0000558d58edb7dd in handle_one_connection (arg=arg@entry=0x558d5b7bdec8) at /data/src/10.2/sql/sql_connect.cc:1241 #20 0x0000558d5949cf01 in pfs_spawn_thread (arg=0x558d5b755888) at /data/src/10.2/storage/perfschema/pfs.cc:1869 #21 0x00007fa10dbd34a4 in start_thread (arg=0x7fa102f9f700) at pthread_create.c:456 #22 0x00007fa10cc51d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
            Roel Roel Van de Paar added a comment -

            Please check MDEV-24225 (uses the SQL from one of the testcases in a new way) if it is related.

            Roel Roel Van de Paar added a comment - Please check MDEV-24225 (uses the SQL from one of the testcases in a new way) if it is related.
            monty Michael Widenius added a comment -

            The reason for the failure is that thd->mdl_context.release_transactional_locks() was called after commit & rollback even in cases where the current transaction is still active.
            I have now created a fix, it's now tested by buildbot in bb-10.2-monty and in review by Serg

            monty Michael Widenius added a comment - The reason for the failure is that thd->mdl_context.release_transactional_locks() was called after commit & rollback even in cases where the current transaction is still active. I have now created a fix, it's now tested by buildbot in bb-10.2-monty and in review by Serg
            monty Michael Widenius added a comment -

            Please take a look at 2aae278aadae191cfee930a69a2ec00af9606ec4

            monty Michael Widenius added a comment - Please take a look at 2aae278aadae191cfee930a69a2ec00af9606ec4
            monty Michael Widenius added a comment -

            The reason for the failure is that thd->mdl_context.release_transactional_locks()
            was called after commit & rollback even in cases where the current transaction is still active.

            For 10.2, 10.3 and 10.4 the fix is simple:

            • Replace all calls to thd->mdl_context.release_transactional_locks() with
              thd->release_transactional_locks(). The thd function will only call
              the mdl_context function if there are no active transactional locks.
              In 10.6 we will better fix where we will change the return value for
              some trans_xxx() functions to indicate if transaction did close the
              transaction or not. This will avoid the need of the indirect call.

            In addition I have pushed a related fix in 10.4 to avoid a problem with the trans_xa_detach()

            monty Michael Widenius added a comment - The reason for the failure is that thd->mdl_context.release_transactional_locks() was called after commit & rollback even in cases where the current transaction is still active. For 10.2, 10.3 and 10.4 the fix is simple: Replace all calls to thd->mdl_context.release_transactional_locks() with thd->release_transactional_locks(). The thd function will only call the mdl_context function if there are no active transactional locks. In 10.6 we will better fix where we will change the return value for some trans_xxx() functions to indicate if transaction did close the transaction or not. This will avoid the need of the indirect call. In addition I have pushed a related fix in 10.4 to avoid a problem with the trans_xa_detach()

            People

              monty Michael Widenius
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              9 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.