[Date Prev][Date Next] [Chronological] [Thread] [Top]
RE: LDAP provisioning error.

To: "Aaron Richton" <richton@nbcs.rutgers.edu>
Subject: RE: LDAP provisioning error.
From: "Sanjay Vivek" <Sanjay.Vivek@newcastle.ac.uk>
Date: Fri, 2 Nov 2007 13:11:29 -0000
Cc: openldap-software@openldap.org
Content-class: urn:content-classes:message
In-reply-to: <Pine.SOC.4.64.0710291440501.899@toolbox.rutgers.edu>
References: <88493EDAE8A32D4EA88F17102879E3950504BC06@moonraker.campus.ncl.ac.uk> <Pine.SOC.4.64.0710291440501.899@toolbox.rutgers.edu>
Thread-index: AcgaXBkaWiYSqA8sQj+qKBFFhaCxQQC1VAyw
Thread-topic: LDAP provisioning error.
 
You're right about the rootdn so I should be able to bind to my LDAP and
pretty much read/write anything to it. I think I should provide a bit
more background to what I'm trying to do here.

We are using a role management tool called Grouper to create groups.
These groups are then populated with users. Subsequently, separate
applications may use these groups to track an individual's role, or to
determine which users are authorized to access the resource.

Grouper also comes with a provisioning functionality whereby these
groups are provisioned over to LDAP server. The groups that are
provisioned over will also contain the users that are members of these
groups.

What we would like to happen is for the groups to be provisioned from
Grouper to LDAP with the following entry in LDAP:

dn: cn=ncl:staff,ou=grouper,dc=ncl,dc=ac,dc=uk
objectClass: groupOfNames
objectClass: top
member: uid=john.smith@ncl.ac.uk,ou=people,dc=ncl,dc=ac,dc=uk
cn: ncl:staff 

The above entry tells us that we have John Smith
(uid=john.smith@ncl.ac.uk) in the Staff group. The Staff group was
created by Grouper and John Smith was already a member of the Staff
group. 

The way our Grouper configuration is setup is we have the all the users
under "ou=people,dc=ncl,dc=ac,dc=uk". The groups are provisioned to
"ou=grouper,dc=ncl,dc=ac,dc=uk". So "ou=grouper,dc=ncl,dc=ac,dc=uk"
starts off empty before any provisioning activity. After the completion
of provisioning, a samply entry (shown above) should be found under
"ou=grouper,dc=ncl,dc=ac,dc=uk".

However, nothing is being provisioned over as described in my previous
email. I believe its an openLDAP issue cos I've pretty much exhausted my
Grouper options. I don't think its an ACL issue cos I'm binding as
rootDN and so I should be able to read/write to
"ou=grouper,dc=ncl,dc=ac,dc=uk". 

I did a "slap -d acl" and what I got is shown below:

