[MDEV-9673] InnoDB/XtraDB recovery should fail early if datadir is not readable Created: 2016-03-02  Updated: 2020-08-25  Resolved: 2017-11-08

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.0.16, 5.5, 10.0, 10.1
Fix Version/s: 10.2.2, 10.3.0

Type: Bug Priority: Minor
Reporter: Hartmut Holzgraefe Assignee: Marko Mäkelä
Resolution: Fixed Votes: 1
Labels: upstream-fixed
Environment:

Linux


 Description   

If mysqld has no read permission on the data directory it will normally pass InnoDB initialization, but will fail with a clear error message during Aria initialization:

  160302 10:09:27 [ERROR] mysqld: File '/usr/local/mysql-maria-10.0.16/var/' not found (Errcode: 13 "Permission denied")
 
  160302 10:09:27 [ERROR] mysqld: Aria engine: log initialization failed
 
  160302 10:09:27 [ERROR] Plugin 'Aria' init function returned error.
 
  160302 10:09:27 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
 
  160302 10:09:27 [ERROR] Aria engine is not enabled or did not start. The Aria engine must be enabled to continue as mysqld was configured with --with-aria-tmp-tables
 
  160302 10:09:27 [ERROR] Aborting

Here the problem "Permission denied" is clearly stated, and the directory name is given.

If InnoDB requires crash recovery though it will also complain about the permission problem, but is only giving the error number and does not print the directory name:

  160302 10:12:57 [Note] InnoDB: Reading tablespace information from the .ibd files...
 
  2016-03-02 10:12:57 7f12e5e67740  InnoDB: Operating system error number 13 in a file operation.
 
  InnoDB: The error means mysqld does not have the access rights to
 
  InnoDB: the directory.

followed by an error message for every per-table .idb file, e.g.:

160302 10:12:58 [ERROR] InnoDB: Table mysql/gtid_slave_pos in the InnoDB data dictionary has tablespace id 3, but tablespace with that id or name does not exist. Have you deleted or moved .ibd files? This may also be a table created with CREATE TEMPORARY TABLE whose .ibd and .frm files MySQL automatically removed, but the table still exists in the InnoDB internal data dictionary.
 
InnoDB: Please refer to
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadict.html
 
InnoDB: for how to resolve the issue.

This makes the actual permission error messages easy to miss in the flood of .ibd per-table related messages.

How to reproduce:

  • kill running mysqld with kill -9 to force InnoDB recovery
  • chmod u-r $data_dir
  • restart mysqld

IMHO InnoDB crash recovery should already fail hard after the initial permission error, it is pretty clear at that point already that full recovery will not be possible.

Also the initial InnoDB error message should contain the textual error description from perror()/strerror() "Permission denied" and should print the directory path, to make clear what the error is and on which directory it happened.

 Comments   
Comment by Elena Stepanova [ 2016-03-02 ]

Also reproducible on MySQL 5.6, but appears to be fixed in MySQL 5.7 – it now recognizes the lack of access and refuses to proceed:

2016-03-02T17:27:51.677180Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-03-02T17:27:51.677598Z 0 [ERROR] InnoDB: Operating system error number 13 in a file operation.
 
2016-03-02T17:27:51.677613Z 0 [ERROR] InnoDB: The error means mysqld does not have the access rights to the directory.
 
2016-03-02T17:27:51.677627Z 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[2174] with error Generic error
 
2016-03-02T17:27:52.280560Z 0 [ERROR] Plugin 'InnoDB' init function returned error.
 
2016-03-02T17:27:52.280602Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
2016-03-02T17:27:52.280621Z 0 [ERROR] Failed to initialize plugins.

Hopefully, it will be fixed in MariaDB 10.2 by merging corresponding versions of InnoDB/XtraDB.

Comment by Marko Mäkelä [ 2017-03-24 ]

elenst, can you confirm whether this is fixed in 10.2.2 (which merged MySQL 5.7.9)? I think that with my WL#7142 (InnoDB Crash Recovery Improvements in MySQL 5.7), InnoDB recovery is more robust. If any .ibd file that is mentioned by the redo log is missing, we will refuse recovery unless innodb_force_recovery=1 is set. Older InnoDB versions would silently lose changes to files that were not accessible.

Comment by Elena Stepanova [ 2017-06-21 ]

I can confirm that now it behaves as described previously for MySQL 5.7:

10.2 0992be927e1 (pre-10.2.7)

 
Version: '10.2.7-MariaDB'  socket: '/data/tmp/mysql.sock'  port: 3306  Source distribution
 
2017-06-21 20:00:13 140556170985792 [ERROR] mysqld: File '/data/bld/10.2-rel/data/' not found (Errcode: 13 "Permission denied")
 
2017-06-21 20:00:13 140556170985792 [ERROR] mysqld: Aria engine: log initialization failed
 
2017-06-21 20:00:13 140556170985792 [ERROR] Plugin 'Aria' init function returned error.
 
2017-06-21 20:00:13 140556170985792 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
 
2017-06-21 20:00:13 140556170985792 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2017-06-21 20:00:13 140556170985792 [Note] InnoDB: Uses event mutexes
 
2017-06-21 20:00:13 140556170985792 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2017-06-21 20:00:13 140556170985792 [Note] InnoDB: Using Linux native AIO
 
