[MDEV-19302] Assertion `!current_stmt_is_commit || !rgi->tables_to_lock' failed in Query_log_event::do_apply_event Created: 2019-04-22  Updated: 2020-04-22  Resolved: 2019-06-10

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.4
Fix Version/s: 10.2.24, 10.1.39, 10.3.15, 10.4.5

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sujatha Sivakumar (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-8203 Assertion `!current_stmt_is_commit ||... Closed
relates to MDEV-22338 Assertion `!current_stmt_is_commit ||... Stalled

 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.

 Comments   
Comment by Sujatha Sivakumar (Inactive) [ 2019-06-10 ]

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.

Generated at Thu Feb 08 08:50:36 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.