thr3ads.net - dovecot - [Dovecot] LDAP w/SASL "Active Directory" authentication failing. [Nov 2011]

If this information is useful, please help other people find it:
Share via:

David Varela

2011-Nov-01 15:55 UTC

[Dovecot] LDAP w/SASL "Active Directory" authentication failing.

Hello,

I am running a Dovecot server (version 1.2.17) on FreeBSD 8.2, using
LDAP to authenticate Active Directory users.  I can successfully bind and
authenticate using PLAIN and LDAP without SASL, but obviously passwords for
the bind user and the user being authenticated are being passed in plain
text.  I've attempted to configure my server to us SASL however when I
attempt to authenticate a user I see authentication failures.  I reviewed
the security log on my domain controller and see that the bind user is
binding properly, so the issue appears to be orginating from the user
authentication, however I cannot determine what the issue is.  Here is all
the information regarding my configuration, along with the logs from the
server:

Dovecot -n

# 1.2.17: /usr/local/etc/dovecot.conf
# OS: FreeBSD 8.2-RELEASE i386  ufs
log_path: /var/log/dovecot.log
info_log_path: /var/log/dovecot_info.log
protocols: imap pop3 imaps pop3s
ssl_cert_file: /etc/ssl/dovecot/cert.pem
ssl_key_file: /etc/ssl//dovecot/key.pem
login_dir: /var/run/dovecot/login
login_executable(default): /usr/local/libexec/dovecot/imap-login
login_executable(imap): /usr/local/libexec/dovecot/imap-login
login_executable(pop3): /usr/local/libexec/dovecot/pop3-login
valid_chroot_dirs: /usr/data/vmail
verbose_proctitle: yes
first_valid_uid: 1001
last_valid_uid: 1001
first_valid_gid: 1001
last_valid_gid: 1001
mail_privileged_group: mail
mail_location: maildir:/usr/data/vmail/%u
mail_executable(default): /usr/local/libexec/dovecot/imap
mail_executable(imap): /usr/local/libexec/dovecot/imap
mail_executable(pop3): /usr/local/libexec/dovecot/pop3
mail_plugin_dir(default): /usr/local/lib/dovecot/imap
mail_plugin_dir(imap): /usr/local/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3
imap_client_workarounds(default): delay-newmail netscape-eoh
tb-extra-mailbox-sep
imap_client_workarounds(imap): delay-newmail netscape-eoh
tb-extra-mailbox-sep
imap_client_workarounds(pop3):
pop3_client_workarounds(default):
pop3_client_workarounds(imap):
pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh
lda:
  sendmail_path: /usr/sbin/sendmail
auth default:
  mechanisms: plain gssapi ntlm login
  username_format: %Ln
  winbind_helper_path: /usr/local/bin/ntlm_auth
  verbose: yes
  debug: yes
  debug_passwords: yes
  use_winbind: yes
  passdb:
    driver: ldap
    args: /usr/local/etc/dovecot-ldap.conf
  userdb:
    driver: static
    args: uid=vmail gid=vmail home=/usr/data/vmail/%u
  socket:
    type: listen
    client:
      path: /var/spool/postfix/private/auth
      mode: 432
      user: postfix
      group: postfix
    master:
      path: /var/run/dovecot/auth-master
      mode: 384
dovecot-ldap.conf

hosts = 192.168.0.240:3268
dn = cn=PostfixBind,ou=IT,ou=Central Office,ou=LMC,dc=smallmountain,dc=Local
dnpass = y0urm0mma
sasl_bind = yes
#sasl_mech = GSSAPI
#sasl_realm = smallmountain.local
#sasl_authz_id debug_level = -1
#auth_bind = yes
ldap_version = 3
base = dc=smallmountain,dc=Local
deref = never
scope = subtree
user_filter = (&(objectClass=person)(mail=%u))
pass_attrs = mail=user
pass_filter = (&(objectClass=person)(sAMAccountName=%n))

dovecot.log

