[MDEV-22048] Assertion `binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES' failed in THD::reset_for_next_command Created: 2020-03-26  Updated: 2020-06-16  Resolved: 2020-06-15

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.5.2, 10.5
Fix Version/s: 10.5.4

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: regression

Attachments: File 000099.log    
Issue Links:
Problem/Incident
is caused by MDEV-21605 Clean up and speed up interfaces for ... Closed
Relates
relates to MDEV-22915 #2 Assertion `binlog_table_maps == 0 ... Open
relates to MDEV-21617 Assertion `binlog_table_maps == 0' fa... Closed

 Description   

Update: See the test case and further information in the comments

origin/10.5 718f18599a9bcf1e7c2d3f18416fca4f7124d00d 2020-03-26T16:05:25+02:00
 
debug build with ASAN
 
Assert hit during RQG testing
 
mysqld: sql/sql_parse.cc:7444: void THD::reset_for_next_command(bool): Assertion `binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES' failed.
 
200326 14:50:05 [ERROR] mysqld got signal 6 ;
 
...
 
Query (0x62b0000a1238): SELECT * FROM `table0_innodb_int_autoinc` AS X WHERE X.`col_char_12_key` IN ( 127, 'y', 's', 230, 'n' ) LIMIT 6  /* E_R Thread1 QNO 35521 CON_ID 12 */
 
...
 
Status: NOT_KILLED
 
 
 
Thread 1 (Thread 0x7fa5b53d0300 (LWP 69908)):
 
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055a8b419f774 in my_write_core (sig=6) at mysys/stacktrace.c:518
 
#2  0x000055a8b2c2f7b8 in handle_fatal_signal (sig=6) at sql/signal_handler.cc:325
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x00007fa5d2865801 in __GI_abort () at abort.c:79
 
#6  0x00007fa5d285539a in __assert_fail_base (fmt=0x7fa5d29dc7d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55a8b46346a0 "binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES", file=file@entry=0x55a8b46309e0 "sql/sql_parse.cc", line=line@entry=7444, function=function@entry=0x55a8b4637f00 <THD::reset_for_next_command(bool)::__PRETTY_FUNCTION__> "void THD::reset_for_next_command(bool)") at assert.c:92
 
#7  0x00007fa5d2855412 in __GI___assert_fail (assertion=0x55a8b46346a0 "binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES", file=0x55a8b46309e0 "sql/sql_parse.cc", line=7444, function=0x55a8b4637f00 <THD::reset_for_next_command(bool)::__PRETTY_FUNCTION__> "void THD::reset_for_next_command(bool)") at assert.c:101
 
#8  0x000055a8b2492d74 in THD::reset_for_next_command (this=0x62b00009a218, do_clear_error=true) at sql/sql_parse.cc:7443
 
#9  0x000055a8b2495de0 in mysql_parse (thd=0x62b00009a218, rawbuf=0x62b0000a1238 "SELECT * FROM `table0_innodb_int_autoinc` AS X WHERE X.`col_char_12_key` IN ( 127, 'y', 's', 230, 'n' ) LIMIT 6  /* E_R Thread1 QNO 35521 CON_ID 12 */", length=150, parser_state=0x7fa5b53ce8f0, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:7894
 
#10 0x000055a8b246bce7 in dispatch_command (command=COM_QUERY, thd=0x62b00009a218, packet=0x629000b59219 "SELECT * FROM `table0_innodb_int_autoinc` AS X WHERE X.`col_char_12_key` IN ( 127, 'y', 's', 230, 'n' ) LIMIT 6  /* E_R Thread1 QNO 35521 CON_ID 12 */ ", packet_length=151, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:1839
 
#11 0x000055a8b2468682 in do_command (thd=0x62b00009a218) at sql/sql_parse.cc:1358
 
#12 0x000055a8b288db4d in do_handle_one_connection (connect=0x608000003a38, put_in_cache=true) at sql/sql_connect.cc:1422
 
#13 0x000055a8b288d3e9 in handle_one_connection (arg=0x6080000036b8) at sql/sql_connect.cc:1319
 
#14 0x000055a8b3537f8b in pfs_spawn_thread (arg=0x615000004918) at storage/perfschema/pfs.cc:2201
 
