[MDEV-18309] #2 InnoDB: Operating system error number 2 in a file operation and InnoDB: Cannot open datafile for read-only upon startup on datadir restored from full backup Created: 2019-01-19  Updated: 2019-04-07  Resolved: 2019-04-07

Status: Closed
Project: MariaDB Server
Component/s: mariabackup, Storage Engine - InnoDB
Affects Version/s: 10.4
Fix Version/s: 10.2.24, 10.3.15, 10.4.5

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Attachments: File mbackup_backup.log     File mysql.err     File trial.log    
Issue Links:
Relates
relates to MDEV-18733 MariaDB slow start after crash recovery Closed

 Description   

Note: Patches for MDEV-18201 and MDEV-18184 should already be in the tree, according to git history.

10.4 10.4 edba047080

 
2019-01-16 23:41:23 0 [Note] InnoDB: New log files created, LSN=37159799
 
2019-01-16 23:41:23 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2019-01-16 23:41:23 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2019-01-16 23:41:23 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2019-01-16 23:41:23 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql-5c90_11.ibd' OS error: 71
 
2019-01-16 23:41:23 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2019-01-16 23:41:23 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2019-01-16 23:41:23 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2019-01-16 23:41:23 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`#sql-5c90_11``. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
 
...

Full error log is attached as mysql.err

The backup datadir before prepare can be found here:
ftp://ftp.askmonty.org/public/mdev18309-backup_before_prepare.tar.gz

The backup log is attached as mbackup_backup.log

To reproduce, unpack the backup datadir, adjust the path to the plugin dir and the encryption key file and run

bin/mariabackup --prepare --target-dir=`pwd`/backup_before_prepare
 
bin/mariabackup --copy-back --target-dir=`pwd`/backup_before_prepare --datadir=`pwd`/data

and start the server with

--innodb-encrypt-tables --innodb-encrypt-log --innodb-encryption-threads=4 --aria-encrypt-tables=1 --encrypt-tmp-disk-tables=1 --file-key-management --file-key-management-filename=/home/travis/mariadb-toolbox/data/keys.txt --plugin-load-add=file_key_management --innodb-compression-algorithm=zlib --innodb-page-size=8K

I have no information yet whether it affects earlier versions.

Notes on the origin of the report


Please note it's not necessarily reproducible this way.

https://travis-ci.org/elenst/travis-tests/jobs/480418805
Tests: elenst-dev 23f517b6dba9c7b542e279d6ab9b1b24c578d6ab
Toolbox: c826c29aaabaf8bc9ba9363b7a9c6427ee9f5810

perl ./runall-new.pl --basedir=/home/travis/server --vardir=/home/travis/logs/vardir --duration=350 --threads=4 --seed=1547681839 --reporters=Backtrace,ErrorLog,Deadlock --skip-gendata --gendata-advanced --views --grammar=conf/mariadb/generic-dml.yy --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=10 --mysqld=--loose-innodb-lock-wait-timeout=5 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --filter=/home/travis/mariadb-toolbox/travis/10.4-combo-filter.ff --mysqld=--innodb-encrypt-tables --mysqld=--innodb-encrypt-log --mysqld=--innodb-encryption-threads=4 --mysqld=--aria-encrypt-tables=1 --mysqld=--encrypt-tmp-disk-tables=1 --mysqld=--file-key-management --mysqld=--file-key-management-filename=/home/travis/mariadb-toolbox/data/keys.txt --mysqld=--plugin-load-add=file_key_management --mysqld=--innodb-compression-algorithm=zlib --mysqld=--innodb-page-size=8K --engine=InnoDB --scenario=MariaBackupFull --redefine=conf/mariadb/alter_table.yy --redefine=conf/mariadb/modules/admin.yy --redefine=conf/mariadb/versioning.yy --redefine=conf/mariadb/sequences.yy

Test log is attached as trial.log

 Comments   
Comment by Vladislav Vaintroub [ 2019-01-19 ]

What is user-visible error?

Comment by Vladislav Vaintroub [ 2019-01-19 ]

marko We do not copy temp files into backup anymore (the only valid operation on restart would be to delete them, if I understand it correctly)
Innodb should not bark if it cannot access a temp file from the old session therefore.

Comment by Elena Stepanova [ 2019-01-19 ]

Errors in the error log are user-visible errors. If they are bogus, they needn't be there.
I don't know if there are further problems after that. I can make the test proceed after hitting these initial errors, but in general, since we recognize the "garbage in, garbage out" concept, I find it pointless.

Comment by Vladislav Vaintroub [ 2019-01-19 ]

This specific message, referring to temporary name ("#sql-something") is bogus. unless marko tells it is not

Comment by Elena Stepanova [ 2019-01-19 ]

It might well be.
I would appreciate if they were removed, then. Suppressing errors selectively in tests significantly increases chances for false negatives, and with corruption-like errors stakes are higher than with regular ones.

Comment by Elena Stepanova [ 2019-02-15 ]

I'm still getting lots of these in 10.4 tests (at least as of February 11th).

Comment by Vladislav Vaintroub [ 2019-04-01 ]

I do not see it anymore with the provided backup. Does it still happen in any of your tests?

Comment by Elena Stepanova [ 2019-04-01 ]

It is still reproducible for me on 10.4 17cbae65 (which is 2 commits before the latest one as of this moment) as described, with additional steps that I didn't mention specifically:

  • before running mariabackup, in backup_before_prepare/backup-my.cnf, modify values of the plugin dir and file_key_management_filename, the former should contain file_key_management plugin, and the latter point at <basedir>/mysql-test/std_data/keys.txt;
  • in the server command line, also modify the path to keys.txt.

Please note that the server still starts. To see the described errors, you need to check the error log.

10.4 17cbae65

 
2019-04-02  2:07:49 0 [Note] InnoDB: innodb_page_size=8192
 
2019-04-02  2:07:49 0 [Note] InnoDB: Using Linux native AIO
 
2019-04-02  2:07:49 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2019-04-02  2:07:49 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2019-04-02  2:07:49 0 [Note] InnoDB: Uses event mutexes
 
2019-04-02  2:07:49 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2019-04-02  2:07:49 0 [Note] InnoDB: Number of pools: 1
 
2019-04-02  2:07:49 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
2019-04-02  2:07:49 0 [Note] mysqld: O_TMPFILE is not supported on /data/bld/10.4/data/tmp (disabling future attempts)
 
2019-04-02  2:07:49 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
 
2019-04-02  2:07:49 0 [Note] InnoDB: Completed initialization of buffer pool
 
2019-04-02  2:07:49 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2019-04-02  2:07:49 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes
 
2019-04-02  2:07:49 0 [Note] InnoDB: Setting log file ./ib_logfile1 size to 50331648 bytes
 
2019-04-02  2:07:49 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
 
2019-04-02  2:07:49 0 [Note] InnoDB: New log files created, LSN=37159799
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql-5c90_11.ibd' OS error: 71
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`#sql-5c90_11``. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
 
