[MDEV-25524] AddressSanitizer: heap-use-after-free in fil0fil.cc:2074 in fil_space_t::rename(char const*, bool, bool) - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Blocker
Resolution: Fixed
Affects Version/s: 10.6.0
Fix Version/s: 10.6.1
Component/s: Storage Engine - InnoDB
Labels:
- regression-10.6
- rr-profile-analyzed

Description

Work flow:

1. Start the server and generate some initial data

2. Concurrent DDL/DML load

3. During 2. is ongoing send SIGKILL to the DB server

4. Restart attempt

According to the server error log (during restart) we have no entries looking like

    [ERROR] InnoDB:   <whatever>

It ends with

...

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 24686]2021-04-26  5:42:15 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-392f2b-45.ibd' with space ID 1227. Another data file called ./test/t3.ibd exists with the same space ID.

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 26173]2021-04-26  5:42:16 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 42 row operations to undo

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 26177]2021-04-26  5:42:16 0 [Note] InnoDB: Trx id counter is 6829

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 26181]2021-04-26  5:42:16 0 [Note] InnoDB: Starting final batch to recover 278 pages from redo log.

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 27110]2021-04-26  5:42:16 0 [Note] InnoDB: Last binlog file './mysql-bin.000001', position 1012195

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 27121]2021-04-26  5:42:16 0 [Note] InnoDB: 128 rollback segments are active.

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 27508]2021-04-26  5:42:16 0 [Note] InnoDB: TRUNCATE rollback: 1227,./test/t3.ibd

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 27520]2021-04-26  5:42:16 0 [Note] InnoDB: Deleting ./test/t3.ibd

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 27526]=================================================================

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 27533][rr 3840652 27537]==3840652==ERROR: AddressSanitizer: heap-use-after-free on address 0x612000003fa8 at pc 0x55ee3443aea2 bp 0x7ffd3a5f39b0 sp 0x7ffd3a5f39a0

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 27540][rr 3840652 27542]READ of size 8 at 0x612000003fa8 thread T0

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33030]    #0 0x55ee3443aea1 in fil_space_t::rename(char const*, bool, bool) /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:2074

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33046]    #1 0x55ee343b1825 in dict_table_rename_in_cache(dict_table_t*, char const*, bool, bool) /data/Server/10.6alpha/storage/innobase/dict/dict0dict.cc:1655

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33056]    #2 0x55ee345461d4 in row_undo_ins_parse_undo_rec /data/Server/10.6alpha/storage/innobase/row/row0uins.cc:401

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33058]    #3 0x55ee34546cb7 in row_undo_ins(undo_node_t*, que_thr_t*) /data/Server/10.6alpha/storage/innobase/row/row0uins.cc:544

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33064]    #4 0x55ee3418222e in row_undo /data/Server/10.6alpha/storage/innobase/row/row0undo.cc:440

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33066]    #5 0x55ee34182710 in row_undo_step(que_thr_t*) /data/Server/10.6alpha/storage/innobase/row/row0undo.cc:496

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33072]    #6 0x55ee3401c5fe in que_thr_step /data/Server/10.6alpha/storage/innobase/que/que0que.cc:651

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33074]    #7 0x55ee3401c9c2 in que_run_threads_low /data/Server/10.6alpha/storage/innobase/que/que0que.cc:709

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33076]    #8 0x55ee3401cb64 in que_run_threads(que_thr_t*) /data/Server/10.6alpha/storage/innobase/que/que0que.cc:729

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33086]    #9 0x55ee3421db01 in trx_rollback_active /data/Server/10.6alpha/storage/innobase/trx/trx0roll.cc:604

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33088]    #10 0x55ee3421ecdb in trx_rollback_recovered(bool) /data/Server/10.6alpha/storage/innobase/trx/trx0roll.cc:756

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33096]    #11 0x55ee341cc311 in srv_start(bool) /data/Server/10.6alpha/storage/innobase/srv/srv0start.cc:1745

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33118]    #12 0x55ee33d645cf in innodb_init /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:3771

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33132]    #13 0x55ee3345645a in ha_initialize_handlerton(st_plugin_int*) /data/Server/10.6alpha/sql/handler.cc:647

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33144]    #14 0x55ee32d0b71a in plugin_initialize /data/Server/10.6alpha/sql/sql_plugin.cc:1459

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33146]    #15 0x55ee32d0d474 in plugin_init(int*, char**, int) /data/Server/10.6alpha/sql/sql_plugin.cc:1751

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33158]    #16 0x55ee32a209b4 in init_server_components /data/Server/10.6alpha/sql/mysqld.cc:5019

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33160]    #17 0x55ee32a22380 in mysqld_main(int, char**) /data/Server/10.6alpha/sql/mysqld.cc:5617

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33162]    #18 0x55ee32a1111c in main /data/Server/10.6alpha/sql/main.cc:25

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33164]    #19 0x7fb3f46250b2 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x270b2)

# 2021-04-26T05:43:28 [3742622] | [rr 3840652 33166]    #20 0x55ee32a1103d in _start (/data/Server_bin/10.6alpha_asan/bin/mariadbd+0x13c103d)

SUMMARY: AddressSanitizer: heap-use-after-free /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:2074 in fil_space_t::rename(char const*, bool, bool)

sdp:/data/Results/1619433372/TBR-1035/dev/shm/vardir/1619433372/83/1/rr

_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0  # Fate of the server till SIGKILL

_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-1  # Fate of the server during restart

/data/Results/1619433372/TBR-1035/dev/shm/vardir/1619433372/83/1/data_copy

         Copy of the data directory of the server after SIGKILL and before restart attempt

10.6 1a647b700f6b72dc97211510a5d0c647d5d3d911 2021-04-23T10:07:08+03:00

RQG

-------

git clone https://github.com/mleich1/rqg --branch experimental RQG

perl rqg.pl \

--grammar=conf/mariadb/table_stress_innodb.yy \

--gendata=conf/mariadb/table_stress.zz \

--gendata_sql=conf/mariadb/table_stress.sql \

--reporters=CrashRecovery1 \

--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \

--mysqld=--loose-idle_write_transaction_timeout=0 \

--mysqld=--loose-idle_transaction_timeout=0 \

--mysqld=--loose-idle_readonly_transaction_timeout=0 \

--mysqld=--connect_timeout=60 \

--mysqld=--interactive_timeout=28800 \

--mysqld=--slave_net_timeout=60 \

--mysqld=--net_read_timeout=30 \

--mysqld=--net_write_timeout=60 \

--mysqld=--loose-table_lock_wait_timeout=50 \

--mysqld=--wait_timeout=28800 \

--mysqld=--lock-wait-timeout=86400 \

--mysqld=--innodb-lock-wait-timeout=50 \

--no-mask \

--queries=10000000 \

--seed=random \

--reporters=Backtrace \

--reporters=ErrorLog \

--reporters=Deadlock1 \

--validators=None \

--mysqld=--log_output=none \

