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
I don't think they're related.
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=""
^^^ here we're within slap_sasl_authorize() (slapd/sasl.c); prop_getnames() was called to collect information about the authenticated identity, including authzDN. This appears to be empty.
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)
^^^ here slapd receives a request to add the entry "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
^^^ here back-hdb gets the parent of the entry that's being added
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)
^^^ here back-hdb verifies that the entry "cn=bbeamon,ou=groups,dc=example,dc=com" does not exist yet. This is why you see this error, but no error is logged, because it is expected.
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"
^^^ a referral is generated because the server is a consumer
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=""
^^^ here you get a referral response code (err=10).
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")
^^^ here slapo-chain(5) tries to chase the referral
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"
^^^ You get an error because the referral was chased anonymously.
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
To determine why the referral was chased anonymously we need to know the configuration of your slapo-chain(5). I assume the configuration you posted in an earlier message http://www.openldap.org/lists/openldap-technical/201012/msg00209.html is still valid (reported below)
--- dn: olcOverlay={0}chain,olcDatabase={-1}frontend,cn=config objectClass: olcOverlayConfig objectClass: olcChainConfig olcOverlay: {0}chain olcChainReturnError: TRUE
dn: olcDatabase={0}ldap,olcOverlay={0}chain,olcDatabase={-1}frontend,cn=config objectClass: olcLDAPConfig objectClass: olcChainDatabase olcDatabase: {0}ldap olcDbURI: "ldap://ldapks.example.com:389/"; olcDbIDAssertBind: bindmethod=sasl saslmech=gssapi mode=self olcDbRebindAsUser: TRUE ---
Assuming you did not mask hostnames and you did not make any mistake in masking them, this configuration should be fine, AFAIK, since the URI in olcDbURI matches that of the referral, "ldap://ldapks.example.com:389", and authenticated referral chasing is based on the referral URI's host:port part.
I haven't checked the specific case of SASL-GSSAPI but authenticated referral chasing works as expected; perhaps you can provide a few more details about what's actually happening inside slapo-chain? For example, if you run the consumer from command line with -dstats,trace,args we can also get the logging from libldap, which may allow to understand what slapo-chain(5) is actually doing.
p.