Bug #72259 MySQL doesn't show informative error message for read-only filesystem in Linux
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.
Portions of this website are copyright © 2001, 2002 The PHP Group
Page generated in 0.055 sec. using MySQL 8.4.7-u6-cloud
Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the
respective copyright holders.
It is not reviewed in advance
by Oracle and does not necessarily represent the opinion of
Oracle or any other party.
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.