fil_ibd_create() may hijack the file handle of an old file

origin/10.6 270eeeb52358db8b76745dfb5fc0e78118a6a2bf 2023-05-23T12:25:39+03:00 + some patch (pluto:/Server/purge.patch).

The same problem (maybe different backtrace) was replayed on

 origin/10.6 270eeeb52358db8b76745dfb5fc0e78118a6a2bf 2023-05-23T12:25:39+03:00

origin/bb-10.6-MDEV-26782 1ed645614b8895857f28839807f2d42c9220b936 2023-04-21T14:14:30+03:00

origin/bb-10.6-MDEV-26782 3d589c462b7e17145e055ce9066bbf27856ca215 2023-04-20T09:14:17+03:00

origin/bb-10.6-MDEV-30996 5f7dfabdaa658ef77c5b511e25134b60e9a129c0 2023-04-19T15:13:39+05:30

origin/bb-10.6-MDEV-31234 ece84a7218c153d2c0fa5c2d33605304bc441fb9 2023-05-22T13:17:49+03:00

origin/bb-10.9-MDEV-29911 e9a6dc7ae59dec89bdbb1d60bcbdc76bc3d583c8 2023-05-11T14:29:56+03:00

origin/10.6 2ddfb838078cb0f81b48ef878d97b966c8d9c494 2023-04-12T19:07:59+05:30

Scenario:

1. Start the server and generate some initial data.

2. Two sessions run concurrent

              ALTER TABLE <some table created+filled in 1.> FORCE ;

The server error log ends with

# 2023-05-25T15:48:34 [1227458] | [rr 1231496 1161866]2023-05-25 15:17:04 14 [Note] InnoDB: Cannot close file ./test/#sql-alter-12ca88-e.ibd because of 1 pending operations

# 2023-05-25T15:48:34 [1227458] | [rr 1231496 1161936]2023-05-25 15:17:04 16 [ERROR] InnoDB: Operating system error number 9 in a file operation.

# 2023-05-25T15:48:34 [1227458] | [rr 1231496 1161940]2023-05-25 15:17:04 16 [ERROR] InnoDB: Error number 9 means 'Bad file descriptor'

# 2023-05-25T15:48:34 [1227458] | [rr 1231496 1161944]2023-05-25 15:17:04 16 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/

# 2023-05-25T15:48:34 [1227458] | [rr 1231496 1161948]2023-05-25 15:17:04 16 [ERROR] InnoDB: File (unknown): 'close' returned OS error 209. Cannot continue operation

# 2023-05-25T15:48:34 [1227458] | [rr 1231496 1161967]230525 15:17:04 [rr 1231496 1161970][ERROR] mysqld got signal 6 ;

Query (0x62b000181238): ALTER TABLE `t7` FORCE /* E_R Thread2 QNO 9 CON_ID 16 */

Connection ID (thread ID): 16

Status: KILL_TIMEOUT

(rr) bt

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

#1  0x000055d697360859 in __GI_abort () at abort.c:79

#2  0x000055d694afd497 in os_file_handle_error_cond_exit (name=name@entry=0x0, operation=operation@entry=0x55d695c113c0 "close", should_abort=should_abort@entry=true, on_error_silent=on_error_silent@entry=false)

    at /data/Server/10.6_with_patch/storage/innobase/os/os0file.cc:3033

#3  0x000055d694afd5da in os_file_handle_error (name=name@entry=0x0, operation=operation@entry=0x55d695c113c0 "close") at /data/Server/10.6_with_patch/storage/innobase/os/os0file.cc:205

#4  0x000055d694afd60b in os_file_close_func (file=<optimized out>) at /data/Server/10.6_with_patch/storage/innobase/os/os0file.cc:1456

#5  0x000055d6950a285c in fil_node_t::close (this=this@entry=0x6060001c9d60) at /data/Server/10.6_with_patch/storage/innobase/include/os0file.h:96

#6  0x000055d6950aac8a in fil_space_t::try_to_close (print_info=print_info@entry=true) at /data/Server/10.6_with_patch/storage/innobase/fil/fil0fil.cc:129

#7  0x000055d6950b1484 in fil_node_open_file (node=node@entry=0x6060000fea80) at /data/Server/10.6_with_patch/storage/innobase/fil/fil0fil.cc:427

#8  0x000055d6950b1acd in fil_space_t::prepare_acquired (this=this@entry=0x6120000448c0) at /data/Server/10.6_with_patch/storage/innobase/include/os0file.h:101

#9  0x000055d6950b1e68 in fil_space_t::acquire_and_prepare (this=this@entry=0x6120000448c0) at /data/Server/10.6_with_patch/storage/innobase/fil/fil0fil.cc:711

