Thousands of SSL certificates stalls new logins during reload - problem with Dovecot config process

2 Sep 2022

      Hello,
I'm running a dovecot 2.3.19.1 server that has around 6000 SSL
certificates in separate config files, each containing:
local_name "domain" {
ssl_cert = ...
ssl_key = ...
}
When new certificate is added, dovecot is reloaded (around 20 times a
day). When dovecot is being reloaded, users are unable to log in for
around 30 seconds.
The main problem here seems to be that during reload, new config process
is immediately designated as the one serving config requests and then it
starts parsing config files, which takes around 20-30 seconds. If it
would parse config files first, and only then would become a new process
for serving config requests, then it would probably solve the problem.
Or perhaps there is a better way to load new certificates or a way to
optimize?
There is another problem with config process and shutdown_clients=no. We
do not want to disconnect users during reload, because e.g. Thunderbird
displays a popup that server is shutting down. When there are long
lasting IMAP connections from Google and other services that aggregate
e-mail, old config process is not being killed. Because config process
with ~6000 certificates is using ~1 GB of RAM, it can quickly rise to 20
GB of memory used. This is not a big issue however, because we have
created a task that kills old processes, but there could be a built-in
mechanism to solve that problem.
I have created minimal configuration and scripts to recreate problem.
Reproduction steps below.
Configuration (doveadm config -n):
# 2.3.19.1 (9b53102964): /etc/dovecot/dovecot.conf
# OS: Linux 4.18.0-372.9.1.1.lve.el8.x86_64 x86_64 CloudLinux release
8.6 (Leonid Kadenyuk)
# Hostname: -
auth_mechanisms = plain login
default_client_limit = 12288
default_process_limit = 2048
default_vsz_limit = 1 G
first_valid_uid = 1000
mail_location = maildir:~/mail
mbox_write_locks = fcntl
namespace inbox {
inbox = yes
location =
mailbox Drafts {
special_use = \Drafts
}
mailbox Sent {
special_use = \Sent
}
mailbox "Sent Messages" {
special_use = \Sent
}
mailbox Trash {
special_use = \Trash
}
prefix =
}
passdb {
args = scheme=CRYPT username_format=%u /etc/dovecot/users
driver = passwd-file
}
service auth-worker {
user = $default_internal_user
}
service auth {
user = $default_internal_user
}
service config {
vsz_limit = 4 G
}
service imap-login {
process_min_avail = 20
service_count = 1
}
service imap {
process_limit = 4096
}
service pop3-login {
process_min_avail = 20
service_count = 1
}
service pop3 {
process_limit = 512
}
shutdown_clients = no
ssl_cert = </etc/dovecot/certs/example.org.crt
ssl_cipher_list =
ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:DHE-DSS-AES128-GCM-SHA256:DHE-DSS-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:DHE-DSS-AES128-SHA256:DHE-DSS-AES256-SHA256:DHE-DSS-AES128-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA:ECDH-ECDSA-AES128-GCM-SHA256:ECDH-ECDSA-AES256-GCM-SHA384:ECDH-RSA-AES128-GCM-SHA256:ECDH-RSA-AES256-GCM-SHA384:ECDH-ECDSA-AES128-SHA256:ECDH-ECDSA-AES256-SHA384:ECDH-ECDSA-AES128-SHA:ECDH-RSA-AES128-SHA256:ECDH-RSA-AES256-SHA384:ECDH-RSA-AES128-SHA:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-CHACHA20-POLY1305
ssl_dh = </etc/dovecot/dh.pem
ssl_key = </etc/dovecot/certs/example.org.key
ssl_options = no_compression
ssl_prefer_server_ciphers = yes
userdb {
args = username_format=%u /etc/dovecot/users
driver = passwd-file
}
verbose_proctitle = yes
protocol imap {
mail_max_userip_connections = 2048
}
protocol pop3 {
mail_max_userip_connections = 2048
}
local_name domain4587.example.org mail.domain4587.example.org {
ssl_cert = </etc/dovecot/certs/domain4587.example.org.crt
ssl_key = </etc/dovecot/certs/domain4587.example.org.key
}
local_name domain4588.example.org mail.domain4588.example.org {
ssl_cert = </etc/dovecot/certs/domain4588.example.org.crt
ssl_key = </etc/dovecot/certs/domain4588.example.org.key
}
(...) 5000 certificates goes here
/etc/dovecot/users:
user@domain1.example.org:{SHA512-CRYPT}$6$...:1000:1000::/home/test/mail/domain1.example.org/user::
user@domain2.example.org:{SHA512-CRYPT}$6$...:1000:1000::/home/test/mail/domain2.example.org/user::
(...) 5000 users goes here, but one should be enough for testing.
Log file from dovecot reload:
Sep 02 12:37:24 dovecot[264040]: imap-login: Login:
user=<user@domain1.example.org>, method=PLAIN, rip=127.0.0.1,
lip=127.0.0.1, mpid=264964, TLS, session=<eQXGUK/ngJJ/AAAB>
Sep 02 12:37:24 dovecot[264040]:
imap(user@domain1.example.org)<264964><eQXGUK/ngJJ/AAAB>: Disconnected:
Logged out in=25 out=782 deleted=0 expunged=0 trashed=0 hdr_count=0
hdr_bytes=0 body_count=0 body_bytes=0
Sep 02 12:37:25 systemd[1]: Reloading Dovecot IMAP/POP3 email server.
Sep 02 12:37:26 dovecot[263234]: master: Warning: SIGHUP received -
reloading configuration
Sep 02 12:37:36 dovecot[263234]: master: Error: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: /usr/local/var/run/dovecot/config is a
UNIX socket
Sep 02 12:37:36 systemd[1]: Reloaded Dovecot IMAP/POP3 email server.
Sep 02 12:37:36 dovecot[264040]: imap-login: Fatal: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: stat(/usr/local/var/run/dovecot/config)
failed: No such file or directory (path is from CONFIG_FILE environment)
Sep 02 12:37:36 dovecot[264040]: imap-login: Fatal: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: stat(/usr/local/var/run/dovecot/config)
failed: No such file or directory (path is from CONFIG_FILE environment)
Sep 02 12:37:42 dovecot[264040]: imap-login: Fatal: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: stat(/usr/local/var/run/dovecot/config)
failed: No such file or directory (path is from CONFIG_FILE environment)
Sep 02 12:37:46 dovecot[264040]: imap-login: Fatal: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: /usr/local/var/run/dovecot/config is a
UNIX socket (path is from CONFIG_FILE environment)
Sep 02 12:37:46 dovecot[264040]: imap-login: Fatal: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: /usr/local/var/run/dovecot/config is a
UNIX socket (path is from CONFIG_FILE environment)
Sep 02 12:37:46 dovecot[263234]: master: Error: service(imap-login):
command startup failed, throttling for 2.000 secs
Sep 02 12:37:46 dovecot[264040]: imap-login: Fatal: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: /usr/local/var/run/dovecot/config is a
UNIX socket (path is from CONFIG_FILE environment)
Sep 02 12:37:47 dovecot[264040]: imap-login: Fatal: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: stat(/usr/local/var/run/dovecot/config)
failed: No such file or directory (path is from CONFIG_FILE environment)
Sep 02 12:37:47 dovecot[264040]: imap-login: Fatal: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: /usr/local/var/run/dovecot/config is a
UNIX socket (path is from CONFIG_FILE environment)
Sep 02 12:37:48 dovecot[264040]: imap-login: Fatal: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: stat(/usr/local/var/run/dovecot/config)
failed: No such file or directory (path is from CONFIG_FILE environment)
Sep 02 12:37:48 dovecot[264040]: imap-login: Fatal: Error reading
configuration: read(/usr/local/var/run/dovecot/config) failed:
read(size=8192) failed: Interrupted system call - Also failed to read
config by executing doveconf: /usr/local/var/run/dovecot/config is a
UNIX socket (path is from CONFIG_FILE environment)
Sep 02 12:37:48 dovecot[263234]: master: Error: service(imap-login):
command startup failed, throttling for 4.000 secs
Sep 02 12:37:49 dovecot[264040]: imap-login: Disconnected: Connection
closed: read(size=737) failed: Connection reset by peer (no auth
attempts in 5 secs): user=<>, rip=127.0.0.1, lip=127.0.0.1, TLS
handshaking: read(size=737) failed: Connection reset by peer,
session=<eNlHUq/njJJ/AAAB>
Sep 02 12:37:49 dovecot[264040]: imap-login: Login:
user=<user@domain1.example.org>, method=PLAIN, rip=127.0.0.1,
lip=127.0.0.1, mpid=265059, TLS, session=<duBHUq/njpJ/AAAB>
Sep 02 12:37:49 dovecot[264040]:
imap(user@domain1.example.org)<265059><duBHUq/njpJ/AAAB>: Disconnected:
Logged out in=25 out=790 deleted=0 expunged=0 trashed=0 hdr_count=0
hdr_bytes=0 body_count=0 body_bytes=0
Script for testing login:
========== test-imap.expect ==========
#!/usr/bin/expect -f
set timeout 5
expect_before {
timeout { puts "Error: Timeout"; exit 1 }
eof     { puts "Error: EOF";     exit 1 }
}
log_user 0
spawn openssl s_client -connect 127.0.0.1:993
expect "* OK"
send -- "C1 LOGIN user@domain1.example.org PASSWORD\n"
expect "C1 OK"
send -- "C2 SELECT Inbox\n"
expect "C2 OK"
send -- "C3 LOGOUT\n"
expect "C3 OK"
expect eof
Script for testing long lasting login:
========== test-imap-long.expect ==========
#!/usr/bin/expect -f
set timeout -1
expect_before {
timeout { puts "Error: Timeout"; exit 1 }
eof     { puts "Error: EOF";     exit 1 }
}
log_user 0
spawn openssl s_client -connect 127.0.0.1:993
expect "* OK"
send -- "C1 LOGIN user@domain1.example.org PASSWORD\n"
expect "C1 OK"
send -- "C2 SELECT Inbox\n"
expect "C2 OK"
Reproduction steps (I can attach full package for testing with 5000
self-signed certificates):

