dovecot - Apr 2011 - Intermitent ldap auth problems benchmarking dovecot

Hello

 We are using SLAMD (Distributed Load Generation Engine, www.slamd.com) to
benchmark our dovecot server (ldap auth). We are simulating 2.000 simultaneous
logins and 20% of them fail. We saw the following errors in the log:


Apr 12 09:40:07 buzon dovecot: auth: Error: ldap(correo,192.168.4.153): Request
queue is full (oldest added 1 secs ago)
 Apr 12 09:40:07 buzon dovecot: auth: Error: ldap(correo,192.168.4.153): Request
queue is full (oldest added 1 secs ago)
 Apr 12 09:40:07 buzon dovecot: auth: Error: ldap(correo,192.168.4.153): Request
queue is full (oldest added 1 secs ago)


 We increased auth_worker_max_count from 350 to 3500 (10x increase). Now we see
the following errors (still 20% of logins fail):


 Apr 12 10:14:45 buzon dovecot: imap-login: Internal login failure (pid=29016
id=24783) (auth failed, 1 attempts): user=<correo>, method=PLAIN,
rip=192.168.4.153, lip=192.168.4.80, mpid=21284
 Apr 12 10:14:45 buzon dovecot: imap-login: Internal login failure (pid=29016
id=24784) (auth failed, 1 attempts): user=<correo>, method=PLAIN,
rip=192.168.4.153, lip=192.168.4.80, mpid=21286


 What are we doing wrong? We expect 1000 simultaneous imap sessions, we have
65.000 mailboxes.


 This is our doveconf -n output

 # 2.0.11: /etc/dovecot/dovecot.conf
 # OS: Linux 2.6.18-238.5.1.el5 x86_64 Red Hat Enterprise Linux Server release
5.6 (Tikanga) ext4
 auth_debug = yes
 auth_master_user_separator = *
 auth_mechanisms = plain login
 auth_worker_max_count = 3500
 base_dir = /var/run/dovecot/
 default_client_limit = 5000
 default_process_limit = 6500
 disable_plaintext_auth = no
 imap_client_workarounds = tb-extra-mailbox-sep delay-newmail
 lda_mailbox_autocreate = yes
 lda_mailbox_autosubscribe = yes
 mail_fsync = never
 mail_gid = entrega
 mail_home = /buzones/%2.26Hn/%2.200Hn/%n/
 mail_location =
mdbox:/buzones/%2.26Hn/%2.200Hn/%n:INDEX=/indices_dovecot/indices/%2.26Hn/%2.200Hn/%n
 mail_max_userip_connections = 15000
 mail_plugins = " zlib acl"
 mail_uid = entrega
 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
 mdbox_rotate_interval = 1 days
 mdbox_rotate_size = 60 M
 passdb {
 args = /etc/dovecot/dovecot-ldap.conf
 driver = ldap
 }
 passdb {
 args = /etc/usuario_maestro.txt
 driver = passwd-file
 master = yes
 }
 passdb {
 args = /etc/dovecot/dovecot-ldap.conf
 driver = ldap
 }
 plugin/acl = vfile
 plugin/quota = dict:Cuota de usuario::file:/buzones/cuotas/%n
 plugin/quota_rule2 = Trash:storage=+10%%
 plugin/quota_warning = storage=95%% /usr/local/bin/quota-warning.sh 95
 plugin/quota_warning2 = storage=80%% /usr/local/bin/quota-warning.sh 80
 plugin/sieve = /buzones/%2.26Hn/%2.200Hn/%n/dovecot.sieve
 plugin/sieve_dir = /buzones//%2.26Hn/%2.200Hn/%n/sieve/
 plugin/zlib_save = gz
 plugin/zlib_save_level = 9
 protocols = pop3 imap sieve
 service anvil {
 client_limit = 25000
 }
 service auth {
 client_limit = 28000
 unix_listener auth-master {
 user = entrega
 }
 unix_listener auth-userdb {
 user = entrega
 }
 user = root
 }
 service imap-login {
 executable = /usr/libexec/dovecot/imap-login
 group = dovenull
 service_count = 0
 }
 service imap {
 executable = /usr/libexec/dovecot/imap
 process_limit = 6000
 }
 service managesieve-login {
 executable = /usr/libexec/dovecot/managesieve-login
 inet_listener sieve {
 port = 2000
 }
 process_limit = 2000
 }
 service managesieve {
 executable = /usr/libexec/dovecot/managesieve
 process_limit = 5000
 }
 service pop3-login {
 executable = /usr/libexec/dovecot/pop3-login
 process_limit = 4000
 service_count = 0
 }
 service pop3 {
 executable = /usr/libexec/dovecot/pop3
 process_limit = 4000
 }
 ssl_ca = </etc/pki/generico/cacert.crt.pem
 ssl_cert = </etc/pki/generico/wildcard.crt
 ssl_key = </etc/pki/generico/wildcard-key.pem
 userdb {
 args = /etc/dovecot/dovecot-ldap.conf
 driver = ldap
 }
 userdb {
 args = /etc/dovecot/dovecot-ldap-userdb.conf
 driver = ldap
 }
 verbose_proctitle = yes
 protocol sieve {
 managesieve_implementation_string = dovecot
 managesieve_logout_format = bytes=%i/%o
 managesieve_max_line_length = 65536
 }
 protocol lda {
 hostname = us.es
 info_log_path  log_path  mail_fsync = optimized
 mail_plugins = sieve zlib
 postmaster_address = evcorreo at domain.es
 syslog_facility = mail
 }
 protocol imap {
 mail_plugins = zlib
 }
 protocol pop3 {
 mail_plugins = zlib
 pop3_enable_last = yes
 pop3_uidl_format = %g
 }

