[MDEV-372] Table gets fatally corrupted if server crashes during ALTER TABLE, "table doesn't exist" is reported - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 5.5.25, 5.3.7, 5.2.12, 5.1.62, 5.5(EOL), 10.0(EOL), 10.1(EOL), 10.2(EOL)
Fix Version/s: 10.6.2
Component/s: Storage Engine - InnoDB
Labels:
- upstream

Description

If server crashes when a table is being altered, the table might end up in a half-existing state: table files are in place, the table is present in I_S and SHOW TABLES output, but it cannot be accessed.
Sometimes the table just completely disappears.

The provided test case uses an InnoDB table. It is not strictly necessary, the problem is reproducible with MyISAM and Aria too, with InnoDB it just happens considerably faster.
Depending on timing, the test might show that table files still exist, or that they disappeared too.

Reproducible on all of MariaDB 5.1-5.5, and on MySQL also.

Test case:

--source include/have_innodb.inc

--enable_reconnect

--let $run = 50

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

--enable_reconnect

--connection default

--delimiter //

CREATE PROCEDURE pr ()

BEGIN

        DECLARE i INT DEFAULT 1;

        wl_loop: WHILE i <= 10000 DO

                ALTER TABLE t1 CHARACTER SET utf8;

                ALTER TABLE t1 CHARACTER SET latin1;

                SET i = i + 1;

        END WHILE wl_loop;

END //

--delimiter ;

--disable_warnings

DROP TABLE IF EXISTS t1;

--enable_warnings

while ($run)

        --connection default

        --append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect

restart

EOF

        CREATE TABLE t1 (a INT) ENGINE=InnoDB;

        --connection con1

        --send CALL pr

        --connection default

        --sleep 1

        --shutdown_server 0

        --source include/wait_until_disconnected.inc

        --source include/wait_until_connected_again.inc

        --echo # Existing t1* files:

        --list_files $MYSQLTEST_VARDIR/mysqld.1/data/test t1*

        SHOW TABLES;

        SHOW CREATE TABLE t1;

        --connection con1

        --error 0,2013

        --reap

        --dec $run

        DROP TABLE t1;

        REPAIR TABLE mysql.proc;

Variants of the failure:

1. No table files, DROP says there is no table, but CREATE says it already exists:

# Existing t1* files:

SHOW TABLES;

Tables_in_test

DROP TABLE IF EXISTS t1;

Warnings:

Note	1051	Unknown table 't1'

CREATE TABLE t1 (a INT) ENGINE=InnoDB;

query 'CREATE TABLE t1 (a INT) ENGINE=InnoDB' failed: 1050: Table '`test`.`t1`' already exists

2. frm file in place, but SHOW CREATE TABLE says the table doesn't exist:

CREATE TABLE t1 (a INT) ENGINE=InnoDB;

CALL pr;

# Existing t1* files:

t1.frm

SHOW TABLES;

Tables_in_test

t1

SHOW CREATE TABLE t1;

query 'SHOW CREATE TABLE t1' failed: 1146: Table 'test.t1' doesn't exist

Attachments

Issue Links

duplicates

MDEV-11655 Transactional data dictionary

Open

is blocked by

MDEV-14717 RENAME TABLE in InnoDB is not crash-safe

Closed

MDEV-25506 Atomic DDL: .frm file is removed and orphan InnoDB tablespace is left behind upon crash recovery

Closed

Activity

Ascending order - Click to sort in descending order

Michael Widenius added a comment - 2013-04-08 16:52

This is unfortunately a very hard bug to fix.
Michael Ronström started to work on this some 4 years ago, but never finished it.
(Part of the solution was done for partition tables).

To fix this, it's probably 2-3 weeks of work.

Michael Widenius added a comment - 2013-04-08 16:52 This is unfortunately a very hard bug to fix. Michael Ronström started to work on this some 4 years ago, but never finished it. (Part of the solution was done for partition tables). To fix this, it's probably 2-3 weeks of work.

Elena Stepanova added a comment - 2017-01-08 01:01

marko, do you happen to know if it's been fixed in MySQL 8.0? (It's still reproducible with 5.7, as well as with MariaDB 10.x, although somewhat less willingly than with 5.5).

The problem is not entirely artificial, every now and then I hear from users who are stuck with a table which they can't drop because it "does not exist", and can't re-create because "it exists".

Note: To reproduce with 10.x, ALGORITHM=COPY needs to be added to ((ALTER}}.

Elena Stepanova added a comment - 2017-01-08 01:01 marko , do you happen to know if it's been fixed in MySQL 8.0? (It's still reproducible with 5.7, as well as with MariaDB 10.x, although somewhat less willingly than with 5.5). The problem is not entirely artificial, every now and then I hear from users who are stuck with a table which they can't drop because it "does not exist", and can't re-create because "it exists". Note: To reproduce with 10.x, ALGORITHM=COPY needs to be added to ((ALTER}}.

Marko Mäkelä added a comment - 2017-03-14 15:28

MySQL 8.0 might fix this with the Global Data Dictionary.
I have filed MDEV-11655 for a simpler version of a transactional data dictionary. The proposed table mysql.ddl_log should fix this bug by making DDL transactions atomic.

