CUCM search - openldap-technical

29 Nov 2011


      Hello,
I'v implemented a OpenLDAP Metadirectory that proxying 2 Microsft AD targets.
Cisco Unified Call Manager (CUCM) sends a rather simpy query:
(&(objectclass=user)(!(objectclass=Computer)))
If CUCM connects AD server directly, all is OK, gets a search result. But sending this search to Meta, does not work.
Log:
Nov 28 20:27:39 walrhel5 slapd[7447]: ber_get_next on fd 10 failed errno=0 (Success)
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_read(10): input error=-2 id=1000, closing.
If I send the same search with various LDAP-Browsers (Softerra, LDP, Perlscript...), all is OK.
I tried witch OpenLDAP version: 2.4.26 and 2.4.28
My config:
include         /usr/local/etc/openldap/schema/core.schema
pidfile         /usr/local/var/run/slapd.pid
argsfile        /usr/local/var/run/slapd.args
loglevel -1
#######################################################################
database        meta
lastmod         off
suffix                  "dc=meta,dc=pov"
rootdn          "cn=metaguru,dc=meta,dc=pov"
rootpw          XXXXXXX
uri                             "ldap://10.11.11.112:389/dc=meta,dc=pov"
suffixmassage           "dc=meta,dc=pov" "dc=adwal,dc=corporate,dc=net"
idassert-authzFrom      "dn:*"
idassert-bind           bindmethod=simple
                        binddn="cn=radiator,cn=Users,dc=adwal,dc=corporate,dc=net"
                        credentials="XXXXXXX"
                        mode=none
uri                             "ldap://10.11.11.114:389/dc=meta,dc=pov"
suffixmassage           "dc=meta,dc=pov" "dc=second,dc=crocus,dc=com"
idassert-authzFrom      "dn:*"
idassert-bind           bindmethod=simple
                        binddn="cn=predator,cn=Users,dc=second,dc=crocus,dc=com"
                        credentials="XXXXXXX"
                        mode=none