Have you test with auth cache?

I get very good results with this options:

auth_cache_size = 10M
auth_cache_ttl = 60
auth_cache_negative_ttl = 180


2011/4/12 Maria Arrea <maria_arrea at gmx.com>:
> Hello
>
> ?We are using SLAMD (Distributed Load Generation Engine, www.slamd.com) to
benchmark our dovecot server (ldap auth). We are simulating 2.000 simultaneous
logins and 20% of them fail. We saw the following errors in the log:
>
>
> Apr 12 09:40:07 buzon dovecot: auth: Error: ldap(correo,192.168.4.153):
Request queue is full (oldest added 1 secs ago)
> ?Apr 12 09:40:07 buzon dovecot: auth: Error: ldap(correo,192.168.4.153):
Request queue is full (oldest added 1 secs ago)
> ?Apr 12 09:40:07 buzon dovecot: auth: Error: ldap(correo,192.168.4.153):
Request queue is full (oldest added 1 secs ago)
>
>
> ?We increased auth_worker_max_count from 350 to 3500 (10x increase). Now we
see the following errors (still 20% of logins fail):
>
>
> ?Apr 12 10:14:45 buzon dovecot: imap-login: Internal login failure
(pid=29016 id=24783) (auth failed, 1 attempts): user=<correo>,
method=PLAIN, rip=192.168.4.153, lip=192.168.4.80, mpid=21284
> ?Apr 12 10:14:45 buzon dovecot: imap-login: Internal login failure
(pid=29016 id=24784) (auth failed, 1 attempts): user=<correo>,
method=PLAIN, rip=192.168.4.153, lip=192.168.4.80, mpid=21286
>
>
> ?What are we doing wrong? We expect 1000 simultaneous imap sessions, we
have 65.000 mailboxes.
>
>
> ?This is our doveconf -n output
>
> ?# 2.0.11: /etc/dovecot/dovecot.conf
> ?# OS: Linux 2.6.18-238.5.1.el5 x86_64 Red Hat Enterprise Linux Server
release 5.6 (Tikanga) ext4
> ?auth_debug = yes
> ?auth_master_user_separator = *
> ?auth_mechanisms = plain login
> ?auth_worker_max_count = 3500
> ?base_dir = /var/run/dovecot/
> ?default_client_limit = 5000
> ?default_process_limit = 6500
> ?disable_plaintext_auth = no
> ?imap_client_workarounds = tb-extra-mailbox-sep delay-newmail
> ?lda_mailbox_autocreate = yes
> ?lda_mailbox_autosubscribe = yes
> ?mail_fsync = never
> ?mail_gid = entrega
> ?mail_home = /buzones/%2.26Hn/%2.200Hn/%n/
> ?mail_location =
mdbox:/buzones/%2.26Hn/%2.200Hn/%n:INDEX=/indices_dovecot/indices/%2.26Hn/%2.200Hn/%n
> ?mail_max_userip_connections = 15000
> ?mail_plugins = " zlib acl"
> ?mail_uid = entrega
> ?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
> ?mdbox_rotate_interval = 1 days
> ?mdbox_rotate_size = 60 M
> ?passdb {
> ?args = /etc/dovecot/dovecot-ldap.conf
> ?driver = ldap
> ?}
> ?passdb {
> ?args = /etc/usuario_maestro.txt
> ?driver = passwd-file
> ?master = yes
> ?}
> ?passdb {
> ?args = /etc/dovecot/dovecot-ldap.conf
> ?driver = ldap
> ?}
> ?plugin/acl = vfile
> ?plugin/quota = dict:Cuota de usuario::file:/buzones/cuotas/%n
> ?plugin/quota_rule2 = Trash:storage=+10%%
> ?plugin/quota_warning = storage=95%% /usr/local/bin/quota-warning.sh 95
> ?plugin/quota_warning2 = storage=80%% /usr/local/bin/quota-warning.sh 80
> ?plugin/sieve = /buzones/%2.26Hn/%2.200Hn/%n/dovecot.sieve
> ?plugin/sieve_dir = /buzones//%2.26Hn/%2.200Hn/%n/sieve/
> ?plugin/zlib_save = gz
> ?plugin/zlib_save_level = 9
> ?protocols = pop3 imap sieve
> ?service anvil {
> ?client_limit = 25000
> ?}
> ?service auth {
> ?client_limit = 28000
> ?unix_listener auth-master {
> ?user = entrega
> ?}
> ?unix_listener auth-userdb {
> ?user = entrega
> ?}
> ?user = root
> ?}
> ?service imap-login {
> ?executable = /usr/libexec/dovecot/imap-login
> ?group = dovenull
> ?service_count = 0
> ?}
> ?service imap {
> ?executable = /usr/libexec/dovecot/imap
> ?process_limit = 6000
> ?}
> ?service managesieve-login {
> ?executable = /usr/libexec/dovecot/managesieve-login
> ?inet_listener sieve {
> ?port = 2000
> ?}
> ?process_limit = 2000
> ?}
> ?service managesieve {
> ?executable = /usr/libexec/dovecot/managesieve
> ?process_limit = 5000
> ?}
> ?service pop3-login {
> ?executable = /usr/libexec/dovecot/pop3-login
> ?process_limit = 4000
> ?service_count = 0
> ?}
> ?service pop3 {
> ?executable = /usr/libexec/dovecot/pop3
> ?process_limit = 4000
> ?}
> ?ssl_ca = </etc/pki/generico/cacert.crt.pem
> ?ssl_cert = </etc/pki/generico/wildcard.crt
> ?ssl_key = </etc/pki/generico/wildcard-key.pem
> ?userdb {
> ?args = /etc/dovecot/dovecot-ldap.conf
> ?driver = ldap
> ?}
> ?userdb {
> ?args = /etc/dovecot/dovecot-ldap-userdb.conf
> ?driver = ldap
> ?}
> ?verbose_proctitle = yes
> ?protocol sieve {
> ?managesieve_implementation_string = dovecot
> ?managesieve_logout_format = bytes=%i/%o
> ?managesieve_max_line_length = 65536
> ?}
> ?protocol lda {
> ?hostname = us.es
> ?info_log_path > ?log_path > ?mail_fsync = optimized
> ?mail_plugins = sieve zlib
> ?postmaster_address = evcorreo at domain.es
> ?syslog_facility = mail
> ?}
> ?protocol imap {
> ?mail_plugins = zlib
> ?}
> ?protocol pop3 {
> ?mail_plugins = zlib
> ?pop3_enable_last = yes
> ?pop3_uidl_format = %g
> ?}
>


