imap-login: Fatal: pipe() failed: Too many open files
Hi
I keep on getting errors and can't connect/login to Dovecot. I did my research but unfortunately without success. It is for sure not ulimit because ulimit is set to unlimited per default already. Still , it complains about "Too many open files" but this is a test system and the service dovecot and postfix have just been started. No one except me is testing on this system. This is very weired ;/
root@WM-01 [~]$ service dovecot stop; service postfix stop ; echo "" > /var/log/maillog ; echo "" > /var/log/slapd.log ; service postfix start ; service dovecot start Stopping dovecot. Waiting for PIDS: 3245. postfix/postfix-script: stopping the Postfix mail system postfix/postfix-script: starting the Postfix mail system Starting dovecot.
root@WM-01 [~]$ telnet 127.0.0.1 143 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. Connection closed by foreign host.
root@WM-01 [~]$ cat /var/log/mail Jan 26 01:39:12 WM-01 dovecot: imap-login: Fatal: pipe() failed: Too many open files Jan 26 01:39:12 WM-01 dovecot: master: Error: service(imap-login): command startup failed, throttling for 4 secs
If I uncoment port = 0 in POP and IMAP then it looks even worse then above. Telnet is not even closed by remote host and three of the "Too many open files" errors are showing up in maillog:
root@WM-01 [~]$ telnet 127.0.0.1 143 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. ^] telnet> Connection closed. root@WM-01 [~]$ cat /var/log/maillog
Jan 26 01:45:19 WM-01 postfix/postfix-script[60560]: starting the Postfix mail system Jan 26 01:45:19 WM-01 postfix/master[60562]: daemon started -- version 1.0, configuration /usr/local/etc/postfix Jan 26 01:45:19 WM-01 dovecot: master: Dovecot v2.2.15 starting up for imap, pop3, lmtp Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: socket(login) failed: Too many open files Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: auth: connect(login) failed: Too many open files Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: net_accept() failed: Too many open files root@WM-01 [~]$
Does anyone have an idea what could be wrong here? I attached the relevant configuration below. I use OpenLDAP as backend. Please let me know if you need more information. Thank you very much.
Best Regards, Leander
# ========================== dovecot -n ============================== #
# 2.2.15: /usr/local/etc/dovecot/dovecot.conf # Pigeonhole version 0.4.6 (3e924b1b6c5c+) # OS: FreeBSD 10.1-RELEASE amd64 ufs auth_debug = yes auth_debug_passwords = yes auth_failure_delay = 3 secs auth_mechanisms = plain login auth_verbose = yes auth_verbose_passwords = yes base_dir = /var/run/dovecot/ disable_plaintext_auth = no imap_client_workarounds = delay-newmail tb-extra-mailbox-sep tb-lsub-flags lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes login_greeting = Welcome to Mail Server. login_log_format_elements = user=<%u> method=%m rip=%r lip=%l mpid=%e %c %k mail_debug = yes mail_gid = vmail mail_location = maildir:/var/mail/%d/%n mail_plugins = quota expire mail_log notify mail_privileged_group = mail mail_temp_dir = /tmp/Dovecot mail_uid = vmail managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave duplicate namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext driver = ldap } plugin { expire = Trash mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid size quota = maildir:User quota quota_exceeded_message = Storage quota for this account has been exceeded, please try again later. quota_rule = *:storage=1G quota_rule2 = Trash:storage=+30%% quota_rule3 = Sent:storage=+30%% quota_warning = storage=90%% quota-warning 90 %u quota_warning2 = storage=75%% quota-warning 75 %u } pop3_client_workarounds = outlook-no-nuls oe-ns-eoh postmaster_address = info@netocean.de sendmail_path = /usr/local/sbin/sendmail service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } unix_listener auth-userdb { group = vmail mode = 0600 user = vmail } } service imap-login { inet_listener imaps { port = 0 } } service lmtp { unix_listener /var/spool/postfix/private/dovecot-lmtp { group = postfix mode = 0660 user = postfix } user = vmail } service pop3-login { inet_listener pop3s { port = 0 } } service quota-warning { executable = script /usr/local/bin/quota-warning.sh unix_listener quota-warning { user = vmail } user = vmail } ssl = required ssl_cert =
# ======================== dovecot/conf.d/auth-ldap.conf.ext =================== #
passdb { driver = ldap
# Path for LDAP configuration file, see example-config/dovecot-ldap.conf.ext args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext }
# "prefetch" user database means that the passdb already provided the
# needed information and there's no need to do a separate userdb lookup.
#
userdb { driver = ldap args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext
# Default fields can be used to specify defaults that LDAP may override #default_fields = home=/home/virtual/%u }
# ======================== dovecot/dovecot-ldap.conf.ext =================== #
hosts = 127.0.0.1:389 dn = uid=dovecot,ou=systemuser,ou=mail,dc=MyDomain,dc=TLD dnpass = TopSecret tls = yes tls_cert_file = /etc/ssl/RootCA/certs/192.168.50.101.pem tls_key_file = /etc/ssl/RootCA/certs/192.168.50.101.key debug_level = -1 auth_bind = yes ldap_version = 3 base = ou=accounts,ou=mail,dc=MyDomain,dc=TLD scope = subtree user_attrs = mailStorageDirectory=home, mailUidNumber=uid, mailGidNumber=gid, mailQuotaSize=quota_rule=*:bytes=%$, mailQuotaCount=quota_rule2 user_filter = (&(objectClass=mailAccount)(mailAddress=%u)) pass_attrs = mailAddress=user,mailPassword=password pass_filter = (&(objectClass=mailAccount)(mailAccountStatus=active)(mailAddress=%u)) default_pass_scheme = SSHA
I just checked my ulimit again and it really seems like it hhas more than enough - so I still don't understand what I've configured wrong here ;/
root@WM-01 [~]$ su -m dovecot -c "ulimit -a" socket buffer size (bytes, -b) unlimited core file size (blocks, -c) unlimited data seg size (kbytes, -d) 33554432 file size (blocks, -f) unlimited max locked memory (kbytes, -l) 131072 max memory size (kbytes, -m) 7067352 open files (-n) 205587 pipe size (512 bytes, -p) 1 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 11278 virtual memory (kbytes, -v) unlimited swap size (kbytes, -w) unlimited
Best Regards, Leander
Am 26.01.15 um 01:50 schrieb Leander Schäfer:
Hi
I keep on getting errors and can't connect/login to Dovecot. I did my research but unfortunately without success. It is for sure not ulimit because ulimit is set to unlimited per default already. Still , it complains about "Too many open files" but this is a test system and the service dovecot and postfix have just been started. No one except me is testing on this system. This is very weired ;/
root@WM-01 [~]$ service dovecot stop; service postfix stop ; echo "" > /var/log/maillog ; echo "" > /var/log/slapd.log ; service postfix start ; service dovecot start Stopping dovecot. Waiting for PIDS: 3245. postfix/postfix-script: stopping the Postfix mail system postfix/postfix-script: starting the Postfix mail system Starting dovecot.
root@WM-01 [~]$ telnet 127.0.0.1 143 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. Connection closed by foreign host.
root@WM-01 [~]$ cat /var/log/mail Jan 26 01:39:12 WM-01 dovecot: imap-login: Fatal: pipe() failed: Too many open files Jan 26 01:39:12 WM-01 dovecot: master: Error: service(imap-login): command startup failed, throttling for 4 secs
If I uncoment port = 0 in POP and IMAP then it looks even worse then above. Telnet is not even closed by remote host and three of the "Too many open files" errors are showing up in maillog:
root@WM-01 [~]$ telnet 127.0.0.1 143 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. ^] telnet> Connection closed. root@WM-01 [~]$ cat /var/log/maillog
Jan 26 01:45:19 WM-01 postfix/postfix-script[60560]: starting the Postfix mail system Jan 26 01:45:19 WM-01 postfix/master[60562]: daemon started -- version 1.0, configuration /usr/local/etc/postfix Jan 26 01:45:19 WM-01 dovecot: master: Dovecot v2.2.15 starting up for imap, pop3, lmtp Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: socket(login) failed: Too many open files Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: auth: connect(login) failed: Too many open files Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: net_accept() failed: Too many open files root@WM-01 [~]$
Does anyone have an idea what could be wrong here? I attached the relevant configuration below. I use OpenLDAP as backend. Please let me know if you need more information. Thank you very much.
Best Regards, Leander
# ========================== dovecot -n ============================== #
# 2.2.15: /usr/local/etc/dovecot/dovecot.conf # Pigeonhole version 0.4.6 (3e924b1b6c5c+) # OS: FreeBSD 10.1-RELEASE amd64 ufs auth_debug = yes auth_debug_passwords = yes auth_failure_delay = 3 secs auth_mechanisms = plain login auth_verbose = yes auth_verbose_passwords = yes base_dir = /var/run/dovecot/ disable_plaintext_auth = no imap_client_workarounds = delay-newmail tb-extra-mailbox-sep tb-lsub-flags lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes login_greeting = Welcome to Mail Server. login_log_format_elements = user=<%u> method=%m rip=%r lip=%l mpid=%e %c %k mail_debug = yes mail_gid = vmail mail_location = maildir:/var/mail/%d/%n mail_plugins = quota expire mail_log notify mail_privileged_group = mail mail_temp_dir = /tmp/Dovecot mail_uid = vmail managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave duplicate namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext driver = ldap } plugin { expire = Trash mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid size quota = maildir:User quota quota_exceeded_message = Storage quota for this account has been exceeded, please try again later. quota_rule = *:storage=1G quota_rule2 = Trash:storage=+30%% quota_rule3 = Sent:storage=+30%% quota_warning = storage=90%% quota-warning 90 %u quota_warning2 = storage=75%% quota-warning 75 %u } pop3_client_workarounds = outlook-no-nuls oe-ns-eoh postmaster_address = info@netocean.de sendmail_path = /usr/local/sbin/sendmail service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } unix_listener auth-userdb { group = vmail mode = 0600 user = vmail } } service imap-login { inet_listener imaps { port = 0 } } service lmtp { unix_listener /var/spool/postfix/private/dovecot-lmtp { group = postfix mode = 0660 user = postfix } user = vmail } service pop3-login { inet_listener pop3s { port = 0 } } service quota-warning { executable = script /usr/local/bin/quota-warning.sh unix_listener quota-warning { user = vmail } user = vmail } ssl = required ssl_cert =
# ======================== dovecot/conf.d/auth-ldap.conf.ext =================== #
passdb { driver = ldap
# Path for LDAP configuration file, see example-config/dovecot-ldap.conf.ext args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext }
# "prefetch" user database means that the passdb already provided the # needed information and there's no need to do a separate userdb lookup. #
userdb { driver = prefetch } userdb { driver = ldap args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext
# Default fields can be used to specify defaults that LDAP may override #default_fields = home=/home/virtual/%u }
# ======================== dovecot/dovecot-ldap.conf.ext =================== #
hosts = 127.0.0.1:389 dn = uid=dovecot,ou=systemuser,ou=mail,dc=MyDomain,dc=TLD dnpass = TopSecret tls = yes tls_cert_file = /etc/ssl/RootCA/certs/192.168.50.101.pem tls_key_file = /etc/ssl/RootCA/certs/192.168.50.101.key debug_level = -1 auth_bind = yes ldap_version = 3 base = ou=accounts,ou=mail,dc=MyDomain,dc=TLD scope = subtree user_attrs = mailStorageDirectory=home, mailUidNumber=uid, mailGidNumber=gid, mailQuotaSize=quota_rule=*:bytes=%$, mailQuotaCount=quota_rule2 user_filter = (&(objectClass=mailAccount)(mailAddress=%u)) pass_attrs = mailAddress=user,mailPassword=password pass_filter = (&(objectClass=mailAccount)(mailAccountStatus=active)(mailAddress=%u)) default_pass_scheme = SSHA
Am 26.01.2015 um 02:13 schrieb Leander Schäfer:
I just checked my ulimit again and it really seems like it has more than enough - so I still don't understand what I've configured wrong here ;/
root@WM-01 [~]$ su -m dovecot -c "ulimit -a" socket buffer size (bytes, -b) unlimited core file size (blocks, -c) unlimited data seg size (kbytes, -d) 33554432 file size (blocks, -f) unlimited max locked memory (kbytes, -l) 131072 max memory size (kbytes, -m) 7067352 open files (-n) 205587 pipe size (512 bytes, -p) 1 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 11278 virtual memory (kbytes, -v) unlimited swap size (kbytes, -w) unlimited
besides that "imap-login" typically does *not* run under the same user (here dovenull versus dovecot) who tells you that 205587 is "more than enough" just because it is a high value?
Am 26.01.15 um 02:24 schrieb Edgar Pettijohn:
Sorry didn't scroll to the bottom to see the dovecot -n. I'm assuming freebsd has an /etc/login.conf similiar to openbsd. If so you may need to do something similiar to this:
dovecot:
:openfiles-cur=512:
:openfiles-max=2048:
:tc=daemon:Rebuild the login.conf.db file if necessary:
# [ -f /etc/login.conf.db ] && cap_mkdb /etc/login.conf
Hope this helps.
Thanks for the hint. FreeBSD takes sysctl(8) settings as a base to ulimit(3). I even tried tuning on those values.
sysctl kern.maxfilesperproc=405587 sysctl kern.maxfiles=428433
Unfortunately this does not solve the problem. I don't think it is the root of the problem.
The current value - even with Dovecot and Postfix already running is: kern.openfiles: 675 It is just, that Dovecot is kind of in a frozen condition when trying to login to it via telnet(1).
Am 26.01.15 um 02:20 schrieb Reindl Harald:
Am 26.01.2015 um 02:13 schrieb Leander Schäfer:
I just checked my ulimit again and it really seems like it has more than enough - so I still don't understand what I've configured wrong here ;/
root@WM-01 [~]$ su -m dovecot -c "ulimit -a" socket buffer size (bytes, -b) unlimited core file size (blocks, -c) unlimited data seg size (kbytes, -d) 33554432 file size (blocks, -f) unlimited max locked memory (kbytes, -l) 131072 max memory size (kbytes, -m) 7067352 open files (-n) 205587 pipe size (512 bytes, -p) 1 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 11278 virtual memory (kbytes, -v) unlimited swap size (kbytes, -w) unlimited
besides that "imap-login" typically does *not* run under the same user (here dovenull versus dovecot) who tells you that 205587 is "more than enough" just because it is a high value?
Yes, because I am monitoring those values via Munin. I can clearly see that my system does not require a value even close to this. By average my system has 673 files open. In FreeBSD sysctl(8) is the base for ulimit(3) - meaning since I don't maintain user specific ulimit(3) - it is also the same values for dovenull, postfix, vmail and every other user on the system. My current sysctl(8) values should provide way enough space to grow super large:
sysctl kern.maxfilesperproc=205587 sysctl kern.maxfiles=228433
And this is where it becomes so absurd to me. I don't see where I should tune anymore. I more and more get the feeling it is a configuration error of dovecot itself?!
Thanks & Best Regards, Leander
I also keep on getting funny errors of dovecot EVEN THOUGH I authenticated successfully through SMTP (Dovecto SASL) ?!?!
Just for debugging this entire issue I set those parameters:
debug_level = -1 auth_verbose = yes auth_verbose_passwords = yes auth_debug = yes auth_debug_passwords = yes mail_debug = yes verbose_ssl = yes
cat /var/loca/maillog
Jan 26 12:08:22 WM-01 postfix/postfix-script[97931]: starting the
Postfix mail system
Jan 26 12:08:22 WM-01 postfix/master[97933]: daemon started -- version
1.0, configuration /usr/local/etc/postfix
Jan 26 12:08:22 WM-01 dovecot: master: Dovecot v2.2.15 starting up for
imap, pop3, lmtp
Jan 26 12:08:59 WM-01 postfix/smtpd[99014]: connect from
localhost[127.0.0.1]
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_extended_operation_s
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_extended_operation
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_send_initial_request
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_new_connection 1 1 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_int_open_connection
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_connect_to_host: TCP
127.0.0.1:389
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_new_socket: 32
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_prepare_socket: 32
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_connect_to_host: Trying
127.0.0.1:389
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_pvt_connect: fd: 32 tm:
-1 async: 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: attempting to connect:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: connect success
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_open_defconn: successful
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_send_server_request
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100
msgid 1
Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid
1 (infinite timeout)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg continue ld
0x1245e100 msgid 1 all 1
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389
(default)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected
Jan 26 12:08:59 WM-01 dovecot: auth: Error: last used: Mon Jan 26
12:08:59 2015
Jan 26 12:08:59 WM-01 dovecot: auth: Error:
Jan 26 12:08:59 WM-01 dovecot: auth: Error:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding
Requests:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: * msgid 1, origid 1,
status InProgress
Jan 26 12:08:59 WM-01 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 request
count 1 (abandoned 0)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: Empty
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList ld
0x1245e100 msgid 1 all 1
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList returns
ld 0x1245e100 NULL
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_int_select
Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100
msgid 1 all 1
Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100
msgid 1 message type extended-result
Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 0
new referrals
Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: mark request
completed, ld 0x1245e100 msgid 1
Jan 26 12:08:59 WM-01 dovecot: auth: Error: request done: ld 0x1245e100
msgid 1
Jan 26 12:08:59 WM-01 dovecot: auth: Error: res_errno: 0, res_error: <>,
res_matched: <>
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_free_request (origid 1,
msgid 1)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_parse_extended_result
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_parse_result
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_msgfree
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace:
SSL_connect:before/connect initialization
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace:
SSL_connect:SSLv2/v3 write client hello A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
read server hello A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS certificate
verification: depth: 1, err: 0, subject: [...]
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS certificate
verification: depth: 0, err: 0, subject: [...]
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
read server certificate A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
read server certificate request A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
read server done A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
write client certificate A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
write client key exchange A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
write certificate verify A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
write change cipher spec A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
write finished A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
flush data
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
read server session ticket A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3
read finished A
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_bind
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_simple_bind
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_sasl_bind
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_send_initial_request
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_send_server_request
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100
msgid -1
Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid
-1 (timeout 0 usec)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg continue ld
0x1245e100 msgid -1 all 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389
(default)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected
Jan 26 12:08:59 WM-01 dovecot: auth: Error: last used: Mon Jan 26
12:08:59 2015
Jan 26 12:08:59 WM-01 dovecot: auth: Error:
Jan 26 12:08:59 WM-01 dovecot: auth: Error:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding
Requests:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: * msgid 2, origid 2,
status InProgress
Jan 26 12:08:59 WM-01 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 request
count 1 (abandoned 0)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: Empty
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList ld
0x1245e100 msgid -1 all 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList returns
ld 0x1245e100 NULL
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_int_select
Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100
msgid -1 all 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100
msgid 2 message type bind
Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 0
new referrals
Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: mark request
completed, ld 0x1245e100 msgid 2
Jan 26 12:08:59 WM-01 dovecot: auth: Error: request done: ld 0x1245e100
msgid 2
Jan 26 12:08:59 WM-01 dovecot: auth: Error: res_errno: 0, res_error: <>,
res_matched: <>
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_free_request (origid 2,
msgid 2)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_parse_result
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_msgfree
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100
msgid -1
Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid
-1 (timeout 0 usec)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg continue ld
0x1245e100 msgid -1 all 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389
(default)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: refcnt: 1 status: Connected
Jan 26 12:08:59 WM-01 dovecot: auth: Error: last used: Mon Jan 26
12:08:59 2015
Jan 26 12:08:59 WM-01 dovecot: auth: Error:
Jan 26 12:08:59 WM-01 dovecot: auth: Error:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding
Requests:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: Empty
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 request
count 0 (abandoned 0)
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue:
Jan 26 12:08:59 WM-01 dovecot: auth: Error: Empty
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList ld
0x1245e100 msgid -1 all 0
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList returns
ld 0x1245e100 NULL
Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_int_select
Jan 26 12:08:59 WM-01 postfix/smtpd[99014]: Anonymous TLS connection
established from localhost[127.0.0.1]: TLSv1.2 with cipher
ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_search
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter:
"(&(objectClass=mailAccount)(mailAccountStatus=active)(mailAddress=postmaster@mydomain.tld))"
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: AND
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter_list
"(objectClass=mailAccount)(mailAccountStatus=active)(mailAddress=postmaster@mydomain.tld)"
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter:
"(objectClass=mailAccount)"
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: simple
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_simple_filter:
"objectClass=mailAccount"
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter:
"(mailAccountStatus=active)"
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: simple
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_simple_filter:
"mailAccountStatus=active"
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter:
"(mailAddress=postmaster@mydomain.tld)"
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: simple
Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_simple_filter:
"mailAddress=postmaster@mydomain.tld"
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_build_search_req ATTRS:
mailAddress
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_send_initial_request
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_send_server_request
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100
msgid -1
Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid
-1 (timeout 0 usec)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg continue ld
0x1245e100 msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389
(default)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected
Jan 26 12:09:09 WM-01 dovecot: auth: Error: last used: Mon Jan 26
12:09:09 2015
Jan 26 12:09:09 WM-01 dovecot: auth: Error:
Jan 26 12:09:09 WM-01 dovecot: auth: Error:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding
Requests:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: * msgid 3, origid 3,
status InProgress
Jan 26 12:09:09 WM-01 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 request
count 1 (abandoned 0)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList ld
0x1245e100 msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList returns
ld 0x1245e100 NULL
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_int_select
Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100
msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100
msgid 3 message type search-entry
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100
msgid -1
Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid
-1 (timeout 0 usec)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg continue ld
0x1245e100 msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389
(default)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected
Jan 26 12:09:09 WM-01 dovecot: auth: Error: last used: Mon Jan 26
12:09:09 2015
Jan 26 12:09:09 WM-01 dovecot: auth: Error:
Jan 26 12:09:09 WM-01 dovecot: auth: Error:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding
Requests:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: * msgid 3, origid 3,
status InProgress
Jan 26 12:09:09 WM-01 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 request
count 1 (abandoned 0)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList ld
0x1245e100 msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList returns
ld 0x1245e100 NULL
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_int_select
Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100
msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100
msgid 3 message type search-result
Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 0
new referrals
Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: mark request
completed, ld 0x1245e100 msgid 3
Jan 26 12:09:09 WM-01 dovecot: auth: Error: request done: ld 0x1245e100
msgid 3
Jan 26 12:09:09 WM-01 dovecot: auth: Error: res_errno: 0, res_error: <>,
res_matched: <>
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_free_request (origid 3,
msgid 3)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_parse_result
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_first_attribute
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_get_values
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_next_attribute
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_first_attribute
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_get_values
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_next_attribute
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_get_dn
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_bind
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_simple_bind
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_sasl_bind
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_send_initial_request
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_send_server_request
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_msgfree
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_msgfree
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100
msgid -1
Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid
-1 (timeout 0 usec)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg continue ld
0x1245e100 msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389
(default)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected
Jan 26 12:09:09 WM-01 dovecot: auth: Error: last used: Mon Jan 26
12:09:09 2015
Jan 26 12:09:09 WM-01 dovecot: auth: Error:
Jan 26 12:09:09 WM-01 dovecot: auth: Error:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding
Requests:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: * msgid 4, origid 4,
status InProgress
Jan 26 12:09:09 WM-01 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 request
count 1 (abandoned 0)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList ld
0x1245e100 msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList returns
ld 0x1245e100 NULL
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_int_select
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100
msgid -1
Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid
-1 (timeout 0 usec)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg continue ld
0x1245e100 msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389
(default)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected
Jan 26 12:09:09 WM-01 dovecot: auth: Error: last used: Mon Jan 26
12:09:09 2015
Jan 26 12:09:09 WM-01 dovecot: auth: Error:
Jan 26 12:09:09 WM-01 dovecot: auth: Error:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding
Requests:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: * msgid 4, origid 4,
status InProgress
Jan 26 12:09:09 WM-01 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 request
count 1 (abandoned 0)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList ld
0x1245e100 msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList returns
ld 0x1245e100 NULL
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_int_select
Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100
msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100
msgid 4 message type bind
Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 0
new referrals
Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: mark request
completed, ld 0x1245e100 msgid 4
Jan 26 12:09:09 WM-01 dovecot: auth: Error: request done: ld 0x1245e100
msgid 4
Jan 26 12:09:09 WM-01 dovecot: auth: Error: res_errno: 0, res_error: <>,
res_matched: <>
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_free_request (origid 4,
msgid 4)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_parse_result
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_parse_result
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_msgfree
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100
msgid -1
Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid
-1 (timeout 0 usec)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg continue ld
0x1245e100 msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389
(default)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: refcnt: 1 status: Connected
Jan 26 12:09:09 WM-01 dovecot: auth: Error: last used: Mon Jan 26
12:09:09 2015
Jan 26 12:09:09 WM-01 dovecot: auth: Error:
Jan 26 12:09:09 WM-01 dovecot: auth: Error:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding
Requests:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 request
count 0 (abandoned 0)
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue:
Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList ld
0x1245e100 msgid -1 all 0
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList returns
ld 0x1245e100 NULL
Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_int_select
Jan 26 12:09:20 WM-01 postfix/smtpd[99014]: lost connection after AUTH
from localhost[127.0.0.1]
Jan 26 12:09:20 WM-01 postfix/smtpd[99014]: disconnect from
localhost[127.0.0.1]
Am 26.01.15 um 11:27 schrieb Leander Schäfer:
Am 26.01.15 um 02:24 schrieb Edgar Pettijohn:
Sorry didn't scroll to the bottom to see the dovecot -n. I'm assuming freebsd has an /etc/login.conf similiar to openbsd. If so you may need to do something similiar to this:
dovecot:
:openfiles-cur=512:
:openfiles-max=2048:
:tc=daemon:Rebuild the login.conf.db file if necessary:
# [ -f /etc/login.conf.db ] && cap_mkdb /etc/login.conf
Hope this helps.
Thanks for the hint. FreeBSD takes sysctl(8) settings as a base to ulimit(3). I even tried tuning on those values.
sysctl kern.maxfilesperproc=405587 sysctl kern.maxfiles=428433
Unfortunately this does not solve the problem. I don't think it is the root of the problem.
The current value - even with Dovecot and Postfix already running is: kern.openfiles: 675 It is just, that Dovecot is kind of in a frozen condition when trying to login to it via telnet(1).
Am 26.01.15 um 02:20 schrieb Reindl Harald:
Am 26.01.2015 um 02:13 schrieb Leander Schäfer:
I just checked my ulimit again and it really seems like it has more than enough - so I still don't understand what I've configured wrong here ;/
root@WM-01 [~]$ su -m dovecot -c "ulimit -a" socket buffer size (bytes, -b) unlimited core file size (blocks, -c) unlimited data seg size (kbytes, -d) 33554432 file size (blocks, -f) unlimited max locked memory (kbytes, -l) 131072 max memory size (kbytes, -m) 7067352 open files (-n) 205587 pipe size (512 bytes, -p) 1 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 11278 virtual memory (kbytes, -v) unlimited swap size (kbytes, -w) unlimited
besides that "imap-login" typically does *not* run under the same user (here dovenull versus dovecot) who tells you that 205587 is "more than enough" just because it is a high value?
Yes, because I am monitoring those values via Munin. I can clearly see that my system does not require a value even close to this. By average my system has 673 files open. In FreeBSD sysctl(8) is the base for ulimit(3) - meaning since I don't maintain user specific ulimit(3) - it is also the same values for dovenull, postfix, vmail and every other user on the system. My current sysctl(8) values should provide way enough space to grow super large:
sysctl kern.maxfilesperproc=205587 sysctl kern.maxfiles=228433
And this is where it becomes so absurd to me. I don't see where I should tune anymore. I more and more get the feeling it is a configuration error of dovecot itself?!
Thanks & Best Regards, Leander
It turns out, that this errors "too many open files ..." occurred because a) missing "index ATTRIBUTE eq" for username and password in slapd.conf as well as b) password attribute was not read properly by dovecot from LDAP - I had to remove it from my schema and instead use "userPassword" from "objectclass: simpleSecurityObject"
This two changes made the "too many open files ..." errors disapear.
BUT, I still have the problem of receiving all those "dovecot: auth: Error:" lines in my maillog. I know I could turn them off by reducing debug parameters - but why is it declared as error in the first place - even though user authentication is working fine?
Thanks & Best Regards, Leander
Am 26.01.15 um 12:16 schrieb Leander Schäfer:
I also keep on getting funny errors of dovecot EVEN THOUGH I authenticated successfully through SMTP (Dovecto SASL) ?!?!
Just for debugging this entire issue I set those parameters:
debug_level = -1 auth_verbose = yes auth_verbose_passwords = yes auth_debug = yes auth_debug_passwords = yes mail_debug = yes verbose_ssl = yes
cat /var/loca/maillog
Jan 26 12:08:22 WM-01 postfix/postfix-script[97931]: starting the Postfix mail system Jan 26 12:08:22 WM-01 postfix/master[97933]: daemon started -- version 1.0, configuration /usr/local/etc/postfix Jan 26 12:08:22 WM-01 dovecot: master: Dovecot v2.2.15 starting up for imap, pop3, lmtp Jan 26 12:08:59 WM-01 postfix/smtpd[99014]: connect from localhost[127.0.0.1] Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_extended_operation_s Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_extended_operation Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_send_initial_request Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_new_connection 1 1 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_int_open_connection Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_connect_to_host: TCP 127.0.0.1:389 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_new_socket: 32 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_prepare_socket: 32 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_connect_to_host: Trying 127.0.0.1:389 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_pvt_connect: fd: 32 tm: -1 async: 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: attempting to connect: Jan 26 12:08:59 WM-01 dovecot: auth: Error: connect success Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_open_defconn: successful Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_send_server_request Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100 msgid 1 Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid 1 (infinite timeout) Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg continue ld 0x1245e100 msgid 1 all 1 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections: Jan 26 12:08:59 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389 (default) Jan 26 12:08:59 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected Jan 26 12:08:59 WM-01 dovecot: auth: Error: last used: Mon Jan 26 12:08:59 2015 Jan 26 12:08:59 WM-01 dovecot: auth: Error: Jan 26 12:08:59 WM-01 dovecot: auth: Error: Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding Requests: Jan 26 12:08:59 WM-01 dovecot: auth: Error: * msgid 1, origid 1, status InProgress Jan 26 12:08:59 WM-01 dovecot: auth: Error: outstanding referrals 0, parent count 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 request count 1 (abandoned 0) Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue: Jan 26 12:08:59 WM-01 dovecot: auth: Error: Empty Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList ld 0x1245e100 msgid 1 all 1 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList returns ld 0x1245e100 NULL Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_int_select Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 msgid 1 all 1 Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 msgid 1 message type extended-result Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 0 new referrals Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: mark request completed, ld 0x1245e100 msgid 1 Jan 26 12:08:59 WM-01 dovecot: auth: Error: request done: ld 0x1245e100 msgid 1 Jan 26 12:08:59 WM-01 dovecot: auth: Error: res_errno: 0, res_error: <>, res_matched: <> Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_free_request (origid 1, msgid 1) Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_parse_extended_result Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_parse_result Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_msgfree Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:before/connect initialization Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv2/v3 write client hello A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 read server hello A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS certificate verification: depth: 1, err: 0, subject: [...] Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS certificate verification: depth: 0, err: 0, subject: [...] Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 read server certificate A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 read server certificate request A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 read server done A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 write client certificate A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 write client key exchange A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 write certificate verify A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 write change cipher spec A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 write finished A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 flush data Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 read server session ticket A Jan 26 12:08:59 WM-01 dovecot: auth: Error: TLS trace: SSL_connect:SSLv3 read finished A Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_bind Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_simple_bind Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_sasl_bind Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_send_initial_request Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_send_server_request Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100 msgid -1 Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid -1 (timeout 0 usec) Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg continue ld 0x1245e100 msgid -1 all 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections: Jan 26 12:08:59 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389 (default) Jan 26 12:08:59 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected Jan 26 12:08:59 WM-01 dovecot: auth: Error: last used: Mon Jan 26 12:08:59 2015 Jan 26 12:08:59 WM-01 dovecot: auth: Error: Jan 26 12:08:59 WM-01 dovecot: auth: Error: Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding Requests: Jan 26 12:08:59 WM-01 dovecot: auth: Error: * msgid 2, origid 2, status InProgress Jan 26 12:08:59 WM-01 dovecot: auth: Error: outstanding referrals 0, parent count 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 request count 1 (abandoned 0) Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue: Jan 26 12:08:59 WM-01 dovecot: auth: Error: Empty Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList ld 0x1245e100 msgid -1 all 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList returns ld 0x1245e100 NULL Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_int_select Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 msgid -1 all 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 msgid 2 message type bind Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 0 new referrals Jan 26 12:08:59 WM-01 dovecot: auth: Error: read1msg: mark request completed, ld 0x1245e100 msgid 2 Jan 26 12:08:59 WM-01 dovecot: auth: Error: request done: ld 0x1245e100 msgid 2 Jan 26 12:08:59 WM-01 dovecot: auth: Error: res_errno: 0, res_error: <>, res_matched: <> Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_free_request (origid 2, msgid 2) Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_parse_result Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_msgfree Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100 msgid -1 Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid -1 (timeout 0 usec) Jan 26 12:08:59 WM-01 dovecot: auth: Error: wait4msg continue ld 0x1245e100 msgid -1 all 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections: Jan 26 12:08:59 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389 (default) Jan 26 12:08:59 WM-01 dovecot: auth: Error: refcnt: 1 status: Connected Jan 26 12:08:59 WM-01 dovecot: auth: Error: last used: Mon Jan 26 12:08:59 2015 Jan 26 12:08:59 WM-01 dovecot: auth: Error: Jan 26 12:08:59 WM-01 dovecot: auth: Error: Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding Requests: Jan 26 12:08:59 WM-01 dovecot: auth: Error: Empty Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 request count 0 (abandoned 0) Jan 26 12:08:59 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue: Jan 26 12:08:59 WM-01 dovecot: auth: Error: Empty Jan 26 12:08:59 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList ld 0x1245e100 msgid -1 all 0 Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_chkResponseList returns ld 0x1245e100 NULL Jan 26 12:08:59 WM-01 dovecot: auth: Error: ldap_int_select Jan 26 12:08:59 WM-01 postfix/smtpd[99014]: Anonymous TLS connection established from localhost[127.0.0.1]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits) Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_search Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: "(&(objectClass=mailAccount)(mailAccountStatus=active)(mailAddress=postmaster@mydomain.tld))" Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: AND Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter_list "(objectClass=mailAccount)(mailAccountStatus=active)(mailAddress=postmaster@mydomain.tld)" Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: "(objectClass=mailAccount)" Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: simple Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_simple_filter: "objectClass=mailAccount" Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: "(mailAccountStatus=active)" Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: simple Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_simple_filter: "mailAccountStatus=active" Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: "(mailAddress=postmaster@mydomain.tld)" Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_filter: simple Jan 26 12:09:09 WM-01 dovecot: auth: Error: put_simple_filter: "mailAddress=postmaster@mydomain.tld" Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_build_search_req ATTRS: mailAddress Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_send_initial_request Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_send_server_request Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100 msgid -1 Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid -1 (timeout 0 usec) Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg continue ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections: Jan 26 12:09:09 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389 (default) Jan 26 12:09:09 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected Jan 26 12:09:09 WM-01 dovecot: auth: Error: last used: Mon Jan 26 12:09:09 2015 Jan 26 12:09:09 WM-01 dovecot: auth: Error: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding Requests: Jan 26 12:09:09 WM-01 dovecot: auth: Error: * msgid 3, origid 3, status InProgress Jan 26 12:09:09 WM-01 dovecot: auth: Error: outstanding referrals 0, parent count 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 request count 1 (abandoned 0) Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList returns ld 0x1245e100 NULL Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_int_select Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 msgid 3 message type search-entry Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100 msgid -1 Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid -1 (timeout 0 usec) Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg continue ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections: Jan 26 12:09:09 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389 (default) Jan 26 12:09:09 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected Jan 26 12:09:09 WM-01 dovecot: auth: Error: last used: Mon Jan 26 12:09:09 2015 Jan 26 12:09:09 WM-01 dovecot: auth: Error: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding Requests: Jan 26 12:09:09 WM-01 dovecot: auth: Error: * msgid 3, origid 3, status InProgress Jan 26 12:09:09 WM-01 dovecot: auth: Error: outstanding referrals 0, parent count 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 request count 1 (abandoned 0) Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList returns ld 0x1245e100 NULL Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_int_select Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 msgid 3 message type search-result Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 0 new referrals Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: mark request completed, ld 0x1245e100 msgid 3 Jan 26 12:09:09 WM-01 dovecot: auth: Error: request done: ld 0x1245e100 msgid 3 Jan 26 12:09:09 WM-01 dovecot: auth: Error: res_errno: 0, res_error: <>, res_matched: <> Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_free_request (origid 3, msgid 3) Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_parse_result Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_first_attribute Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_get_values Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_next_attribute Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_first_attribute Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_get_values Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_next_attribute Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_get_dn Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_bind Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_simple_bind Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_sasl_bind Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_send_initial_request Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_send_server_request Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_msgfree Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_msgfree Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100 msgid -1 Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid -1 (timeout 0 usec) Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg continue ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections: Jan 26 12:09:09 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389 (default) Jan 26 12:09:09 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected Jan 26 12:09:09 WM-01 dovecot: auth: Error: last used: Mon Jan 26 12:09:09 2015 Jan 26 12:09:09 WM-01 dovecot: auth: Error: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding Requests: Jan 26 12:09:09 WM-01 dovecot: auth: Error: * msgid 4, origid 4, status InProgress Jan 26 12:09:09 WM-01 dovecot: auth: Error: outstanding referrals 0, parent count 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 request count 1 (abandoned 0) Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList returns ld 0x1245e100 NULL Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_int_select Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100 msgid -1 Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid -1 (timeout 0 usec) Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg continue ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections: Jan 26 12:09:09 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389 (default) Jan 26 12:09:09 WM-01 dovecot: auth: Error: refcnt: 2 status: Connected Jan 26 12:09:09 WM-01 dovecot: auth: Error: last used: Mon Jan 26 12:09:09 2015 Jan 26 12:09:09 WM-01 dovecot: auth: Error: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding Requests: Jan 26 12:09:09 WM-01 dovecot: auth: Error: * msgid 4, origid 4, status InProgress Jan 26 12:09:09 WM-01 dovecot: auth: Error: outstanding referrals 0, parent count 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 request count 1 (abandoned 0) Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList returns ld 0x1245e100 NULL Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_int_select Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 msgid 4 message type bind Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: ld 0x1245e100 0 new referrals Jan 26 12:09:09 WM-01 dovecot: auth: Error: read1msg: mark request completed, ld 0x1245e100 msgid 4 Jan 26 12:09:09 WM-01 dovecot: auth: Error: request done: ld 0x1245e100 msgid 4 Jan 26 12:09:09 WM-01 dovecot: auth: Error: res_errno: 0, res_error: <>, res_matched: <> Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_free_request (origid 4, msgid 4) Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_parse_result Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_parse_result Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_msgfree Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_result ld 0x1245e100 msgid -1 Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg ld 0x1245e100 msgid -1 (timeout 0 usec) Jan 26 12:09:09 WM-01 dovecot: auth: Error: wait4msg continue ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Connections: Jan 26 12:09:09 WM-01 dovecot: auth: Error: * host: 127.0.0.1 port: 389 (default) Jan 26 12:09:09 WM-01 dovecot: auth: Error: refcnt: 1 status: Connected Jan 26 12:09:09 WM-01 dovecot: auth: Error: last used: Mon Jan 26 12:09:09 2015 Jan 26 12:09:09 WM-01 dovecot: auth: Error: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Outstanding Requests: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 request count 0 (abandoned 0) Jan 26 12:09:09 WM-01 dovecot: auth: Error: ** ld 0x1245e100 Response Queue: Jan 26 12:09:09 WM-01 dovecot: auth: Error: Empty Jan 26 12:09:09 WM-01 dovecot: auth: Error: ld 0x1245e100 response count 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList ld 0x1245e100 msgid -1 all 0 Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_chkResponseList returns ld 0x1245e100 NULL Jan 26 12:09:09 WM-01 dovecot: auth: Error: ldap_int_select Jan 26 12:09:20 WM-01 postfix/smtpd[99014]: lost connection after AUTH from localhost[127.0.0.1] Jan 26 12:09:20 WM-01 postfix/smtpd[99014]: disconnect from localhost[127.0.0.1]
Am 26.01.15 um 11:27 schrieb Leander Schäfer:
Am 26.01.15 um 02:24 schrieb Edgar Pettijohn:
Sorry didn't scroll to the bottom to see the dovecot -n. I'm assuming freebsd has an /etc/login.conf similiar to openbsd. If so you may need to do something similiar to this:
dovecot:
:openfiles-cur=512:
:openfiles-max=2048:
:tc=daemon:Rebuild the login.conf.db file if necessary:
# [ -f /etc/login.conf.db ] && cap_mkdb /etc/login.conf
Hope this helps.
Thanks for the hint. FreeBSD takes sysctl(8) settings as a base to ulimit(3). I even tried tuning on those values.
sysctl kern.maxfilesperproc=405587 sysctl kern.maxfiles=428433
Unfortunately this does not solve the problem. I don't think it is the root of the problem.
The current value - even with Dovecot and Postfix already running is: kern.openfiles: 675 It is just, that Dovecot is kind of in a frozen condition when trying to login to it via telnet(1).
Am 26.01.15 um 02:20 schrieb Reindl Harald:
Am 26.01.2015 um 02:13 schrieb Leander Schäfer:
I just checked my ulimit again and it really seems like it has more than enough - so I still don't understand what I've configured wrong here ;/
root@WM-01 [~]$ su -m dovecot -c "ulimit -a" socket buffer size (bytes, -b) unlimited core file size (blocks, -c) unlimited data seg size (kbytes, -d) 33554432 file size (blocks, -f) unlimited max locked memory (kbytes, -l) 131072 max memory size (kbytes, -m) 7067352 open files (-n) 205587 pipe size (512 bytes, -p) 1 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 11278 virtual memory (kbytes, -v) unlimited swap size (kbytes, -w) unlimited
besides that "imap-login" typically does *not* run under the same user (here dovenull versus dovecot) who tells you that 205587 is "more than enough" just because it is a high value?
Yes, because I am monitoring those values via Munin. I can clearly see that my system does not require a value even close to this. By average my system has 673 files open. In FreeBSD sysctl(8) is the base for ulimit(3) - meaning since I don't maintain user specific ulimit(3) - it is also the same values for dovenull, postfix, vmail and every other user on the system. My current sysctl(8) values should provide way enough space to grow super large:
sysctl kern.maxfilesperproc=205587 sysctl kern.maxfiles=228433
And this is where it becomes so absurd to me. I don't see where I should tune anymore. I more and more get the feeling it is a configuration error of dovecot itself?!
Thanks & Best Regards, Leander
Am 26.01.15 um 02:24 schrieb Edgar Pettijohn:
Sorry didn't scroll to the bottom to see the dovecot -n. I'm assuming freebsd has an /etc/login.conf similiar to openbsd. If so you may need to do something similiar to this:
dovecot:
:openfiles-cur=512:
:openfiles-max=2048:
:tc=daemon:Rebuild the login.conf.db file if necessary:
# [ -f /etc/login.conf.db ] && cap_mkdb /etc/login.conf
Hope this helps.
Thanks for the hint. FreeBSD takes sysctl(8) settings as a base to ulimit(3). I even tried tuning on those values.
sysctl kern.maxfilesperproc=405587 sysctl kern.maxfiles=428433
Unfortunately this does not solve the problem. I don't think it is the root of the problem.
The current value - even with Dovecot and Postfix already running is: kern.openfiles: 675 It is just, that Dovecot is kind of in a frozen condition when trying to login to it via telnet(1).
Am 26.01.15 um 02:20 schrieb Reindl Harald:
Am 26.01.2015 um 02:13 schrieb Leander Schäfer:
I just checked my ulimit again and it really seems like it has more than enough - so I still don't understand what I've configured wrong here ;/
root@WM-01 [~]$ su -m dovecot -c "ulimit -a" socket buffer size (bytes, -b) unlimited core file size (blocks, -c) unlimited data seg size (kbytes, -d) 33554432 file size (blocks, -f) unlimited max locked memory (kbytes, -l) 131072 max memory size (kbytes, -m) 7067352 open files (-n) 205587 pipe size (512 bytes, -p) 1 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 11278 virtual memory (kbytes, -v) unlimited swap size (kbytes, -w) unlimited
besides that "imap-login" typically does *not* run under the same user (here dovenull versus dovecot) who tells you that 205587 is "more than enough" just because it is a high value?
Yes, because I am monitoring those values via Munin. I can clearly see that my system does not require a value even close to this. By average my system has 673 files open. In FreeBSD sysctl(8) is the base for ulimit(3) - meaning since I don't maintain user specific ulimit(3) - it is also the same values for dovenull, postfix, vmail and every other user on the system. My current sysctl(8) values should provide way enough space to grow super large:
sysctl kern.maxfilesperproc=205587 sysctl kern.maxfiles=228433
And this is where it becomes so absurd to me. I don't see where I should tune anymore. I more and more get the feeling it is a configuration error of dovecot itself?!
Thanks & Best Regards, Leander
I know thats the error it gave me until I changed the settings for dovecot in login.conf. The only other thing I would suggest trying is install dovecot from the opposite of what you installed it from either
On 01/26/15 04:27, Leander Schäfer wrote: packages or ports, and see if its a bug in the build.
What is the OS?
On 01/25/15 18:50, Leander Schäfer wrote:
Hi
I keep on getting errors and can't connect/login to Dovecot. I did my research but unfortunately without success. It is for sure not ulimit because ulimit is set to unlimited per default already. Still , it complains about "Too many open files" but this is a test system and the service dovecot and postfix have just been started. No one except me is testing on this system. This is very weired ;/
root@WM-01 [~]$ service dovecot stop; service postfix stop ; echo "" > /var/log/maillog ; echo "" > /var/log/slapd.log ; service postfix start ; service dovecot start Stopping dovecot. Waiting for PIDS: 3245. postfix/postfix-script: stopping the Postfix mail system postfix/postfix-script: starting the Postfix mail system Starting dovecot.
root@WM-01 [~]$ telnet 127.0.0.1 143 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. Connection closed by foreign host.
root@WM-01 [~]$ cat /var/log/mail Jan 26 01:39:12 WM-01 dovecot: imap-login: Fatal: pipe() failed: Too many open files Jan 26 01:39:12 WM-01 dovecot: master: Error: service(imap-login): command startup failed, throttling for 4 secs
If I uncoment port = 0 in POP and IMAP then it looks even worse then above. Telnet is not even closed by remote host and three of the "Too many open files" errors are showing up in maillog:
root@WM-01 [~]$ telnet 127.0.0.1 143 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. ^] telnet> Connection closed. root@WM-01 [~]$ cat /var/log/maillog
Jan 26 01:45:19 WM-01 postfix/postfix-script[60560]: starting the Postfix mail system Jan 26 01:45:19 WM-01 postfix/master[60562]: daemon started -- version 1.0, configuration /usr/local/etc/postfix Jan 26 01:45:19 WM-01 dovecot: master: Dovecot v2.2.15 starting up for imap, pop3, lmtp Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: socket(login) failed: Too many open files Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: auth: connect(login) failed: Too many open files Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: net_accept() failed: Too many open files root@WM-01 [~]$
Does anyone have an idea what could be wrong here? I attached the relevant configuration below. I use OpenLDAP as backend. Please let me know if you need more information. Thank you very much.
Best Regards, Leander
# ========================== dovecot -n ============================== #
# 2.2.15: /usr/local/etc/dovecot/dovecot.conf # Pigeonhole version 0.4.6 (3e924b1b6c5c+) # OS: FreeBSD 10.1-RELEASE amd64 ufs auth_debug = yes auth_debug_passwords = yes auth_failure_delay = 3 secs auth_mechanisms = plain login auth_verbose = yes auth_verbose_passwords = yes base_dir = /var/run/dovecot/ disable_plaintext_auth = no imap_client_workarounds = delay-newmail tb-extra-mailbox-sep tb-lsub-flags lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes login_greeting = Welcome to Mail Server. login_log_format_elements = user=<%u> method=%m rip=%r lip=%l mpid=%e %c %k mail_debug = yes mail_gid = vmail mail_location = maildir:/var/mail/%d/%n mail_plugins = quota expire mail_log notify mail_privileged_group = mail mail_temp_dir = /tmp/Dovecot mail_uid = vmail managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave duplicate namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext driver = ldap } plugin { expire = Trash mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid size quota = maildir:User quota quota_exceeded_message = Storage quota for this account has been exceeded, please try again later. quota_rule = *:storage=1G quota_rule2 = Trash:storage=+30%% quota_rule3 = Sent:storage=+30%% quota_warning = storage=90%% quota-warning 90 %u quota_warning2 = storage=75%% quota-warning 75 %u } pop3_client_workarounds = outlook-no-nuls oe-ns-eoh postmaster_address = info@netocean.de sendmail_path = /usr/local/sbin/sendmail service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } unix_listener auth-userdb { group = vmail mode = 0600 user = vmail } } service imap-login { inet_listener imaps { port = 0 } } service lmtp { unix_listener /var/spool/postfix/private/dovecot-lmtp { group = postfix mode = 0660 user = postfix } user = vmail } service pop3-login { inet_listener pop3s { port = 0 } } service quota-warning { executable = script /usr/local/bin/quota-warning.sh unix_listener quota-warning { user = vmail } user = vmail } ssl = required ssl_cert =
# ======================== dovecot/conf.d/auth-ldap.conf.ext =================== #
passdb { driver = ldap
# Path for LDAP configuration file, see example-config/dovecot-ldap.conf.ext args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext }
# "prefetch" user database means that the passdb already provided the # needed information and there's no need to do a separate userdb lookup. #
userdb { driver = prefetch } userdb { driver = ldap args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext
# Default fields can be used to specify defaults that LDAP may override #default_fields = home=/home/virtual/%u }
# ======================== dovecot/dovecot-ldap.conf.ext =================== #
hosts = 127.0.0.1:389 dn = uid=dovecot,ou=systemuser,ou=mail,dc=MyDomain,dc=TLD dnpass = TopSecret tls = yes tls_cert_file = /etc/ssl/RootCA/certs/192.168.50.101.pem tls_key_file = /etc/ssl/RootCA/certs/192.168.50.101.key debug_level = -1 auth_bind = yes ldap_version = 3 base = ou=accounts,ou=mail,dc=MyDomain,dc=TLD scope = subtree user_attrs = mailStorageDirectory=home, mailUidNumber=uid, mailGidNumber=gid, mailQuotaSize=quota_rule=*:bytes=%$, mailQuotaCount=quota_rule2 user_filter = (&(objectClass=mailAccount)(mailAddress=%u)) pass_attrs = mailAddress=user,mailPassword=password pass_filter = (&(objectClass=mailAccount)(mailAccountStatus=active)(mailAddress=%u)) default_pass_scheme = SSHA
Sorry didn't scroll to the bottom to see the dovecot -n. I'm assuming freebsd has an /etc/login.conf similiar to openbsd. If so you may need to do something similiar to this:
dovecot:
:openfiles-cur=512:
:openfiles-max=2048:
:tc=daemon:
Rebuild the login.conf.db file if necessary:
# [ -f /etc/login.conf.db ] && cap_mkdb /etc/login.conf
Hope this helps.
On 01/25/15 19:18, Edgar Pettijohn wrote:
What is the OS?
On 01/25/15 18:50, Leander Schäfer wrote:
Hi
I keep on getting errors and can't connect/login to Dovecot. I did my research but unfortunately without success. It is for sure not ulimit because ulimit is set to unlimited per default already. Still , it complains about "Too many open files" but this is a test system and the service dovecot and postfix have just been started. No one except me is testing on this system. This is very weired ;/
/var/log/maillog ; echo "" > /var/log/slapd.log ; service postfix start ; service dovecot start Stopping dovecot. Waiting for PIDS: 3245.
root@WM-01 [~]$ service dovecot stop; service postfix stop ; echo "" postfix/postfix-script: stopping the Postfix mail system postfix/postfix-script: starting the Postfix mail system Starting dovecot.
root@WM-01 [~]$ telnet 127.0.0.1 143 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. Connection closed by foreign host.
root@WM-01 [~]$ cat /var/log/mail Jan 26 01:39:12 WM-01 dovecot: imap-login: Fatal: pipe() failed: Too many open files Jan 26 01:39:12 WM-01 dovecot: master: Error: service(imap-login): command startup failed, throttling for 4 secs
If I uncoment port = 0 in POP and IMAP then it looks even worse then above. Telnet is not even closed by remote host and three of the "Too many open files" errors are showing up in maillog:
root@WM-01 [~]$ telnet 127.0.0.1 143 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. ^] telnet> Connection closed. root@WM-01 [~]$ cat /var/log/maillog
Jan 26 01:45:19 WM-01 postfix/postfix-script[60560]: starting the Postfix mail system Jan 26 01:45:19 WM-01 postfix/master[60562]: daemon started -- version 1.0, configuration /usr/local/etc/postfix Jan 26 01:45:19 WM-01 dovecot: master: Dovecot v2.2.15 starting up for imap, pop3, lmtp Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: socket(login) failed: Too many open files Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: auth: connect(login) failed: Too many open files Jan 26 01:45:24 WM-01 dovecot: imap-login: Error: net_accept() failed: Too many open files root@WM-01 [~]$
Does anyone have an idea what could be wrong here? I attached the relevant configuration below. I use OpenLDAP as backend. Please let me know if you need more information. Thank you very much.
Best Regards, Leander
# ========================== dovecot -n ============================== #
# 2.2.15: /usr/local/etc/dovecot/dovecot.conf # Pigeonhole version 0.4.6 (3e924b1b6c5c+) # OS: FreeBSD 10.1-RELEASE amd64 ufs auth_debug = yes auth_debug_passwords = yes auth_failure_delay = 3 secs auth_mechanisms = plain login auth_verbose = yes auth_verbose_passwords = yes base_dir = /var/run/dovecot/ disable_plaintext_auth = no imap_client_workarounds = delay-newmail tb-extra-mailbox-sep tb-lsub-flags lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes login_greeting = Welcome to Mail Server. login_log_format_elements = user=<%u> method=%m rip=%r lip=%l mpid=%e %c %k mail_debug = yes mail_gid = vmail mail_location = maildir:/var/mail/%d/%n mail_plugins = quota expire mail_log notify mail_privileged_group = mail mail_temp_dir = /tmp/Dovecot mail_uid = vmail managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave duplicate namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext driver = ldap } plugin { expire = Trash mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid size quota = maildir:User quota quota_exceeded_message = Storage quota for this account has been exceeded, please try again later. quota_rule = *:storage=1G quota_rule2 = Trash:storage=+30%% quota_rule3 = Sent:storage=+30%% quota_warning = storage=90%% quota-warning 90 %u quota_warning2 = storage=75%% quota-warning 75 %u } pop3_client_workarounds = outlook-no-nuls oe-ns-eoh postmaster_address = info@netocean.de sendmail_path = /usr/local/sbin/sendmail service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } unix_listener auth-userdb { group = vmail mode = 0600 user = vmail } } service imap-login { inet_listener imaps { port = 0 } } service lmtp { unix_listener /var/spool/postfix/private/dovecot-lmtp { group = postfix mode = 0660 user = postfix } user = vmail } service pop3-login { inet_listener pop3s { port = 0 } } service quota-warning { executable = script /usr/local/bin/quota-warning.sh unix_listener quota-warning { user = vmail } user = vmail } ssl = required ssl_cert =
# ======================== dovecot/conf.d/auth-ldap.conf.ext =================== #
passdb { driver = ldap
# Path for LDAP configuration file, see example-config/dovecot-ldap.conf.ext args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext }
# "prefetch" user database means that the passdb already provided the # needed information and there's no need to do a separate userdb lookup. #
userdb { driver = prefetch } userdb { driver = ldap args = /usr/local/etc/dovecot/dovecot-ldap.conf.ext
# Default fields can be used to specify defaults that LDAP may override #default_fields = home=/home/virtual/%u }
# ======================== dovecot/dovecot-ldap.conf.ext =================== #
hosts = 127.0.0.1:389 dn = uid=dovecot,ou=systemuser,ou=mail,dc=MyDomain,dc=TLD dnpass = TopSecret tls = yes tls_cert_file = /etc/ssl/RootCA/certs/192.168.50.101.pem tls_key_file = /etc/ssl/RootCA/certs/192.168.50.101.key debug_level = -1 auth_bind = yes ldap_version = 3 base = ou=accounts,ou=mail,dc=MyDomain,dc=TLD scope = subtree user_attrs = mailStorageDirectory=home, mailUidNumber=uid, mailGidNumber=gid, mailQuotaSize=quota_rule=*:bytes=%$, mailQuotaCount=quota_rule2 user_filter = (&(objectClass=mailAccount)(mailAddress=%u)) pass_attrs = mailAddress=user,mailPassword=password pass_filter = (&(objectClass=mailAccount)(mailAccountStatus=active)(mailAddress=%u)) default_pass_scheme = SSHA
participants (3)
-
Edgar Pettijohn
-
Leander Schäfer
-
Reindl Harald