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

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

To: "Jaap Winius" <jwinius@umrk.nl>
Subject: Re: SASL proxy auth problem -- looks like a bug
From: masarati@aero.polimi.it
Date: Sun, 2 Jan 2011 11:37:38 +0100 (CET)
Cc: openldap-technical@openldap.org
Importance: Normal
In-reply-to: <20110102040251.151873lg8yll7gws@bitis.umrk.nl>
References: <20110101200248.14724kb8t7f9ddic@bitis.umrk.nl> <20110102040251.151873lg8yll7gws@bitis.umrk.nl>
User-agent: SquirrelMail/1.4.15

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

Follow-Ups:
- Re: SASL proxy auth problem -- looks like a bug
  - From: Jaap Winius <jwinius@umrk.nl>

References:
- SASL proxy auth problem
  - From: Jaap Winius <jwinius@umrk.nl>
- Re: SASL proxy auth problem -- looks like a bug
  - From: Jaap Winius <jwinius@umrk.nl>

Prev by Date: Re: SASL proxy auth problem -- looks like a bug
Next by Date: Re: Windows ldp.exe kills openldap 2.4.23
Index(es):
- Chronological
- Thread