Dovecot and MySQL aborted connections.

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

Dovecot and MySQL aborted connections.

Dovecot mailing list
We also spotted these sql connections getting aborted, upon upgrading
MySQL from 5.6 to 5.7. (Going back to 5.6 we don't see them!)

Turning on mysql general query logging we can see it is Dovecot's mysql
connections that inquire about or update quota usage in particular:


*** /logs//mysql.log ***
2019-10-30T10:52:22.624690-07:00    2 Connect dovecot@localhost on
npomail using Socket

2019-10-30T10:52:40.019780-07:00    2 Query SELECT bytes FROM quota2
WHERE username = 'a@bla'
2019-10-30T10:52:40.020948-07:00    2 Query SELECT messages FROM quota2
WHERE username = 'a@bla'

2019-10-30T10:53:40.113374-07:00 2 [Note] Aborted connection 2 to db:
'npomail' user: 'dovecot' host: 'localhost' (Got an error reading
communication packets)


Increasing mysqld's net_read_timeout and net_write_timeout values to
3600 does not stop the aborted connections.

It seems asymptomatic. If the connection to mysql is still there to do
quota operations, Dovecot seems to use it. If it's been aborted by the
server, Dovecot seems to just (re)connect. . . But I'd love to help find
the root or file a bug report or learn what it is we've configured
wrong. . .

  Benjamin
Reply | Threaded
Open this post in threaded view
|

Re: Dovecot and MySQL aborted connections.

Dovecot mailing list

> We also spotted these sql connections getting aborted, upon upgrading MySQL from 5.6 to 5.7. (Going back to 5.6 we don't see them!)

I have a mailserver running MySQL 5.6.44 which is not very busy that logs these warnings.
Another busy one running MySQL 5.6.45 does not log any warnings.

MySQL interactive-/wait_timeout is 28800 (8 hours), which is more than enough time to wait for a query. Connections are closed way earlier.

dovecot and postfix use the same database and mysql user, so I created a new user for dovecot.
syslog shows a few communication packet errors but these are all from postfix, none from dovecot so far.

It seems connections are closed after 60s of inactivity (vmail is postfix, vmail2 is dovecot):

mysql> select * from INFORMATION_SCHEMA.PROCESSLIST where USER like 'vmail%';
+-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
| ID  | USER   | HOST            | DB    | COMMAND | TIME | STATE | INFO | TIME_MS | ROWS_SENT | ROWS_EXAMINED | TID  |
+-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
| 147 | vmail  | localhost       | vmail | Sleep   |    1 |       | NULL |     566 |         0 |             0 | 6664 |
| 148 | vmail  | localhost       | vmail | Sleep   |    1 |       | NULL |     564 |         0 |             0 | 6069 |
| 149 | vmail  | localhost       | vmail | Sleep   |    1 |       | NULL |     566 |         0 |             0 | 6037 |
| 151 | vmail2 | 127.0.0.2:35058 | vmail | Sleep   |   51 |       | NULL |   50872 |         1 |             1 | 6072 |
| 152 | vmail2 | 127.0.0.2:35060 | vmail | Sleep   |   60 |       | NULL |   59324 |         1 |             1 | 6025 |
| 150 | vmail  | localhost       | vmail | Sleep   |    1 |       | NULL |     565 |         0 |             0 | 6071 |
+-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
6 rows in set (0.00 sec)

mysql> select * from INFORMATION_SCHEMA.PROCESSLIST where USER like 'vmail%';
+-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
| ID  | USER   | HOST            | DB    | COMMAND | TIME | STATE | INFO | TIME_MS | ROWS_SENT | ROWS_EXAMINED | TID  |
+-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
| 147 | vmail  | localhost       | vmail | Sleep   |    2 |       | NULL |    1775 |         0 |             0 | 6664 |
| 148 | vmail  | localhost       | vmail | Sleep   |    2 |       | NULL |    1772 |         0 |             0 | 6069 |
| 149 | vmail  | localhost       | vmail | Sleep   |    2 |       | NULL |    1774 |         0 |             0 | 6037 |
| 151 | vmail2 | 127.0.0.2:35058 | vmail | Sleep   |   52 |       | NULL |   52080 |         1 |             1 | 6072 |
| 150 | vmail  | localhost       | vmail | Sleep   |    2 |       | NULL |    1773 |         0 |             0 | 6071 |
+-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
5 rows in set (0.00 sec)

Only vmail (postfix) has dropped connections (you need performance schema enabled):

mysql> SELECT ess.user, ess.host, (a.total_connections - a.current_connections) - ess.count_star as not_closed, ((a.total_connections - a.current_connections) - ess.count_star) * 100 / (a.total_connections - a.current_connections) as pct_not_closed FROM performance_schema.events_statements_summary_by_account_by_event_name ess JOIN performance_schema.accounts a on (ess.user = a.user and ess.host = a.host)  WHERE ess.event_name = 'statement/com/quit' AND (a.total_connections - a.current_connections) > ess.count_star;
+-------+-----------+------------+----------------+
| user  | host      | not_closed | pct_not_closed |
+-------+-----------+------------+----------------+
| vmail | localhost |         11 |        15.4930 |
+-------+-----------+------------+----------------+
1 row in set (0.02 sec)


My setup is different concerning quotas, they are not stored in MySQL. So if you don't use postfix with the same user/database the source for your warnings might be quota. For me it seems to be related to postfix.

Don't know if this helps, there is a new option in 5.7
https://dev.mysql.com/doc/refman/5.7/en/x-plugin-options-system-variables.html#sysvar_mysqlx_idle_worker_thread_timeout

Gerald


> Turning on mysql general query logging we can see it is Dovecot's mysql connections that inquire about or update quota usage in particular:
>
>
> *** /logs//mysql.log ***
> 2019-10-30T10:52:22.624690-07:00    2 Connect dovecot@localhost on npomail using Socket
>
> 2019-10-30T10:52:40.019780-07:00    2 Query SELECT bytes FROM quota2 WHERE username = 'a@bla'
> 2019-10-30T10:52:40.020948-07:00    2 Query SELECT messages FROM quota2 WHERE username = 'a@bla'
>
> 2019-10-30T10:53:40.113374-07:00 2 [Note] Aborted connection 2 to db: 'npomail' user: 'dovecot' host: 'localhost' (Got an error reading communication packets)
>
>
> Increasing mysqld's net_read_timeout and net_write_timeout values to 3600 does not stop the aborted connections.
>
> It seems asymptomatic. If the connection to mysql is still there to do quota operations, Dovecot seems to use it. If it's been aborted by the server, Dovecot seems to just (re)connect. . . But I'd love to help find the root or file a bug report or learn what it is we've configured wrong. . .
>
> Benjamin

Reply | Threaded
Open this post in threaded view
|

Re: Dovecot and MySQL aborted connections.

Dovecot mailing list
I will top post here ...

got a similar issue with mariadb a while ago after upgrading from 10.1
to 10.2
lots of warnings about aborted connections in the logs.

after digging into this issue the culprit was a new default setting
value in the newer maridb server.

during the update the log_warnings changed from 1 to 2 therefore showing
lots of aborted connection notices in the logs

changing the log_warnings back from 2 to 1 solved this issue

https://mariadb.com/kb/en/library/upgrading-from-mariadb-101-to-mariadb-102/
https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_log_warnings

perhaps this might help someone?

greetings
Becki

Am 30.10.2019 um 22:14 schrieb Gerald Galster via dovecot:

>> We also spotted these sql connections getting aborted, upon upgrading MySQL from 5.6 to 5.7. (Going back to 5.6 we don't see them!)
> I have a mailserver running MySQL 5.6.44 which is not very busy that logs these warnings.
> Another busy one running MySQL 5.6.45 does not log any warnings.
>
> MySQL interactive-/wait_timeout is 28800 (8 hours), which is more than enough time to wait for a query. Connections are closed way earlier.
>
> dovecot and postfix use the same database and mysql user, so I created a new user for dovecot.
> syslog shows a few communication packet errors but these are all from postfix, none from dovecot so far.
>
> It seems connections are closed after 60s of inactivity (vmail is postfix, vmail2 is dovecot):
>
> mysql> select * from INFORMATION_SCHEMA.PROCESSLIST where USER like 'vmail%';
> +-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
> | ID  | USER   | HOST            | DB    | COMMAND | TIME | STATE | INFO | TIME_MS | ROWS_SENT | ROWS_EXAMINED | TID  |
> +-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
> | 147 | vmail  | localhost       | vmail | Sleep   |    1 |       | NULL |     566 |         0 |             0 | 6664 |
> | 148 | vmail  | localhost       | vmail | Sleep   |    1 |       | NULL |     564 |         0 |             0 | 6069 |
> | 149 | vmail  | localhost       | vmail | Sleep   |    1 |       | NULL |     566 |         0 |             0 | 6037 |
> | 151 | vmail2 | 127.0.0.2:35058 | vmail | Sleep   |   51 |       | NULL |   50872 |         1 |             1 | 6072 |
> | 152 | vmail2 | 127.0.0.2:35060 | vmail | Sleep   |   60 |       | NULL |   59324 |         1 |             1 | 6025 |
> | 150 | vmail  | localhost       | vmail | Sleep   |    1 |       | NULL |     565 |         0 |             0 | 6071 |
> +-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
> 6 rows in set (0.00 sec)
>
> mysql> select * from INFORMATION_SCHEMA.PROCESSLIST where USER like 'vmail%';
> +-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
> | ID  | USER   | HOST            | DB    | COMMAND | TIME | STATE | INFO | TIME_MS | ROWS_SENT | ROWS_EXAMINED | TID  |
> +-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
> | 147 | vmail  | localhost       | vmail | Sleep   |    2 |       | NULL |    1775 |         0 |             0 | 6664 |
> | 148 | vmail  | localhost       | vmail | Sleep   |    2 |       | NULL |    1772 |         0 |             0 | 6069 |
> | 149 | vmail  | localhost       | vmail | Sleep   |    2 |       | NULL |    1774 |         0 |             0 | 6037 |
> | 151 | vmail2 | 127.0.0.2:35058 | vmail | Sleep   |   52 |       | NULL |   52080 |         1 |             1 | 6072 |
> | 150 | vmail  | localhost       | vmail | Sleep   |    2 |       | NULL |    1773 |         0 |             0 | 6071 |
> +-----+--------+-----------------+-------+---------+------+-------+------+---------+-----------+---------------+------+
> 5 rows in set (0.00 sec)
>
> Only vmail (postfix) has dropped connections (you need performance schema enabled):
>
> mysql> SELECT ess.user, ess.host, (a.total_connections - a.current_connections) - ess.count_star as not_closed, ((a.total_connections - a.current_connections) - ess.count_star) * 100 / (a.total_connections - a.current_connections) as pct_not_closed FROM performance_schema.events_statements_summary_by_account_by_event_name ess JOIN performance_schema.accounts a on (ess.user = a.user and ess.host = a.host)  WHERE ess.event_name = 'statement/com/quit' AND (a.total_connections - a.current_connections) > ess.count_star;
> +-------+-----------+------------+----------------+
> | user  | host      | not_closed | pct_not_closed |
> +-------+-----------+------------+----------------+
> | vmail | localhost |         11 |        15.4930 |
> +-------+-----------+------------+----------------+
> 1 row in set (0.02 sec)
>
>
> My setup is different concerning quotas, they are not stored in MySQL. So if you don't use postfix with the same user/database the source for your warnings might be quota. For me it seems to be related to postfix.
>
> Don't know if this helps, there is a new option in 5.7
> https://dev.mysql.com/doc/refman/5.7/en/x-plugin-options-system-variables.html#sysvar_mysqlx_idle_worker_thread_timeout
>
> Gerald
>
>
>> Turning on mysql general query logging we can see it is Dovecot's mysql connections that inquire about or update quota usage in particular:
>>
>>
>> *** /logs//mysql.log ***
>> 2019-10-30T10:52:22.624690-07:00    2 Connect dovecot@localhost on npomail using Socket
>>
>> 2019-10-30T10:52:40.019780-07:00    2 Query SELECT bytes FROM quota2 WHERE username = 'a@bla'
>> 2019-10-30T10:52:40.020948-07:00    2 Query SELECT messages FROM quota2 WHERE username = 'a@bla'
>>
>> 2019-10-30T10:53:40.113374-07:00 2 [Note] Aborted connection 2 to db: 'npomail' user: 'dovecot' host: 'localhost' (Got an error reading communication packets)
>>
>>
>> Increasing mysqld's net_read_timeout and net_write_timeout values to 3600 does not stop the aborted connections.
>>
>> It seems asymptomatic. If the connection to mysql is still there to do quota operations, Dovecot seems to use it. If it's been aborted by the server, Dovecot seems to just (re)connect. . . But I'd love to help find the root or file a bug report or learn what it is we've configured wrong. . .
>>
>> Benjamin
>
Reply | Threaded
Open this post in threaded view
|

Re: Dovecot and MySQL aborted connections.

Dovecot mailing list
> during the update the log_warnings changed from 1 to 2 therefore
> showing lots of aborted connection notices in the logs
>
> changing the log_warnings back from 2 to 1 solved this issue

Yes the same setting made the same change to the default with mysql:

https://dev.mysql.com/doc/refman/5.7/en/server-options.html#option_mysqld_log-warnings

So now we know how to silence the "Aborted connection" mysql loglines
thank you!


But still I wonder if Dovecot wants to handle these connections slightly
differently - if it could be cleaner? Or is it moot?
Reply | Threaded
Open this post in threaded view
|

Re: Dovecot and MySQL aborted connections.

Dovecot mailing list
On 01/11/2019 01:19, Benjamin Connelly via dovecot wrote:

>> during the update the log_warnings changed from 1 to 2 therefore
>> showing lots of aborted connection notices in the logs
>>
>> changing the log_warnings back from 2 to 1 solved this issue
>
> Yes the same setting made the same change to the default with mysql:
>
> https://dev.mysql.com/doc/refman/5.7/en/server-options.html#option_mysqld_log-warnings 
>
>
> So now we know how to silence the "Aborted connection" mysql loglines
> thank you!
>
>
> But still I wonder if Dovecot wants to handle these connections
> slightly differently - if it could be cleaner? Or is it moot?

Unfortunately there are (replication info) messages that I actually need
from that log level and I wouldn't want to just hide issues anyway. :)
Reply | Threaded
Open this post in threaded view
|

Re: Dovecot and MySQL aborted connections.

Dovecot mailing list
On 01/11/2019 10:16, Reio Remma via dovecot wrote:

> On 01/11/2019 01:19, Benjamin Connelly via dovecot wrote:
>>> during the update the log_warnings changed from 1 to 2 therefore
>>> showing lots of aborted connection notices in the logs
>>>
>>> changing the log_warnings back from 2 to 1 solved this issue
>>
>> Yes the same setting made the same change to the default with mysql:
>>
>> https://dev.mysql.com/doc/refman/5.7/en/server-options.html#option_mysqld_log-warnings 
>>
>>
>> So now we know how to silence the "Aborted connection" mysql loglines
>> thank you!
>>
>>
>> But still I wonder if Dovecot wants to handle these connections
>> slightly differently - if it could be cleaner? Or is it moot?
>
> Unfortunately there are (replication info) messages that I actually
> need from that log level and I wouldn't want to just hide issues
> anyway. :)

I monitored the situation in MySQL Workbench a little and it seems the
userdb MySQL connection closes cleanly.

What doesn't close cleanly is the dict engine MySQL connection that is
updating last login timestamp (its connection shows COMMIT as the last
query).

The dict connection closes after sleeping exactly 60 seconds (server
net_write_timeout is 60 seconds).
The userdb connection closes after about 61-62 seconds for some reason.

I tried changing read/write_timeout in Dovecot MySQL connection to
lower, equal and higher than those set by the server, but it didn't
change anything.