Bug #84708 mysqld fills up error logs with [ERROR] Error in accept: Bad file descriptor
Submitted: 29 Jan 2017 23:09 Modified: 24 Apr 2017 18:17
Reporter: Nick Seth-Smith Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Connection Handling Severity:S2 (Serious)
Version:5.7.17 OS:Linux (Ubuntu)
Assigned to: CPU Architecture:Any

[29 Jan 2017 23:09] Nick Seth-Smith
Description:
When mysqld is secured with tcp_wrappers it will close a socket from an unauthorized ip address and them immediately start polling that socket.  This runs in a tight loop generating very large error log files and putting load on the machine.  The server continues to serve authorized connections albeit slowly.

The following is an extract from an strace that demonstrates the issue:

...
socket(PF_INET6, SOCK_STREAM, IPPROTO_TCP) = 20
write(2, "2017-01-29T22:22:45.433033Z 0 [N"..., 72) = 72
setsockopt(20, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(20, SOL_IPV6, IPV6_V6ONLY, [0], 4) = 0
bind(20, {sa_family=AF_INET6, sin6_port=htons(3306), inet_pton(AF_INET6, "::", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 28) = 0
listen(20, 70)                          = 0
fcntl(20, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(20, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
 ...
accept(20, {sa_family=AF_INET6, sin6_port=htons(58332), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 37
rt_sigaction(SIGCHLD, {SIG_DFL, [CHLD], SA_RESTORER|SA_RESTART, 0x7f3ddeac84b0}, {SIG_DFL, [], 0}, 8) = 0
getpeername(37, {sa_family=AF_INET6, sin6_port=htons(58332), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
getsockname(37, {sa_family=AF_INET6, sin6_port=htons(3306), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
open("/etc/hosts.allow", O_RDONLY)      = 38
fstat(38, {st_mode=S_IFREG|0644, st_size=589, ...}) = 0
read(38, "# /etc/hosts.allow: list of host"..., 4096) = 589
read(38, "", 4096)                      = 0
close(38)                               = 0
open("/etc/hosts.deny", O_RDONLY)       = 38
fstat(38, {st_mode=S_IFREG|0644, st_size=704, ...}) = 0
read(38, "# /etc/hosts.deny: list of hosts"..., 4096) = 704
close(38)                               = 0
socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 38
connect(38, {sa_family=AF_LOCAL, sun_path="/dev/log"}, 110) = 0
sendto(38, "<36>Jan 29 14:23:08 mysqld[13052"..., 72, MSG_NOSIGNAL, NULL, 0) = 72
shutdown(20, SHUT_RDWR)                 = 0
close(20)                               = 0

poll([{fd=20, events=POLLIN}, {fd=22, events=POLLIN}], 2, -1) = 1 ([{fd=20, revents=POLLNVAL}])
accept(-1, 0x7ffe6ebd7160, 0x7ffe6ebd70fc) = -1 EBADF (Bad file descriptor)
write(2, "2017-01-29T22:23:08.109451Z 0 [E"..., 75) = 75
 ... rinse and repeat *REALLY* fast!

Note that this occured in 5.7.16 as well as 5.7.17.
me@myhost:/tmp/mysql# uname -a
Linux myhost 4.4.0-57-generic #78-Ubuntu SMP Fri Dec 9 23:50:32 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

How to repeat:
configure hosts.allow and hosts.deny to restrict access from an IP address and then connect to the server from that address.

Suggested fix:
The closed socket should be correctly removed from the list of those being polled.  As a suggestion you might also log the fact that the connection is being closed because of a tcp_wrappers security violation.

Short term work-around:  Make sure that tcp_wrappers is not the tightest security wrapper (i.e. that the hosts.allow and hosts.deny configuration will accept any connection that is allowed past any firewalls and other protection.
[31 Jan 2017 17:21] MySQL Verification Team
Hi!

Usage of tcp wrappers is totally non-researched and not documented. Hence, our manual should contain recommendations on the usage of these daemons.
[3 Feb 2017 14:40] MySQL Verification Team
Turns out that this is a real bug that needs fixing in the code.
[24 Apr 2017 18:17] Paul DuBois
Posted by developer:
 
Noted in 5.7.19, 8.0.2 changelogs.

With mysqld secured by TCP wrappers and the hosts.allow and
hosts.deny files configured to restrict access from an IP address,
connection attempts from that address resulted in too many messages
to the error log.
[28 Jul 2017 23:06] Federico Razzoli
Is it possible that this bug also affects a server which doesn't use TCP wrappers?

I encountered exactly the same symptoms two times on servers with empty hosts.deny and hosts.allow, but unfortunately I am not able to reproduce the bug to provide details.
[1 Aug 2017 9:01] Karthik Kamath Koteshwar
The issue reported in the bug description can not occur
without TCP wrappers. I did not face the above mentioned
issue with TCP wrappers disabled. 

I request you to raise a bug once you have a reproducible
scenario.

Thanks,
Karthik