Quoting Jaap Winius jwinius@umrk.nl:
... The last time I followed these instructions to the letter, proxy authorization worked. Now I've booted up the same machines again a few days later and it no longer works: the consumer still uses SASL to bind with the provider for replication, but it uses a SIMPLE bind for proxy authorization. ...
Okay, I think this is a bug.
It occurs on the consumer server when, logged in as the admin user, I try to add a new group, cn=bbeamon, to the DIT. After setting the olcLogLevel to -1, I found this:
slapd[2112]: <= hdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found (-30988)
It looks similar to this earlier bug report, which contains the same error:
http://www.openldap.org/its/index.cgi/Software%20Bugs?id=6472
Below is a larger section of the log from the consumer, ldapks2, that contains the above log entry (ldapks is an alias for the provider, ldapks1):
================================================= Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: epoll: listen=8 active_threads=0 tvp=zero Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: epoll: listen=9 active_threads=0 tvp=zero Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: epoll: listen=10 active_threads=0 tvp=zero Jan 2 02:56:12 ldapks2 slapd[2112]: SASL proxy authorize [conn=1000]: authcid="admin@EXAMPLE.COM" authzid="admin@EXAMPLE.COM" Jan 2 02:56:12 ldapks2 slapd[2112]: conn=1000 op=2 BIND authcid="admin@EXAMPLE.COM" authzid="admin@EXAMPLE.COM" Jan 2 02:56:12 ldapks2 slapd[2112]: SASL Authorize [conn=1000]: proxy authorization allowed authzDN="" Jan 2 02:56:12 ldapks2 slapd[2112]: send_ldap_sasl: err=0 len=-1 Jan 2 02:56:12 ldapks2 slapd[2112]: conn=1000 op=2 BIND dn="uid=admin,ou=people,dc=example,dc=com" mech=GSSAPI sasl_ssf=56 ssf=56 Jan 2 02:56:12 ldapks2 slapd[2112]: do_bind: SASL/GSSAPI bind: dn="uid=admin,ou=people,dc=example,dc=com" sasl_ssf=56 Jan 2 02:56:12 ldapks2 slapd[2112]: send_ldap_response: msgid=3 tag=97 err=0 Jan 2 02:56:12 ldapks2 slapd[2112]: conn=1000 op=2 RESULT tag=97 err=0 text= Jan 2 02:56:12 ldapks2 slapd[2112]: <== slap_sasl_bind: rc=0 Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: activity on 1 descriptor Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: activity on: Jan 2 02:56:12 ldapks2 slapd[2112]: 16r Jan 2 02:56:12 ldapks2 slapd[2112]: Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: read active on 16 Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: epoll: listen=8 active_threads=0 tvp=zero Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: epoll: listen=9 active_threads=0 tvp=zero Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: epoll: listen=10 active_threads=0 tvp=zero Jan 2 02:56:12 ldapks2 slapd[2112]: connection_get(16) Jan 2 02:56:12 ldapks2 slapd[2112]: connection_get(16): got connid=1000 Jan 2 02:56:12 ldapks2 slapd[2112]: connection_read(16): checking for input on id=1000 Jan 2 02:56:12 ldapks2 slapd[2112]: op tag 0x68, time 1293933372 Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: activity on 1 descriptor Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: activity on: Jan 2 02:56:12 ldapks2 slapd[2112]: Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: epoll: listen=8 active_threads=0 tvp=zero Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: epoll: listen=9 active_threads=0 tvp=zero Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: epoll: listen=10 active_threads=0 tvp=zero Jan 2 02:56:12 ldapks2 slapd[2112]: conn=1000 op=3 do_add Jan 2 02:56:12 ldapks2 slapd[2112]: conn=1000 op=3 do_add: dn (cn=bbeamon,ou=groups,dc=example,dc=com) Jan 2 02:56:12 ldapks2 slapd[2112]: >>> dnPrettyNormal: <cn=bbeamon,ou=groups,dc=example,dc=com> Jan 2 02:56:12 ldapks2 slapd[2112]: <<< dnPrettyNormal: <cn=bbeamon,ou=groups,dc=example,dc=com>, <cn=bbeamon,ou=groups,dc=example,dc=com> Jan 2 02:56:12 ldapks2 slapd[2112]: conn=1000 op=3 ADD dn="cn=bbeamon,ou=groups,dc=example,dc=com" Jan 2 02:56:12 ldapks2 slapd[2112]: bdb_dn2entry("cn=bbeamon,ou=groups,dc=example,dc=com") Jan 2 02:56:12 ldapks2 slapd[2112]: => hdb_dn2id("ou=groups,dc=example,dc=com") Jan 2 02:56:12 ldapks2 slapd[2112]: <= hdb_dn2id: got id=0x3 Jan 2 02:56:12 ldapks2 slapd[2112]: => hdb_dn2id("cn=bbeamon,ou=groups,dc=example,dc=com") Jan 2 02:56:12 ldapks2 slapd[2112]: <= hdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found (-30988) Jan 2 02:56:12 ldapks2 slapd[2112]: entry_decode: "" Jan 2 02:56:12 ldapks2 slapd[2112]: <= entry_decode() Jan 2 02:56:12 ldapks2 slapd[2112]: hdb_referrals: tag=104 target="cn=bbeamon,ou=groups,dc=example,dc=com" matched="ou=groups,dc=example,dc=com" Jan 2 02:56:12 ldapks2 slapd[2112]: send_ldap_result: conn=1000 op=3 p=3 Jan 2 02:56:12 ldapks2 slapd[2112]: send_ldap_result: err=10 matched="" text="" Jan 2 02:56:12 ldapks2 slapd[2112]: send_ldap_result: referral="ldap://ldapks.example.com:389/cn=bbeamon,ou=groups,dc=example,dc=com" Jan 2 02:56:12 ldapks2 slapd[2112]: >>> dnPrettyNormal: <cn=bbeamon,ou=groups,dc=example,dc=com> Jan 2 02:56:12 ldapks2 slapd[2112]: <<< dnPrettyNormal: <cn=bbeamon,ou=groups,dc=example,dc=com>, <cn=bbeamon,ou=groups,dc=example,dc=com> Jan 2 02:56:12 ldapks2 slapd[2112]: ldap_back_db_open: URI=ldap://ldapks.example.com:389 Jan 2 02:56:12 ldapks2 slapd[2112]: ==> ldap_back_add("cn=bbeamon,ou=groups,dc=example,dc=com") Jan 2 02:56:12 ldapks2 slapd[2112]: send_ldap_result: conn=1000 op=3 p=3 Jan 2 02:56:12 ldapks2 slapd[2112]: send_ldap_result: err=8 matched="" text="modifications require authentication" Jan 2 02:56:12 ldapks2 slapd[2112]: <== ldap_back_add("cn=bbeamon,ou=groups,dc=example,dc=com"): 8 Jan 2 02:56:12 ldapks2 slapd[2112]: send_ldap_result: conn=1000 op=3 p=3 Jan 2 02:56:12 ldapks2 slapd[2112]: send_ldap_result: err=8 matched="" text="" Jan 2 02:56:12 ldapks2 slapd[2112]: send_ldap_response: msgid=4 tag=105 err=8 Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: activity on 1 descriptor Jan 2 02:56:12 ldapks2 slapd[2112]: daemon: activity on:
=================================================