Marko Mäkelä added a comment - 2017-03-14 15:28 MySQL 8.0 might fix this with the Global Data Dictionary. I have filed MDEV-11655 for a simpler version of a transactional data dictionary. The proposed table mysql.ddl_log should fix this bug by making DDL transactions atomic.

Marko Mäkelä added a comment - 2018-02-14 12:00

~~MDEV-14717~~ fixed a problem within InnoDB that could affect the scenario: RENAME operations inside InnoDB were not crash-safe. This would cause an inconsistency between the InnoDB internal data dictionary and the .ibd file names.

The test in the Description employs ALTER TABLE…ALGORITHM=COPY operations. Currently, those operations are executed as multiple transactions within InnoDB, and the .frm files are modified independently of the InnoDB transactions.

Inside InnoDB, there still exist some limitations, such as: only a single CREATE TABLE or DROP TABLE operation per transaction is supported. This forces the ALTER TABLE…ALGORITHM=COPY to use multiple transactions inside InnoDB. That could be fixed by improving the InnoDB undo logging.

It might be possible to fix most of this by introducing another layer of logging around DDL operations, so that each operation can be rolled forward or rolled back on both the .frm file and the storage engines. As far as I can tell, the trickiest part to fix with external logging would be an operation that rebuilds the table, such as:

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

ALTER TABLE t1 ADD COLUMN i INT, ADD INDEX(i), FORCE, ALGORITHM=INPLACE;

Inside InnoDB, the ALTER TABLE operation would be committed and persisted before the control returns to the SQL layer.

Marko Mäkelä added a comment - 2018-02-14 12:00 MDEV-14717 fixed a problem within InnoDB that could affect the scenario: RENAME operations inside InnoDB were not crash-safe. This would cause an inconsistency between the InnoDB internal data dictionary and the .ibd file names. The test in the Description employs ALTER TABLE…ALGORITHM=COPY operations. Currently, those operations are executed as multiple transactions within InnoDB, and the .frm files are modified independently of the InnoDB transactions. Inside InnoDB, there still exist some limitations, such as: only a single CREATE TABLE or DROP TABLE operation per transaction is supported. This forces the ALTER TABLE…ALGORITHM=COPY to use multiple transactions inside InnoDB. That could be fixed by improving the InnoDB undo logging. It might be possible to fix most of this by introducing another layer of logging around DDL operations, so that each operation can be rolled forward or rolled back on both the .frm file and the storage engines. As far as I can tell, the trickiest part to fix with external logging would be an operation that rebuilds the table, such as: CREATE TABLE t1 (a INT PRIMARY KEY ) ENGINE=InnoDB; ALTER TABLE t1 ADD COLUMN i INT , ADD INDEX (i), FORCE , ALGORITHM=INPLACE; Inside InnoDB, the ALTER TABLE operation would be committed and persisted before the control returns to the SQL layer.

Elena Stepanova added a comment - 2018-09-03 12:45 - edited

If we run the same test, but don't let it stop upon the first failing statement, it eventually reveals various side effects. I'm not filing them separately, because they probably fall into the "garbage in, garbage out" category, but it's good to have them searchable, so I'll add them here.

--source include/have_innodb.inc

--disable_abort_on_error

--enable_reconnect

--let $run = 50

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

--enable_reconnect

--connection default

--delimiter //

CREATE PROCEDURE pr ()

BEGIN

        DECLARE i INT DEFAULT 1;

        wl_loop: WHILE i <= 10000 DO

                ALTER TABLE t1 CHARACTER SET utf8, ALGORITHM=COPY;

                ALTER TABLE t1 CHARACTER SET latin1, ALGORITHM=COPY;

                SET i = i + 1;

        END WHILE wl_loop;

END //

--delimiter ;

--disable_warnings

DROP TABLE IF EXISTS t1;

--enable_warnings

while ($run)

        --connection default

        --append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect

restart

EOF

        CREATE TABLE t1 (a INT) ENGINE=InnoDB;

        --connection con1

        --send CALL pr

        --connection default

        --sleep 1

        --shutdown_server 0

        --source include/wait_until_disconnected.inc

        --source include/wait_until_connected_again.inc

        --echo # Existing t1* files:

        --list_files $MYSQLTEST_VARDIR/mysqld.1/data/test t1*

        SHOW TABLES;

        SHOW CREATE TABLE t1;

        --connection con1

        --reap

        --dec $run

        DROP TABLE t1;

        REPAIR TABLE mysql.proc;

10.1 non-debug 288212f489
2018-09-03 15:31:24 7fad55fdcb00 InnoDB: Operating system error number 17 in a file operation.
InnoDB: Error number 17 means 'File exists'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2018-09-03 15:31:24 140382448765696 [ERROR] InnoDB: Cannot create file './test/t1.ibd'

2018-09-03 15:31:24 140382448765696 [ERROR] InnoDB: The file './test/t1.ibd' already exists though the corresponding table did not exist in the InnoDB data dictionary. Have you moved InnoDB .ibd files around without using the SQL commands DISCARD TABLESPACE and IMPORT TABLESPACE, or did mysqld crash in the middle of CREATE TABLE? You can resolve the problem by removing the file './test/t1.ibd' under the 'datadir' of MySQL.

