<div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr">Hi,<div><br></div><div>We've experienced this too, happens once in a few months</div><div>i'm reply-ing now because it happend this morning on one of our multiple nodes, other nodes were fine.</div><div><br></div><div>debian 9.4</div><div>dovecot-core                         1:2.2.34-2~bpo9+1<br></div><div><br></div><div><div>Feb  1 06:24:58 machine61 dovecot: auth: Error: plain(EDITED@EDITED.nl,10.0.10.182,<zHU8VM6ATrIKAAq2>): Request 890.37948303 timed out after 150 secs, state=1</div></div><div><br></div><div>Restart of the daemon fixed it.</div><div>unable to reproduce.</div><div><br></div><div>I'm willing to enable specific debug options to help debug this.</div><div>if you could point me in the correct settings for the dovecot: auth: daemon.</div><div><br></div></div></div></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Wed, May 30, 2018 at 3:32 PM Hajo Locke <<a href="mailto:Hajo.Locke@gmx.de">Hajo.Locke@gmx.de</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Hello,<br>
<br>
<br>
Am 29.05.2018 um 11:30 schrieb Gerald Galster:<br>
><br>
>> Am 29.05.2018 um 11:00 schrieb Aki Tuomi <<a href="mailto:aki.tuomi@dovecot.fi" target="_blank">aki.tuomi@dovecot.fi</a>>:<br>
>><br>
>><br>
>><br>
>> On 29.05.2018 11:35, Hajo Locke wrote:<br>
>>> Hello,<br>
>>><br>
>>><br>
>>> Am 29.05.2018 um 09:22 schrieb Aki Tuomi:<br>
>>>> On 29.05.2018 09:54, Hajo Locke wrote:<br>
>>>>> Hello List,<br>
>>>>><br>
>>>>> i use dovecot 2.2.22 and have the same problem described here:<br>
>>>>> <a href="https://dovecot.org/pipermail/dovecot/2017-November/110020.html" rel="noreferrer" target="_blank">https://dovecot.org/pipermail/dovecot/2017-November/110020.html</a><br>
>>>>><br>
>>>>> I can confirm that sometimes there is a problem with connection to<br>
>>>>> mysql-db, but sometimes not.<br>
>>>>> Reasons for failing are still under investigation by my mates.<br>
>>>>><br>
>>>>> My current main problem is, that this fail seems to be a one way<br>
>>>>> ticket for dovecot. Even if mysql is verifyable working again and<br>
>>>>> waiting for connection dovecot stucks furthermore with errors like<br>
>>>>> this:<br>
>>>>><br>
>>>>> May 29 07:00:49 hostname dovecot: auth: Error:<br>
>>>>> plain(<a href="mailto:mail@example.com" target="_blank">mail@example.com</a>,xxx.xxx.xx.xxx,<HGI4FVFt2Oy80j3P>): Request<br>
>>>>> 999.7 timed out after 150 secs, state=1<br>
>>>>><br>
>>>>> When restarting dovecot all is immediately working again.<br>
>>>>> Is there a way to tell dovecot to restart auth services or<br>
>>>>> reinitialize mysql-connection after these hard fails? I could insert<br>
>>>>> "idle_kill = 1 mins" into service auth and service auth-worker, but i<br>
>>>>> dont know if this would work. Unfortunately i am not able to reproduce<br>
>>>>> this error and there are always a couple of days between errors.<br>
>>>>><br>
>>>>> Thanks,<br>
>>>>> Hajo<br>
>>>>><br>
>>>>><br>
>>>> Hi!<br>
>>>><br>
>>>> I was not able to repeat this problem using 2.2.36. Can you provide<br>
>>>> steps to reproduce?<br>
>>>><br>
>>>> May 29 10:20:24 auth: Debug: client in: AUTH    1    PLAIN<br>
>>>> service=imap    secured    session=XtpgEVNtQeUAAAAAAAAAAAAAAAAAAAAB<br>
>>>> lip=::1    rip=::1    lport=143    rport=58689    resp=<hidden><br>
>>>> May 29 10:20:24 auth-worker(31098): Debug:<br>
>>>> sql(<a href="mailto:test@domain.org" target="_blank">test@domain.org</a>,::1,<XtpgEVNtQeUAAAAAAAAAAAAAAAAAAAAB>): query:<br>
>>>> SELECT userid AS username, domain, password FROM users WHERE userid =<br>
>>>> 'test' AND domain = '<a href="http://domain.org" rel="noreferrer" target="_blank">domain.org</a>'<br>
>>>> May 29 10:20:54 auth-worker(31098): Warning: mysql: Query failed,<br>
>>>> retrying: Lost connection to MySQL server during query (idled for 28<br>
>>>> secs)<br>
>>>> May 29 10:20:59 auth-worker(31098): Error: mysql(127.0.0.1): Connect<br>
>>>> failed to database (dovecot): Can't connect to MySQL server on<br>
>>>> '127.0.0.1' (4) - waiting for 5 seconds before retry<br>
>>>> May 29 10:21:04 auth-worker(31098): Error: mysql(127.0.0.1): Connect<br>
>>>> failed to database (dovecot): Can't connect to MySQL server on<br>
>>>> '127.0.0.1' (4) - waiting for 5 seconds before retry<br>
>>>> May 29 10:21:14 auth: Debug: auth client connected (pid=31134)<br>
>>>> May 29 10:21:14 imap-login: Warning: Growing pool 'imap login commands'<br>
>>>> with: 1024<br>
>>>> May 29 10:21:14 auth-worker(31098): Error: mysql(127.0.0.1): Connect<br>
>>>> failed to database (dovecot): Can't connect to MySQL server on<br>
>>>> '127.0.0.1' (4) - waiting for 25 seconds before retry<br>
>>>><br>
>>>> This is what it looks like for me and after restoring connectivity, it<br>
>>>> started working normally.<br>
>>> Unfortunately i can not reproduce. Servers running well for days or<br>
>>> sometimes weeks and then it happens one time. I can provide some more<br>
>>> logs.<br>
>>><br>
>>> This is an error with mysql involvement:<br>
>>><br>
>>> May 29 06:56:59 hostname dovecot: auth-worker(1099): Error:<br>
>>> mysql(xx.xx.xx.xx): Connect failed to database (mysql): Can't connect<br>
>>> to MySQL server on 'xx.xx.xx.xx' (111) - waiting for 1 seconds before<br>
>>> retry<br>
>>> .<br>
>>> . some more of above line<br>
>>> .<br>
>>> May 29 06:56:59 hostname dovecot: auth-worker(1110): Error:<br>
>>> sql(<a href="mailto:mail@example.com" target="_blank">mail@example.com</a>,xx.xx.xx.xx): Password query failed: Not<br>
>>> connected to database<br>
>>> May 29 06:56:59 hostname dovecot: auth: Error: auth worker: Aborted<br>
>>> PASSV request for <a href="mailto:mail@example.com" target="_blank">mail@example.com</a>: Internal auth worker failure<br>
>>> May 29 06:57:59 hostname dovecot: auth-worker(1099): Error: mysql:<br>
>>> Query timed out (no free connections for 60 secs): SELECT `inbox` as<br>
>>> `user`, `password` FROM `mail_users` WHERE `login` = 'username' AND<br>
>>> `active`='Y'<br>
>>> May 29 06:59:30 hostname dovecot: auth: Error:<br>
>>> plain(username,xx.xx.xx.xx,<jc9yEFFtXcJXmx0F>): Request 999.2 timed<br>
>>> out after 151 secs, state=1<br>
>>> .<br>
>>> . much more of these lines with Request timed out<br>
>>> .<br>
>>><br>
>>> At this point my mates restartet dovecot and all worked well<br>
>>> immediately. Mysql performed a short restart at 6:56 and dovecot was<br>
>>> not able to reconnect for about 10 mins until my mates did the<br>
>>> restart. I could not reproduce the problem by manually restarting of<br>
>>> mysql, this worked well.<br>
>>><br>
>>> This is an error without visible mysql involvement:<br>
>>> .<br>
>>> . lines of normal imap/pop activity<br>
>>> .<br>
>>> May 29 05:43:03 hostname dovecot: imap-login: Error: master(imap):<br>
>>> Auth request timed out (received 0/12 bytes)<br>
>>> May 29 05:43:03 hostname dovecot: imap-login: Internal login failure<br>
>>> (pid=1014 id=16814) (internal failure, 1 successful auths):<br>
>>> user=<username>, method=PLAIN, rip=xx.xx.xx.xx, lip=xx.xx.xx.xx, TLS<br>
>>> May 29 05:43:03 hostname dovecot: imap: Error: Login client<br>
>>> disconnected too early<br>
>>> May 29 05:44:03 hostname dovecot: auth: Error:<br>
>>> plain(username,xx.xx.xx.xx,<Wry1AlBt7couU7FV>): Request 1014.16815<br>
>>> timed out after 150 secs, state=1<br>
>>> May 29 05:44:08 hostname dovecot: imap: Error: Auth server request<br>
>>> timed out after 155 secs (client-pid=1014 client-id=16814)<br>
>>> May 29 05:44:33 hostname dovecot: imap-login: Disconnected: Inactivity<br>
>>> during authentication (disconnected while authenticating, waited 180<br>
>>> secs): user=<>, method=PLAIN, rip=xx.xx.xx.xx, lip=xx.xx.xx.xx, TLS:<br>
>>> Disconnected<br>
>>> May 29 05:46:07 hostname dovecot: auth: Error:<br>
>>> plain(<a href="mailto:mail@example.com" target="_blank">mail@example.com</a>,xx.xx.xx.xx,<j2cWClBtVf3Z+t+p>): Request<br>
>>> 1014.16819 timed out after 150 secs, state=1<br>
>>> .<br>
>>> . and so on until restart<br>
>>> .<br>
>>><br>
>>> There is no errorlog in relation to mysql written by dovecot.<br>
>>><br>
>>> We use 2.2.22 because this version is provided with Ubuntu 16.04 and<br>
>>> Ubuntu Team is maintaining software and providing security patches,<br>
>>> which happens 2017 and 2018 a couple of times. By manually compiling<br>
>>> and using newer versions you have to check updates by yourself and you<br>
>>> are forced to run every single update. Our goal is reliability which<br>
>>> contradicts to use of bleeding edge software.<br>
>>><br>
>>><br>
>>> This is output of current doveconf -n<br>
>>><br>
>>> # 2.2.22 (fe789d2): /etc/dovecot/dovecot.conf<br>
>>> # Pigeonhole version 0.4.13 (7b14904)<br>
>>> # OS: Linux 4.4.0-127-generic x86_64 Ubuntu 16.04.4 LTS<br>
>>> auth_mechanisms = plain login<br>
>>> auth_username_chars =<br>
>>> abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_@üÜöÖäÄ<br>
>>> auth_worker_max_count = 60<br>
>>> disable_plaintext_auth = no<br>
>>> imap_capability = +XLIST<br>
>>> lock_method = flock<br>
>>> login_greeting = mailserver ready.<br>
>>> login_log_format_elements = user=<%u> method=%m rip=%r lip=%l %c<br>
>>> mail_cache_min_mail_count = 30<br>
>>> mail_location = mbox:~/mail:INBOX=/var/mail/%u<br>
>>> mail_max_userip_connections = 30<br>
>>> mbox_read_locks = dotlock<br>
>>> mbox_very_dirty_syncs = yes<br>
>>> namespace inbox {<br>
>>>    inbox = yes<br>
>>>    location =<br>
>>>    mailbox Archiv {<br>
>>>      auto = no<br>
>>>      special_use =<br>
>>>    }<br>
>>>    mailbox Drafts {<br>
>>>      auto = no<br>
>>>      special_use =<br>
>>>    }<br>
>>>    mailbox Junk {<br>
>>>      auto = no<br>
>>>      special_use =<br>
>>>    }<br>
>>>    mailbox Sent {<br>
>>>      auto = no<br>
>>>      special_use =<br>
>>>    }<br>
>>>    mailbox Trash {<br>
>>>      auto = no<br>
>>>      special_use =<br>
>>>    }<br>
>>>    prefix =<br>
>>> }<br>
>>> passdb {<br>
>>>    args = /etc/dovecot/dovecot-sql.conf<br>
>>>    driver = sql<br>
>>> }<br>
>>> protocols = imap pop3<br>
>>> service auth {<br>
>>>    unix_listener /var/spool/postfix/private/auth {<br>
>>>      group = postfix<br>
>>>      mode = 0660<br>
>>>      user = postfix<br>
>>>    }<br>
>>>    user = root<br>
>>> }<br>
>>> service imap-login {<br>
>>>    executable = /usr/lib/dovecot/imap-login<br>
>>>    process_min_avail = 1<br>
>>>    service_count = 0<br>
>>>    user = dovecot<br>
>>> }<br>
>>> service imap {<br>
>>>    process_limit = 1024<br>
>>> }<br>
>>> service pop3-login {<br>
>>>    executable = /usr/lib/dovecot/pop3-login<br>
>>>    process_min_avail = 1<br>
>>>    service_count = 0<br>
>>>    user = dovecot<br>
>>> }<br>
>>> service pop3 {<br>
>>>    executable = /usr/lib/dovecot/pop3<br>
>>>    process_limit = 1024<br>
>>> }<br>
>>> shutdown_clients = no<br>
>>> ssl_ca = </path/path/cert.pem<br>
>>> ssl_cert = </path/path/cert.pem<br>
>>> ssl_cipher_list =<br>
>>> ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-DSS-AES128-GCM-SHA256:kEDH+AESGCM:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA:DHE-DSS-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-DSS-AES256-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:AES:CAMELLIA:!DES-CBC3-SHA:!aNULL:!eNULL:!EXPORT:!DES:!RC4:!MD5:!PSK:!aECDH:!EDH-DSS-DES-CBC3-SHA:!EDH-RSA-DES-CBC3-SHA:!KRB5-DES-CBC3-SHA<br>
>>> ssl_dh_parameters_length = 2048<br>
>>> ssl_key = </path/path/cert.pem<br>
>>> ssl_prefer_server_ciphers = yes<br>
>>> ssl_protocols = !SSLv2 !SSLv3<br>
>>> userdb {<br>
>>>    args = /etc/dovecot/dovecot-sql.conf<br>
>>>    driver = sql<br>
>>> }<br>
>>> verbose_proctitle = yes<br>
>>> protocol imap {<br>
>>>    imap_client_workarounds = delay-newmail<br>
>>>    mail_plugins = mail_log notify<br>
>>>    ssl = yes<br>
>>> }<br>
>>> protocol pop3 {<br>
>>>    pop3_client_workarounds = oe-ns-eoh outlook-no-nuls<br>
>>>    pop3_no_flag_updates = no<br>
>>>    pop3_uidl_format = %08Xu%08Xv<br>
>>>    ssl = yes<br>
>>> }<br>
>>><br>
>>> I hope you have some hints. I dislike to monitor this with fail2ban<br>
>>> and do hard restarts.<br>
>>>> Aki<br>
>>>><br>
>>> Thanks,<br>
>>> Hajo<br>
>> Can you try doing successful auth MySQL, then, for short while, blocking<br>
>> access to MySQL server using iptables (no idea how to do this with<br>
>> socket based), and try authenticating while access is blocked. It<br>
>> should, hopefully, reproduce this error.<br>
> You could try to remove the socket file when mysql is running and then using socat:<br>
><br>
> socat UNIX-LISTEN:/var/lib/mysql/mysql.sock,fork,reuseaddr,unlink-early,mode=777 TCP:<a href="http://127.0.0.1:3306" rel="noreferrer" target="_blank">127.0.0.1:3306</a><br>
><br>
> Best regards<br>
> Gerald<br>
><br>
><br>
Thanks for your help. Unfortunately iam not able to reproduce this <br>
manually. Bei blocking port with iptables or manipulating the socket <br>
dovecot always log correctly the disconnection.<br>
After unblock port or reestablishing the socket dovecot reconnects <br>
succsessful and auth works immediately.<br>
I think my report must have other nature of invalid connection/bug.<br>
<br>
A few minutes ago i noticed one server having this problem.  dovecot was <br>
logging just lines about timed out connections but in parallel i was <br>
able to connect to local mysql and run userdb/passdb queries.<br>
<br>
It starts like this:<br>
<br>
May 30 14:51:44 hostname dovecot: imap-login: Error: master(imap): Auth <br>
request timed out (received 0/12 bytes)<br>
May 30 14:51:44 hostname dovecot: imap-login: Internal login failure <br>
(pid=29595 id=1556) (internal failure, 1 successful auths): <br>
user=<username>, method=PLAIN, rip=xx.xx.xx.xx, lip=xx.xx.xx.xx, TLS<br>
May 30 14:51:44 hostname dovecot: imap: Error: Login client disconnected <br>
too early<br>
<br>
After that only lines with error, timeouts or other fails:<br>
<br>
May 30 14:52:44 hostname dovecot: auth: Error: <br>
plain(username,xx.xx.xx.xx,<3ObCymttnsZNu+bd>): Request 29595.1557 timed <br>
out after 150 secs, state=1<br>
May 30 14:52:49 hostname dovecot: imap: Error: Auth server request timed <br>
out after 155 secs (client-pid=29595 client-id=1556)<br>
May 30 14:52:59 hostname dovecot: auth: Error: <br>
plain(<a href="mailto:mail@example.com" target="_blank">mail@example.com</a>,xx.xx.xx.xx,<dqOoy2ttm/pe2WEH>): Request <br>
29595.1558 timed out after 150 secs, state=1<br>
May 30 14:53:13 hostname dovecot: imap-login: Disconnected: Inactivity <br>
during authentication (disconnected while authenticating, waited 179 <br>
secs): user=<>, method=PLAIN, rip=xx.xx.xx.xx, lip=xx.xx.xx.xx, TLS: <br>
Disconnected<br>
<br>
Unfortunately dovecot was not able to reestablish connection to local <br>
mysql.<br>
ps axu showed stack of jamed passdb queries:<br>
<br>
root      1055  0.0  0.0  40984  6120 ?        S    Mai29   0:09 <br>
dovecot/auth [0 wait, 84 passdb, 1 userdb]<br>
root      9057  0.0  0.0  40084  5144 ?        S    15:03   0:00 <br>
dovecot/auth [0 wait, 0 passdb, 0 userdb]<br>
root     11823  0.0  0.0  40084  5036 ?        S    15:04   0:00 <br>
dovecot/auth [0 wait, 0 passdb, 0 userdb]<br>
root     12975  0.0  0.0  40084  5080 ?        S    15:05   0:00 <br>
dovecot/auth worker: idling<br>
<br>
<br>
By killing PID 1055 dovecot was spawning new auth process and normal <br>
processing startet again. Until restart no Login was possible for any user.<br>
<br>
Other people reported limitproblems with systemd, but affected servers <br>
have no higher load than usual. Hmm, iam running out of ideas now.<br>
<br>
Thanks,<br>
Hajo<br>
<br>
<br>
</blockquote></div>