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

Assertion `!current_stmt_is_commit || !rgi->tables_to_lock' failed in Query_log_event::do_apply_event

Details

    Description

      Note: There was a bug report with a similar assertion failure, MDEV-8203. But even thought it's not closed in JIRA, there had been commits for MDEV-8203 in main trees (and hence in change logs) fixing it, and indeed, it's not reproducible any longer with that particular scenario in 10.3+.

      --source include/have_innodb.inc
      		 
      --source include/have_binlog_format_mixed_or_row.inc
      		 
      --source include/master-slave.inc
      		 
       
      		 
      CREATE TABLE t1 (a INT) ENGINE=MyISAM;
      		 
      CREATE TABLE t2 (b INT);
      		 
      CREATE TABLE t3 (c INT) ENGINE=InnoDB;
      		 
      --delimiter $
      		 
      CREATE TRIGGER d AFTER UPDATE ON t1 FOR EACH ROW
      		 
      BEGIN
      		 
        UPDATE t2 SET b = 0 LIMIT 0;
      		 
        INSERT INTO t3 VALUES (NULL);
      		 
        CALL x();
      		 
      END $
      		 
      --delimiter ;
      		 
      INSERT INTO t1 VALUES (1);
      		 
      --error ER_SP_DOES_NOT_EXIST
      		 
      UPDATE t1 SET a = 0;
      		 
       
      		 
      --sync_slave_with_master
      		 
       
      		 
      # Cleanup
      		 
      --connection master
      		 
      DROP TABLE t1, t2, t3;
      		 
      --source include/rpl_end.inc

      10.4 a65d3b2c

      		 
      mysqld: /data/src/10.4/sql/log_event.cc:5479: int Query_log_event::do_apply_event(rpl_group_info*, const char*, uint32): Assertion `!current_stmt_is_commit || !rgi->tables_to_lock' failed.
      		 
      190422 16:00:39 [ERROR] mysqld got signal 6 ;
      		 
       
      		 
      #7  0x00007fae1d785ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
      		 
      #8  0x0000562a574cc884 in Query_log_event::do_apply_event (this=0x7fadb0031040, rgi=0x7fadb0000a90, query_arg=0x7fadb00a4b4b "COMMIT", q_len_arg=6) at /data/src/10.4/sql/log_event.cc:5479
      		 
      #9  0x0000562a574cc4a3 in Query_log_event::do_apply_event (this=0x7fadb0031040, rgi=0x7fadb0000a90) at /data/src/10.4/sql/log_event.cc:5373
      		 
      #10 0x0000562a56f64013 in Log_event::apply_event (this=0x7fadb0031040, rgi=0x7fadb0000a90) at /data/src/10.4/sql/log_event.h:1482
      		 
      #11 0x0000562a56f57620 in apply_event_and_update_pos_apply (ev=0x7fadb0031040, thd=0x7fadb0001560, rgi=0x7fadb0000a90, reason=0) at /data/src/10.4/sql/slave.cc:3953
      		 
      #12 0x0000562a56f57c52 in apply_event_and_update_pos (ev=0x7fadb0031040, thd=0x7fadb0001560, rgi=0x7fadb0000a90) at /data/src/10.4/sql/slave.cc:4107
      		 
      #13 0x0000562a56f5868c in exec_relay_log_event (thd=0x7fadb0001560, rli=0x562a5a2920d8, serial_rgi=0x7fadb0000a90) at /data/src/10.4/sql/slave.cc:4428
      		 
      #14 0x0000562a56f5be6f in handle_slave_sql (arg=0x562a5a290410) at /data/src/10.4/sql/slave.cc:5592
      		 
      #15 0x0000562a575ea2f5 in pfs_spawn_thread (arg=0x7fadc4049160) at /data/src/10.4/storage/perfschema/pfs.cc:1862
      		 
      #16 0x00007fae1f87a494 in start_thread (arg=0x7fae129b3700) at pthread_create.c:333
      		 
      #17 0x00007fae1d84293f in clone () from /lib/x86_64-linux-gnu/libc.so.6

      Not reproducible on 10.3.
      No obvious problems on a non-debug build.

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-8203 Assertion `!current_stmt_is_commit || !rgi->tables_to_lock' failed in Query_log_event::do_apply_event(rpl_group_info*, const char*, uint32)

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-22338 Assertion `!current_stmt_is_commit || !rgi->tables_to_lock' failed in Query_log_event::do_apply_event

          • Major - Major loss of function.
          • Stalled

          Activity

            Ascending order - Click to sort in descending order
            elenst Elena Stepanova created issue -
            elenst Elena Stepanova made changes -
            Field Original Value New Value
            Elkin Andrei Elkin made changes -
            Assignee Andrei Elkin [ elkin ] Sujatha Sivakumar [ sujatha.sivakumar ]
            sujatha.sivakumar Sujatha Sivakumar (Inactive) made changes -
            Status Open [ 1 ] In Progress [ 3 ]
            sujatha.sivakumar Sujatha Sivakumar (Inactive) added a comment - - edited

            This issue is already fixed as part of MDEV:18300's fix.

            Analysis: During the execution of stored procedure the table map event gets
            written twice in the binlog as shown below. Observe that table map event is
            written for INSERT statement as shown below. Because of this additional
            table_map event slave reports an assert.

            ### UPDATE `test`.`t1`
            		 
            ### WHERE
            		 
            ###   @1=1
            		 
            ### SET
            		 
            ###   @1=0
            		 
            # Number of rows: 1
            		 
            # at 1461
            		 
            # at 1512
            		 
            #190610 13:40:01 server id 1  end_log_pos 1512 CRC32 0x047a074c   Annotate_rows:
            		 
            #Q> INSERT INTO t3 VALUES (NULL)
            		 
            #190610 13:40:01 server id 1  end_log_pos 1557 CRC32 0x5213bc91   Table_map: `test`.`t1` mapped to number 33 (has triggers)
            		 
            # at 1557
            		 
            #190610 13:40:01 server id 1  end_log_pos 1602 CRC32 0x42051901   Table_map: `test`.`t2` mapped to number 35
            		 
            # at 1602
            		 
            #190610 13:40:01 server id 1  end_log_pos 1675 CRC32 0x79539423   Query thread_id=14  exec_time=0 error_code=0
            		 
            SET TIMESTAMP=1560154201/*!*/;
            		 
            COMMIT
            		 
            /*!*/;
            		 
            # at 1675
            		 
            #190610 13:40:01 server id 1  end_log_pos 1717 CRC32 0x4d9da44c   GTID 0-1-7 trans
            		 
            /*!100001 SET @@session.gtid_seq_no=7*//*!*/;
            		 
            BEGIN
            		 
            /*!*/;
            		 
            # at 1717
            		 
            #190610 13:40:01 server id 1  end_log_pos 1762 CRC32 0x72308344   Table_map: `test`.`t3` mapped to number 34
            		 
            # at 1762
            		 
            #190610 13:40:01 server id 1  end_log_pos 1807 CRC32 0x974f13e4   Table_map: `test`.`t3` mapped to number 34
            		 
            # at 1807
            		 
            #190610 13:40:01 server id 1  end_log_pos 1841 CRC32 0x9c5e0f41   Write_rows: table id 34 flags: STMT_END_F

            At the time of execution of INSERT statement on the master, code tries to read
            the statistics of the table. Since the statistics are not available, system
            tables are opened for reading stats and then they are closed. During this
            process the pending events get written into binlog and they also clear
            existing table_maps that were prepared during update statement. Hence when
            code reaches a place where it has to write insert into the binary log it finds
            no table maps and re-writes them once again. This leads to an assert on slave.

            As part of MDEV-18300 patch 'read_statistics_for_tables_if_needed' is added
            within "mysql_update" code. Since stats are already calculated during 'update'
            statement execution the following 'insert' doesn't have to recalculate stats
            and table_maps get retained so no additional table_map event is written.
            Binlog is clear.

            Hence closing this issue as fixed.

            sujatha.sivakumar Sujatha Sivakumar (Inactive) added a comment - - edited This issue is already fixed as part of MDEV:18300's fix. Analysis: During the execution of stored procedure the table map event gets written twice in the binlog as shown below. Observe that table map event is written for INSERT statement as shown below. Because of this additional table_map event slave reports an assert. ### UPDATE `test`.`t1` ### WHERE ### @1=1 ### SET ### @1=0 # Number of rows: 1 # at 1461 # at 1512 #190610 13:40:01 server id 1 end_log_pos 1512 CRC32 0x047a074c Annotate_rows: #Q> INSERT INTO t3 VALUES (NULL) #190610 13:40:01 server id 1 end_log_pos 1557 CRC32 0x5213bc91 Table_map: `test`.`t1` mapped to number 33 (has triggers) # at 1557 #190610 13:40:01 server id 1 end_log_pos 1602 CRC32 0x42051901 Table_map: `test`.`t2` mapped to number 35 # at 1602 #190610 13:40:01 server id 1 end_log_pos 1675 CRC32 0x79539423 Query thread_id=14 exec_time=0 error_code=0 SET TIMESTAMP=1560154201/*!*/; COMMIT /*!*/; # at 1675 #190610 13:40:01 server id 1 end_log_pos 1717 CRC32 0x4d9da44c GTID 0-1-7 trans /*!100001 SET @@session.gtid_seq_no=7*//*!*/; BEGIN /*!*/; # at 1717 #190610 13:40:01 server id 1 end_log_pos 1762 CRC32 0x72308344 Table_map: `test`.`t3` mapped to number 34 # at 1762 #190610 13:40:01 server id 1 end_log_pos 1807 CRC32 0x974f13e4 Table_map: `test`.`t3` mapped to number 34 # at 1807 #190610 13:40:01 server id 1 end_log_pos 1841 CRC32 0x9c5e0f41 Write_rows: table id 34 flags: STMT_END_F At the time of execution of INSERT statement on the master, code tries to read the statistics of the table. Since the statistics are not available, system tables are opened for reading stats and then they are closed. During this process the pending events get written into binlog and they also clear existing table_maps that were prepared during update statement. Hence when code reaches a place where it has to write insert into the binary log it finds no table maps and re-writes them once again. This leads to an assert on slave. As part of MDEV-18300 patch 'read_statistics_for_tables_if_needed' is added within "mysql_update" code. Since stats are already calculated during 'update' statement execution the following 'insert' doesn't have to recalculate stats and table_maps get retained so no additional table_map event is written. Binlog is clear. Hence closing this issue as fixed.
            sujatha.sivakumar Sujatha Sivakumar (Inactive) made changes -
            issue.field.resolutiondate 2019-06-10 13:16:53.0 2019-06-10 13:16:53.101
            sujatha.sivakumar Sujatha Sivakumar (Inactive) made changes -
            Fix Version/s 10.4.5 [ 23311 ]
            Fix Version/s 10.3.15 [ 23309 ]
            Fix Version/s 10.2.24 [ 23308 ]
            Fix Version/s 10.1.39 [ 23305 ]
            Fix Version/s 10.4 [ 22408 ]
            Resolution Fixed [ 1 ]
            Status In Progress [ 3 ] Closed [ 6 ]
            alice Alice Sherepa made changes -
            serg Sergei Golubchik made changes -
            Workflow MariaDB v3 [ 96274 ] MariaDB v4 [ 156102 ]

            People

              sujatha.sivakumar Sujatha Sivakumar (Inactive)
              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.