slapd -d acl
@(#) $OpenLDAP: slapd 2.3.27 (Jan  3 2007 13:11:16) $
 
brewbuilder@ls20-bc1-14.build.redhat.com:/builddir/build/BUILD/openldap-
2.3.27/openldap-2.3.27/build-servers/servers/slapd
daemon: bind(7) failed errno=98 (Address already in use)
daemon: bind(7) failed errno=98 (Address already in use)
slapd stopped.
connections_destroy: nothing to destroy.

And when I do a "lsof -i :389", 

[root@pen openldap]# lsof -i :389
COMMAND   PID USER   FD   TYPE  DEVICE SIZE NODE NAME
slapd   19048 ldap    7u  IPv6 2005549       TCP *:ldap (LISTEN)
slapd   19048 ldap    8u  IPv4 2005550       TCP *:ldap (LISTEN)

I can't tell if this is an error or not. My LDAP server seems to be
working fine so the "Address already in use" error shouldn't be popping
up. From what I gather while trawling through the mailing lists, this
could be an Ipv6 issue. Is this indeed the case?

The logs (set at loglevel=256) is given below when I try to run the
provisioning program. Any help would be greatly appreciated. Cheers.

Regards
Sanjay

Nov  2 11:15:06 pen slapd[18902]: conn=6 fd=12 ACCEPT from
IP=128.240.2.3:43541 (IP=0.0.0.0:389) 
Nov  2 11:15:06 pen slapd[18902]: conn=6 op=0 BIND
dn="cn=Manager,dc=ncl,dc=ac,dc=uk" method=128 
Nov  2 11:15:06 pen slapd[18902]: conn=6 op=0 BIND
dn="cn=Manager,dc=ncl,dc=ac,dc=uk" mech=SIMPLE ssf=0 
Nov  2 11:15:06 pen slapd[18902]: conn=6 op=0 RESULT tag=97 err=0 text= 
Nov  2 11:15:06 pen slapd[18902]: conn=7 fd=13 ACCEPT from
IP=128.240.2.3:51570 (IP=0.0.0.0:389) 
Nov  2 11:15:06 pen slapd[18902]: conn=7 op=0 BIND
dn="cn=Manager,dc=ncl,dc=ac,dc=uk" method=128 
Nov  2 11:15:06 pen slapd[18902]: conn=7 op=0 BIND
dn="cn=Manager,dc=ncl,dc=ac,dc=uk" mech=SIMPLE ssf=0 
Nov  2 11:15:06 pen slapd[18902]: conn=7 op=0 RESULT tag=97 err=0 text= 
Nov  2 11:15:06 pen slapd[18902]: conn=7 op=1 UNBIND 
Nov  2 11:15:06 pen slapd[18902]: conn=7 fd=13 closed 
Nov  2 11:15:07 pen slapd[18902]: conn=8 fd=13 ACCEPT from
IP=128.240.2.3:48240 (IP=0.0.0.0:389) 
Nov  2 11:15:07 pen slapd[18902]: conn=8 op=0 BIND
dn="cn=Manager,dc=ncl,dc=ac,dc=uk" method=128 
Nov  2 11:15:07 pen slapd[18902]: conn=8 op=0 BIND
dn="cn=Manager,dc=ncl,dc=ac,dc=uk" mech=SIMPLE ssf=0 
Nov  2 11:15:07 pen slapd[18902]: conn=8 op=0 RESULT tag=97 err=0 text= 
Nov  2 11:15:07 pen slapd[18902]: conn=8 op=1 SRCH
base="ou=people,dc=ncl,dc=ac,dc=uk" scope=2 deref=3
filter="(&(uid=groupersystem)(objectClass=eduPerson))" 
Nov  2 11:15:07 pen slapd[18902]: conn=8 op=1 SRCH attr=cn cn uid 
Nov  2 11:15:07 pen slapd[18902]: conn=8 op=1 SEARCH RESULT tag=101
err=0 nentries=0 text= 
Nov  2 11:15:07 pen slapd[18902]: conn=8 op=2 UNBIND 
Nov  2 11:15:07 pen slapd[18902]: conn=8 fd=13 closed 
Nov  2 11:15:07 pen slapd[18902]: conn=6 op=1 UNBIND 
Nov  2 11:15:07 pen slapd[18902]: conn=6 fd=12 closed 


>-----Original Message-----
>From: Aaron Richton [mailto:richton@nbcs.rutgers.edu] 
>Sent: 29 October 2007 18:47
>To: Sanjay Vivek
>Cc: openldap-software@openldap.org
>Subject: Re: LDAP provisioning error.
>
>It looks like you're binding as the rootdn (therefore access 
>rules don't apply). Furthermore, you've got two log messages 
>regarding "access granted" and none regarding denials. "does 
>not match filter" seems to be your issue, your statement that 
>they "should match" aside.
>
>What makes you think this is an ACL issue? Does it change for 
>rootdn vs. 
>non-root?
>
>If you want to debug ACLs, try slapd -d acl to make it easier to read.
>
>What does slapcat(8) show for these entries in question?
>
>You're searching on edupersonprincipalname, but you don't seem 
>to have an index present there. You probably should...
>
>On Mon, 29 Oct 2007, Sanjay Vivek wrote:
>
>>
>> Hello everyone,
>>
>> I'm involved in a project whereby access groups (with users) are 
>> provisioned to a LDAP server. In a nutshell, the groups should be 
>> provisioned under ""ou=groups,dc=ncl,dc=ac,dc=uk" while the users in 
>> each group are found in ""ou=people,dc=ncl,dc=ac,dc=uk".  
>However, the 
>> groups are not being provisioned over to our LDAP server. Among the 
>> dubious looking lines in the log files include:
>>
>> bdb_search: 134 does not match filter
>>
>> (the above entry should match the filter. And similiarly for other
>> entries)
>>
>> I'm guessing this has something to do with the ACL control list in 
>> slapd.conf. The relevant section in slapd.conf is given below:
>>
>> # Allow anyone to write and read to ou=people access to 
>> dn.one="ou=people,dc=ncl,dc=ac,dc=uk"
>>        attr=children
>>        by anonymous read
>>        by anonymous write
>>
>> # Allow anyone to write and read to ou=grouper access to 
>> dn.one="ou=grouper,dc=ncl,dc=ac,dc=uk"
>>        attr=children
>>        by anonymous read
>>        by anonymous write
>>
>> So basically what the above configuration is meant to do is that 
>> anyone can read or write to one level below both people and 
>grouper. I 
>> realise this is highly insecure but it's merely for testing purposes.
>>
>> Any suggestions or help would be greatly appreciated. The complete 
>> logs of this transaction is given below. Thanks again.
>>
>> Cheers
>> Sanjay
>>
>>
>> Oct 16 15:13:34 pen slapd[9559]: daemon: activity on 1 
>descriptor Oct 
>> 16 15:13:34 pen slapd[9559]: daemon: activity on:
>> Oct 16 15:13:34 pen slapd[9559]:
>> Oct 16 15:13:34 pen slapd[9559]: daemon: listen=8, new connection on 
>> 13 Oct 16 15:13:34 pen slapd[9559]: daemon: added 13r Oct 16 
>15:13:34 
>> pen slapd[9559]: conn=8 fd=13 ACCEPT from
>> IP=128.240.2.3:51855 (IP=0.0.0.0:389)
>> Oct 16 15:13:34 pen slapd[9559]: daemon: select: listen=7 
>> active_threads=0 tvp=NULL Oct 16 15:13:34 pen slapd[9559]: daemon: 
>> select: listen=8 active_threads=0 tvp=NULL Oct 16 15:13:34 pen 
>> slapd[9559]: daemon: activity on 1 descriptor Oct 16 15:13:34 pen 
>> slapd[9559]: daemon: activity on:
>> Oct 16 15:13:34 pen slapd[9559]:  13r
>> Oct 16 15:13:34 pen slapd[9559]:
>> Oct 16 15:13:34 pen slapd[9559]: daemon: read active on 13 Oct 16 
>> 15:13:34 pen slapd[9559]: connection_get(13) Oct 16 15:13:34 pen 
>> slapd[9559]: connection_get(13): got connid=8 Oct 16 15:13:34 pen 
>> slapd[9559]: connection_read(13): checking for input on id=8 Oct 16 
>> 15:13:34 pen slapd[9559]: ber_get_next on fd 13 failed errno=11 
>> (Resource temporarily unavailable) Oct 16 15:13:34 pen slapd[9559]: 
>> daemon: select: listen=7 active_threads=0 tvp=NULL Oct 16 
>15:13:34 pen 
>> slapd[9559]: daemon: select: listen=8 active_threads=0 
>tvp=NULL Oct 16 
>> 15:13:34 pen slapd[9559]: do_bind Oct 16 15:13:34 pen 
>slapd[9559]: >>> 
>> dnPrettyNormal:
>> <cn=Manager,dc=ncl,dc=ac,dc=uk>
>> Oct 16 15:13:34 pen slapd[9559]: <<< dnPrettyNormal:
>> <cn=Manager,dc=ncl,dc=ac,dc=uk>, <cn=manager,dc=ncl,dc=ac,dc=uk> Oct 
>> 16 15:13:34 pen slapd[9559]: do_bind: version=3 
>> dn="cn=Manager,dc=ncl,dc=ac,dc=uk" method=128 Oct 16 15:13:34 pen 
>> slapd[9559]: conn=8 op=0 BIND dn="cn=Manager,dc=ncl,dc=ac,dc=uk" 
>> method=128 Oct 16 15:13:34 pen slapd[9559]: ==> bdb_bind: dn:
>> cn=Manager,dc=ncl,dc=ac,dc=uk
>> Oct 16 15:13:34 pen slapd[9559]: conn=8 op=0 BIND 
>> dn="cn=Manager,dc=ncl,dc=ac,dc=uk" mech=SIMPLE ssf=0 Oct 16 15:13:34 
>> pen slapd[9559]: do_bind: v3 bind:
>> "cn=Manager,dc=ncl,dc=ac,dc=uk" to "cn=Manager,dc=ncl,dc=ac,dc=uk"
>> Oct 16 15:13:34 pen slapd[9559]: send_ldap_result: conn=8 
>op=0 p=3 Oct 
>> 16 15:13:34 pen slapd[9559]: send_ldap_result: err=0 matched=""
>> text=""
>> Oct 16 15:13:34 pen slapd[9559]: send_ldap_response: msgid=1 tag=97 
>> err=0 Oct 16 15:13:34 pen slapd[9559]: conn=8 op=0 RESULT 
>tag=97 err=0 
>> text= Oct 16 15:13:34 pen slapd[9559]: daemon: activity on 1 
>> descriptor Oct 16 15:13:34 pen slapd[9559]: daemon: activity on:
>> Oct 16 15:13:34 pen slapd[9559]:
>> Oct 16 15:13:34 pen slapd[9559]: daemon: listen=8, new connection on 
>> 15 Oct 16 15:13:34 pen slapd[9559]: daemon: added 15r Oct 16 
>15:13:34 
>> pen slapd[9559]: conn=9 fd=15 ACCEPT from
>> IP=128.240.2.3:36766 (IP=0.0.0.0:389)
>> Oct 16 15:13:34 pen slapd[9559]: daemon: select: listen=7 
>> active_threads=0 tvp=NULL Oct 16 15:13:34 pen slapd[9559]: daemon: 
>> select: listen=8 active_threads=0 tvp=NULL Oct 16 15:13:34 pen 
>> slapd[9559]: daemon: activity on 1 descriptor Oct 16 15:13:34 pen 
>> slapd[9559]: daemon: activity on:
>> Oct 16 15:13:34 pen slapd[9559]:  15r
>> Oct 16 15:13:34 pen slapd[9559]:
>> Oct 16 15:13:34 pen slapd[9559]: daemon: read active on 15 Oct 16 
>> 15:13:34 pen slapd[9559]: connection_get(15) Oct 16 15:13:34 pen 
>> slapd[9559]: connection_get(15): got connid=9 Oct 16 15:13:34 pen 
>> slapd[9559]: connection_read(15): checking for input on id=9 Oct 16 
>> 15:13:34 pen slapd[9559]: ber_get_next on fd 15 failed errno=11 
>> (Resource temporarily unavailable) Oct 16 15:13:34 pen slapd[9559]: 
>> daemon: select: listen=7 active_threads=0 tvp=NULL Oct 16 
>15:13:34 pen 
>> slapd[9559]: daemon: select: listen=8 active_threads=0 
>tvp=NULL Oct 16 
>> 15:13:34 pen slapd[9559]: do_bind Oct 16 15:13:34 pen 
>slapd[9559]: >>> 
>> dnPrettyNormal:
>> <cn=Manager,dc=ncl,dc=ac,dc=uk>
>> Oct 16 15:13:34 pen slapd[9559]: <<< dnPrettyNormal:
>> <cn=Manager,dc=ncl,dc=ac,dc=uk>, <cn=manager,dc=ncl,dc=ac,dc=uk> Oct 
>> 16 15:13:34 pen slapd[9559]: do_bind: version=3 
>> dn="cn=Manager,dc=ncl,dc=ac,dc=uk" method=128 Oct 16 15:13:34 pen 
>> slapd[9559]: conn=9 op=0 BIND dn="cn=Manager,dc=ncl,dc=ac,dc=uk" 
>> method=128 Oct 16 15:13:34 pen slapd[9559]: ==> bdb_bind: dn:
>> cn=Manager,dc=ncl,dc=ac,dc=uk
>> Oct 16 15:13:34 pen slapd[9559]: conn=9 op=0 BIND 
>> dn="cn=Manager,dc=ncl,dc=ac,dc=uk" mech=SIMPLE ssf=0 Oct 16 15:13:34 
>> pen slapd[9559]: do_bind: v3 bind:
>> "cn=Manager,dc=ncl,dc=ac,dc=uk" to "cn=Manager,dc=ncl,dc=ac,dc=uk"
>> Oct 16 15:13:34 pen slapd[9559]: send_ldap_result: conn=9 
>op=0 p=3 Oct 
>> 16 15:13:34 pen slapd[9559]: send_ldap_result: err=0 matched=""
>> text=""
>> Oct 16 15:13:34 pen slapd[9559]: send_ldap_response: msgid=1 tag=97 
>> err=0 Oct 16 15:13:34 pen slapd[9559]: conn=9 op=0 RESULT 
>tag=97 err=0 
>> text= Oct 16 15:13:34 pen slapd[9559]: daemon: activity on 1 
>> descriptor Oct 16 15:13:34 pen slapd[9559]: daemon: activity on:
>> Oct 16 15:13:34 pen slapd[9559]:  15r
>> Oct 16 15:13:34 pen slapd[9559]:
>> Oct 16 15:13:34 pen slapd[9559]: daemon: read active on 15 Oct 16 
>> 15:13:34 pen slapd[9559]: connection_get(15) Oct 16 15:13:34 pen 
>> slapd[9559]: connection_get(15): got connid=9 Oct 16 15:13:34 pen 
>> slapd[9559]: connection_read(15): checking for input on id=9 Oct 16 
>> 15:13:34 pen slapd[9559]: ber_get_next on fd 15 failed errno=0
>> (Success)
>> Oct 16 15:13:34 pen slapd[9559]: connection_read(15): input error=-2 
>> id=9, closing.
>> Oct 16 15:13:34 pen slapd[9559]: connection_closing: readying conn=9
>> sd=15 for close
>> Oct 16 15:13:34 pen slapd[9559]: connection_close: deferring conn=9
>> sd=15
>> Oct 16 15:13:34 pen slapd[9559]: daemon: select: listen=7 
>> active_threads=0 tvp=NULL Oct 16 15:13:34 pen slapd[9559]: daemon: 
>> select: listen=8 active_threads=0 tvp=NULL Oct 16 15:13:34 pen 
>> slapd[9559]: daemon: activity on 1 descriptor Oct 16 15:13:34 pen 
>> slapd[9559]: daemon: activity on:
>> Oct 16 15:13:34 pen slapd[9559]:
>> Oct 16 15:13:34 pen slapd[9559]: daemon: select: listen=7 
>> active_threads=0 tvp=NULL Oct 16 15:13:34 pen slapd[9559]: daemon: 
>> select: listen=8 active_threads=0 tvp=NULL Oct 16 15:13:34 pen 
>> slapd[9559]: do_unbind Oct 16 15:13:34 pen slapd[9559]: conn=9 op=1 
>> UNBIND Oct 16 15:13:34 pen slapd[9559]: connection_resched: 
>attempting 
>> closing
>> conn=9 sd=15
>> Oct 16 15:13:34 pen slapd[9559]: connection_close: conn=9 
>sd=15 Oct 16 
>> 15:13:34 pen slapd[9559]: daemon: removing 15 Oct 16 15:13:34 pen 
>> slapd[9559]: conn=9 fd=15 closed Oct 16 15:13:35 pen slapd[9559]: 
>> daemon: activity on 1 descriptor Oct 16 15:13:35 pen slapd[9559]: 
>> daemon: activity on:
>> Oct 16 15:13:35 pen slapd[9559]:
>> Oct 16 15:13:35 pen slapd[9559]: daemon: listen=8, new connection on 
>> 15 Oct 16 15:13:35 pen slapd[9559]: daemon: added 15r Oct 16 
>15:13:35 
>> pen slapd[9559]: conn=10 fd=15 ACCEPT from
>> IP=128.240.2.3:50097 (IP=0.0.0.0:389)
>> Oct 16 15:13:35 pen slapd[9559]: daemon: select: listen=7 
>> active_threads=0 tvp=NULL Oct 16 15:13:35 pen slapd[9559]: daemon: 
>> select: listen=8 active_threads=0 tvp=NULL Oct 16 15:13:35 pen 
>> slapd[9559]: daemon: activity on 1 descriptor Oct 16 15:13:35 pen 
>> slapd[9559]: daemon: activity on:
>> Oct 16 15:13:35 pen slapd[9559]:  15r
>> Oct 16 15:13:35 pen slapd[9559]:
>> Oct 16 15:13:35 pen slapd[9559]: daemon: read active on 15 Oct 16 
>> 15:13:35 pen slapd[9559]: connection_get(15) Oct 16 15:13:35 pen 
>> slapd[9559]: connection_get(15): got connid=10 Oct 16 15:13:35 pen 
>> slapd[9559]: connection_read(15): checking for input on id=10 Oct 16 
>> 15:13:35 pen slapd[9559]: ber_get_next on fd 15 failed errno=11 
>> (Resource temporarily unavailable) Oct 16 15:13:35 pen slapd[9559]: 
>> daemon: select: listen=7 active_threads=0 tvp=NULL Oct 16 
>15:13:35 pen 
>> slapd[9559]: daemon: select: listen=8 active_threads=0 
>tvp=NULL Oct 16 
>> 15:13:35 pen slapd[9559]: do_bind Oct 16 15:13:35 pen 
>slapd[9559]: >>> 
>> dnPrettyNormal:
>> <cn=Manager,dc=ncl,dc=ac,dc=uk>
>> Oct 16 15:13:35 pen slapd[9559]: <<< dnPrettyNormal:
>> <cn=Manager,dc=ncl,dc=ac,dc=uk>, <cn=manager,dc=ncl,dc=ac,dc=uk> Oct 
>> 16 15:13:35 pen slapd[9559]: do_bind: version=3 
>> dn="cn=Manager,dc=ncl,dc=ac,dc=uk" method=128 Oct 16 15:13:35 pen 
>> slapd[9559]: conn=10 op=0 BIND dn="cn=Manager,dc=ncl,dc=ac,dc=uk" 
>> method=128 Oct 16 15:13:35 pen slapd[9559]: ==> bdb_bind: dn:
>> cn=Manager,dc=ncl,dc=ac,dc=uk
>> Oct 16 15:13:35 pen slapd[9559]: conn=10 op=0 BIND 
>> dn="cn=Manager,dc=ncl,dc=ac,dc=uk" mech=SIMPLE ssf=0 Oct 16 15:13:35 
>> pen slapd[9559]: do_bind: v3 bind:
>> "cn=Manager,dc=ncl,dc=ac,dc=uk" to "cn=Manager,dc=ncl,dc=ac,dc=uk"
>> Oct 16 15:13:35 pen slapd[9559]: send_ldap_result: conn=10 op=0 p=3 
>> Oct 16 15:13:35 pen slapd[9559]: send_ldap_result: err=0 matched=""
>> text=""
>> Oct 16 15:13:35 pen slapd[9559]: send_ldap_response: msgid=1 tag=97 
>> err=0 Oct 16 15:13:35 pen slapd[9559]: conn=10 op=0 RESULT tag=97 
>> err=0 text= Oct 16 15:13:35 pen slapd[9559]: daemon: activity on 1 
>> descriptor Oct 16 15:13:35 pen slapd[9559]: daemon: activity on:
>> Oct 16 15:13:35 pen slapd[9559]:  15r
>> Oct 16 15:13:35 pen slapd[9559]:
>> Oct 16 15:13:35 pen slapd[9559]: daemon: read active on 15 Oct 16 
>> 15:13:35 pen slapd[9559]: connection_get(15) Oct 16 15:13:35 pen 
>> slapd[9559]: connection_get(15): got connid=10 Oct 16 15:13:35 pen 
>> slapd[9559]: connection_read(15): checking for input on id=10 Oct 16 
>> 15:13:35 pen slapd[9559]: ber_get_next on fd 15 failed errno=11 
>> (Resource temporarily unavailable) Oct 16 15:13:35 pen slapd[9559]: 
>> daemon: select: listen=7 active_threads=0 tvp=NULL Oct 16 
>15:13:35 pen 
>> slapd[9559]: daemon: select: listen=8 active_threads=0 
>tvp=NULL Oct 16 
>> 15:13:35 pen slapd[9559]: do_search Oct 16 15:13:35 pen slapd[9559]: 
>> >>> dnPrettyNormal:
>> <ou=people,dc=ncl,dc=ac,dc=uk>
>> Oct 16 15:13:35 pen slapd[9559]: <<< dnPrettyNormal:
>> <ou=people,dc=ncl,dc=ac,dc=uk>, 
><ou=people,dc=ncl,dc=ac,dc=uk> Oct 16 
>> 15:13:35 pen slapd[9559]: SRCH "ou=people,dc=ncl,dc=ac,dc=uk" 2 3
>> Oct 16 15:13:35 pen slapd[9559]:     0 0 0
>> Oct 16 15:13:35 pen slapd[9559]: begin get_filter Oct 16 
>15:13:35 pen 
>> slapd[9559]: AND Oct 16 15:13:35 pen slapd[9559]: begin 
>> get_filter_list Oct 16 15:13:35 pen slapd[9559]: begin 
>get_filter Oct 
>> 16 15:13:35 pen slapd[9559]: EQUALITY Oct 16 15:13:35 pen 
>slapd[9559]: 
>> end get_filter 0 Oct 16 15:13:35 pen slapd[9559]: begin 
>get_filter Oct 
>> 16 15:13:35 pen slapd[9559]: EQUALITY Oct 16 15:13:35 pen 
>slapd[9559]: 
>> end get_filter 0 Oct 16 15:13:35 pen slapd[9559]: end 
>get_filter_list 
>> Oct 16 15:13:35 pen slapd[9559]: end get_filter 0
>> Oct 16 15:13:35 pen slapd[9559]:     filter:
>> (&(eduPersonPrincipalName=groupersystem)(objectClass=eduPerson))
>> Oct 16 15:13:35 pen slapd[9559]: => get_ctrls Oct 16 15:13:35 pen 
>> slapd[9559]: => get_ctrls:
>> oid="2.16.840.1.113730.3.4.2" (noncritical) Oct 16 15:13:35 pen 
>> slapd[9559]: <= get_ctrls: n=1 rc=0 err=""
>> Oct 16 15:13:35 pen slapd[9559]:     attrs:
>> Oct 16 15:13:35 pen slapd[9559]:  cn
>> Oct 16 15:13:35 pen slapd[9559]:  cn
>> Oct 16 15:13:35 pen slapd[9559]:  eduPersonPrincipalName Oct 16 
>> 15:13:35 pen slapd[9559]:
>> Oct 16 15:13:35 pen slapd[9559]: conn=10 op=1 SRCH 
>> base="ou=people,dc=ncl,dc=ac,dc=uk" scope=2 deref=3
>> 
>filter="(&(eduPersonPrincipalName=groupersystem)(objectClass=eduPerson
>> ))
>> "
>> Oct 16 15:13:35 pen slapd[9559]: conn=10 op=1 SRCH attr=cn cn 
>> eduPersonPrincipalName Oct 16 15:13:35 pen slapd[9559]: 
>> slap_global_control: unavailable
>> control: 2.16.840.1.113730.3.4.2
>> Oct 16 15:13:35 pen slapd[9559]: => bdb_search Oct 16 15:13:35 pen 
>> slapd[9559]:
>> bdb_dn2entry("ou=people,dc=ncl,dc=ac,dc=uk")
>> Oct 16 15:13:35 pen slapd[9559]: search_candidates:
>> base="ou=people,dc=ncl,dc=ac,dc=uk" (0x0000004d) scope=2 Oct 16 
>> 15:13:35 pen slapd[9559]: => bdb_filter_candidates
>> Oct 16 15:13:35 pen slapd[9559]:     EQUALITY
>> Oct 16 15:13:35 pen slapd[9559]: => bdb_equality_candidates
>> (objectClass)
>> Oct 16 15:13:35 pen slapd[9559]: => key_read Oct 16 15:13:35 pen 
>> slapd[9559]: bdb_idl_fetch_key: [01872a84] Oct 16 15:13:35 pen 
>> slapd[9559]: <= bdb_index_read: failed (-30989) Oct 16 15:13:35 pen 
>> slapd[9559]: <= bdb_equality_candidates: id=0, first=0, 
>last=0 Oct 16 
>> 15:13:35 pen slapd[9559]: <= bdb_filter_candidates: id=0 first=0 
>> last=0 Oct 16 15:13:35 pen slapd[9559]: =>
>> bdb_dn2idl("ou=people,dc=ncl,dc=ac,dc=uk")
>> Oct 16 15:13:35 pen slapd[9559]: bdb_idl_fetch_key:
>> @ou=people,dc=ncl,dc=ac,dc=uk
>> Oct 16 15:13:35 pen slapd[9559]: <= bdb_dn2idl: id=9 
>first=77 last=135 
>> Oct 16 15:13:35 pen slapd[9559]: => bdb_filter_candidates
>> Oct 16 15:13:35 pen slapd[9559]:     AND
>> Oct 16 15:13:35 pen slapd[9559]: => bdb_list_candidates 0xa0 Oct 16 
>> 15:13:35 pen slapd[9559]: => bdb_filter_candidates
>> Oct 16 15:13:35 pen slapd[9559]:     AND
>> Oct 16 15:13:35 pen slapd[9559]: => bdb_list_candidates 0xa0 Oct 16 
>> 15:13:35 pen slapd[9559]: => bdb_filter_candidates
>> Oct 16 15:13:35 pen slapd[9559]:     EQUALITY
>> Oct 16 15:13:35 pen slapd[9559]: => bdb_equality_candidates
>> (eduPersonPrincipalName)
>> Oct 16 15:13:35 pen slapd[9559]: <= bdb_equality_candidates:
>> (eduPersonPrincipalName) index_param failed (18) Oct 16 15:13:35 pen 
>> slapd[9559]: <= bdb_filter_candidates: id=-1 first=1
>> last=135
>> Oct 16 15:13:35 pen slapd[9559]: => bdb_filter_candidates
>> Oct 16 15:13:35 pen slapd[9559]:     EQUALITY
>> Oct 16 15:13:35 pen slapd[9559]: => bdb_equality_candidates
>> (objectClass)
>> Oct 16 15:13:35 pen slapd[9559]: => key_read Oct 16 15:13:35 pen 
>> slapd[9559]: bdb_idl_fetch_key: [aef9a643] Oct 16 15:13:35 pen 
>> slapd[9559]: <= bdb_index_read 8 candidates Oct 16 15:13:35 pen 
>> slapd[9559]: <= bdb_equality_candidates: id=8, first=128, 
>last=135 Oct 
>> 16 15:13:35 pen slapd[9559]: <= bdb_filter_candidates: id=8
>> first=128 last=135
>> Oct 16 15:13:35 pen slapd[9559]: <= bdb_list_candidates: id=-1 
>> first=128
>> last=135
>> Oct 16 15:13:35 pen slapd[9559]: <= bdb_filter_candidates: id=-1
>> first=128 last=135
>> Oct 16 15:13:35 pen slapd[9559]: <= bdb_list_candidates: id=8 
>> first=128
>> last=135
>> Oct 16 15:13:35 pen slapd[9559]: <= bdb_filter_candidates: id=8
>> first=128 last=135
>> Oct 16 15:13:35 pen slapd[9559]: bdb_search_candidates: id=8 
>first=128
>> last=135
>> Oct 16 15:13:35 pen slapd[9559]: => test_filter
>> Oct 16 15:13:35 pen slapd[9559]:     AND
>> Oct 16 15:13:35 pen slapd[9559]: => test_filter_and Oct 16 15:13:35 
>> pen slapd[9559]: => test_filter
>> Oct 16 15:13:35 pen slapd[9559]:     EQUALITY
>> Oct 16 15:13:35 pen slapd[9559]: => access_allowed: search access to 
>> "uid=gene.wilder@hotmail.com,ou=people,dc=ncl,dc=ac,dc=uk"
>> "eduPersonPrincipalName" requested
>> Oct 16 15:13:35 pen slapd[9559]: <= root access granted Oct 16 
>> 15:13:35 pen slapd[9559]: <= test_filter 5 Oct 16 15:13:35 pen 
>> slapd[9559]: <= test_filter_and 5 Oct 16 15:13:35 pen 
>slapd[9559]: <= 
>> test_filter 5 Oct 16 15:13:35 pen slapd[9559]: bdb_search: 128 does 
>> not match filter Oct 16 15:13:35 pen slapd[9559]: => test_filter
>> Oct 16 15:13:35 pen slapd[9559]:     AND
>> Oct 16 15:13:35 pen slapd[9559]: => test_filter_and Oct 16 15:13:35 
>> pen slapd[9559]: => test_filter
>> Oct 16 15:13:35 pen slapd[9559]:     EQUALITY
>> Oct 16 15:13:35 pen slapd[9559]: => access_allowed: search access to 
>> "uid=lionel.messi@hotmail.com,ou=people,dc=ncl,dc=ac,dc=uk"
>> "eduPersonPrincipalName" requested
>> Oct 16 15:13:35 pen slapd[9559]: <= root access granted Oct 16 
>> 15:13:35 pen slapd[9559]: <= test_filter 5 Oct 16 15:13:35 pen 
>> slapd[9559]: <= test_filter_and 5 Oct 16 15:13:35 pen 
>slapd[9559]: <= 
>> test_filter 5 Oct 16 15:13:35 pen slapd[9559]: bdb_search: 135 does 
>> not match filter Oct 16 15:13:35 pen slapd[9559]: send_ldap_result: 
>> conn=10 op=1 p=3 Oct 16 15:13:35 pen slapd[9559]: send_ldap_result: 
>> err=0 matched=""
>> text=""
>> Oct 16 15:13:35 pen slapd[9559]: send_ldap_response: msgid=2 tag=101 
>> err=0 Oct 16 15:13:35 pen slapd[9559]: conn=10 op=1 SEARCH RESULT 
>> tag=101 err=0 nentries=0 text= Oct 16 15:13:35 pen slapd[9559]: 
>> daemon: activity on 1 descriptor Oct 16 15:13:35 pen slapd[9559]: 
>> daemon: activity on:
>> Oct 16 15:13:35 pen slapd[9559]:  15r
>> Oct 16 15:13:35 pen slapd[9559]:
>> Oct 16 15:13:35 pen slapd[9559]: daemon: read active on 15 Oct 16 
>> 15:13:35 pen slapd[9559]: connection_get(15) Oct 16 15:13:35 pen 
>> slapd[9559]: connection_get(15): got connid=10 Oct 16 15:13:35 pen 
>> slapd[9559]: connection_read(15): checking for input on id=10 Oct 16 
>> 15:13:35 pen slapd[9559]: ber_get_next on fd 15 failed errno=0
>> (Success)
>> Oct 16 15:13:35 pen slapd[9559]: connection_read(15): input error=-2 
>> id=10, closing.
>> Oct 16 15:13:35 pen slapd[9559]: connection_closing: readying conn=10
>> sd=15 for close
>> Oct 16 15:13:35 pen slapd[9559]: connection_close: deferring conn=10
>> sd=15
>> Oct 16 15:13:35 pen slapd[9559]: daemon: select: listen=7 
>> active_threads=0 tvp=NULL Oct 16 15:13:35 pen slapd[9559]: daemon: 
>> select: listen=8 active_threads=0 tvp=NULL Oct 16 15:13:35 pen 
>> slapd[9559]: daemon: activity on 1 descriptor Oct 16 15:13:35 pen 
>> slapd[9559]: daemon: activity on:
>> Oct 16 15:13:35 pen slapd[9559]:
>> Oct 16 15:13:35 pen slapd[9559]: daemon: select: listen=7 
>> active_threads=0 tvp=NULL Oct 16 15:13:35 pen slapd[9559]: daemon: 
>> select: listen=8 active_threads=0 tvp=NULL Oct 16 15:13:35 pen 
>> slapd[9559]: do_unbind Oct 16 15:13:35 pen slapd[9559]: conn=10 op=2 
>> UNBIND Oct 16 15:13:35 pen slapd[9559]: connection_resched: 
>attempting 
>> closing conn=10 sd=15 Oct 16 15:13:35 pen slapd[9559]: 
>> connection_close: conn=10 sd=15 Oct 16 15:13:35 pen slapd[9559]: 
>> daemon: removing 15 Oct 16 15:13:35 pen slapd[9559]: conn=10 fd=15 
>> closed Oct 16 15:13:35 pen slapd[9559]: daemon: activity on 1 
>> descriptor Oct 16 15:13:35 pen slapd[9559]: daemon: activity on:
>> Oct 16 15:13:35 pen slapd[9559]:  13r
>> Oct 16 15:13:35 pen slapd[9559]:
>> Oct 16 15:13:35 pen slapd[9559]: daemon: read active on 13 Oct 16 
>> 15:13:35 pen slapd[9559]: connection_get(13) Oct 16 15:13:35 pen 
>> slapd[9559]: connection_get(13): got connid=8 Oct 16 15:13:35 pen 
>> slapd[9559]: connection_read(13): checking for input on id=8 Oct 16 
>> 15:13:35 pen slapd[9559]: ber_get_next on fd 13 failed errno=11 
>> (Resource temporarily unavailable) Oct 16 15:13:35 pen slapd[9559]: 
>> daemon: select: listen=7 active_threads=0 tvp=NULL Oct 16 
>15:13:35 pen 
>> slapd[9559]: daemon: select: listen=8 active_threads=0 
>tvp=NULL Oct 16 
>> 15:13:35 pen slapd[9559]: do_unbind Oct 16 15:13:35 pen slapd[9559]: 
>> conn=8 op=1 UNBIND Oct 16 15:13:35 pen slapd[9559]: 
>> connection_closing: readying conn=8
>> sd=13 for close
>> Oct 16 15:13:35 pen slapd[9559]: connection_resched: attempting 
>> closing
>> conn=8 sd=13
>> Oct 16 15:13:35 pen slapd[9559]: connection_close: conn=8 
>sd=13 Oct 16 
>> 15:13:35 pen slapd[9559]: daemon: removing 13 Oct 16 15:13:35 pen 
>> slapd[9559]: conn=8 fd=13 closed Oct 16 15:13:35 pen slapd[9559]: 
>> daemon: activity on 1 descriptor Oct 16 15:13:35 pen slapd[9559]: 
>> daemon: activity on:
>> Oct 16 15:13:35 pen slapd[9559]:  13r
>> Oct 16 15:13:35 pen slapd[9559]:
>> Oct 16 15:13:35 pen slapd[9559]: daemon: read active on 13 Oct 16 
>> 15:13:35 pen slapd[9559]: connection_get(13) Oct 16 15:13:35 pen 
>> slapd[9559]: connection_get(13): connection not used Oct 16 15:13:35 
>> pen slapd[9559]: connection_read(13): no connection!
>> Oct 16 15:13:35 pen slapd[9559]: daemon: select: listen=7 
>> active_threads=0 tvp=NULL Oct 16 15:13:35 pen slapd[9559]: daemon: 
>> select: listen=8 active_threads=0 tvp=NULL Oct 16 15:13:35 pen 
>> slapd[9559]: daemon: activity on 1 descriptor Oct 16 15:13:35 pen 
>> slapd[9559]: daemon: activity on:
>> Oct 16 15:13:35 pen slapd[9559]:
>> Oct 16 15:13:35 pen slapd[9559]: daemon: select: listen=7 
>> active_threads=0 tvp=NULL Oct 16 15:13:35 pen slapd[9559]: daemon: 
>> select: listen=8 active_threads=0 tvp=NULL
>>
>> Regards
>> --------------
>> Sanjay Vivek
>> Middleware Team
>> ISS
>> University of Newcastle Upon Tyne
>>
>>
>
Follow-Ups:
- Re: LDAP provisioning error.
  - From: Buchan Milne <bgmilne@staff.telkomsa.net>
Prev by Date: Re: When to delete client content during RFC4533 synchronization?
Next by Date: Re: LDAP provisioning error.
Index(es):
- Chronological
- Thread