10.1 ASAN 288212f489
==8920==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000008 (pc 0x7f9a788208cf sp 0x7f9a67c10cc0 bp 0x6160000072f8 T23)
#0 0x7f9a788208ce in fil_space_for_table_exists_in_mem(unsigned long, char const, bool, bool, mem_block_info_t, unsigned long, unsigned long) /data/src/10.1/storage/innobase/fil/fil0fil.cc:510
6
#1 0x7f9a787d6461 in dict_load_table(char const*, unsigned long, dict_err_ignore_t) /data/src/10.1/storage/innobase/dict/dict0load.cc:2389
#2 0x7f9a787bbb8e in dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t) /data/src/10.1/storage/innobase/dict/dict0dict.cc:1144
#3 0x7f9a789089b2 in ha_innodb::open(char const*, int, unsigned int) /data/src/10.1/storage/innobase/handler/ha_innodb.cc:5813
#4 0x561861ddcf60 in handler::ha_open(TABLE, char const, int, unsigned int) /data/src/10.1/sql/handler.cc:2533
#5 0x561861ae940e in open_table_from_share(THD, TABLE_SHARE, char const, unsigned int, unsigned int, unsigned int, TABLE, bool) /data/src/10.1/sql/table.cc:2974
#6 0x5618617c52b6 in open_table(THD, TABLE_LIST, Open_table_context*) /data/src/10.1/sql/sql_base.cc:2563
#7 0x5618617d0f4b in open_and_process_table /data/src/10.1/sql/sql_base.cc:4091
#8 0x5618617d0f4b in open_tables(THD, DDL_options_st const&, TABLE_LIST, unsigned int, unsigned int, Prelocking_strategy*) /data/src/10.1/sql/sql_base.cc:4602
#9 0x5618619f56ae in open_tables /data/src/10.1/sql/sql_base.h:510
#10 0x5618619f56ae in mysqld_show_create_get_fields(THD, TABLE_LIST, List<Item>, String) /data/src/10.1/sql/sql_show.cc:1165
#11 0x5618619f7ffb in mysqld_show_create(THD, TABLE_LIST) /data/src/10.1/sql/sql_show.cc:1260
#12 0x5618618c14c4 in mysql_execute_command(THD*) /data/src/10.1/sql/sql_parse.cc:3740
#13 0x5618618d1320 in mysql_parse(THD, char, unsigned int, Parser_state*) /data/src/10.1/sql/sql_parse.cc:7463
#14 0x5618618d8073 in dispatch_command(enum_server_command, THD, char, unsigned int) /data/src/10.1/sql/sql_parse.cc:1495
#15 0x5618618de74f in do_command(THD*) /data/src/10.1/sql/sql_parse.cc:1124
#16 0x561861b84e12 in do_handle_one_connection(THD*) /data/src/10.1/sql/sql_connect.cc:1330
#17 0x561861b85323 in handle_one_connection /data/src/10.1/sql/sql_connect.cc:1242
#18 0x5618624551ae in pfs_spawn_thread /data/src/10.1/storage/perfschema/pfs.cc:1861
#19 0x7f9a8227e493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
#20 0x7f9a8063793e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)

AddressSanitizer can not provide additional info.
SUMMARY: AddressSanitizer: SEGV /data/src/10.1/storage/innobase/fil/fil0fil.cc:5106 fil_space_for_table_exists_in_mem(unsigned long, char const, bool, bool, mem_block_info_t, unsigned long, unsigned long)
Thread T23 created by T0 here:
#0 0x7f9a824b7bba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
#1 0x561862460a05 in spawn_thread_v1 /data/src/10.1/storage/perfschema/pfs.cc:1911