2019-04-02  2:07:49 0 [Warning] InnoDB: Ignoring tablespace for `test`.`#sql-5c90_11` because it could not be opened.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql-5c90_e.ibd' OS error: 71
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`#sql-5c90_e``. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
 
2019-04-02  2:07:49 0 [Warning] InnoDB: Ignoring tablespace for `test`.`#sql-5c90_e` because it could not be opened.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql-5c90_11.ibd' OS error: 71
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`#sql-5c90_11``. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
 
2019-04-02  2:07:49 0 [Note] InnoDB: Deleting ./test/#sql-5c90_11.ibd
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql-5c90_e.ibd' OS error: 71
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2019-04-02  2:07:49 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`#sql-5c90_e``. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
 
2019-04-02  2:07:49 0 [Note] InnoDB: Deleting ./test/#sql-5c90_e.ibd
 
2019-04-02  2:07:49 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2019-04-02  2:07:49 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2019-04-02  2:07:49 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2019-04-02  2:07:49 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2019-04-02  2:07:49 0 [Note] InnoDB: Waiting for purge to start
 
2019-04-02  2:07:49 0 [Note] InnoDB: 10.4.4 started; log sequence number 37159948; transaction id 3824
 
2019-04-02  2:07:49 0 [Note] InnoDB: Creating #1 encryption thread id 140026235041536 total threads 4.
 
2019-04-02  2:07:49 0 [Note] InnoDB: Creating #2 encryption thread id 140026226648832 total threads 4.
 
2019-04-02  2:07:49 0 [Note] InnoDB: Creating #3 encryption thread id 140026218256128 total threads 4.
 
2019-04-02  2:07:49 0 [Note] InnoDB: Loading buffer pool(s) from /data/bld/10.4/data/ib_buffer_pool
 
2019-04-02  2:07:49 0 [Note] InnoDB: Creating #4 encryption thread id 140025933068032 total threads 4.
 
2019-04-02  2:07:49 0 [Note] InnoDB: Buffer pool(s) load completed at 190402  2:07:49
 
2019-04-02  2:07:49 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2019-04-02  2:07:49 0 [Note] Server socket created on IP: '::'.
 
2019-04-02  2:07:49 0 [Note] Reading of all Master_info entries succeded
 
