Bug #72259 MySQL doesn't show informative error message for read-only filesystem in Linux
Submitted: 7 Apr 2014 6:42 Modified: 8 Apr 2014 19:58
Reporter: Shahriyar Rzayev Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Errors Severity:S1 (Critical)
Version:5.6.16 OS:Linux (Red Hat 4 Tikanga)
Assigned to: CPU Architecture:Any

[7 Apr 2014 6:42] Shahriyar Rzayev
Description:
Dear experts,
i have faced with an interesting situation in my Linux test server.
Will provide all necessary information below:

Linux server information:

>>> print platform.dist(),platform.uname()
('redhat', '4', 'Tikanga') ('Linux', 'bsnew', '2.6.18-308.el5', '#1 SMP Fri Jan 27 17:17:51 EST 2012', 'x86_64', 'x86_64')

After i installed MySQL 5.6.16 from official repo and day after installing..
I just want to start MySQL:

[root@bsnew home]# service mysql start
Starting MySQL.The server quit without updating PID file (/[FAILED]mysql/bsnew.pid).

immediately cat contents of error log:

[root@bsnew home]# cat /var/lib/mysql/bsnew.err
140131 15:47:23 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2014-01-31 15:47:24 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-01-31 15:47:24 25056 [Note] Plugin 'FEDERATED' is disabled.
2014-01-31 15:47:24 25056 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-01-31 15:47:24 25056 [Note] InnoDB: The InnoDB memory heap is disabled
2014-01-31 15:47:24 25056 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-01-31 15:47:24 25056 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-01-31 15:47:24 25056 [Note] InnoDB: Using Linux native AIO
2014-01-31 15:47:24 25056 [Note] InnoDB: Using CPU crc32 instructions
2014-01-31 15:47:24 25056 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2014-01-31 15:47:24 25056 [Note] InnoDB: Completed initialization of buffer pool
2014-01-31 15:47:24 25056 [Note] InnoDB: Highest supported file format is Barracuda.
2014-01-31 15:47:24 25056 [Note] InnoDB: 128 rollback segment(s) are active.
2014-01-31 15:47:24 25056 [Note] InnoDB: Waiting for purge to start
2014-01-31 15:47:24 25056 [Note] InnoDB: 5.6.16 started; log sequence number 1625987
2014-01-31 15:47:24 25056 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 7368022c-8a6d-11e3-8986-005056aa5faa.
2014-01-31 15:47:24 25056 [Note] Server hostname (bind-address): '*'; port: 3306
2014-01-31 15:47:24 25056 [Note] IPv6 is available.
2014-01-31 15:47:24 25056 [Note]   - '::' resolves to '::';
2014-01-31 15:47:24 25056 [Note] Server socket created on IP: '::'.
2014-01-31 15:47:24 25056 [Note] Event Scheduler: Loaded 0 events
2014-01-31 15:47:24 25056 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.16'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
2014-03-14 10:53:22 25056 [Note] /usr/sbin/mysqld: Normal shutdown

2014-03-14 10:53:22 25056 [Note] Giving 0 client threads a chance to die gracefully

2014-03-14 10:53:29 25056 [Note] /usr/sbin/mysqld: Shutdown complete

140314 10:53:30 mysqld_safe mysqld from pid file /var/lib/mysql/bsnew.pid ended
140314 10:53:51 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2014-03-14 10:53:53 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-03-14 10:53:53 3368 [Note] Plugin 'FEDERATED' is disabled.
2014-03-14 10:53:53 3368 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-03-14 10:53:53 3368 [Note] InnoDB: The InnoDB memory heap is disabled
2014-03-14 10:53:53 3368 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-03-14 10:53:53 3368 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-03-14 10:53:53 3368 [Note] InnoDB: Using Linux native AIO
2014-03-14 10:53:53 3368 [Note] InnoDB: Using CPU crc32 instructions
2014-03-14 10:53:53 3368 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2014-03-14 10:53:53 3368 [Note] InnoDB: Completed initialization of buffer pool
2014-03-14 10:53:53 3368 [Note] InnoDB: Highest supported file format is Barracuda.
2014-03-14 10:53:54 3368 [Note] InnoDB: 128 rollback segment(s) are active.
2014-03-14 10:53:54 3368 [Note] InnoDB: Waiting for purge to start
2014-03-14 10:53:54 3368 [Note] InnoDB: 5.6.16 started; log sequence number 1625997
2014-03-14 10:53:54 3368 [Note] Server hostname (bind-address): '*'; port: 3306
2014-03-14 10:53:54 3368 [Note] IPv6 is available.
2014-03-14 10:53:54 3368 [Note]   - '::' resolves to '::';
2014-03-14 10:53:54 3368 [Note] Server socket created on IP: '::'.
2014-03-14 10:53:54 3368 [Note] Event Scheduler: Loaded 0 events
2014-03-14 10:53:54 3368 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.16'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
2014-03-14 10:53:57 3368 [Note] /usr/sbin/mysqld: Normal shutdown