Start dovecot 2.3.19.1 with 5000 certificates in configuration files
using config above.
Start test-imap.expect on another console, like that:
while true; do date_now=$(date "+%Y-%m-%d %H:%M:%S"); echo -n
"[$date_now] Test: "; ./imap-test.expect && echo "OK"; sleep 1; done
Reload dovecot.
Check logs and test-imap.expect output.

Reproduction steps for config process not being terminated:

Start dovecot 2.3.19.1 using config above.
Start test-imap-long.expect (the second script) on another console.
Reload dovecot.
Start another test-imap-long.expect on another console.
Reload dovecot.
Check process list for dovecot config.

Best regards,
Bartosz Kwitniewski

Thousands of SSL certificates stalls new logins during reload - problem with Dovecot config process

Bartosz Kwitniewski

Configuration (doveadm config -n):

/etc/dovecot/users:

user@domain1.example.org:{SHA512-CRYPT}$6$...:1000:1000::/home/test/mail/domain1.example.org/user:: user@domain2.example.org:{SHA512-CRYPT}$6$...:1000:1000::/home/test/mail/domain2.example.org/user:: (...) 5000 users goes here, but one should be enough for testing.

Log file from dovecot reload:

spawn openssl s_client -connect 127.0.0.1:993 expect "* OK" send -- "C1 LOGIN user@domain1.example.org PASSWORD\n" expect "C1 OK" send -- "C2 SELECT Inbox\n" expect "C2 OK" send -- "C3 LOGOUT\n" expect "C3 OK" expect eof

spawn openssl s_client -connect 127.0.0.1:993 expect "* OK" send -- "C1 LOGIN user@domain1.example.org PASSWORD\n" expect "C1 OK" send -- "C2 SELECT Inbox\n" expect "C2 OK"

Best regards,