==8920==ABORTING
{noformat:title=10.1 debug 288212f489}
#3 <signal handler called>
#4 0x00007f446ea97e64 in fil_space_for_table_exists_in_mem (id=2384, name=0x7f44776c7130 "test/t1", print_error_if_does_not_exist=false, adjust_space=true, heap=0x7f445e8f2000, table_id=2392, table_flags=1) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:5106
#5 0x00007f446ea72fbb in dict_load_table (name=0x7f44776c7130 "test/t1", cached=1, ignore_err=DICT_ERR_IGNORE_NONE) at /data/src/10.1/storage/innobase/dict/dict0load.cc:2389
#6 0x00007f446ea58e8f in dict_table_open_on_name (table_name=0x7f44776c7130 "test/t1", dict_locked=0, try_drop=1, ignore_err=DICT_ERR_IGNORE_NONE) at /data/src/10.1/storage/innobase/dict/dict0dict.cc:1144
#7 0x00007f446eaea71c in ha_innodb::open (this=0x7f445e88d088, name=0x7f445e8bf960 "./test/t1", mode=2, test_if_locked=18) at /data/src/10.1/storage/innobase/handler/ha_innodb.cc:5813
#8 0x000055d220b93378 in handler::ha_open (this=0x7f445e88d088, table_arg=0x7f445e8cfe70, name=0x7f445e8bf960 "./test/t1", mode=2, test_if_locked=18) at /data/src/10.1/sql/handler.cc:2533
#9 0x000055d220a42652 in open_table_from_share (thd=0x7f44687f7070, share=0x7f445e8bf488, alias=0x7f445e843158 "t1", db_stat=39, prgflag=44, ha_open_flags=18, outparam=0x7f445e8cfe70, is_create_table=false) at /data/src/10.1/sql/table.cc:2974
#10 0x000055d2208e6978 in open_table (thd=0x7f44687f7070, table_list=0x7f445e843160, ot_ctx=0x7f44776c7e20) at /data/src/10.1/sql/sql_base.cc:2563
#11 0x000055d2208e929d in open_and_process_table (thd=0x7f44687f7070, lex=0x7f44687faae0, tables=0x7f445e843160, counter=0x7f44776c7ef4, flags=1024, prelocking_strategy=0x7f44776c7ea0, has_prelocking_list=false, ot_ctx=0x7f44776c7e20) at /data/src/10.1/sql/sql_base.cc:4091
#12 0x000055d2208ea318 in open_tables (thd=0x7f44687f7070, options=..., start=0x7f44776c7ee0, counter=0x7f44776c7ef4, flags=1024, prelocking_strategy=0x7f44776c7ea0) at /data/src/10.1/sql/sql_base.cc:4602
#13 0x000055d22092adbd in open_tables (thd=0x7f44687f7070, tables=0x7f44776c7ee0, counter=0x7f44776c7ef4, flags=1024) at /data/src/10.1/sql/sql_base.h:510
#14 0x000055d2209d7ca9 in mysqld_show_create_get_fields (thd=0x7f44687f7070, table_list=0x7f445e843160, field_list=0x7f44776c81b0, buffer=0x7f44776c81d0) at /data/src/10.1/sql/sql_show.cc:1165
#15 0x000055d2209d82a0 in mysqld_show_create (thd=0x7f44687f7070, table_list=0x7f445e843160) at /data/src/10.1/sql/sql_show.cc:1260
#16 0x000055d220951595 in mysql_execute_command (thd=0x7f44687f7070) at /data/src/10.1/sql/sql_parse.cc:3740
#17 0x000055d22095ccd0 in mysql_parse (thd=0x7f44687f7070, rawbuf=0x7f445e843088 "SHOW CREATE TABLE t1", length=20, parser_state=0x7f44776c95e0) at /data/src/10.1/sql/sql_parse.cc:7463
#18 0x000055d22094b665 in dispatch_command (command=COM_QUERY, thd=0x7f44687f7070, packet=0x7f446deca071 "SHOW CREATE TABLE t1", packet_length=20) at /data/src/10.1/sql/sql_parse.cc:1495
#19 0x000055d22094a3ea in do_command (thd=0x7f44687f7070) at /data/src/10.1/sql/sql_parse.cc:1124
#20 0x000055d220a84835 in do_handle_one_connection (thd_arg=0x7f44687f7070) at /data/src/10.1/sql/sql_connect.cc:1330
#21 0x000055d220a84599 in handle_one_connection (arg=0x7f44687f7070) at /data/src/10.1/sql/sql_connect.cc:1242
#22 0x000055d220e42540 in pfs_spawn_thread (arg=0x7f446deed870) at /data/src/10.1/storage/perfschema/pfs.cc:1861
#23 0x00007f4477359494 in start_thread (arg=0x7f44776cab00) at pthread_create.c:333
#24 0x00007f447571293f in clone () from /lib/x86_64-linux-gnu/libc.so.6

10.2 debug 08d0a2a8cf4
2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Starting crash recovery from checkpoint LSN=8934204
2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/#sql2-1285-9.ibd' with space ID 1295, since the redo log references ./test/#sql2-1285-9.ibd with space ID 1251.
2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 1296, since the redo log references ./test/t1.ibd with space ID 1252.
...
...
2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/#sql-1246_9.ibd' with space ID 924. Another data file called ./test/#sql2-1246-9.ibd exists with the same space ID.
2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/#sql-1246_9.ibd' with space ID 924. Another data file called ./test/#sql2-1246-9.ibd exists with the same space ID.
...
2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 1295. Another data file called ./test/#sql2-1285-9.ibd exists with the same space ID.
2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 1295. Another data file called ./test/#sql2-1285-9.ibd exists with the same space ID.
2018-09-03 15:26:44 139641360583552 [ERROR] InnoDB: Tablespace 1296 was not found at ./test/#sql-1285_9.ibd.
2018-09-03 15:26:44 139641360583552 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore this and to permanently lose all changes to the tablespace.
2018-09-03 15:26:44 139641360583552 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[2239] with error Tablespace not found
2018-09-03 15:26:45 139641360583552 [Note] InnoDB: Starting shutdown...
2018-09-03 15:26:45 139641360583552 [ERROR] Plugin 'InnoDB' init function returned error.
2018-09-03 15:26:45 139641360583552 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.

