Bug #75989 Creation of dict_foreign_err_file fail and crash server if non writable tmpdir
Submitted: 20 Feb 2015 23:19 Modified: 14 Apr 2015 11:49
Reporter: Mauritz Sundell Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7.5 OS:Any
Assigned to: CPU Architecture:Any

[20 Feb 2015 23:19] Mauritz Sundell 
Description:
MySQL server can not start with non writable tmpdir due to innodb need to create a temporary file (dict_foreign_err_file) for keeping latest foreign key error to be used by innodb monitor.

mysqld: Can't create/write to file '/readonly-tmp/ibvUiJ7M' (Errcode: 13 - Permission denied)
2015-02-20T22:51:50.687013Z 0 [ERROR] InnoDB: Unable to create temporary file; errno: 13
2015-02-20 23:51:50 0x7f0e0c116780  InnoDB: Assertion failure in thread 139698308736896 in
 file dict0dict.cc line 1009
InnoDB: Failing assertion: dict_foreign_err_file

In previous versions it was possible to start with non writable tmp.

Also comment about srv_read_only_mode in dict0dict.cc seems outdated:
/* Stream for storing detailed information about the latest foreign key
and unique key errors. Only created if !srv_read_only_mode */

How to repeat:
Start server with a tmpdir, either not existing, readonly, or no inodes left.

mysqld --tmpdir=/readonly-tmp/ ...

Suggested fix:
Remove use of file for storing latest foreign/unique key error in innodb.
Use some method updating some kind of internal memory area instead.
[24 Feb 2015 15:09] Naga Satyanarayana Bodapati 
Posted by developer:
 
I observed that this behaviour is same in all GA version

Testcase:
---------
cat mysql-trunk/mysql-test/t/crash-master.opt 
--tmpdir=/readonly-tmp/ 

cat mysql-trunk/mysql-test/t/crash.test 
--source include/have_innodb.inc
CREATE TABLE t1(a INT) ENGINE=InnoDB;
DROP TABLE t1;

5.5
---
[sabodapa@tyr03]/export/home/tmp/satya/mysql-5.5/bld/mysql-test: ./mtr crash
Logging: /export/home/tmp/satya/mysql-5.5/mysql-test/mysql-test-run.pl  crash
150224 16:05:49 [Note] /export/home/tmp/satya/mysql-5.5/bld/sql/mysqld (mysqld 5.5.44-debug) starting as process 17448 ...
MySQL Version 5.5.44
Checking supported features...
 - skipping SSL, mysqld not compiled with SSL
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/export/home/tmp/satya/mysql-5.5/bld/mysql-test/var'...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 17476, winpid: 17476, exit: 256] died after mysql-test-run waited 0.4 seconds for /export/home/tmp/satya/mysql-5.5/bld/mysql-test/var/run/mysqld.1.pid to be created.
main.crash                               [ fail ]
        Test ended at 2015-02-24 16:05:56

Server log is:
150224 18:05:56 [Note] /export/home/tmp/satya/mysql-5.5/bld/sql/mysqld (mysqld 5.5.44-debug-log) starting as process 17477 ...
150224 18:05:56 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
150224 18:05:56 InnoDB: The InnoDB memory heap is disabled
150224 18:05:56 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150224 18:05:56 InnoDB: Compressed tables use zlib 1.2.3
150224 18:05:56 InnoDB: Using Linux native AIO
/export/home/tmp/satya/mysql-5.5/bld/sql/mysqld: Can't create/write to file '/readonly-tmp/ibgzqket' (Errcode: 2)
150224 18:05:56  InnoDB: Error: unable to create temporary file; errno: 2
150224 18:05:56 [ERROR] Plugin 'InnoDB' init function returned error.
150224 18:05:56 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
150224 18:05:56 [ERROR] Unknown/unsupported storage engine: InnoDB
150224 18:05:56 [ERROR] Aborting

5.6:
----
[sabodapa@tyr03]/export/home/tmp/satya/mysql-5.6/bld/mysql-test: ./mtr crash
Logging: /export/home/tmp/satya/mysql-5.6/mysql-test/mysql-test-run.pl  crash
2015-02-24 16:05:01 17388 [Note] Plugin 'FEDERATED' is disabled.
2015-02-24 16:05:01 17388 [Note] Binlog end
2015-02-24 16:05:01 17388 [Note] Shutting down plugin 'CSV'
2015-02-24 16:05:01 17388 [Note] Shutting down plugin 'MyISAM'
MySQL Version 5.6.23
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
 - WARNING: Using the 'mysql-test/var' symlink
