Bug #100407 mysqldump mysql_list_tables silent failure
Submitted: 1 Aug 2020 14:09 Modified: 4 Aug 2020 12:33
Reporter: Mike Griffin Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: mysqldump Command-line Client Severity:S3 (Non-critical)
Version:5.6, 5.7 OS:Linux
Assigned to: CPU Architecture:Any

[1 Aug 2020 14:09] Mike Griffin
Description:
When number of open files is approaching the limit for the mysqld PID, mysqldump can exit without failing despite not returning existing tables for a database, despite getTableName call to mysql_list_tables failing:

# mysqldump mysql > /dev/null; echo $?
mysqldump: Error: 'Out of resources when opening file '/tmp/#sql_7e2_2.MYI' (Errcode: 24 - Too many open files)' when trying to dump tablespaces
0

In this case, you only get the mysqldump headers but no data, while mysqldump will exit 0.

Other mysqldump calls such as "LOCK TABLES" or "show fields from" do not have this problem, as mysqldump exits with return code of 2 in those cases.

The mysqlshow command exits with return code of 1 in this scenario.

How to repeat:
This is hard to reproduce organically but can be contrived by changing the "Max open files" limit in /proc or using prlimit.

In my case, I was most able to repeat after I set the soft file open limit to 74 above the current number of open files, and then run mysqldump --skip-lock-tables --no-tablespaces mysql, eg:

# grep "Max open" /proc/$(cat /var/lib/mysql/host.pid)/limits; lsof -np $(cat /var/lib/mysql/host.pid) | grep -i tmp | wc -l
Max open files            1055                 1055                 files
981

# mysqldump --skip-lock-tables --no-tablespaces mysql; echo $?

When using a mysqldump binary compiled with -DCMAKE_BUILD_TYPE=Debug you will see:

| | >mysql_list_tables

