[Dovecot] rc31 -> "deferring operation: binding"
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
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.html
Aye, 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@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
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
Sorry; cut myself off.
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 deferred binding issue.
-Ben
Ben Beuchler wrote:
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:
Some ideas from the peanut gallery here -- if you run 'ldd dovecot-auth', what openldap library is it linked into? Have you tried compiling dovecot against this new 2.3.32 openldap install?
cliff:~ root# egrep -v '(^$|^#)' /opt/dovecot/etc/dovecot-ldap.conf ldap_version = 3
Have you tried binding as version 2, just to see what happens?
-te
-- Troy Engel | Systems Engineer Fluid Inc. | http://www.fluid.com
Some ideas from the peanut gallery here -- if you run 'ldd dovecot-auth', what openldap library is it linked into?
The system libldap_r library, which is a 2.2.x release.
Have you tried compiling dovecot against this new 2.3.32 openldap install?
Nope; that's on my list of things to try today.
Have you tried binding as version 2, just to see what happens?
Worth trying. I'll give it a shot.
-Ben
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
participants (3)
-
Ben Beuchler
-
Timo Sirainen
-
Troy Engel