[MDEV-23705] Assertion `table->data_dir_path || !space' failed in row_drop_table_for_mysql on TRUNCATE after DISCARD TABLESPACE Created: 2020-09-09  Updated: 2020-10-06  Resolved: 2020-09-22

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.2.35, 10.3.26, 10.4.16, 10.5.7

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: debug, not-10.1

Issue Links:
Problem/Incident
is caused by MDEV-13564 TRUNCATE TABLE and undo tablespace tr... Closed
Relates
relates to MDEV-22939 Server crashes in row_make_new_pathna... Closed
relates to MDEV-22343 Remove SYS_TABLESPACES and SYS_DATAFILES Closed

 Description    

CREATE TABLE t(c INT) ENGINE=InnoDB;
 
ALTER TABLE t DISCARD TABLESPACE;
 
RENAME TABLE t TO u;
 
TRUNCATE u;
 
TRUNCATE u;

Leads to:

10.5.6 c5517cd86440b6669509211b1ad10f837a929952 (Debug)

 
mysqld: /test/10.5_dbg/storage/innobase/row/row0mysql.cc:3694: dberr_t row_drop_table_for_mysql(const char*, trx_t*, enum_sql_command, bool, bool): Assertion `table->data_dir_path || !space' failed.

10.5.6 c5517cd86440b6669509211b1ad10f837a929952 (Debug)

 
Core was generated by `/test/MD080920-mariadb-10.5.6-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:57
 
[Current thread is 1 (Thread 0x14a736165700 (LWP 3580839))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055e79331f4e8 in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:424
 
#2  0x000055e792ae656b in handle_fatal_signal (sig=6) at /test/10.5_dbg/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  0x000014a7343fb8b1 in __GI_abort () at abort.c:79
 
#6  0x000014a7343eb42a in __assert_fail_base (fmt=0x14a734572a38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55e793773338 "table->data_dir_path || !space", file=file@entry=0x55e793770ee0 "/test/10.5_dbg/storage/innobase/row/row0mysql.cc", line=line@entry=3694, function=function@entry=0x55e793774220 <row_drop_table_for_mysql(char const*, trx_t*, enum_sql_command, bool, bool)::__PRETTY_FUNCTION__> "dberr_t row_drop_table_for_mysql(const char*, trx_t*, enum_sql_command, bool, bool)") at assert.c:92
 
#7  0x000014a7343eb4a2 in __GI___assert_fail (assertion=assertion@entry=0x55e793773338 "table->data_dir_path || !space", file=file@entry=0x55e793770ee0 "/test/10.5_dbg/storage/innobase/row/row0mysql.cc", line=line@entry=3694, function=function@entry=0x55e793774220 <row_drop_table_for_mysql(char const*, trx_t*, enum_sql_command, bool, bool)::__PRETTY_FUNCTION__> "dberr_t row_drop_table_for_mysql(const char*, trx_t*, enum_sql_command, bool, bool)") at assert.c:101
 
#8  0x000055e793029375 in row_drop_table_for_mysql (name=<optimized out>, name@entry=0x14a736162de0 "test/#sql-ib22", trx=trx@entry=0x14a721003548, sqlcom=sqlcom@entry=SQLCOM_TRUNCATE, create_failed=create_failed@entry=false, nonatomic=<optimized out>, nonatomic@entry=true) at /test/10.5_dbg/storage/innobase/row/row0mysql.cc:3694
 
#9  0x000055e792eccf7a in ha_innobase::delete_table (this=this@entry=0x14a7135246a0, name=<optimized out>, name@entry=0x14a7134570a0 "test/#sql-ib22", sqlcom=sqlcom@entry=SQLCOM_TRUNCATE) at /test/10.5_dbg/storage/innobase/handler/ha_innodb.cc:13210
 
#10 0x000055e792ec417d in ha_innobase::truncate (this=0x14a7135246a0) at /test/10.5_dbg/storage/innobase/handler/ha_innodb.cc:13603
 
#11 0x000055e792af4ddf in handler::ha_truncate (this=0x14a7135246a0) at /test/10.5_dbg/sql/handler.cc:4693
 
#12 0x000055e7929bdbda in Sql_cmd_truncate_table::handler_truncate (this=this@entry=0x14a713474830, thd=thd@entry=0x14a713415088, table_ref=table_ref@entry=0x14a713474158, is_tmp_table=is_tmp_table@entry=false) at /test/10.5_dbg/sql/sql_truncate.cc:238
 
#13 0x000055e7929be806 in Sql_cmd_truncate_table::truncate_table (this=this@entry=0x14a713474830, thd=thd@entry=0x14a713415088, table_ref=table_ref@entry=0x14a713474158) at /test/10.5_dbg/sql/sql_truncate.cc:461
 
#14 0x000055e7929be958 in Sql_cmd_truncate_table::execute (this=0x14a713474830, thd=0x14a713415088) at /test/10.5_dbg/sql/sql_truncate.cc:517
 
#15 0x000055e792838b44 in mysql_execute_command (thd=thd@entry=0x14a713415088) at /test/10.5_dbg/sql/sql_parse.cc:5952
 
#16 0x000055e7928404b8 in mysql_parse (thd=thd@entry=0x14a713415088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14a736164350, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7994
 
#17 0x000055e79282cee8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14a713415088, packet=packet@entry=0x14a713467089 "TRUNCATE u", packet_length=packet_length@entry=10, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1867
 
#18 0x000055e79282b6d2 in do_command (thd=0x14a713415088) at /test/10.5_dbg/sql/sql_parse.cc:1348
 
#19 0x000055e79298aa27 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14a7150d42c8, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1410
 
#20 0x000055e79298b14b in handle_one_connection (arg=arg@entry=0x14a7150d42c8) at /test/10.5_dbg/sql/sql_connect.cc:1312
 
#21 0x000055e792df5784 in pfs_spawn_thread (arg=0x14a733046508) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#22 0x000014a7350de6db in start_thread (arg=0x14a736165700) at pthread_create.c:463
 
#23 0x000014a7344dca3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.2.34 (dbg), 10.3.25 (dbg), 10.4.15 (dbg), 10.5.6 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.47 (dbg), 10.1.47 (opt), 10.2.34 (opt), 10.3.25 (opt), 10.4.15 (opt), 10.5.6 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

 Comments   
Comment by Marko Mäkelä [ 2020-09-22 ]

This is a rather interesting bug. The DATA DIRECTORY flag will be wrongly set. And not only that, the table->data_dir_path will have been truncated to "./t":

10.2 e05650e6868eab2dbb9f58c4786bcc71afc4ffce

 
Thread 3 hit Watchpoint 8: table->data_dir_path[3]
 
 
 
Old value = 101 'e'
 
New value = 0 '\000'
 
os_file_make_data_dir_path (data_dir_path=<optimized out>) at /mariadb/10.2o/storage/innobase/os/os0file.cc:1393
 
1393	}
 
(rr) bt
 
#0  os_file_make_data_dir_path (data_dir_path=<optimized out>) at /mariadb/10.2o/storage/innobase/os/os0file.cc:1393
 
#1  0x000055685158363d in dict_save_data_dir_path (table=0x7f635816c6b0, filepath=<optimized out>) at /mariadb/10.2o/storage/innobase/dict/dict0load.cc:2724
 
#2  dict_get_and_save_data_dir_path (table=0x7f635816c6b0, dict_mutex_own=false) at /mariadb/10.2o/storage/innobase/dict/dict0load.cc:2755
 
#3  0x00005568512eeaa2 in ha_innobase::truncate (this=0x7f6358091f60) at /mariadb/10.2o/storage/innobase/handler/ha_innodb.cc:13706

I was suspecting heap-use-after-free, but WITH_ASAN will not flag anything before the assertion failure. We seem to get this truncated data_file_name = "./t" on the first invocation of ha_innobase::truncate().

Comment by Marko Mäkelä [ 2020-09-22 ]

After ALTER TABLE t DISCARD TABLESPACE, the tablespace will no longer exist, and dict_get_and_save_data_dir_path() would invoke dict_get_first_path() to read an entry from SYS_DATAFILES (which we plan to remove in MDEV-22343). For some reason, DISCARD TABLESPACE would not to remove the entry from there.

I did not try to figure out why we truncate the name from "./test/t.ibd" to "./t". I think that this entire function dict_get_and_save_data_dir_path() is unnecessary (because unlike MySQL 5.7, we do not support CREATE TABLESPACE for InnoDB) and should be removed, possibly as part of MDEV-22343.

Comment by Roel Van de Paar [ 2020-10-02 ]

Whilst this bug is resolved, I still had an older testcase which I wanted to add as it's quite different and sporadic (requires 10 to 500 executions to hit, and interestingly the drop/create does not seem to be required to hit the [now-fixed] bug):

DROP DATABASE test;
 
CREATE DATABASE test;
 
SET SQL_MODE='';
 
USE test;
 
CREATE TABLE tab(c1 int NOT NULL PRIMARY KEY,c2 POINT NOT NULL, c3 LINESTRING NOT NULL,c4 POLYGON NOT NULL,c5 GEOMETRY NOT NULL)  ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=8;
 
ALTER TABLE tab DISCARD TABLESPACE;
 
SET @@enforce_storage_engine=INNODB;
 
ALTER TABLE tab  ENGINE Aria;

It leads to the same assert on 10.4, does not produce on 10.5. I build 10.4.15 at revision bd64c2e8cc610dc774411c5f0a8ab163fc685934 today, and the bug does not reproduce there anymore with this testcase, or the one above (both tested on debug only), so I consider it solved.

Interestingly, the testcase above (or quite close to it) led also to this assert (on the older revision) in the original run (and was reduced to the above). Perhaps the occurrence of this particular assert is even less pronounced, or requires the C-API for replay.

10.4.15 eae968f62d285de97ed607c87bc131cd863d5d03

 
mysqld: /test/10.4_dbg/include/mysql/psi/mysql_socket.h:744: inline_mysql_socket_send: Assertion `mysql_socket.fd != -1' failed.

