[MDEV-22338] Assertion `!current_stmt_is_commit || !rgi->tables_to_lock' failed in Query_log_event::do_apply_event Created: 2020-04-22  Updated: 2023-04-27

Status: Stalled
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.4, 10.5

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Brandon Nesterenko
Resolution: Unresolved Votes: 0
Labels: None

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

 Description    

mysqld: /10.2/sql/log_event.cc:5144: int Query_log_event::do_apply_event(rpl_group_info*, const char*, uint32): Assertion `!current_stmt_is_commit || !rgi->tables_to_lock' failed.
 
200724 13:14:41 [ERROR] mysqld got signal 6 ;
 
 
 
Server version: 10.2.33-MariaDB-debug-log
 
 
 
linux/raise.c:51(__GI_raise)[0x7f82824f87bb]
 
stdlib/abort.c:81(__GI_abort)[0x7f82824e3535]
 
intl/loadmsgcat.c:1177(_nl_load_domain)[0x7f82824e340f]
 
/lib/x86_64-linux-gnu/libc.so.6(+0x30102)[0x7f82824f1102]
 
sql/log_event.cc:5145(Query_log_event::do_apply_event(rpl_group_info*, char const*, unsigned int))[0x55dab3df36ee]
 
sql/log_event.cc:5040(Query_log_event::do_apply_event(rpl_group_info*))[0x55dab3df3325]
 
sql/log_event.h:1452(Log_event::apply_event(rpl_group_info*))[0x55dab39a97d3]
 
sql/slave.cc:3567(apply_event_and_update_pos_apply(Log_event*, THD*, rpl_group_info*, int))[0x55dab399e6d5]
 
sql/slave.cc:3763(apply_event_and_update_pos_for_parallel(Log_event*, THD*, rpl_group_info*))[0x55dab399eced]
 
sql/rpl_parallel.cc:50(rpt_handle_event(rpl_parallel_thread::queued_event*, rpl_parallel_thread*))[0x55dab3c1b60a]
 
sql/rpl_parallel.cc:1316(handle_rpl_parallel_thread)[0x55dab3c1e6b5]
 
nptl/pthread_create.c:487(start_thread)[0x7f8282c36fa3]
 
x86_64/clone.S:97(clone)[0x7f82825ba4cf]

