"do_bind: invalid dn" while trying to monitor slapd using pacemaker `slapd' resource agent
Hello.
I'm deploing mirrormode openldap cluster. I have two hosts running openSUSE 12.1 with openldap2-2.4.30-83.3.x86_64
I created special user for mirrormode and tuned limits, so replication works fine.
But for transparent switch between two nodes in case of failure i need some additional software to monitor ldap daemons and manage IP addresses on which my consumers connect.
So i went for pacemaker and used following document to set it up: http://www.daasi.de/ldapcon2011/downloads/Haferkamp-paper.pdf
I decided to create a special uid for monitoring my tree which can read only root element: ldap2:~# grep -C 2 pcmk /etc/openldap/slapd.conf # access to dn.base="dc=test,dc=org" by dn="uid=slapd-pcmk,ou=Services,dc=test,dc=org" read
And here is my problem: I can successfully execute search query by hands using ldapsearch(1): ldap2:~# ldapsearch -H "ldap:/// ldaps:/// ldapi:///" -b dc=test,dc=org -LLL -s base -x -D 'uid=slapd-pcmk,ou=Services,dc=test,dc=org -w 'P@ssw0rd,' Enter LDAP Password: dn: dc=test,dc=org dc: test objectClass: organization objectClass: dcObject o: Test org ldap2:~# echo $? 0
Pacemaker uses resource agents to monitor various daemons, so i downloaded resource agent for slapd. Resource agent is just a script file (e.g. resource agent for slapd) and it executes same query as i do by hand, but slapd complains about "invalid dn": Here is how slapd resource was defined: ldap2:~# crm configure primitive slapd_mirrormode ocf:heartbeat:slapd params \ slapd="/usr/lib/openldap/slapd" config="/etc/openldap/slapd.conf" \ user="ldap" group="ldap" services="ldap:/// ldaps:/// ldapi:///" \ watch_suffix="dc=test,dc=org" \ bind_dn="uid=slapd-pcmk,ou=Services,dc=test,dc=org" \ password="P@ssw0rd," parameters="-o slp=on" \ meta migration-threshold="3" op monitor interval="10s"
I changed loglevel in slapd to `1' and see following in log: May 16 13:07:00 ldap2 slapd[7641]: slap_listener_activate(8): May 16 13:07:00 ldap2 slapd[7641]: >>> slap_listener(ldap:///) May 16 13:07:00 ldap2 slapd[7641]: connection_get(17): got connid=1013 May 16 13:07:00 ldap2 slapd[7641]: connection_read(17): checking for input on id=1013 May 16 13:07:00 ldap2 slapd[7641]: op tag 0x60, time 1337159220 May 16 13:07:00 ldap2 slapd[7641]: conn=1013 op=0 do_bind May 16 13:07:00 ldap2 slapd[7641]: >>> dnPrettyNormal: <'uid=slapd-pcmk,ou=Services,dc=test,dc=org'> May 16 13:07:00 ldap2 slapd[7641]: conn=1013 op=0 do_bind: invalid dn ('uid=slapd-pcmk,ou=Services,dc=test,dc=org') May 16 13:07:00 ldap2 slapd[7641]: send_ldap_result: conn=1013 op=0 p=3 May 16 13:07:00 ldap2 slapd[7641]: send_ldap_response: msgid=1 tag=97 err=34 May 16 13:07:00 ldap2 slapd[7641]: connection_get(17): got connid=1013 May 16 13:07:00 ldap2 slapd[7641]: connection_read(17): checking for input on id=1013 May 16 13:07:00 ldap2 slapd[7641]: op tag 0x42, time 1337159220 May 16 13:07:00 ldap2 slapd[7641]: conn=1013 op=1 do_unbind May 16 13:07:00 ldap2 slapd[7641]: connection_close: conn=1013 sd=17 May 16 13:07:01 ldap2 slapd[7641]: slap_listener_activate(8): May 16 13:07:01 ldap2 slapd[7641]: >>> slap_listener(ldap:///) May 16 13:07:01 ldap2 slapd[7641]: connection_get(17): got connid=1014 May 16 13:07:01 ldap2 slapd[7641]: connection_read(17): checking for input on id=1014 May 16 13:07:01 ldap2 slapd[7641]: op tag 0x60, time 1337159221 May 16 13:07:01 ldap2 slapd[7641]: conn=1014 op=0 do_bind May 16 13:07:01 ldap2 slapd[7641]: >>> dnPrettyNormal: <'uid=slapd-pcmk,ou=Services,dc=test,dc=org'> May 16 13:07:01 ldap2 slapd[7641]: conn=1014 op=0 do_bind: invalid dn ('uid=slapd-pcmk,ou=Services,dc=test,dc=org') May 16 13:07:01 ldap2 slapd[7641]: send_ldap_result: conn=1014 op=0 p=3 May 16 13:07:01 ldap2 slapd[7641]: send_ldap_response: msgid=1 tag=97 err=34 May 16 13:07:01 ldap2 slapd[7641]: connection_get(17): got connid=1014 May 16 13:07:01 ldap2 slapd[7641]: connection_read(17): checking for input on id=1014 May 16 13:07:01 ldap2 slapd[7641]: op tag 0x42, time 1337159221 May 16 13:07:01 ldap2 slapd[7641]: ber_get_next on fd 17 failed errno=0 (Success) May 16 13:07:01 ldap2 slapd[7641]: conn=1014 op=1 do_unbind May 16 13:07:01 ldap2 slapd[7641]: connection_close: conn=1014 sd=17 May 16 13:07:02 ldap2 slapd[7641]: slap_listener_activate(8): May 16 13:07:02 ldap2 slapd[7641]: >>> slap_listener(ldap:///) May 16 13:07:02 ldap2 slapd[7641]: connection_get(17): got connid=1015 May 16 13:07:02 ldap2 slapd[7641]: connection_read(17): checking for input on id=1015 May 16 13:07:02 ldap2 slapd[7641]: op tag 0x60, time 1337159222 May 16 13:07:02 ldap2 slapd[7641]: conn=1015 op=0 do_bind May 16 13:07:02 ldap2 slapd[7641]: >>> dnPrettyNormal: <'uid=slapd-pcmk,ou=Services,dc=test,dc=org'> May 16 13:07:02 ldap2 slapd[7641]: conn=1015 op=0 do_bind: invalid dn ('uid=slapd-pcmk,ou=Services,dc=test,dc=org') May 16 13:07:02 ldap2 slapd[7641]: send_ldap_result: conn=1015 op=0 p=3 May 16 13:07:02 ldap2 slapd[7641]: send_ldap_response: msgid=1 tag=97 err=34 May 16 13:07:02 ldap2 slapd[7641]: connection_get(17): got connid=1015 May 16 13:07:02 ldap2 slapd[7641]: connection_read(17): checking for input on id=1015 May 16 13:07:02 ldap2 slapd[7641]: op tag 0x42, time 1337159222 May 16 13:07:02 ldap2 slapd[7641]: conn=1015 op=1 do_unbind May 16 13:07:02 ldap2 slapd[7641]: connection_close: conn=1015 sd=17 May 16 13:07:04 ldap2 slapd[7641]: slap_listener_activate(8): May 16 13:07:04 ldap2 slapd[7641]: >>> slap_listener(ldap:///) May 16 13:07:04 ldap2 slapd[7641]: connection_get(17): got connid=1016 May 16 13:07:04 ldap2 slapd[7641]: connection_read(17): checking for input on id=1016 May 16 13:07:04 ldap2 slapd[7641]: op tag 0x60, time 1337159224 May 16 13:07:04 ldap2 slapd[7641]: conn=1016 op=0 do_bind May 16 13:07:04 ldap2 slapd[7641]: >>> dnPrettyNormal: <'uid=slapd-pcmk,ou=Services,dc=test,dc=org'> May 16 13:07:04 ldap2 slapd[7641]: conn=1016 op=0 do_bind: invalid dn ('uid=slapd-pcmk,ou=Services,dc=test,dc=org') May 16 13:07:04 ldap2 slapd[7641]: send_ldap_result: conn=1016 op=0 p=3 May 16 13:07:04 ldap2 slapd[7641]: send_ldap_response: msgid=1 tag=97 err=34 May 16 13:07:04 ldap2 slapd[7641]: connection_get(17): got connid=1016 May 16 13:07:04 ldap2 slapd[7641]: connection_read(17): checking for input on id=1016 May 16 13:07:04 ldap2 slapd[7641]: op tag 0x42, time 1337159224 May 16 13:07:04 ldap2 slapd[7641]: conn=1016 op=1 do_unbind May 16 13:07:04 ldap2 slapd[7641]: connection_close: conn=1016 sd=17 May 16 13:07:05 ldap2 slapd[7641]: slap_listener_activate(8): May 16 13:07:05 ldap2 slapd[7641]: >>> slap_listener(ldap:///) May 16 13:07:05 ldap2 slapd[7641]: connection_get(17): got connid=1017 May 16 13:07:05 ldap2 slapd[7641]: connection_read(17): checking for input on id=1017 May 16 13:07:05 ldap2 slapd[7641]: op tag 0x60, time 1337159225 May 16 13:07:05 ldap2 slapd[7641]: conn=1017 op=0 do_bind May 16 13:07:05 ldap2 slapd[7641]: >>> dnPrettyNormal: <'uid=slapd-pcmk,ou=Services,dc=test,dc=org'> May 16 13:07:05 ldap2 slapd[7641]: conn=1017 op=0 do_bind: invalid dn ('uid=slapd-pcmk,ou=Services,dc=test,dc=org') May 16 13:07:05 ldap2 slapd[7641]: send_ldap_result: conn=1017 op=0 p=3 May 16 13:07:05 ldap2 slapd[7641]: send_ldap_response: msgid=1 tag=97 err=34 May 16 13:07:05 ldap2 slapd[7641]: connection_get(17): got connid=1017 May 16 13:07:05 ldap2 slapd[7641]: connection_read(17): checking for input on id=1017 May 16 13:07:05 ldap2 slapd[7641]: op tag 0x42, time 1337159225 May 16 13:07:05 ldap2 slapd[7641]: conn=1017 op=1 do_unbind May 16 13:07:05 ldap2 slapd[7641]: connection_close: conn=1017 sd=17 May 16 13:07:06 ldap2 slapd[7641]: daemon: shutdown requested and initiated. May 16 13:07:06 ldap2 slapd[7641]: slapd shutdown: waiting for 1 operations/tasks to finish May 16 13:07:06 ldap2 slapd[7641]: slapd shutdown: initiated May 16 13:07:06 ldap2 slapd[7641]: ====> bdb_cache_release_all May 16 13:07:06 ldap2 slapd[7641]: slapd destroy: freeing system resources. May 16 13:07:06 ldap2 slapd[7641]: syncinfo_free: rid=001 May 16 13:07:06 ldap2 slapd[7641]: connection_get(14): got connid=0 May 16 13:07:06 ldap2 slapd[7641]: slapd stopped.
I understand that there might be a problem in pacemakers `slapd' resource agent. Maybe it corrupts bind dn somehow...
Agent executes `monitor' operation, here is a snippet from resource agent code: ldap2:~# less /usr/lib/ocf/resource.d/heartbeat/slapd ... slapd_monitor() { ... options="-LLL -s base -x"
if [ -n "$bind_dn" ]; then options="$options -D '$bind_dn' -w '$password'" fi
[ -z "$1" ] && err_option="" for suffix in $suffixes; do ocf_run -q $err_option "$ldapsearch" -H "$services" -b "$suffix" $options >/dev/null 2>&1; rc=$?
case "$rc" in "0") ocf_log debug "slapd database with suffix '$suffix' reachable" ;; "49") ocf_log err "slapd database with suffix '$suffix' unreachable. Invalid credentials." return $OCF_ERR_CONFIGURED ;; *) if [ -z "$1" ] || [ -n "$1" -a $rc -ne 1 ]; then ocf_log err "slapd database with suffix '$suffix' unreachable. exit code ($rc)" fi ...
Still scratching head...
On Wednesday, 16 May 2012 11:33:02 Igor Zinovik wrote:
And here is my problem: I can successfully execute search query by hands using ldapsearch(1): ldap2:~# ldapsearch -H "ldap:/// ldaps:/// ldapi:///" -b dc=test,dc=org -LLL -s base -x -D 'uid=slapd-pcmk,ou=Services,dc=test,dc=org -w 'P@ssw0rd,' Enter LDAP Password: dn: dc=test,dc=org dc: test objectClass: organization objectClass: dcObject o: Test org ldap2:~# echo $? 0
Pacemaker uses resource agents to monitor various daemons, so i downloaded resource agent for slapd. Resource agent is just a script file (e.g. resource agent for slapd) and it executes same query as i do by hand, but slapd complains about "invalid dn": Here is how slapd resource was defined: ldap2:~# crm configure primitive slapd_mirrormode ocf:heartbeat:slapd params \ slapd="/usr/lib/openldap/slapd" config="/etc/openldap/slapd.conf" \ user="ldap" group="ldap" services="ldap:/// ldaps:/// ldapi:///" \ watch_suffix="dc=test,dc=org" \ bind_dn="uid=slapd-pcmk,ou=Services,dc=test,dc=org" \ password="P@ssw0rd," parameters="-o slp=on" \ meta migration-threshold="3" op monitor interval="10s"
I changed loglevel in slapd to `1' and see following in log:
[...]
May 16 13:07:02 ldap2 slapd[7641]: conn=1015 op=0 do_bind: invalid dn ('uid=slapd-pcmk,ou=Services,dc=test,dc=org')
The single quotes are part of the DN being sent. For example:
$ ldapsearch -x -D "'uid=bgmilne,ou=People,dc=ranger,dc=dnsalias,dc=com'" ldap_bind: Invalid DN syntax (34) additional info: invalid DN
yields:
May 16 16:51:00 tiger slapd[6395]: conn=4082 fd=41 ACCEPT from PATH=/var/run/ldap/ldapi (PATH=/var/run/ldap/ldapi) May 16 16:51:00 tiger slapd[6395]: conn=4082 op=0 do_bind: invalid dn ('uid=bgmilne,ou=People,dc=ranger,dc=dnsalias,dc=com') May 16 16:51:00 tiger slapd[6395]: conn=4082 op=0 RESULT tag=97 err=34 text=invalid DN May 16 16:51:00 tiger slapd[6395]: conn=4082 fd=41 ACCEPT from PATH=/var/run/ldap/ldapi (PATH=/var/run/ldap/ldapi) May 16 16:51:00 tiger slapd[6395]: conn=4082 op=0 do_bind: invalid dn ('uid=bgmilne,ou=People,dc=ranger,dc=dnsalias,dc=com') May 16 16:51:00 tiger slapd[6395]: conn=4082 op=0 RESULT tag=97 err=34 text=invalid DN May 16 16:51:00 tiger slapd[6395]: conn=4082 op=1 UNBIND May 16 16:51:00 tiger slapd[6395]: conn=4082 fd=41 closed May 16 16:51:00 tiger slapd[6395]: conn=4082 op=1 UNBIND May 16 16:51:00 tiger slapd[6395]: conn=4082 fd=41 closed
Whereas:
$ ldapsearch -x -D "uid=bgmilne,ou=People,dc=ranger,dc=dnsalias,dc=com" ldap_bind: Server is unwilling to perform (53) additional info: unauthenticated bind (DN with no password) disallowed
yields:
May 16 16:51:05 tiger slapd[6395]: conn=4083 fd=41 ACCEPT from PATH=/var/run/ldap/ldapi (PATH=/var/run/ldap/ldapi) May 16 16:51:05 tiger slapd[6395]: conn=4083 fd=41 ACCEPT from PATH=/var/run/ldap/ldapi (PATH=/var/run/ldap/ldapi) May 16 16:51:05 tiger slapd[6395]: conn=4083 op=0 BIND dn="uid=bgmilne,ou=People,dc=ranger,dc=dnsalias,dc=com" method=128 May 16 16:51:05 tiger slapd[6395]: conn=4083 op=0 RESULT tag=97 err=53 text=unauthenticated bind (DN with no password) disallowed May 16 16:51:05 tiger slapd[6395]: conn=4083 op=0 BIND dn="uid=bgmilne,ou=People,dc=ranger,dc=dnsalias,dc=com" method=128 May 16 16:51:05 tiger slapd[6395]: conn=4083 op=0 RESULT tag=97 err=53 text=unauthenticated bind (DN with no password) disallowed
and:
$ ldapsearch -x -D "xxxx" ldap_bind: Invalid DN syntax (34) additional info: invalid DN
yields:
May 16 16:56:23 May 16 16:56:23 tiger slapd[6395]: conn=4085 fd=41 ACCEPT from PATH=/var/run/ldap/ldapi (PATH=/var/run/ldap/ldapi) May 16 16:56:23 tiger slapd[6395]: conn=4085 fd=41 ACCEPT from PATH=/var/run/ldap/ldapi (PATH=/var/run/ldap/ldapi) May 16 16:56:23 tiger slapd[6395]: conn=4085 op=0 do_bind: invalid dn (xxxx) May 16 16:56:23 tiger slapd[6395]: conn=4085 op=0 RESULT tag=97 err=34 text=invalid DN May 16 16:56:23 tiger slapd[6395]: conn=4085 op=0 do_bind: invalid dn (xxxx) May 16 16:56:23 tiger slapd[6395]: conn=4085 op=0 RESULT tag=97 err=34 text=invalid DNtiger slapd[6395]: conn=4085 fd=41 ACCEPT from PATH=/var/run/ldap/ldapi (PATH=/var/run/ldap/ldapi) May 16 16:56:23 tiger slapd[6395]: conn=4085 fd=41 ACCEPT from PATH=/var/run/ldap/ldapi (PATH=/var/run/ldap/ldapi) May 16 16:56:23 tiger slapd[6395]: conn=4085 op=0 do_bind: invalid dn (xxxx) May 16 16:56:23 tiger slapd[6395]: conn=4085 op=0 RESULT tag=97 err=34 text=invalid DN May 16 16:56:23 tiger slapd[6395]: conn=4085 op=0 do_bind: invalid dn (xxxx) May 16 16:56:23 tiger slapd[6395]: conn=4085 op=0 RESULT tag=97 err=34 text=invalid DN
slapd is not quoting the invalid DN, so the quotes are part of the DN being sent, which is obviously invalid due to the quotes.
I understand that there might be a problem in pacemakers `slapd' resource agent. Maybe it corrupts bind dn somehow...
Agent executes `monitor' operation, here is a snippet from resource agent code: ldap2:~# less /usr/lib/ocf/resource.d/heartbeat/slapd ... slapd_monitor() { ... options="-LLL -s base -x"
if [ -n "$bind_dn" ]; then options="$options -D '$bind_dn' -w '$password'"
This is wrong. Removing the single quotes in the line above should fix it.
Regards, Buchan
openldap-technical@openldap.org
-
Buchan Milne -
Igor Zinovik