MySQL Bugs: #76020: InnoDB does not report filename in I/O error message for reads

Bug #76020	InnoDB does not report filename in I/O error message for reads
Submitted:	24 Feb 2015 9:23	Modified:	9 May 2019 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

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.

Hello valeriy,

Thank you for the bug report.

Thanks,
Umesh

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

// 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]#

Bug #77578 marked as duplicate of this

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.

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.

Posted by developer:
 
Correction: 

This bug is fixed in MySQL 8.0.18.

Apologies.