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

Unexpected ER_FILE_NOT_FOUND upon reading from logging table after crash recovery

Details

    • Bug
    • Status: Closed (View Workflow)
    • Critical
    • Resolution: Fixed
    • 10.4(EOL), 10.5, 10.6, 10.11, 11.0(EOL), 11.1(EOL), 11.2(EOL), 11.3(EOL), 11.4
    • 10.5.27, 10.6.20, 10.11.10, 11.2.6, 11.4.4
    • Server
    • None

    Description

      SET GLOBAL log_output="TABLE";
      		 
      CREATE TABLE t (a INT);
      		 
      --let $shutdown_timeout= 0
      		 
      --source include/restart_mysqld.inc
      		 
      DROP TABLE t;
      		 
      SELECT * FROM mysql.general_log;

      10.5 cc5c0eda4c1a516753de238e02a024b0f044b738

      		 
      mysqltest: At line 6: query 'SELECT * FROM mysql.general_log' failed: 1017: Can't find file: './mysql/general_log.CSV' (errno: 2 "No such file or directory")

      The table is of course still there and is readable after REPAIR.

      With some other combinations of queries and startup options different errors can be produced, ranging between more or less expected, such as "Got error 175 "File too short; Expected more data in file" from storage engine CSV", to confusing ones like "Cannot execute statement in a READ ONLY transaction" if the server is running under tx-read-only. I'm not sure whether they all have the same root cause (other than the expected table corruption upon a crash in the absence of automatic recovery), or they would need to be dealt with separately. So far I'll file the one above, as it is the strangest from those I've seen so far.

      Attachments

        Activity

          Ascending order - Click to sort in descending order
          sanja Oleksandr Byelkin added a comment - 

          Thread 6 "mariadbd" hit Breakpoint 1, my_message_sql (error=1017, str=0x7ffff2ffbed0 "Can't find file: './mysql/general_log.CSV' (errno: 2 \"No such file or directory\")", MyFlags=0) at /home/sanja/maria/git/10.5/sql/mysqld.cc:3111
          		 
          (gdb) where
          		 
          #0  my_message_sql (error=1017, str=0x7ffff2ffbed0 "Can't find file: './mysql/general_log.CSV' (errno: 2 \"No such file or directory\")", MyFlags=0) at /home/sanja/maria/git/10.5/sql/mysqld.cc:3111
          		 
          #1  0x0000555556d74816 in my_error (nr=1017, MyFlags=0) at /home/sanja/maria/git/10.5/mysys/my_error.c:124
          		 
          #2  0x000055555633646c in handler::print_error (this=0x7fffd4069630, error=2, errflag=0) at /home/sanja/maria/git/10.5/sql/handler.cc:4379
          		 
          #3  0x00005555560d14b7 in open_table_from_share (thd=0x7fffd4000dc8, share=0x7fffd4062590, alias=0x7fffd40182f0, db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x7fffd4067698, is_create_table=false, partitions_to_open=0x0) at /home/sanja/maria/git/10.5/sql/table.cc:4330
          		 
          #4  0x0000555555eb730c in open_table (thd=0x7fffd4000dc8, table_list=0x7fffd40182a8, ot_ctx=0x7ffff2ffd5f0) at /home/sanja/maria/git/10.5/sql/sql_base.cc:2024
          		 
          #5  0x0000555555ebb355 in open_and_process_table (thd=0x7fffd4000dc8, tables=0x7fffd40182a8, counter=0x7ffff2ffd684, flags=0, prelocking_strategy=0x7ffff2ffd708, has_prelocking_list=false, ot_ctx=0x7ffff2ffd5f0) at /home/sanja/maria/git/10.5/sql/sql_base.cc:3819
          		 
          #6  0x0000555555ebc696 in open_tables (thd=0x7fffd4000dc8, options=..., start=0x7ffff2ffd668, counter=0x7ffff2ffd684, flags=0, prelocking_strategy=0x7ffff2ffd708) at /home/sanja/maria/git/10.5/sql/sql_base.cc:4303
          		 
          #7  0x0000555555ebe766 in open_and_lock_tables (thd=0x7fffd4000dc8, options=..., tables=0x7fffd40182a8, derived=true, flags=0, prelocking_strategy=0x7ffff2ffd708) at /home/sanja/maria/git/10.5/sql/sql_base.cc:5250
          		 
          #8  0x0000555555e702ba in open_and_lock_tables (thd=0x7fffd4000dc8, tables=0x7fffd40182a8, derived=true, flags=0) at /home/sanja/maria/git/10.5/sql/sql_base.h:509
          		 
          #9  0x0000555555f77d1d in execute_sqlcom_select (thd=0x7fffd4000dc8, all_tables=0x7fffd40182a8) at /home/sanja/maria/git/10.5/sql/sql_parse.cc:6359
          		 
          #10 0x0000555555f6eecf in mysql_execute_command (thd=0x7fffd4000dc8) at /home/sanja/maria/git/10.5/sql/sql_parse.cc:4030
          		 
          #11 0x0000555555f7d4fd in mysql_parse (thd=0x7fffd4000dc8, rawbuf=0x7fffd4017ba0 "SELECT * FROM mysql.general_log", length=31, parser_state=0x7ffff2ffe370, is_com_multi=false, is_next_command=false) at /home/sanja/maria/git/10.5/sql/sql_parse.cc:8236
          		 
          #12 0x0000555555f682ee in dispatch_command (command=COM_QUERY, thd=0x7fffd4000dc8, packet=0x7fffd400b759 "SELECT * FROM mysql.general_log", packet_length=31, is_com_multi=false, is_next_command=false) at /home/sanja/maria/git/10.5/sql/sql_parse.cc:1892
          		 
          #13 0x0000555555f66a7d in do_command (thd=0x7fffd4000dc8) at /home/sanja/maria/git/10.5/sql/sql_parse.cc:1376
          		 
          #14 0x00005555561344f3 in do_handle_one_connection (connect=0x555558c0dec8, put_in_cache=true) at /home/sanja/maria/git/10.5/sql/sql_connect.cc:1417
          		 
          #15 0x0000555556134263 in handle_one_connection (arg=0x555558c0dec8) at /home/sanja/maria/git/10.5/sql/sql_connect.cc:1319
          		 
          #16 0x00005555566dea3a in pfs_spawn_thread (arg=0x555558ba7cc8) at /home/sanja/maria/git/10.5/storage/perfschema/pfs.cc:2201
          		 
          #17 0x00007ffff789ca94 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
          		 
          #18 0x00007ffff7929c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

          sanja Oleksandr Byelkin added a comment - Thread 6 "mariadbd" hit Breakpoint 1, my_message_sql (error=1017, str=0x7ffff2ffbed0 "Can't find file: './mysql/general_log.CSV' (errno: 2 \"No such file or directory\")", MyFlags=0) at /home/sanja/maria/git/10.5/sql/mysqld.cc:3111 (gdb) where #0 my_message_sql (error=1017, str=0x7ffff2ffbed0 "Can't find file: './mysql/general_log.CSV' (errno: 2 \"No such file or directory\")", MyFlags=0) at /home/sanja/maria/git/10.5/sql/mysqld.cc:3111 #1 0x0000555556d74816 in my_error (nr=1017, MyFlags=0) at /home/sanja/maria/git/10.5/mysys/my_error.c:124 #2 0x000055555633646c in handler::print_error (this=0x7fffd4069630, error=2, errflag=0) at /home/sanja/maria/git/10.5/sql/handler.cc:4379 #3 0x00005555560d14b7 in open_table_from_share (thd=0x7fffd4000dc8, share=0x7fffd4062590, alias=0x7fffd40182f0, db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x7fffd4067698, is_create_table=false, partitions_to_open=0x0) at /home/sanja/maria/git/10.5/sql/table.cc:4330 #4 0x0000555555eb730c in open_table (thd=0x7fffd4000dc8, table_list=0x7fffd40182a8, ot_ctx=0x7ffff2ffd5f0) at /home/sanja/maria/git/10.5/sql/sql_base.cc:2024 #5 0x0000555555ebb355 in open_and_process_table (thd=0x7fffd4000dc8, tables=0x7fffd40182a8, counter=0x7ffff2ffd684, flags=0, prelocking_strategy=0x7ffff2ffd708, has_prelocking_list=false, ot_ctx=0x7ffff2ffd5f0) at /home/sanja/maria/git/10.5/sql/sql_base.cc:3819 #6 0x0000555555ebc696 in open_tables (thd=0x7fffd4000dc8, options=..., start=0x7ffff2ffd668, counter=0x7ffff2ffd684, flags=0, prelocking_strategy=0x7ffff2ffd708) at /home/sanja/maria/git/10.5/sql/sql_base.cc:4303 #7 0x0000555555ebe766 in open_and_lock_tables (thd=0x7fffd4000dc8, options=..., tables=0x7fffd40182a8, derived=true, flags=0, prelocking_strategy=0x7ffff2ffd708) at /home/sanja/maria/git/10.5/sql/sql_base.cc:5250 #8 0x0000555555e702ba in open_and_lock_tables (thd=0x7fffd4000dc8, tables=0x7fffd40182a8, derived=true, flags=0) at /home/sanja/maria/git/10.5/sql/sql_base.h:509 #9 0x0000555555f77d1d in execute_sqlcom_select (thd=0x7fffd4000dc8, all_tables=0x7fffd40182a8) at /home/sanja/maria/git/10.5/sql/sql_parse.cc:6359 #10 0x0000555555f6eecf in mysql_execute_command (thd=0x7fffd4000dc8) at /home/sanja/maria/git/10.5/sql/sql_parse.cc:4030 #11 0x0000555555f7d4fd in mysql_parse (thd=0x7fffd4000dc8, rawbuf=0x7fffd4017ba0 "SELECT * FROM mysql.general_log", length=31, parser_state=0x7ffff2ffe370, is_com_multi=false, is_next_command=false) at /home/sanja/maria/git/10.5/sql/sql_parse.cc:8236 #12 0x0000555555f682ee in dispatch_command (command=COM_QUERY, thd=0x7fffd4000dc8, packet=0x7fffd400b759 "SELECT * FROM mysql.general_log", packet_length=31, is_com_multi=false, is_next_command=false) at /home/sanja/maria/git/10.5/sql/sql_parse.cc:1892 #13 0x0000555555f66a7d in do_command (thd=0x7fffd4000dc8) at /home/sanja/maria/git/10.5/sql/sql_parse.cc:1376 #14 0x00005555561344f3 in do_handle_one_connection (connect=0x555558c0dec8, put_in_cache=true) at /home/sanja/maria/git/10.5/sql/sql_connect.cc:1417 #15 0x0000555556134263 in handle_one_connection (arg=0x555558c0dec8) at /home/sanja/maria/git/10.5/sql/sql_connect.cc:1319 #16 0x00005555566dea3a in pfs_spawn_thread (arg=0x555558ba7cc8) at /home/sanja/maria/git/10.5/storage/perfschema/pfs.cc:2201 #17 0x00007ffff789ca94 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447 #18 0x00007ffff7929c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78
          sanja Oleksandr Byelkin added a comment - - edited

          The file is really absent:
          (gdb) p share->path
          $1 =

          {str = 0x7fffd4062b48 "./mysql/general_log", length = 19}

          (gdb)

          (gdb) p share->normalized_path.str
          $2 = 0x7fffd4062b48 "./mysql/general_log"
          (gdb)

          sanja@sanja-portable:~/maria/git/10.5$ ls mysql-test/var/mysqld.1/
          		 
          data  mysqld.log  mysqld-slow.log
          		 
          sanja@sanja-portable:~/maria/git/10.5$ ls mysql-test/var/mysqld.1/data/
          		 
          aria_log.00000001  ibdata1      multi-master.info   test
          		 
          aria_log_control   ib_logfile0  mysql
          		 
          ib_buffer_pool     mtr          performance_schema
          		 
          sanja@sanja-portable:~/maria/git/10.5$ ls mysql-test/var/mysqld.1/data/mysql/
          		 
          columns_priv.frm    help_relation.frm       servers.MAI
          		 
          columns_priv.MAD    help_relation.MAD       slow_log.CSM
          		 
          columns_priv.MAI    help_relation.MAI       slow_log.CSV
          		 
          column_stats.frm    help_topic.frm          slow_log.frm
          		 
          column_stats.MAD    help_topic.MAD          tables_priv.frm
          		 
          column_stats.MAI    help_topic.MAI          tables_priv.MAD
          		 
          db.frm              index_stats.frm         tables_priv.MAI
          		 
          db.MAD              index_stats.MAD         table_stats.frm
          		 
          db.MAI              index_stats.MAI         table_stats.MAD
          		 
          event.frm           innodb_index_stats.frm  table_stats.MAI
          		 
          event.MAD           innodb_index_stats.ibd  time_zone.frm
          		 
          event.MAI           innodb_table_stats.frm  time_zone_leap_second.frm
          		 
          func.frm            innodb_table_stats.ibd  time_zone_leap_second.MAD
          		 
          func.MAD            plugin.frm              time_zone_leap_second.MAI
          		 
          func.MAI            plugin.MAD              time_zone.MAD
          		 
          general_log.CSM     plugin.MAI              time_zone.MAI
          		 
          general_log.CSV     proc.frm                time_zone_name.frm
          		 
          general_log.frm     proc.MAD                time_zone_name.MAD
          		 
          global_priv.frm     proc.MAI                time_zone_name.MAI
          		 
          global_priv.MAD     procs_priv.frm          time_zone_transition.frm
          		 
          global_priv.MAI     procs_priv.MAD          time_zone_transition.MAD
          		 
          gtid_slave_pos.frm  procs_priv.MAI          time_zone_transition.MAI
          		 
          gtid_slave_pos.MAD  proxies_priv.frm        time_zone_transition_type.frm
          		 
          gtid_slave_pos.MAI  proxies_priv.MAD        time_zone_transition_type.MAD
          		 
          help_category.frm   proxies_priv.MAI        time_zone_transition_type.MAI
          		 
          help_category.MAD   roles_mapping.frm       transaction_registry.frm
          		 
          help_category.MAI   roles_mapping.MAD       transaction_registry.ibd
          		 
          help_keyword.frm    roles_mapping.MAI       user.frm
          		 
          help_keyword.MAD    servers.frm
          		 
          help_keyword.MAI    servers.MAD
          		 
          sanja@sanja-portable:~/maria/git/10.5$ 
           
          		 
           
          		 
          (gdb) p thd->query()
          		 
          $3 = 0x7fffd4017ba0 "SELECT * FROM mysql.general_log"

          sanja Oleksandr Byelkin added a comment - - edited The file is really absent: (gdb) p share->path $1 = {str = 0x7fffd4062b48 "./mysql/general_log", length = 19} (gdb) (gdb) p share->normalized_path.str $2 = 0x7fffd4062b48 "./mysql/general_log" (gdb) sanja@sanja-portable:~/maria/git/10.5$ ls mysql-test/var/mysqld.1/ data mysqld.log mysqld-slow.log sanja@sanja-portable:~/maria/git/10.5$ ls mysql-test/var/mysqld.1/data/ aria_log.00000001 ibdata1 multi-master.info test aria_log_control ib_logfile0 mysql ib_buffer_pool mtr performance_schema sanja@sanja-portable:~/maria/git/10.5$ ls mysql-test/var/mysqld.1/data/mysql/ columns_priv.frm help_relation.frm servers.MAI columns_priv.MAD help_relation.MAD slow_log.CSM columns_priv.MAI help_relation.MAI slow_log.CSV column_stats.frm help_topic.frm slow_log.frm column_stats.MAD help_topic.MAD tables_priv.frm column_stats.MAI help_topic.MAI tables_priv.MAD db.frm index_stats.frm tables_priv.MAI db.MAD index_stats.MAD table_stats.frm db.MAI index_stats.MAI table_stats.MAD event.frm innodb_index_stats.frm table_stats.MAI event.MAD innodb_index_stats.ibd time_zone.frm event.MAI innodb_table_stats.frm time_zone_leap_second.frm func.frm innodb_table_stats.ibd time_zone_leap_second.MAD func.MAD plugin.frm time_zone_leap_second.MAI func.MAI plugin.MAD time_zone.MAD general_log.CSM plugin.MAI time_zone.MAI general_log.CSV proc.frm time_zone_name.frm general_log.frm proc.MAD time_zone_name.MAD global_priv.frm proc.MAI time_zone_name.MAI global_priv.MAD procs_priv.frm time_zone_transition.frm global_priv.MAI procs_priv.MAD time_zone_transition.MAD gtid_slave_pos.frm procs_priv.MAI time_zone_transition.MAI gtid_slave_pos.MAD proxies_priv.frm time_zone_transition_type.frm gtid_slave_pos.MAI proxies_priv.MAD time_zone_transition_type.MAD help_category.frm proxies_priv.MAI time_zone_transition_type.MAI help_category.MAD roles_mapping.frm transaction_registry.frm help_category.MAI roles_mapping.MAD transaction_registry.ibd help_keyword.frm roles_mapping.MAI user.frm help_keyword.MAD servers.frm help_keyword.MAI servers.MAD sanja@sanja-portable:~/maria/git/10.5$     (gdb) p thd->query() $3 = 0x7fffd4017ba0 "SELECT * FROM mysql.general_log"
          sanja Oleksandr Byelkin added a comment -

          I was not right, the file is here

          sanja Oleksandr Byelkin added a comment - I was not right, the file is here
          sanja Oleksandr Byelkin added a comment - - edited

          I can not read the file becouse crashed bit is set in the descriptor file

          sanja Oleksandr Byelkin added a comment - - edited I can not read the file becouse crashed bit is set in the descriptor file
          sanja Oleksandr Byelkin added a comment -

          The server was not correctly shutdown in the test case (if let it shotdown, i.e. increase shutdown timeout from 0 to something real, there is no error.

          CSV Engineread "crashed" bit and do not want to open the table. So probably error message is misleading.

          sanja Oleksandr Byelkin added a comment - The server was not correctly shutdown in the test case (if let it shotdown, i.e. increase shutdown timeout from 0 to something real, there is no error. CSV Engineread "crashed" bit and do not want to open the table. So probably error message is misleading.
          sanja Oleksandr Byelkin added a comment -

          It looks like something set my_errno so CSV do not want to set its one

          sanja Oleksandr Byelkin added a comment - It looks like something set my_errno so CSV do not want to set its one
          elenst Elena Stepanova added a comment -

          The server was not correctly shutdown in the test case (if let it shotdown, i.e. increase shutdown timeout from 0 to something real, there is no error.

          Yes, because the test implements a crash recovery scenario, as said in the bug summary.

          elenst Elena Stepanova added a comment - The server was not correctly shutdown in the test case (if let it shotdown, i.e. increase shutdown timeout from 0 to something real, there is no error. Yes, because the test implements a crash recovery scenario, as said in the bug summary.
          sanja Oleksandr Byelkin added a comment -

          and I desribe all sequence in one message

          sanja Oleksandr Byelkin added a comment - and I desribe all sequence in one message
          sanja Oleksandr Byelkin added a comment -

          1) CSV doing wrong correct way to set my_errno
          2) it is better to reset my_errno as we sent resul to the client to avoid it be absolute junk for the next command

          sanja Oleksandr Byelkin added a comment - 1) CSV doing wrong correct way to set my_errno 2) it is better to reset my_errno as we sent resul to the client to avoid it be absolute junk for the next command
          sanja Oleksandr Byelkin added a comment - - edited 

           
          		 
          commit 7d93e6bc70de8078d7d821c4a727bb353345fdcc (HEAD -> bb-10.5-MDEV-33373, origin/bb-10.5-MDEV-33373)
          		 
          Author: Sergei Golubchik <serg@mariadb.org>
          		 
          Date:   Thu Sep 19 18:57:37 2024 +0200
          		 
           
          		 
              MDEV-33373 part 2: Unexpected ER_FILE_NOT_FOUND upon reading from logging table after crash recovery
          		 
              
              CSV engine shoud set my_errno if use it.
          		 
           
          		 
          commit 02685acbca12008e8d01b6894a99d7f034275220
          		 
          Author: Oleksandr Byelkin <sanja@mariadb.com>
          		 
          Date:   Thu Sep 19 16:51:05 2024 +0200
          		 
           
          		 
              MDEV-33373 part 1: Unexpected ER_FILE_NOT_FOUND upon reading from logging table after crash recovery
          		 
              
              We have found that my_errno can be "passed" to the next commad in some cases.
          		 
              
              It is practically impossible to check/fix all cases of my_errno in the server,
          		 
              plugins and engines so we will reset it as we reset other errors.
          		 
              
              The test case will be fixed by CSV engine fix so will be added with it
          		 
              (see part2).

          sanja Oleksandr Byelkin added a comment - - edited   commit 7d93e6bc70de8078d7d821c4a727bb353345fdcc (HEAD -> bb-10.5-MDEV-33373, origin/bb-10.5-MDEV-33373) Author: Sergei Golubchik <serg@mariadb.org> Date: Thu Sep 19 18:57:37 2024 +0200   MDEV-33373 part 2: Unexpected ER_FILE_NOT_FOUND upon reading from logging table after crash recovery CSV engine shoud set my_errno if use it.   commit 02685acbca12008e8d01b6894a99d7f034275220 Author: Oleksandr Byelkin <sanja@mariadb.com> Date: Thu Sep 19 16:51:05 2024 +0200   MDEV-33373 part 1: Unexpected ER_FILE_NOT_FOUND upon reading from logging table after crash recovery We have found that my_errno can be "passed" to the next commad in some cases. It is practically impossible to check/fix all cases of my_errno in the server, plugins and engines so we will reset it as we reset other errors. The test case will be fixed by CSV engine fix so will be added with it (see part2).
          serg Sergei Golubchik added a comment -

          02685acbc and 7d93e6bc7 are ok to push

          serg Sergei Golubchik added a comment - 02685acbc and 7d93e6bc7 are ok to push

          People

            sanja Oleksandr Byelkin
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            3 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.