--mysqld=--log-bin \

--mysqld=--log_bin_trust_function_creators=1 \

--mysqld=--loose-debug_assert_on_not_freed_memory=0 \

--engine=InnoDB \

--restart_timeout=240 \

--mysqld=--plugin-load-add=file_key_management.so \

--mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \

--duration=300 \

--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \

--mysqld=--loose-innodb-sync-debug \

--mysqld=--innodb_stats_persistent=off \

--mysqld=--innodb_adaptive_hash_index=on \

--mysqld=--loose-innodb_evict_tables_on_commit_debug=off \

--mysqld=--loose-max-statement-time=30 \

--threads=9 \

--mysqld=--innodb-use-native-aio=0 \

--rr=Extended \

--rr_options="--wait" \

--mysqld=--innodb_page_size=8K \

--mysqld=--innodb-buffer-pool-size=8M \

--duration=300 \

--no_mask \

--workdir=<local settings> \

--vardir=<local settings> \

--mtr-build-thread=<local settings> \

--basedir1=<local settings> \

--script_debug=_nix_

Attachments

Issue Links

causes

MDEV-28752 Rollback of RENAME is broken if innodb_file_per_table=0

Closed

is caused by

MDEV-25312 Remove fil_space_t::name and related code

Closed

Activity

Ascending order - Click to sort in descending order

Matthias Leich added a comment - 2021-04-26 16:29

Error pattern for RQG

[ 'TBR-1035', 'INFO: Reporter \'CrashRecovery1\': Attempting database recovery using the server.+\[Note\] InnoDB: Starting crash recovery from checkpoint LSN.+SUMMARY: AddressSanitizer: heap-use-after-free .{1,200}fil0fil.cc:.{1,20}in fil_space_t::rename\(char const\*, bool, bool\).+RESULT: The RQG run ended with status STATUS_RECOVERY_FAILURE' ],

Archive: pluto:/data/Results/1619433372/004000.tar.xz

Matthias Leich added a comment - 2021-04-26 16:29 Error pattern for RQG [ 'TBR-1035', 'INFO: Reporter \'CrashRecovery1\': Attempting database recovery using the server.+\[Note\] InnoDB: Starting crash recovery from checkpoint LSN.+SUMMARY: AddressSanitizer: heap-use-after-free .{1,200}fil0fil.cc:.{1,20}in fil_space_t::rename$char const\*, bool, bool$.+RESULT: The RQG run ended with status STATUS_RECOVERY_FAILURE' ], Archive: pluto:/data/Results/1619433372/004000.tar.xz

Marko Mäkelä added a comment - 2021-04-28 06:46

The tablespace was freed in the same thread that accessed it a little later:

#0  fil_delete_tablespace (id=1227, if_exists=false, detached_handles=0x0) at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:1761

#1  0x000055ee3443a9fa in fil_rename_tablespace_check (old_path=0x602000002d70 "./test/t3.ibd", new_path=0x60200000b190 "./test/t3.ibd", replace_new=true)

    at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:2050

#2  0x000055ee3443ae6c in fil_space_t::rename (this=0x612000003f40, path=0x60200000b190 "./test/t3.ibd", log=true, replace=true) at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:2069

#3  0x000055ee343b1826 in dict_table_rename_in_cache (table=0x618000001d08, new_name=0x61300003df4e "test/t3", rename_also_foreigns=false, replace_new_file=true)

    at /data/Server/10.6alpha/storage/innobase/dict/dict0dict.cc:1655

#4  0x000055ee345461d5 in row_undo_ins_parse_undo_rec (node=0x61a000019908, dict_locked=true) at /data/Server/10.6alpha/storage/innobase/row/row0uins.cc:401

The error is flagged in

#0  0x00007fb3f4f85170 in __asan_report_load8 () from /lib/x86_64-linux-gnu/libasan.so.5

#1  0x000055ee3443aea2 in fil_space_t::rename (this=0x612000003f40, path=0x60200000b190 "./test/t3.ibd", log=true, replace=true) at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:2074

