I hate to bring up anything that might delay 1.0, but the behavior I'm
seeing is rather... weird.
I'm running rc31, using "userdb static" and
"auth_bind=yes".
With rc1 (what I had been running) I would occasionally get some
"deferring operation" complaints from LDAP, but very rarely. Every
now and then it would start to throw "deferring operation: pending
operations" and stop authenticating. Digging through the Changelog
indicated you've made considerable updates to the auth_bind code,
apparently to eliminate just such problems, so I upgraded.
Now I'm running rc31 and my OpenLDAP logs are throwing an error like
this every few seconds:
Apr 9 19:56:42 swizzle slapd[1626]: connection_input: conn=6696168
deferring operation: binding
This appears to happen with around every 3rd or 4th bind request.
Sometimes it happens with the anonymous requests, sometimes with the
auth bind request.
As I understand it, the new auth_bind code is extremely careful about
flushing all pending operations before attempting to perform the
authentication bind. If that's the case, any idea why OpenLDAP is
deferring the binding operations so frequently? So far it hasn't
caused any login problems, but it's quite disconcerting given the
expected behavior described in the Changelog.
Any thoughts?
-Ben
cliff:/opt/dovecot/etc root# ../sbin/dovecot -n
# /opt/dovecot-1.0.rc31/etc/dovecot.conf
log_timestamp: %Y-%m-%d %H:%M:%S
protocols: imap imaps pop3 pop3s
ssl_cert_file: /etc/ssl/certs/mcad.edu.rapidssl.crt
ssl_key_file: /etc/ssl/private/mcad.edu.rapidssl.key
disable_plaintext_auth: no
shutdown_clients: no
login_dir: /opt/dovecot-1.0.rc31/var/run/dovecot/login
login_executable(default): /opt/dovecot-1.0.rc31/libexec/dovecot/imap-login
login_executable(imap): /opt/dovecot-1.0.rc31/libexec/dovecot/imap-login
login_executable(pop3): /opt/dovecot-1.0.rc31/libexec/dovecot/pop3-login
login_greeting: Line forms at the rear.
login_greeting_capability(default): yes
login_greeting_capability(imap): yes
login_greeting_capability(pop3): no
login_processes_count: 5
verbose_proctitle: yes
first_valid_uid: 5000
last_valid_uid: 5000
first_valid_gid: 5000
last_valid_gid: 5000
mail_location: maildir:/mail/mcad.edu/%u/Maildir/
maildir_stat_dirs: yes
maildir_copy_with_hardlinks: yes
mail_executable(default): /opt/dovecot-1.0.rc31/libexec/dovecot/imap
mail_executable(imap): /opt/dovecot-1.0.rc31/libexec/dovecot/imap
mail_executable(pop3): /opt/dovecot-1.0.rc31/libexec/dovecot/pop3
mail_plugin_dir(default): /opt/dovecot-1.0.rc31/lib/dovecot/imap
mail_plugin_dir(imap): /opt/dovecot-1.0.rc31/lib/dovecot/imap
mail_plugin_dir(pop3): /opt/dovecot-1.0.rc31/lib/dovecot/pop3
pop3_uidl_format(default):
pop3_uidl_format(imap):
pop3_uidl_format(pop3): %08Xu%08Xv
auth default:
mechanisms: plain login
user: dovecot-auth
passdb:
driver: ldap
args: /opt/dovecot/etc/dovecot-ldap.conf
userdb:
driver: static
args: uid=5000 gid=5000
socket:
type: listen
client:
path: /var/spool/postfix/private/auth
mode: 432
user: postfix
group: postfix
master:
On 10.4.2007, at 4.04, Ben Beuchler wrote:> As I understand it, the new auth_bind code is extremely careful about > flushing all pending operations before attempting to perform the > authentication bind. If that's the case, any idea why OpenLDAP is > deferring the binding operations so frequently? So far it hasn't > caused any login problems, but it's quite disconcerting given the > expected behavior described in the Changelog.Well, I've really no idea. I know it works for many people and I couldn't get it to break when stress testing with hundreds of connections per second. Is there anything else in slapd logs? For example I found this with google: http://www.openldap.org/lists/openldap-software/200507/ msg00063.html -------------- next part -------------- A non-text attachment was scrubbed... Name: PGP.sig Type: application/pgp-signature Size: 186 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20070410/66c31229/attachment.bin>
> Is there anything else in slapd logs?I haven't been able to identify anything of consequence.> For example I found this with google: http://www.openldap.org/lists/openldap-software/200507/ > msg00063.htmlAye, I saw that as well. Unfortunately, Howard points out that the author of that message was mistaken and, as near as I can tell, the only "solution" anyone could come up with was to upgrade. I'm already running the current stable OpenLDAP. I'll try to track down more info. -Ben
On 4/10/07, Timo Sirainen <tss at iki.fi> wrote:> On 10.4.2007, at 4.04, Ben Beuchler wrote: > > > As I understand it, the new auth_bind code is extremely careful about > > flushing all pending operations before attempting to perform the > > authentication bind. If that's the case, any idea why OpenLDAP is > > deferring the binding operations so frequently? So far it hasn't > > caused any login problems, but it's quite disconcerting given the > > expected behavior described in the Changelog. > > Well, I've really no idea. I know it works for many people and I > couldn't get it to break when stress testing with hundreds of > connections per second.I installed a virgin install of OpenLDAP 2.3.32 directly on the mail server, copied over my LDAP database, pointed Dovecot at it, and started it up. I immediately started getting the same log entries: Apr 10 18:55:45 cliff slapd[10420]: connection_input: conn=3 deferring operation: binding I *must* be doing something wrong... Or, at least, I must be doing something a little different than the other test cases. Any thoughts? The really frustrating thing, of course, is that I really have no proof whatsoever that the occasional auth failures (all authentication attempts hang until Dovecot is restarted) have anything to do with the cliff:/usr/local/etc/openldap root# /opt/dovecot/sbin/dovecot -n # /opt/dovecot-1.0.rc31/etc/dovecot.conf log_timestamp: %Y-%m-%d %H:%M:%S protocols: imap imaps pop3 pop3s ssl_cert_file: /etc/ssl/certs/mcad.edu.rapidssl.crt ssl_key_file: /etc/ssl/private/mcad.edu.rapidssl.key disable_plaintext_auth: no verbose_ssl: yes shutdown_clients: no login_dir: /opt/dovecot-1.0.rc31/var/run/dovecot/login login_executable(default): /opt/dovecot-1.0.rc31/libexec/dovecot/imap-login login_executable(imap): /opt/dovecot-1.0.rc31/libexec/dovecot/imap-login login_executable(pop3): /opt/dovecot-1.0.rc31/libexec/dovecot/pop3-login login_greeting: Line forms at the rear. login_greeting_capability(default): yes login_greeting_capability(imap): yes login_greeting_capability(pop3): no login_processes_count: 5 verbose_proctitle: yes first_valid_uid: 5000 last_valid_uid: 5000 first_valid_gid: 5000 last_valid_gid: 5000 mail_location: maildir:/mail/mcad.edu/%u/Maildir/ maildir_stat_dirs: yes maildir_copy_with_hardlinks: yes mail_executable(default): /opt/dovecot-1.0.rc31/libexec/dovecot/imap mail_executable(imap): /opt/dovecot-1.0.rc31/libexec/dovecot/imap mail_executable(pop3): /opt/dovecot-1.0.rc31/libexec/dovecot/pop3 mail_plugin_dir(default): /opt/dovecot-1.0.rc31/lib/dovecot/imap mail_plugin_dir(imap): /opt/dovecot-1.0.rc31/lib/dovecot/imap mail_plugin_dir(pop3): /opt/dovecot-1.0.rc31/lib/dovecot/pop3 pop3_uidl_format(default): pop3_uidl_format(imap): pop3_uidl_format(pop3): %08Xu%08Xv auth default: mechanisms: plain login user: dovecot-auth verbose: yes debug: yes passdb: driver: ldap args: /opt/dovecot/etc/dovecot-ldap.conf userdb: driver: static args: uid=5000 gid=5000 socket: type: listen client: path: /var/spool/postfix/private/auth mode: 432 user: postfix group: postfix master: cliff:~ root# egrep -v '(^$|^#)' /opt/dovecot/etc/dovecot-ldap.conf uris = ldap://localhost auth_bind = yes ldap_version = 3 base = dc=accounts,dc=ldap,dc=mcad,dc=edu pass_attrs = uid=user,userPassword=password pass_filter = (&(objectClass=mcadEmailAccount)(activePopImap=TRUE)(uid=%u)) default_pass_scheme = SSHA user_global_uid = 5000 user_global_gid = 5000
> Well, I've really no idea. I know it works for many people and I > couldn't get it to break when stress testing with hundreds of > connections per second.More info: In the 5 minutes between when Nagios flagged IMAP as down (and we tested it as down) until we restarted Dovecot, 103 authentications successfully completed. For the sake of reference, in the previous 5 minutes 311 IMAP logins succeeded. Also interesting: IMAP has died twice so far today (both times were at typical daily usage peaks). POP3 has not tested as down once. Admittedly, we do roughly 9 X as many IMAP logins as POP, but they both auth via dovecot-auth, right? -Ben