Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-31347

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

    XMLWordPrintable

Details

    Description

      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>
      

      Attachments

        1. TBR-1868.cfg
          44 kB
          Matthias Leich
        2. TBR-1868.yy
          0.2 kB
          Matthias Leich

        Issue Links

          Activity

            People

              marko Marko Mäkelä
              mleich Matthias Leich
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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