[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 14:43:55 +0100 (CET)
Cc: openldap-technical@openldap.org
Importance: Normal
In-reply-to: <20110102141722.1967293ozhmzlick@bitis.umrk.nl>
References: <20110101200248.14724kb8t7f9ddic@bitis.umrk.nl> <20110102040251.151873lg8yll7gws@bitis.umrk.nl> <9f99a6e0f6955e466f96d90f2fb8a7b1.squirrel@www.aero.polimi.it> <20110102141722.1967293ozhmzlick@bitis.umrk.nl>
User-agent: SquirrelMail/1.4.15
> Quoting masarati@aero.polimi.it:
>
>> 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)
>
> Yes, it's still exactly the same.
>
>> 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.
>
> Checked it again. I can ssh from ldapks2 to ldapks.example.com and,
> indeed, end up on ldapks1 as expected. There's no firewall or anything
> in between. If I use nmap on ldapks2 to check TCP port 389 on ldapks,
> it's open.
>
>> 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.
>
> Okay, here's the output from slapd again, to add cn=bbeamon as admin
> from the consumer (same result), but with the -dstats,trace,args:
>
> =======================================
> slap_listener_activate(7):
>>>> slap_listener(ldap:///)
> conn=1001 fd=14 ACCEPT from IP=127.0.1.1:41637 (IP=0.0.0.0:389)
> connection_get(14)
> connection_get(14): got connid=1001
> connection_read(14): checking for input on id=1001
> ber_get_next
> ber_get_next: tag 0x30 len 632 contents:
> op tag 0x60, time 1293973781
> ber_get_next
> conn=1001 op=0 do_bind
> ber_scanf fmt ({imt) ber:
> ber_scanf fmt ({m) ber:
> ber_scanf fmt (m) ber:
> ber_scanf fmt (}}) ber:
>>>> dnPrettyNormal: <>
> <<< dnPrettyNormal: <>, <>
> conn=1001 op=0 BIND dn="" method=163
> do_bind: dn () SASL mech GSSAPI
> ==> sasl_bind: dn="" mech=GSSAPI datalen=604
> send_ldap_sasl: err=14 len=156
> send_ldap_response: msgid=1 tag=97 err=14
> ber_flush2: 203 bytes to sd 14
> conn=1001 op=0 RESULT tag=97 err=14 text=SASL(0): successful result:
> <== slap_sasl_bind: rc=14
> connection_get(14)
> connection_get(14): got connid=1001
> connection_read(14): checking for input on id=1001
> ber_get_next
> ber_get_next: tag 0x30 len 20 contents:
> op tag 0x60, time 1293973781
> ber_get_next
> conn=1001 op=1 do_bind
> ber_scanf fmt ({imt) ber:
> ber_scanf fmt ({m) ber:
> ber_scanf fmt (}}) ber:
>>>> dnPrettyNormal: <>
> <<< dnPrettyNormal: <>, <>
> conn=1001 op=1 BIND dn="" method=163
> do_bind: dn () SASL mech GSSAPI
> ==> sasl_bind: dn="" mech=<continuing> datalen=0
> send_ldap_sasl: err=14 len=32
> send_ldap_response: msgid=2 tag=97 err=14
> ber_flush2: 76 bytes to sd 14
> conn=1001 op=1 RESULT tag=97 err=14 text=SASL(0): successful result:
> connection_get(14)
> connection_get(14): got connid=1001
> connection_read(14): checking for input on id=1001
> ber_get_next
> ber_get_next: tag 0x30 len 54 contents:
> op tag 0x60, time 1293973781
> connection_input: conn=1001 deferring operation: binding
> ber_get_next
> <== slap_sasl_bind: rc=14
> conn=1001 op=2 do_bind
> ber_scanf fmt ({imt) ber:
> ber_scanf fmt ({m) ber:
> ber_scanf fmt (m) ber:
> ber_scanf fmt (}}) ber:
>>>> dnPrettyNormal: <>
> <<< dnPrettyNormal: <>, <>
> conn=1001 op=2 BIND dn="" method=163
> do_bind: dn () SASL mech GSSAPI
> ==> sasl_bind: dn="" mech=<continuing> datalen=32
> SASL Canonicalize [conn=1001]: authcid="admin"
> slap_sasl_getdn: conn 1001 id=admin [len=5]
> => ldap_dn2bv(16)
> <= ldap_dn2bv(uid=admin,cn=EXAMPLE.COM,cn=GSSAPI,cn=auth)=0
> slap_sasl_getdn: u:id converted to
> uid=admin,cn=EXAMPLE.COM,cn=GSSAPI,cn=auth
>>>> dnNormalize: <uid=admin,cn=EXAMPLE.COM,cn=GSSAPI,cn=auth>
> => ldap_bv2dn(uid=admin,cn=EXAMPLE.COM,cn=GSSAPI,cn=auth,0)
> <= ldap_bv2dn(uid=admin,cn=EXAMPLE.COM,cn=GSSAPI,cn=auth)=0
> => ldap_dn2bv(272)
> <= ldap_dn2bv(uid=admin,cn=example.com,cn=gssapi,cn=auth)=0
> <<< dnNormalize: <uid=admin,cn=example.com,cn=gssapi,cn=auth>
> ==>slap_sasl2dn: converting SASL name
> uid=admin,cn=example.com,cn=gssapi,cn=auth to a DN
> ==> rewrite_context_apply [depth=1]
> string='uid=admin,cn=example.com,cn=gssapi,cn=auth'
> ==> rewrite_rule_apply
> rule='uid=([^,]+),cn=example.com,cn=gssapi,cn=auth'
> string='uid=admin,cn=example.com,cn=gssapi,cn=auth' [1 pass(es)]
> ==> rewrite_context_apply [depth=1]
> res={0,'uid=admin,ou=people,dc=example,dc=com'}
> [rw] authid: "uid=admin,cn=example.com,cn=gssapi,cn=auth" ->
> "uid=admin,ou=people,dc=example,dc=com"
> slap_parseURI: parsing uid=admin,ou=people,dc=example,dc=com
> ldap_url_parse_ext(uid=admin,ou=people,dc=example,dc=com)
>>>> dnNormalize: <uid=admin,ou=people,dc=example,dc=com>
> => ldap_bv2dn(uid=admin,ou=people,dc=example,dc=com,0)
> <= ldap_bv2dn(uid=admin,ou=people,dc=example,dc=com)=0
> => ldap_dn2bv(272)
> <= ldap_dn2bv(uid=admin,ou=people,dc=example,dc=com)=0
> <<< dnNormalize: <uid=admin,ou=people,dc=example,dc=com>
> <==slap_sasl2dn: Converted SASL name to
> uid=admin,ou=people,dc=example,dc=com
> slap_sasl_getdn: dn:id converted to uid=admin,ou=people,dc=example,dc=com
> SASL Canonicalize [conn=1001]:
> slapAuthcDN="uid=admin,ou=people,dc=example,dc=com"
> SASL proxy authorize [conn=1001]: authcid="admin@EXAMPLE.COM"
> authzid="admin@EXAMPLE.COM"
> conn=1001 op=2 BIND authcid="admin@EXAMPLE.COM"
> authzid="admin@EXAMPLE.COM"
> SASL Authorize [conn=1001]:  proxy authorization allowed authzDN=""
> send_ldap_sasl: err=0 len=-1
> conn=1001 op=2 BIND dn="uid=admin,ou=people,dc=example,dc=com"
> mech=GSSAPI sasl_ssf=56 ssf=56
> do_bind: SASL/GSSAPI bind: dn="uid=admin,ou=people,dc=example,dc=com"
> sasl_ssf=56
> send_ldap_response: msgid=3 tag=97 err=0
> ber_flush2: 14 bytes to sd 14
> conn=1001 op=2 RESULT tag=97 err=0 text=
> <== slap_sasl_bind: rc=0
> connection_get(14)
> connection_get(14): got connid=1001
> connection_read(14): checking for input on id=1001
> ldap_pvt_sasl_generic_install
> ber_get_next
> ber_get_next: tag 0x30 len 120 contents:
> op tag 0x68, time 1293973781
> ber_get_next
> conn=1001 op=3 do_add
> ber_scanf fmt ({m) ber:
> conn=1001 op=3 do_add: dn (cn=bbeamon,ou=groups,dc=example,dc=com)
> ber_scanf fmt ({m{W}}) ber:
> ber_scanf fmt ({m{W}}) ber:
> ber_scanf fmt ({m{W}}) ber:
> ber_scanf fmt (}) ber:
>>>> dnPrettyNormal: <cn=bbeamon,ou=groups,dc=example,dc=com>
> => ldap_bv2dn(cn=bbeamon,ou=groups,dc=example,dc=com,0)
> <= ldap_bv2dn(cn=bbeamon,ou=groups,dc=example,dc=com)=0
> => ldap_dn2bv(272)
> <= ldap_dn2bv(cn=bbeamon,ou=groups,dc=example,dc=com)=0
> => ldap_dn2bv(272)
> <= ldap_dn2bv(cn=bbeamon,ou=groups,dc=example,dc=com)=0
> <<< dnPrettyNormal: <cn=bbeamon,ou=groups,dc=example,dc=com>,
> <cn=bbeamon,ou=groups,dc=example,dc=com>
> conn=1001 op=3 ADD dn="cn=bbeamon,ou=groups,dc=example,dc=com"
> bdb_dn2entry("cn=bbeamon,ou=groups,dc=example,dc=com")
> => hdb_dn2id("cn=bbeamon,ou=groups,dc=example,dc=com")
> <= hdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found
> (-30988)
> hdb_referrals: tag=104 target="cn=bbeamon,ou=groups,dc=example,dc=com"
> matched="ou=groups,dc=example,dc=com"
> ldap_url_parse_ext(ldap://ldapks.example.com:389/)
> send_ldap_result: conn=1001 op=3 p=3
> send_ldap_result: err=10 matched="" text=""
> send_ldap_result:
> referral="ldap://ldapks.example.com:389/cn=bbeamon,ou=groups,dc=example,dc=com";
> ldap_url_parse_ext(ldap://ldapks.example.com:389/cn=bbeamon,ou=groups,dc=example,dc=com)
>>>> dnPrettyNormal: <cn=bbeamon,ou=groups,dc=example,dc=com>
> => ldap_bv2dn(cn=bbeamon,ou=groups,dc=example,dc=com,0)
> <= ldap_bv2dn(cn=bbeamon,ou=groups,dc=example,dc=com)=0
> => ldap_dn2bv(272)
> <= ldap_dn2bv(cn=bbeamon,ou=groups,dc=example,dc=com)=0
> => ldap_dn2bv(272)
> <= ldap_dn2bv(cn=bbeamon,ou=groups,dc=example,dc=com)=0
> <<< dnPrettyNormal: <cn=bbeamon,ou=groups,dc=example,dc=com>,
> <cn=bbeamon,ou=groups,dc=example,dc=com>
> ldap_back_db_open: URI=ldap://ldapks.example.com:389
> ==> ldap_back_add("cn=bbeamon,ou=groups,dc=example,dc=com")
> ldap_create
> ldap_url_parse_ext(ldap://ldapks.example.com:389)
> =>ldap_back_getconn: conn=1001 op=3: lc=0x960e6f8 inserted refcnt=1 rc=0
> ldap_sasl_bind

^^^ this call shouldn't be here; on the contrary, this should result in
calling ldap_sasl_interactive_bind_s() from within back-ldap's
ldap_back_proxy_authz_bind().  I have no clue about why this is happening
since I've never tested this with GSSAPI (and I can't do it now).  However
I've tested it with other SASL mechs (including DIGEST-MD5 and EXTERNAL)
and it worked as expected.

p.

> ldap_send_initial_request
> ldap_new_connection 1 1 0
> ldap_int_open_connection
> ldap_connect_to_host: TCP ldapks.example.com:389
> ldap_new_socket: 16
> ldap_prepare_socket: 16
> ldap_connect_to_host: Trying 192.168.2.53:389
> ldap_pvt_connect: fd: 16 tm: -1 async: 0
> ldap_open_defconn: successful
> ldap_send_server_request
> ber_scanf fmt ({it) ber:
> ber_scanf fmt ({i) ber:
> ber_flush2: 14 bytes to sd 16
> ldap_result ld 0x962a208 msgid 1
> wait4msg ld 0x962a208 msgid 1 (timeout 100000 usec)
> wait4msg continue ld 0x962a208 msgid 1 all 1
> ** ld 0x962a208 Connections:
> * host: ldapks.example.com  port: 389  (default)
>    refcnt: 2  status: Connected
>    last used: Sun Jan  2 14:09:41 2011
>
>
> ** ld 0x962a208 Outstanding Requests:
>   * msgid 1,  origid 1, status InProgress
>     outstanding referrals 0, parent count 0
>    ld 0x962a208 request count 1 (abandoned 0)
> ** ld 0x962a208 Response Queue:
>     Empty
>    ld 0x962a208 response count 0
> ldap_chkResponseList ld 0x962a208 msgid 1 all 1
> ldap_chkResponseList returns ld 0x962a208 NULL
> ldap_int_select
> read1msg: ld 0x962a208 msgid 1 all 1
> ber_get_next
> ber_get_next: tag 0x30 len 12 contents:
> read1msg: ld 0x962a208 msgid 1 message type bind
> ber_scanf fmt ({eAA) ber:
> read1msg: ld 0x962a208 0 new referrals
> read1msg:  mark request completed, ld 0x962a208 msgid 1
> request done: ld 0x962a208 msgid 1
> res_errno: 0, res_error: <>, res_matched: <>
> ldap_free_request (origid 1, msgid 1)
> ldap_parse_result
> ber_scanf fmt ({iAA) ber:
> ber_scanf fmt (}) ber:
> ldap_msgfree
> ldap_add_ext
> ldap_send_initial_request
> ldap_send_server_request
> ber_scanf fmt ({it) ber:
> ber_scanf fmt ({) ber:
> ber_flush2: 122 bytes to sd 16
> ldap_result ld 0x962a208 msgid 2
> wait4msg ld 0x962a208 msgid 2 (timeout 100000 usec)
> wait4msg continue ld 0x962a208 msgid 2 all 1
> ** ld 0x962a208 Connections:
> * host: ldapks.example.com  port: 389  (default)
>    refcnt: 2  status: Connected
>    last used: Sun Jan  2 14:09:41 2011
>
>
> ** ld 0x962a208 Outstanding Requests:
>   * msgid 2,  origid 2, status InProgress
>     outstanding referrals 0, parent count 0
>    ld 0x962a208 request count 1 (abandoned 0)
> ** ld 0x962a208 Response Queue:
>     Empty
>    ld 0x962a208 response count 0
> ldap_chkResponseList ld 0x962a208 msgid 2 all 1
> ldap_chkResponseList returns ld 0x962a208 NULL
> ldap_int_select
> read1msg: ld 0x962a208 msgid 2 all 1
> ber_get_next
> ber_get_next: tag 0x30 len 48 contents:
> read1msg: ld 0x962a208 msgid 2 message type add
> ber_scanf fmt ({eAA) ber:
> ldap_chase_referrals
> read1msg:  V2 referral chased, mark request completed, id = 2
> read1msg: ld 0x962a208 0 new referrals
> read1msg:  mark request completed, ld 0x962a208 msgid 2
> request done: ld 0x962a208 msgid 2
> res_errno: 8, res_error: <modifications require authentication>,
> res_matched: <>
> ldap_free_request (origid 2, msgid 2)
> ldap_parse_result
> ber_scanf fmt ({iAA) ber:
> ber_scanf fmt (}) ber:
> ldap_msgfree
> send_ldap_result: conn=1001 op=3 p=3
> send_ldap_result: err=8 matched="" text="modifications require
> authentication"
> <== ldap_back_add("cn=bbeamon,ou=groups,dc=example,dc=com"): 8
> ldap_free_connection 1 1
> ldap_send_unbind
> ber_flush2: 7 bytes to sd 16
> ldap_free_connection: actually freed
> send_ldap_result: conn=1001 op=3 p=3
> send_ldap_result: err=8 matched="" text=""
> send_ldap_response: msgid=4 tag=105 err=8
> ber_flush2: 14 bytes to sd 14
> connection_get(14)
> connection_get(14): got connid=1001
> connection_read(14): checking for input on id=1001
> ber_get_next
> ber_get_next: tag 0x30 len 5 contents:
> op tag 0x42, time 1293973781
> ber_get_next
> ber_get_next on fd 14 failed errno=0 (Success)
> conn=1001 op=4 do_unbind
> conn=1001 op=4 UNBIND
> conn=1001 op=3 RESULT tag=105 err=8 text=
> connection_close: conn=1001 sd=14
> conn=1001 fd=14 closed
>
> =======================================
>
> Thanks,
>
> Jaap
>
>
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>
- Re: SASL proxy auth problem -- looks like a bug
  - From: masarati@aero.polimi.it
- 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: SASL proxy auth problem -- looks like a bug
Index(es):
- Chronological
- Thread