[Date Prev][Date Next] [Chronological] [Thread] [Top]
2.1.23 w/ StartTLS not authenticating Courier-IMAP

To: openldap-software@OpenLDAP.org
Subject: 2.1.23 w/ StartTLS not authenticating Courier-IMAP
From: Adam Theo <adamtheo@new.theoretic.com>
Date: Fri, 2 Jan 2004 04:53:34 +0000
Content-disposition: inline
User-agent: Mutt/1.5.4i
Hello, all.

I have set up a Postfix + LDAP/StartTLS + Courier-IMAP system. I am 
attempting to test the connection by using an IMAP client. However, it 
is returning a "wrong username/password" error, which is odd, since I 
can bind fine to this account fine using ldapsearch.

Unfortunately, I can't make heads or tails of any of this. It seems like slapd is 
rejecting the login for "uid=imapd,ou=services,dc=theoretic" for some reason, looks like a 
TLS error, but can't understand why.

My setup: OpenLDAP 2.1.23 on tcp/389 with non-TLS and StartTLS enabled. I have the slapd 
ACL's set to restrict all reading to authenticated users, so I have given each service 
that will use LDAP an account with password to bind with in order to validate users. I 
have Courier-IMAP set up using "uid=imapd,ou=services,dc=theoretic", with a password which 
works using ldapsearch. I am trying to log into user "adamtheo", which is dn 
"uid=adamtheo,ou=persons,dc=theoretic". This password for this account works using 
ldapsearch, as well.

I'm really hoping for any help here. Please let me know what files or othger info I can 
give to help this effort.

Here are the logs from openldap's slapd:

Dec 30 15:46:17 new slapd[2295]: daemon: activity on 1 descriptors
Dec 30 15:46:17 new slapd[2295]: daemon: new connection on 20
Dec 30 15:46:17 new slapd[2295]: daemon: added 20r
Dec 30 15:46:17 new slapd[2295]: daemon: activity on:
Dec 30 15:46:17 new slapd[2295]:
Dec 30 15:46:17 new slapd[2295]: daemon: select: listen=6 active_threads=0 tvp=NULL
Dec 30 15:46:17 new slapd[2295]: daemon: activity on 1 descriptors
Dec 30 15:46:17 new slapd[2295]: daemon: activity on:
Dec 30 15:46:17 new slapd[2295]:  20r
Dec 30 15:46:17 new slapd[2295]:
Dec 30 15:46:17 new slapd[2295]: daemon: read activity on 20
Dec 30 15:46:17 new slapd[2295]: connection_get(20)
Dec 30 15:46:17 new slapd[2295]: connection_get(20): got connid=803
Dec 30 15:46:17 new slapd[2295]: connection_read(20): checking for input on id=803
Dec 30 15:46:17 new slapd[2345]: do_extended
Dec 30 15:46:17 new slapd[2345]: do_extended: oid=1.3.6.1.4.1.1466.20037
Dec 30 15:46:17 new slapd[2295]: ber_get_next on fd 20 failed errno=11 (Resource 
temporarily unav$
Dec 30 15:46:17 new slapd[2345]: send_ldap_extended: err=0 oid= len=0
Dec 30 15:46:17 new slapd[2345]: send_ldap_response: msgid=1 tag=120 err=0
Dec 30 15:46:17 new slapd[2295]: daemon: select: listen=6 active_threads=0 tvp=NULL
Dec 30 15:46:17 new slapd[2295]: daemon: activity on 1 descriptors
Dec 30 15:46:17 new slapd[2295]: daemon: activity on:
Dec 30 15:46:17 new slapd[2295]:  20r
Dec 30 15:46:17 new slapd[2295]:
Dec 30 15:46:17 new slapd[2295]: daemon: read activity on 20
Dec 30 15:46:17 new slapd[2295]: connection_get(20)
Dec 30 15:46:17 new slapd[2295]: connection_get(20): got connid=803
Dec 30 15:46:17 new slapd[2295]: connection_read(20): checking for input on id=803
Dec 30 15:46:17 new slapd[2295]: connection_read(20): unable to get TLS client DN error=49 
id=803
Dec 30 15:46:17 new slapd[2295]: daemon: select: listen=6 active_threads=0 tvp=NULL
Dec 30 15:46:17 new slapd[2295]: daemon: activity on 1 descriptors
Dec 30 15:46:17 new slapd[2295]: daemon: activity on:
Dec 30 15:46:17 new slapd[2295]:  20r
Dec 30 15:46:17 new slapd[2295]:
Dec 30 15:46:17 new slapd[2295]: daemon: read activity on 20
Dec 30 15:46:17 new slapd[2295]: connection_get(20)
Dec 30 15:46:17 new slapd[2295]: connection_get(20): got connid=803
Dec 30 15:46:17 new slapd[2295]: connection_read(20): checking for input on id=803
Dec 30 15:46:17 new slapd[2624]: do_bind
Dec 30 15:46:17 new slapd[2295]: ber_get_next on fd 20 failed errno=11 (Resource 
temporarily unav$
Dec 30 15:46:17 new slapd[2624]: >>> dnPrettyNormal: <uid=imapd,ou=services,dc=theoretic>
Dec 30 15:46:17 new slapd[2624]: <<< dnPrettyNormal: <uid=imapd,ou=services,dc=theoretic>, 
<uid=i$
Dec 30 15:46:17 new slapd[2624]: do_bind: version=3 
dn="uid=imapd,ou=services,dc=theoretic" metho$

............ <<cut>>.................

Dec 30 15:46:17 new slapd[2354]: ====> cache_find_entry_id( 3 ) "ou=persons,dc=theoretic" 
(found) (1 tries)
Dec 30 15:46:17 new slapd[2354]: <= id2entry_r( 3 ) 0x816fa70 (cache)
Dec 30 15:46:17 new slapd[2354]: => test_filter
Dec 30 15:46:17 new slapd[2354]:     EQUALITY
Dec 30 15:46:17 new slapd[2354]: => access_allowed: search access to 
"ou=persons,dc=theoretic" "mail" requested
Dec 30 15:46:17 new slapd[2354]: => acl_get: [1] check attr mail
Dec 30 15:46:17 new slapd[2354]: => dn: [2] ou=persons,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => acl_get: [2] matched
Dec 30 15:46:17 new slapd[2354]: => acl_get: [2] check attr mail
Dec 30 15:46:17 new slapd[2354]: <= acl_get: [2] acl ou=persons,dc=theoretic attr: mail
Dec 30 15:46:17 new slapd[2354]: => acl_mask: access to entry "ou=persons,dc=theoretic", 
attr "mail" requested
Dec 30 15:46:17 new slapd[2354]: => acl_mask: to value by 
"uid=imapd,ou=services,dc=theoretic", (=n)
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: 
uid=webregister,ou=services,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => string_expand: pattern:  
uid=webregister,ou=services,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => string_expand: expanded: 
uid=webregister,ou=services,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => regex_matches: string:       
uid=imapd,ou=services,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => regex_matches: rc: 1 no matches
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: anonymous
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: users
Dec 30 15:46:17 new slapd[2354]: <= acl_mask: [3] applying read(=rscx) (stop)
Dec 30 15:46:17 new slapd[2354]: <= acl_mask: [3] mask: read(=rscx)
Dec 30 15:46:17 new slapd[2354]: => access_allowed: search access granted by read(=rscx)
Dec 30 15:46:17 new slapd[2354]: <= test_filter 5
Dec 30 15:46:17 new slapd[2354]: ldbm_search: candidate entry 3 does not match filter
Dec 30 15:46:17 new slapd[2354]: ====> cache_return_entry_r( 3 ): returned (0)
Dec 30 15:46:17 new slapd[2354]: => id2entry_r( 11 )
Dec 30 15:46:17 new slapd[2354]: ====> cache_find_entry_id( 11 ) 
"uid=adamtheo,ou=persons,dc=theoretic" (found) (1 tries)
Dec 30 15:46:17 new slapd[2354]: <= id2entry_r( 11 ) 0x816f5c0 (cache)
Dec 30 15:46:17 new slapd[2354]: => test_filter
Dec 30 15:46:17 new slapd[2354]:     EQUALITY
Dec 30 15:46:17 new slapd[2354]: => access_allowed: search access to 
"uid=adamtheo,ou=persons,dc=theoretic" "mail" requested
Dec 30 15:46:17 new slapd[2354]: => acl_get: [1] check attr mail
Dec 30 15:46:17 new slapd[2354]: => dn: [2] ou=persons,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => dn: [3] ou=persons,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => acl_get: [3] matched
Dec 30 15:46:17 new slapd[2354]: => acl_get: [3] check attr mail
Dec 30 15:46:17 new slapd[2354]: <= acl_get: [3] acl uid=adamtheo,ou=persons,dc=theoretic 
attr: mail
Dec 30 15:46:17 new slapd[2354]: => acl_mask: access to entry 
"uid=adamtheo,ou=persons,dc=theoretic", attr "mail" requested
Dec 30 15:46:17 new slapd[2354]: => acl_mask: to value by 
"uid=imapd,ou=services,dc=theoretic", (=n)
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: 
uid=webregister,ou=services,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: anonymous
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: users
Dec 30 15:46:17 new slapd[2354]: <= acl_mask: [3] applying read(=rscx) (stop)
Dec 30 15:46:17 new slapd[2354]: <= acl_mask: [3] mask: read(=rscx)
Dec 30 15:46:17 new slapd[2354]: => access_allowed: search access granted by read(=rscx)
Dec 30 15:46:17 new slapd[2354]: <= test_filter 5
Dec 30 15:46:17 new slapd[2354]: ldbm_search: candidate entry 11 does not match filter
Dec 30 15:46:17 new slapd[2354]: ====> cache_return_entry_r( 11 ): returned (0)
Dec 30 15:46:17 new slapd[2295]: ber_get_next on fd 20 failed errno=11 (Resource 
temporarily unavailable)
Dec 30 15:46:17 new slapd[2354]: => id2entry_r( 12 )
Dec 30 15:46:17 new slapd[2354]: ====> cache_find_entry_id( 12 ) 
"uid=mike,ou=persons,dc=theoretic" (found) (1 tries)
Dec 30 15:46:17 new slapd[2354]: <= id2entry_r( 12 ) 0x81d4cc0 (cache)
Dec 30 15:46:17 new slapd[2354]: => test_filter
Dec 30 15:46:17 new slapd[2354]:     EQUALITY
Dec 30 15:46:17 new slapd[2354]: => access_allowed: search access to 
"uid=mike,ou=persons,dc=theoretic" "mail" requested
Dec 30 15:46:17 new slapd[2354]: => acl_get: [1] check attr mail
Dec 30 15:46:17 new slapd[2354]: => dn: [2] ou=persons,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => dn: [3] ou=persons,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => acl_get: [3] matched
Dec 30 15:46:17 new slapd[2354]: => acl_get: [3] check attr mail
Dec 30 15:46:17 new slapd[2354]: <= acl_get: [3] acl uid=mike,ou=persons,dc=theoretic 
attr: mail
Dec 30 15:46:17 new slapd[2354]: => acl_mask: access to entry 
"uid=mike,ou=persons,dc=theoretic", attr "mail" requested
Dec 30 15:46:17 new slapd[2354]: => acl_mask: to value by 
"uid=imapd,ou=services,dc=theoretic", (=n)
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: 
uid=webregister,ou=services,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: anonymous
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: users
Dec 30 15:46:17 new slapd[2354]: <= acl_mask: [3] applying read(=rscx) (stop)
Dec 30 15:46:17 new slapd[2354]: <= acl_mask: [3] mask: read(=rscx)
Dec 30 15:46:17 new slapd[2354]: => access_allowed: search access granted by read(=rscx)
Dec 30 15:46:17 new slapd[2354]: <= test_filter 5
Dec 30 15:46:17 new slapd[2354]: ldbm_search: candidate entry 12 does not match filter
Dec 30 15:46:17 new slapd[2354]: ====> cache_return_entry_r( 12 ): returned (0)
Dec 30 15:46:17 new slapd[2295]: daemon: select: listen=6 active_threads=1 tvp=NULL
Dec 30 15:46:17 new slapd[2295]: daemon: activity on 1 descriptors
Dec 30 15:46:17 new slapd[2295]: daemon: select: listen=6 active_threads=1 tvp=NULL
Dec 30 15:46:17 new slapd[2354]: => id2entry_r( 13 )
Dec 30 15:46:17 new slapd[2354]: ====> cache_find_entry_id( 13 ) 
"uid=reatmon,ou=persons,dc=theoretic" (found) (1 tries)
Dec 30 15:46:17 new slapd[2354]: <= id2entry_r( 13 ) 0x81d52b0 (cache)
Dec 30 15:46:17 new slapd[2354]: => test_filter
Dec 30 15:46:17 new slapd[2354]:     EQUALITY
Dec 30 15:46:17 new slapd[2354]: => access_allowed: search access to 
"uid=reatmon,ou=persons,dc=theoretic" "mail" requested
Dec 30 15:46:17 new slapd[2354]: => acl_get: [1] check attr mail
Dec 30 15:46:17 new slapd[2354]: => dn: [2] ou=persons,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => dn: [3] ou=persons,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: => acl_get: [3] matched
Dec 30 15:46:17 new slapd[2354]: => acl_get: [3] check attr mail
Dec 30 15:46:17 new slapd[2354]: <= acl_get: [3] acl uid=reatmon,ou=persons,dc=theoretic 
attr: mail
Dec 30 15:46:17 new slapd[2354]: => acl_mask: access to entry 
"uid=reatmon,ou=persons,dc=theoretic", attr "mail" requested
Dec 30 15:46:17 new slapd[2354]: => acl_mask: to value by 
"uid=imapd,ou=services,dc=theoretic", (=n)
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: 
uid=webregister,ou=services,dc=theoretic
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: anonymous
Dec 30 15:46:17 new slapd[2354]: <= check a_dn_pat: users
Dec 30 15:46:17 new slapd[2354]: <= acl_mask: [3] applying read(=rscx) (stop)
Dec 30 15:46:17 new slapd[2354]: <= acl_mask: [3] mask: read(=rscx)
Dec 30 15:46:17 new slapd[2354]: => access_allowed: search access granted by read(=rscx)
Dec 30 15:46:17 new slapd[2354]: <= test_filter 5
Dec 30 15:46:17 new slapd[2354]: ldbm_search: candidate entry 13 does not match filter
Dec 30 15:46:17 new slapd[2354]: ====> cache_return_entry_r( 13 ): returned (0)
Dec 30 15:46:17 new slapd[2354]: send_search_result: err=0 matched="" text=""
Dec 30 15:46:17 new slapd[2354]: send_ldap_response: msgid=3 tag=101 err=0

And here is the debug from authdaemond.ldap and the rest of the courier-imap programs

Dec 30 15:46:17 new imapd: Connection, ip=[::ffff:209.16.240.20]
Dec 30 15:46:17 new imapd: LOGIN: DEBUG: ip=[::ffff:209.16.240.20], command=CAPABILITY
Dec 30 15:46:17 new imapd: LOGIN: DEBUG: ip=[::ffff:209.16.240.20], command=LOGIN
Dec 30 15:46:17 new imapd: LOGIN: DEBUG: ip=[::ffff:209.16.240.20], username=adamtheo
Dec 30 15:46:23 new imapd: LOGIN FAILED, ip=[::ffff:209.16.240.20]
Dec 30 15:46:28 new imapd: DISCONNECTED, ip=[::ffff:209.16.240.20], headers=0, body=0
Follow-Ups:
- Re: 2.1.23 w/ StartTLS not authenticating Courier-IMAP
  - From: Tony Earnshaw <tonye@billy.demon.nl>
Prev by Date: Re: SASL External Mechanism
Next by Date: Re: can slapcat dump dbb file which size larger than 9G?
Index(es):
- Chronological
- Thread