Nov 01 09:09:48 dovecot: Warning: Killed with signal 15 (by pid=99758 uid=0
code=kill)
Nov 01 09:09:48 auth(default): Error: ldap_pvt_sasl_getmech
Nov 01 09:09:48 auth(default): Error: ldap_search
Nov 01 09:09:48 auth(default): Error: put_filter: "(objectclass=*)"
Nov 01 09:09:48 auth(default): Error: put_filter: simple
Nov 01 09:09:48 auth(default): Error: put_simple_filter:
"objectclass=*"
Nov 01 09:09:48 auth(default): Error: ldap_build_search_req ATTRS:
supportedSASLMechanisms
Nov 01 09:09:48 auth(default): Error: ldap_send_initial_request
Nov 01 09:09:48 auth(default): Error: ldap_new_connection 1 1 0
Nov 01 09:09:48 auth(default): Error: ldap_int_open_connection
Nov 01 09:09:48 auth(default): Error: ldap_connect_to_host: TCP
192.168.0.240:3268
Nov 01 09:09:48 auth(default): Error: ldap_new_socket: 11
Nov 01 09:09:48 auth(default): Error: ldap_prepare_socket: 11
Nov 01 09:09:48 auth(default): Error: ldap_connect_to_host: Trying
192.168.0.240:3268
Nov 01 09:09:48 auth(default): Error: ldap_pvt_connect: fd: 11 tm: -1
async: 0
Nov 01 09:09:48 auth(default): Error: ldap_open_defconn: successful
Nov 01 09:09:48 auth(default): Error: ldap_send_server_request
Nov 01 09:09:48 auth(default): Error: ldap_result ld 0x18611700 msgid 1
Nov 01 09:09:48 auth(default): Error: wait4msg ld 0x18611700 msgid 1
(infinite timeout)
Nov 01 09:09:48 auth(default): Error: wait4msg continue ld 0x18611700 msgid
1 all 1
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Connections:
Nov 01 09:09:48 auth(default): Error: * host: 192.168.0.240  port: 3268
(default)
Nov 01 09:09:48 auth(default): Error:   refcnt: 2  status: Connected
Nov 01 09:09:48 auth(default): Error:   last used: Tue Nov  1 09:09:48 2011
Nov 01 09:09:48 auth(default): Error:
Nov 01 09:09:48 auth(default): Error:
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Outstanding Requests:
Nov 01 09:09:48 auth(default): Error:  * msgid 1,  origid 1, status
InProgress
Nov 01 09:09:48 auth(default): Error:    outstanding referrals 0, parent
count 0
Nov 01 09:09:48 auth(default): Error:   ld 0x18611700 request count 1
(abandoned 0)
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Response Queue:
Nov 01 09:09:48 auth(default): Error:    Empty
Nov 01 09:09:48 auth(default): Error:   ld 0x18611700 response count 0
Nov 01 09:09:48 auth(default): Error: ldap_chkResponseList ld 0x18611700
msgid 1 all 1
Nov 01 09:09:48 auth(default): Error: ldap_chkResponseList returns ld
0x18611700 NULL
Nov 01 09:09:48 auth(default): Error: ldap_int_select
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 msgid 1 all 1
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 msgid 1
message type search-entry
Nov 01 09:09:48 auth(default): Error: wait4msg continue ld 0x18611700 msgid
1 all 1
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Connections:
Nov 01 09:09:48 auth(default): Error: * host: 192.168.0.240  port: 3268
(default)
Nov 01 09:09:48 auth(default): Error:   refcnt: 2  status: Connected
Nov 01 09:09:48 auth(default): Error:   last used: Tue Nov  1 09:09:48 2011
Nov 01 09:09:48 auth(default): Error:
Nov 01 09:09:48 auth(default): Error:
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Outstanding Requests:
Nov 01 09:09:48 auth(default): Error:  * msgid 1,  origid 1, status
InProgress
Nov 01 09:09:48 auth(default): Error:    outstanding referrals 0, parent
count 0
Nov 01 09:09:48 auth(default): Error:   ld 0x18611700 request count 1
(abandoned 0)
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Response Queue:
Nov 01 09:09:48 auth(default): Error:  * msgid 1,  type 100
Nov 01 09:09:48 auth(default): Error:   ld 0x18611700 response count 1
Nov 01 09:09:48 auth(default): Error: ldap_chkResponseList ld 0x18611700
msgid 1 all 1
Nov 01 09:09:48 auth(default): Error: ldap_chkResponseList returns ld
0x18611700 NULL
Nov 01 09:09:48 auth(default): Error: ldap_int_select
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 msgid 1 all 1
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 msgid 1
message type search-result
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 0 new
referrals
Nov 01 09:09:48 auth(default): Error: read1msg:  mark request completed, ld
0x18611700 msgid 1
Nov 01 09:09:48 auth(default): Error: request done: ld 0x18611700 msgid 1
Nov 01 09:09:48 auth(default): Error: res_errno: 0, res_error: <>,
res_matched: <>
Nov 01 09:09:48 auth(default): Error: ldap_free_request (origid 1, msgid 1)
Nov 01 09:09:48 auth(default): Error: adding response ld 0x18611700 msgid 1
type 101:
Nov 01 09:09:48 auth(default): Error: ldap_parse_result
Nov 01 09:09:48 auth(default): Error: ldap_get_values
Nov 01 09:09:48 auth(default): Error: ldap_msgfree
Nov 01 09:09:48 auth(default): Error: ldap_sasl_interactive_bind: server
supports: GSSAPI GSS-SPNEGO EXTERNAL DIGEST-MD5
Nov 01 09:09:48 auth(default): Error: ldap_int_sasl_bind: GSSAPI GSS-SPNEGO
EXTERNAL DIGEST-MD5
Nov 01 09:09:48 auth(default): Error: ldap_int_sasl_open:
host=adminserver-1.smallmountain.local
Nov 01 09:09:48 auth(default): Error: ldap_sasl_bind
Nov 01 09:09:48 auth(default): Error: ldap_send_initial_request
Nov 01 09:09:48 auth(default): Error: ldap_send_server_request
Nov 01 09:09:48 auth(default): Error: ldap_msgfree
Nov 01 09:09:48 auth(default): Error: ldap_result ld 0x18611700 msgid 2
Nov 01 09:09:48 auth(default): Error: wait4msg ld 0x18611700 msgid 2
(infinite timeout)
Nov 01 09:09:48 auth(default): Error: wait4msg continue ld 0x18611700 msgid
2 all 1
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Connections:
Nov 01 09:09:48 auth(default): Error: * host: 192.168.0.240  port: 3268
(default)
Nov 01 09:09:48 auth(default): Error:   refcnt: 2  status: Connected
Nov 01 09:09:48 auth(default): Error:   last used: Tue Nov  1 09:09:48 2011
Nov 01 09:09:48 auth(default): Error:
Nov 01 09:09:48 auth(default): Error:
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Outstanding Requests:
Nov 01 09:09:48 auth(default): Error:  * msgid 2,  origid 2, status
InProgress
Nov 01 09:09:48 auth(default): Error:    outstanding referrals 0, parent
count 0
Nov 01 09:09:48 auth(default): Error:   ld 0x18611700 request count 1
(abandoned 0)
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Response Queue:
Nov 01 09:09:48 auth(default): Error:    Empty
Nov 01 09:09:48 auth(default): Error:   ld 0x18611700 response count 0
Nov 01 09:09:48 auth(default): Error: ldap_chkResponseList ld 0x18611700
msgid 2 all 1
Nov 01 09:09:48 auth(default): Error: ldap_chkResponseList returns ld
0x18611700 NULL
Nov 01 09:09:48 auth(default): Error: ldap_int_select
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 msgid 2 all 1
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 msgid 2
message type bind
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 0 new
referrals
Nov 01 09:09:48 auth(default): Error: read1msg:  mark request completed, ld
0x18611700 msgid 2
Nov 01 09:09:48 auth(default): Error: request done: ld 0x18611700 msgid 2
Nov 01 09:09:48 auth(default): Error: res_errno: 14, res_error: <>,
res_matched: <>
Nov 01 09:09:48 auth(default): Error: ldap_free_request (origid 2, msgid 2)
Nov 01 09:09:48 auth(default): Error: ldap_int_sasl_bind: <null>
Nov 01 09:09:48 auth(default): Error: ldap_parse_sasl_bind_result
Nov 01 09:09:48 auth(default): Error: ldap_parse_result
Nov 01 09:09:48 auth(default): Error: sasl_client_step: 2
Nov 01 09:09:48 auth(default): Error: sasl_client_step: 1
Nov 01 09:09:48 auth(default): Error: ldap_sasl_bind
Nov 01 09:09:48 auth(default): Error: ldap_send_initial_request
Nov 01 09:09:48 auth(default): Error: ldap_send_server_request
Nov 01 09:09:48 auth(default): Error: ldap_msgfree
Nov 01 09:09:48 auth(default): Error: ldap_result ld 0x18611700 msgid 3
Nov 01 09:09:48 auth(default): Error: wait4msg ld 0x18611700 msgid 3
(infinite timeout)
Nov 01 09:09:48 auth(default): Error: wait4msg continue ld 0x18611700 msgid
3 all 1
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Connections:
Nov 01 09:09:48 auth(default): Error: * host: 192.168.0.240  port: 3268
(default)
Nov 01 09:09:48 auth(default): Error:   refcnt: 2  status: Connected
Nov 01 09:09:48 auth(default): Error:   last used: Tue Nov  1 09:09:48 2011
Nov 01 09:09:48 auth(default): Error:
Nov 01 09:09:48 auth(default): Error:
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Outstanding Requests:
Nov 01 09:09:48 auth(default): Error:  * msgid 3,  origid 3, status
InProgress
Nov 01 09:09:48 auth(default): Error:    outstanding referrals 0, parent
count 0
Nov 01 09:09:48 auth(default): Error:   ld 0x18611700 request count 1
(abandoned 0)
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Response Queue:
Nov 01 09:09:48 auth(default): Error:    Empty
Nov 01 09:09:48 auth(default): Error:   ld 0x18611700 response count 0
Nov 01 09:09:48 auth(default): Error: ldap_chkResponseList ld 0x18611700
msgid 3 all 1
Nov 01 09:09:48 auth(default): Error: ldap_chkResponseList returns ld
0x18611700 NULL
Nov 01 09:09:48 auth(default): Error: ldap_int_select
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 msgid 3 all 1
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 msgid 3
message type bind
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 0 new
referrals
Nov 01 09:09:48 auth(default): Error: read1msg:  mark request completed, ld
0x18611700 msgid 3
Nov 01 09:09:48 auth(default): Error: request done: ld 0x18611700 msgid 3
Nov 01 09:09:48 auth(default): Error: res_errno: 14, res_error: <>,
res_matched: <>
Nov 01 09:09:48 auth(default): Error: ldap_free_request (origid 3, msgid 3)
Nov 01 09:09:48 auth(default): Error: ldap_int_sasl_bind: <null>
Nov 01 09:09:48 auth(default): Error: ldap_parse_sasl_bind_result
Nov 01 09:09:48 auth(default): Error: ldap_parse_result
Nov 01 09:09:48 auth(default): Error: sasl_client_step: 0
Nov 01 09:09:48 auth(default): Error: ldap_sasl_bind
Nov 01 09:09:48 auth(default): Error: ldap_send_initial_request
Nov 01 09:09:48 auth(default): Error: ldap_send_server_request
Nov 01 09:09:48 auth(default): Error: ldap_msgfree
Nov 01 09:09:48 auth(default): Error: ldap_result ld 0x18611700 msgid 4
Nov 01 09:09:48 auth(default): Error: wait4msg ld 0x18611700 msgid 4
(infinite timeout)
Nov 01 09:09:48 auth(default): Error: wait4msg continue ld 0x18611700 msgid
4 all 1
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Connections:
Nov 01 09:09:48 auth(default): Error: * host: 192.168.0.240  port: 3268
(default)
Nov 01 09:09:48 auth(default): Error:   refcnt: 2  status: Connected
Nov 01 09:09:48 auth(default): Error:   last used: Tue Nov  1 09:09:48 2011
Nov 01 09:09:48 auth(default): Error:
Nov 01 09:09:48 auth(default): Error:
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Outstanding Requests:
Nov 01 09:09:48 auth(default): Error:  * msgid 4,  origid 4, status
InProgress
Nov 01 09:09:48 auth(default): Error:    outstanding referrals 0, parent
count 0
Nov 01 09:09:48 auth(default): Error:   ld 0x18611700 request count 1
(abandoned 0)
Nov 01 09:09:48 auth(default): Error: ** ld 0x18611700 Response Queue:
Nov 01 09:09:48 auth(default): Error:    Empty
Nov 01 09:09:48 auth(default): Error:   ld 0x18611700 response count 0
Nov 01 09:09:48 auth(default): Error: ldap_chkResponseList ld 0x18611700
msgid 4 all 1
Nov 01 09:09:48 auth(default): Error: ldap_chkResponseList returns ld
0x18611700 NULL
Nov 01 09:09:48 auth(default): Error: ldap_int_select
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 msgid 4 all 1
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 msgid 4
message type bind
Nov 01 09:09:48 auth(default): Error: read1msg: ld 0x18611700 0 new
referrals
Nov 01 09:09:48 auth(default): Error: read1msg:  mark request completed, ld
0x18611700 msgid 4
Nov 01 09:09:48 auth(default): Error: request done: ld 0x18611700 msgid 4
Nov 01 09:09:48 auth(default): Error: res_errno: 0, res_error: <>,
res_matched: <>
Nov 01 09:09:48 auth(default): Error: ldap_free_request (origid 4, msgid 4)
Nov 01 09:09:48 auth(default): Error: ldap_int_sasl_bind: <null>
Nov 01 09:09:48 auth(default): Error: ldap_parse_sasl_bind_result
Nov 01 09:09:48 auth(default): Error: ldap_parse_result
Nov 01 09:09:48 auth(default): Error: ldap_pvt_sasl_generic_install
Nov 01 09:09:48 auth(default): Error: ldap_msgfree
Nov 01 09:10:13 auth(default): Error: ldap_search
Nov 01 09:10:13 auth(default): Error: put_filter:
"(&(objectClass=person)(sAMAccountName=davidv))"
Nov 01 09:10:13 auth(default): Error: put_filter: AND
Nov 01 09:10:13 auth(default): Error: put_filter_list
"(objectClass=person)(sAMAccountName=davidv)"
Nov 01 09:10:13 auth(default): Error: put_filter:
"(objectClass=person)"
Nov 01 09:10:13 auth(default): Error: put_filter: simple
Nov 01 09:10:13 auth(default): Error: put_simple_filter:
"objectClass=person"
Nov 01 09:10:13 auth(default): Error: put_filter:
"(sAMAccountName=davidv)"
Nov 01 09:10:13 auth(default): Error: put_filter: simple
Nov 01 09:10:13 auth(default): Error: put_simple_filter:
"sAMAccountName=davidv"
Nov 01 09:10:13 auth(default): Error: ldap_build_search_req ATTRS: mail
Nov 01 09:10:13 auth(default): Error: ldap_send_initial_request
Nov 01 09:10:13 auth(default): Error: ldap_send_server_request
Nov 01 09:10:13 auth(default): Error: ldap_result ld 0x18611700 msgid -1
Nov 01 09:10:13 auth(default): Error: wait4msg ld 0x18611700 msgid -1
(timeout 0 usec)
Nov 01 09:10:13 auth(default): Error: wait4msg continue ld 0x18611700 msgid
-1 all 1
Nov 01 09:10:13 auth(default): Error: ** ld 0x18611700 Connections:
Nov 01 09:10:13 auth(default): Error: * host: 192.168.0.240  port: 3268
(default)
Nov 01 09:10:13 auth(default): Error:   refcnt: 2  status: Connected
Nov 01 09:10:13 auth(default): Error:   last used: Tue Nov  1 09:10:13 2011
Nov 01 09:10:13 auth(default): Error:
Nov 01 09:10:13 auth(default): Error:
Nov 01 09:10:13 auth(default): Error: ** ld 0x18611700 Outstanding Requests:
Nov 01 09:10:13 auth(default): Error:  * msgid 5,  origid 5, status
InProgress
Nov 01 09:10:13 auth(default): Error:    outstanding referrals 0, parent
count 0
Nov 01 09:10:13 auth(default): Error:   ld 0x18611700 request count 1
(abandoned 0)
Nov 01 09:10:13 auth(default): Error: ** ld 0x18611700 Response Queue:
Nov 01 09:10:13 auth(default): Error:    Empty
Nov 01 09:10:13 auth(default): Error:   ld 0x18611700 response count 0
Nov 01 09:10:13 auth(default): Error: ldap_chkResponseList ld 0x18611700
msgid -1 all 1
Nov 01 09:10:13 auth(default): Error: ldap_chkResponseList returns ld
0x18611700 NULL
Nov 01 09:10:13 auth(default): Error: ldap_int_select
Nov 01 09:10:13 auth(default): Error: read1msg: ld 0x18611700 msgid -1 all 1
Nov 01 09:10:13 auth(default): Error: read1msg: ld 0x18611700 msgid 5
message type search-entry
Nov 01 09:10:13 auth(default): Error: read1msg: ld 0x18611700 msgid 5
message type search-result
Nov 01 09:10:13 auth(default): Error: read1msg: ld 0x18611700 0 new
referrals
Nov 01 09:10:13 auth(default): Error: read1msg:  mark request completed, ld
0x18611700 msgid 5
Nov 01 09:10:13 auth(default): Error: request done: ld 0x18611700 msgid 5
Nov 01 09:10:13 auth(default): Error: res_errno: 0, res_error: <>,
res_matched: <>
Nov 01 09:10:13 auth(default): Error: ldap_free_request (origid 5, msgid 5)
Nov 01 09:10:13 auth(default): Error: adding response ld 0x18611700 msgid 5
type 101:
Nov 01 09:10:13 auth(default): Error: ldap_parse_result
Nov 01 09:10:13 auth(default): Error: ldap_first_attribute
Nov 01 09:10:13 auth(default): Error: ldap_get_values
Nov 01 09:10:13 auth(default): Error: ldap_next_attribute
Nov 01 09:10:13 auth(default): Error: ldap_msgfree
Nov 01 09:10:13 auth(default): Error: ldap_result ld 0x18611700 msgid -1
Nov 01 09:10:13 auth(default): Error: wait4msg ld 0x18611700 msgid -1
(timeout 0 usec)
Nov 01 09:10:13 auth(default): Error: wait4msg continue ld 0x18611700 msgid
-1 all 1
Nov 01 09:10:13 auth(default): Error: ** ld 0x18611700 Connections:
Nov 01 09:10:13 auth(default): Error: * host: 192.168.0.240  port: 3268
(default)
Nov 01 09:10:13 auth(default): Error:   refcnt: 1  status: Connected
Nov 01 09:10:13 auth(default): Error:   last used: Tue Nov  1 09:10:13 2011
Nov 01 09:10:13 auth(default): Error:
Nov 01 09:10:13 auth(default): Error:
Nov 01 09:10:13 auth(default): Error: ** ld 0x18611700 Outstanding Requests:
Nov 01 09:10:13 auth(default): Error:    Empty
Nov 01 09:10:13 auth(default): Error:   ld 0x18611700 request count 0
(abandoned 0)
Nov 01 09:10:13 auth(default): Error: ** ld 0x18611700 Response Queue:
Nov 01 09:10:13 auth(default): Error:    Empty
Nov 01 09:10:13 auth(default): Error:   ld 0x18611700 response count 0
Nov 01 09:10:13 auth(default): Error: ldap_chkResponseList ld 0x18611700
msgid -1 all 1
Nov 01 09:10:13 auth(default): Error: ldap_chkResponseList returns ld
0x18611700 NULL
Nov 01 09:10:13 auth(default): Error: ldap_int_select
Nov 01 09:13:26 auth(default): Error: ldap_search
Nov 01 09:13:26 auth(default): Error: put_filter:
"(&(objectClass=person)(sAMAccountName=davidv))"
Nov 01 09:13:26 auth(default): Error: put_filter: AND
Nov 01 09:13:26 auth(default): Error: put_filter_list
"(objectClass=person)(sAMAccountName=davidv)"
Nov 01 09:13:26 auth(default): Error: put_filter:
"(objectClass=person)"
Nov 01 09:13:26 auth(default): Error: put_filter: simple
Nov 01 09:13:26 auth(default): Error: put_simple_filter:
"objectClass=person"
Nov 01 09:13:26 auth(default): Error: put_filter:
"(sAMAccountName=davidv)"
Nov 01 09:13:26 auth(default): Error: put_filter: simple
Nov 01 09:13:26 auth(default): Error: put_simple_filter:
"sAMAccountName=davidv"
Nov 01 09:13:26 auth(default): Error: ldap_build_search_req ATTRS: mail
Nov 01 09:13:26 auth(default): Error: ldap_send_initial_request
Nov 01 09:13:26 auth(default): Error: ldap_send_server_request
Nov 01 09:13:26 auth(default): Error: ldap_result ld 0x18611700 msgid -1
Nov 01 09:13:26 auth(default): Error: wait4msg ld 0x18611700 msgid -1
(timeout 0 usec)
Nov 01 09:13:26 auth(default): Error: wait4msg continue ld 0x18611700 msgid
-1 all 1
Nov 01 09:13:26 auth(default): Error: ** ld 0x18611700 Connections:
Nov 01 09:13:26 auth(default): Error: * host: 192.168.0.240  port: 3268
(default)
Nov 01 09:13:26 auth(default): Error:   refcnt: 2  status: Connected
Nov 01 09:13:26 auth(default): Error:   last used: Tue Nov  1 09:13:26 2011
Nov 01 09:13:26 auth(default): Error:
Nov 01 09:13:26 auth(default): Error:
Nov 01 09:13:26 auth(default): Error: ** ld 0x18611700 Outstanding Requests:
Nov 01 09:13:26 auth(default): Error:  * msgid 6,  origid 6, status
InProgress
Nov 01 09:13:26 auth(default): Error:    outstanding referrals 0, parent
count 0
Nov 01 09:13:26 auth(default): Error:   ld 0x18611700 request count 1
(abandoned 0)
Nov 01 09:13:26 auth(default): Error: ** ld 0x18611700 Response Queue:
Nov 01 09:13:26 auth(default): Error:    Empty
Nov 01 09:13:26 auth(default): Error:   ld 0x18611700 response count 0
Nov 01 09:13:26 auth(default): Error: ldap_chkResponseList ld 0x18611700
msgid -1 all 1
Nov 01 09:13:26 auth(default): Error: ldap_chkResponseList returns ld
0x18611700 NULL
Nov 01 09:13:26 auth(default): Error: ldap_int_select
Nov 01 09:13:26 auth(default): Error: read1msg: ld 0x18611700 msgid -1 all 1
Nov 01 09:13:26 auth(default): Error: read1msg: ld 0x18611700 msgid 6
message type search-entry
Nov 01 09:13:26 auth(default): Error: read1msg: ld 0x18611700 msgid 6
message type search-result
Nov 01 09:13:26 auth(default): Error: read1msg: ld 0x18611700 0 new
referrals
Nov 01 09:13:26 auth(default): Error: read1msg:  mark request completed, ld
0x18611700 msgid 6
Nov 01 09:13:26 auth(default): Error: request done: ld 0x18611700 msgid 6
Nov 01 09:13:26 auth(default): Error: res_errno: 0, res_error: <>,
res_matched: <>
Nov 01 09:13:26 auth(default): Error: ldap_free_request (origid 6, msgid 6)
Nov 01 09:13:26 auth(default): Error: adding response ld 0x18611700 msgid 6
type 101:
Nov 01 09:13:26 auth(default): Error: ldap_parse_result
Nov 01 09:13:26 auth(default): Error: ldap_first_attribute
Nov 01 09:13:26 auth(default): Error: ldap_get_values
Nov 01 09:13:26 auth(default): Error: ldap_next_attribute
Nov 01 09:13:26 auth(default): Error: ldap_msgfree
Nov 01 09:13:26 auth(default): Error: ldap_result ld 0x18611700 msgid -1
Nov 01 09:13:26 auth(default): Error: wait4msg ld 0x18611700 msgid -1
(timeout 0 usec)
Nov 01 09:13:26 auth(default): Error: wait4msg continue ld 0x18611700 msgid
-1 all 1
Nov 01 09:13:26 auth(default): Error: ** ld 0x18611700 Connections:
Nov 01 09:13:26 auth(default): Error: * host: 192.168.0.240  port: 3268
(default)
Nov 01 09:13:26 auth(default): Error:   refcnt: 1  status: Connected
Nov 01 09:13:26 auth(default): Error:   last used: Tue Nov  1 09:13:26 2011
Nov 01 09:13:26 auth(default): Error:
Nov 01 09:13:26 auth(default): Error:
Nov 01 09:13:26 auth(default): Error: ** ld 0x18611700 Outstanding Requests:
Nov 01 09:13:26 auth(default): Error:    Empty
Nov 01 09:13:26 auth(default): Error:   ld 0x18611700 request count 0
(abandoned 0)
Nov 01 09:13:26 auth(default): Error: ** ld 0x18611700 Response Queue:
Nov 01 09:13:26 auth(default): Error:    Empty
Nov 01 09:13:26 auth(default): Error:   ld 0x18611700 response count 0
Nov 01 09:13:26 auth(default): Error: ldap_chkResponseList ld 0x18611700
msgid -1 all 1
Nov 01 09:13:26 auth(default): Error: ldap_chkResponseList returns ld
0x18611700 NULL
Nov 01 09:13:26 auth(default): Error: ldap_int_select
dovecot_info.log