10.4.15 eae968f62d285de97ed607c87bc131cd863d5d03

 
Core was generated by `/test/MD110820-mariadb-10.4.15-linux-x86_64-dbg/bin/mysqld --no-defaults --max_'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
[Current thread is 1 (Thread 0x14813c0ad700 (LWP 843609))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x0000558484cae8a6 in my_write_core (sig=sig@entry=6) at /test/10.4_dbg/mysys/stacktrace.c:482
 
#2  0x000055848442acdc in handle_fatal_signal (sig=6) at /test/10.4_dbg/sql/signal_handler.cc:343
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x0000148146df48b1 in __GI_abort () at abort.c:79
 
#6  0x0000148146de442a in __assert_fail_base (fmt=0x148146f6ba38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55848534bd6a "mysql_socket.fd != -1", file=file@entry=0x55848534bb78 "/test/10.4_dbg/include/mysql/psi/mysql_socket.h", line=line@entry=744, function=function@entry=0x55848534beb0 <__PRETTY_FUNCTION__.15660> "inline_mysql_socket_send") at assert.c:92
 
#7  0x0000148146de44a2 in __GI___assert_fail (assertion=assertion@entry=0x55848534bd6a "mysql_socket.fd != -1", file=file@entry=0x55848534bb78 "/test/10.4_dbg/include/mysql/psi/mysql_socket.h", line=line@entry=744, function=function@entry=0x55848534beb0 <__PRETTY_FUNCTION__.15660> "inline_mysql_socket_send") at assert.c:101
 
#8  0x0000558484d0eca6 in inline_mysql_socket_send (flags=64, n=84, buf=0x1480e08ab840, mysql_socket={fd = -1, m_psi = 0x0}, src_line=301, src_file=0x55848534b9e0 "/test/10.4_dbg/vio/viosocket.c") at /test/10.4_dbg/include/mysql/psi/mysql_socket.h:744
 
#9  vio_write (vio=0x55848900b640, buf=0x1480e08ab840 "\001", size=84) at /test/10.4_dbg/vio/viosocket.c:300
 
#10 0x000055848459de2d in net_real_write (net=net@entry=0x1480e0001048, packet=0x1480e08ab840 "\001", len=<optimized out>) at /test/10.4_dbg/sql/net_serv.cc:693
 
#11 0x000055848459e094 in net_flush (net=net@entry=0x1480e0001048) at /test/10.4_dbg/sql/net_serv.cc:384
 
#12 0x000055848459e5df in net_write_command (net=net@entry=0x1480e0001048, command=command@entry=255 '\377', header=header@entry=0x558484f61b76 "", head_len=head_len@entry=0, packet=packet@entry=0x14813c0abf00 "\207\a#70100Connection was killed", len=29) at /test/10.4_dbg/sql/net_serv.cc:533
 
#13 0x0000558484089ea3 in net_send_error_packet (thd=0x1480e0000d50, sql_errno=sql_errno@entry=1927, err=<optimized out>, err@entry=0x1480e0006753 "Connection was killed", sqlstate=sqlstate@entry=0x1480e0006738 "70100") at /test/10.4_dbg/sql/protocol.cc:475
 
#14 0x000055848408a101 in Protocol::send_error (this=0x1480e0001318, sql_errno=1927, err_msg=0x1480e0006753 "Connection was killed", sql_state=0x1480e0006738 "70100") at /test/10.4_dbg/sql/protocol.cc:672
 
#15 0x000055848408a300 in Protocol::end_statement (this=0x1480e0001318) at /test/10.4_dbg/sql/protocol.cc:596
 
#16 0x0000558484186c9f in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1480e0000d50, packet=<optimized out>, packet@entry=0x1480e08ab841 "", packet_length=<optimized out>, packet_length@entry=76, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_parse.cc:2424
 
#17 0x000055848418835b in do_command (thd=0x1480e0000d50) at /test/10.4_dbg/sql/sql_parse.cc:1352
 
#18 0x00005584842b48b6 in do_handle_one_connection (connect=connect@entry=0x558488fc2560) at /test/10.4_dbg/sql/sql_connect.cc:1412
 
#19 0x00005584842b49d6 in handle_one_connection (arg=arg@entry=0x558488fc2560) at /test/10.4_dbg/sql/sql_connect.cc:1316
 
#20 0x0000558484bc1898 in pfs_spawn_thread (arg=0x558488ed0440) at /test/10.4_dbg/storage/perfschema/pfs.cc:1869
 
#21 0x0000148147d5b6db in start_thread (arg=0x14813c0ad700) at pthread_create.c:463
 
#22 0x0000148146ed5a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

In any case, I will add this to the filters, and immediately remark this one as well as the original one. So, if any of this shows again, we'll pick up on it and know it's related.

Comment by Roel Van de Paar [ 2020-10-02 ]

Also interesting (and perhaps another bug) is that on the current version, the second truncate does not give the same warning as the first:

10.4.15 bd64c2e8cc610dc774411c5f0a8ab163fc685934 (Debug)

 
10.4.15>CREATE TABLE t(c INT) ENGINE=InnoDB;
 
Query OK, 0 rows affected (0.012 sec)
 
 
 
10.4.15>ALTER TABLE t DISCARD TABLESPACE;
 
Query OK, 0 rows affected (0.004 sec)
 
 
 
10.4.15>RENAME TABLE t TO u;
 
Query OK, 0 rows affected (0.009 sec)
 
 
 
10.4.15>TRUNCATE u;
 
Query OK, 0 rows affected, 1 warning (0.017 sec)
 
 
 
10.4.15>show warnings;
 
+---------+------+---------------------------------------------+
 
| Level   | Code | Message                                     |
 
+---------+------+---------------------------------------------+
 
| Warning | 1814 | Tablespace has been discarded for table `u` |
 
+---------+------+---------------------------------------------+
 
1 row in set (0.000 sec)
 
 
 
10.4.15>TRUNCATE u;
 
Query OK, 0 rows affected (0.022 sec)

Not sure how that second truncate is able to complete "OK"?

marko do you consider this another bug?

Comment by Roel Van de Paar [ 2020-10-02 ]

Interestingly, the assertion `mysql_socket.fd != -1' is seen a lot of my runs on scanning the same. I wonder if it is a separate bug as well.

Comment by Marko Mäkelä [ 2020-10-02 ]

Roel, I believe the ALTER TABLE t DISCARD TABLESPACE is broken by design, basically corrupting the table by removing the data file while retaining the metadata.

TRUNCATE TABLE will fix this corruption by creating an empty table. It will also issue a warning if the tablespace had been discarded.

If you see assertions mysql_socket.fd != 1 failing, those should have nothing to do with InnoDB. In any case, that should be a separate bug.

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