#10 0x000055d6950b2242 in fil_space_t::acquire (this=0x6120000448c0) at /data/Server/10.6_with_patch/storage/innobase/fil/fil0fil.cc:722

#11 fil_space_extend (space=space@entry=0x6120000448c0, size=size@entry=7) at /data/Server/10.6_with_patch/storage/innobase/fil/fil0fil.cc:724

#12 0x000055d6950edda2 in fsp_try_extend_data_file_with_pages (space=space@entry=0x6120000448c0, page_no=page_no@entry=6, header=header@entry=0x13de2229fdc0, mtr=mtr@entry=0x48ab569eed90)

    at /data/Server/10.6_with_patch/storage/innobase/fsp/fsp0fsp.cc:606

#13 0x000055d6950ee372 in fsp_reserve_free_pages (space=space@entry=0x6120000448c0, header=header@entry=0x13de2229fdc0, size=size@entry=5, mtr=mtr@entry=0x48ab569eed90, n_pages=n_pages@entry=2)

    at /data/Server/10.6_with_patch/storage/innobase/fsp/fsp0fsp.cc:2337

#14 0x000055d6950ef0fd in fsp_reserve_free_extents (n_reserved=n_reserved@entry=0x48ab569eed70, space=0x6120000448c0, n_ext=n_ext@entry=1, alloc_type=alloc_type@entry=FSP_NORMAL, mtr=mtr@entry=0x48ab569eed90, 

    n_pages=n_pages@entry=2) at /data/Server/10.6_with_patch/storage/innobase/fsp/fsp0fsp.cc:2414

#15 0x000055d694e96953 in PageBulk::init (this=this@entry=0x619001595a80) at /data/Server/10.6_with_patch/storage/innobase/btr/btr0bulk.cc:64

#16 0x000055d694e9a9e7 in BtrBulk::insert (this=this@entry=0x6040000046d0, tuple=tuple@entry=0x6310004888b8, level=level@entry=0) at /data/Server/10.6_with_patch/storage/innobase/btr/btr0bulk.cc:1023

#17 0x000055d694c40913 in BtrBulk::insert (tuple=0x6310004888b8, this=0x6040000046d0) at /data/Server/10.6_with_patch/storage/innobase/include/btr0bulk.h:301

#18 row_merge_insert_index_tuples (index=0x61600b374f08, old_table=old_table@entry=0x6180000c7d08, fd=..., block=block@entry=0x0, row_buf=row_buf@entry=0x615000052188, btr_bulk=<optimized out>, 

    table_total_rows=<optimized out>, pct_progress=pct_progress@entry=17.685342388228637, pct_cost=pct_cost@entry=33.333333333333336, crypt_block=<optimized out>, space=<optimized out>, stage=<optimized out>)

    at /data/Server/10.6_with_patch/storage/innobase/row/row0merge.cc:3667

#19 0x000055d694c524f7 in row_merge_read_clustered_index (trx=trx@entry=0x267b1ba2c440, table=table@entry=0x48ab569f2370, old_table=old_table@entry=0x6180000c7d08, new_table=new_table@entry=0x6180002d3508, 

    online=online@entry=true, index=index@entry=0x619001598a78, fts_sort_idx=<optimized out>, psort_info=<optimized out>, files=<optimized out>, key_numbers=<optimized out>, n_index=<optimized out>, 

    defaults=<optimized out>, add_v=<optimized out>, col_map=<optimized out>, add_autoinc=<optimized out>, sequence=..., block=<optimized out>, skip_pk_sort=<optimized out>, tmpfd=<optimized out>, stage=<optimized out>, 

    pct_cost=pct_cost@entry=33.333333333333336, crypt_block=<optimized out>, eval_table=<optimized out>, allow_not_null=<optimized out>, col_collate=<optimized out>)

    at /data/Server/10.6_with_patch/storage/innobase/include/os0file.h:82

#20 0x000055d694c55be9 in row_merge_build_indexes (trx=<optimized out>, old_table=<optimized out>, new_table=new_table@entry=0x6180002d3508, online=<optimized out>, indexes=0x619001598a78, key_numbers=<optimized out>, 

    n_indexes=<optimized out>, table=<optimized out>, defaults=<optimized out>, col_map=<optimized out>, add_autoinc=<optimized out>, sequence=..., skip_pk_sort=<optimized out>, stage=<optimized out>, 

    add_v=<optimized out>, eval_table=<optimized out>, allow_not_null=<optimized out>, col_collate=<optimized out>) at /data/Server/10.6_with_patch/storage/innobase/row/row0merge.cc:4584

#21 0x000055d69491de08 in ha_innobase::inplace_alter_table (this=0x61d000535cb8, altered_table=<optimized out>, ha_alter_info=0x48ab569f1c70) at /usr/include/c++/9/bits/stl_tree.h:1038