#15 0x00007fa5d37606db in start_thread (arg=0x7fa5b53d0300) at pthread_create.c:463
 
#16 0x00007fa5d294688f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
 
 
Hitting this assert seems to be rare.



 Comments   
Comment by Matthias Leich [ 2020-03-26 ]

000099.log – Log of the RQG run It contains the setup of the RQG test and a full backtrace of all threads.

Comment by Elena Stepanova [ 2020-04-13 ] 

--source include/have_innodb.inc
 
--source include/have_binlog_format_mixed_or_row.inc
 
 
 
CREATE TABLE t1 (a INT) ENGINE=InnoDB;
 
INSERT INTO t1 (a) VALUES (1),(2);
 
 
 
CREATE TABLE t2 (b INT) ENGINE=InnoDB;
 
 
 
CREATE TRIGGER tr1 BEFORE UPDATE ON t1 FOR EACH ROW SET @a = 0;
 
CREATE TRIGGER tr2 BEFORE INSERT ON t2 FOR EACH ROW DELETE FROM t1 LIMIT 1;
 
 
 
SET AUTOCOMMIT= OFF;
 
LOCK TABLES t2 WRITE;
 
DELETE FROM t1 LIMIT 1;
 
SAVEPOINT A;
 
UNLOCK TABLES;
 
DROP TABLE t1, t2;

10.5 8c0b9880

 
mariadbd: /data/src/10.5/sql/sql_parse.cc:7444: void THD::reset_for_next_command(bool): Assertion `binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES' failed.
 
200413 17:59:22 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f989031f102 in __GI___assert_fail (assertion=0x558cd68f2200 "binlog_table_maps == 0 || locked_tables_mode == LTM_LOCK_TABLES", file=0x558cd68ee540 "/data/src/10.5/sql/sql_parse.cc", line=7444, function=0x558cd68f5a60 <THD::reset_for_next_command(bool)::__PRETTY_FUNCTION__> "void THD::reset_for_next_command(bool)") at assert.c:101
 
#8  0x0000558cd48dfb74 in THD::reset_for_next_command (this=0x62b00008c288, do_clear_error=true) at /data/src/10.5/sql/sql_parse.cc:7443
 
#9  0x0000558cd48e2b6f in mysql_parse (thd=0x62b00008c288, rawbuf=0x62b0000932a8 "DROP TABLE t1, t2", length=17, parser_state=0x7f98824a0a50, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7894
 
#10 0x0000558cd48b8ed3 in dispatch_command (command=COM_QUERY, thd=0x62b00008c288, packet=0x6290002b2289 "DROP TABLE t1, t2", packet_length=17, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1839
 
#11 0x0000558cd48b5908 in do_command (thd=0x62b00008c288) at /data/src/10.5/sql/sql_parse.cc:1358
 
#12 0x0000558cd4cd4b81 in do_handle_one_connection (connect=0x611000042248, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1422
 
#13 0x0000558cd4cd441c in handle_one_connection (arg=0x611000042108) at /data/src/10.5/sql/sql_connect.cc:1319
 
#14 0x0000558cd5973596 in pfs_spawn_thread (arg=0x61600000fa08) at /data/src/10.5/storage/perfschema/pfs.cc:2201
 
#15 0x00007f9890b99fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#16 0x00007f98903e84cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

No obvious problem on a non-debug build.

The failure (or at least the assertion itself) was introduced by this commit:

commit 91ab42a823b244a3d4b051ab79701b7a552f274a
 
Author: Monty
 
Date:   Tue Jan 28 23:23:51 2020 +0200
 
 
 
    Clean up and speed up interfaces for binary row logging
 
    
    MDEV-21605 Clean up and speed up interfaces for binary row logging
 
    MDEV-21617 Bug fix for previous version of this code

Comment by Michael Widenius [ 2020-06-08 ]

Old bug that was discovered thanks to the assert.

UNLOCK TABLES didn't clean the marker that we had written table maps for the involved tables. This could cause problems in row based replication.
Fixed by clearing the marker in unlock tables

Comment by Michael Widenius [ 2020-06-15 ]

Pushed into 10.5 tree

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