2017-06-21 20:00:13 140556170985792 [Note] InnoDB: Number of pools: 1
 
2017-06-21 20:00:13 140556170985792 [Note] InnoDB: Using SSE2 crc32 instructions
 
2017-06-21 20:00:13 140556170985792 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
 
2017-06-21 20:00:13 140556170985792 [Note] InnoDB: Completed initialization of buffer pool
 
2017-06-21 20:00:13 140555513411328 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2017-06-21 20:00:13 140556170985792 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-06-21 20:00:13 140556170985792 [ERROR] InnoDB: Operating system error number 13 in a file operation.
 
2017-06-21 20:00:13 140556170985792 [ERROR] InnoDB: The error means mysqld does not have the access rights to the directory.
 
2017-06-21 20:00:13 140556170985792 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
 
2017-06-21 20:00:13 140556170985792 [Note] InnoDB: Starting shutdown...
 
2017-06-21 20:00:14 140556170985792 [ERROR] Plugin 'InnoDB' init function returned error.
 
2017-06-21 20:00:14 140556170985792 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
2017-06-21 20:00:14 140556170985792 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-06-21 20:00:14 140556170985792 [ERROR] Unknown/unsupported storage engine: InnoDB
 
2017-06-21 20:00:14 140556170985792 [ERROR] Aborting

It still doesn't print the datadir as mentioned in the initial description, but neither does MySQL; at least the error message isn't that easy to miss anymore.

On a debug build, this refusal to start is followed by Assertion `global_status_var.global_memory_used == 0' failed:

10.2 0992be927e1

 
mysqld: /data/src/10.2/sql/mysqld.cc:2160: void mysqld_exit(int): Assertion `global_status_var.global_memory_used == 0' failed.
 
170621 19:58:41 [ERROR] mysqld got signal 6 ;
 
 
 
#3  <signal handler called>
 
#4  0x00007f1fea4fcfcf in raise () from /lib/x86_64-linux-gnu/libc.so.6
 
#5  0x00007f1fea4fe3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#6  0x00007f1fea4f5e37 in __assert_fail_base () from /lib/x86_64-linux-gnu/libc.so.6
 
#7  0x00007f1fea4f5ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x0000557c13b9013c in mysqld_exit (exit_code=1) at /data/src/10.2/sql/mysqld.cc:2160
 
#9  0x0000557c13b90046 in unireg_abort (exit_code=1) at /data/src/10.2/sql/mysqld.cc:2128
 
#10 0x0000557c13b96b7e in init_server_components () at /data/src/10.2/sql/mysqld.cc:5356
 
#11 0x0000557c13b9788a in mysqld_main (argc=11, argv=0x557c15ff83c8) at /data/src/10.2/sql/mysqld.cc:5843
 
#12 0x0000557c13b8c7b0 in main (argc=11, argv=0x7ffcc82c0818) at /data/src/10.2/sql/main.cc:25

marko, are you okay with the above, or do you want to fix anything else in scope of this issue?

Comment by Julien Fritsch [ 2017-09-06 ]

Hi marko, can I ask you if this bug shouldn't be closed ? I have seen your comment asking Elena if this was fixed in 10.2.2 and she confirmed that it behaves as described previously for MySQL 5.7

Comment by Marko Mäkelä [ 2017-09-06 ]

I think that this should be fixed in MariaDB.
I would not count on Oracle to fix the
Bug#18131883 IMPROVE INNODB ERROR MESSAGES REGARDING FILES
that I think I filed years ago; in any case it was some time before 2014 when my commit comment referred to it.

Comment by Hartmut Holzgraefe [ 2017-11-08 ]

The excessive error messages are reproducible up to MariaDB 10.1.x

With 10.2 they are gone, startup indeed gets terminated right after the first permission problem is detected:

2017-11-08 11:23:04 139692680157376 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-11-08 11:23:04 139692680157376 [ERROR] InnoDB: Operating system error number 13 in a file operation.
 
2017-11-08 11:23:04 139692680157376 [ERROR] InnoDB: The error means mysqld does not have the access rights to the directory.
 
2017-11-08 11:23:04 139692680157376 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
 
2017-11-08 11:23:05 139692680157376 [Note] InnoDB: Starting shutdown...

The original problem was that in function recv_init_crash_recovery() the return value of fil_load_single_table_tablespaces() was ignored, so letting execution continue ...

This part of code has changed substantially in the MySQL 5.7 version of the InnoDB storage engine code we are now using instead of XtraDB.

The lack of printing the actual path related to the permission error code persists, but was never the main focus of this bug report.

So this can be closed at this point IMHO

Comment by Marko Mäkelä [ 2017-11-08 ]

hholzgra, thank you!
In fact, I fixed this in MySQL 5.7.4 in WL#7142, which introduced the MLOG_FILE_NAME record. I even blogged about it back then.

The goal was to make crash recovery more reliable, so that missing data files are no longer silently ignored, and also faster, because applying redo log no longer requires reading the first page of all the *.ibd files.
MariaDB 10.2.2 is based on MySQL 5.7.9.

The error messages related to file I/O should indeed be improved, and the whole I/O layer should be simplified. That is challenging to do in a GA release, and for development releases, there always seem to exist higher-priority tasks.

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