[Dovecot] rc31 -> "deferring operation: binding"

[Ben Beuchler]

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: