[MDEV-24503] Assertion `m_prebuilt->trx == thd_to_trx(m_user_thd)' failed in ha_innobase::is_read_only Created: 2020-12-30  Updated: 2021-01-25  Resolved: 2021-01-01

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.6
Fix Version/s: 10.6.0

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: regression

Issue Links:
Problem/Incident
is caused by MDEV-23497 make ROW_FORMAT=COMPRESSED read-only ... Closed

 Description   

The test case below is non-deterministic in the sense that the statement after COMMIT RELEASE sometimes fails with 2006/2013 errors. This non-determinism exists in previous versions too, only the assertion (and thus the failure) is new. I intentionally don't mask the errors as they may be somehow related to the reported problem. If the test case fails with one of the errors instead of the assertion failure, just re-run it. I hope it will be made deterministic after the analysis.

--source include/have_innodb.inc
 
 
 
--connect (con1,localhost,root,,test)
 
--disconnect con1
 
 
 
--connection default
 
--enable_reconnect
 
CREATE TABLE t1 (pk INT PRIMARY KEY) ENGINE=InnoDB;
 
--error ER_BAD_FIELD_ERROR
 
ALTER TABLE t1 ADD CHECK (b <= 1);
 
COMMIT RELEASE;
 
ALTER TABLE t1 AUTO_INCREMENT=1;
 
 
 
# Cleanup
 
--connection default
 
DROP TABLE t1;

10.6 9118fd36

 
mariadbd: /data/src/10.6/storage/innobase/handler/ha_innodb.cc:7269: bool ha_innobase::is_read_only() const: Assertion `m_prebuilt->trx == thd_to_trx(m_user_thd)' failed.
 
201230 19:31:06 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f48a7525f36 in __GI___assert_fail (assertion=0x5608c7c28af8 "m_prebuilt->trx == thd_to_trx(m_user_thd)", file=0x5608c7c26d48 "/data/src/10.6/storage/innobase/handler/ha_innodb.cc", line=7269, function=0x5608c7c2ab28 "bool ha_innobase::is_read_only() const") at assert.c:101
 
#8  0x00005608c7379d79 in ha_innobase::is_read_only (this=0x7f48741ac080) at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:7269
 
#9  0x00005608c73afc58 in ha_innobase::check_if_supported_inplace_alter (this=0x7f48741ac080, altered_table=0x7f48a087f950, ha_alter_info=0x7f48a087f8b0) at /data/src/10.6/storage/innobase/handler/handler0alter.cc:1978
 
#10 0x00005608c6c9ad54 in mysql_alter_table (thd=0x7f4868000db8, new_db=0x7f4868005828, new_name=0x7f4868005c28, create_info=0x7f48a0881480, table_list=0x7f4868012958, alter_info=0x7f48a08813b0, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/src/10.6/sql/sql_table.cc:10609
 
#11 0x00005608c6d42f28 in Sql_cmd_alter_table::execute (this=0x7f4868013038, thd=0x7f4868000db8) at /data/src/10.6/sql/sql_alter.cc:539
 
#12 0x00005608c6b99dda in mysql_execute_command (thd=0x7f4868000db8) at /data/src/10.6/sql/sql_parse.cc:5858
 
#13 0x00005608c6ba0126 in mysql_parse (thd=0x7f4868000db8, rawbuf=0x7f4868012870 "ALTER TABLE t1 AUTO_INCREMENT=1", length=31, parser_state=0x7f48a0882510) at /data/src/10.6/sql/sql_parse.cc:7881
 
#14 0x00005608c6b8c739 in dispatch_command (command=COM_QUERY, thd=0x7f4868000db8, packet=0x7f4868008e49 "ALTER TABLE t1 AUTO_INCREMENT=1", packet_length=31) at /data/src/10.6/sql/sql_parse.cc:1816
 
#15 0x00005608c6b8b150 in do_command (thd=0x7f4868000db8) at /data/src/10.6/sql/sql_parse.cc:1348
 
#16 0x00005608c6d382eb in do_handle_one_connection (connect=0x5608c95ae228, put_in_cache=true) at /data/src/10.6/sql/sql_connect.cc:1410
 
#17 0x00005608c6d3804e in handle_one_connection (arg=0x5608c95add88) at /data/src/10.6/sql/sql_connect.cc:1312
 
