Re: auth: Error - Request timed out
Hi, We've experienced this too, happens once in a few months i'm reply-ing now because it happend this morning on one of our multiple nodes, other nodes were fine. debian 9.4 dovecot-core 1:2.2.34-2~bpo9+1 Feb 1 06:24:58 machine61 dovecot: auth: Error: plain(edi...@edited.nl,10.0.10.182,): Request 890.37948303 timed out after 150 secs, state=1 Restart of the daemon fixed it. unable to reproduce. I'm willing to enable specific debug options to help debug this. if you could point me in the correct settings for the dovecot: auth: daemon. On Wed, May 30, 2018 at 3:32 PM Hajo Locke wrote: > Hello, > > > Am 29.05.2018 um 11:30 schrieb Gerald Galster: > > > >> Am 29.05.2018 um 11:00 schrieb Aki Tuomi : > >> > >> > >> > >> On 29.05.2018 11:35, Hajo Locke wrote: > >>> Hello, > >>> > >>> > >>> Am 29.05.2018 um 09:22 schrieb Aki Tuomi: > On 29.05.2018 09:54, Hajo Locke wrote: > > Hello List, > > > > i use dovecot 2.2.22 and have the same problem described here: > > https://dovecot.org/pipermail/dovecot/2017-November/110020.html > > > > I can confirm that sometimes there is a problem with connection to > > mysql-db, but sometimes not. > > Reasons for failing are still under investigation by my mates. > > > > My current main problem is, that this fail seems to be a one way > > ticket for dovecot. Even if mysql is verifyable working again and > > waiting for connection dovecot stucks furthermore with errors like > > this: > > > > May 29 07:00:49 hostname dovecot: auth: Error: > > plain(m...@example.com,xxx.xxx.xx.xxx,): Request > > 999.7 timed out after 150 secs, state=1 > > > > When restarting dovecot all is immediately working again. > > Is there a way to tell dovecot to restart auth services or > > reinitialize mysql-connection after these hard fails? I could insert > > "idle_kill = 1 mins" into service auth and service auth-worker, but i > > dont know if this would work. Unfortunately i am not able to > reproduce > > this error and there are always a couple of days between errors. > > > > Thanks, > > Hajo > > > > > Hi! > > I was not able to repeat this problem using 2.2.36. Can you provide > steps to reproduce? > > May 29 10:20:24 auth: Debug: client in: AUTH1PLAIN > service=imapsecuredsession=XtpgEVNtQeUB > lip=::1rip=::1lport=143rport=58689resp= > May 29 10:20:24 auth-worker(31098): Debug: > sql(t...@domain.org,::1,): query: > SELECT userid AS username, domain, password FROM users WHERE userid = > 'test' AND domain = 'domain.org' > May 29 10:20:54 auth-worker(31098): Warning: mysql: Query failed, > retrying: Lost connection to MySQL server during query (idled for 28 > secs) > May 29 10:20:59 auth-worker(31098): Error: mysql(127.0.0.1): Connect > failed to database (dovecot): Can't connect to MySQL server on > '127.0.0.1' (4) - waiting for 5 seconds before retry > May 29 10:21:04 auth-worker(31098): Error: mysql(127.0.0.1): Connect > failed to database (dovecot): Can't connect to MySQL server on > '127.0.0.1' (4) - waiting for 5 seconds before retry > May 29 10:21:14 auth: Debug: auth client connected (pid=31134) > May 29 10:21:14 imap-login: Warning: Growing pool 'imap login > commands' > with: 1024 > May 29 10:21:14 auth-worker(31098): Error: mysql(127.0.0.1): Connect > failed to database (dovecot): Can't connect to MySQL server on > '127.0.0.1' (4) - waiting for 25 seconds before retry > > This is what it looks like for me and after restoring connectivity, it > started working normally. > >>> Unfortunately i can not reproduce. Servers running well for days or > >>> sometimes weeks and then it happens one time. I can provide some more > >>> logs. > >>> > >>> This is an error with mysql involvement: > >>> > >>> May 29 06:56:59 hostname dovecot: auth-worker(1099): Error: > >>> mysql(xx.xx.xx.xx): Connect failed to database (mysql): Can't connect > >>> to MySQL server on 'xx.xx.xx.xx' (111) - waiting for 1 seconds before > >>> retry > >>> . > >>> . some more of above line > >>> . > >>> May 29 06:56:59 hostname dovecot: auth-worker(1110): Error: > >>> sql(m...@example.com,xx.xx.xx.xx): Password query failed: Not > >>> connected to database > >>> May 29 06:56:59 hostname dovecot: auth: Error: auth worker: Aborted > >>> PASSV request for m...@example.com: Internal auth worker failure > >>> May 29 06:57:59 hostname dovecot: auth-worker(1099): Error: mysql: > >>> Query timed out (no free connections for 60 secs): SELECT `inbox` as > >>> `user`, `password` FROM `mail_users` WHERE `login` = 'username' AND > >>> `active`='Y' > >>> May 29 06:59:30 hostname dovecot: auth: Error: > >>> plain(username,xx.xx.xx.xx,): Request 999.2 timed > >>> out after 151 secs, state=1 > >>> .
Re: auth: Error - Request timed out
Hello, Am 29.05.2018 um 11:30 schrieb Gerald Galster: Am 29.05.2018 um 11:00 schrieb Aki Tuomi : On 29.05.2018 11:35, Hajo Locke wrote: Hello, Am 29.05.2018 um 09:22 schrieb Aki Tuomi: On 29.05.2018 09:54, Hajo Locke wrote: Hello List, i use dovecot 2.2.22 and have the same problem described here: https://dovecot.org/pipermail/dovecot/2017-November/110020.html I can confirm that sometimes there is a problem with connection to mysql-db, but sometimes not. Reasons for failing are still under investigation by my mates. My current main problem is, that this fail seems to be a one way ticket for dovecot. Even if mysql is verifyable working again and waiting for connection dovecot stucks furthermore with errors like this: May 29 07:00:49 hostname dovecot: auth: Error: plain(m...@example.com,xxx.xxx.xx.xxx,): Request 999.7 timed out after 150 secs, state=1 When restarting dovecot all is immediately working again. Is there a way to tell dovecot to restart auth services or reinitialize mysql-connection after these hard fails? I could insert "idle_kill = 1 mins" into service auth and service auth-worker, but i dont know if this would work. Unfortunately i am not able to reproduce this error and there are always a couple of days between errors. Thanks, Hajo Hi! I was not able to repeat this problem using 2.2.36. Can you provide steps to reproduce? May 29 10:20:24 auth: Debug: client in: AUTH1PLAIN service=imapsecuredsession=XtpgEVNtQeUB lip=::1rip=::1lport=143rport=58689resp= May 29 10:20:24 auth-worker(31098): Debug: sql(t...@domain.org,::1,): query: SELECT userid AS username, domain, password FROM users WHERE userid = 'test' AND domain = 'domain.org' May 29 10:20:54 auth-worker(31098): Warning: mysql: Query failed, retrying: Lost connection to MySQL server during query (idled for 28 secs) May 29 10:20:59 auth-worker(31098): Error: mysql(127.0.0.1): Connect failed to database (dovecot): Can't connect to MySQL server on '127.0.0.1' (4) - waiting for 5 seconds before retry May 29 10:21:04 auth-worker(31098): Error: mysql(127.0.0.1): Connect failed to database (dovecot): Can't connect to MySQL server on '127.0.0.1' (4) - waiting for 5 seconds before retry May 29 10:21:14 auth: Debug: auth client connected (pid=31134) May 29 10:21:14 imap-login: Warning: Growing pool 'imap login commands' with: 1024 May 29 10:21:14 auth-worker(31098): Error: mysql(127.0.0.1): Connect failed to database (dovecot): Can't connect to MySQL server on '127.0.0.1' (4) - waiting for 25 seconds before retry This is what it looks like for me and after restoring connectivity, it started working normally. Unfortunately i can not reproduce. Servers running well for days or sometimes weeks and then it happens one time. I can provide some more logs. This is an error with mysql involvement: May 29 06:56:59 hostname dovecot: auth-worker(1099): Error: mysql(xx.xx.xx.xx): Connect failed to database (mysql): Can't connect to MySQL server on 'xx.xx.xx.xx' (111) - waiting for 1 seconds before retry . . some more of above line . May 29 06:56:59 hostname dovecot: auth-worker(1110): Error: sql(m...@example.com,xx.xx.xx.xx): Password query failed: Not connected to database May 29 06:56:59 hostname dovecot: auth: Error: auth worker: Aborted PASSV request for m...@example.com: Internal auth worker failure May 29 06:57:59 hostname dovecot: auth-worker(1099): Error: mysql: Query timed out (no free connections for 60 secs): SELECT `inbox` as `user`, `password` FROM `mail_users` WHERE `login` = 'username' AND `active`='Y' May 29 06:59:30 hostname dovecot: auth: Error: plain(username,xx.xx.xx.xx,): Request 999.2 timed out after 151 secs, state=1 . . much more of these lines with Request timed out . At this point my mates restartet dovecot and all worked well immediately. Mysql performed a short restart at 6:56 and dovecot was not able to reconnect for about 10 mins until my mates did the restart. I could not reproduce the problem by manually restarting of mysql, this worked well. This is an error without visible mysql involvement: . . lines of normal imap/pop activity . May 29 05:43:03 hostname dovecot: imap-login: Error: master(imap): Auth request timed out (received 0/12 bytes) May 29 05:43:03 hostname dovecot: imap-login: Internal login failure (pid=1014 id=16814) (internal failure, 1 successful auths): user=, method=PLAIN, rip=xx.xx.xx.xx, lip=xx.xx.xx.xx, TLS May 29 05:43:03 hostname dovecot: imap: Error: Login client disconnected too early May 29 05:44:03 hostname dovecot: auth: Error: plain(username,xx.xx.xx.xx,): Request 1014.16815 timed out after 150 secs, state=1 May 29 05:44:08 hostname dovecot: imap: Error: Auth server request timed out after 155 secs (client-pid=1014 client-id=16814) May 29 05:44:33 hostname dovecot: imap-login: Disconnected: Inactivity during authentication (disconnected while authenticating, waited 180 secs): user=<>, method=PLAIN, rip=xx.xx.xx.xx, lip=xx.
Re: auth: Error - Request timed out
> Am 29.05.2018 um 11:00 schrieb Aki Tuomi : > > > > On 29.05.2018 11:35, Hajo Locke wrote: >> Hello, >> >> >> Am 29.05.2018 um 09:22 schrieb Aki Tuomi: >>> >>> On 29.05.2018 09:54, Hajo Locke wrote: Hello List, i use dovecot 2.2.22 and have the same problem described here: https://dovecot.org/pipermail/dovecot/2017-November/110020.html I can confirm that sometimes there is a problem with connection to mysql-db, but sometimes not. Reasons for failing are still under investigation by my mates. My current main problem is, that this fail seems to be a one way ticket for dovecot. Even if mysql is verifyable working again and waiting for connection dovecot stucks furthermore with errors like this: May 29 07:00:49 hostname dovecot: auth: Error: plain(m...@example.com,xxx.xxx.xx.xxx,): Request 999.7 timed out after 150 secs, state=1 When restarting dovecot all is immediately working again. Is there a way to tell dovecot to restart auth services or reinitialize mysql-connection after these hard fails? I could insert "idle_kill = 1 mins" into service auth and service auth-worker, but i dont know if this would work. Unfortunately i am not able to reproduce this error and there are always a couple of days between errors. Thanks, Hajo >>> Hi! >>> >>> I was not able to repeat this problem using 2.2.36. Can you provide >>> steps to reproduce? >>> >>> May 29 10:20:24 auth: Debug: client in: AUTH1PLAIN >>> service=imapsecuredsession=XtpgEVNtQeUB >>> lip=::1rip=::1lport=143rport=58689resp= >>> May 29 10:20:24 auth-worker(31098): Debug: >>> sql(t...@domain.org,::1,): query: >>> SELECT userid AS username, domain, password FROM users WHERE userid = >>> 'test' AND domain = 'domain.org' >>> May 29 10:20:54 auth-worker(31098): Warning: mysql: Query failed, >>> retrying: Lost connection to MySQL server during query (idled for 28 >>> secs) >>> May 29 10:20:59 auth-worker(31098): Error: mysql(127.0.0.1): Connect >>> failed to database (dovecot): Can't connect to MySQL server on >>> '127.0.0.1' (4) - waiting for 5 seconds before retry >>> May 29 10:21:04 auth-worker(31098): Error: mysql(127.0.0.1): Connect >>> failed to database (dovecot): Can't connect to MySQL server on >>> '127.0.0.1' (4) - waiting for 5 seconds before retry >>> May 29 10:21:14 auth: Debug: auth client connected (pid=31134) >>> May 29 10:21:14 imap-login: Warning: Growing pool 'imap login commands' >>> with: 1024 >>> May 29 10:21:14 auth-worker(31098): Error: mysql(127.0.0.1): Connect >>> failed to database (dovecot): Can't connect to MySQL server on >>> '127.0.0.1' (4) - waiting for 25 seconds before retry >>> >>> This is what it looks like for me and after restoring connectivity, it >>> started working normally. >> Unfortunately i can not reproduce. Servers running well for days or >> sometimes weeks and then it happens one time. I can provide some more >> logs. >> >> This is an error with mysql involvement: >> >> May 29 06:56:59 hostname dovecot: auth-worker(1099): Error: >> mysql(xx.xx.xx.xx): Connect failed to database (mysql): Can't connect >> to MySQL server on 'xx.xx.xx.xx' (111) - waiting for 1 seconds before >> retry >> . >> . some more of above line >> . >> May 29 06:56:59 hostname dovecot: auth-worker(1110): Error: >> sql(m...@example.com,xx.xx.xx.xx): Password query failed: Not >> connected to database >> May 29 06:56:59 hostname dovecot: auth: Error: auth worker: Aborted >> PASSV request for m...@example.com: Internal auth worker failure >> May 29 06:57:59 hostname dovecot: auth-worker(1099): Error: mysql: >> Query timed out (no free connections for 60 secs): SELECT `inbox` as >> `user`, `password` FROM `mail_users` WHERE `login` = 'username' AND >> `active`='Y' >> May 29 06:59:30 hostname dovecot: auth: Error: >> plain(username,xx.xx.xx.xx,): Request 999.2 timed >> out after 151 secs, state=1 >> . >> . much more of these lines with Request timed out >> . >> >> At this point my mates restartet dovecot and all worked well >> immediately. Mysql performed a short restart at 6:56 and dovecot was >> not able to reconnect for about 10 mins until my mates did the >> restart. I could not reproduce the problem by manually restarting of >> mysql, this worked well. >> >> This is an error without visible mysql involvement: >> . >> . lines of normal imap/pop activity >> . >> May 29 05:43:03 hostname dovecot: imap-login: Error: master(imap): >> Auth request timed out (received 0/12 bytes) >> May 29 05:43:03 hostname dovecot: imap-login: Internal login failure >> (pid=1014 id=16814) (internal failure, 1 successful auths): >> user=, method=PLAIN, rip=xx.xx.xx.xx, lip=xx.xx.xx.xx, TLS >> May 29 05:43:03 hostname dovecot: imap: Error: Login client >> disconnected too early >> May 29 05:44:03 hostname dovecot: auth: Error: >> plain(username,xx.xx.xx.x
Re: auth: Error - Request timed out
On 29.05.2018 11:35, Hajo Locke wrote: > Hello, > > > Am 29.05.2018 um 09:22 schrieb Aki Tuomi: >> >> On 29.05.2018 09:54, Hajo Locke wrote: >>> Hello List, >>> >>> i use dovecot 2.2.22 and have the same problem described here: >>> https://dovecot.org/pipermail/dovecot/2017-November/110020.html >>> >>> I can confirm that sometimes there is a problem with connection to >>> mysql-db, but sometimes not. >>> Reasons for failing are still under investigation by my mates. >>> >>> My current main problem is, that this fail seems to be a one way >>> ticket for dovecot. Even if mysql is verifyable working again and >>> waiting for connection dovecot stucks furthermore with errors like >>> this: >>> >>> May 29 07:00:49 hostname dovecot: auth: Error: >>> plain(m...@example.com,xxx.xxx.xx.xxx,): Request >>> 999.7 timed out after 150 secs, state=1 >>> >>> When restarting dovecot all is immediately working again. >>> Is there a way to tell dovecot to restart auth services or >>> reinitialize mysql-connection after these hard fails? I could insert >>> "idle_kill = 1 mins" into service auth and service auth-worker, but i >>> dont know if this would work. Unfortunately i am not able to reproduce >>> this error and there are always a couple of days between errors. >>> >>> Thanks, >>> Hajo >>> >>> >> Hi! >> >> I was not able to repeat this problem using 2.2.36. Can you provide >> steps to reproduce? >> >> May 29 10:20:24 auth: Debug: client in: AUTH 1 PLAIN >> service=imap secured session=XtpgEVNtQeUB >> lip=::1 rip=::1 lport=143 rport=58689 resp= >> May 29 10:20:24 auth-worker(31098): Debug: >> sql(t...@domain.org,::1,): query: >> SELECT userid AS username, domain, password FROM users WHERE userid = >> 'test' AND domain = 'domain.org' >> May 29 10:20:54 auth-worker(31098): Warning: mysql: Query failed, >> retrying: Lost connection to MySQL server during query (idled for 28 >> secs) >> May 29 10:20:59 auth-worker(31098): Error: mysql(127.0.0.1): Connect >> failed to database (dovecot): Can't connect to MySQL server on >> '127.0.0.1' (4) - waiting for 5 seconds before retry >> May 29 10:21:04 auth-worker(31098): Error: mysql(127.0.0.1): Connect >> failed to database (dovecot): Can't connect to MySQL server on >> '127.0.0.1' (4) - waiting for 5 seconds before retry >> May 29 10:21:14 auth: Debug: auth client connected (pid=31134) >> May 29 10:21:14 imap-login: Warning: Growing pool 'imap login commands' >> with: 1024 >> May 29 10:21:14 auth-worker(31098): Error: mysql(127.0.0.1): Connect >> failed to database (dovecot): Can't connect to MySQL server on >> '127.0.0.1' (4) - waiting for 25 seconds before retry >> >> This is what it looks like for me and after restoring connectivity, it >> started working normally. > Unfortunately i can not reproduce. Servers running well for days or > sometimes weeks and then it happens one time. I can provide some more > logs. > > This is an error with mysql involvement: > > May 29 06:56:59 hostname dovecot: auth-worker(1099): Error: > mysql(xx.xx.xx.xx): Connect failed to database (mysql): Can't connect > to MySQL server on 'xx.xx.xx.xx' (111) - waiting for 1 seconds before > retry > . > . some more of above line > . > May 29 06:56:59 hostname dovecot: auth-worker(1110): Error: > sql(m...@example.com,xx.xx.xx.xx): Password query failed: Not > connected to database > May 29 06:56:59 hostname dovecot: auth: Error: auth worker: Aborted > PASSV request for m...@example.com: Internal auth worker failure > May 29 06:57:59 hostname dovecot: auth-worker(1099): Error: mysql: > Query timed out (no free connections for 60 secs): SELECT `inbox` as > `user`, `password` FROM `mail_users` WHERE `login` = 'username' AND > `active`='Y' > May 29 06:59:30 hostname dovecot: auth: Error: > plain(username,xx.xx.xx.xx,): Request 999.2 timed > out after 151 secs, state=1 > . > . much more of these lines with Request timed out > . > > At this point my mates restartet dovecot and all worked well > immediately. Mysql performed a short restart at 6:56 and dovecot was > not able to reconnect for about 10 mins until my mates did the > restart. I could not reproduce the problem by manually restarting of > mysql, this worked well. > > This is an error without visible mysql involvement: > . > . lines of normal imap/pop activity > . > May 29 05:43:03 hostname dovecot: imap-login: Error: master(imap): > Auth request timed out (received 0/12 bytes) > May 29 05:43:03 hostname dovecot: imap-login: Internal login failure > (pid=1014 id=16814) (internal failure, 1 successful auths): > user=, method=PLAIN, rip=xx.xx.xx.xx, lip=xx.xx.xx.xx, TLS > May 29 05:43:03 hostname dovecot: imap: Error: Login client > disconnected too early > May 29 05:44:03 hostname dovecot: auth: Error: > plain(username,xx.xx.xx.xx,): Request 1014.16815 > timed out after 150 secs, state=1 > May 29 05:44:08 hostname dovecot: imap: Error: Auth server request > timed out after 155 secs (client-pid=1014 client-id=1681
Re: auth: Error - Request timed out
Hello, Am 29.05.2018 um 09:22 schrieb Aki Tuomi: On 29.05.2018 09:54, Hajo Locke wrote: Hello List, i use dovecot 2.2.22 and have the same problem described here: https://dovecot.org/pipermail/dovecot/2017-November/110020.html I can confirm that sometimes there is a problem with connection to mysql-db, but sometimes not. Reasons for failing are still under investigation by my mates. My current main problem is, that this fail seems to be a one way ticket for dovecot. Even if mysql is verifyable working again and waiting for connection dovecot stucks furthermore with errors like this: May 29 07:00:49 hostname dovecot: auth: Error: plain(m...@example.com,xxx.xxx.xx.xxx,): Request 999.7 timed out after 150 secs, state=1 When restarting dovecot all is immediately working again. Is there a way to tell dovecot to restart auth services or reinitialize mysql-connection after these hard fails? I could insert "idle_kill = 1 mins" into service auth and service auth-worker, but i dont know if this would work. Unfortunately i am not able to reproduce this error and there are always a couple of days between errors. Thanks, Hajo Hi! I was not able to repeat this problem using 2.2.36. Can you provide steps to reproduce? May 29 10:20:24 auth: Debug: client in: AUTH 1 PLAIN service=imap secured session=XtpgEVNtQeUB lip=::1 rip=::1 lport=143 rport=58689 resp= May 29 10:20:24 auth-worker(31098): Debug: sql(t...@domain.org,::1,): query: SELECT userid AS username, domain, password FROM users WHERE userid = 'test' AND domain = 'domain.org' May 29 10:20:54 auth-worker(31098): Warning: mysql: Query failed, retrying: Lost connection to MySQL server during query (idled for 28 secs) May 29 10:20:59 auth-worker(31098): Error: mysql(127.0.0.1): Connect failed to database (dovecot): Can't connect to MySQL server on '127.0.0.1' (4) - waiting for 5 seconds before retry May 29 10:21:04 auth-worker(31098): Error: mysql(127.0.0.1): Connect failed to database (dovecot): Can't connect to MySQL server on '127.0.0.1' (4) - waiting for 5 seconds before retry May 29 10:21:14 auth: Debug: auth client connected (pid=31134) May 29 10:21:14 imap-login: Warning: Growing pool 'imap login commands' with: 1024 May 29 10:21:14 auth-worker(31098): Error: mysql(127.0.0.1): Connect failed to database (dovecot): Can't connect to MySQL server on '127.0.0.1' (4) - waiting for 25 seconds before retry This is what it looks like for me and after restoring connectivity, it started working normally. Unfortunately i can not reproduce. Servers running well for days or sometimes weeks and then it happens one time. I can provide some more logs. This is an error with mysql involvement: May 29 06:56:59 hostname dovecot: auth-worker(1099): Error: mysql(xx.xx.xx.xx): Connect failed to database (mysql): Can't connect to MySQL server on 'xx.xx.xx.xx' (111) - waiting for 1 seconds before retry . . some more of above line . May 29 06:56:59 hostname dovecot: auth-worker(1110): Error: sql(m...@example.com,xx.xx.xx.xx): Password query failed: Not connected to database May 29 06:56:59 hostname dovecot: auth: Error: auth worker: Aborted PASSV request for m...@example.com: Internal auth worker failure May 29 06:57:59 hostname dovecot: auth-worker(1099): Error: mysql: Query timed out (no free connections for 60 secs): SELECT `inbox` as `user`, `password` FROM `mail_users` WHERE `login` = 'username' AND `active`='Y' May 29 06:59:30 hostname dovecot: auth: Error: plain(username,xx.xx.xx.xx,): Request 999.2 timed out after 151 secs, state=1 . . much more of these lines with Request timed out . At this point my mates restartet dovecot and all worked well immediately. Mysql performed a short restart at 6:56 and dovecot was not able to reconnect for about 10 mins until my mates did the restart. I could not reproduce the problem by manually restarting of mysql, this worked well. This is an error without visible mysql involvement: . . lines of normal imap/pop activity . May 29 05:43:03 hostname dovecot: imap-login: Error: master(imap): Auth request timed out (received 0/12 bytes) May 29 05:43:03 hostname dovecot: imap-login: Internal login failure (pid=1014 id=16814) (internal failure, 1 successful auths): user=, method=PLAIN, rip=xx.xx.xx.xx, lip=xx.xx.xx.xx, TLS May 29 05:43:03 hostname dovecot: imap: Error: Login client disconnected too early May 29 05:44:03 hostname dovecot: auth: Error: plain(username,xx.xx.xx.xx,): Request 1014.16815 timed out after 150 secs, state=1 May 29 05:44:08 hostname dovecot: imap: Error: Auth server request timed out after 155 secs (client-pid=1014 client-id=16814) May 29 05:44:33 hostname dovecot: imap-login: Disconnected: Inactivity during authentication (disconnected while authenticating, waited 180 secs): user=<>, method=PLAIN, rip=xx.xx.xx.xx, lip=xx.xx.xx.xx, TLS: Disconnected May 29 05:46:07 hostname dovecot: auth: Error: plain(m...@example.com,xx.xx.xx.xx,): Req
Re: auth: Error - Request timed out
On 29.05.2018 09:54, Hajo Locke wrote: > Hello List, > > i use dovecot 2.2.22 and have the same problem described here: > https://dovecot.org/pipermail/dovecot/2017-November/110020.html > > I can confirm that sometimes there is a problem with connection to > mysql-db, but sometimes not. > Reasons for failing are still under investigation by my mates. > > My current main problem is, that this fail seems to be a one way > ticket for dovecot. Even if mysql is verifyable working again and > waiting for connection dovecot stucks furthermore with errors like this: > > May 29 07:00:49 hostname dovecot: auth: Error: > plain(m...@example.com,xxx.xxx.xx.xxx,): Request > 999.7 timed out after 150 secs, state=1 > > When restarting dovecot all is immediately working again. > Is there a way to tell dovecot to restart auth services or > reinitialize mysql-connection after these hard fails? I could insert > "idle_kill = 1 mins" into service auth and service auth-worker, but i > dont know if this would work. Unfortunately i am not able to reproduce > this error and there are always a couple of days between errors. > > Thanks, > Hajo > > Hi! I was not able to repeat this problem using 2.2.36. Can you provide steps to reproduce? May 29 10:20:24 auth: Debug: client in: AUTH 1 PLAIN service=imap secured session=XtpgEVNtQeUB lip=::1 rip=::1 lport=143 rport=58689 resp= May 29 10:20:24 auth-worker(31098): Debug: sql(t...@domain.org,::1,): query: SELECT userid AS username, domain, password FROM users WHERE userid = 'test' AND domain = 'domain.org' May 29 10:20:54 auth-worker(31098): Warning: mysql: Query failed, retrying: Lost connection to MySQL server during query (idled for 28 secs) May 29 10:20:59 auth-worker(31098): Error: mysql(127.0.0.1): Connect failed to database (dovecot): Can't connect to MySQL server on '127.0.0.1' (4) - waiting for 5 seconds before retry May 29 10:21:04 auth-worker(31098): Error: mysql(127.0.0.1): Connect failed to database (dovecot): Can't connect to MySQL server on '127.0.0.1' (4) - waiting for 5 seconds before retry May 29 10:21:14 auth: Debug: auth client connected (pid=31134) May 29 10:21:14 imap-login: Warning: Growing pool 'imap login commands' with: 1024 May 29 10:21:14 auth-worker(31098): Error: mysql(127.0.0.1): Connect failed to database (dovecot): Can't connect to MySQL server on '127.0.0.1' (4) - waiting for 25 seconds before retry This is what it looks like for me and after restoring connectivity, it started working normally. Aki