Full Log:
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 fd=10 ACCEPT from IP=10.11.11.119:40478 (IP=0.0.0.0:389)
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_get(10)
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_get(10): got connid=1000
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_read(10): checking for input on id=1000
Nov 28 20:27:39 walrhel5 slapd[7447]: op tag 0x60, time 1322508459
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=0 do_bind
Nov 28 20:27:39 walrhel5 slapd[7447]: >>> dnPrettyNormal: <cn=metaguru,dc=meta,dc=pov>
Nov 28 20:27:39 walrhel5 slapd[7447]: <<< dnPrettyNormal: <cn=metaguru,dc=meta,dc=pov>, <cn=metaguru,dc=meta,dc=pov>
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=0 BIND dn="cn=metaguru,dc=meta,dc=pov" method=128
Nov 28 20:27:39 walrhel5 slapd[7447]: do_bind: version=3 dn="cn=metaguru,dc=meta,dc=pov" method=128
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=0 meta_back_bind: dn="cn=metaguru,dc=meta,dc=pov".
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=0: rootdn="cn=metaguru,dc=meta,dc=pov" bind succeeded
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=0 BIND dn="cn=metaguru,dc=meta,dc=pov" mech=SIMPLE ssf=0
Nov 28 20:27:39 walrhel5 slapd[7447]: do_bind: v3 bind: "cn=metaguru,dc=meta,dc=pov" to "cn=metaguru,dc=meta,dc=pov"
Nov 28 20:27:39 walrhel5 slapd[7447]: send_ldap_result: conn=1000 op=0 p=3
Nov 28 20:27:39 walrhel5 slapd[7447]: send_ldap_result: err=0 matched="" text=""
Nov 28 20:27:39 walrhel5 slapd[7447]: send_ldap_response: msgid=1 tag=97 err=0
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=0 RESULT tag=97 err=0 text=
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_get(10)
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_get(10): got connid=1000
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_read(10): checking for input on id=1000
Nov 28 20:27:39 walrhel5 slapd[7447]: op tag 0x63, time 1322508459
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 do_search
Nov 28 20:27:39 walrhel5 slapd[7447]: >>> dnPrettyNormal: <dc=meta,dc=pov>
Nov 28 20:27:39 walrhel5 slapd[7447]: <<< dnPrettyNormal: <dc=meta,dc=pov>, <dc=meta,dc=pov>
Nov 28 20:27:39 walrhel5 slapd[7447]: SRCH "dc=meta,dc=pov" 0 3
Nov 28 20:27:39 walrhel5 slapd[7447]:     0 0 0
Nov 28 20:27:39 walrhel5 slapd[7447]: begin get_filter
Nov 28 20:27:39 walrhel5 slapd[7447]: AND
Nov 28 20:27:39 walrhel5 slapd[7447]: begin get_filter_list
Nov 28 20:27:39 walrhel5 slapd[7447]: begin get_filter
Nov 28 20:27:39 walrhel5 slapd[7447]: EQUALITY
Nov 28 20:27:39 walrhel5 slapd[7447]: get_ava: illegal value for attributeType objectclass
Nov 28 20:27:39 walrhel5 slapd[7447]: end get_filter 0
Nov 28 20:27:39 walrhel5 slapd[7447]: begin get_filter
Nov 28 20:27:39 walrhel5 slapd[7447]: NOT
Nov 28 20:27:39 walrhel5 slapd[7447]: begin get_filter
Nov 28 20:27:39 walrhel5 slapd[7447]: EQUALITY
Nov 28 20:27:39 walrhel5 slapd[7447]: get_ava: illegal value for attributeType objectclass
Nov 28 20:27:39 walrhel5 slapd[7447]: end get_filter 0
Nov 28 20:27:39 walrhel5 slapd[7447]: end get_filter 0
Nov 28 20:27:39 walrhel5 slapd[7447]: end get_filter_list
Nov 28 20:27:39 walrhel5 slapd[7447]: end get_filter 0
Nov 28 20:27:39 walrhel5 slapd[7447]:     filter: (&(?objectClass=user)(!(?objectClass=Computer)))
Nov 28 20:27:39 walrhel5 slapd[7447]: => get_ctrls
Nov 28 20:27:39 walrhel5 slapd[7447]: => get_ctrls: oid="2.16.840.1.113730.3.4.2" (noncritical)
Nov 28 20:27:39 walrhel5 slapd[7447]: <= get_ctrls: n=1 rc=0 err=""
Nov 28 20:27:39 walrhel5 slapd[7447]:     attrs:
Nov 28 20:27:39 walrhel5 slapd[7447]:
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 SRCH base="dc=meta,dc=pov" scope=0 deref=3 filter="(&(?objectClass=user)(!(?objectClass=Computer)))"
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1: meta_back_getconn[0]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1: meta_back_getconn[1]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 meta_back_getconn: candidates=2 conn=ROOTDN inserted
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 >>> meta_back_search_start[0]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 >>> meta_search_dobind_init[0]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 <<< meta_search_dobind_init[0]=4
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 <<< meta_back_search_start[0]=4
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 >>> meta_back_search_start[1]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 >>> meta_search_dobind_init[1]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 <<< meta_search_dobind_init[1]=4
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 <<< meta_back_search_start[1]=4
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 meta_back_search: ncandidates=2 cnd="**"
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 >>> meta_search_dobind_init[0]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 <<< meta_search_dobind_init[0]=2
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 >>> meta_search_dobind_init[1]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 <<< meta_search_dobind_init[1]=2
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 >>> meta_back_search_start[0]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 >>> meta_search_dobind_init[0]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 <<< meta_search_dobind_init[0]=1
Nov 28 20:27:39 walrhel5 slapd[7447]: ==> rewrite_context_apply [depth=1] string='dc=meta,dc=pov'
Nov 28 20:27:39 walrhel5 slapd[7447]: ==> rewrite_rule_apply rule='((.+),)?dc=meta,[ ]?dc=pov$' string='dc=meta,dc=pov' [1 pass(es)]
Nov 28 20:27:39 walrhel5 slapd[7447]: ==> rewrite_context_apply [depth=1] res={0,'dc=adwal,dc=corporate,dc=net'}
Nov 28 20:27:39 walrhel5 slapd[7447]: [rw] searchBase: "dc=meta,dc=pov" -> "dc=adwal,dc=corporate,dc=net"
Nov 28 20:27:39 walrhel5 slapd[7447]: ==> rewrite_context_apply [depth=1] string='(&(objectClass=user)(!(objectClass=Computer)))'
Nov 28 20:27:39 walrhel5 slapd[7447]: ==> rewrite_context_apply [depth=1] res={0,'NULL'}
Nov 28 20:27:39 walrhel5 slapd[7447]: [rw] searchFilter: "(&(objectClass=user)(!(objectClass=Computer)))" -> "(&(objectClass=user)(!(objectClass=Computer)))"
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 <<< meta_back_search_start[0]=1
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 >>> meta_back_search_start[1]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 >>> meta_search_dobind_init[1]
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 <<< meta_search_dobind_init[1]=1
Nov 28 20:27:39 walrhel5 slapd[7447]: ==> rewrite_context_apply [depth=1] string='dc=meta,dc=pov'
Nov 28 20:27:39 walrhel5 slapd[7447]: ==> rewrite_rule_apply rule='((.+),)?dc=meta,[ ]?dc=pov$' string='dc=meta,dc=pov' [1 pass(es)]
Nov 28 20:27:39 walrhel5 slapd[7447]: ==> rewrite_context_apply [depth=1] res={0,'dc=second,dc=crocus,dc=com'}
Nov 28 20:27:39 walrhel5 slapd[7447]: [rw] searchBase: "dc=meta,dc=pov" -> "dc=second,dc=crocus,dc=com"
Nov 28 20:27:39 walrhel5 slapd[7447]: ==> rewrite_context_apply [depth=1] string='(&(objectClass=user)(!(objectClass=Computer)))'
Nov 28 20:27:39 walrhel5 slapd[7447]: ==> rewrite_context_apply [depth=1] res={0,'NULL'}
Nov 28 20:27:39 walrhel5 slapd[7447]: [rw] searchFilter: "(&(objectClass=user)(!(objectClass=Computer)))" -> "(&(objectClass=user)(!(objectClass=Computer)))"
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 <<< meta_back_search_start[1]=1
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 meta_back_search[0] match="" err=0.
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 meta_back_search[1] match="" err=0.
Nov 28 20:27:39 walrhel5 slapd[7447]: send_ldap_result: conn=1000 op=1 p=3
Nov 28 20:27:39 walrhel5 slapd[7447]: send_ldap_result: err=0 matched="" text=""
Nov 28 20:27:39 walrhel5 slapd[7447]: send_ldap_response: msgid=2 tag=101 err=0
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=1 SEARCH RESULT tag=101 err=0 nentries=0 text=
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_get(10)
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_get(10): got connid=1000
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_read(10): checking for input on id=1000
Nov 28 20:27:39 walrhel5 slapd[7447]: op tag 0x42, time 1322508459
Nov 28 20:27:39 walrhel5 slapd[7447]: ber_get_next on fd 10 failed errno=0 (Success)
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_read(10): input error=-2 id=1000, closing.
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_closing: readying conn=1000 sd=10 for close
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_close: deferring conn=1000 sd=10
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=2 do_unbind
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 op=2 UNBIND
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_resched: attempting closing conn=1000 sd=10
Nov 28 20:27:39 walrhel5 slapd[7447]: connection_close: conn=1000 sd=10
Nov 28 20:27:39 walrhel5 slapd[7447]: =>meta_back_conn_destroy: fetching conn=1000 DN="cn=metaguru,dc=meta,dc=pov"
Nov 28 20:27:39 walrhel5 slapd[7447]: daemon: removing 10
Nov 28 20:27:39 walrhel5 slapd[7447]: conn=1000 fd=10 closed
Where is my mistake ? Can you help me please
Kind regards
Waldemar