Bug #96658 Access denied for user 'ROUTER'@'127.0.0.1'
Submitted: 26 Aug 2019 14:56 Modified: 12 Sep 2019 17:36
Reporter: Pavel Dobryakov Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Router Severity:S2 (Serious)
Version:8.0.17 OS:Debian
Assigned to: CPU Architecture:x86

[26 Aug 2019 14:56] Pavel Dobryakov
Description:
Regular error in mysql log
2019-08-26T14:52:19.255207Z 4326194 [Note] Access denied for user 'ROUTER'@'127.0.0.1' (using password: YES)

How to repeat:
Configuration of Mysqlrouter
[DEFAULT]
logging_folder = /var/log/mysqlrouter/
runtime_folder = /var/run/mysqlrouter
config_folder = /etc/mysqlrouter

[logger]
level = DEBUG

[keepalive]
interval = 60

[routing:route1]
bind_address = 0.0.0.0:3307
destinations = localhost
mode = read-write
connect_timeout = 10
max_connect_errors = 100000

I see regular error in Mysql log
2019-08-26T14:52:19.255207Z 4326194 [Note] Access denied for user 'ROUTER'@'127.0.0.1' (using password: YES)

In log of mysqlrouter i see
2019-08-26 17:55:18 routing DEBUG [7efc579a0700] [routing:iris] fd=7 connection accepted at 0.0.0.0:3307
2019-08-26 17:55:18 routing DEBUG [7efc579a0700] Trying server localhost:3306 (index 0)
2019-08-26 17:55:18 routing DEBUG [7efc5619d700] [routing:iris] fd=7 connected 127.0.0.1:56062 -> localhost:3306 as fd=8
2019-08-26 17:55:18 routing INFO [7efc5619d700] [routing:iris] fd=7 Pre-auth socket failure 127.0.0.1:56062: Copy client->server failed: unexpected connection close
2019-08-26 17:55:18 routing INFO [7efc5619d700] [routing:iris] 8 connection errors for 127.0.0.1:56062 (max 100000)
2019-08-26 17:55:18 routing DEBUG [7efc5619d700] [routing:iris] fd=7 connection closed (up: 0b; down: 0b) Copy client->server failed: unexpected connection close

In tcpdump check i see attempt to connect

 at 2019-08-26 17:34:18.902885
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count        100       1
# Exec time    100   747us   747us   747us   747us   747us       0   747us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size   100      30      30      30      30      30       0      30
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    fake_router_login
# Error msg    Access denied for user 'ROUTER'@'127.0.0.1' ...
# Errors       1045
# Hosts        127.0.0.1
# Users        ROUTER
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
administrator command: Connect\G
[4 Sep 2019 7:09] MySQL Verification Team
Hello Pavel,

Thank you for the report and feedback.
I was trying to reproduce this issue at my end (attempted multiple times during the verification of Bug #96652) but none of the time I observed reported issue. Could you please provide more details about your environment such as - is router configured for any cluster or for standalone instance? Could you please share more details about MySQL server version, what kind of load you are running against the instance etc to investigate this issue further at our end? 
Also, I see information messages i.e [Note] is logged to the MySQL server's error log and similar in router's error log. Is this causing any issues in your environment? Thank you.

Sincerely,
Umesh
[9 Sep 2019 10:16] Pavel Dobryakov
Full config of router
# Copyright (c) 2015, 2018, Oracle and/or its affiliates. All rights reserved.
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License, version 2.0,
# as published by the Free Software Foundation.
#
# This program is also distributed with certain software (including
# but not limited to OpenSSL) that is licensed under separate terms,
# as designated in a particular file or component or in included license
# documentation.  The authors of MySQL hereby grant you an additional
# permission to link the program and your derivative works with the
# separately licensed software that they have included with MySQL.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License, version 2.0, for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301  USA

#
# MySQL Router configuration file for Debian/Ubuntu
#
# Documentation is available at
#    http://dev.mysql.com/doc/mysql-router/en/

[DEFAULT]
logging_folder = /var/log/mysqlrouter/
runtime_folder = /var/run/mysqlrouter
config_folder = /etc/mysqlrouter

[logger]
level = DEBUG

[keepalive]
interval = 60

[routing:iris]
bind_address = 0.0.0.0:3307
destinations = localhost
mode = read-write
connect_timeout = 10
max_connect_errors = 100000

There is now cluster route - it`s only proxy for local MySQL
MySQL version
mysql  Ver 14.14 Distrib 5.7.22-22, for debian-linux-gnu (x86_64) using  6.3
Mysql load
Uptime: 4126143  Threads: 33  Questions: 239328073  Slow queries: 311957  Opens: 5658516  Flush tables: 1  Open tables: 4096  Queries per second avg: 58.002

Problem is Access denied in server logs and a constant increase in the values of the variable max_connect_errors
[10 Sep 2019 6:37] Siddharth Agravat
@Pavel Dobryakov Are you trying to monitor router port using port_exporter any monitoring tool?
We've faced similar issues where router stopped accepting new connections after reaching max_connect_errors limit (default: 100) with error : Too Many Connections.

MySQL Router  Ver 8.0.17 for Linux on x86_64 (MySQL Community - GPL)
MySQL Server Version : 8.0.16 MySQL Community Server - GPL
OS and kernel : CentOS Linux release 7.6.1810 (Core) -  3.10.0-957.10.1.el7.x86_64

Router error logs:
2019-09-09 17:26:30 routing INFO [7f6a0cb75700] [routing:my_cluster_default_rw] fd=13 Pre-auth socket failure 127.0.0.1:29976: Copy client->server failed: unexpected connection close
2019-09-09 17:26:30 routing INFO [7f6a0cb75700] [routing:my_cluster_default_rw] 28 connection errors for 127.0.0.1:29976 (max 100)
2019-09-09 17:26:32 routing INFO [7f6a0fd7d700] Too many connection errors from 127.0.0.1

Even telnet to router port triggers connect error and increment error_count. There should be proper way of handling such requests on port without triggering errors. Is there any workaround to this?
[11 Sep 2019 10:42] MySQL Verification Team
Thank you Pavel,  Siddharth.

regards,
Umesh
[11 Sep 2019 10:42] MySQL Verification Team
Test results - 8.0.17

Attachment: 96658.results (application/octet-stream, text), 17.06 KiB.

[12 Sep 2019 17:36] Jan Kneschke
Posted by developer:
 
The "access denied for user 'router'@..." is related to max-connect-errors
handling in the MySQL Router and MySQL Server:

The server treats all aborted connects as "connect-error" and after
a while would block connections from the source-address.

In the case of the router, the source-address is the router. Any faileda
aborted connections to the router would result in a same aborted connection
from router to server. If the router wouldn't handle this situation
the router would quickly be blocked by the server due to a misbehaving client.

To avoid that, the router will continue the handshake with the server
in that case as the user ROUTER, which is not treated as a "max-connect-error"
by the server.