[Date Prev][Date Next] [Chronological] [Thread] [Top]

Re: SASL proxy auth problem -- looks like a bug

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:

=================================================