Nov 01 09:09:48 dovecot: Info: Dovecot v1.2.17 starting up
Nov 01 09:09:49 auth(default): Info: new auth connection: pid=99773
Nov 01 09:09:49 auth(default): Info: new auth connection: pid=99774
Nov 01 09:09:49 auth(default): Info: new auth connection: pid=99775
Nov 01 09:09:49 auth(default): Info: new auth connection: pid=99776
Nov 01 09:09:49 auth(default): Info: new auth connection: pid=99777
Nov 01 09:09:49 auth(default): Info: new auth connection: pid=99778
Nov 01 09:10:09 auth(default): Info: new auth connection: pid=99782
Nov 01 09:10:13 auth(default): Info: client in:
AUTH 1 PLAIN service=imap secured lip=127.0.0.1 rip=127.0.0.1
lport=993 rport=55010 resp=AGRhdmlkdgBlbGkqNDJ0dW4Nov 01 09:10:13 auth(default):
Info: ldap(davidv,127.0.0.1): pass search:
base=dc=smallmountain,dc=Local scope=subtree
filter=(&(objectClass=person)(sAMAccountName=davidv)) fields=mail
Nov 01 09:10:13 auth(default): Info: auth(davidv,127.0.0.1): username
changed davidv -> davidv at smallmountain.net
Nov 01 09:10:13 auth(default): Info: ldap(davidv at
smallmountain.net,127.0.0.1):
result: mail(user)=davidv at smallmountain.net
Nov 01 09:10:13 auth(default): Info: ldap(davidv at
smallmountain.net,127.0.0.1):
No password returned (and no nopassword)
Nov 01 09:10:15 auth(default): Info: client out: FAIL 1
user=davidv at smallmountain.net
Nov 01 09:13:13 imap-login: Info: Disconnected: Inactivity (auth failed, 1
attempts): user=<davidv at smallmountain.net>, method=PLAIN,
rip=127.0.0.1,
lip=127.0.0.1, TLS
Nov 01 09:13:21 auth(default): Info: new auth connection: pid=99797
Nov 01 09:13:26 auth(default): Info: client in:
AUTH 1 PLAIN service=imap secured lip=127.0.0.1 rip=127.0.0.1
lport=993 rport=61080 resp=AGRhdmlkdgBlbGkqNDJ0dW4Nov 01 09:13:26 auth(default):
Info: ldap(davidv,127.0.0.1): pass search:
base=dc=smallmountain,dc=Local scope=subtree
filter=(&(objectClass=person)(sAMAccountName=davidv)) fields=mail
Nov 01 09:13:26 auth(default): Info: auth(davidv,127.0.0.1): username
changed davidv -> davidv at smallmountain.net
Nov 01 09:13:26 auth(default): Info: ldap(davidv at
smallmountain.net,127.0.0.1):
result: mail(user)=davidv at smallmountain.net
Nov 01 09:13:26 auth(default): Info: ldap(davidv at
smallmountain.net,127.0.0.1):
No password returned (and no nopassword)
Nov 01 09:13:28 auth(default): Info: client out: FAIL 1
user=davidv at smallmountain.net
Nov 01 09:13:36 imap-login: Info: Aborted login (auth failed, 1 attempts):
user=<davidv at smallmountain.net>, method=PLAIN, rip=127.0.0.1,
lip=127.0.0.1, TLS
Your assistance is greatly appreciated,