#18 0x00005608c7294b27 in pfs_spawn_thread (arg=0x5608c95ade68) at /data/src/10.6/storage/perfschema/pfs.cc:2201
 
#19 0x00007f48a7a3d609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#20 0x00007f48a7611293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

The assertion [failure] appeared in 10.6 branch after this commit:

Author: Marko Mäkelä
 
Date:   Tue Nov 10 17:21:16 2020 +0200
 
 
 
    MDEV-23497 Make ROW_FORMAT=COMPRESSED read-only by default



 Comments   
Comment by Marko Mäkelä [ 2020-12-31 ]

I believe that the MDEV-23497 changes in 10.6 are merely exposing some wrongdoing, by introducing a call that would enforce a correctness constraint more often.

The COMMIT RELEASE syntax is completely new to me, but apparently it was introduced in WL#1967 in MySQL 5.0.3 already. I’d check with rr replay what exactly is going on.

Comment by Elena Stepanova [ 2020-12-31 ]

COMMIT RELEASE forces the session to disconnect, while MTR's enable_reconnect makes it reconnect again. I don't know why it is important to do it this way, but I couldn't convert it into the "normal" disconnect=>connect. Maybe it involves a race condition, or COMMIT RELEASE disconnects the session in a different/wrong way.
The first, seemingly void and redundant, connect/disconnect of con1 is also somehow important for the test case.

Comment by Marko Mäkelä [ 2021-01-01 ]

Thank you for educating me. It was helpful for finding the trivial issue. I was unable to repeat the failure under rr record. I confirmed that the problem was indeed introduced by MDEV-23497, and the following fixes it for me:

diff --git a/storage/innobase/handler/handler0alter.cc b/storage/innobase/handler/handler0alter.cc
 
index 8dceb3a21f5..2749eb11ef1 100644
 
--- a/storage/innobase/handler/handler0alter.cc
 
+++ b/storage/innobase/handler/handler0alter.cc
 
@@ -1975,13 +1975,6 @@ ha_innobase::check_if_supported_inplace_alter(
 
 		DBUG_RETURN(HA_ALTER_INPLACE_NOT_SUPPORTED);
 
 	}
 
 
-	if (is_read_only()) {
 
-		ha_alter_info->unsupported_reason =
 
-			my_get_err_msg(ER_READ_ONLY_MODE);
 
-
 
-		DBUG_RETURN(HA_ALTER_INPLACE_NOT_SUPPORTED);
 
-	}
 