Creating var directory '/export/home/tmp/satya/mysql-5.6/bld/mysql-test/var'...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 17413, winpid: 17413, exit: 256] died after mysql-test-run waited 0.3 seconds for /export/home/tmp/satya/mysql-5.6/bld/mysql-test/var/mysqld.1/data/auto.cnf to be created.
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 17413, winpid: 17413, exit: 256] died after mysql-test-run waited 0.1 seconds for /export/home/tmp/satya/mysql-5.6/bld/mysql-test/var/run/mysqld.1.pid to be created.
main.crash                               [ fail ]
        Test ended at 2015-02-24 16:05:04

Server log is:
2015-02-24 18:05:03 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-02-24 18:05:03 17414 [Note] Plugin 'FEDERATED' is disabled.
2015-02-24 18:05:03 7f98fd835720 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2015-02-24 18:05:03 17414 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-02-24 18:05:03 7f98fd835720 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2015-02-24 18:05:03 7f98fd835720 InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2015-02-24 18:05:03 17414 [Note] InnoDB: The InnoDB memory heap is disabled
2015-02-24 18:05:03 17414 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-02-24 18:05:03 17414 [Note] InnoDB: Memory barrier is not used
2015-02-24 18:05:03 17414 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-02-24 18:05:03 17414 [Note] InnoDB: Using Linux native AIO
2015-02-24 18:05:03 17414 [Note] InnoDB: Not using CPU crc32 instructions
/export/home/tmp/satya/mysql-5.6/bld/sql/mysqld: Can't create/write to file '/readonly-tmp/ibAoT5mO' (Errcode: 2 - No such file or directory)
2015-02-24 18:05:03 7f98fd835720  InnoDB: Error: unable to create temporary file; errno: 2
2015-02-24 18:05:03 17414 [ERROR] Plugin 'InnoDB' init function returned error.
2015-02-24 18:05:03 17414 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2015-02-24 18:05:03 17414 [ERROR] Unknown/unsupported storage engine: InnoDB
2015-02-24 18:05:03 17414 [ERROR] Aborting

2015-02-24 18:05:03 17414 [Note] Binlog end

mysql-trunk (behaviour should be same as 5.7)
---------------------------------------------

[sabodapa@tyr03]/export/home/tmp/satya/mysql-trunk/bld/mysql-test: ./mtr crash
Logging: /export/home/tmp/satya/mysql-trunk/mysql-test/mysql-test-run.pl  crash
MySQL Version 5.8.0
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
 - WARNING: Using the 'mysql-test/var' symlink
Creating var directory '/export/home/tmp/satya/mysql-trunk/bld/mysql-test/var'...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 17897, winpid: 17897, exit: 256] died after mysql-test-run waited 0.4 seconds for /export/home/tmp/satya/mysql-trunk/bld/mysql-test/var/mysqld.1/data/auto.cnf to be created.
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 17897, winpid: 17897, exit: 256] died after mysql-test-run waited 0.1 seconds for /export/home/tmp/satya/mysql-trunk/bld/mysql-test/var/run/mysqld.1.pid to be created.
main.crash                               [ fail ]
        Test ended at 2015-02-24 16:07:16

Server log is:
2015-02-24T15:07:16.671296Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-02-24T15:07:16.672023Z 0 [Warning] Insecure configuration for --secure-file-priv: Data directory is accessible through --secure-file-priv. Consider choosing a different directory.
2015-02-24T15:07:16.672035Z 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory.
2015-02-24T15:07:16.672095Z 0 [Note] /export/home/tmp/satya/mysql-trunk/bld/sql/mysqld (mysqld 5.8.0-m17-debug-log) starting as process 17898 ...
2015-02-24T15:07:16.677936Z 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2015-02-24T15:07:16.677964Z 0 [Note] InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2015-02-24T15:07:16.677977Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-02-24T15:07:16.677986Z 0 [Note] InnoDB: Uses event mutexes
2015-02-24T15:07:16.677997Z 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2015-02-24T15:07:16.678006Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-02-24T15:07:16.678015Z 0 [Note] InnoDB: Using Linux native AIO
2015-02-24T15:07:16.678774Z 0 [Note] InnoDB: Number of pools: 1
2015-02-24T15:07:16.679019Z 0 [Note] InnoDB: Not using CPU crc32 instructions
mysqld: Can't create/write to file '/readonly-tmp/iby0cISs' (Errcode: 2 - No such file or directory)
2015-02-24T15:07:16.679081Z 0 [ERROR] InnoDB: Unable to create temporary file; errno: 2
2015-02-24T15:07:16.679097Z 0 [ERROR] Plugin 'InnoDB' init function returned error.
2015-02-24T15:07:16.679105Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2015-02-24T15:07:16.679118Z 0 [ERROR] Failed to initialize plugins.
2015-02-24T15:07:16.679124Z 0 [ERROR] Aborting

