[MDEV-22915] #2 Assertion `binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES' failed in THD::reset_for_next_command Created: 2020-06-16  Updated: 2021-06-22

Status: Open
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.5, 10.6
Fix Version/s: 10.5

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Michael Widenius
Resolution: Unresolved Votes: 0
Labels: not-10.2, not-10.3, not-10.4

Issue Links:
Relates
relates to MDEV-22048 Assertion `binlog_table_maps == 0 || ... Closed

 Description   

Note: MDEV-22048 is already in the tree, its test case now passes. I am a new one rather than re-opening MDEV-22048 because I'm not sure a fix for it will make it to 10.5.4, and we generally don't want to have separate fixes for the same bug in different release change logs.
Also, I'm not marking it as a regression this time, because according to MDEV-22048 analysis the underlying problem existed before, it surfaced because of the new assertion.

--source include/have_innodb.inc
 
--source include/have_binlog_format_row.inc
 
 
 
--connect (con1,localhost,root,,)
 
CREATE TABLE t1 (a INT) ENGINE=InnoDB;
 
CREATE  TRIGGER tr BEFORE UPDATE ON t1 FOR EACH ROW BEGIN END;
 
LOCK TABLES t1 WRITE;
 
--error ER_TABLE_NOT_LOCKED
 
LOAD DATA INFILE 'x' INTO TABLE x;
 
SET AUTOCOMMIT= OFF;
 
INSERT INTO t1 VALUES (1);
 
SAVEPOINT A;
 
COMMIT;
 
--disconnect con1
 
 
 
--connect (con2,localhost,root,,)
 
SELECT 1;
 
 
 
# Cleanup
 
--disconnect con2
 
--connection default
 
DROP TABLE t1;

10.5 e290e5a7

 
mariadbd: /data/src/10.5/sql/sql_parse.cc:7484: void THD::reset_for_next_command(bool): Assertion `binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES' failed.
 
200616 17:34:45 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f724ccfbf12 in __GI___assert_fail (assertion=0x555b5a16e870 "binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES", file=0x555b5a16d1c0 "/data/src/10.5/sql/sql_parse.cc", line=7484, function=0x555b5a170600 <THD::reset_for_next_command(bool)::__PRETTY_FUNCTION__> "void THD::reset_for_next_command(bool)") at assert.c:101
 
#8  0x0000555b593cd175 in THD::reset_for_next_command (this=0x7f720c000b18, do_clear_error=true) at /data/src/10.5/sql/sql_parse.cc:7483
 
#9  0x0000555b593ce62f in mysql_parse (thd=0x7f720c000b18, rawbuf=0x7f720c0126f0 "SELECT 1", length=8, parser_state=0x7f72421cf520, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7934
 
#10 0x0000555b593babd1 in dispatch_command (command=COM_QUERY, thd=0x7f720c000b18, packet=0x7f720c008749 "SELECT 1", packet_length=8, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1875
 
#11 0x0000555b593b9309 in do_command (thd=0x7f720c000b18) at /data/src/10.5/sql/sql_parse.cc:1356
 
#12 0x0000555b5955e421 in do_handle_one_connection (connect=0x555b5de3be28, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1411
 
#13 0x0000555b5955e189 in handle_one_connection (arg=0x555b5de3be28) at /data/src/10.5/sql/sql_connect.cc:1313
 
#14 0x0000555b59a9888a in pfs_spawn_thread (arg=0x555b5dd1a368) at /data/src/10.5/storage/perfschema/pfs.cc:2201
 
#15 0x00007f724ec844a4 in start_thread (arg=0x7f72421d0700) at pthread_create.c:456
 
#16 0x00007f724cdb8d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

No obvious problem on a non-debug build.

 Comments   
Comment by Roel Van de Paar [ 2021-01-21 ] 

# mysqld options required for replay:  --log-bin
 
SET autocommit = 0;
 
SET sql_mode='';
 
CREATE TABLE t (a INT) ENGINE=InnoDB;
 
CREATE TEMPORARY TABLE t2 (id INT) ENGINE=InnoDB;
 
SELECT * FROM t LIMIT 1;
 
CREATE TRIGGER t BEFORE UPDATE ON t FOR EACH ROW SET @a=1;
 
LOCK TABLES t WRITE CONCURRENT;
 
INSERT INTO t VALUES (1);
 
SAVEPOINT B;
 
BEGIN;
 
SELECT * FROM non_existing;

Leads to:

10.6.0 9118fd360a3da0bba521caf2a35c424968235ac4 (Debug)

 
mysqld: /test/10.6_dbg/sql/sql_parse.cc:7384: void THD::reset_for_next_command(bool): Assertion `binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES' failed.

10.6.0 9118fd360a3da0bba521caf2a35c424968235ac4 (Debug)

 
Core was generated by `/test/MD010121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
[Current thread is 1 (Thread 0x145e24054700 (LWP 3407919))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
#1  0x00005639d3b9e0d7 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424
 
#2  0x00005639d3332ab1 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#5  0x0000145e2451f859 in __GI_abort () at abort.c:79
 
#6  0x0000145e2451f729 in __assert_fail_base (fmt=0x145e246b5588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5639d3d06098 "binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES", file=0x5639d3d05ee8 "/test/10.6_dbg/sql/sql_parse.cc", line=7384, function=<optimized out>) at assert.c:92
 
#7  0x0000145e24530f36 in __GI___assert_fail (assertion=assertion@entry=0x5639d3d06098 "binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES", file=file@entry=0x5639d3d05ee8 "/test/10.6_dbg/sql/sql_parse.cc", line=line@entry=7384, function=function@entry=0x5639d3d06060 "void THD::reset_for_next_command(bool)") at assert.c:101
 
#8  0x00005639d30583bb in THD::reset_for_next_command (this=this@entry=0x145dd4000db8, do_clear_error=do_clear_error@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:7384
 
#9  0x00005639d3059e2b in mysql_parse (thd=thd@entry=0x145dd4000db8, rawbuf=0x145dd40127e0 "SELECT * FROM non_existing", length=26, parser_state=parser_state@entry=0x145e240533d0) at /test/10.6_dbg/sql/sql_parse.cc:7827
 
#10 0x00005639d30681ec in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x145dd4000db8, packet=packet@entry=0x145dd4008e59 "SELECT * FROM non_existing", packet_length=packet_length@entry=26) at /test/10.6_dbg/sql/sql_class.h:1293
 
#11 0x00005639d306b52d in do_command (thd=0x145dd4000db8) at /test/10.6_dbg/sql/sql_parse.cc:1348
 
#12 0x00005639d31c77fc in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5639d61bb688, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
 
#13 0x00005639d31c7f03 in handle_one_connection (arg=arg@entry=0x5639d61bb688) at /test/10.6_dbg/sql/sql_connect.cc:1312
 
#14 0x00005639d367d88f in pfs_spawn_thread (arg=0x5639d6137fe8) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
 
#15 0x0000145e24a2d609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#16 0x0000145e2461c293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.5.9 (dbg), 10.6.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.37 (dbg), 10.2.37 (opt), 10.3.28 (dbg), 10.3.28 (opt), 10.4.18 (dbg), 10.4.18 (opt), 10.5.9 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.50 (dbg), 5.6.50 (opt), 5.7.32 (dbg), 5.7.32 (opt), 8.0.22 (dbg), 8.0.22 (opt)

Comment by Roel Van de Paar [ 2021-06-22 ]

Additional testcase:

# mysqld options required for replay:  --log-bin
 
SET autocommit=0;
 
CREATE TABLE t (a TEXT) ENGINE=InnoDB;
 
CREATE TEMPORARY TABLE tmp (id INT NOT NULL) ENGINE=MEMORY;
 
SELECT * FROM t WHERE c1 IN ('a','a') ORDER BY c1 DESC LIMIT 2;
 
CREATE TRIGGER tr BEFORE UPDATE ON t FOR EACH ROW SET @a:=1;
 
LOCK TABLES t WRITE CONCURRENT;
 
INSERT INTO t VALUES ('a');
 
SAVEPOINT B;
 
BEGIN;
 
SELECT * FROM t_bigint WHERE id IN ('a', 'a');

Leads to:

10.6.2 6c39eaeb126328e7813b146ecf652d51e4508981 (Debug)

 
mysqld: /test/10.6_dbg/sql/sql_parse.cc:7514: void THD::reset_for_next_command(bool): Assertion `binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES' failed.

10.6.2 6c39eaeb126328e7813b146ecf652d51e4508981 (Debug)

 
Core was generated by `/test/MD120621-mariadb-10.6.2-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
[Current thread is 1 (Thread 0x1487fcd70700 (LWP 1918775))]
 
(gdb) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x0000148811c35859 in __GI_abort () at abort.c:79
 
#2  0x0000148811c35729 in __assert_fail_base (fmt=0x148811dcb588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55674c8c9b28 "binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES", file=0x55674c8c9978 "/test/10.6_dbg/sql/sql_parse.cc", line=7514, function=<optimized out>) at assert.c:92
 
#3  0x0000148811c46f36 in __GI___assert_fail (assertion=assertion@entry=0x55674c8c9b28 "binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES", file=file@entry=0x55674c8c9978 "/test/10.6_dbg/sql/sql_parse.cc", line=line@entry=7514, function=function@entry=0x55674c8c9af0 "void THD::reset_for_next_command(bool)") at assert.c:101
 
#4  0x000055674bc19bbb in THD::reset_for_next_command (this=this@entry=0x1487c0000db8, do_clear_error=do_clear_error@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:7514
 
#5  0x000055674bc1b687 in mysql_parse (thd=thd@entry=0x1487c0000db8, rawbuf=0x1487c00140d0 "SELECT * FROM t_bigint WHERE id IN ('a', 'a')", length=45, parser_state=parser_state@entry=0x1487fcd6f400) at /test/10.6_dbg/sql/sql_parse.cc:7962
 
#6  0x000055674bc2a3fa in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1487c0000db8, packet=packet@entry=0x1487c000b889 "SELECT * FROM t_bigint WHERE id IN ('a', 'a')", packet_length=packet_length@entry=45, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_class.h:1340
 
#7  0x000055674bc2d7da in do_command (thd=0x1487c0000db8, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:1406
 
#8  0x000055674bd91c8e in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55674f7b7e58, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
 
#9  0x000055674bd92293 in handle_one_connection (arg=arg@entry=0x55674f7b7e58) at /test/10.6_dbg/sql/sql_connect.cc:1312
 
#10 0x000055674c240166 in pfs_spawn_thread (arg=0x55674f687e28) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
 
#11 0x0000148812143609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#12 0x0000148811d32293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.5.11 (dbg), 10.6.2 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.39 (dbg), 10.2.39 (opt), 10.3.30 (dbg), 10.3.30 (opt), 10.4.20 (dbg), 10.4.20 (opt), 10.5.11 (opt), 10.6.2 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.34 (dbg), 5.7.34 (opt), 8.0.24 (dbg), 8.0.24 (opt)

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