MySQL Bugs: #24761: dropped TCP connections not logged as errors but result in blocked host

Bug #24761	dropped TCP connections not logged as errors but result in blocked host
Submitted:	1 Dec 2006 20:50	Modified:	29 Sep 2008 13:24
Reporter:	Joshua Franklin	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: General	Severity:	S3 (Non-critical)
Version:	5.0.36-BK, 5.0.27, 5.1, 6.0.7	OS:	Linux (Linux (Fedora))
Assigned to:	Assigned Account	CPU Architecture:	Any
Tags:	affects_connectors

Description:
Recently we had set up the monitoring software Nagios to check if a MySQL Server was listening via a simple check that the TCP port was open. Unfortunately this caused the host running the TCP check to be blocked, but even after turning on all logging there was no indication that the dropped TCP connection was seen as a connection error.

How to repeat:
Turn on all logging on MySQL server. From a remote host, repeatedly 
open the MySQL TCP port, but abandon the connection.
Then attempt to connect with a mysql client. You will receive the message:

Host 'host_name' is blocked because of many connection errors.
Unblock with 'mysqladmin flush-hosts'

However, nothing will appear in the logs.

Suggested fix:
Log dropped TCP connections as connection errors.

Thank you for a problem report. Please, read the manual (http://dev.mysql.com/doc/refman/5.0/en/communication-errors.html, http://dev.mysql.com/doc/refman/5.0/en/error-log.html) and try with log_warnings=2.

I already mentioned that we tried that and there was nothing in the log. You can easily verify this yourself with nmap.

Here is a more clear example. On testhost (Fedora Core 6, mysqld 5.0.27) I have added the following to /etc/my.cnf:

log-long-format
log_warnings=2
log-error=/var/log/mysql/error.log
log=/var/log/qmysql.log
log-error=/var/log/mysqld.log
max_connect_errors=1

The following is a sample session from remotehost:

[joshuadf]$ mysql  -p -h testhost TESTDB
Enter password: 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 22 to server version: 5.0.27-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> quit;
Bye

[joshuadf]$ telnet testhost 3306
Trying 192.168.0.30...
Connected to testhost (192.168.0.30).
Escape character is '^]'.
8
5.0.27-logP=}~&<;T,uqYF5rcyX-u'

Bad handshakeConnection closed by foreign host.

[joshuadf]$ 