-
 
 	if (altered_table->s->fields > REC_MAX_N_USER_FIELDS) {
 
 		/* Deny the inplace ALTER TABLE. MySQL will try to
 
 		re-create the table and ha_innobase::create() will
 
@@ -1994,6 +1987,13 @@ ha_innobase::check_if_supported_inplace_alter(
 
 
 	update_thd();
 
 
+	if (is_read_only()) {
 
+		ha_alter_info->unsupported_reason =
 
+			my_get_err_msg(ER_READ_ONLY_MODE);
 
+
 
+		DBUG_RETURN(HA_ALTER_INPLACE_NOT_SUPPORTED);
 
+	}
 
+
 
 	if (ha_alter_info->handler_flags
 
 	    & ~(INNOBASE_INPLACE_IGNORE
 
 		| INNOBASE_ALTER_INSTANT

The assertion failed because it was being executed before the update_thd() call. The above patch fixes the issue. The only functional difference should be that an ADD COLUMN that tries to add too many columns to a ROW_FORMAT=COMPRESSED table would refuse the operation due to ER_TOO_MANY_FIELDS instead of ER_READ_ONLY_MODE.

For some reason, the test would occasionally (and always under rr record) fail with the following bogus message, even after I added another --enable_reconnect right before the stament:

10.6 9118fd360a3da0bba521caf2a35c424968235ac4

 
mysqltest: At line 11: query 'ALTER TABLE t1 AUTO_INCREMENT=1' failed: 2013: Lost connection to MySQL server during query

Hence, I will not add the test case to the regression suite.

Comment by Elena Stepanova [ 2021-01-03 ]

For some reason, the test would occasionally (and always under rr record) fail with the following bogus message, even after I added another --enable_reconnect right before the stament:
2013: Lost connection to MySQL server during query

Yes, that's what I was referring to at the beginning of the description as "statement after COMMIT RELEASE sometimes fails with 2006/2013 errors". I've seen it occasionally happen also on previous versions and without rr. My best guess is that there is some race condition which doesn't allow the session to reconnect fully by the time MTR attempts to execute the statement. I am not sure if it's worth investigating though, given that COMMIT RELEASE in itself is rare (at least I've never seen any users mention it), and combining it with the "reconnect" capability and the sporadic-and-not-so-disastrous effect brings it as close to an edge case as it can be.

Comment by Roel Van de Paar [ 2021-01-25 ]

marko This testcase:

CREATE TABLE t (a INT);
 
INSERT DELAYED INTO t VALUES(1);
 
ALTER TABLE t AUTO_INCREMENT=1;

Which previously crashed with this:

10.6.0 9118fd360a3da0bba521caf2a35c424968235ac4 (Debug)

 
mysqld: /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:7269: bool ha_innobase::is_read_only() const: Assertion `m_prebuilt->trx == thd_to_trx(m_user_thd)' 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 0x1478fc0c3700 (LWP 666366))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
#1  0x00005624a6ced0d7 in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424
 
#2  0x00005624a6481ab1 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  0x00001478fec81859 in __GI_abort () at abort.c:79
 
#6  0x00001478fec81729 in __assert_fail_base (fmt=0x1478fee17588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5624a7091ef0 "m_prebuilt->trx == thd_to_trx(m_user_thd)", file=0x5624a7090008 "/test/10.6_dbg/storage/innobase/handler/ha_innodb.cc", line=7269, function=<optimized out>) at assert.c:92
 
#7  0x00001478fec92f36 in __GI___assert_fail (assertion=assertion@entry=0x5624a7091ef0 "m_prebuilt->trx == thd_to_trx(m_user_thd)", file=file@entry=0x5624a7090008 "/test/10.6_dbg/storage/innobase/handler/ha_innodb.cc", line=line@entry=7269, function=function@entry=0x5624a7093d20 "bool ha_innobase::is_read_only() const") at assert.c:101
 
#8  0x00005624a6880d47 in ha_innobase::is_read_only (this=this@entry=0x1478ac004a40) at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:7269
 
#9  0x00005624a68b1434 in ha_innobase::check_if_supported_inplace_alter (this=0x1478ac004a40, altered_table=0x1478fc0bf7f0, ha_alter_info=0x1478fc0bf750) at /test/10.6_dbg/storage/innobase/handler/handler0alter.cc:1978
 
#10 0x00005624a62989fc in mysql_alter_table (thd=thd@entry=0x1478b8000db8, new_db=new_db@entry=0x1478b8005828, new_name=new_name@entry=0x1478b8005c28, create_info=create_info@entry=0x1478fc0c14a0, table_list=<optimized out>, table_list@entry=0x1478b80127a8, alter_info=alter_info@entry=0x1478fc0c13d0, order_num=0, order=0x0, ignore=false, if_exists=false) at /test/10.6_dbg/sql/sql_table.cc:10608
 
#11 0x00005624a631e640 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x1478b8000db8) at /test/10.6_dbg/sql/structs.h:559
 
#12 0x00005624a61c24c6 in mysql_execute_command (thd=thd@entry=0x1478b8000db8) at /test/10.6_dbg/sql/sql_parse.cc:5858
 
#13 0x00005624a61a9072 in mysql_parse (thd=thd@entry=0x1478b8000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1478fc0c23d0) at /test/10.6_dbg/sql/sql_parse.cc:7881
 
#14 0x00005624a61b71ec in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1478b8000db8, packet=packet@entry=0x1478b8008d39 "ALTER TABLE t AUTO_INCREMENT=1", packet_length=packet_length@entry=30) at /test/10.6_dbg/sql/sql_class.h:1293
 
#15 0x00005624a61ba52d in do_command (thd=0x1478b8000db8) at /test/10.6_dbg/sql/sql_parse.cc:1348
 
#16 0x00005624a63167fc in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5624a8fe1b68, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
 
#17 0x00005624a6316f03 in handle_one_connection (arg=arg@entry=0x5624a8fe1b68) at /test/10.6_dbg/sql/sql_connect.cc:1312
 
#18 0x00005624a67cc88f in pfs_spawn_thread (arg=0x5624a8ee8898) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
 
#19 0x00001478ff18f609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#20 0x00001478fed7e293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Also seems to be fixed by this patch:

commit 3f38e2a452575e22813c363a8f7900f727f6b16b
 
Author: Marko Mäkelä <marko.makela@mariadb.com>
 
Date:   Fri Jan 1 16:04:00 2021 +0200
 
    MDEV-24503 Assertion m_prebuilt->trx == thd_to_trx(m_user_thd) failed in ha_innobase::is_read_only
 
    ha_innobase::check_if_supported_inplace_alter(): Invoke is_read_only()
 
    only after calling update_thd(). In this way, the assertion failure
 
    should be avoided even if the client was reconnected right before an
 
    ALTER TABLE statement.
 
    This bug was introduced by MDEV-23497.

I was able to capture some ASAN data for this bug on an earlier build, which may be of interest to post-verify the bugfix:

10.6.0 c2ea036b7f4fc4200f168bf53ad3afd208370459 (Debug)

 
2021-01-25 20:12:32 0 [Note] /test/UBASAN_MD301120-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld: ready for connections.
 
Version: '10.6.0-MariaDB-debug'  socket: '/test/UBASAN_MD301120-mariadb-10.6.0-linux-x86_64-dbg/socket.sock'  port: 11155  MariaDB Server
 
=================================================================
 
==1076218==ERROR: AddressSanitizer: heap-use-after-free on address 0x62c0000702a8 at pc 0x561a0e570770 bp 0x14efa72188e0 sp 0x14efa72188d0
 
READ of size 8 at 0x62c0000702a8 thread T13
 
    #0 0x561a0e57076f in thd_get_ha_data /test/10.6_dbg_san/sql/sql_class.cc:476
 
    #1 0x561a11caa339 in thd_to_trx /test/10.6_dbg_san/storage/innobase/handler/ha_innodb.cc:1541
 
    #2 0x561a11cfe018 in ha_innobase::is_read_only() const /test/10.6_dbg_san/storage/innobase/handler/ha_innodb.cc:7228
 
    #3 0x561a11e0a1b2 in ha_innobase::check_if_supported_inplace_alter(TABLE*, Alter_inplace_info*) /test/10.6_dbg_san/storage/innobase/handler/handler0alter.cc:1978
 
    #4 0x561a0efed533 in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool, bool) /test/10.6_dbg_san/sql/sql_table.cc:10602
 
    #5 0x561a0f385a1c in Sql_cmd_alter_table::execute(THD*) /test/10.6_dbg_san/sql/sql_alter.cc:539
 
    #6 0x561a0e9ac8c0 in mysql_execute_command(THD*) /test/10.6_dbg_san/sql/sql_parse.cc:5860
 
    #7 0x561a0e8ec50e in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/10.6_dbg_san/sql/sql_parse.cc:7883
 
    #8 0x561a0e95afec in dispatch_command(enum_server_command, THD*, char*, unsigned int) /test/10.6_dbg_san/sql/sql_parse.cc:1816
 
    #9 0x561a0e9703b4 in do_command(THD*) /test/10.6_dbg_san/sql/sql_parse.cc:1348
 
    #10 0x561a0f34ff1a in do_handle_one_connection(CONNECT*, bool) /test/10.6_dbg_san/sql/sql_connect.cc:1410
 
    #11 0x561a0f35319d in handle_one_connection /test/10.6_dbg_san/sql/sql_connect.cc:1312
 
    #12 0x561a1184f42d in pfs_spawn_thread /test/10.6_dbg_san/storage/perfschema/pfs.cc:2201
 
    #13 0x14efc9faf608 in start_thread /build/glibc-ZN95T4/glibc-2.31/nptl/pthread_create.c:477
 
    #14 0x14efc9103292 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x122292)
 
 
 
0x62c0000702a8 is located 168 bytes inside of 29580-byte region [0x62c000070200,0x62c00007758c)
 
freed by thread T14 here:
 
    #0 0x561a0e0c620f in free (/test/UBASAN_MD301120-mariadb-10.6.0-linux-x86_64-dbg/bin/mariadbd+0x808d20f)
 
    #1 0x561a130e2d27 in free_memory /test/10.6_dbg_san/mysys/safemalloc.c:279
 
    #2 0x561a130e3635 in sf_free /test/10.6_dbg_san/mysys/safemalloc.c:197
 
    #3 0x561a130a0cf9 in my_free /test/10.6_dbg_san/mysys/my_malloc.c:209
 
    #4 0x561a0e72a5a8 in Delayed_insert::~Delayed_insert() (/test/UBASAN_MD301120-mariadb-10.6.0-linux-x86_64-dbg/bin/mariadbd+0x86f15a8)
 
    #5 0x561a0e6e1244 in handle_delayed_insert /test/10.6_dbg_san/sql/sql_insert.cc:3368
 
    #6 0x561a1184f42d in pfs_spawn_thread /test/10.6_dbg_san/storage/perfschema/pfs.cc:2201
 
    #7 0x14efc9faf608 in start_thread /build/glibc-ZN95T4/glibc-2.31/nptl/pthread_create.c:477
 
 
 
previously allocated by thread T13 here:
 
    #0 0x561a0e0c6608 in malloc (/test/UBASAN_MD301120-mariadb-10.6.0-linux-x86_64-dbg/bin/mariadbd+0x808d608)
 
    #1 0x561a130e2f36 in sf_malloc /test/10.6_dbg_san/mysys/safemalloc.c:118
 
    #2 0x561a130a061d in my_malloc /test/10.6_dbg_san/mysys/my_malloc.c:88
 
    #3 0x561a0e7011e6 in ilink::operator new(unsigned long) /test/10.6_dbg_san/sql/sql_list.h:680
 
    #4 0x561a0e7011e6 in delayed_get_table /test/10.6_dbg_san/sql/sql_insert.cc:2444
 
    #5 0x561a0e7011e6 in open_and_lock_for_insert_delayed /test/10.6_dbg_san/sql/sql_insert.cc:574
 
    #6 0x561a0e712430 in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool, select_result*) /test/10.6_dbg_san/sql/sql_insert.cc:751
 
    #7 0x561a0e9911ca in mysql_execute_command(THD*) /test/10.6_dbg_san/sql/sql_parse.cc:4439
 
    #8 0x561a0e8ec50e in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/10.6_dbg_san/sql/sql_parse.cc:7883
 
    #9 0x561a0e95afec in dispatch_command(enum_server_command, THD*, char*, unsigned int) /test/10.6_dbg_san/sql/sql_parse.cc:1816
 
    #10 0x561a0e9703b4 in do_command(THD*) /test/10.6_dbg_san/sql/sql_parse.cc:1348
 
    #11 0x561a0f34ff1a in do_handle_one_connection(CONNECT*, bool) /test/10.6_dbg_san/sql/sql_connect.cc:1410
 
    #12 0x561a0f35319d in handle_one_connection /test/10.6_dbg_san/sql/sql_connect.cc:1312
 
    #13 0x561a1184f42d in pfs_spawn_thread /test/10.6_dbg_san/storage/perfschema/pfs.cc:2201
 
    #14 0x14efc9faf608 in start_thread /build/glibc-ZN95T4/glibc-2.31/nptl/pthread_create.c:477
 
 
 
Thread T13 created by T0 here:
 
    #0 0x561a0dff3275 in __interceptor_pthread_create (/test/UBASAN_MD301120-mariadb-10.6.0-linux-x86_64-dbg/bin/mariadbd+0x7fba275)
 
    #1 0x561a1185ff45 in my_thread_create /test/10.6_dbg_san/storage/perfschema/my_thread.h:38
 
    #2 0x561a1185ff45 in pfs_spawn_thread_v1 /test/10.6_dbg_san/storage/perfschema/pfs.cc:2252
 
    #3 0x561a0e12130d in inline_mysql_thread_create /test/10.6_dbg_san/include/mysql/psi/mysql_thread.h:1323
 
    #4 0x561a0e12130d in create_thread_to_handle_connection(CONNECT*) /test/10.6_dbg_san/sql/mysqld.cc:5804
 
    #5 0x561a0e134d9b in create_new_thread(CONNECT*) /test/10.6_dbg_san/sql/mysqld.cc:5863
 
    #6 0x561a0e1353d0 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /test/10.6_dbg_san/sql/mysqld.cc:5928
 
    #7 0x561a0e136e54 in handle_connections_sockets() /test/10.6_dbg_san/sql/mysqld.cc:6055
 
    #8 0x561a0e13a966 in mysqld_main(int, char**) /test/10.6_dbg_san/sql/mysqld.cc:5699
 
    #9 0x561a0e107bba in main /test/10.6_dbg_san/sql/main.cc:25
 
    #10 0x14efc90080b2 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x270b2)
 
 
 
Thread T14 created by T13 here:
 
    #0 0x561a0dff3275 in __interceptor_pthread_create (/test/UBASAN_MD301120-mariadb-10.6.0-linux-x86_64-dbg/bin/mariadbd+0x7fba275)
 
    #1 0x561a1185ff45 in my_thread_create /test/10.6_dbg_san/storage/perfschema/my_thread.h:38
 
    #2 0x561a1185ff45 in pfs_spawn_thread_v1 /test/10.6_dbg_san/storage/perfschema/pfs.cc:2252
 
    #3 0x561a0e70ae5a in inline_mysql_thread_create /test/10.6_dbg_san/include/mysql/psi/mysql_thread.h:1323
 
    #4 0x561a0e70ae5a in delayed_get_table /test/10.6_dbg_san/sql/sql_insert.cc:2481
 
    #5 0x561a0e70ae5a in open_and_lock_for_insert_delayed /test/10.6_dbg_san/sql/sql_insert.cc:574
 
    #6 0x561a0e712430 in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool, select_result*) /test/10.6_dbg_san/sql/sql_insert.cc:751
 
    #7 0x561a0e9911ca in mysql_execute_command(THD*) /test/10.6_dbg_san/sql/sql_parse.cc:4439
 
    #8 0x561a0e8ec50e in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/10.6_dbg_san/sql/sql_parse.cc:7883
 
    #9 0x561a0e95afec in dispatch_command(enum_server_command, THD*, char*, unsigned int) /test/10.6_dbg_san/sql/sql_parse.cc:1816
 
    #10 0x561a0e9703b4 in do_command(THD*) /test/10.6_dbg_san/sql/sql_parse.cc:1348
 
    #11 0x561a0f34ff1a in do_handle_one_connection(CONNECT*, bool) /test/10.6_dbg_san/sql/sql_connect.cc:1410
 
    #12 0x561a0f35319d in handle_one_connection /test/10.6_dbg_san/sql/sql_connect.cc:1312
 
    #13 0x561a1184f42d in pfs_spawn_thread /test/10.6_dbg_san/storage/perfschema/pfs.cc:2201
 
    #14 0x14efc9faf608 in start_thread /build/glibc-ZN95T4/glibc-2.31/nptl/pthread_create.c:477
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /test/10.6_dbg_san/sql/sql_class.cc:476 in thd_get_ha_data
 
Shadow bytes around the buggy address:
 
  0x0c5880006000: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5880006010: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5880006020: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5880006030: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5880006040: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c5880006050: fd fd fd fd fd[fd]fd fd fd fd fd fd fd fd fd fd
 
  0x0c5880006060: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5880006070: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5880006080: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5880006090: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c58800060a0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
Shadow byte legend (one shadow byte represents 8 application bytes):
 
  Addressable:           00
 
  Partially addressable: 01 02 03 04 05 06 07
 
  Heap left redzone:       fa
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack after return:      f5
 
  Stack use after scope:   f8
 
  Global redzone:          f9
 
  Global init order:       f6
 
  Poisoned by user:        f7
 
  Container overflow:      fc
 
  Array cookie:            ac
 
  Intra object redzone:    bb
 
  ASan internal:           fe
 
  Left alloca redzone:     ca
 
  Right alloca redzone:    cb
 
  Shadow gap:              cc
 
==1076218==ABORTING
 
210125 20:12:35 [ERROR] mysqld got signal 6 ;
 
...
 
Query (0x62b0000a12a8): ALTER TABLE t AUTO_INCREMENT=1

Comment by Roel Van de Paar [ 2021-01-25 ]

Also did a quick re-run under ASAN with a build at 3f38e2a452575e22813c363a8f7900f727f6b16b (i.e. inc the patch). No ASAN errors show anymore post-patch.

10.6.0 3f38e2a452575e22813c363a8f7900f727f6b16b (Debug)

 
2021-01-25 21:13:48 0 [Note] /test/MDEV-24503_UBASAN_MD250121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld: Shutdown complete
 
AddressSanitizer exit stats: ...

Comment by Marko Mäkelä [ 2021-01-25 ]

Roel, thank you. I think that it is rather obvious that due to the missing ha_innobase::update_thd() call, the ha_innobase::is_read_only() check may be referring to freed memory. Your stack traces seem to confirm that.

Comment by Roel Van de Paar [ 2021-01-25 ]

Aha, super. Thank you!

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