The code in fil_space_t::rename() between lines 2069 and 2074 is as follows:

		dberr_t err = fil_rename_tablespace_check(

			chain.start->name, path, replace);

		if (err != DB_SUCCESS) {

			return(err);

		fil_name_write_rename(id, chain.start->name, path);

The reason why we are deleting the tablespace is that we seem to think that we are rolling back a TRUNCATE TABLE operation. But, in reality we seem to be rolling back a rename of cool_down.t3 to test.t3, and the tablespace file name seems to be unchanged (it always was test/t3.ibd).

It seems that this has been broken ever since ~~MDEV-13564~~.

Before the failing recovery, the server was killed during a RENAME TABLE operation. The table contains many FULLTEXT INDEX. Because the schema name of the table is changing, all the internal tables for the fulltext indexes are being renamed:

mariadb-10.6.0
#0 0x000055cfdac623a4 in std::__atomic_base<unsigned long>::store (__m=std::memory_order_release, __i=11842593, this=0x55cfdde60408 <log_sys+8>) at /usr/include/c++/9/bits/atomic_base.h:397
#1 log_t::set_flushed_lsn (this=0x55cfdde60400 <log_sys>, lsn=11842593) at /data/Server/10.6alpha/storage/innobase/include/log0log.h:656
#2 0x000055cfdac5c26f in log_write_flush_to_disk_low (lsn=11842593) at /data/Server/10.6alpha/storage/innobase/log/log0log.cc:629
#3 0x000055cfdac5d3a7 in log_write_up_to (lsn=11842593, flush_to_disk=true, rotate_key=false, callback=0x0) at /data/Server/10.6alpha/storage/innobase/log/log0log.cc:830
#4 0x000055cfdb1744a1 in fil_name_write_rename (space_id=1228, old_name=0x60400005fc90 "./test/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED.ibd",
new_name=0x606000057080 "./cool_down/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED.ibd") at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:1546
#5 0x000055cfdb177f0b in fil_space_t::rename (this=0x612000083bc0, path=0x606000057080 "./cool_down/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED.ibd", log=true, replace=false)
at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:2074
#6 0x000055cfdb0ee826 in dict_table_rename_in_cache (table=0x6180001abd08, new_name=0x7fceecd2ed20 "cool_down/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED", rename_also_foreigns=true,
replace_new_file=false) at /data/Server/10.6alpha/storage/innobase/dict/dict0dict.cc:1655
#7 0x000055cfdae34a8a in row_rename_table_for_mysql (old_name=0x7fceecd2efc0 "test/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED",
new_name=0x7fceecd2ed20 "cool_down/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED", trx=0x7fcf0002fca8, commit=false, use_fk=false) at /data/Server/10.6alpha/storage/innobase/row/row0mysql.cc:4436
#8 0x000055cfdb1e7917 in fts_rename_one_aux_table (new_name=0x7fceecd30ec0 "cool_down/t3", fts_table_old_name=0x7fceecd2efc0 "test/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED", trx=0x7fcf0002fca8)
at /data/Server/10.6alpha/storage/innobase/fts/fts0fts.cc:1486
#9 0x000055cfdb1e7ca9 in fts_rename_aux_tables (table=0x6180001aa908, new_name=0x7fceecd30ec0 "cool_down/t3", trx=0x7fcf0002fca8) at /data/Server/10.6alpha/storage/innobase/fts/fts0fts.cc:1514
#10 0x000055cfdae34231 in row_rename_table_for_mysql (old_name=0x7fceecd31100 "test/t3", new_name=0x7fceecd30ec0 "cool_down/t3", trx=0x7fcf0002fca8, commit=true, use_fk=true)
at /data/Server/10.6alpha/storage/innobase/row/row0mysql.cc:4394
#11 0x000055cfdab072ad in innobase_rename_table (trx=0x7fcf0002fca8, from=0x7fceecd32370 "./test/t3", to=0x7fceecd32600 "./cool_down/t3", commit=true)
at /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:13291
#12 0x000055cfdaad2579 in ha_innobase::rename_table (this=0x62b0000a9560, from=0x7fceecd32370 "./test/t3", to=0x7fceecd32600 "./cool_down/t3")
at /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:13484
#13 0x000055cfda1acc8d in handler::ha_rename_table (this=0x62b0000a9560, from=0x7fceecd32370 "./test/t3", to=0x7fceecd32600 "./cool_down/t3") at /data/Server/10.6alpha/sql/handler.cc:4980
#14 0x000055cfd9c6f1fb in mysql_rename_table (base=0x615000002118, old_db=0x62b0000a8408, old_name=0x7fceecd32eb0, new_db=0x62b0000a8b08, new_name=0x7fceecd32ed0, flags=0)
at /data/Server/10.6alpha/sql/sql_table.cc:5855
#15 0x000055cfd9a81abd in do_rename (thd=0x62b0000d9218, ren_table=0x62b0000a83f0, new_db=0x62b0000a8b08, new_table_name=0x62b0000a8b18, new_table_alias=0x62b0000a8b38, skip_error=false, if_exists=false,
force_if_exists=0x7fceecd33010) at /data/Server/10.6alpha/sql/sql_rename.cc:340
#16 0x000055cfd9a81f4e in rename_tables (thd=0x62b0000d9218, table_list=0x62b0000a83f0, skip_error=false, if_exists=false, force_if_exists=0x7fceecd33010) at /data/Server/10.6alpha/sql/sql_rename.cc:424
#17 0x000055cfd9a80b05 in mysql_rename_tables (thd=0x62b0000d9218, table_list=0x62b0000a83f0, silent=false, if_exists=false) at /data/Server/10.6alpha/sql/sql_rename.cc:158
#18 0x000055cfd9a17982 in mysql_execute_command (thd=0x62b0000d9218) at /data/Server/10.6alpha/sql/sql_parse.cc:4322
#19 0x000055cfd9a30738 in mysql_parse (thd=0x62b0000d9218, rawbuf=0x62b0000a8238 "RENAME TABLE t3 TO cool_down.t3 /* E_R Thread1 QNO 817 CON_ID 17 */", length=68, parser_state=0x7fceecd33b20)
at /data/Server/10.6alpha/sql/sql_parse.cc:8018
#20 0x000055cfd9a09022 in dispatch_command (command=COM_QUERY, thd=0x62b0000d9218, packet=0x629000bdb219 " RENAME TABLE t3 TO cool_down.t3 /* E_R Thread1 QNO 817 CON_ID 17 */ ", packet_length=70,
blocking=true) at /data/Server/10.6alpha/sql/sql_parse.cc:1897

We did this for many FTS_ tables, and were still doing this when the server was killed:

fts_rename_aux_tables (table=0x6180001aa908, new_name=0x7fceecd30ec0 "cool_down/t3", trx=0x7fcf0002fca8) at /data/Server/10.6alpha/storage/innobase/fts/fts0fts.cc:1540