[joshuadf]$ telnet testhost 3306
Trying 192.168.0.30...
Connected to testhost (192.168.0.30).
Escape character is '^]'.
8
5.0.27-log=0w+l`|q,A1nXOax[>d]'

Bad handshakeConnection closed by foreign host.

[joshuadf]$ telnet testhost 3306 
Trying 192.168.0.30...
Connected to testhost (192.168.0.30).
Escape character is '^]'.
{Host 'remotehost' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'Connection closed by foreign host.

[joshuadf]$ mysql  -p -h testhost TESTDB
Enter password: 
ERROR 1129 (00000): Host 'remotehost' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'

Please note that if the client "mysql" program is used, the error is logged, but
when just "telnet" is used there is no logging. The complete log for this test is:

061204 14:14:55	     21 Connect     root@localhost on 
		     21 Query       flush hosts
		     21 Quit       
061204 14:15:16	     22 Connect     joshuadf@remotehost on TESTDB
		     22 Query       show databases
		     22 Query       show tables
061204 14:15:19	     22 Quit

I have encountered the same problem with 5.0.26

Please, clarify where is the bug here? According to http://dev.mysql.com/doc/refman/5.0/en/blocked-host.html, you are explicitely required your host to be blocked after one interrupted connection request. And you had not aborted conection (that should be logged with log_warnings=2), but rather not yet established connection.

So, this looks like a new feature request to me. Do you agree?

No, it is not a feature request. The bug is that even with 
log_warnings=2 nothing is logged.
http://dev.mysql.com/doc/refman/5.0/en/error-log.html says
"Aborted connections are not logged to the error log unless 
the value is greater than 1." This means that with log_warnings=2
aborted connections should be logged to the error log.

Again, the logging only fails if you are NOT using a mysql 
client program (or jdbc, etc.) but instead just open the 
TCP port with telnet or netcat or nagios. 

If you do not know how to test just use "telnet testhost 3306" 
several times. Nothing appears in the log even with 
log_warnings=2.

Sorry, another way of looking at the bug is that a TCP 
connect should not be counted as a failed attempt if
the connection is not established.

So in the case of a TCP connect ("telnet testhost 3306") either:

--do not count as a failed connection attempt <- bugfix opportunity
--no logging required (current behavior)

OR

--count a TCP connect as a failed connection attempt (current behavior)
--log it when log_warnings=2  <- bugfix opportunity

Verified based on your last comment with 5.0.36-BK on Linux:

openxs@suse:~/dbs/5.0> bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.0.36 Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> show global status like '%abort%';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| Aborted_clients  | 0     |
| Aborted_connects | 0     |
+------------------+-------+
2 rows in set (0.00 sec)

Now, from other shell:

openxs@suse:~> telnet localhost 3306
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
4
5.0.36 ☻   9:W'Xi&} ,☻              hq|?aL7oI^!% Connection closed by foreign ho
st.
openxs@suse:~>

Let's check:

mysql> show global status like '%abort%';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| Aborted_clients  | 0     |
| Aborted_connects | 1     |
+------------------+-------+
2 rows in set (0.00 sec)

mysql> exit
Bye
openxs@suse:~/dbs/5.0> tail var/suse.err
InnoDB: Have you moved InnoDB .ibd files around without using the
InnoDB: commands DISCARD TABLESPACE and IMPORT TABLESPACE?
InnoDB: It is also possible that this is a temporary table #sql...,
InnoDB: and MySQL removed the .ibd file for this.
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.0/en/innodb-troubleshooting.html
InnoDB: for how to resolve the issue.
070214 13:53:21  InnoDB: Started; log sequence number 1 1106293645
070214 13:53:21 [Note] /home/openxs/dbs/5.0/libexec/mysqld: ready for connection
s.
Version: '5.0.36'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution

So, this attempt was treated as aborted connection, but not logged. It is a bug.

Thank you for writing to us. The described behaviour corresponds to the manual:

 If Aborted connections messages appear in the error log, the cause can be any of the following:

    * The client program did not call mysql_close() before exiting.
    * The client had been sleeping more than wait_timeout or interactive_timeout seconds without issuing any requests to the server. See Section 5.2.3, “System Variables”.
    * The client program ended abruptly in the middle of a data transfer.

When any of these things happen, the server increments the Aborted_clients status variable.

The server increments the Aborted_connects status variable when the following things happen:

    * A client doesn't have privileges to connect to a database.
    * A client uses an incorrect password.
    * A connection packet doesn't contain the right information.
    * It takes more than connect_timeout seconds to get a connect packet. See Section 5.2.3, “System Variables”.

As you can see from this explanation, the error message is printed only when one of the three reasons occur: no mysql_close(), connect timeout, data transfer error. All of these errors can occur on an already established connection.
Generally, the idea is to print a warning when something spooky is going
on with the client application. The warning is not printed on an authentication error - this can potentially cause a Denial Of Service: if a mailicious user tries to open and close loads of connections, MySQL Server will have to fight for the 
error log mutex trying to log all the failing attempts.

So, the server does not print anything to the log when a connection that is not yet authenticated is aborted.

I am providing the maintenance team with instructions how to fix this below, but I believe this is not a bug in behaviour - the code works as designed. At best we should clarify this in the manual.

Please feel free to reopen this bug report if you have additional information.

Tim: the function that needs a fix is check_connection().
Search for the call to inc_host_errors() - you will see that no warning is printed to the log there.
If check_connection returns an error, handle_one_connection function terminates
silently, without writing anything to the log:

    if ((error=check_connection(thd)))
    {                                           // Wrong permissions
      if (error > 0)
        net_printf_error(thd, error, sctx->host_or_ip);
#ifdef __NT__
      if (vio_type(net->vio) == VIO_TYPE_NAMEDPIPE)
        my_sleep(1000);                         /* must wait after eof() */
#endif
      statistic_increment(aborted_connects,&LOCK_status);
      goto end_thread;
    }
(Nothing is printed in end_thread label either).

Here's the place that logs the warning - it is alrady after do_command loop, that is, it is executed only if do_command returned an error:

  if (net->error && net->vio != 0 && net->report_error)
    {
      if (!thd->killed && thd->variables.log_warnings > 1)
        sql_print_warning(ER(ER_NEW_ABORTING_CONNECTION),
                          thd->thread_id,(thd->db ? thd->db : "unconnected"),
                          sctx->user ? sctx->user : "unauthenticated",
                          sctx->host_or_ip,
                          (net->last_errno ? ER(net->last_errno) :
                           ER(ER_UNKNOWN_ERROR)));
      net_send_error(thd, net->last_errno, NullS);
      statistic_increment(aborted_threads,&LOCK_status);
    }

I cannot agree that this is "not a bug in behaviour". There is no technical reason for a failed attempt to be counted but not logged if the connection is not established.

It is already a possible denial of service vector; if "a mailicious user
tries to open and close loads of connections" the MySQL server blocks the host! It might even be possible to block an arbitrary host by setting the source header for the tcp connect() calls.

If you're worried about the system performance in writing to the error log, the correct behavior would be not to increment Aborted_connects.

I'd like to add support for Joshua's position -- we are running into the same problem; and would like to see MySQL fix this.

It is most certainly a bug that it locks out users and does not log it.

Our preference would be that tcp connections with no login attempt do not count toward any lock-out.

I also concur that this is a security bug.  If nothing is logged, yet the action will eventually block the connection, there is no way to track what is causing the connection to go down.  There is also a possible DoS scenario without any tracking in the log.

I believe this was fixed in 6.0, needs to be re-verified.

I do not know what was fixed, but my test case gives exactly the same results with 6.0.7 from bzr:

openxs@suse:/home2/openxs/dbs/6.0> bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 6.0.7-alpha-debug Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> show variables like '%warn%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_warnings  | 2     |
| sql_warnings  | OFF   |
| warning_count | 0     |
+---------------+-------+
3 rows in set (0.00 sec)

mysql> show global status like '%abort%';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| Aborted_clients  | 0     |
| Aborted_connects | 0     |
+------------------+-------+
2 rows in set (0.02 sec)

Now, from other shell:

openxs@suse:/home2/openxs/dbs/5.1> telnet localhost 3306
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
?
6.0.7-alpha-debugg>?aK3^?^>X#A_;F.R4Connection closed by foreign host.
openxs@suse:/home2/openxs/dbs/5.1>

This attempt was counted as aborted connect:

mysql> show global status like '%abort%';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| Aborted_clients  | 0     |
| Aborted_connects | 1     |
+------------------+-------+
2 rows in set (0.00 sec)

But nothing is logged in the error log:

mysql> exit
Bye
openxs@suse:/home2/openxs/dbs/6.0> tail var/suse.err
080813 12:58:27  InnoDB: Starting shutdown...
080813 12:58:28  InnoDB: Shutdown completed; log sequence number 0 48117
080813 12:58:28 [Note] /home2/openxs/dbs/6.0/libexec/mysqld: Shutdown complete

080813 12:58:28 mysqld_safe mysqld from pid file /home2/openxs/dbs/6.0/var/suse.pid ended
080901 21:59:30 mysqld_safe Starting mysqld daemon with databases from /home2/openxs/dbs/6.0/var
080901 21:59:35  InnoDB: Started; log sequence number 0 48117
080901 21:59:37 [Note] Event Scheduler: Loaded 0 events
080901 21:59:37 [Note] /home2/openxs/dbs/6.0/libexec/mysqld: ready for connections.
Version: '6.0.7-alpha-debug'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution

OK, it was fixed differently:
      /*
        Log the command before authentication checks, so that the user can
        check the log for the tried login tried and also to detect
        break-in attempts.
      */
      general_log_print(thd, command,
                        (thd->main_security_ctx.priv_user ==
                         thd->main_security_ctx.user ?
                         (char*) "%s@%s on %s" :
                         (char*) "%s@%s as anonymous on %s"),
                        thd->main_security_ctx.user,
                        thd->main_security_ctx.host_or_ip,
                        db ? db : (char*) "");

So, this is logged in the general log at least.

I was reviewing a patch that added more logging, but I can't remember the worklog task number.

The reason the behavior described in the report is default is that printing messages to the error log can significantly bog down performance. 
If we decide to fix the bug, we should perhaps have an option for this behavior.

I'd just like to point out that blocking connections also has some pretty serious performance issues. If you can't connect, performance drops to zero while the poor admin is trying to figure out what's going on with no logging to work with.

hmmm, but is this fixed in the 5.x series aswell...

since we will not use an alpha version on a production server..

find it odd aswell, blocking users but not telling it in the log..

toke me a week to figure out the prob.

This is NOT fixed yet in any version. But currently we are going to fix it only in 6.0 and up.

Would be nice to know what hosts are blocked. (list blocked hosts)

i mean, i would like to know who or what is attacking the system.
only a counter with abort counts will not cut it for most
system admins...

We'll wait and see....

Thx..

Collen, adding a SHOW HOSTS CACHE feature is covered by bug #22821. It seems more likely to arrive as an information schema table, but no idea when or if it will happen.

One way to address this without introducing a denial of service vulnerability would be logging only the change of a host from not blocked to blocked. Not a lot of load except in a DDoS case. A log entry when the count reaches 75% of the limit would also be nice.

I'm using 5.5 and have the same issue.  How can I identify when a host has had a problem (and I need to run flush hosts), when I can't check a log, or a status, to identify that a particular host is blocked?.