10.3 debug c03c6adf58
2018-09-03 15:30:08 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=49603013
2018-09-03 15:30:08 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 7798, since the redo log references ./test/t1.ibd with space ID 7766.
2018-09-03 15:30:08 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 7798, since the redo log references ./test/t1.ibd with space ID 7376.
2018-09-03 15:30:08 0 [Note] InnoDB: Ignoring data file './test/#sql2-1a73-9.ibd' with space ID 7488, since the redo log references ./test/#sql2-1a73-9.ibd with space ID 7376.
...
...
2018-09-03 15:30:08 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 7642. Another data file called ./test/#sql2-1a93-9.ibd exists with the same space ID.
2018-09-03 15:30:08 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 7642. Another data file called ./test/#sql2-1a93-9.ibd exists with the same space ID.
...
2018-09-03 15:30:09 0 [Note] InnoDB: Ignoring data file './test/#sql-1ab5_9.ibd' with space ID 7798. Another data file called ./test/#sql2-1ab5-9.ibd exists with the same space ID.
2018-09-03 15:30:09 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 5 row operations to undo
2018-09-03 15:30:09 0 [Note] InnoDB: Trx id counter is 108627
2018-09-03 15:30:09 0 [Note] InnoDB: Starting final batch to recover 18 pages from redo log.
2018-09-03 15:30:10 0 [Note] InnoDB: Rolled back recovered transaction 108626
2018-09-03 15:30:10 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2018-09-03 15:30:10 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
2018-09-03 15:30:10 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
2018-09-03 15:30:10 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql2-166a-9.ibd' OS error: 71
2018-09-03 15:30:10 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2018-09-03 15:30:10 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
2018-09-03 15:30:10 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
2018-09-03 15:30:10 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`#sql2-166a-9``. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html
for how to resolve the issue.
2018-09-03 15:30:10 0 [Warning] InnoDB: Ignoring tablespace for `test`.`#sql2-166a-9` because it could not be opened.
2018-09-03 15:30:10 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2018-09-03 15:30:10 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
2018-09-03 15:30:10 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
2018-09-03 15:30:10 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql2-192e-9.ibd' OS error: 71
2018-09-03 15:30:10 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2018-09-03 15:30:10 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
2018-09-03 15:30:10 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
2018-09-03 15:30:10 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`#sql2-192e-9``. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html
for how to resolve the issue.
2018-09-03 15:30:10 0 [Warning] InnoDB: Ignoring tablespace for `test`.`#sql2-192e-9` because it could not be opened.
2018-09-03 15:30:10 0 [Note] InnoDB: 128 out of 128 rollback segments are active.