1540				DBUG_EXECUTE_IF("fts_rename_failure",

(rr)

1544				if (err != DB_SUCCESS) {

(rr)

1533			for (ulint j = 0; j < FTS_NUM_AUX_INDEX; ++j) {

(rr)

1534				fts_table.suffix = fts_get_suffix(j);

(rr)

1535				fts_get_table_name(&fts_table, old_table_name, true);

(rr)

1537				err = fts_rename_one_aux_table(

(rr)

Thread 21 received signal SIGKILL, Killed.

An interesting observation is that long before we started renaming the FTS_ tables, we had already written an undo log record for renaming the main table:

mariadb-10.6.0
#0 trx_undo_report_rename (trx=0x7fcf0002fca8, table=0x6180001aa908) at /data/Server/10.6alpha/storage/innobase/trx/trx0rec.cc:1909
#1 0x000055cfdae33b35 in row_rename_table_for_mysql (old_name=0x7fceecd31100 "test/t3", new_name=0x7fceecd30ec0 "cool_down/t3", trx=0x7fcf0002fca8, commit=true, use_fk=true)
at /data/Server/10.6alpha/storage/innobase/row/row0mysql.cc:4229
#2 0x000055cfdab072ad in innobase_rename_table (trx=0x7fcf0002fca8, from=0x7fceecd32370 "./test/t3", to=0x7fceecd32600 "./cool_down/t3", commit=true)
at /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:13291

After this, we spend a lot of time in fts_rename_aux_tables() (where the server was ultimately killed), and only after that, we would finally rename the tablespace:

	} else {

		/* The following call will also rename the .ibd data file if

		the table is stored in a single-table tablespace */

		err = dict_table_rename_in_cache(

			table, new_name, !new_is_tmp);

		if (err != DB_SUCCESS) {

			trx->error_state = DB_SUCCESS;

			trx->rollback();

			trx->error_state = DB_SUCCESS;

			goto funct_exit;

Note: There is some unnecessary-looking logic in row_rename_table_for_mysql() for renaming back the FTS_ tables. That should probably automatically happen as part of rollback.

The fix should be to make dict_table_rename_in_cache() smarter so that it will not do anything to the tablespace if no change to the name is needed.

Marko Mäkelä added a comment - 2021-04-28 06:46 The tablespace was freed in the same thread that accessed it a little later: #0 fil_delete_tablespace (id=1227, if_exists=false, detached_handles=0x0) at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:1761 #1 0x000055ee3443a9fa in fil_rename_tablespace_check (old_path=0x602000002d70 "./test/t3.ibd", new_path=0x60200000b190 "./test/t3.ibd", replace_new=true) at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:2050 #2 0x000055ee3443ae6c in fil_space_t::rename (this=0x612000003f40, path=0x60200000b190 "./test/t3.ibd", log=true, replace=true) at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:2069 #3 0x000055ee343b1826 in dict_table_rename_in_cache (table=0x618000001d08, new_name=0x61300003df4e "test/t3", rename_also_foreigns=false, replace_new_file=true) at /data/Server/10.6alpha/storage/innobase/dict/dict0dict.cc:1655 #4 0x000055ee345461d5 in row_undo_ins_parse_undo_rec (node=0x61a000019908, dict_locked=true) at /data/Server/10.6alpha/storage/innobase/row/row0uins.cc:401 The error is flagged in #0 0x00007fb3f4f85170 in __asan_report_load8 () from /lib/x86_64-linux-gnu/libasan.so.5 #1 0x000055ee3443aea2 in fil_space_t::rename (this=0x612000003f40, path=0x60200000b190 "./test/t3.ibd", log=true, replace=true) at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:2074 The code in fil_space_t::rename() between lines 2069 and 2074 is as follows: dberr_t err = fil_rename_tablespace_check( chain.start->name, path, replace); if (err != DB_SUCCESS) { return (err); } fil_name_write_rename(id, chain.start->name, path); The reason why we are deleting the tablespace is that we seem to think that we are rolling back a TRUNCATE TABLE operation. But, in reality we seem to be rolling back a rename of cool_down.t3 to test.t3 , and the tablespace file name seems to be unchanged (it always was test/t3.ibd ). It seems that this has been broken ever since MDEV-13564 . Before the failing recovery, the server was killed during a RENAME TABLE operation. The table contains many FULLTEXT INDEX . Because the schema name of the table is changing, all the internal tables for the fulltext indexes are being renamed: mariadb-10.6.0 #0 0x000055cfdac623a4 in std::__atomic_base<unsigned long>::store (__m=std::memory_order_release, __i=11842593, this=0x55cfdde60408 <log_sys+8>) at /usr/include/c++/9/bits/atomic_base.h:397 #1 log_t::set_flushed_lsn (this=0x55cfdde60400 <log_sys>, lsn=11842593) at /data/Server/10.6alpha/storage/innobase/include/log0log.h:656 #2 0x000055cfdac5c26f in log_write_flush_to_disk_low (lsn=11842593) at /data/Server/10.6alpha/storage/innobase/log/log0log.cc:629 #3 0x000055cfdac5d3a7 in log_write_up_to (lsn=11842593, flush_to_disk=true, rotate_key=false, callback=0x0) at /data/Server/10.6alpha/storage/innobase/log/log0log.cc:830 #4 0x000055cfdb1744a1 in fil_name_write_rename (space_id=1228, old_name=0x60400005fc90 "./test/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED.ibd", new_name=0x606000057080 "./cool_down/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED.ibd") at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:1546 #5 0x000055cfdb177f0b in fil_space_t::rename (this=0x612000083bc0, path=0x606000057080 "./cool_down/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED.ibd", log=true, replace=false) at /data/Server/10.6alpha/storage/innobase/fil/fil0fil.cc:2074 #6 0x000055cfdb0ee826 in dict_table_rename_in_cache (table=0x6180001abd08, new_name=0x7fceecd2ed20 "cool_down/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED", rename_also_foreigns=true, replace_new_file=false) at /data/Server/10.6alpha/storage/innobase/dict/dict0dict.cc:1655 #7 0x000055cfdae34a8a in row_rename_table_for_mysql (old_name=0x7fceecd2efc0 "test/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED", new_name=0x7fceecd2ed20 "cool_down/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED", trx=0x7fcf0002fca8, commit=false, use_fk=false) at /data/Server/10.6alpha/storage/innobase/row/row0mysql.cc:4436 #8 0x000055cfdb1e7917 in fts_rename_one_aux_table (new_name=0x7fceecd30ec0 "cool_down/t3", fts_table_old_name=0x7fceecd2efc0 "test/FTS_", '0' <repeats 13 times>, "4d8_BEING_DELETED", trx=0x7fcf0002fca8) at /data/Server/10.6alpha/storage/innobase/fts/fts0fts.cc:1486 #9 0x000055cfdb1e7ca9 in fts_rename_aux_tables (table=0x6180001aa908, new_name=0x7fceecd30ec0 "cool_down/t3", trx=0x7fcf0002fca8) at /data/Server/10.6alpha/storage/innobase/fts/fts0fts.cc:1514 #10 0x000055cfdae34231 in row_rename_table_for_mysql (old_name=0x7fceecd31100 "test/t3", new_name=0x7fceecd30ec0 "cool_down/t3", trx=0x7fcf0002fca8, commit=true, use_fk=true) at /data/Server/10.6alpha/storage/innobase/row/row0mysql.cc:4394 #11 0x000055cfdab072ad in innobase_rename_table (trx=0x7fcf0002fca8, from=0x7fceecd32370 "./test/t3", to=0x7fceecd32600 "./cool_down/t3", commit=true) at /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:13291 #12 0x000055cfdaad2579 in ha_innobase::rename_table (this=0x62b0000a9560, from=0x7fceecd32370 "./test/t3", to=0x7fceecd32600 "./cool_down/t3") at /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:13484 #13 0x000055cfda1acc8d in handler::ha_rename_table (this=0x62b0000a9560, from=0x7fceecd32370 "./test/t3", to=0x7fceecd32600 "./cool_down/t3") at /data/Server/10.6alpha/sql/handler.cc:4980 #14 0x000055cfd9c6f1fb in mysql_rename_table (base=0x615000002118, old_db=0x62b0000a8408, old_name=0x7fceecd32eb0, new_db=0x62b0000a8b08, new_name=0x7fceecd32ed0, flags=0) at /data/Server/10.6alpha/sql/sql_table.cc:5855 #15 0x000055cfd9a81abd in do_rename (thd=0x62b0000d9218, ren_table=0x62b0000a83f0, new_db=0x62b0000a8b08, new_table_name=0x62b0000a8b18, new_table_alias=0x62b0000a8b38, skip_error=false, if_exists=false, force_if_exists=0x7fceecd33010) at /data/Server/10.6alpha/sql/sql_rename.cc:340 #16 0x000055cfd9a81f4e in rename_tables (thd=0x62b0000d9218, table_list=0x62b0000a83f0, skip_error=false, if_exists=false, force_if_exists=0x7fceecd33010) at /data/Server/10.6alpha/sql/sql_rename.cc:424 #17 0x000055cfd9a80b05 in mysql_rename_tables (thd=0x62b0000d9218, table_list=0x62b0000a83f0, silent=false, if_exists=false) at /data/Server/10.6alpha/sql/sql_rename.cc:158 #18 0x000055cfd9a17982 in mysql_execute_command (thd=0x62b0000d9218) at /data/Server/10.6alpha/sql/sql_parse.cc:4322 #19 0x000055cfd9a30738 in mysql_parse (thd=0x62b0000d9218, rawbuf=0x62b0000a8238 "RENAME TABLE t3 TO cool_down.t3 /* E_R Thread1 QNO 817 CON_ID 17 */", length=68, parser_state=0x7fceecd33b20) at /data/Server/10.6alpha/sql/sql_parse.cc:8018 #20 0x000055cfd9a09022 in dispatch_command (command=COM_QUERY, thd=0x62b0000d9218, packet=0x629000bdb219 " RENAME TABLE t3 TO cool_down.t3 /* E_R Thread1 QNO 817 CON_ID 17 */ ", packet_length=70, blocking=true) at /data/Server/10.6alpha/sql/sql_parse.cc:1897 We did this for many FTS_ tables, and were still doing this when the server was killed: fts_rename_aux_tables (table=0x6180001aa908, new_name=0x7fceecd30ec0 "cool_down/t3", trx=0x7fcf0002fca8) at /data/Server/10.6alpha/storage/innobase/fts/fts0fts.cc:1540 1540 DBUG_EXECUTE_IF("fts_rename_failure", (rr) 1544 if (err != DB_SUCCESS) { (rr) 1533 for (ulint j = 0; j < FTS_NUM_AUX_INDEX; ++j) { (rr) 1534 fts_table.suffix = fts_get_suffix(j); (rr) 1535 fts_get_table_name(&fts_table, old_table_name, true); (rr) 1537 err = fts_rename_one_aux_table( (rr) Thread 21 received signal SIGKILL, Killed. An interesting observation is that long before we started renaming the FTS_ tables, we had already written an undo log record for renaming the main table: mariadb-10.6.0 #0 trx_undo_report_rename (trx=0x7fcf0002fca8, table=0x6180001aa908) at /data/Server/10.6alpha/storage/innobase/trx/trx0rec.cc:1909 #1 0x000055cfdae33b35 in row_rename_table_for_mysql (old_name=0x7fceecd31100 "test/t3", new_name=0x7fceecd30ec0 "cool_down/t3", trx=0x7fcf0002fca8, commit=true, use_fk=true) at /data/Server/10.6alpha/storage/innobase/row/row0mysql.cc:4229 #2 0x000055cfdab072ad in innobase_rename_table (trx=0x7fcf0002fca8, from=0x7fceecd32370 "./test/t3", to=0x7fceecd32600 "./cool_down/t3", commit=true) at /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:13291 After this, we spend a lot of time in fts_rename_aux_tables() (where the server was ultimately killed), and only after that, we would finally rename the tablespace: } else { /* The following call will also rename the .ibd data file if the table is stored in a single-table tablespace */ err = dict_table_rename_in_cache( table, new_name, !new_is_tmp); if (err != DB_SUCCESS) { trx->error_state = DB_SUCCESS; trx->rollback(); trx->error_state = DB_SUCCESS; goto funct_exit; } Note: There is some unnecessary-looking logic in row_rename_table_for_mysql() for renaming back the FTS_ tables. That should probably automatically happen as part of rollback. The fix should be to make dict_table_rename_in_cache() smarter so that it will not do anything to the tablespace if no change to the name is needed.

Marko Mäkelä added a comment - 2021-04-28 08:50

The following test case does not cause a crash in 10.2, but it fails for other reasons:

diff --git a/mysql-test/suite/innodb/t/rename_table_debug.test b/mysql-test/suite/innodb/t/rename_table_debug.test

index c75f2fbca10..3e2de242d49 100644

--- a/mysql-test/suite/innodb/t/rename_table_debug.test

+++ b/mysql-test/suite/innodb/t/rename_table_debug.test

@@ -19,4 +19,23 @@ SET DEBUG_SYNC='now WAIT_FOR renamed';

 --source include/restart_mysqld.inc

 --disconnect con1

 SELECT * FROM t1;

-DROP TABLE t1;

+CREATE TABLE t2 (a INT PRIMARY KEY) ENGINE=InnoDB;

+BEGIN;

+INSERT INTO t2 VALUES(1);

+--connect (con1,localhost,root,,test)

+SET DEBUG_SYNC='innodb_rename_in_cache SIGNAL committed WAIT_FOR ever';

+--send

+RENAME TABLE t1 TO t3;

+--connection default

+SET DEBUG_SYNC='now WAIT_FOR committed';

+COMMIT;

+--let $shutdown_timeout=0

+--source include/restart_mysqld.inc

+--disconnect con1

+SELECT * FROM t1;

+SELECT * FROM t2;

+DROP TABLE t1,t2;

diff --git a/storage/innobase/row/row0mysql.cc b/storage/innobase/row/row0mysql.cc

index c2f9186d408..673df836c08 100644

--- a/storage/innobase/row/row0mysql.cc

+++ b/storage/innobase/row/row0mysql.cc

@@ -4514,6 +4514,7 @@ row_rename_table_for_mysql(

 		trx_rollback_to_savepoint(trx, NULL);

 		trx->error_state = DB_SUCCESS;

 	} else {

+		DEBUG_SYNC_C("innodb_rename_in_cache");

 		/* The following call will also rename the .ibd data file if

 		the table is stored in a single-table tablespace */

10.2 91599701d07a9efb02a2f27d17a8f95bc2b9accf
CURRENT_TEST: innodb.rename_table_debug
mysqltest: At line 38: query 'SELECT * FROM t1' failed: 1286: Unknown storage engine 'InnoDB'

The error log contains the following:

2021-04-28 11:36:31 140015862220864 [ERROR] InnoDB: Cannot rename './test/t1.ibd' to './test/t2.ibd' for space ID 4 because the target file exists. Remove the target file and try again.

2021-04-28 11:36:31 140015862220864 [ERROR] InnoDB:  Cannot replay file rename. Remove either file and try again.

This looks like ~~MDEV-24184~~ (10.5.10 and 10.6.0 only). If I change the later CREATE TABLE t2 to CREATE TABLE t0 and adjust subsequent names, then the test would pass without problems. Let us check what happens in 10.5. The instrumentation patch is a little different for 10.5:

diff --git a/storage/innobase/row/row0mysql.cc b/storage/innobase/row/row0mysql.cc

index ce0746f20c6..ff37ec78256 100644

--- a/storage/innobase/row/row0mysql.cc

+++ b/storage/innobase/row/row0mysql.cc

@@ -4549,6 +4549,7 @@ row_rename_table_for_mysql(

 		trx->rollback();

 		trx->error_state = DB_SUCCESS;

 	} else {

+		DEBUG_SYNC_C("innodb_rename_in_cache");

 		/* The following call will also rename the .ibd data file if

 		the table is stored in a single-table tablespace */

With that patch, the test will pass just fine in 10.5. Also 10.6 cf552f5886968fc022122960d3a9274ce9f27819~ is fine. The culprit is ~~MDEV-25312~~:

10.6 cf552f5886968fc022122960d3a9274ce9f27819 WITH_ASAN=ON
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 412390, winpid: 412390, exit: 256] died after mysql-test-run waited 1.7 seconds for /dev/shm/10.6a/mysql-test/var/run/mysqld.1.pid to be created.
worker[1] mysql-test-run: *** ERROR: Failed to start mysqld mysqld.1 with command /dev/shm/10.6a/sql/mariadbd
mysql-test-run: *** ERROR: Test suite aborted

In the error log, we have:

2021-04-28 11:46:57 0 [Note] InnoDB: Trx id counter is 37

2021-04-28 11:46:57 0 [Note] InnoDB: Starting final batch to recover 7 pages from redo log.

2021-04-28 11:46:57 0 [Note] InnoDB: 128 rollback segments are active.

2021-04-28 11:46:57 0 [Note] InnoDB: TRUNCATE rollback: 5,./test/t1.ibd

2021-04-28 11:46:57 0 [Note] InnoDB: Deleting ./test/t1.ibd

=================================================================

==412391==ERROR: AddressSanitizer: heap-use-after-free on address 0x613000001058 at pc 0x0000023d528f bp 0x7ffd7a005430 sp 0x7ffd7a005428

READ of size 8 at 0x613000001058 thread T0

    #0 0x23d528e in fil_space_t::rename(char const*, bool, bool) /mariadb/10.6/storage/innobase/fil/fil0fil.cc:2074:25

    #1 0x231efc7 in dict_table_rename_in_cache(dict_table_t*, char const*, bool, bool) /mariadb/10.6/storage/innobase/dict/dict0dict.cc:1655:23

    #2 0x24ec31c in row_undo_ins_parse_undo_rec(undo_node_t*, bool) /mariadb/10.6/storage/innobase/row/row0uins.cc:399:4

10.6 cf552f5886968fc022122960d3a9274ce9f27819 Debug WITH_ASAN=OFF
CURRENT_TEST: innodb.rename_table_debug
mysqltest: At line 38: query 'SELECT * FROM t1' failed: 2013: Lost connection to MySQL server during query
…
Version: '10.6.0-MariaDB-debug-log' socket: '/dev/shm/10.6/mysql-test/var/tmp/mysqld.1.sock' port: 16000 Source distribution
2021-04-28 11:48:44 3 [ERROR] InnoDB: Failed to find tablespace for table `test`.`t1` in the cache. Attempting to load the tablespace with space id 5
2021-04-28 11:48:44 3 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2021-04-28 11:48:44 3 [ERROR] InnoDB: The error means the system cannot find the path specified.
2021-04-28 11:48:44 3 [ERROR] InnoDB: Cannot open datafile for read-only: './test/t1.ibd' OS error: 71
2021-04-28 11:48:44 3 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2021-04-28 11:48:44 3 [ERROR] InnoDB: The error means the system cannot find the path specified.
2021-04-28 11:48:44 3 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`t1``. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.
2021-04-28 11:48:44 0x7f8475eff700 InnoDB: Assertion failure in file /mariadb/10.6/storage/innobase/dict/dict0dict.cc line 1282
InnoDB: Failing assertion: table2 == NULL

Marko Mäkelä added a comment - 2021-04-28 08:50 The following test case does not cause a crash in 10.2, but it fails for other reasons: diff --git a/mysql-test/suite/innodb/t/rename_table_debug.test b/mysql-test/suite/innodb/t/rename_table_debug.test index c75f2fbca10..3e2de242d49 100644 --- a/mysql-test/suite/innodb/t/rename_table_debug.test +++ b/mysql-test/suite/innodb/t/rename_table_debug.test @@ -19,4 +19,23 @@ SET DEBUG_SYNC='now WAIT_FOR renamed'; --source include/restart_mysqld.inc --disconnect con1 SELECT * FROM t1; -DROP TABLE t1; + +CREATE TABLE t2 (a INT PRIMARY KEY) ENGINE=InnoDB; +BEGIN; +INSERT INTO t2 VALUES(1); + +--connect (con1,localhost,root,,test) +SET DEBUG_SYNC='innodb_rename_in_cache SIGNAL committed WAIT_FOR ever'; +--send +RENAME TABLE t1 TO t3; +--connection default +SET DEBUG_SYNC='now WAIT_FOR committed'; +COMMIT; + +--let $shutdown_timeout=0 +--source include/restart_mysqld.inc +--disconnect con1 +SELECT * FROM t1; +SELECT * FROM t2; + +DROP TABLE t1,t2; diff --git a/storage/innobase/row/row0mysql.cc b/storage/innobase/row/row0mysql.cc index c2f9186d408..673df836c08 100644 --- a/storage/innobase/row/row0mysql.cc +++ b/storage/innobase/row/row0mysql.cc @@ -4514,6 +4514,7 @@ row_rename_table_for_mysql( trx_rollback_to_savepoint(trx, NULL); trx->error_state = DB_SUCCESS; } else { + DEBUG_SYNC_C("innodb_rename_in_cache"); /* The following call will also rename the .ibd data file if the table is stored in a single-table tablespace */ 10.2 91599701d07a9efb02a2f27d17a8f95bc2b9accf CURRENT_TEST: innodb.rename_table_debug mysqltest: At line 38: query 'SELECT * FROM t1' failed: 1286: Unknown storage engine 'InnoDB' The error log contains the following: 2021-04-28 11:36:31 140015862220864 [ERROR] InnoDB: Cannot rename './test/t1.ibd' to './test/t2.ibd' for space ID 4 because the target file exists. Remove the target file and try again. 2021-04-28 11:36:31 140015862220864 [ERROR] InnoDB: Cannot replay file rename. Remove either file and try again. This looks like MDEV-24184 (10.5.10 and 10.6.0 only). If I change the later CREATE TABLE t2 to CREATE TABLE t0 and adjust subsequent names, then the test would pass without problems. Let us check what happens in 10.5. The instrumentation patch is a little different for 10.5: diff --git a/storage/innobase/row/row0mysql.cc b/storage/innobase/row/row0mysql.cc index ce0746f20c6..ff37ec78256 100644 --- a/storage/innobase/row/row0mysql.cc +++ b/storage/innobase/row/row0mysql.cc @@ -4549,6 +4549,7 @@ row_rename_table_for_mysql( trx->rollback(); trx->error_state = DB_SUCCESS; } else { + DEBUG_SYNC_C("innodb_rename_in_cache"); /* The following call will also rename the .ibd data file if the table is stored in a single-table tablespace */ With that patch, the test will pass just fine in 10.5. Also 10.6 cf552f5886968fc022122960d3a9274ce9f27819~ is fine. The culprit is MDEV-25312 : 10.6 cf552f5886968fc022122960d3a9274ce9f27819 WITH_ASAN=ON worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019 worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 412390, winpid: 412390, exit: 256] died after mysql-test-run waited 1.7 seconds for /dev/shm/10.6a/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: *** ERROR: Failed to start mysqld mysqld.1 with command /dev/shm/10.6a/sql/mariadbd mysql-test-run: *** ERROR: Test suite aborted In the error log, we have: 2021-04-28 11:46:57 0 [Note] InnoDB: Trx id counter is 37 2021-04-28 11:46:57 0 [Note] InnoDB: Starting final batch to recover 7 pages from redo log. 2021-04-28 11:46:57 0 [Note] InnoDB: 128 rollback segments are active. 2021-04-28 11:46:57 0 [Note] InnoDB: TRUNCATE rollback: 5,./test/t1.ibd 2021-04-28 11:46:57 0 [Note] InnoDB: Deleting ./test/t1.ibd ================================================================= ==412391==ERROR: AddressSanitizer: heap-use-after-free on address 0x613000001058 at pc 0x0000023d528f bp 0x7ffd7a005430 sp 0x7ffd7a005428 READ of size 8 at 0x613000001058 thread T0 #0 0x23d528e in fil_space_t::rename(char const*, bool, bool) /mariadb/10.6/storage/innobase/fil/fil0fil.cc:2074:25 #1 0x231efc7 in dict_table_rename_in_cache(dict_table_t*, char const*, bool, bool) /mariadb/10.6/storage/innobase/dict/dict0dict.cc:1655:23 #2 0x24ec31c in row_undo_ins_parse_undo_rec(undo_node_t*, bool) /mariadb/10.6/storage/innobase/row/row0uins.cc:399:4 10.6 cf552f5886968fc022122960d3a9274ce9f27819 Debug WITH_ASAN=OFF CURRENT_TEST: innodb.rename_table_debug mysqltest: At line 38: query 'SELECT * FROM t1' failed: 2013: Lost connection to MySQL server during query … Version: '10.6.0-MariaDB-debug-log' socket: '/dev/shm/10.6/mysql-test/var/tmp/mysqld.1.sock' port: 16000 Source distribution 2021-04-28 11:48:44 3 [ERROR] InnoDB: Failed to find tablespace for table `test`.`t1` in the cache. Attempting to load the tablespace with space id 5 2021-04-28 11:48:44 3 [ERROR] InnoDB: Operating system error number 2 in a file operation. 2021-04-28 11:48:44 3 [ERROR] InnoDB: The error means the system cannot find the path specified. 2021-04-28 11:48:44 3 [ERROR] InnoDB: Cannot open datafile for read-only: './test/t1.ibd' OS error: 71 2021-04-28 11:48:44 3 [ERROR] InnoDB: Operating system error number 2 in a file operation. 2021-04-28 11:48:44 3 [ERROR] InnoDB: The error means the system cannot find the path specified. 2021-04-28 11:48:44 3 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`t1``. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue. 2021-04-28 11:48:44 0x7f8475eff700 InnoDB: Assertion failure in file /mariadb/10.6/storage/innobase/dict/dict0dict.cc line 1282 InnoDB: Failing assertion: table2 == NULL

Marko Mäkelä added a comment - 2021-04-28 14:59

This will need more work. After a SIGKILL a little after

(rr) bt

#0  log_write_up_to (lsn=15664105, flush_to_disk=<optimized out>, rotate_key=<optimized out>,

    callback=<optimized out>) at /Server/bb-10.6-MDEV-25491/storage/innobase/log/log0log.cc:830

#1  0x000055eec463a51d in dict_build_table_def_step (thr=<optimized out>, node=<optimized out>)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/include/mtr0mtr.h:635

#2  0x000055eec463af1c in dict_create_table_step (thr=thr@entry=0x61b00070f178)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/dict/dict0crea.cc:1087

#3  0x000055eec42cb5ed in que_thr_step (thr=0x61b00070f178)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/que/que0que.cc:661

#4  que_run_threads_low (thr=0x61b00070f178)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/que/que0que.cc:709

#5  que_run_threads (thr=thr@entry=0x61b00070f178)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/que/que0que.cc:729

#6  0x000055eec43795be in row_create_table_for_mysql (table=table@entry=0x6180000bb920,

    trx=0x7f63ece8ff70, mode=<optimized out>, key_id=1)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/row/row0mysql.cc:2365

#7  0x000055eec40d1e4c in create_table_info_t::create_table_def (this=this@entry=0x7f63cef7ea90)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/handler/ha_innodb.cc:10404

#8  0x000055eec40c3877 in create_table_info_t::create_table (this=0x7f63cef7ea90,

    create_fk=<optimized out>) at /Server/bb-10.6-MDEV-25491/storage/innobase/handler/ha_innodb.cc:12224

#9  0x000055eec40e0cd0 in ha_innobase::create (this=this@entry=0x61d000da3eb8,

    name=name@entry=0x6190007a7750 "test/t3", form=<optimized out>,

    create_info=create_info@entry=0x7f63cef7f270, file_per_table=file_per_table@entry=true,

    trx=trx@entry=0x7f63ece8ff70)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/handler/ha_innodb.cc:12772

#10 0x000055eec40c6f03 in ha_innobase::truncate (this=0x61d000da3eb8)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/include/dict0dict.ic:1137

(create_table_info_t::create_table_def() finished, but create_table_info_t::create_table() was still in progress)
we got a failure on rolling back the TRUNCATE TABLE t3 operation:

#3  0x00007f7eb7b16f36 in __GI___assert_fail (assertion=assertion@entry=0x565346487cc0 "!exists",

    file=file@entry=0x565346485a80 "/Server/bb-10.6-MDEV-25491/storage/innobase/os/os0file.cc",

    line=line@entry=1625,

    function=function@entry=0x565346487c60 "bool os_file_rename_func(const char*, const char*)")

    at assert.c:101

#4  0x0000565343729515 in os_file_rename_func (

    oldpath=oldpath@entry=0x6040000874a8 "./test/#sql-ib2355.ibd",

    newpath=newpath@entry=0x604000088068 "./test/t3.ibd")

    at /Server/bb-10.6-MDEV-25491/storage/innobase/os/os0file.cc:1625

