Bug #76020 InnoDB does not report filename in I/O error message for reads
Submitted: 24 Feb 2015 9:23 Modified: 9 May 13:14
Reporter: Valeriy Kravchuk Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.1, 5.5, 5.6, 5.6.24, 5.7.8 OS:Any
Assigned to: Darshan M n CPU Architecture:Any
Tags: innodb, os_file_handle_error

[24 Feb 2015 9:23] Valeriy Kravchuk
Description:
InnoDB may experience an I/O error while reading from some file, but it does not report the name of the file it was trying to read (it is reported as "(unknown)").

See https://bugs.launchpad.net/percona-server/+bug/1412243 for more details on one of cases.

How to repeat:
Code review is enough to find out that for reads file name is never reported:

[openxs@chief mysql-5.6]$ grep -rn os_file_handle_error * | grep 'read'
storage/innobase/os/os0file.cc:947:             os_file_handle_error_no_exit(NULL, "readdir_next_file", FALSE);
storage/innobase/os/os0file.cc:2652:    retry = os_file_handle_error(NULL, "rea ");
storage/innobase/os/os0file.cc:2775:    retry = os_file_handle_error_no_exit(NULL, "read", FALSE);

Compare to errors on "stat", for example:

[openxs@chief mysql-5.6]$ grep -rn os_file_handle_error * | grep 'stat'
storage/innobase/os/os0file.cc:1033:            os_file_handle_error_no_exit(full_path, "stat", FALSE);
storage/innobase/os/os0file.cc:3024:            os_file_handle_error_no_exit(path, "stat", FALSE);
storage/innobase/os/os0file.cc:3052:            os_file_handle_error_no_exit(path, "stat", FALSE);
storage/innobase/os/os0file.cc:3101:            os_file_handle_error_no_exit(path, "stat", FALSE);
storage/innobase/os/os0file.cc:3154:            os_file_handle_error_no_exit(path, "stat", FALSE);
[openxs@chief mysql-5.6]$

Suggested fix:
Report file name in the error message in case of failures/OS errors happening during read. At least for individual .ibd files maybe. This would help a lot with troubleshooting.
[20 May 2015 12:53] Umesh Shastry
Hello valeriy,

Thank you for the bug report.

Thanks,
Umesh
[20 May 2015 12:54] Umesh Shastry
Also, this can be reproduced with injecting faults(other than source code review):

// OS and Build details

[root@cluster-repo ~]# cat /etc/*release
LSB_VERSION=base-4.0-amd64:base-4.0-noarch:core-4.0-amd64:core-4.0-noarch:graphics-4.0-amd64:graphics-4.0-noarch:printing-4.0-amd64:printing-4.0-noarch
Oracle Linux Server release 6.6
Red Hat Enterprise Linux Server release 6.6 (Santiago)
Oracle Linux Server release 6.6
[root@cluster-repo ~]#

[root@cluster-repo mysql-5.6.24]# more docs/INFO_SRC
commit: caae6b64ef613df007609b569b8368c599d5c995
date: 2015-02-03 12:05:54 +0100
build-date: 2015-02-03 18:45:47 +0100
short: caae6b6
branch: mysql-5.6

MySQL source 5.6.24

//  Installed libfiu - Fault injection in userspace (http://blitiri.com.ar/p/libfiu/)

[root@cluster-repo mysql-5.6.24]# which fiu-run
/usr/local/bin/fiu-run

[root@cluster-repo mysql-5.6.24]scripts/mysql_install_db --basedir=/data/ushastry/server/mysql-5.6.24 --datadir=/data/ushastry/server/mysql-5.6.24/76020
[root@cluster-repo mysql-5.6.24]# fiu-run -x -c "enable_random name=posix/io/*,probability=0.05" bin/mysqld  --basedir=/data/ushastry/server/mysql-5.6.24 --datadir=/data/ushastry/server/mysql-5.6.24/76020 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/data/ushastry/server/mysql-5.6.24/76020/log.err 2>&1 &

2015-05-20 19:12:07 31030 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-05-20 19:12:07 31030 [Note] InnoDB: The InnoDB memory heap is disabled
2015-05-20 19:12:07 31030 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-05-20 19:12:07 31030 [Note] InnoDB: Memory barrier is not used
2015-05-20 19:12:07 31030 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-05-20 19:12:07 31030 [Note] InnoDB: Using Linux native AIO
2015-05-20 19:12:07 31030 [Note] InnoDB: Not using CPU crc32 instructions
2015-05-20 19:12:07 31030 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2015-05-20 19:12:07 31030 [Note] InnoDB: Completed initialization of buffer pool
2015-05-20 19:12:07 31030 [ERROR] InnoDB: Error in system call pread(). The operating system error number is 5.
2015-05-20 19:12:07 7f7986efc720  InnoDB: Operating system error number 5 in a file operation.
InnoDB: Error number 5 means 'Input/output error'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2015-05-20 19:12:07 31030 [ERROR] InnoDB: File (unknown): 'read' returned OS error 105. Cannot continue operation
[20 May 2015 13:25] Umesh Shastry
// 5.7.8