Elena Stepanova added a comment - 2018-09-03 12:45 - edited If we run the same test, but don't let it stop upon the first failing statement, it eventually reveals various side effects. I'm not filing them separately, because they probably fall into the "garbage in, garbage out" category, but it's good to have them searchable, so I'll add them here. --source include/have_innodb.inc --disable_abort_on_error --enable_reconnect --let $run = 50 --connect (con1,localhost,root,,) --enable_reconnect --connection default --delimiter // CREATE PROCEDURE pr () BEGIN DECLARE i INT DEFAULT 1; wl_loop: WHILE i <= 10000 DO ALTER TABLE t1 CHARACTER SET utf8, ALGORITHM=COPY; ALTER TABLE t1 CHARACTER SET latin1, ALGORITHM=COPY; SET i = i + 1; END WHILE wl_loop; END // --delimiter ; --disable_warnings DROP TABLE IF EXISTS t1; --enable_warnings while ($run) { --connection default --append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect restart EOF CREATE TABLE t1 (a INT ) ENGINE=InnoDB; --connection con1 --send CALL pr --connection default --sleep 1 --shutdown_server 0 --source include/wait_until_disconnected.inc --source include/wait_until_connected_again.inc --echo # Existing t1* files: --list_files $MYSQLTEST_VARDIR/mysqld.1/data/test t1* SHOW TABLES; SHOW CREATE TABLE t1; --connection con1 --reap --dec $run DROP TABLE t1; REPAIR TABLE mysql.proc; } 10.1 non-debug 288212f489 2018-09-03 15:31:24 7fad55fdcb00 InnoDB: Operating system error number 17 in a file operation. InnoDB: Error number 17 means 'File exists'. InnoDB: Some operating system error numbers are described at InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html 2018-09-03 15:31:24 140382448765696 [ERROR] InnoDB: Cannot create file './test/t1.ibd' 2018-09-03 15:31:24 140382448765696 [ERROR] InnoDB: The file './test/t1.ibd' already exists though the corresponding table did not exist in the InnoDB data dictionary. Have you moved InnoDB .ibd files around without using the SQL commands DISCARD TABLESPACE and IMPORT TABLESPACE, or did mysqld crash in the middle of CREATE TABLE? You can resolve the problem by removing the file './test/t1.ibd' under the 'datadir' of MySQL. 10.1 ASAN 288212f489 ==8920==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000008 (pc 0x7f9a788208cf sp 0x7f9a67c10cc0 bp 0x6160000072f8 T23) #0 0x7f9a788208ce in fil_space_for_table_exists_in_mem(unsigned long, char const*, bool, bool, mem_block_info_t*, unsigned long, unsigned long) /data/src/10.1/storage/innobase/fil/fil0fil.cc:510 6 #1 0x7f9a787d6461 in dict_load_table(char const*, unsigned long, dict_err_ignore_t) /data/src/10.1/storage/innobase/dict/dict0load.cc:2389 #2 0x7f9a787bbb8e in dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t) /data/src/10.1/storage/innobase/dict/dict0dict.cc:1144 #3 0x7f9a789089b2 in ha_innodb::open(char const*, int, unsigned int) /data/src/10.1/storage/innobase/handler/ha_innodb.cc:5813 #4 0x561861ddcf60 in handler::ha_open(TABLE*, char const*, int, unsigned int) /data/src/10.1/sql/handler.cc:2533 #5 0x561861ae940e in open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool) /data/src/10.1/sql/table.cc:2974 #6 0x5618617c52b6 in open_table(THD*, TABLE_LIST*, Open_table_context*) /data/src/10.1/sql/sql_base.cc:2563 #7 0x5618617d0f4b in open_and_process_table /data/src/10.1/sql/sql_base.cc:4091 #8 0x5618617d0f4b in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /data/src/10.1/sql/sql_base.cc:4602 #9 0x5618619f56ae in open_tables /data/src/10.1/sql/sql_base.h:510 #10 0x5618619f56ae in mysqld_show_create_get_fields(THD*, TABLE_LIST*, List<Item>*, String*) /data/src/10.1/sql/sql_show.cc:1165 #11 0x5618619f7ffb in mysqld_show_create(THD*, TABLE_LIST*) /data/src/10.1/sql/sql_show.cc:1260 #12 0x5618618c14c4 in mysql_execute_command(THD*) /data/src/10.1/sql/sql_parse.cc:3740 #13 0x5618618d1320 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.1/sql/sql_parse.cc:7463 #14 0x5618618d8073 in dispatch_command(enum_server_command, THD*, char*, unsigned int) /data/src/10.1/sql/sql_parse.cc:1495 #15 0x5618618de74f in do_command(THD*) /data/src/10.1/sql/sql_parse.cc:1124 #16 0x561861b84e12 in do_handle_one_connection(THD*) /data/src/10.1/sql/sql_connect.cc:1330 #17 0x561861b85323 in handle_one_connection /data/src/10.1/sql/sql_connect.cc:1242 #18 0x5618624551ae in pfs_spawn_thread /data/src/10.1/storage/perfschema/pfs.cc:1861 #19 0x7f9a8227e493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493) #20 0x7f9a8063793e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e) AddressSanitizer can not provide additional info. SUMMARY: AddressSanitizer: SEGV /data/src/10.1/storage/innobase/fil/fil0fil.cc:5106 fil_space_for_table_exists_in_mem(unsigned long, char const*, bool, bool, mem_block_info_t*, unsigned long, unsigned long) Thread T23 created by T0 here: #0 0x7f9a824b7bba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba) #1 0x561862460a05 in spawn_thread_v1 /data/src/10.1/storage/perfschema/pfs.cc:1911 ==8920==ABORTING {noformat:title=10.1 debug 288212f489} #3 <signal handler called> #4 0x00007f446ea97e64 in fil_space_for_table_exists_in_mem (id=2384, name=0x7f44776c7130 "test/t1", print_error_if_does_not_exist=false, adjust_space=true, heap=0x7f445e8f2000, table_id=2392, table_flags=1) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:5106 #5 0x00007f446ea72fbb in dict_load_table (name=0x7f44776c7130 "test/t1", cached=1, ignore_err=DICT_ERR_IGNORE_NONE) at /data/src/10.1/storage/innobase/dict/dict0load.cc:2389 #6 0x00007f446ea58e8f in dict_table_open_on_name (table_name=0x7f44776c7130 "test/t1", dict_locked=0, try_drop=1, ignore_err=DICT_ERR_IGNORE_NONE) at /data/src/10.1/storage/innobase/dict/dict0dict.cc:1144 #7 0x00007f446eaea71c in ha_innodb::open (this=0x7f445e88d088, name=0x7f445e8bf960 "./test/t1", mode=2, test_if_locked=18) at /data/src/10.1/storage/innobase/handler/ha_innodb.cc:5813 #8 0x000055d220b93378 in handler::ha_open (this=0x7f445e88d088, table_arg=0x7f445e8cfe70, name=0x7f445e8bf960 "./test/t1", mode=2, test_if_locked=18) at /data/src/10.1/sql/handler.cc:2533 #9 0x000055d220a42652 in open_table_from_share (thd=0x7f44687f7070, share=0x7f445e8bf488, alias=0x7f445e843158 "t1", db_stat=39, prgflag=44, ha_open_flags=18, outparam=0x7f445e8cfe70, is_create_table=false) at /data/src/10.1/sql/table.cc:2974 #10 0x000055d2208e6978 in open_table (thd=0x7f44687f7070, table_list=0x7f445e843160, ot_ctx=0x7f44776c7e20) at /data/src/10.1/sql/sql_base.cc:2563 #11 0x000055d2208e929d in open_and_process_table (thd=0x7f44687f7070, lex=0x7f44687faae0, tables=0x7f445e843160, counter=0x7f44776c7ef4, flags=1024, prelocking_strategy=0x7f44776c7ea0, has_prelocking_list=false, ot_ctx=0x7f44776c7e20) at /data/src/10.1/sql/sql_base.cc:4091 #12 0x000055d2208ea318 in open_tables (thd=0x7f44687f7070, options=..., start=0x7f44776c7ee0, counter=0x7f44776c7ef4, flags=1024, prelocking_strategy=0x7f44776c7ea0) at /data/src/10.1/sql/sql_base.cc:4602 #13 0x000055d22092adbd in open_tables (thd=0x7f44687f7070, tables=0x7f44776c7ee0, counter=0x7f44776c7ef4, flags=1024) at /data/src/10.1/sql/sql_base.h:510 #14 0x000055d2209d7ca9 in mysqld_show_create_get_fields (thd=0x7f44687f7070, table_list=0x7f445e843160, field_list=0x7f44776c81b0, buffer=0x7f44776c81d0) at /data/src/10.1/sql/sql_show.cc:1165 #15 0x000055d2209d82a0 in mysqld_show_create (thd=0x7f44687f7070, table_list=0x7f445e843160) at /data/src/10.1/sql/sql_show.cc:1260 #16 0x000055d220951595 in mysql_execute_command (thd=0x7f44687f7070) at /data/src/10.1/sql/sql_parse.cc:3740 #17 0x000055d22095ccd0 in mysql_parse (thd=0x7f44687f7070, rawbuf=0x7f445e843088 "SHOW CREATE TABLE t1", length=20, parser_state=0x7f44776c95e0) at /data/src/10.1/sql/sql_parse.cc:7463 #18 0x000055d22094b665 in dispatch_command (command=COM_QUERY, thd=0x7f44687f7070, packet=0x7f446deca071 "SHOW CREATE TABLE t1", packet_length=20) at /data/src/10.1/sql/sql_parse.cc:1495 #19 0x000055d22094a3ea in do_command (thd=0x7f44687f7070) at /data/src/10.1/sql/sql_parse.cc:1124 #20 0x000055d220a84835 in do_handle_one_connection (thd_arg=0x7f44687f7070) at /data/src/10.1/sql/sql_connect.cc:1330 #21 0x000055d220a84599 in handle_one_connection (arg=0x7f44687f7070) at /data/src/10.1/sql/sql_connect.cc:1242 #22 0x000055d220e42540 in pfs_spawn_thread (arg=0x7f446deed870) at /data/src/10.1/storage/perfschema/pfs.cc:1861 #23 0x00007f4477359494 in start_thread (arg=0x7f44776cab00) at pthread_create.c:333 #24 0x00007f447571293f in clone () from /lib/x86_64-linux-gnu/libc.so.6 10.2 debug 08d0a2a8cf4 2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Starting crash recovery from checkpoint LSN=8934204 2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/#sql2-1285-9.ibd' with space ID 1295, since the redo log references ./test/#sql2-1285-9.ibd with space ID 1251. 2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 1296, since the redo log references ./test/t1.ibd with space ID 1252. ... ... 2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/#sql-1246_9.ibd' with space ID 924. Another data file called ./test/#sql2-1246-9.ibd exists with the same space ID. 2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/#sql-1246_9.ibd' with space ID 924. Another data file called ./test/#sql2-1246-9.ibd exists with the same space ID. ... 2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 1295. Another data file called ./test/#sql2-1285-9.ibd exists with the same space ID. 2018-09-03 15:26:44 139641360583552 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 1295. Another data file called ./test/#sql2-1285-9.ibd exists with the same space ID. 2018-09-03 15:26:44 139641360583552 [ERROR] InnoDB: Tablespace 1296 was not found at ./test/#sql-1285_9.ibd. 2018-09-03 15:26:44 139641360583552 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore this and to permanently lose all changes to the tablespace. 2018-09-03 15:26:44 139641360583552 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[2239] with error Tablespace not found 2018-09-03 15:26:45 139641360583552 [Note] InnoDB: Starting shutdown... 2018-09-03 15:26:45 139641360583552 [ERROR] Plugin 'InnoDB' init function returned error. 2018-09-03 15:26:45 139641360583552 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. 10.3 debug c03c6adf58 2018-09-03 15:30:08 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=49603013 2018-09-03 15:30:08 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 7798, since the redo log references ./test/t1.ibd with space ID 7766. 2018-09-03 15:30:08 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 7798, since the redo log references ./test/t1.ibd with space ID 7376. 2018-09-03 15:30:08 0 [Note] InnoDB: Ignoring data file './test/#sql2-1a73-9.ibd' with space ID 7488, since the redo log references ./test/#sql2-1a73-9.ibd with space ID 7376. ... ... 2018-09-03 15:30:08 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 7642. Another data file called ./test/#sql2-1a93-9.ibd exists with the same space ID. 2018-09-03 15:30:08 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 7642. Another data file called ./test/#sql2-1a93-9.ibd exists with the same space ID. ... 2018-09-03 15:30:09 0 [Note] InnoDB: Ignoring data file './test/#sql-1ab5_9.ibd' with space ID 7798. Another data file called ./test/#sql2-1ab5-9.ibd exists with the same space ID. 2018-09-03 15:30:09 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 5 row operations to undo 2018-09-03 15:30:09 0 [Note] InnoDB: Trx id counter is 108627 2018-09-03 15:30:09 0 [Note] InnoDB: Starting final batch to recover 18 pages from redo log. 2018-09-03 15:30:10 0 [Note] InnoDB: Rolled back recovered transaction 108626 2018-09-03 15:30:10 0 [ERROR] InnoDB: Operating system error number 2 in a file operation. 2018-09-03 15:30:10 0 [ERROR] InnoDB: The error means the system cannot find the path specified. 2018-09-03 15:30:10 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them. 2018-09-03 15:30:10 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql2-166a-9.ibd' OS error: 71 2018-09-03 15:30:10 0 [ERROR] InnoDB: Operating system error number 2 in a file operation. 2018-09-03 15:30:10 0 [ERROR] InnoDB: The error means the system cannot find the path specified. 2018-09-03 15:30:10 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them. 2018-09-03 15:30:10 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`#sql2-166a-9``. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue. 2018-09-03 15:30:10 0 [Warning] InnoDB: Ignoring tablespace for `test`.`#sql2-166a-9` because it could not be opened. 2018-09-03 15:30:10 0 [ERROR] InnoDB: Operating system error number 2 in a file operation. 2018-09-03 15:30:10 0 [ERROR] InnoDB: The error means the system cannot find the path specified. 2018-09-03 15:30:10 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them. 2018-09-03 15:30:10 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql2-192e-9.ibd' OS error: 71 2018-09-03 15:30:10 0 [ERROR] InnoDB: Operating system error number 2 in a file operation. 2018-09-03 15:30:10 0 [ERROR] InnoDB: The error means the system cannot find the path specified. 2018-09-03 15:30:10 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them. 2018-09-03 15:30:10 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`#sql2-192e-9``. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue. 2018-09-03 15:30:10 0 [Warning] InnoDB: Ignoring tablespace for `test`.`#sql2-192e-9` because it could not be opened. 2018-09-03 15:30:10 0 [Note] InnoDB: 128 out of 128 rollback segments are active.

