[Dovecot] Dovecot proxying results in "too many open files"
Hi,
Some words about my Dovecot setup:
- 10 dovecot servers
- each server has some local mailboxes
- each server has proxying enabled to seamlessly connect to another host if the mailbox is not local
Running Dovecot 1.1.1 on FreeBSD 6.3-RELEASE-p3.
First of all, local mailbox access is fine. Proxying works also as expected.
Now for the actual problem:
Shortly after startup, Dovecot starts throwing errors concerning connection which should be proxied.
Here are some examples from the logs:
Aug 6 15:49:10 dovecot: imap-login: socket() failed: Too many open
files
Aug 6 15:49:10 dovecot: imap-login: proxy(XYZ): connect(1.2.3.4, 143)
failed: Too many open files
Aug 6 15:49:10 dovecot: imap-login: accept() failed: Too many open
files
Aug 6 15:49:10 dovecot: imap-login: socket() failed: Too many open
files
Aug 6 15:49:10 dovecot: imap-login: proxy(XYZ): connect(1.2.3.4, 143)
failed: Too many open files
Aug 6 15:49:10 dovecot: imap-login: socket() failed: Too many open
files
Aug 6 15:49:10 dovecot: imap-login: proxy(XYZ): connect(1.2.3.4, 143)
failed: Too many open files
Aug 6 15:49:10 dovecot: imap-login: socket() failed: Too many open
files
Aug 6 15:49:10 dovecot: imap-login: proxy(XYZ): connect(1.2.3.4, 143)
failed: Too many open files
Aug 6 15:49:11 dovecot: imap-login: socket() failed: Too many open
files
[..]
Aug 6 16:00:05 dovecot: imap-login: accept() failed: Too many open
files
Aug 6 16:00:08 dovecot: imap-login: accept() failed: Too many open
files
Aug 6 16:00:11 dovecot: imap-login: accept() failed: Too many open
files
Aug 6 16:00:13 dovecot: imap-login: accept() failed: Too many open
files
As from the context it seems to be a file descriptor issue, as such I
have done
the following:
- added a 'limits -e -n 32768 -U dovecot' to dovecot startup file to
ensure it has enough FD's - additionally, I've checked my kernel file limits, however I always
set it through loader and sysctl to be as large as 64k
sysctl -a |grep files
kern.maxfiles: 65535 kern.maxfilesperproc: 32768 kern.openfiles: 1632
- also checked the limits of the dovecot user like this:
su -c dovecot root -c 'ulimit -a'
core file size (blocks, -c) unlimited data seg size (kbytes, -d) 1048576 file size (blocks, -f) unlimited max locked memory (kbytes, -l) unlimited max memory size (kbytes, -m) unlimited open files (-n) 32768 pipe size (512 bytes, -p) 1 stack size (kbytes, -s) 131072 cpu time (seconds, -t) unlimited max user processes (-u) 5547 virtual memory (kbytes, -v) unlimited
- done some monitoring of file descriptor usage for the dovecot user,
though somewhat inacurate, like this:
while [ : ]; do date; fstat -u dovecot |wc -l; sleep 1; done
this gave me these results while tailing the logfile:
Wed Aug 6 15:44:12 CEST 2008 585 Wed Aug 6 15:44:13 CEST 2008 579 Wed Aug 6 15:44:14 CEST 2008 582 Wed Aug 6 15:44:15 CEST 2008 582 Wed Aug 6 15:44:16 CEST 2008 586 Wed Aug 6 15:44:17 CEST 2008 585 Wed Aug 6 15:44:18 CEST 2008 582
So it didn't seem to be anywhere near the theoretical upper limit I've
set at 32k.
On the other hand, when restarting Dovecot, it works for a few minutes
for at least as long as the FD usage as reported above stays at around
500.
I remember from the docs that dovecot-login would require the double
amount of file descriptors to run.
Assuming my report is somewhat inaccurate and lags behind, I could
imagine
that upon a proxy requests it would effectively peak our at some 500 x
2 FDs.
Thus effectively reaching the 1024 FD barrier.
I conclude this from the fact that I currently have some 350 - 450
logins in parallel,
most of which can and shell be proxied.
From the error message in the logs I got the impression, that only
proxied
connections are affected.
I was not able to reproduce the issue with non-proxied logins to local
mailboxes.
Some further steps I've done from the configuration side to no avail:
- disabled imaps/pop3s/ssl
- changed between login_process_per_connection yes/no
- played around with login_max_connections et all (raised/lowered)
limits - tried with/without plugins enabled
- tried with SQL-based and passwd-file based userdb/passdb, single and
mixed
Dovecot config:
# dovecot -n
# 1.1.1: /usr/local/etc/dovecot.conf
base_dir: /var/run/dovecot/
protocols: imap pop3
listen: *, [::]
ssl_disable: yes
ssl_cert_file: /usr/local/etc/postfix/tls/server.crt
ssl_key_file: /usr/local/etc/postfix/tls/server.key
disable_plaintext_auth: no
verbose_ssl: yes
login_dir: /var/run/dovecot/login
login_executable(default): /usr/local/libexec/dovecot/imap-login
login_process_per_connection: no
login_greeting_capability(default): yes
login_greeting_capability(imap): yes
login_greeting_capability(pop3): no
login_processes_count: 16
login_max_processes_count: 64
login_max_connections: 64
max_mail_processes: 256
mail_max_userip_connections: 3
verbose_proctitle: yes
mail_privileged_group: mail
mail_uid: 1000
mail_gid: 1000
mail_location: maildir:~/Maildir
fsync_disable: yes
maildir_copy_preserve_filename: yes
mail_drop_priv_before_exec: yes
mail_executable(default): /mailserver/scripts/dovecot/imap
mail_executable(imap): /mailserver/scripts/dovecot/imap
mail_executable(pop3): /mailserver/scripts/dovecot/pop3
mail_plugins: expire mail_log
mail_plugin_dir(default): /usr/local/lib/dovecot/imap
mail_plugin_dir(imap): /usr/local/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3
mail_log_max_lines_per_sec: 0
imap_client_workarounds(default): delay-newmail netscape-eoh tb-extra-
mailbox-sep
imap_client_workarounds(imap): delay-newmail netscape-eoh tb-extra-
mailbox-sep
imap_client_workarounds(pop3):
pop3_no_flag_updates(default): no
pop3_no_flag_updates(imap): no
pop3_no_flag_updates(pop3): yes
pop3_enable_last(default): no
pop3_enable_last(imap): no
pop3_enable_last(pop3): yes
pop3_uidl_format(default): %08Xu%08Xv
pop3_uidl_format(imap): %08Xu%08Xv
pop3_uidl_format(pop3): UID%u-%v
pop3_client_workarounds(default):
pop3_client_workarounds(imap):
pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh
namespace:
type: private
inbox: yes
list: yes
subscriptions: yes
namespace:
type: private
separator: .
prefix: INBOX.
hidden: yes
auth default:
mechanisms: plain login cram-md5
cache_size: 131072
username_translation: #@/@%@
username_format: %Lu
verbose: yes
debug: yes
debug_passwords: yes
worker_max_request_count: 16384
passdb:
driver: sql
args: /usr/local/etc/dovecot-sql.conf
userdb:
driver: prefetch
userdb:
driver: passwd-file
args: username_format=%n /usr/local/etc/postfix/tables/
deliver_passwd
userdb:
driver: sql
args: /usr/local/etc/dovecot-sql.conf
socket:
type: listen
client:
path: /var/spool/postfix/private/auth
mode: 432
user: postfix
group: postfix
master:
path: /var/run/dovecot/auth-master
mode: 384
user: vpostfix
group: vpostfix
plugin:
expire: Trash 14 Trash/* 14 Spam 14 Spam/* 14 VirusAlerts 14
VirusAlerts/* 14 Quarantine 14 Quarantine/* 14
expire_dict: proxy::expire
dict:
expire: mysql:/usr/local/etc/dovecot-expire.conf
Maybe I am missing something here. I'd really, really appreciate some help on this to get it sorted out.
Thank you.
Regards,
Gianpaolo
On Aug 6, 2008, at 10:29 AM, Gianpaolo Del Matto wrote:
Aug 6 15:49:10 dovecot: imap-login: socket() failed: Too many open
files Aug 6 15:49:10 dovecot: imap-login: proxy(XYZ): connect(1.2.3.4,
143) failed: Too many open files
Login processes change the fd limits themselves, but looks like the
value wasn't calculated correctly for SSL connections. This should
help: http://hg.dovecot.org/dovecot-1.1/rev/ea6aea0a4cbb
Hello Timo
Well, that was fast indeed. Thank you!
I applied the patch to 1.1.2 and recompiled it, so far it did not happen within the last 30 minutes.
I will let you know what it looks like in a day or two.
Am 06.08.2008 um 18:55 schrieb Timo Sirainen:
On Aug 6, 2008, at 10:29 AM, Gianpaolo Del Matto wrote:
Aug 6 15:49:10 dovecot: imap-login: socket() failed: Too many open
files Aug 6 15:49:10 dovecot: imap-login: proxy(XYZ): connect(1.2.3.4,
143) failed: Too many open filesLogin processes change the fd limits themselves, but looks like the
value wasn't calculated correctly for SSL connections. This should
help: http://hg.dovecot.org/dovecot-1.1/rev/ea6aea0a4cbb
Greetings,
Gianpaolo
Hi again,
Here's some more information on the case.
In the meanwhile I tried the same setup with Dovecot 1.1.2, still the same result
As I saw in fstat on FreeBSD memory mapped files are ommited, so I did some further yet inaccurate monitoring with mmaped files included.
while [ : ]; do date; fstat -m -u dovecot |wc -l; sleep 1; done Wed Aug 6 18:37:05 CEST 2008 918 Wed Aug 6 18:37:06 CEST 2008 923 Wed Aug 6 18:37:07 CEST 2008 917 Wed Aug 6 18:37:08 CEST 2008 911 Wed Aug 6 18:37:09 CEST 2008 912 Wed Aug 6 18:37:10 CEST 2008 914 Wed Aug 6 18:37:11 CEST 2008 913 Wed Aug 6 18:37:13 CEST 2008 912 Wed Aug 6 18:37:14 CEST 2008 911 Wed Aug 6 18:37:15 CEST 2008 909 Wed Aug 6 18:37:16 CEST 2008 912 Wed Aug 6 18:37:17 CEST 2008 910
So actually I am very close to the 1024 FD barrier, so the question remains, if Dovecot inherits FD_SETSIZE from libc and if this might be the cause of the whole trouble.
During testing I did also a build of both 1.1.1 and 1.1.2 without SSL and mysql libraries, so basically just "plain" Dovecout without anything, though that made no difference at all.
Greetings,
Gianpaolo
participants (2)
-
Gianpaolo Del Matto
-
Timo Sirainen