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

Unexpected ER_ERROR_DURING_COMMIT or assertion failure in innobase_xa_prepare

Details

    Description

      The test case is almost the same as in MDEV-36101, only SBR is additionally enabled.
      Earlier the behavior was the same as in MDEV-36101: a debug assertion failure in diagnostics area, and no obvious problem on a release build. But starting from this commit in 10.11.11 and higher versions

      commit ddd7d5d8e34c3edd7ebf4790eec2c4e4d9141e94
      		 
      Author: Marko Mäkelä
      		 
      Date:   Thu Dec 12 18:02:00 2024 +0200
      		 
       
      		 
          MDEV-24035 Failing assertion: UT_LIST_GET_LEN(lock.trx_locks) == 0 causing disruption and replication failure

      a non-debug build started returning an error (and a debug assertion also changed). So, at least for a release build it's a regression, although given the combination of features involved into the test case, I don't see it as a blocker.

      --source include/have_binlog_format_statement.inc
      		 
      --source include/have_innodb.inc
      		 
       
      		 
      call mtr.add_suppression("Unsafe statement written to the binary log using statement");
      		 
       
      		 
      INSTALL SONAME 'ha_oqgraph';
      		 
      SET innodb_snapshot_isolation= ON;
      		 
       
      		 
      CREATE TABLE oq_backing (origid INT UNSIGNED NOT NULL, destid INT UNSIGNED NOT NULL, PRIMARY KEY (origid, destid), KEY (destid)) ENGINE=InnoDB;
      		 
      CREATE TABLE oq (latch VARCHAR(32) NULL, origid BIGINT UNSIGNED NULL, destid BIGINT UNSIGNED NULL, weight DOUBLE NULL, seq BIGINT UNSIGNED NULL, linkid BIGINT UNSIGNED NULL, KEY (latch, origid, destid) USING HASH, KEY (latch, destid, origid) USING HASH) ENGINE=OQGRAPH data_table='oq_backing' origid='origid' destid='destid';
      		 
      INSERT INTO oq_backing (origid, destid) VALUES (170, 241);
      		 
      XA START 'x';
      		 
      SELECT * FROM oq_backing;
      		 
      --connect (con2,localhost,root,,)
      		 
      INSERT INTO oq_backing (origid, destid) VALUES (23632, 49079);
      		 
      --connection default
      		 
      INSERT IGNORE INTO oq_backing (origid, destid) SELECT origid, destid FROM oq;
      		 
       
      		 
      # Cleanup
      		 
      XA END 'x';
      		 
      XA ROLLBACK 'x';
      		 
      DROP TABLE oq, oq_backing;
      		 
      UNINSTALL SONAME 'ha_oqgraph';

      10.11 43c5d1303f5c7c726db276815c459436110f342f non-debug

      		 
      mysqltest: At line 17: query 'INSERT IGNORE INTO oq_backing (origid, destid) SELECT origid, destid FROM oq' failed: ER_ERROR_DURING_COMMIT (1180): Got error 168 "Unknown (generic) error from engine" during COMMIT

      10.11 43c5d1303f5c7c726db276815c459436110f342f debug

      		 
      mariadbd: /data/bld/10.11-asan/storage/innobase/handler/ha_innodb.cc:17213: int innobase_xa_prepare(handlerton*, THD*, bool): Assertion `"invalid state" == 0' failed.
      		 
      250216 22:57:45 [ERROR] /share8t/bld/10.11-asan/sql/mariadbd got signal 6 ;
      		 
       
      		 
      #9  0x00007f6fffe53eb2 in __GI___assert_fail (assertion=0x564afa466960 "\"invalid state\" == 0", file=0x564afa460600 "/data/bld/10.11-asan/storage/innobase/handler/ha_innodb.cc", line=17213, function=0x564afa4773a0 "int innobase_xa_prepare(handlerton*, THD*, bool)") at ./assert/assert.c:101
      		 
      #10 0x0000564af8a8463a in innobase_xa_prepare (thd=0x62c000200218, prepare_trx=false) at /data/bld/10.11-asan/storage/innobase/handler/ha_innodb.cc:17213
      		 
      #11 0x0000564af803878a in prepare_or_error (ht=0x615000002398, thd=0x62c000200218, all=false) at /data/bld/10.11-asan/sql/handler.cc:1450
      		 
      #12 0x0000564af803aad9 in ha_commit_trans (thd=0x62c000200218, all=false) at /data/bld/10.11-asan/sql/handler.cc:1927
      		 
      #13 0x0000564af7c34fb6 in trans_commit_stmt (thd=0x62c000200218) at /data/bld/10.11-asan/sql/transaction.cc:501
      		 
      #14 0x0000564af7743738 in mysql_execute_command (thd=0x62c000200218, is_called_from_prepared_stmt=false) at /data/bld/10.11-asan/sql/sql_parse.cc:6225
      		 
      #15 0x0000564af774fdb2 in mysql_parse (thd=0x62c000200218, rawbuf=0x62d0000b4438 "INSERT IGNORE INTO oq_backing (origid, destid) SELECT origid, destid FROM oq", length=76, parser_state=0x7f6fefce2a80) at /data/bld/10.11-asan/sql/sql_parse.cc:8188
      		 
      #16 0x0000564af77253ea in dispatch_command (command=COM_QUERY, thd=0x62c000200218, packet=0x629000276219 "INSERT IGNORE INTO oq_backing (origid, destid) SELECT origid, destid FROM oq", packet_length=76, blocking=true) at /data/bld/10.11-asan/sql/sql_parse.cc:1905
      		 
      #17 0x0000564af7722117 in do_command (thd=0x62c000200218, blocking=true) at /data/bld/10.11-asan/sql/sql_parse.cc:1418
      		 
      #18 0x0000564af7bed569 in do_handle_one_connection (connect=0x60800001d738, put_in_cache=true) at /data/bld/10.11-asan/sql/sql_connect.cc:1386
      		 
      #19 0x0000564af7bed0c8 in handle_one_connection (arg=0x60800001d6b8) at /data/bld/10.11-asan/sql/sql_connect.cc:1298
      		 
      #20 0x0000564af881c430 in pfs_spawn_thread (arg=0x617000008598) at /data/bld/10.11-asan/storage/perfschema/pfs.cc:2201
      		 
      #21 0x00007f6fffea81c4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
      		 
      #22 0x00007f6ffff2885c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

      Attachments

        Issue Links

          is caused by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-24035 Failing assertion: UT_LIST_GET_LEN(lock.trx_locks) == 0 causing disruption and replication failure

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

          Activity

            marko Marko Mäkelä added a comment -

            The problem appears to be that OQGraph is disregarding the fact that the transaction had been aborted:

            10.11 6e6a1b316ca8df5116613fbe4ca2dc37b3c73bd1

            		 
            #7  0x0000558f42f5dc37 in handler::ha_rnd_next (this=0x7f05bc078118, buf=0x7f05bc078918 "\245\252") at /mariadb/10.11/sql/handler.cc:3538
            		 
            #8  0x00007f05d93cfef6 in oqgraph3::cursor::seek_next (this=0x7f05bc183d80) at /mariadb/10.11/storage/oqgraph/oqgraph_thunk.cc:287
            		 
            #9  0x00007f05d93ceb5f in oqgraph3::edge_iterator::seek (this=0x7f05dace53e0) at /mariadb/10.11/storage/oqgraph/oqgraph_shim.cc:40
            		 
            #10 0x00007f05d93ced0f in oqgraph3::edge_iterator::operator!= (this=0x7f05dace53e0, x=@0x7f05dace53f0: {_graph = {px = 0x7f05bc098040}, _offset = 0xffffffffffffffff})
            		 
                at /mariadb/10.11/storage/oqgraph/oqgraph_shim.cc:71
            		 
            #11 0x00007f05d93ac1e2 in open_query::edges_cursor::fetch_row (this=0x7f05bc07e220, 
                row_info=@0x7f05bc068b40: {latch_indicator = 0x0, orig_indicator = 0x0, dest_indicator = 0x0, weight_indicator = 0x0, seq_indicator = 0x0, link_indicator = 0x0, latch = 0x0, latchStringValue = 0x0, latchStringValueLen = 0x0, orig = 0x0, dest = 0x0, weight = 0, seq = 0x0, link = 0x0}, 
                result=@0x7f05dace54b0: {latch_indicator = 0x0, orig_indicator = 0x0, dest_indicator = 0x0, weight_indicator = 0x0, seq_indicator = 0x0, link_indicator = 0x0, latch = 0x0, latchStringValue = 0x0, latchStringValueLen = 0x0, orig = 0x0, dest = 0x0, weight = 0, seq = 0x0, link = 0x0}) at /mariadb/10.11/storage/oqgraph/graphcore.cc:1172
            		 
            #12 0x00007f05d93ab84f in open_query::oqgraph::fetch_row (this=0x7f05bc068b30, 
                result=@0x7f05dace54b0: {latch_indicator = 0x0, orig_indicator = 0x0, dest_indicator = 0x0, weight_indicator = 0x0, seq_indicator = 0x0, link_indicator = 0x0, latch = 0x0, latchStringValue = 0x0, latchStringValueLen = 0x0, orig = 0x0, dest = 0x0, weight = 0, seq = 0x0, link = 0x0}) at /mariadb/10.11/storage/oqgraph/graphcore.cc:1028
            		 
            #13 0x00007f05d93a573e in ha_oqgraph::rnd_next (this=0x7f05bc075118, buf=0x7f05bc0760a8 <incomplete sequence \361>) at /mariadb/10.11/storage/oqgraph/ha_oqgraph.cc:1097
            		 
            #14 0x0000558f42f5dc37 in handler::ha_rnd_next (this=0x7f05bc075118, buf=0x7f05bc0760a8 <incomplete sequence \361>) at /mariadb/10.11/sql/handler.cc:3538
            		 
            #15 0x0000558f42a500e1 in rr_sequential (info=0x7f05bc018890) at /mariadb/10.11/sql/records.cc:519
            		 
            #16 0x0000558f42a3bd3f in READ_RECORD::read_record (this=0x7f05bc018890) at /mariadb/10.11/sql/records.h:81
            		 
            #17 0x0000558f42c2033e in sub_select (join=0x7f05bc017268, join_tab=0x7f05bc0187b8, end_of_records=0x0) at /mariadb/10.11/sql/sql_select.cc:22943
            		 
            #18 0x0000558f42c1f83c in do_select (join=0x7f05bc017268, procedure=0x0) at /mariadb/10.11/sql/sql_select.cc:22447
            		 
            #19 0x0000558f42bef401 in JOIN::exec_inner (this=0x7f05bc017268) at /mariadb/10.11/sql/sql_select.cc:4974
            		 
            #20 0x0000558f42bee539 in JOIN::exec (this=0x7f05bc017268) at /mariadb/10.11/sql/sql_select.cc:4752
            		 
            #21 0x0000558f42befc80 in mysql_select (thd=0x7f05bc0013f8, tables=0x7f05bc016130, 
                fields=@0x7f05bc015c80: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x7f05bc015fb0, last = 0x7f05bc0160e0, elements = 0x2}, <No data fields>}, conds=0x0, og_num=0x0, order=0x0, group=0x0, 
                having=0x0, proc_param=0x0, select_options=0x220081140b00, result=0x7f05bc0171a8, unit=0x7f05bc0056b8, select_lex=0x7f05bc0159c0) at /mariadb/10.11/sql/sql_select.cc:5232
            		 
            #22 0x0000558f42bde81d in handle_select (thd=0x7f05bc0013f8, lex=0x7f05bc0055e0, result=0x7f05bc0171a8, setup_tables_done_option=0x200000000000) at /mariadb/10.11/sql/sql_select.cc:600
            		 
            #23 0x0000558f42b83e86 in mysql_execute_command (thd=0x7f05bc0013f8, is_called_from_prepared_stmt=0x0) at /mariadb/10.11/sql/sql_parse.cc:4823
            		 
            #24 0x0000558f42b8ee2c in mysql_parse (thd=0x7f05bc0013f8, rawbuf=0x7f05bc014ef0 "INSERT IGNORE INTO oq_backing (origid, destid) SELECT origid, destid FROM oq", length=0x4c, parser_state=0x7f05dace63a0)
            		 
                at /mariadb/10.11/sql/sql_parse.cc:8188

            The error HA_ERR_RECORD_CHANGED=123 is being correctly propagated up to oqgraph3::edge_iterator::seek(). That function will return true, and open_query::edges_cursor::fetch_row() will wrongly return 0, instead of an error code.

            InnoDB is only the messenger here. Before MDEV-24035 introduced the consistency check, this test case was executing in garbage/in-garbage/out mode. A similar error should also be possible if a deadlock or lock wait timeout occurred during the locking read of the INSERT…SELECT statement.

            marko Marko Mäkelä added a comment - The problem appears to be that OQGraph is disregarding the fact that the transaction had been aborted: 10.11 6e6a1b316ca8df5116613fbe4ca2dc37b3c73bd1 #7 0x0000558f42f5dc37 in handler::ha_rnd_next (this=0x7f05bc078118, buf=0x7f05bc078918 "\245\252") at /mariadb/10.11/sql/handler.cc:3538 #8 0x00007f05d93cfef6 in oqgraph3::cursor::seek_next (this=0x7f05bc183d80) at /mariadb/10.11/storage/oqgraph/oqgraph_thunk.cc:287 #9 0x00007f05d93ceb5f in oqgraph3::edge_iterator::seek (this=0x7f05dace53e0) at /mariadb/10.11/storage/oqgraph/oqgraph_shim.cc:40 #10 0x00007f05d93ced0f in oqgraph3::edge_iterator::operator!= (this=0x7f05dace53e0, x=@0x7f05dace53f0: {_graph = {px = 0x7f05bc098040}, _offset = 0xffffffffffffffff}) at /mariadb/10.11/storage/oqgraph/oqgraph_shim.cc:71 #11 0x00007f05d93ac1e2 in open_query::edges_cursor::fetch_row (this=0x7f05bc07e220, row_info=@0x7f05bc068b40: {latch_indicator = 0x0, orig_indicator = 0x0, dest_indicator = 0x0, weight_indicator = 0x0, seq_indicator = 0x0, link_indicator = 0x0, latch = 0x0, latchStringValue = 0x0, latchStringValueLen = 0x0, orig = 0x0, dest = 0x0, weight = 0, seq = 0x0, link = 0x0}, result=@0x7f05dace54b0: {latch_indicator = 0x0, orig_indicator = 0x0, dest_indicator = 0x0, weight_indicator = 0x0, seq_indicator = 0x0, link_indicator = 0x0, latch = 0x0, latchStringValue = 0x0, latchStringValueLen = 0x0, orig = 0x0, dest = 0x0, weight = 0, seq = 0x0, link = 0x0}) at /mariadb/10.11/storage/oqgraph/graphcore.cc:1172 #12 0x00007f05d93ab84f in open_query::oqgraph::fetch_row (this=0x7f05bc068b30, result=@0x7f05dace54b0: {latch_indicator = 0x0, orig_indicator = 0x0, dest_indicator = 0x0, weight_indicator = 0x0, seq_indicator = 0x0, link_indicator = 0x0, latch = 0x0, latchStringValue = 0x0, latchStringValueLen = 0x0, orig = 0x0, dest = 0x0, weight = 0, seq = 0x0, link = 0x0}) at /mariadb/10.11/storage/oqgraph/graphcore.cc:1028 #13 0x00007f05d93a573e in ha_oqgraph::rnd_next (this=0x7f05bc075118, buf=0x7f05bc0760a8 <incomplete sequence \361>) at /mariadb/10.11/storage/oqgraph/ha_oqgraph.cc:1097 #14 0x0000558f42f5dc37 in handler::ha_rnd_next (this=0x7f05bc075118, buf=0x7f05bc0760a8 <incomplete sequence \361>) at /mariadb/10.11/sql/handler.cc:3538 #15 0x0000558f42a500e1 in rr_sequential (info=0x7f05bc018890) at /mariadb/10.11/sql/records.cc:519 #16 0x0000558f42a3bd3f in READ_RECORD::read_record (this=0x7f05bc018890) at /mariadb/10.11/sql/records.h:81 #17 0x0000558f42c2033e in sub_select (join=0x7f05bc017268, join_tab=0x7f05bc0187b8, end_of_records=0x0) at /mariadb/10.11/sql/sql_select.cc:22943 #18 0x0000558f42c1f83c in do_select (join=0x7f05bc017268, procedure=0x0) at /mariadb/10.11/sql/sql_select.cc:22447 #19 0x0000558f42bef401 in JOIN::exec_inner (this=0x7f05bc017268) at /mariadb/10.11/sql/sql_select.cc:4974 #20 0x0000558f42bee539 in JOIN::exec (this=0x7f05bc017268) at /mariadb/10.11/sql/sql_select.cc:4752 #21 0x0000558f42befc80 in mysql_select (thd=0x7f05bc0013f8, tables=0x7f05bc016130, fields=@0x7f05bc015c80: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x7f05bc015fb0, last = 0x7f05bc0160e0, elements = 0x2}, <No data fields>}, conds=0x0, og_num=0x0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=0x220081140b00, result=0x7f05bc0171a8, unit=0x7f05bc0056b8, select_lex=0x7f05bc0159c0) at /mariadb/10.11/sql/sql_select.cc:5232 #22 0x0000558f42bde81d in handle_select (thd=0x7f05bc0013f8, lex=0x7f05bc0055e0, result=0x7f05bc0171a8, setup_tables_done_option=0x200000000000) at /mariadb/10.11/sql/sql_select.cc:600 #23 0x0000558f42b83e86 in mysql_execute_command (thd=0x7f05bc0013f8, is_called_from_prepared_stmt=0x0) at /mariadb/10.11/sql/sql_parse.cc:4823 #24 0x0000558f42b8ee2c in mysql_parse (thd=0x7f05bc0013f8, rawbuf=0x7f05bc014ef0 "INSERT IGNORE INTO oq_backing (origid, destid) SELECT origid, destid FROM oq", length=0x4c, parser_state=0x7f05dace63a0) at /mariadb/10.11/sql/sql_parse.cc:8188 The error HA_ERR_RECORD_CHANGED=123 is being correctly propagated up to oqgraph3::edge_iterator::seek() . That function will return true , and open_query::edges_cursor::fetch_row() will wrongly return 0, instead of an error code. InnoDB is only the messenger here. Before MDEV-24035 introduced the consistency check, this test case was executing in garbage/in-garbage/out mode. A similar error should also be possible if a deadlock or lock wait timeout occurred during the locking read of the INSERT…SELECT statement.

            People

              Unassigned Unassigned
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

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