Bug #80489 Very misleading log messages upon failures of file operations
Submitted: 24 Feb 2016 7:26 Modified: 24 Feb 2016 7:37
Reporter: Tianyin Xu Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S2 (Serious)
Version:5.7.11 OS:Any
Assigned to: CPU Architecture:Any

[24 Feb 2016 7:26] Tianyin Xu
Description:
One of the most common and misleading error msgs in the MySQL project is,
"Can't find file: 'an_existent_file_path'"

I see so many times this msg confuses the users by telling them MySQL is looking for a file but fails to find it. However, in most cases, this is not true! In fact, the common causes are permission problems, i.e., MySQL does not have permissions to access the files.

Over the years, some of the log stmts are improved by giving the errono and then giving the error text. However, there're still many terrible msgs left, such as the following ones,

/* storage/ndb/src/kernel/blocks/dbdih/printFragfile.cpp */
228     if(stat(filename, &sbuf) != 0)
229     {
230       ndbout << "Could not find file: \"" << filename << "\"" << endl;
231       continue;
232     }

/* storage/ndb/src/kernel/blocks/dbdih/printSysfile.cpp */
145     if(stat(filename, &sbuf) != 0)
146     {
147       ndbout << "Could not find file: \"" << filename << "\"" << endl;
148       continue;
149     }

/* storage/ndb/src/kernel/blocks/print_file.cpp */
 74     if(stat(filename, &sbuf) != 0)
 75     {
 76       ndbout << "Could not find file: \"" << filename << "\"" << endl;
 77       continue;
 78     }

/* storage/ndb/src/common/mgmcommon/ConfigRetriever.cpp */
193   if (access(filename, F_OK))
194   {
195     BaseString err;
196     err.assfmt("Could not find file: '%s'", filename);
197     setError(CR_ERROR, err);
198     return 0;
199   }

Seriously, why can't we just tell users that MySQL encounters error when stat/access the file? There're really too many reasons to fail stat()/access() besides "file cannot be found"... In my experience, permission issues are the most common ones.

 

How to repeat:
To repeat, simply chmod a system file in the datadir, e.g., plugin.db, and then start mysqld, you will see something like, 

"bin/mysqld: Can't find file: './mysql/db.frm' (errno: 13 - Permission denied)"

This one is printed when an open() call fails in open_table_def(), 

 748     if (length == share->normalized_path.length ||
 749         ((file= mysql_file_open(key_file_frm,
 750                                 path, O_RDONLY | O_SHARE, MYF(0))) < 0))
 751       goto err_not_open;
 ...
 833 err_not_open:
 834   if (error && !error_given)
 835   {
 836     share->error= error;
 837     open_table_error(share, error, (share->open_errno= my_errno()), 0);
 838   }

Suggested fix:
In error logs, just precisely tell which file operation (e.g., open, access, stat) fails, rather than tell users something like "can't find the file" etc. I did see people use strace to figure out what was failed inside the box.
[24 Feb 2016 7:37] MySQL Verification Team
Hello Tianyin,

Thank you for the report.

Thanks,
Umesh