[root@cluster-repo mysql-5.7.8]# bin/mysql_install_db --insecure --basedir=/data/ushastry/server/mysql-5.7.8 --datadir=/data/ushastry/server/mysql-5.7.8/76020
fiu-run -x -c "enable_random name=posix/io/*,probability=0.05" bin/mysqld  --basedir=/data/ushastry/server/mysql-5.7.8 --datadir=/data/ushastry/server/mysql-5.7.8/76020 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/data/ushastry/server/mysql-5.7.8/76020/log.err 2>&1 &
2015-05-20 19:53:57 [WARNING] mysql_install_db is deprecated. Please consider switching to mysqld --initialize
2015-05-20 19:54:03 [WARNING] The bootstrap log isn't empty:
2015-05-20 19:54:03 [WARNING] mysqld: [Warning] --bootstrap is deprecated. Please consider using --initialize instead

[root@cluster-repo mysql-5.7.8]# fiu-run -x -c "enable_random name=posix/io/*,probability=0.05" bin/mysqld  --basedir=/data/ushastry/server/mysql-5.7.8 --datadir=/data/ushastry/server/mysql-5.7.8/76020 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/data/ushastry/server/mysql-5.7.8/76020/log.err 2>&1 &
[1] 31254
[root@cluster-repo mysql-5.7.8]# 2015-05-20T14:24:03.819878Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-05-20T14:24:03.819983Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2015-05-20T14:24:03.820070Z 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2015-05-20T14:24:03.820202Z 0 [Note] bin/mysqld (mysqld 5.7.8-rc-enterprise-commercial-advanced-log) starting as process 31254 ...
2015-05-20T14:24:03.821534Z 0 [ERROR] Can't read from messagefile '/data/ushastry/server/mysql-5.7.8/share/english/errmsg.sys'

[1]+  Exit 3                  fiu-run -x -c "enable_random name=posix/io/*,probability=0.05" bin/mysqld --basedir=/data/ushastry/server/mysql-5.7.8 --datadir=/data/ushastry/server/mysql-5.7.8/76020 --core-file --socket=/tmp/mysql_ushastry.sock --port=15000 --log-error=/data/ushastry/server/mysql-5.7.8/76020/log.err 2>&1
[root@cluster-repo mysql-5.7.8]# more /data/ushastry/server/mysql-5.7.8/76020/log.err
2015-05-20T14:24:03.828614Z 0 [Note] InnoDB: PUNCH HOLE support not available
2015-05-20T14:24:03.828673Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-05-20T14:24:03.828686Z 0 [Note] InnoDB: Uses event mutexes
2015-05-20T14:24:03.828697Z 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2015-05-20T14:24:03.828707Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-05-20T14:24:03.828718Z 0 [Note] InnoDB: Using Linux native AIO
2015-05-20T14:24:03.829657Z 0 [Note] InnoDB: Number of pools: 1
2015-05-20T14:24:03.829985Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2015-05-20T14:24:03.861147Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2015-05-20T14:24:03.910297Z 0 [Note] InnoDB: Completed initialization of buffer pool
2015-05-20T14:24:03.917118Z 0 [Note] InnoDB: page_cleaner coordinator priority: -20
2015-05-20T14:24:03.921543Z 0 [Warning] InnoDB: 1048576 bytes should have been read. Only 991100 bytes read. Retrying for the remaining bytes.
2015-05-20T14:24:03.923118Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2015-05-20T14:24:03.923353Z 0 [Warning] InnoDB: Retry attempts for reading partial data failed.
2015-05-20T14:24:03.923368Z 0 [ERROR] InnoDB: Tried to read 512 bytes at offset 1536 was only able to read0
2015-05-20T14:24:03.923393Z 0 [ERROR] InnoDB: Operating system error number 22 in a file operation.
2015-05-20T14:24:03.923431Z 0 [ERROR] InnoDB: Error number 22 means 'Invalid argument'
2015-05-20T14:24:03.923449Z 0 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2015-05-20T14:24:03.923467Z 0 [ERROR] InnoDB: File (unknown): 'read' returned OS error 122. Cannot continue operation
2015-05-20T14:24:03.923484Z 0 [ERROR] InnoDB: Cannot continue operation.
[root@cluster-repo mysql-5.7.8]#
[2 Jul 2015 6:50] Umesh Shastry
Bug #77578 marked as duplicate of this
[9 May 13:14] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 8.0.17 release, and here's the changelog entry:

An error reported during a read operation did not identify the name
of the file that was read. 

Thank you for the bug report.
[24 Jul 12:28] Laurynas Biveinis
Has this really been fixed in 8.0.17? There is no entry in the release notes, and the read code still greps for os_file_handle_error calls with NULL path.
[24 Jul 13:12] Daniel Price
Posted by developer:
 
Correction: 

This bug is fixed in MySQL 8.0.18.

Apologies.