2014-03-14 10:53:57 3368 [Note] Giving 0 client threads a chance to die gracefully
2014-03-14 10:53:57 3368 [Note] Event Scheduler: Purging the queue. 0 events
2014-03-14 10:53:57 3368 [Note] Shutting down slave threads
2014-03-14 10:53:57 3368 [Note] Forcefully disconnecting 0 remaining clients
2014-03-14 10:53:57 3368 [Note] Binlog end
.
.
.
2014-03-14 10:53:57 3368 [Note] InnoDB: FTS optimize thread exiting.
2014-03-14 10:53:57 3368 [Note] InnoDB: Starting shutdown...
2014-03-14 10:53:59 3368 [Note] InnoDB: Shutdown completed; log sequence number 1626007
.
.
.
2014-03-14 10:53:59 3368 [Note] /usr/sbin/mysqld: Shutdown complete

140314 10:53:59 mysqld_safe mysqld from pid file /var/lib/mysql/bsnew.pid ended

As you see there is no error message indicating exact problem that i found.

After investigating deeper , it was clear that something happened with Linux server and it goes to read-only (remounted as read-only).

Buffer I/O error on device sdb1, logical block 1769961
lost page write due to I/O error on sdb1
sd 0:0:1:0: timing out command, waited 360s
sd 0:0:1:0: Unhandled error code
sd 0:0:1:0: SCSI error: return code = 0x06000008
Result: hostbyte=DID_OK driverbyte=DRIVER_TIMEOUT,SUGGEST_OK
mptscsih: ioc0: attempting task abort! (sc=ffff8100b629a6c0)
sd 0:0:1:0:
        command: Write(10): 2a 00 00 d8 15 17 00 04 00 00
mptscsih: ioc0: task abort: SUCCESS (rv=2002) (sc=ffff8100b629a6c0)
Aborting journal on device sdb1.
ext3_abort called.
EXT3-fs error (device sdb1): ext3_journal_start_sb: Detected aborted journal
Remounting filesystem read-only
__journal_remove_journal_head: freeing b_committed_data
EXT3-fs error (device sdb1) in ext3_new_inode: Journal has aborted
ext3_abort called.
EXT3-fs error (device sdb1): ext3_remount: Abort forced by user
ext3_abort called.
EXT3-fs error (device sdb1): ext3_remount: Abort forced by user

So from these, we can say that, MySQL doesn't start because of read-only filesystem (maybe because /tmp that needed while starting?) and again because of read-only it can't write anything to error-log.
So it will be greate that MySQL shows such kind of error with read-only mounted filesystems.

On this server , i have an Oracle 11g so want to connect from sqlplus:

[root@bsnew home]# su - oracle
-bash-3.2$ sqlplus / as sysdba

SQL*Plus: Release 11.2.0.4.0 Production on Mon Apr 7 11:35:10 2014

Copyright (c) 1982, 2013, Oracle.  All rights reserved.

ERROR:
ORA-09925: Unable to create audit trail file
Linux-x86_64 Error: 30: Read-only file system
Additional information: 9925
ORA-09925: Unable to create audit trail file
Linux-x86_64 Error: 30: Read-only file system
Additional information: 9925

So Oracle handles this kind situation.

Please add informative error message for this kind situation , because it takes from me a lot of time to figure out exact reason of problem. For me it was a critical situation.

How to repeat:
Remount file-system ad read-only and try to start MySQL.

Suggested fix:
Adding valuable and descriptive Error Message.
[8 Apr 2014 19:58] Sveta Smirnova
Thank you for the reasonable feature request.
[30 Jul 2015 11:47] OCA Admin
Contribution submitted via Github - Bug #72259 - Filesystem read-only detector 
(*) Contribution by Elshad Aghazade (Github elshadaghazade, mysql-server/pull/24#issuecomment-125584754): I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: git_patch_40954132.txt (text/plain), 2.50 KiB.