Marko Mäkelä added a comment - 2021-05-20 17:12

There are several fixes to DDL crash-safety in MariaDB 10.6, such as ~~MDEV-24589~~, ~~MDEV-18518~~, ~~MDEV-24626~~. I will check this after fixing the last part of ~~MDEV-25506~~, which will correct the way how we delete data files. We currently delete files before the DDL transaction was committed, which is obviously wrong.

I aim to fix the test innodb_fts.crash_recovery,release in 10.6 so that it will not warn anything, no matter at which point during ALTER TABLE the server was killed.

Marko Mäkelä added a comment - 2021-05-20 17:12 There are several fixes to DDL crash-safety in MariaDB 10.6, such as MDEV-24589 , MDEV-18518 , MDEV-24626 . I will check this after fixing the last part of MDEV-25506 , which will correct the way how we delete data files. We currently delete files before the DDL transaction was committed, which is obviously wrong. I aim to fix the test innodb_fts.crash_recovery,release in 10.6 so that it will not warn anything, no matter at which point during ALTER TABLE the server was killed.

Marko Mäkelä added a comment - 2021-06-16 08:29

This seems to be fixed now, after ~~MDEV-25506~~ part 3 corrected the last major problem (we no longer delete any files before the transaction commit has been made durable).

10.6 71964c76fe0d7266103025c31d5b7f5d50854383
The servers were restarted 0 times
Spent 796.839 of 64 seconds executing testcases