David

Timo Sirainen

2011-Nov-04 20:38 UTC

head link

[Dovecot] LDAP w/SASL "Active Directory" authentication failing.

On Tue, 2011-11-01 at 09:55 -0600, David Varela wrote:
> I am running a Dovecot server (version 1.2.17) on FreeBSD 8.2, using
> LDAP to authenticate Active Directory users.  I can successfully bind and
> authenticate using PLAIN and LDAP without SASL, but obviously passwords for
> the bind user and the user being authenticated are being passed in plain
> text.  I've attempted to configure my server to us SASL however when I
> attempt to authenticate a user I see authentication failures.  I reviewed
> the security log on my domain controller and see that the bind user is
> binding properly, so the issue appears to be orginating from the user
> authentication, however I cannot determine what the issue is.  Here is all
> the information regarding my configuration, along with the logs from the
> server:
SASL binding currently works only for the initial "ldap admin user"
authentication. It doesn't work for individual user authentication
requests (auth_bind=yes).
> #auth_bind = yes
Here you're not even attempting to use auth binds.
> pass_attrs = mail=user
And you're also not returning a password for user.
> Nov 01 09:13:26 auth(default): Info: ldap(davidv at
smallmountain.net,127.0.0.1):
> No password returned (and no nopassword)
So Dovecot has no way of authenticating user.

I'd suggest forgetting about SASL and enabling TLS instead.

Possibly Parallel Threads

Search for more reasonably related threads

dovecot - Nov 2011 - LDAP w/SASL "Active Directory" authentication failing.

[Dovecot] LDAP w/SASL "Active Directory" authentication failing.

[Dovecot] LDAP w/SASL "Active Directory" authentication failing.

Possibly Parallel Threads