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 &quot;uid=gene.wilder(a)hotmail.com,ou=people,dc=ncl,dc=ac,dc=uk&quot; "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 &quot;uid=lionel.messi(a)hotmail.com,ou=people,dc=ncl,dc=ac,dc=uk&quot; "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

-----Original Message----- From: Aaron Richton [mailto:richton@nbcs.rutgers.edu] Sent: 29 October 2007 18:47 To: Sanjay Vivek Cc: openldap-software(a)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 > &quot;uid=gene.wilder(a)hotmail.com,ou=people,dc=ncl,dc=ac,dc=uk&quot; > "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 > &quot;uid=lionel.messi(a)hotmail.com,ou=people,dc=ncl,dc=ac,dc=uk&quot; > "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 > >

-----Original Message----- From: Buchan Milne [mailto:bgmilne@staff.telkomsa.net] Sent: 02 November 2007 15:59 To: openldap-software(a)openldap.org Cc: Sanjay Vivek Subject: Re: LDAP provisioning error. On Friday 02 November 2007 15:11:29 Sanjay Vivek wrote: > 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(a)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(a)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. Yes, these are fairly standard groupOfNames groups .... > 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. From your logs below, it doesn't seem so ... > 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/openlda > p- 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. Well, slapd was evidently still running. Maybe you should rather set: loglevel acl in slapd.conf, and restart slapd via the normal means you use to start slapd, ensure that syslog is configured to log the facility slapd logs to (local4 by default), and then look for the errors. However, so far ACLs don't seem to be the problem. > 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. Except while your LDAP server is "working" ... > From what I gather while trawling through the mailing lists, this > could be an Ipv6 issue. ??????? > Is this indeed the case? No, you can't run two processes listening on the same port and IP. > 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= So, it found no entry from the search it ran with the filter specified. Inspect your data, and see why this is the case. Do a search with the same filter/base/scope as the same DN, if you think the data is right ... > 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 At present, you've provided us with most things we would need, except the data you have, so we can't see why your application isn't finding the data it wants ... and this could simply be because it isn't there ... Regards, Buchan

-----Original Message----- From: Buchan Milne [mailto:bgmilne@staff.telkomsa.net] Sent: 06 November 2007 15:27 To: Sanjay Vivek Cc: openldap-software(a)openldap.org Subject: Re: LDAP provisioning error. On Tuesday 06 November 2007 16:49:29 Sanjay Vivek wrote: > Hi again, > > I don't think the errors have anything to with the LDAP search filter > because it works perfectly fine with a similar installation with > another LDAP server. The only difference between both installions is > the LDAP server. So something about my openLDAP configuration is > messing up the LDAP provisioning. But thus far you haven't provided anything that anyone can use to try and find out what is wrong with your configuration. Please try and include logs relating to all the operations on a connection, where an ADD, MOD, or DEL operation is done on the connection. A connection with one bind and one search, is almost useless (unless you can show the data in the directory that should be found by that search). > > I did a "ps -fade | grep slapd" > > [root@pen openldap]# ps -fade | grep slapd > ldap 29465 1 0 11:51 ? 00:00:00 /usr/sbin/slapd -h > ldap:/// -u ldap > root 29616 28950 0 13:53 pts/0 00:00:00 grep slapd > > So this means that only one instance of slapd is running. BUT YOU ARE NOW ABOUT TO TRY TO START A SECOND ONE!!!!! > So why do I > get a "daemon: bind(7) failed errno=98 (Address already in use)" error > when I run "slapd -d acl" as shown below: > > [root@pen openldap]# slapd -d acl But, this is starting slapd. By default, it will try and bind to port 389 on all IPs. So, you should stop this one, if you *really* want to start a slapd as above. Instead, maybe you should add: loglevel acl and restart the ldap service ('service ldap restart'), and then (if your syslog is configured to log for slapd) you should end up with acl-related entries in your log files. Regards, Buchan