Question PostFix Dovecot Timeout

[swiper]

Server operating system version

20.04

Plesk version and microupdate number

18.0.44

I have big problems with my mail server.

What I have already tried:

# Plesk Repair Mailserver
# disable Fail2Ban
# Plesk Mailserver Max connections = 10240
... max connections pro ip = 5000
# DMARC = yes
# DKIM spam outgoing = yes

Imap mailboxes ~ 30

Sometimes I have zero problems, but often my MailClient query times out.

How could I proceed further?

Expand/Collapse Block: mail.err

Jul 6 10:52:29 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 2.000 secs
Jul 6 10:52:31 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:52:31 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 2.000 secs
Jul 6 10:52:33 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:52:33 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 2.000 secs
Jul 6 10:52:35 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:52:35 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 2.000 secs
Jul 6 10:52:37 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:52:37 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 2.000 secs
Jul 6 10:52:37 srv1 dovecot: master: Error: service(imap): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:52:37 srv1 dovecot: master: Error: service(imap): command startup failed, throttling for 2.000 secs
Jul 6 10:52:39 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:52:39 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 4.000 secs
.....
Jul 6 10:56:01 srv1 dovecot: master: Error: service(pop3-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:56:01 srv1 dovecot: master: Error: service(pop3-login): command startup failed, throttling for 2.000 secs
Jul 6 10:56:10 srv1 dk_check[2503934]: D6F29120069: DKIM Feed: No signature
Jul 6 10:56:10 srv1 psa-pc-remote[2502854]: Message aborted.
Jul 6 10:56:10 srv1 psa-pc-remote[2502854]: Message aborted.
Jul 6 10:56:22 srv1 dovecot: imap-login: Error: master(imap): Auth request timed out (client-pid=2503840, client-id=1, rip=93.192.54.206, created 90057 msecs ago, received 0/4 bytes)
Jul 6 10:56:54 srv1 dovecot: imap(2503970): Error: Login client disconnected too early (connection created 0 msecs ago, client created 0 msecs ago: session=K0tLHx/ju9VdwDbO, rip=93.192.54.206, auth_pid=2502948, client-pid=2503840, client-id=1)
Jul 6 10:56:54 srv1 dovecot: imap(2503970): Error: auth-master: login: request [2845704193]: Login auth request failed: Internal auth failure (auth connected 0 msecs ago, request took 0 msecs, client-pid=2503840 client-id=1)
Jul 6 10:56:54 srv1 dovecot: auth: Error: auth-master client: Master requested auth for nonexistent client 2503840 (created 0 msecs ago, handshake 0 msecs ago)
Jul 6 10:57:49 srv1 spf[2504032]: A1DCC120054: Error code: (2) Could not find a valid SPF record
Jul 6 10:57:49 srv1 spf[2504032]: A1DCC120054: Failed to query MAIL-FROM: No DNS data for 'mau-taxi.de'.
Jul 6 10:57:49 srv1 dk_check[2504034]: A1DCC120054: DKIM Feed: No signature
Jul 6 10:58:11 srv1 dk_check[2504062]: 0D016120054: DKIM Feed: No signature
Jul 6 10:58:14 srv1 dovecot: master: Error: service(imap): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:58:14 srv1 dovecot: master: Error: service(imap): command startup failed, throttling for 2.000 secs
Jul 6 10:58:16 srv1 dovecot: master: Error: service(imap): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:58:16 srv1 dovecot: master: Error: service(imap): command startup failed, throttling for 4.000 secs
Jul 6 10:58:20 srv1 dovecot: master: Error: service(imap): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:58:20 srv1 dovecot: master: Error: service(imap): command startup failed, throttling for 8.000 secs
Jul 6 10:58:22 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:58:22 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 2.000 secs
Jul 6 10:58:24 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:58:24 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 4.000 secs
Jul 6 10:58:28 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:58:28 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 8.000 secs
Jul 6 10:58:28 srv1 dovecot: master: Error: service(imap): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:58:28 srv1 dovecot: master: Error: service(imap): command startup failed, throttling for 16.000 secs
Jul 6 10:58:36 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:58:36 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 16.000 secs
Jul 6 10:58:44 srv1 dovecot: master: Error: service(imap): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:58:44 srv1 dovecot: master: Error: service(imap): command startup failed, throttling for 32.000 secs
Jul 6 10:58:52 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:58:52 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 32.000 secs
Jul 6 10:59:17 srv1 dovecot: master: Error: service(imap): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:59:17 srv1 dovecot: master: Error: service(imap): command startup failed, throttling for 60.000 secs
Jul 6 10:59:24 srv1 dovecot: master: Error: service(imap-login): fork() failed: Resource temporarily unavailable (ulimit -u 62987 reached?)
Jul 6 10:59:24 srv1 dovecot: master: Error: service(imap-login): command startup failed, throttling for 60.000 secs

 

[swiper]

Now i have changed my config to:
process_limit : 512
mail_max_userip_connections: 64

It looks like fewer "fork() failed" errors are coming in. However, there are still some coming in.

 

[Maarten.]

You're running into a ulimit issue: Resource temporarily unavailable (ulimit -u 62987 reached?)

Check and raise the ulimit of the dovecot user if possible.

 

[swiper]

So far I have not found out where I could set this.

But do you really mean that I have just under 63k of connections on my server? There are max. 100 website visitors at the same time and about 30 mailboxes.

I found the following command. Is that correct?

ps -eLf | wc -l
432

 

[Maarten.]

Try this:

Edit /etc/systemd/system/multi-user.target.wants/dovecot.service and add/change:
LimitNOFILE=65535

Next:
# systemctl daemon-reload
# systemctl restart dovecot.service

And check the limits:
# grep files /proc/$(pgrep -f 'dovecot -F')/limits

 

[swiper]

Try this:

Edit /etc/systemd/system/multi-user.target.wants/dovecot.service and add/change:
LimitNOFILE=65535

Next:
# systemctl daemon-reload
# systemctl restart dovecot.service

And check the limits:
# grep files /proc/$(pgrep -f 'dovecot -F')/limits

LimitNOFILE was already on 65535

# systemctl restart dovecot.service -> needed 60 seconds

root@srv1:/var/log# grep files /proc/$(pgrep -f 'dovecot -F')/limits
Max open files 65535 65535 files

 

[Maarten.]

Have you tried the dovecot debug mode?

https://support.plesk.com/hc/en-us/articles/115003712374-How-to-enable-Dovecot-debug-logging-

 

[swiper]

In the meantime, I enabled the Dovecot debug logs. But unfortunately I could not get any new insights here.

Now, I get new errors:

Jul 7 16:52:56 srv1 dovecot: lda(2607512): Fatal: Internal error occurred. Refer to server log for more information.
Jul 7 16:52:56 srv1 dovecot: lda(2607513): Fatal: Internal error occurred. Refer to server log for more information.
Jul 7 16:57:15 srv1 dovecot_authdb_plesk[2607699]: unable to execute /opt/psa/admin/sbin/mailmng-server --features: Cannot allocate memory
Jul 7 16:57:15 srv1 dovecot: auth: Fatal: authdb plesk: initialization failed - unable to detect current mail authentication DB
Jul 7 16:57:15 srv1 dovecot: master: Error: service(auth): command startup failed, throttling for 60.000 secs
Jul 7 16:58:22 srv1 dovecot_authdb_plesk[2607761]: unable to execute /opt/psa/admin/sbin/mailmng-server --features: Cannot allocate memory
Jul 7 16:58:22 srv1 dovecot: auth: Fatal: authdb plesk: initialization failed - unable to detect current mail authentication DB
Jul 7 16:58:22 srv1 dovecot: master: Error: service(auth): command startup failed, throttling for 60.000 secs
Jul 7 16:58:53 srv1 dovecot: imap-login: Error: auth-client: conn unix:login (pid=2543439,uid=0): Timeout waiting for handshake from auth server. my pid=2607763, input bytes=0

As I said, my server is not particularly busy.

Plesk process list:
8 GB RAM and 70% free

Now I can find entries in the "server-wide email settings

 

[swiper]

Perhaps:

Jul 7 17:27:26 srv1 dovecot: service=lda, user=s@cl####.de, ip=[]. Error: auth-master: userdb lookup(s@cl#####.de): Disconnected unexpectedly
Jul 7 17:27:26 srv1 dovecot: lda(2633330): Fatal: Internal error occurred. Refer to server log for more information.
Jul 7 17:27:26 srv1 dovecot: service=lda, user=gps@cl####.de, ip=[]. Error: auth-master: userdb lookup(gps@cl####.de): Disconnected unexpectedly
Jul 7 17:27:26 srv1 dovecot: lda(2633333): Fatal: Internal error occurred. Refer to server log for more information.

?? ServerLog = var/log/syslog

 

[kassi]

@swiper Did you find a solution? Seems like I'm running into similar issues since update to plesk 18.0.55 (Update 2 I think).
Never had trouble before.
Now iOS clients will trigger the "Disconnected unexpectedly" while Mail.app on MacOS can't connect at all, getting

/var/log/mail.err

Oct  7 10:42:46 h2554124 dovecot: service=lda, [email protected], ip=[]. Error: auth-master: userdb lookup([email protected]): Connecting timed out
Oct  7 10:42:46 h2554124 dovecot: lda(1912326): Fatal: Internal error occurred. Refer to server log for more information.

Debugging is enabled, but the server log doesn't reveal much more, just a bit:
/var/log/syslog

Oct  7 10:42:46 h2554124 dovecot: service=lda, [email protected], ip=[]. Error: auth-master: userdb lookup([email protected]): Connecting timed out
Oct  7 10:42:46 h2554124 dovecot: service=lda, [email protected], ip=[]. Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb (pid=1901811,uid=0): Disconnected: Connection closed (fd=9)
Oct  7 10:42:46 h2554124 dovecot: service=lda, [email protected], ip=[]. Debug: auth-master: userdb lookup([email protected]): Userdb lookup failed
Oct  7 10:42:46 h2554124 dovecot: lda(1912326): Fatal: Internal error occurred. Refer to server log for more information.

 

[kassi]

Correction to the above: after a service restart of dovecot, Mail.app connects once and downloads mails. After a few minutes I see the triangles telling me that mail app is offline and no connection to mail server is possible anymore.
I don't see anything in the logs of successful or failed login attempts, although debugging is switched on.

 

[Peter Debik]

Maybe too many connections are made to the database? These could result from too many connections from the end user device. Just a guess, though.

 

[kassi]

How to check / change this? I'm not a dovecot expert (thought I'm using Plesk in order to not having to bother with such details).

 