Datadir from master and slave attached.
The assertion is reproducible on 10.5 30c9833751529d4039 (I haven't checked versions before 10.5 yet). To reproduce I started slave with (default cnf+ --slave-skip-errors=all) and then pointed it in binlog from master, where the problem occurred :

 change master to master_host='localhost', master_port=3306, master_user='root', MASTER_LOG_FILE='mysql-bin.000001', MASTER_LOG_POS=1728186; start slave;



 Comments   
Comment by Sujatha Sivakumar (Inactive) [ 2020-06-19 ]

Hello alice,

Please assign this issue back to me along with simplified set of queries.

Thank you.

Comment by Alice Sherepa [ 2020-07-28 ] 

--source include/have_innodb.inc
 
--source include/have_binlog_format_mixed_or_row.inc
 
--source include/master-slave.inc
 
 
CREATE TABLE t1 (id int) engine=innodb;
 
CREATE TABLE t2 (id int) engine=myisam;
 
CREATE TRIGGER t2 BEFORE INSERT ON t2 FOR EACH ROW DELETE FROM t1 LIMIT 1;
 
INSERT INTO t2 VALUES (1);
 
 
 
--sync_slave_with_master
 
 
# Cleanup
 
--connection master
 
DROP TABLE t1,t2;
 
--source include/rpl_end.inc

10.1 29851b677ebbd954278d5530

 
 
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#5  0x00007faed09b8535 in __GI_abort () at abort.c:79
 
#6  0x00007faed09b840f in __assert_fail_base (fmt=0x7faed0b1aee0 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55f79acc1fc8 "!current_stmt_is_commit || !rgi->tables_to_lock", file=0x55f79acbfff0 "/10.1/sql/log_event.cc", line=4332, function=<optimized out>) at assert.c:92
 
#7  0x00007faed09c6102 in __GI___assert_fail (assertion=0x55f79acc1fc8 "!current_stmt_is_commit || !rgi->tables_to_lock", file=0x55f79acbfff0 "/10.1/sql/log_event.cc", line=4332, function=0x55f79acc51e0 <Query_log_event::do_apply_event(rpl_group_info*, char const*, unsigned int)::__PRETTY_FUNCTION__> "int Query_log_event::do_apply_event(rpl_group_info*, const char*, uint32)") at assert.c:101
 
#8  0x000055f79a58ea63 in Query_log_event::do_apply_event (this=0x7faeb8474070, rgi=0x7faeb8404000, query_arg=0x7faeb842897b "COMMIT", q_len_arg=6) at /10.1/sql/log_event.cc:4332
 
#9  0x000055f79a58e691 in Query_log_event::do_apply_event (this=0x7faeb8474070, rgi=0x7faeb8404000) at /10.1/sql/log_event.cc:4226
 
#10 0x000055f79a1b6a01 in Log_event::apply_event (this=0x7faeb8474070, rgi=0x7faeb8404000) at /10.1/sql/log_event.h:1343
 
#11 0x000055f79a1ac44a in apply_event_and_update_pos_apply (ev=0x7faeb8474070, thd=0x7faeb8418130, rgi=0x7faeb8404000, reason=0) at /10.1/sql/slave.cc:3482
 
#12 0x000055f79a1ac820 in apply_event_and_update_pos (ev=0x7faeb8474070, thd=0x7faeb8418130, rgi=0x7faeb8404000) at /10.1/sql/slave.cc:3603
 
#13 0x000055f79a1ace7d in exec_relay_log_event (thd=0x7faeb8418130, rli=0x7faec9c3ead0, serial_rgi=0x7faeb8404000) at /10.1/sql/slave.cc:3884
 
#14 0x000055f79a1b0013 in handle_slave_sql (arg=0x7faec9c3ce00) at /10.1/sql/slave.cc:4987
 
#15 0x000055f79a7ae252 in pfs_spawn_thread (arg=0x7faeb9214070) at /10.1/storage/perfschema/pfs.cc:1868
 
#16 0x00007faed13cafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#17 0x00007faed0a8f4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Sujatha Sivakumar (Inactive) [ 2020-08-06 ]

Test case to reproduce the issue on 10.5:

--source include/have_innodb.inc
 
--source include/have_binlog_format_mixed.inc
 
--source include/master-slave.inc
 
 
 
CREATE TABLE t1(f INT) ENGINE=innodb;
 
CREATE VIEW v_t1 AS SELECT * FROM t1;
 
CREATE TABLE tm(f INT) ENGINE=MYISAM;
 
CREATE TABLE t2(id INT AUTO_INCREMENT, i INT, PRIMARY KEY (id)) ENGINE=INNODB;
 
CREATE TABLE t3(f INT) ENGINE=MYISAM;
 
CREATE TRIGGER trig1 BEFORE INSERT ON tm FOR EACH ROW INSERT INTO t2(i) SELECT * FROM t3 LIMIT 0; 
 
 
BEGIN;
 
DELETE FROM v_t1 WHERE f=0;
 
INSERT INTO tm VALUES (2);
 
COMMIT;
 
--sync_slave_with_master
 
 
 
--connection master
 
DROP TABLE t1,t2,t3,tm;
 
 
 
--source incude/rpl_end.inc

Problematic Binlog Output:
======================

#200806 15:12:46 server id 1  end_log_pos 2107 CRC32 0x8191997a 	GTID 0-1-9 trans
 
/*!100001 SET @@session.gtid_seq_no=9*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 2107
 
#200806 15:12:46 server id 1  end_log_pos 2200 CRC32 0x07386b19 	Query	thread_id=9	exec_time=0	error_code=0
 
SET TIMESTAMP=1596706966/*!*/;
 
DELETE FROM v_t1 WHERE f=0
 
/*!*/;
 
# at 2200
 
#200806 15:12:46 server id 1  end_log_pos 2246 CRC32 0x95b8e22b 	Table_map: `test`.`t2` mapped to number 38
 
# at 2246
 
#200806 15:12:46 server id 1  end_log_pos 2319 CRC32 0x1c05f94d 	Query	thread_id=9	exec_time=0	error_code=0
 
SET TIMESTAMP=1596706966/*!*/;
 
COMMIT
 
/*!*/;
 
DELIMITER ;

Issue:
=====
Table map event is not followed by a row event. (MDEV-8203).

Assert stack:
==========

Thread 1 (Thread 0x7fc04822e700 (LWP 10333)):
 
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x00005600fac6aa79 in my_write_core (sig=6) at /home/sujatha/bug_repo/MDEV-22338-10.5/mysys/stacktrace.c:518
 
#2  0x00005600fa31082e in handle_fatal_signal (sig=6) at /home/sujatha/bug_repo/MDEV-22338-10.5/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x00007fc0500178b1 in __GI_abort () at abort.c:79
 
#6  0x00007fc05000742a in __assert_fail_base (fmt=0x7fc05018ea38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x5600fb05ba10 "!current_stmt_is_commit || !rgi->tables_to_lock", file=file@entry=0x5600fb05aaf8 "/home/sujatha/bug_repo/MDEV-22338-10.5/sql/log_event_server.cc", line=line@entry=1667, function=function@entry=0x5600fb05ebc0 <Query_log_event::do_apply_event(rpl_group_info*, char const*, unsigned int)::__PRETTY_FUNCTION__> "int Query_log_event::do_apply_event(rpl_group_info*, const char*, uint32)") at assert.c:92
 
#7  0x00007fc0500074a2 in __GI___assert_fail (assertion=0x5600fb05ba10 "!current_stmt_is_commit || !rgi->tables_to_lock", file=0x5600fb05aaf8 "/home/sujatha/bug_repo/MDEV-22338-10.5/sql/log_event_server.cc", line=1667, function=0x5600fb05ebc0 <Query_log_event::do_apply_event(rpl_group_info*, char const*, unsigned int)::__PRETTY_FUNCTION__> "int Query_log_event::do_apply_event(rpl_group_info*, const char*, uint32)") at assert.c:101
 
#8  0x00005600fa476335 in Query_log_event::do_apply_event (this=0x7fc00802c4d8, rgi=0x7fc008000cf0, query_arg=0x7fc0089772c3 "COMMIT", q_len_arg=6) at /home/sujatha/bug_repo/MDEV-22338-10.5/sql/log_event_server.cc:1667
 
#9  0x00005600fa475f11 in Query_log_event::do_apply_event (this=0x7fc00802c4d8, rgi=0x7fc008000cf0) at /home/sujatha/bug_repo/MDEV-22338-10.5/sql/log_event_server.cc:1561
 
#10 0x00005600f9ebe845 in Log_event::apply_event (this=0x7fc00802c4d8, rgi=0x7fc008000cf0) at /home/sujatha/bug_repo/MDEV-22338-10.5/sql/log_event.h:1496
 
#11 0x00005600f9eb13a0 in apply_event_and_update_pos_apply (ev=0x7fc00802c4d8, thd=0x7fc008001a48, rgi=0x7fc008000cf0, reason=0) at /home/sujatha/bug_repo/MDEV-22338-10.5/sql/slave.cc:4003
 
#12 0x00005600f9eb1975 in apply_event_and_update_pos (ev=0x7fc00802c4d8, thd=0x7fc008001a48, rgi=0x7fc008000cf0) at /home/sujatha/bug_repo/MDEV-22338-10.5/sql/slave.cc:4165
 
#13 0x00005600f9eb2316 in exec_relay_log_event (thd=0x7fc008001a48, rli=0x5600fe73f328, serial_rgi=0x7fc008000cf0) at /home/sujatha/bug_repo/MDEV-22338-10.5/sql/slave.cc:4486
 
#14 0x00005600f9eb5c58 in handle_slave_sql (arg=0x5600fe73d660) at /home/sujatha/bug_repo/MDEV-22338-10.5/sql/slave.cc:5659
 
#15 0x00005600fa693cb9 in pfs_spawn_thread (arg=0x7fc01c195e98) at /home/sujatha/bug_repo/MDEV-22338-10.5/storage/perfschema/pfs.cc:2201
 
#16 0x00007fc050f5d6db in start_thread (arg=0x7fc04822e700) at pthread_create.c:463
 
#17 0x00007fc0500f8a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Sujatha Sivakumar (Inactive) [ 2020-08-10 ]

Hello Andrei,

Can you please review the fix for MDEV-22338.

10.1 Patch:
https://github.com/MariaDB/server/commit/0664e1e766d303187b381ace1c53547d1821e35c
Test results: http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.1-sujatha

10.3 Patch:
https://github.com/MariaDB/server/commit/f3b3b2fb542327ce4e799c546acb00f1a35a8df7
Test results: http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.3-sujatha

This issue is a duplicate of MDEV-8203 and the fix was pushed into 10.3+
version. The assert still exists in 10.3+ version in case of mixed mode
replication. The main idea of MDEV-8203 patch is to remember the set of events
written into the cache and ignore/reset the cache content if it has only
Table_Map event. This fix works for row based replication mode but it fails
with mixed based replication as the cache contains a combination of
Query_log_events and Table_Map event. Hence reverted the patch. Following fix
is implemented.

Fix:
====
Replace the assert with if-else check. In a case where TABLE_MAP event is not
followed by rows event invoke 'rows_event_stmt_cleanup' to initiate
appropriate cleanup.

Comment by Andrei Elkin [ 2021-04-22 ]

Directions provided in the last comment.

Generated at Thu Feb 08 09:13:58 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.