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

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_