#5  0x000056534589c4f9 in pfs_os_file_rename_func (

    src_file=0x565346617aa0 "/Server/bb-10.6-MDEV-25491/storage/innobase/fil/fil0fil.cc",

    src_line=1963, newpath=0x604000088068 "./test/t3.ibd",

    oldpath=0x6040000874a8 "./test/#sql-ib2355.ibd", key=<optimized out>)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/include/os0file.ic:381

#6  fil_rename_tablespace (new_path_in=<optimized out>, old_path=<optimized out>, id=<optimized out>)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/fil/fil0fil.cc:1963

#7  fil_space_t::rename (this=<optimized out>, path=path@entry=0x604000088028 "./test/t3.ibd",

    log=log@entry=true, replace=<optimized out>)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/fil/fil0fil.cc:1904

#8  0x000056534582b7e9 in dict_table_rename_in_cache (table=table@entry=0x618000002920,

    new_name=new_name@entry=0x614000005ce6 "test/t3",

    rename_also_foreigns=rename_also_foreigns@entry=false, replace_new_file=replace_new_file@entry=true)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/dict/dict0dict.cc:1655

#9  0x00005653459ac974 in row_undo_ins_parse_undo_rec (node=0x61b000003920, dict_locked=<optimized out>)

    at /Server/bb-10.6-MDEV-25491/storage/innobase/row/row0uins.cc:401