#22 0x000055d693895ca4 in handler::ha_inplace_alter_table (ha_alter_info=0x48ab569f1c70, altered_table=0x48ab569f2370, this=<optimized out>) at /data/Server/10.6_with_patch/sql/handler.h:4683

#23 mysql_inplace_alter_table (thd=thd@entry=0x62b00011f218, table_list=<optimized out>, table=table@entry=0x61900159aa98, altered_table=<optimized out>, ha_alter_info=0x48ab569f1c70, target_mdl_request=<optimized out>, 

    ddl_log_state=<optimized out>, trigger_param=<optimized out>, alter_ctx=<optimized out>) at /data/Server/10.6_with_patch/sql/sql_table.cc:7423

#24 0x000055d6938cd25c in mysql_alter_table (thd=thd@entry=0x62b00011f218, new_db=new_db@entry=0x62b000123c48, new_name=new_name@entry=0x62b0001240a0, create_info=0x48ab569f4720, table_list=<optimized out>, 

    table_list@entry=0x62b000181390, recreate_info=<optimized out>, alter_info=<optimized out>, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>, if_exists=<optimized out>)

    at /data/Server/10.6_with_patch/sql/sql_table.cc:10354

#25 0x000055d693a58daa in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x62b00011f218) at /data/Server/10.6_with_patch/sql/structs.h:568

#26 0x000055d6936139d9 in mysql_execute_command (thd=thd@entry=0x62b00011f218, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/10.6_with_patch/sql/sql_parse.cc:6014

#27 0x000055d6935c9ae4 in mysql_parse (thd=thd@entry=0x62b00011f218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x48ab569f6130) at /data/Server/10.6_with_patch/sql/sql_parse.cc:8036

#28 0x000055d6935f8f2a in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62b00011f218, packet=packet@entry=0x6290005be219 "ALTER TABLE `t7` FORCE /* E_R Thread2 QNO 9 CON_ID 16 */ ", 

    packet_length=packet_length@entry=57, blocking=blocking@entry=true) at /data/Server/10.6_with_patch/sql/sql_class.h:1385

#29 0x000055d6935ffd50 in do_command (thd=0x62b00011f218, blocking=blocking@entry=true) at /data/Server/10.6_with_patch/sql/sql_parse.cc:1409

#30 0x000055d693a41fc3 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x608000002eb8, put_in_cache=put_in_cache@entry=true) at /data/Server/10.6_with_patch/sql/sql_connect.cc:1416

#31 0x000055d693a42b0c in handle_one_connection (arg=0x608000002eb8) at /data/Server/10.6_with_patch/sql/sql_connect.cc:1318

#32 0x000039254d707609 in start_thread (arg=<optimized out>) at pthread_create.c:477

#33 0x000055d69745d293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

(rr)

pluto:/data/results/1685024739/TBR-1868$ _RR_TRACE_DIR=./1/rr/ rr replay --mark-stdio

RQG

===

# git clone https://github.com/mleich1/rqg --branch <pick the right branch> RQG

#

# GIT_SHOW: HEAD -> master, origin/master, origin/HEAD 9b710460ff8c54260b0e0649f029efa932aee22c 2023-05-23T14:33:37+02:00

# rqg.pl  : Version 4.2.1 (2022-12)

#

# $RQG_HOME/rqg.pl \

# --duration=300 \

# --queries=10000000 \

# --no_mask \

# --seed=random \

# --rpl_mode=none \

# --engine=InnoDB \

# --gendata=conf/mariadb/innodb_compression_encryption.zz \

# --max_gd_duration=1200 \

# --mysqld=--interactive_timeout=28800 \

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

# --mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \

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

# --mysqld=--net_read_timeout=30 \

# --mysqld=--innodb-open-files=10 \   # <== Important

# --mysqld=--net_write_timeout=60 \

# --mysqld=--innodb-encryption-threads=1 \

# --mysqld=--wait_timeout=28800 \

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

# --mysqld=--slave_net_timeout=60 \

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

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

# --mysqld=--log_bin_trust_function_creators=1 \

# --mysqld=--innodb_page_size=4K \

# --mysqld=--connect_timeout=60 \

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

# --mysqld=--log-output=none \

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

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

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

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

# --mysqld=--sync-binlog=1 \

# --mysqld=--loose-innodb_read_only_compressed=OFF \

# --mysqld=--innodb_undo_tablespaces=16 \

# --mysqld=--loose-plugin-load-add=provider_lz4.so \

# --mysqld=--innodb-buffer-pool-size=5M \

# --mysqld=--log-bin \

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

# --reporters=Backtrace,Deadlock,None \

# --validators=None \

# --grammar=TBR-1868.yy \

# <local settings>