[Date Prev][Date Next] [Chronological] [Thread] [Top]

log entries: LDAP search failed. Timed out. LDAP exception catched. Decision: 9

To: openldap-software@OpenLDAP.org
Subject: log entries: LDAP search failed. Timed out. LDAP exception catched. Decision: 9
From: Rob Kudyba <rkudyba@messagepartners.com>
Date: Wed, 14 Sep 2005 14:35:49 -0400
User-agent: Mozilla Thunderbird 1.0 (Macintosh/20041206)

For some reason, an application I'm working on can't seem to bind with LDAP. I have OpenLDAP 2.3.7 with BDB 4.3.28 & OpenSSL-0.9.7e going on RH9. When starting slapd in debug here are some results from an "ldapsearch -x -b 'dc=nuro,dc=raeinternet,dc=com' '(objectclass=*)' "

# Rob, nuro.raeinternet.com
dn: cn=Rob,dc=nuro,dc=raeinternet,dc=com
cn:: Um9iIA==
objectClass: person
objectClass: raeMpp
mail:: cmt1ZHliYUByYWVpbnRlcm5ldC5jb20g
raeMppGroupnameSender:: Z3JvdXAxIA==
raeMppGroupnameRecipient:: Z3JvdXAyIA==
sn: User3 Rob Kudyba

# search result
search: 2
result: 0 Success

# numResponses: 4
# numEntries: 3
daemon: activity on 1 descriptors
daemon: activity on: 13r
daemon: read activity on 13
connection_get(13)
connection_get(13): got connid=8
connection_read(13): checking for input on id=8
ber_get_next
ldap_read: want=8, got=7
0000: 30 05 02 01 03 42 00 0....B.
ber_get_next: tag 0x30 len 5 contents:
ber_dump: buf=0x081ee420 ptr=0x081ee420 end=0x081ee425 len=5
0000: 02 01 03 42 00 ...B.
ber_get_next
ldap_read: want=8 error=Resource temporarily unavailable
ber_get_next on fd 13 failed errno=11 (Resource temporarily unavailable)
daemon: select: listen=6 active_threads=0 tvp=NULL
do_unbind
conn=8 op=2 UNBIND
connection_closing: readying conn=8 sd=13 for close
connection_resched: attempting closing conn=8 sd=13
connection_close: conn=8 sd=13
daemon: removing 13
conn=8 fd=13 closed
daemon: activity on 1 descriptors
daemon: select: listen=6 active_threads=0 tvp=NULL

---------
Snip from our app's log file:

[10:47:13] 8 [0b30] [LDAP.query] LDAP server name for query:127.0.0.1
[10:47:13] 8 [0b30] [LDAP.query] The number of entries returned was 0
[10:47:13] 8 [0b30] [LDAP.query] LDAP server name for query:127.0.0.1
[10:47:13] 2 [0b30] [GroupParseJob] LDAP search failed. Timed out.
[10:47:13] 8 [0b30] [GroupParseJob] LDAP exception catched. Decision: 9

-----------------
initial.ldif:
dn: dc=nuro,dc=raeinternet,dc=com
objectClass: top
objectClass: dcObject
objectClass: organization
o: RAEInternet
dc: nuro

dn: cn=Manager,dc=nuro,dc=raeinternet,dc=com
objectClass: organizationalRole
cn: Manager

----------------

user.ldif:
dn: cn=Rob, dc=nuro,dc=raeinternet, dc=com
cn: Rob
objectClass: person
objectClass: raeMpp
mail: rkudyba@raeinternet.com
raeMppGroupnameSender: group1
raeMppGroupnameRecipient: group2
sn: User3 Rob Kudyba

---------------
slapd.conf entries:
include /etc/openldap/schema/core.schema
include /etc/openldap/schema/cosine.schema
include /etc/openldap/schema/inetorgperson.schema
include /etc/openldap/schema/nis.schema
include /etc/openldap/schema/redhat/rfc822-MailMember.schema
include /etc/openldap/schema/redhat/autofs.schema
#include /etc/openldap/schema/redhat/kerberosobject.schema
include /etc/openldap/schema/rae-mpp.schema
database bdb
suffix "dc=nuro,dc=raeinternet,dc=com"
rootdn "cn=Manager,dc=nuro,dc=raeinternet,dc=com"
rootpw ****
index objectClass eq
directory /var/lib/openldap-data

------------------
ls -l /var/lib/openldap-data
total 180
-rw-r--r-- 1 ldap ldap 2048 Sep 14 10:44 alock
-rw------- 1 ldap ldap 24576 Sep 14 10:44 __db.001
-rw------- 1 ldap ldap 278528 Sep 14 10:44 __db.002
-rw------- 1 ldap ldap 98304 Sep 14 10:44 __db.003
-rw------- 1 ldap ldap 450560 Sep 14 10:44 __db.004
-rw------- 1 ldap ldap 24576 Sep 14 10:44 __db.005
-rw------- 1 ldap ldap 8192 Sep 14 10:44 dn2id.bdb
-rw------- 1 ldap ldap 32768 Sep 14 10:44 id2entry.bdb
-rw------- 1 ldap ldap 10485760 Sep 14 10:46 log.0000000001
-rw------- 1 ldap ldap 8192 Sep 14 10:45 objectClass.bdb

-------------------- ps -auwx | grep slapd ldap 32108 0.0 0.7 38756 4040 pts/3 S 10:44 0:00 /usr/sbin/slapd -u ldap -f /etc/openldap/slapd.conf -d -1

--------------------

On that note, how do you read the log.0000000001 file?
--------------------
Our custom schema:
# raeMpp object class
#
# Depends upon
#   RFC 1274 (uid/dc)
#       (core.schema)

attributetype ( 1.3.6.1.4.1.21157.2.1.1 NAME 'raeMppGroupnameRecipient' DESC 'Group name for e-mail`s that contains current e-mail in Recipients field (used by RAE-INTERNET MPP)' EQUALITY caseIgnoreMatch SUBSTR caseIgnoreSubstringsMatch SYNTAX 1.3.6.1.4.1.1466.115.121.1.15 SINGLE-VALUE )

attributetype ( 1.3.6.1.4.1.21157.2.1.2 NAME 'raeMppGroupnameSender' DESC 'Group name for e-mail`s that contains current e-mail in Sender field (used by RAE-INTERNET MPP)' SUP raeMppGroupnameRecipient )

# raeMpp # The raeMpp represents group names and e-mail address which are associated with a # person in some way. objectclass ( 1.3.6.1.4.1.21157.2.2.1 NAME 'raeMpp' DESC 'Object class for group names for RAE-INTERNET MPP' AUXILIARY MAY ( raeMppGroupnameRecipient $ raeMppGroupnameSender $ mail ) )

_____________

Oh & here's a partial debug to STD ERR: ------------------- ber_get_next ldap_read: want=8 error=Resource temporarily unavailable ber_get_next on fd 13 failed errno=11 (Resource temporarily unavailable) daemon: select: listen=6 active_threads=0 tvp=NULL do_search ber_scanf fmt ({miiiib) ber: ber_dump: buf=0x081eb8f8 ptr=0x081eb8fb end=0x081eb94e len=83 0000: 63 51 04 1d 64 63 3d 6e 75 72 6f 2c 64 63 3d 72 cQ..dc=nuro,dc=r 0010: 61 65 69 6e 74 65 72 6e 65 74 2c 64 63 3d 63 6f aeinternet,dc=co 0020: 6d 0a 01 02 0a 01 00 02 01 00 02 01 00 01 01 00 m............... 0030: a3 1f 04 04 6d 61 69 6c 04 17 72 6b 75 64 79 62 ....mail..rkudyb 0040: 61 40 72 61 65 69 6e 74 65 72 6e 65 74 2e 63 6f a@raeinternet.co 0050: 6d 30 00 m0. >>> dnPrettyNormal: <dc=nuro,dc=raeinternet,dc=com> => ldap_bv2dn(dc=nuro,dc=raeinternet,dc=com,0) ldap_err2string <= ldap_bv2dn(dc=nuro,dc=raeinternet,dc=com)=0 Success => ldap_dn2bv(272) ldap_err2string <= ldap_dn2bv(dc=nuro,dc=raeinternet,dc=com)=0 Success => ldap_dn2bv(272) ldap_err2string <= ldap_dn2bv(dc=nuro,dc=raeinternet,dc=com)=0 Success <<< dnPrettyNormal: <dc=nuro,dc=raeinternet,dc=com>, <dc=nuro,dc=raeinternet,dc=com> SRCH "dc=nuro,dc=raeinternet,dc=com" 2 0 0 0 0 begin get_filter EQUALITY ber_scanf fmt ({mm}) ber: ber_dump: buf=0x081eb8f8 ptr=0x081eb92b end=0x081eb94e len=35 0000: a3 1f 04 04 6d 61 69 6c 04 17 72 6b 75 64 79 62 ....mail..rkudyb 0010: 61 40 72 61 65 69 6e 74 65 72 6e 65 74 2e 63 6f a@raeinternet.co 0020: 6d 30 00 m0. end get_filter 0 filter: (mail=rkudyba@raeinternet.com) ber_scanf fmt ({M}}) ber: ber_dump: buf=0x081eb8f8 ptr=0x081eb94c end=0x081eb94e len=2 0000: 00 00 .. attrs: => bdb_search bdb_dn2entry("dc=nuro,dc=raeinternet,dc=com") search_candidates: base="dc=nuro,dc=raeinternet,dc=com" (0x00000001) scope=2 => bdb_dn2idl("dc=nuro,dc=raeinternet,dc=com") => bdb_filter_candidates AND => bdb_list_candidates 0xa0 => bdb_filter_candidates OR => bdb_list_candidates 0xa1 => bdb_filter_candidates EQUALITY => bdb_equality_candidates (objectClass) => key_read bdb_idl_fetch_key: [b49d1940] <= bdb_index_read: failed (-30989) <= bdb_equality_candidates: id=0, first=0, last=0 <= bdb_filter_candidates: id=0 first=0 last=0 => bdb_filter_candidates EQUALITY => bdb_equality_candidates (mail) <= bdb_equality_candidates: (mail) index_param failed (18) <= bdb_filter_candidates: id=-1 first=1 last=3 <= bdb_list_candidates: id=-1 first=1 last=3 <= bdb_filter_candidates: id=-1 first=1 last=3 <= bdb_list_candidates: id=-1 first=1 last=3 <= bdb_filter_candidates: id=-1 first=1 last=3 bdb_search_candidates: id=-1 first=1 last=3 => test_filter EQUALITY => access_allowed: search access to "dc=nuro,dc=raeinternet,dc=com" "mail" requested <= root access granted <= test_filter 5 bdb_search: 1 does not match filter => test_filter EQUALITY => access_allowed: search access to "cn=Manager,dc=nuro,dc=raeinternet,dc=com" "mail" requested <= root access granted <= test_filter 5 bdb_search: 2 does not match filter => test_filter EQUALITY => access_allowed: search access to "cn=Rob,dc=nuro,dc=raeinternet,dc=com" "mail" requested <= root access granted <= test_filter 6 => send_search_entry: conn 3 dn="cn=Rob,dc=nuro,dc=raeinternet,dc=com" => access_allowed: read access to "cn=Rob,dc=nuro,dc=raeinternet,dc=com" "entry" requested <= root access granted => access_allowed: read access to "cn=Rob,dc=nuro,dc=raeinternet,dc=com" "cn" requested <= root access granted => access_allowed: read access to "cn=Rob,dc=nuro,dc=raeinternet,dc=com" "objectClass" requested <= root access granted => access_allowed: read access to "cn=Rob,dc=nuro,dc=raeinternet,dc=com" "mail" requested <= root access granted => access_allowed: read access to "cn=Rob,dc=nuro,dc=raeinternet,dc=com" "raeMppGroupnameSender" requested <= root access granted => access_allowed: read access to "cn=Rob,dc=nuro,dc=raeinternet,dc=com" "raeMppGroupnameRecipient" requested <= root access granted => access_allowed: read access to "cn=Rob,dc=nuro,dc=raeinternet,dc=com" "sn" requested <= root access granted ber_flush: 234 bytes to sd 13 0000: 30 81 e7 02 01 02 64 81 e1 04 24 63 6e 3d 52 6f 0.....d...$cn=Ro 0010: 62 2c 64 63 3d 6e 75 72 6f 2c 64 63 3d 72 61 65 b,dc=nuro,dc=rae 0020: 69 6e 74 65 72 6e 65 74 2c 64 63 3d 63 6f 6d 30 internet,dc=com0 0030: 81 b8 30 0c 04 02 63 6e 31 06 04 04 52 6f 62 20 ..0...cn1...Rob 0040: 30 1f 04 0b 6f 62 6a 65 63 74 43 6c 61 73 73 31 0...objectClass1 0050: 10 04 06 70 65 72 73 6f 6e 04 06 72 61 65 4d 70 ...person..raeMp 0060: 70 30 22 04 04 6d 61 69 6c 31 1a 04 18 72 6b 75 p0"..mail1...rku 0070: 64 79 62 61 40 72 61 65 69 6e 74 65 72 6e 65 74 dyba@raeinternet 0080: 2e 63 6f 6d 20 30 22 04 15 72 61 65 4d 70 70 47 .com 0"..raeMppG 0090: 72 6f 75 70 6e 61 6d 65 53 65 6e 64 65 72 31 09 roupnameSender1. 00a0: 04 07 67 72 6f 75 70 31 20 30 25 04 18 72 61 65 ..group1 0%..rae 00b0: 4d 70 70 47 72 6f 75 70 6e 61 6d 65 52 65 63 69 MppGroupnameReci 00c0: 70 69 65 6e 74 31 09 04 07 67 72 6f 75 70 32 20 pient1...group2 00d0: 30 18 04 02 73 6e 31 12 04 10 55 73 65 72 33 20 0...sn1...User3 00e0: 52 6f 62 20 4b 75 64 79 62 61 Rob Kudyba ldap_write: want=234, written=234 0000: 30 81 e7 02 01 02 64 81 e1 04 24 63 6e 3d 52 6f 0.....d...$cn=Ro 0010: 62 2c 64 63 3d 6e 75 72 6f 2c 64 63 3d 72 61 65 b,dc=nuro,dc=rae 0020: 69 6e 74 65 72 6e 65 74 2c 64 63 3d 63 6f 6d 30 internet,dc=com0 0030: 81 b8 30 0c 04 02 63 6e 31 06 04 04 52 6f 62 20 ..0...cn1...Rob 0040: 30 1f 04 0b 6f 62 6a 65 63 74 43 6c 61 73 73 31 0...objectClass1 0050: 10 04 06 70 65 72 73 6f 6e 04 06 72 61 65 4d 70 ...person..raeMp 0060: 70 30 22 04 04 6d 61 69 6c 31 1a 04 18 72 6b 75 p0"..mail1...rku 0070: 64 79 62 61 40 72 61 65 69 6e 74 65 72 6e 65 74 dyba@raeinternet 0080: 2e 63 6f 6d 20 30 22 04 15 72 61 65 4d 70 70 47 .com 0"..raeMppG 0090: 72 6f 75 70 6e 61 6d 65 53 65 6e 64 65 72 31 09 roupnameSender1. 00a0: 04 07 67 72 6f 75 70 31 20 30 25 04 18 72 61 65 ..group1 0%..rae 00b0: 4d 70 70 47 72 6f 75 70 6e 61 6d 65 52 65 63 69 MppGroupnameReci 00c0: 70 69 65 6e 74 31 09 04 07 67 72 6f 75 70 32 20 pient1...group2 00d0: 30 18 04 02 73 6e 31 12 04 10 55 73 65 72 33 20 0...sn1...User3 00e0: 52 6f 62 20 4b 75 64 79 62 61 Rob Kudyba <= send_search_entry: conn 3 exit. daemon: activity on 1 descriptors daemon: activity on: 13r daemon: read activity on 13 connection_get(13) connection_get(13): got connid=3 connection_read(13): checking for input on id=3 ber_get_next ldap_read: want=8, got=8 0000: 30 06 02 01 03 50 01 02 0....P.. ber_get_next: tag 0x30 len 6 contents: ber_dump: buf=0x081ee688 ptr=0x081ee688 end=0x081ee68e len=6 0000: 02 01 03 50 01 02 ...P.. ber_get_next ldap_read: want=8 error=Resource temporarily unavailable ber_get_next on fd 13 failed errno=11 (Resource temporarily unavailable) daemon: select: listen=6 active_threads=0 tvp=NULL do_abandon ber_scanf fmt (i) ber: ber_dump: buf=0x081ee688 ptr=0x081ee68b end=0x081ee68e len=3 0000: 50 01 02 P.. do_abandon: id=2 do_abandon: op=2 found send_ldap_result: conn=3 op=1 p=3 send_ldap_result: err=0 matched="" text="" send_ldap_response: msgid=2 tag=101 err=0 ber_flush: 14 bytes to sd 13 0000: 30 0c 02 01 02 65 07 0a 01 00 04 00 04 00 0....e........ ldap_write: want=14, written=14 0000: 30 0c 02 01 02 65 07 0a 01 00 04 00 04 00 0....e........

Prev by Date: Re: Update to FAQ
Next by Date: Re: Update to FAQ
Index(es):
- Chronological
- Thread