2019-04-02  2:07:49 0 [Note] Added new Master_info '' to hash table
 
2019-04-02  2:07:49 0 [Note] /data/bld/10.4/bin/mysqld: ready for connections.
 
Version: '10.4.4-MariaDB-debug'  socket: '/data/bld/10.4/data/tmp/mysql.sock'  port: 3306  Source distribution

Comment by Vladislav Vaintroub [ 2019-04-02 ]

on some reason I can't see any [ERROR]s on Windows, but on Linux, setting breakpoint to ib::error::~error , I get this

#0  ib::error::~error (this=0x7ffffffe7c20, __in_chrg=<optimized out>)
 
    at /home/wlad/server/storage/innobase/ut/ut0ut.cc:747
 
#1  0x0000000008dbddbc in os_file_get_last_error_low (report_all_errors=true, on_error_silent=false)
 
    at /home/wlad/server/storage/innobase/os/os0file.cc:2268
 
#2  0x0000000008dc0f13 in os_file_get_last_error (report_all_errors=true)
 
    at /home/wlad/server/storage/innobase/os/os0file.cc:4997
 
#3  0x0000000009035104 in Datafile::open_read_only (this=0x7ffffffe8040, strict=true)
 
    at /home/wlad/server/storage/innobase/fsp/fsp0file.cc:112
 
#4  0x0000000009017ec4 in fil_ibd_open (validate=false, fix_dict=true, purpose=FIL_TYPE_TABLESPACE, id=222, flags=289,
 
    tablename=..., path_in=0xc0ab510 "./test/#sql-5c90_11.ibd", err=0x0)
 
    at /home/wlad/server/storage/innobase/fil/fil0fil.cc:3242
 
#5  0x0000000008fe92c1 in dict_check_sys_tables (validate=false)
 
    at /home/wlad/server/storage/innobase/dict/dict0load.cc:1450
 
#6  0x0000000008fe9576 in dict_check_tablespaces_and_store_max_id (validate=false)
 
    at /home/wlad/server/storage/innobase/dict/dict0load.cc:1508
 
#7  0x0000000008ec377f in srv_start (create_new_db=false) at /home/wlad/server/storage/innobase/srv/srv0start.cc:2151
 
#8  0x0000000008ce8063 in innodb_init (p=0xabce580) at /home/wlad/server/storage/innobase/handler/ha_innodb.cc:4275
 
#9  0x0000000008ac2767 in ha_initialize_handlerton (plugin=0xab076f8) at /home/wlad/server/sql/handler.cc:531
 
#10 0x000000000879a97d in plugin_initialize (tmp_root=0x7ffffffed5a0, plugin=0xab076f8,
 
    argc=0x9fe9ed8 <remaining_argc>, argv=0xaaa4ca8, options_only=false) at /home/wlad/server/sql/sql_plugin.cc:1437
 
#11 0x000000000879b641 in plugin_init (argc=0x9fe9ed8 <remaining_argc>, argv=0xaaa4ca8, flags=0)
 
    at /home/wlad/server/sql/sql_plugin.cc:1719
 
#12 0x000000000865065f in init_server_components () at /home/wlad/server/sql/mysqld.cc:5174
 
#13 0x0000000008651843 in mysqld_main (argc=14, argv=0xaaa4ca8) at /home/wlad/server/sql/mysqld.cc:5703
 
#14 0x000000000864612a in main (argc=13, argv=0x7ffffffedfe8) at /home/wlad/server/sql/main.cc:25

Comment by Marko Mäkelä [ 2019-04-02 ]

Thanks, wlad! I think that we should revamp this code as part of MDEV-18733.

It should not be necessary to try to open all files on startup, and the parameter dict_check_tablespaces_and_store_max_id(validate=true) should be completely redundant, now that the rename operations inside InnoDB are properly logged.

Comment by Marko Mäkelä [ 2019-04-07 ]

We must avoid loading tablespaces or displaying error messages about missing tablespaces in row_mysql_drop_garbage_tables().

Comment by Marko Mäkelä [ 2019-04-07 ]

After this fix, DROP TABLE will no longer complain about a missing tablespace; it will just delete any matching .ibd file, no matter if it was attached to the table.

In MariaDB 10.2, the following message was only reachable during DROP TABLE, and with this fix it was removed:

               ib::error() << "Table " << name << " in InnoDB data dictionary"
 
                       " has tablespace id " << id << ", but the tablespace"
 
                       " with that id has name " << space->name << "."
 
                       " Have you deleted or moved .ibd files?";

In MariaDB 10.3 and 10.4, this message was and will be reachable under other conditions.

Generated at Thu Feb 08 08:43:07 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.