-- 
Antonio P?rez-Aranda Alcaide
aperezaranda at yaco.es

Yaco Sistemas S.L.
http://www.yaco.es/
C/ Rioja 5, 41001 Sevilla
Tel?fono +34 954 50 00 57
Fax ? ? ?+34 954 50 09 29

On Tue, 2011-04-12 at 09:15 +0000, Maria Arrea wrote:
> Hello
> 
>  We are using SLAMD (Distributed Load Generation Engine, www.slamd.com) to
benchmark our dovecot server (ldap auth). We are simulating 2.000 simultaneous
logins and 20% of them fail. We saw the following errors in the log:
> 
> 
> Apr 12 09:40:07 buzon dovecot: auth: Error: ldap(correo,192.168.4.153):
Request queue is full (oldest added 1 secs ago)
>  Apr 12 09:40:07 buzon dovecot: auth: Error: ldap(correo,192.168.4.153):
Request queue is full (oldest added 1 secs ago)
>  Apr 12 09:40:07 buzon dovecot: auth: Error: ldap(correo,192.168.4.153):
Request queue is full (oldest added 1 secs ago)
Hmm. This is a hard coded limit. I didn't really think people wanted >1k
logins per second.. In src/auth/db-ldap.h:

/* Maximum number of requests in queue. After this new requests are
dropped. */
#define DB_LDAP_MAX_QUEUE_SIZE 1024

Maybe that limit should be dynamic. Like only >30sec old requests
actually get dropped when the limit gets over 1k.
>  We increased auth_worker_max_count from 350 to 3500 (10x increase). Now we
see the following errors (still 20% of logins fail):
LDAP doesn't use auth workers, so that change shouldn't have affected
anything.