[Date Prev][Date Next]
[Chronological]
[Thread]
[Top]
2.1.23 w/ StartTLS not authenticating Courier-IMAP
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