[Maarten.]

This would help:

https://support.plesk.com/hc/en-us/articles/12376926396183-Unable-to-connect-to-mailbox-on-Plesk-via-IMAP-POP3-Maximum-number-of-connections-from-user-IP-exceeded-OR-Maximum-connection-limit-reached-

 

[kassi]

Thanks. However I'm not getting anything related to max number of connections.
I'm trying since days to fix it. There are probably several issues, but I can't resolve any one individually.
For instance

dovecot: log(2214938): Error: net_accept() failed: Bad file descriptor

happens everytime dovecot is restarted. May be normal. Current workaround - which is really not nice - is to restart dovecot via cron every couple of minutes, so I can at least fetch mails once every couple of minutes.

Most recent error is:

dovecot: master: Error: service(imap-login): Initial status notification not received in 30 seconds, killing the process

Also see couple of those in a row

dovecot: master: Error: service(imap-login): child 1980944 returned error 82 (Internal logging error)

and several (with diverging process number)

dovecot: master: Error: service(imap-login): Process 2000467 is ignoring idle SIGINT

I also don't see any logging related to imap-login although everything is set to debug.

This all happened out of a sudden on Sep 30 from a time right after plesk system update cron, without me interacting with the config at all. Couldn't figure out if anything has been auto installed / updated though.

 

[Maarten.]

I recommend opening a support ticket with https://support.plesk.com, so that an engineer can check and fix the issue directly on your server.

To sign in to support, please go to https://support.plesk.com

If you experience login issues, please see this KB article:
https://support.plesk.com/hc/en-us/...rt-plesk-com-and-password-reset-does-not-work

If you bought your license from a reseller, your reseller should provide support for you. If the reseller does not provide support, here is an alternative:
https://support.plesk.com/hc/en-us/articles/12388090147095-How-to-get-support-directly-from-Plesk-