| | | | | >vio_read_buff
| | | | | | enter: sd: 4  buf: 0x7f93cb1a9080  size: 71
| | | | | <vio_read_buff
| | | | | error: Got error: 1018/HY000 (Can't read dir of './mysql/' (errno: 24 "Too many open files"))
| | | | <cli_read_query_result
| | | <mysql_real_query
| | <mysql_list_tables
| | >mysql_real_query
| | | enter: handle: 0x9af580
| | | query: Query = 'UNLOCK TABLES'

Suggested fix:
Hackish approach is to clone append_wild and mysql_list_tables from ./libmysql/libmysql.c in to ./client/mysqldump.c in the style of mysql_query_with_error_report, eg:

  if (mysql_query_with_error_report(mysql, 0, buff))
    DBUG_RETURN(0);
  DBUG_RETURN (mysql_store_result(mysql));

This avoids the problem:

# cmake -DCMAKE_BUILD_TYPE=Debug . && make -j3 mysqldump && ./client/mysqldump -S /var/lib/mysql/mysql.sock --debug="d:t:o,/root/mysqldump.trace" --skip-lock-tables --no-tablespaces mysql; echo $?

mysqldump: Couldn't execute 'show tables': Can't read dir of './mysql/' (errno: 24 "Too many open files") (1018)
2
[3 Aug 2020 13:52] MySQL Verification Team
Hi Mr. Griffin,

Thank you for your bug report.

However, we do have some additional questions.

First of all, please confirm whether you see the same behaviour in mysqldump for MySQL server (ONLY) for versions 5.6, 5.7 and 8.0. We need to know this, because of our internal policy, regarding fixing 5.6 bugs.

Second, are you trying to dump only tables belonging to storage engines, other then InnoDB ????

Also, as far as we understand the report, the only problem that you are reporting is that mysqldump does not return the proper error code on its exit. Please, confirm this fact.

Thank you in advance.
[4 Aug 2020 1:34] Mike Griffin
This can manifest in 5.7 server easily with --show-compatibility-56:

[root@host1 ~]# grep "^Max open files" /proc/$(cat /var/run/mysqld/mysqld.pid)/limits; echo "File descriptors in use:  `lsof -np $(cat /var/run/mysqld/mysqld.pid) |  awk '$4 ~ /^[0-9]/ || $4 ~ /txt/' | wc -l`"
Max open files            5000                 5000                 files
File descriptors in use:  5000

[root@host1 ~]# mysqladmin flush-tables; mysqldump --set-gtid-purged=OFF --skip-lock-tables test; echo $?
-- MySQL dump 10.13  Distrib 5.7.31, for Linux (x86_64)
--
-- Host: localhost    Database: test
-- ------------------------------------------------------
-- Server version	5.7.31-log

/*!40101 SET @OLD_CHARACTER_SET_CLIENT=@@CHARACTER_SET_CLIENT */;
/*!40101 SET @OLD_CHARACTER_SET_RESULTS=@@CHARACTER_SET_RESULTS */;
/*!40101 SET @OLD_COLLATION_CONNECTION=@@COLLATION_CONNECTION */;
/*!40101 SET NAMES utf8 */;
/*!40103 SET @OLD_TIME_ZONE=@@TIME_ZONE */;
/*!40103 SET TIME_ZONE='+00:00' */;
/*!40014 SET @OLD_UNIQUE_CHECKS=@@UNIQUE_CHECKS, UNIQUE_CHECKS=0 */;
/*!40014 SET @OLD_FOREIGN_KEY_CHECKS=@@FOREIGN_KEY_CHECKS, FOREIGN_KEY_CHECKS=0 */;
/*!40101 SET @OLD_SQL_MODE=@@SQL_MODE, SQL_MODE='NO_AUTO_VALUE_ON_ZERO' */;
/*!40111 SET @OLD_SQL_NOTES=@@SQL_NOTES, SQL_NOTES=0 */;
/*!40103 SET TIME_ZONE=@OLD_TIME_ZONE */;

/*!40101 SET SQL_MODE=@OLD_SQL_MODE */;
/*!40014 SET FOREIGN_KEY_CHECKS=@OLD_FOREIGN_KEY_CHECKS */;
/*!40014 SET UNIQUE_CHECKS=@OLD_UNIQUE_CHECKS */;
/*!40101 SET CHARACTER_SET_CLIENT=@OLD_CHARACTER_SET_CLIENT */;
/*!40101 SET CHARACTER_SET_RESULTS=@OLD_CHARACTER_SET_RESULTS */;
/*!40101 SET COLLATION_CONNECTION=@OLD_COLLATION_CONNECTION */;
/*!40111 SET SQL_NOTES=@OLD_SQL_NOTES */;

-- Dump completed on 2020-08-04  0:58:06
0
[root@host1 ~]# my_print_defaults mysqld
--skip-networking
--skip-grant-tables
--datadir=/var/lib/mysql
--socket=/var/lib/mysql/mysql.sock
--log-error=/var/log/mysqld.log
--pid-file=/var/run/mysqld/mysqld.pid
--general-log=1
--show-compatibility-56

[root@host1 ~]# mysqlshow test
mysqlshow: Cannot list tables in test: Can't read dir of './test/' (errno: 24 - Too many open files)

In this case, I have created a single InnoDB table in the `test` database.

[root@host1 ~]# find /var/lib/mysql/test/ -type f
/var/lib/mysql/test/db.opt
/var/lib/mysql/test/t1.frm
/var/lib/mysql/test/t1.ibd

If mysql client from 8.0 is installed (eg on another host) it can also run in to this problem:

[root@host1 ~]# /root/my8/usr/bin/mysqldump --set-gtid-purged=OFF --skip-lock-tables test; echo $?
-- MySQL dump 10.13  Distrib 8.0.21, for Linux (x86_64)
--
-- Host: localhost    Database: test
-- ------------------------------------------------------
-- Server version	5.7.31-log

/*!40101 SET @OLD_CHARACTER_SET_CLIENT=@@CHARACTER_SET_CLIENT */;
/*!40101 SET @OLD_CHARACTER_SET_RESULTS=@@CHARACTER_SET_RESULTS */;
/*!40101 SET @OLD_COLLATION_CONNECTION=@@COLLATION_CONNECTION */;
/*!50503 SET NAMES utf8mb4 */;
/*!40103 SET @OLD_TIME_ZONE=@@TIME_ZONE */;
/*!40103 SET TIME_ZONE='+00:00' */;
/*!40014 SET @OLD_UNIQUE_CHECKS=@@UNIQUE_CHECKS, UNIQUE_CHECKS=0 */;
/*!40014 SET @OLD_FOREIGN_KEY_CHECKS=@@FOREIGN_KEY_CHECKS, FOREIGN_KEY_CHECKS=0 */;
/*!40101 SET @OLD_SQL_MODE=@@SQL_MODE, SQL_MODE='NO_AUTO_VALUE_ON_ZERO' */;
/*!40111 SET @OLD_SQL_NOTES=@@SQL_NOTES, SQL_NOTES=0 */;
/*!40103 SET TIME_ZONE=@OLD_TIME_ZONE */;

/*!40101 SET SQL_MODE=@OLD_SQL_MODE */;
/*!40014 SET FOREIGN_KEY_CHECKS=@OLD_FOREIGN_KEY_CHECKS */;
/*!40014 SET UNIQUE_CHECKS=@OLD_UNIQUE_CHECKS */;
/*!40101 SET CHARACTER_SET_CLIENT=@OLD_CHARACTER_SET_CLIENT */;
/*!40101 SET CHARACTER_SET_RESULTS=@OLD_CHARACTER_SET_RESULTS */;
/*!40101 SET COLLATION_CONNECTION=@OLD_COLLATION_CONNECTION */;
/*!40111 SET SQL_NOTES=@OLD_SQL_NOTES */;

-- Dump completed on 2020-08-04  1:03:36
0

The reason I used --show-compatibility-56 was to work around server opening a file descriptor in performance_schema via "SHOW VARIABLES LIKE 'ndbinfo\_version'"

This would seem to imply that the problem still exists as a race condition (something else acquires that fd between "Query	SHOW VARIABLES LIKE 'ndbinfo\_version'" and "Query	show tables"

I think the problem might not be possible when MySQL 8.0 server is used, since it seems that "show tables" is implemented differently in server, due to data dictionary changes.

So, to answer your questions:

>> please confirm whether you see the same behaviour in mysqldump for MySQL server (ONLY) for versions 5.6, 5.7 and 8.0

> This happens with MySQL Server 5.6 and MySQL Server 5.7. To encounter the problem more easily in 5.7, for demonstration purposes, you can use "--set-gtid-purged=OFF", "--single-transaction" (or --skip-lock-tables), and/or configuring the server with show_compatibility_56. This is optional but convenient

> The problem is in the mysqldump client from 5.6, 5.7, and 5.8.

>> are you trying to dump only tables belonging to storage engines, other then InnoDB ????

> I am using mysqldump against the test database which has a single table, using the InnoDB engine.

> I did create some temporary tables using MyISAM, in another database, which was a simple way to control how many file descriptors were used. If I use InnoDB for these temporary tables, the server runs out of memory or runs in to "[FATAL] Unable to read page [] into the buffer pool after 100 attempts" after having run out of file descriptors.

>> the only problem that you are reporting is that mysqldump does not return the proper error code on its exit

> Yes, the problem is that you take a backup with mysqldump, no data is exported, and mysqldump reports that the backup was correctly executed. My first post shows the bug in mysqldump can be fixed here:

https://github.com/mysql/mysql-server/blob/0f9074a78272aa9671a45ea231f17597584ff6a9/client...

"""
if (!(res = mysql_list_tables(mysql, NullS))) return (nullptr);
"""

This is an unsafe call to:

https://github.com/mysql/mysql-server/blob/0f9074a78272aa9671a45ea231f17597584ff6a9/libmys...

"""
 if (mysql_query(mysql, buff)) return nullptr;
"""

Suggested fix is do something like this:

https://github.com/mysql/mysql-server/blob/0f9074a78272aa9671a45ea231f17597584ff6a9/client...

"""
 Sends a query to server, optionally reads result, prints error message if
  some.
"""

Doing so would still require append_wild from libmysql/libmysql.cc
[4 Aug 2020 12:35] MySQL Verification Team
Hi Mr. Griffin,

We have managed to repeat this behaviour by severely decreasing available file descriptors for our server.

Since this problem affects both 5.6 and 5.7, we are treating this report as a verified bug for the versions 5.6 and 5.7 only.

Verified as reported.