As part of my patch, I had removed that code altogether. I will have to retain that logic in some form and try to make the data directory recover. For my reference, the location is sdp:/data/Results/1619618348/tmp/dev/shm/vardir/1619618348/202/1.

Marko Mäkelä added a comment - 2021-04-28 14:59 This will need more work. After a SIGKILL a little after (rr) bt #0 log_write_up_to (lsn=15664105, flush_to_disk=<optimized out>, rotate_key=<optimized out>, callback=<optimized out>) at /Server/bb-10.6-MDEV-25491/storage/innobase/log/log0log.cc:830 #1 0x000055eec463a51d in dict_build_table_def_step (thr=<optimized out>, node=<optimized out>) at /Server/bb-10.6-MDEV-25491/storage/innobase/include/mtr0mtr.h:635 #2 0x000055eec463af1c in dict_create_table_step (thr=thr@entry=0x61b00070f178) at /Server/bb-10.6-MDEV-25491/storage/innobase/dict/dict0crea.cc:1087 #3 0x000055eec42cb5ed in que_thr_step (thr=0x61b00070f178) at /Server/bb-10.6-MDEV-25491/storage/innobase/que/que0que.cc:661 #4 que_run_threads_low (thr=0x61b00070f178) at /Server/bb-10.6-MDEV-25491/storage/innobase/que/que0que.cc:709 #5 que_run_threads (thr=thr@entry=0x61b00070f178) at /Server/bb-10.6-MDEV-25491/storage/innobase/que/que0que.cc:729 #6 0x000055eec43795be in row_create_table_for_mysql (table=table@entry=0x6180000bb920, trx=0x7f63ece8ff70, mode=<optimized out>, key_id=1) at /Server/bb-10.6-MDEV-25491/storage/innobase/row/row0mysql.cc:2365 #7 0x000055eec40d1e4c in create_table_info_t::create_table_def (this=this@entry=0x7f63cef7ea90) at /Server/bb-10.6-MDEV-25491/storage/innobase/handler/ha_innodb.cc:10404 #8 0x000055eec40c3877 in create_table_info_t::create_table (this=0x7f63cef7ea90, create_fk=<optimized out>) at /Server/bb-10.6-MDEV-25491/storage/innobase/handler/ha_innodb.cc:12224 #9 0x000055eec40e0cd0 in ha_innobase::create (this=this@entry=0x61d000da3eb8, name=name@entry=0x6190007a7750 "test/t3", form=<optimized out>, create_info=create_info@entry=0x7f63cef7f270, file_per_table=file_per_table@entry=true, trx=trx@entry=0x7f63ece8ff70) at /Server/bb-10.6-MDEV-25491/storage/innobase/handler/ha_innodb.cc:12772 #10 0x000055eec40c6f03 in ha_innobase::truncate (this=0x61d000da3eb8) at /Server/bb-10.6-MDEV-25491/storage/innobase/include/dict0dict.ic:1137 ( create_table_info_t::create_table_def() finished, but create_table_info_t::create_table() was still in progress) we got a failure on rolling back the TRUNCATE TABLE t3 operation: #3 0x00007f7eb7b16f36 in __GI___assert_fail (assertion=assertion@entry=0x565346487cc0 "!exists", file=file@entry=0x565346485a80 "/Server/bb-10.6-MDEV-25491/storage/innobase/os/os0file.cc", line=line@entry=1625, function=function@entry=0x565346487c60 "bool os_file_rename_func(const char*, const char*)") at assert.c:101 #4 0x0000565343729515 in os_file_rename_func ( oldpath=oldpath@entry=0x6040000874a8 "./test/#sql-ib2355.ibd", newpath=newpath@entry=0x604000088068 "./test/t3.ibd") at /Server/bb-10.6-MDEV-25491/storage/innobase/os/os0file.cc:1625 #5 0x000056534589c4f9 in pfs_os_file_rename_func ( src_file=0x565346617aa0 "/Server/bb-10.6-MDEV-25491/storage/innobase/fil/fil0fil.cc", src_line=1963, newpath=0x604000088068 "./test/t3.ibd", oldpath=0x6040000874a8 "./test/#sql-ib2355.ibd", key=<optimized out>) at /Server/bb-10.6-MDEV-25491/storage/innobase/include/os0file.ic:381 #6 fil_rename_tablespace (new_path_in=<optimized out>, old_path=<optimized out>, id=<optimized out>) at /Server/bb-10.6-MDEV-25491/storage/innobase/fil/fil0fil.cc:1963 #7 fil_space_t::rename (this=<optimized out>, path=path@entry=0x604000088028 "./test/t3.ibd", log=log@entry=true, replace=<optimized out>) at /Server/bb-10.6-MDEV-25491/storage/innobase/fil/fil0fil.cc:1904 #8 0x000056534582b7e9 in dict_table_rename_in_cache (table=table@entry=0x618000002920, new_name=new_name@entry=0x614000005ce6 "test/t3", rename_also_foreigns=rename_also_foreigns@entry=false, replace_new_file=replace_new_file@entry=true) at /Server/bb-10.6-MDEV-25491/storage/innobase/dict/dict0dict.cc:1655 #9 0x00005653459ac974 in row_undo_ins_parse_undo_rec (node=0x61b000003920, dict_locked=<optimized out>) at /Server/bb-10.6-MDEV-25491/storage/innobase/row/row0uins.cc:401 As part of my patch, I had removed that code altogether. I will have to retain that logic in some form and try to make the data directory recover. For my reference, the location is sdp:/data/Results/1619618348/tmp/dev/shm/vardir/1619618348/202/1 .

Marko Mäkelä added a comment - 2021-04-29 14:45

Adjusting the following seems to have done the trick:

In row_undo_ins_parse_undo_rec() (in the rollback of a recovered incomplete DDL transaction that did rename), even if the table->name needs no change, the data file may need to be renamed!
In os_file_rename_func(), the new_file may exist it is an ‘orphan’ file and we are renaming a #sql-ib file to it, in the rollback of TRUNCATE. A debug assertion had to be relaxed to work around ~~MDEV-25506~~.

Marko Mäkelä added a comment - 2021-04-29 14:45 Adjusting the following seems to have done the trick: In row_undo_ins_parse_undo_rec() (in the rollback of a recovered incomplete DDL transaction that did rename), even if the table->name needs no change, the data file may need to be renamed! In os_file_rename_func() , the new_file may exist it is an ‘orphan’ file and we are renaming a #sql-ib file to it, in the rollback of TRUNCATE . A debug assertion had to be relaxed to work around MDEV-25506 .

People

Assignee:: Marko Mäkelä

Reporter:: Matthias Leich

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 2021-04-26 16:25

Updated:: 2022-06-06 06:58

Resolved:: 2021-04-29 15:57

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server