"do_bind: invalid dn" while trying to monitor slapd using pacemaker `slapd' resource agent

[Igor Zinovik <zinovik.igor@gmail.com>]

  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...