Monitoring MySQL/MariaDB: annoying 'Aborted connection ...' on /var/log/mysql/error.log [HACK]

I've been having a few nightmares figuring out the spikes in performance on my MariaDB instance, and, although this is not related to ISPConfig3 (but rather to a security plugin in WordPress...), there was something that has been annoying me for half a decade or so. Because it's just annoying, I have not really bothered with it.

If you take a look at your /var/log/mysql/error.log, with ISPConfig3 running, you'll be getting this message every minute:

Code:

2022-06-05 18:30:01 79092 [Warning] Aborted connection 79092 to db: 'unconnected' user: 'unauthenticated' host: 'localhost' (This connection closed normally without authentication)
2022-06-05 18:30:04 79096 [Warning] Aborted connection 79096 to db: 'unconnected' user: 'unauthenticated' host: 'localhost' (This connection closed normally without authentication)
2022-06-05 18:31:01 79132 [Warning] Aborted connection 79132 to db: 'unconnected' user: 'unauthenticated' host: 'localhost' (This connection closed normally without authentication)
2022-06-05 18:32:01 79163 [Warning] Aborted connection 79163 to db: 'unconnected' user: 'unauthenticated' host: 'localhost' (This connection closed normally without authentication)
2022-06-05 18:33:02 79199 [Warning] Aborted connection 79199 to db: 'unconnected' user: 'unauthenticated' host: 'localhost' (This connection closed normally without authentication)

Since it's just a warning, it's quite harmless. Unless, of course, you're doing benchmarking and/or running MySQL optimisation toolkits. Even phpMyAdmin will complain about the 'excessive warnings'. Because the logs are not very explicit, it's tough to figure out where they come from. I even tried to use packet sniffers! (I know... overkill)

Actually, the 'once per minute' message should have tipped me off — this is nothing less than the ISPConfig3 monitoring tool, testing if something is replying on port 3306 (MySQL's default) or whatever port you might have configured it to.

What happens is that the PHP-based cron tool will, for the sake of monitoring, just open the socket. If the socket is being listened to by any application (and one assumes that the MySQL server is listening if and only if it is running!), the monitor flags the MySQL app as being fine, closes the socket, and goes on with the rest of the tests.

For most kinds of socket-listening applications, such a behaviour is enough to figure out if things are running or not. MariaDB (and presumably MySQL as well) is, however, a bit more skeptical: why should an external application open the socket and then immediately close it without authentication? Usually, that's the kind of behaviour expected from illegitimate port scanners, but also (possibly) of a badly coded application trying to talk to MySQL but failing to do so and closing the connection before even making an attempt to establish the basics of the MySQL communication protocol. As such, the database signals a warning — meant for the system administrator to check what is going on (and eventually fix it).

The code that does this checking is in the file /usr/local/ispconfig/server/lib/classes/monitor_tools.inc.php; the actual method doing that is on line 700 or so, called _checkTcp(). The same code is applied to all port-based scans, except for port 80, where a few extra tests are made (to make sure that the web server is really alive and accepting connections). Doing that for each and every other port is not trivial, since it requires actually understanding the protocol and writing a short test suite. Doing that for plain-text HTTP is very easy; I guess the same could be said by plain-text SMTP or POP3 without authentication, and perhaps a few more protocols like these. By contrast, the protocol for MySQL/MariaDB is complex! So... opening and closing the socket is the best that can be done, I guess.

To avoid the warnings, but also keep the connection down to the essentials, what I've done is a very simple hack. Instead of going through _checkTcp(), I changed the code on line 473 (or so), which was originally something like this:

PHP:

        /* Monitor MySQL Server */
        $data['mysqlserver'] = -1; // unknown - not needed
        if ($services['db_server'] == 1) {
           if ($this->_checkTcp($conf['db_host'], $conf['db_port']) {
                $data['mysqlserver'] = 1;
            } else {
                $data['mysqlserver'] = 0;
                $state = 'error'; // because service is down
            }
        }

to an explicit call to the database server, using the built-in mysqli extension:

PHP:

        /* Monitor MySQL Server */
        $data['mysqlserver'] = -1; // unknown - not needed
        if ($services['db_server'] == 1) {
            // hail MySQL server:
            mysqli_report(MYSQLI_REPORT_ERROR | MYSQLI_REPORT_STRICT);
            $ispcDB = mysqli_connect($conf['db_host'], $conf['db_user'], $conf['db_password'], $conf['db_database'], $conf['db_port']);
            if ($ispcDB !== false) {
                $data['mysqlserver'] = 1;
            } else {
                $data['mysqlserver'] = 0;
                $state = 'error'; // because service is down
            }
            mysqli_close($ispcDB);  // we can ignore the result (gwyneth 20220605)
        }

Note that I'm just opening the connection to the database and closing it immediately afterwards. But the warnings on the error log are gone. Why? Because mysqli_connect doesn't simply open a socket to the server; it sets up the necessary protocol to establish a real connection (which means exchanging information with the MySQL/MariaDB server). But this gets closed immediately afterwards.

Sure, I'm aware that this has a bit more overhead than the simplistic approach of opening and closing a socket. In fact, I believe that some statistic-collecting mechanisms of MariaDB/MySQL will pick up the connections that were made and silently discarded without making a single query; so it might make some sense to just make a very simple, straightforward query that can easily be cached (such as retrieving the value of a static system variable).

I'm just sharing this in the (unlikely) case that someone encountered those strange warnings and wondered who, or what, was 'attacking' the database server once every minute...

 

Huh, I should probably submit that as a merge request on ISPConfig's GitLab...

 

Hello Gwyneth, I noticed these "aborted connections" as well! You said "unlikely" someone would encountered this annoyance. Well I did and you saved me time, Thank you!

 

Hello Gwyneth, like Rumas, I am seeing this but, on a Windows Server both in the MariaDB text log and in the Windows event log. I have other installations not doing this and yes, it is annoying! It stops when I shut down the MariaDB service (which is how MySQL/MariaDB runs on Windows). So, in this case I am guessing ... maybe some kind of "heartbeat", not coded so well.

At least I know that I am not alone (-;

 

Hello Gwyneth, I took the approach of setting the "log_warnings" variable in MariaDB to 0 (zero), it defaults to 2, and that made the music stop. Search: MariaDB logging (server system variables) and find that. I figure I can set it to whatever if needed.

 

Oh — sure, disabling log warnings is definitely a possibility
However, I'm always weary of blocking warning messages — who knows what real warnings get 'lost' that way!
Especially since, in this case, it's just a question of fixing the underlying PHP code.
Now I just have to do the same for Postfix & Dovecot, they will also benefit from proper checks (as opposed to just opening and closing their sockets...).

 

Your solution is definitely a best practice, no question! I set log_warnings=1 and that works for now so, not all warnings are quashed. PHP on Windows is not like Linux, no cron, and is "just another WordPress site" in development. Thanks for responding.