Check of testcase failed for: …

Completed: All 13 tests were successful.

I did one more run after adding the missing cleanup:

DROP PROCEDURE pr;

10.6 71964c76fe0d7266103025c31d5b7f5d50854383
The servers were restarted 0 times
Spent 1044.198 of 64 seconds executing testcases

Completed: All 17 tests were successful.

A recent addition to the test innodb_fts.crash_recovery,release is similar to the described one. The server is being killed at an arbitrary phase while 3 ALTER TABLE have been submitted to execution. (The debug version of the test is less interesting, due to DEBUG_SYNC.)

Marko Mäkelä added a comment - 2021-06-16 08:29 This seems to be fixed now, after MDEV-25506 part 3 corrected the last major problem (we no longer delete any files before the transaction commit has been made durable). 10.6 71964c76fe0d7266103025c31d5b7f5d50854383 The servers were restarted 0 times Spent 796.839 of 64 seconds executing testcases Check of testcase failed for: … Completed: All 13 tests were successful. I did one more run after adding the missing cleanup: DROP PROCEDURE pr; 10.6 71964c76fe0d7266103025c31d5b7f5d50854383 The servers were restarted 0 times Spent 1044.198 of 64 seconds executing testcases Completed: All 17 tests were successful. A recent addition to the test innodb_fts.crash_recovery,release is similar to the described one. The server is being killed at an arbitrary phase while 3 ALTER TABLE have been submitted to execution. (The debug version of the test is less interesting, due to DEBUG_SYNC .)

People

Assignee:: Marko Mäkelä

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 8 Start watching this issue

Dates

Created:: 2012-06-28 05:43

Updated:: 2021-06-16 08:29

Resolved:: 2021-06-16 08:29

Git Integration

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

MariaDB Server