[KLUG Members] debug ldap failure

Richard Harding members@kalamazoolinux.org
Tue, 16 Dec 2003 10:28:08 -0500
Previous message: [KLUG Members] debug ldap failure
Next message: [KLUG Members] debug ldap failure
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]
Richard Harding wrote:
> 
>>> I am finding that I am not getting the search results I expect 
>>> however. For some reason if I just list out the database I can see 
>>> the user and the attribute mail (that is being search on) is there 
>>> and valid. However when I perform a specific search on that mail 
>>> attibute it comes up empty. I even tried searching on the uid value 
>>> and still get no results. Any idea as to why my searches are coming 
>>> up empty?
>>> host:ldapsearch -a never -b "dc=home,dc=ricksweb,dc=info" -h 
>>> localhost -x
>>> <---snip--->
>>> # rharding, home.ricksweb.info
>>> dn: uid=rharding,dc=home,dc=ricksweb,dc=info
>>>   
>>
>> ...
>>  
>>
>>> mail: rharding
>>>   
>>
>> ...
>>
>> Do you have any indexes declared on the mail attribute?
>>  
>>
> Yes, I have this line in the conf:
> index           objectClass eq
> index           mail eq
> index           uid eq

I found part of the problem with the help of someone on the courier 
list. He suggested I try the search with "(mail=*rharding*)" and through 
that I found that because my ldif file was set up
mail: rharding instead of mail:rharding I had a space at the start of 
the field that was causing me to not match on the search.

I now seem to be getting one step closer, but the imap test 
authentication by telnetting to port 143 on localhost still fails.

Here is the latest debug info from -d255:

<= bdb_equality_candidates: id=1, first=6, last=6
<= bdb_filter_candidates: id=1 first=6 last=6
<= bdb_list_candidates: id=1 first=6 last=6
<= bdb_filter_candidates: id=1 first=6 last=6
<= bdb_list_candidates: id=1 first=6 last=6
<= bdb_filter_candidates: id=1 first=6 last=6
bdb_search_candidates: id=1 first=6 last=6
====> bdb_cache_return_entry_r( 1 ): created (0)
entry_decode: "uid=jmolidor,dc=home,dc=ricksweb,dc=info"
<= entry_decode(uid=jmolidor,dc=home,dc=ricksweb,dc=info)
=> test_filter
     EQUALITY
=> access_allowed: search access to 
"uid=jmolidor,dc=home,dc=ricksweb,dc=info" "mail" requested
=> acl_get: [1] check attr mail
=> dn: [2]
=> acl_get: [3] check attr mail
<= acl_get: [3] acl uid=jmolidor,dc=home,dc=ricksweb,dc=info attr: mail
=> acl_mask: access to entry "uid=jmolidor,dc=home,dc=ricksweb,dc=info", 
attr "mail" requested
=> acl_mask: to value by "", (=n)
<= check a_dn_pat: cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: pattern:  cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: expanded: cn=admin,dc=home,dc=ricksweb,dc=info
=> regex_matches: string:
=> regex_matches: rc: 1 no matches
<= check a_dn_pat: *
<= acl_mask: [2] applying read(=rscx) (stop)
<= acl_mask: [2] mask: read(=rscx)
=> access_allowed: search access granted by read(=rscx)
<= test_filter 6
=> send_search_entry: dn="uid=jmolidor,dc=home,dc=ricksweb,dc=info"
=> access_allowed: read access to 
"uid=jmolidor,dc=home,dc=ricksweb,dc=info" "entry" requested
=> acl_get: [1] check attr entry
=> dn: [2]
=> acl_get: [3] check attr entry
<= acl_get: [3] acl uid=jmolidor,dc=home,dc=ricksweb,dc=info attr: entry
=> acl_mask: access to entry "uid=jmolidor,dc=home,dc=ricksweb,dc=info", 
attr "entry" requested
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: pattern:  cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: expanded: cn=admin,dc=home,dc=ricksweb,dc=info
=> regex_matches: string:
=> regex_matches: rc: 1 no matches
<= check a_dn_pat: *
<= acl_mask: [2] applying read(=rscx) (stop)
<= acl_mask: [2] mask: read(=rscx)
=> access_allowed: read access granted by read(=rscx)
=> access_allowed: read access to 
"uid=jmolidor,dc=home,dc=ricksweb,dc=info" "mail" requested
=> acl_get: [1] check attr mail
=> dn: [2]
=> acl_get: [3] check attr mail
<= acl_get: [3] acl uid=jmolidor,dc=home,dc=ricksweb,dc=info attr: mail
access_allowed: no res from state (mail)
=> acl_mask: access to entry "uid=jmolidor,dc=home,dc=ricksweb,dc=info", 
attr "mail" requested
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: pattern:  cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: expanded: cn=admin,dc=home,dc=ricksweb,dc=info
=> regex_matches: string:
=> regex_matches: rc: 1 no matches
<= check a_dn_pat: *
<= acl_mask: [2] applying read(=rscx) (stop)
<= acl_mask: [2] mask: read(=rscx)
=> access_allowed: read access granted by read(=rscx)
=> access_allowed: read access to 
"uid=jmolidor,dc=home,dc=ricksweb,dc=info" "cn" requested
=> acl_get: [1] check attr cn
=> dn: [2]
=> acl_get: [3] check attr cn
<= acl_get: [3] acl uid=jmolidor,dc=home,dc=ricksweb,dc=info attr: cn
access_allowed: no res from state (cn)
=> acl_mask: access to entry "uid=jmolidor,dc=home,dc=ricksweb,dc=info", 
attr "cn" requested
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: pattern:  cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: expanded: cn=admin,dc=home,dc=ricksweb,dc=info
=> regex_matches: string:
=> regex_matches: rc: 1 no matches
<= check a_dn_pat: *
<= acl_mask: [2] applying read(=rscx) (stop)
<= acl_mask: [2] mask: read(=rscx)
=> access_allowed: read access granted by read(=rscx)
=> access_allowed: read access to 
"uid=jmolidor,dc=home,dc=ricksweb,dc=info" "uidNumber" requested
=> acl_get: [1] check attr uidNumber
=> dn: [2]
=> acl_get: [3] check attr uidNumber
<= acl_get: [3] acl uid=jmolidor,dc=home,dc=ricksweb,dc=info attr: uidNumber
access_allowed: no res from state (uidNumber)
=> acl_mask: access to entry "uid=jmolidor,dc=home,dc=ricksweb,dc=info", 
attr "uidNumber" requested
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: pattern:  cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: expanded: cn=admin,dc=home,dc=ricksweb,dc=info
=> regex_matches: string:
=> regex_matches: rc: 1 no matches
<= check a_dn_pat: *
<= acl_mask: [2] applying read(=rscx) (stop)
<= acl_mask: [2] mask: read(=rscx)
=> access_allowed: read access granted by read(=rscx)
=> access_allowed: read access to 
"uid=jmolidor,dc=home,dc=ricksweb,dc=info" "homeDirectory" requested
=> acl_get: [1] check attr homeDirectory
=> dn: [2]
=> acl_get: [3] check attr homeDirectory
<= acl_get: [3] acl uid=jmolidor,dc=home,dc=ricksweb,dc=info attr: 
homeDirectory
access_allowed: no res from state (homeDirectory)
=> acl_mask: access to entry "uid=jmolidor,dc=home,dc=ricksweb,dc=info", 
attr "homeDirectory" requested
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: pattern:  cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: expanded: cn=admin,dc=home,dc=ricksweb,dc=info
=> regex_matches: string:
=> regex_matches: rc: 1 no matches
<= check a_dn_pat: *
<= acl_mask: [2] applying read(=rscx) (stop)
<= acl_mask: [2] mask: read(=rscx)
=> access_allowed: read access granted by read(=rscx)
=> access_allowed: read access to 
"uid=jmolidor,dc=home,dc=ricksweb,dc=info" "userPassword" requested
=> acl_get: [1] check attr userPassword
<= acl_get: [1] acl uid=jmolidor,dc=home,dc=ricksweb,dc=info attr: 
userPassword
access_allowed: no res from state (userPassword)
=> acl_mask: access to entry "uid=jmolidor,dc=home,dc=ricksweb,dc=info", 
attr "userPassword" requested
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: pattern:  cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: expanded: cn=admin,dc=home,dc=ricksweb,dc=info
=> regex_matches: string:
=> regex_matches: rc: 1 no matches
<= check a_dn_pat: anonymous
<= acl_mask: [2] applying auth(=x) (stop)
<= acl_mask: [2] mask: auth(=x)
=> access_allowed: read access denied by auth(=x)
acl: access to attribute userPassword not allowed
ber_flush: 161 bytes to sd 12
   0000:  30 81 9e 02 01 02 64 81  98 04 28 75 69 64 3d 6a 0.....d...(uid=j
   0010:  6d 6f 6c 69 64 6f 72 2c  64 63 3d 68 6f 6d 65 2c molidor,dc=home,
   0020:  64 63 3d 72 69 63 6b 73  77 65 62 2c 64 63 3d 69 dc=ricksweb,dc=i
   0030:  6e 66 6f 30 6c 30 12 04  04 6d 61 69 6c 31 0a 04 nfo0l0...mail1..
   0040:  08 6a 6d 6f 6c 69 64 6f  72 30 16 04 02 63 6e 31 .jmolidor0...cn1
   0050:  10 04 0e 4a 6f 68 6e 20  42 20 4d 6f 6c 69 64 6f   ...John B 
Molido
   0060:  72 30 13 04 09 75 69 64  4e 75 6d 62 65 72 31 06 r0...uidNumber1.
   0070:  04 04 32 30 30 34 30 29  04 0d 68 6f 6d 65 44 69 ..20040)..homeDi
   0080:  72 65 63 74 6f 72 79 31  18 04 16 2f 68 6f 6d 65 rectory1.../home
   0090:  2f 63 6f 75 72 69 65 72  2f 6a 6d 6f 6c 69 64 6f /courier/jmolido
   00a0:  72                                                 r
ldap_write: want=161, written=161
   0000:  30 81 9e 02 01 02 64 81  98 04 28 75 69 64 3d 6a 0.....d...(uid=j
   0010:  6d 6f 6c 69 64 6f 72 2c  64 63 3d 68 6f 6d 65 2c molidor,dc=home,
   0020:  64 63 3d 72 69 63 6b 73  77 65 62 2c 64 63 3d 69 dc=ricksweb,dc=i
   0030:  6e 66 6f 30 6c 30 12 04  04 6d 61 69 6c 31 0a 04 nfo0l0...mail1..
   0040:  08 6a 6d 6f 6c 69 64 6f  72 30 16 04 02 63 6e 31 .jmolidor0...cn1
   0050:  10 04 0e 4a 6f 68 6e 20  42 20 4d 6f 6c 69 64 6f   ...John B 
Molido
   0060:  72 30 13 04 09 75 69 64  4e 75 6d 62 65 72 31 06 r0...uidNumber1.
   0070:  04 04 32 30 30 34 30 29  04 0d 68 6f 6d 65 44 69 ..20040)..homeDi
   0080:  72 65 63 74 6f 72 79 31  18 04 16 2f 68 6f 6d 65 rectory1.../home
   0090:  2f 63 6f 75 72 69 65 72  2f 6a 6d 6f 6c 69 64 6f /courier/jmolido
   00a0:  72                                                 r
<= send_search_entry
====> bdb_cache_return_entry_r( 6 ): created (0)
send_search_result: err=0 matched="" text=""
send_ldap_response: msgid=2 tag=101 err=0
ber_flush: 14 bytes to sd 12
   0000:  30 0c 02 01 02 65 07 0a  01 00 04 00 04 00         0....e........
daemon: activity on 1 descriptors
daemon: new connection on 15
daemon: added 15r
daemon: activity on:
daemon: select: listen=6 active_threads=1 tvp=NULL
daemon: activity on 1 descriptors
daemon: activity on: 15r
daemon: read activity on 15
connection_get(15)
connection_get(15): got connid=1
connection_read(15): checking for input on id=1
ber_get_next
ldap_read: want=8, got=8
   0000:  30 3b 02 01 01 60 36 02                            0;...`6.
ldap_read: want=53, got=53
   0000:  01 02 04 28 75 69 64 3d  6a 6d 6f 6c 69 64 6f 72 ...(uid=jmolidor
   0010:  2c 64 63 3d 68 6f 6d 65  2c 64 63 3d 72 69 63 6b ,dc=home,dc=rick
   0020:  73 77 65 62 2c 64 63 3d  69 6e 66 6f 80 07 6d 69 sweb,dc=info..mi
   0030:  63 68 31 32 33                                     ch123
ber_get_next: tag 0x30 len 59 contents:
ber_dump: buf=0x08122e40 ptr=0x08122e40 end=0x08122e7b len=59
   0000:  02 01 01 60 36 02 01 02  04 28 75 69 64 3d 6a 6d ...`6....(uid=jm
   0010:  6f 6c 69 64 6f 72 2c 64  63 3d 68 6f 6d 65 2c 64 olidor,dc=home,d
   0020:  63 3d 72 69 63 6b 73 77  65 62 2c 64 63 3d 69 6e c=ricksweb,dc=in
   0030:  66 6f 80 07 6d 69 63 68  31 32 33                  fo..mich123
ber_get_next
ldap_read: want=8 error=Resource temporarily unavailable
ber_get_next on fd 15 failed errno=11 (Resource temporarily unavailable)
daemon: select: listen=6 active_threads=2 tvp=NULL
ldap_write: want=14, written=14
   0000:  30 0c 02 01 02 65 07 0a  01 00 04 00 04 00         0....e........
do_bind
ber_scanf fmt ({imt) ber:
ber_dump: buf=0x08122e40 ptr=0x08122e43 end=0x08122e7b len=56
   0000:  60 36 02 01 02 04 28 75  69 64 3d 6a 6d 6f 6c 69 `6....(uid=jmoli
   0010:  64 6f 72 2c 64 63 3d 68  6f 6d 65 2c 64 63 3d 72 dor,dc=home,dc=r
   0020:  69 63 6b 73 77 65 62 2c  64 63 3d 69 6e 66 6f 80 icksweb,dc=info.
   0030:  07 6d 69 63 68 31 32 33                            .mich123
ber_scanf fmt (m}) ber:
ber_dump: buf=0x08122e40 ptr=0x08122e72 end=0x08122e7b len=9
   0000:  00 07 6d 69 63 68 31 32  33                        ..mich123
 >>> dnPrettyNormal: <uid=jmolidor,dc=home,dc=ricksweb,dc=info>
=> ldap_bv2dn(uid=jmolidor,dc=home,dc=ricksweb,dc=info,0)
<= ldap_bv2dn(uid=jmolidor,dc=home,dc=ricksweb,dc=info,0)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(uid=jmolidor,dc=home,dc=ricksweb,dc=info,272)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(uid=jmolidor,dc=home,dc=ricksweb,dc=info,272)=0
<<< dnPrettyNormal: <uid=jmolidor,dc=home,dc=ricksweb,dc=info>, 
<uid=jmolidor,dc=home,dc=ricksweb,dc=info>
do_bind: version=2 dn="uid=jmolidor,dc=home,dc=ricksweb,dc=info" method=128
==> bdb_bind: dn: uid=jmolidor,dc=home,dc=ricksweb,dc=info
bdb_dn2entry_rw("uid=jmolidor,dc=home,dc=ricksweb,dc=info")
=> bdb_dn2id_matched( "uid=jmolidor,dc=home,dc=ricksweb,dc=info" )
====> 
bdb_cache_find_entry_dn2id("uid=jmolidor,dc=home,dc=ricksweb,dc=info"): 
6 (1 tries)
====> bdb_cache_find_entry_id( 6 ) 
"uid=jmolidor,dc=home,dc=ricksweb,dc=info" (found) (1 tries)
=> access_allowed: auth access to 
"uid=jmolidor,dc=home,dc=ricksweb,dc=info" "userPassword" requested
=> acl_get: [1] check attr userPassword
<= acl_get: [1] acl uid=jmolidor,dc=home,dc=ricksweb,dc=info attr: 
userPassword
=> acl_mask: access to entry "uid=jmolidor,dc=home,dc=ricksweb,dc=info", 
attr "userPassword" requested
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: pattern:  cn=admin,dc=home,dc=ricksweb,dc=info
=> string_expand: expanded: cn=admin,dc=home,dc=ricksweb,dc=info
=> regex_matches: string:
=> regex_matches: rc: 1 no matches
<= check a_dn_pat: anonymous
<= acl_mask: [2] applying auth(=x) (stop)
<= acl_mask: [2] mask: auth(=x)
=> access_allowed: auth access granted by auth(=x)
====> bdb_cache_return_entry_r( 6 ): returned (0)
do_bind: v2 bind: "uid=jmolidor,dc=home,dc=ricksweb,dc=info" to 
"uid=jmolidor,dc=home,dc=ricksweb,dc=info"
send_ldap_result: conn=1 op=0 p=2
send_ldap_result: err=0 matched="" text=""
send_ldap_response: msgid=1 tag=97 err=0
ber_flush: 14 bytes to sd 15
   0000:  30 0c 02 01 01 61 07 0a  01 00 04 00 04 00         0....a........
daemon: activity on 1 descriptors
daemon: activity on: 15r
daemon: read activity on 15
connection_get(15)
ldap_write: want=14, written=14
   0000:  30 0c 02 01 01 61 07 0a  01 00 04 00 04 00         0....a........
connection_get(15): got connid=1
connection_read(15): checking for input on id=1
ber_get_next
ldap_read: want=8, got=7
   0000:  30 05 02 01 02 42 00                               0....B.
ber_get_next: tag 0x30 len 5 contents:
ber_dump: buf=0x0810da30 ptr=0x0810da30 end=0x0810da35 len=5
   0000:  02 01 02 42 00                                     ...B.
deferring operation
daemon: select: listen=6 active_threads=1 tvp=NULL
daemon: activity on 1 descriptors
daemon: activity on: 15r
daemon: read activity on 15
connection_get(15)
connection_get(15): got connid=1
connection_read(15): checking for input on id=1
ber_get_next
ldap_read: want=8, got=0

ber_get_next on fd 15 failed errno=0 (Success)
connection_read(15): input error=-2 id=1, closing.
connection_closing: readying conn=1 sd=15 for close
connection_close: deferring conn=1 sd=15
do_unbind
connection_resched: attempting closing conn=1 sd=15
connection_close: conn=1 sd=15
daemon: removing 15
daemon: select: listen=6 active_threads=0 tvp=NULL
daemon: activity on 1 descriptors
daemon: select: listen=6 active_threads=0 tvp=NULL
Previous message: [KLUG Members] debug ldap failure
Next message: [KLUG Members] debug ldap failure
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]