[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=AGRhdmlkdgBlbGkqNDJ0dW4= Nov 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@smallmountain.net Nov 01 09:10:13 auth(default): Info: ldap(davidv@smallmountain.net,127.0.0.1): result: mail(user)=davidv@smallmountain.net Nov 01 09:10:13 auth(default): Info: ldap(davidv@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@smallmountain.net Nov 01 09:13:13 imap-login: Info: Disconnected: Inactivity (auth failed, 1 attempts): user=davidv@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=AGRhdmlkdgBlbGkqNDJ0dW4= Nov 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@smallmountain.net Nov 01 09:13:26 auth(default): Info: ldap(davidv@smallmountain.net,127.0.0.1): result: mail(user)=davidv@smallmountain.net Nov 01 09:13:26 auth(default): Info: ldap(davidv@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@smallmountain.net Nov 01 09:13:36 imap-login: Info: Aborted login (auth failed, 1 attempts): user=davidv@smallmountain.net, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, TLS Your assistance is greatly appreciated,
David
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@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.
participants (2)
-
David Varela
-
Timo Sirainen