2015-02-24T15:07:16.679134Z 0 [Note] Binlog end
2015-02-24T15:07:16.679210Z 0 [Note] Shutting down plugin 'MyISAM'
2015-02-24T15:07:16.679673Z 0 [Note] Debug sync points hit:                   0
2015-02-24T15:07:16.679682Z 0 [Note] Debug sync points executed:              0
2015-02-24T15:07:16.679687Z 0 [Note] Debug sync points max active per thread: 0
2015-02-24T15:07:16.679694Z 0 [Note] /export/home/tmp/satya/mysql-trunk/bld/sql/mysqld: Shutdown complete

So, I believe this is not a regression.

I would like to know the settings which you have used for mysql-5.6, mysql-5.5
[24 Feb 2015 15:26] Naga Satyanarayana Bodapati 
Posted by developer:
 
If it is proved that it is not regression, then it is a change in behaviour.

Non-writable tmpdir has many implications if used with srv_innodb_read_only mode.
ALTER TABLE could fail, all server operations which used tmpdir would fail.

It is better to ask to writable tmpdir unless innodb is started in read_only mode.
[24 Feb 2015 15:27] Naga Satyanarayana Bodapati 
Posted by developer:
 
Correction: "Non-writable tmpdir has many implications if used with srv_innodb_read_only mode."

to--> Non-writable tmpdir has many implications if NOT used with srv_innodb_read_only mode.
[24 Feb 2015 15:46] Naga Satyanarayana Bodapati 
Posted by developer:
 
If the .opt has --innodb-read-only=1, then there is a regression.

With 5.6, server was started

With 5.7/trunk, assert failure

So I agree this is a regression (with both options --tmpdir=/non-existent/ --innodb-read-only=1)
[24 Feb 2015 15:54] Mauritz Sundell 
Posted by developer:
 
It might be that all new GA versions have this behaviour.
But older GA probably have not, so it is a regression.

And yes, not having a writable tmpdir have implication what can be done.
In application that have managed to run without writable tmpdir with older GA versions, this new bahaviour will come as a surprise.
[24 Feb 2015 16:00] Naga Satyanarayana Bodapati 
Posted by developer:
 
5.7:

diff --git a/storage/innobase/dict/dict0dict.cc b/storage/innobase/dict/dict0dict.cc
index cddcb04..e4fe481 100644
--- a/storage/innobase/dict/dict0dict.cc
+++ b/storage/innobase/dict/dict0dict.cc
@@ -1038,8 +1038,10 @@ dict_init(void)
 	rw_lock_create(dict_operation_lock_key,
 		       &dict_operation_lock, SYNC_DICT_OPERATION);
 
-	dict_foreign_err_file = os_file_create_tmpfile();
-	ut_a(dict_foreign_err_file);
+	if (!srv_read_only_mode) {
+		dict_foreign_err_file = os_file_create_tmpfile();
+		ut_a(dict_foreign_err_file);
+	}
 
 	mutex_create("dict_foreign_err", &dict_foreign_err_mutex);
 }

All the callers of os_file_create_tmpfile():

  File         Function                           Line
0 dict0dict.cc dict_init                          1042 dict_foreign_err_file = os_file_create_tmpfile();
1 lock0lock.cc lock_sys_create                     450 lock_latest_err_file = os_file_create_tmpfile();
2 srv0start.cc innobase_start_or_create_for_mysql 1652 srv_monitor_file = os_file_create_tmpfile();
3 srv0start.cc innobase_start_or_create_for_mysql 1661 srv_dict_tmpfile = os_file_create_tmpfile();
4 srv0start.cc innobase_start_or_create_for_mysql 1669 srv_misc_tmpfile = os_file_create_tmpfile();

More analysis required to avoid the file creation completely.
[24 Feb 2015 16:04] Naga Satyanarayana Bodapati 
Posted by developer:
 
Mauritz,

With --tmpdir=/non-existent/ , the behaviour is same in 5.5,5.6,5.7,trunk

With --tmpdir=/non-existent/ --innodb-read-only=1, the behaviour is not same.
5.6: passes
5.7 & trunk: crashes (assert failure)

So I accept it is a regression but only with --tmpdir=/non-existent/ --innodb-read-only=1
[14 Apr 2015 11:49] Daniel Price 
Posted by developer:
 
Fixed as of the upcoming 5.7.8, 5.8.0 release, and here's the changelog entry:

An assertion was raised on server startup when "InnoDB" tried to create a
temporary file in a non-existent temporary directory ("tmpdir") while in
read-only mode.