Hi folks,
Although I've been able to get proxy authorization to work on Debian lenny systems using OpenLDAP 2.4.11 and Kerberos authentication with SASL-GSSAPI, and I've been able to get it to work on Debian squeeze using 2.4.23 (with Pierangelo's 2010-04-29 patch) and clear-text passwords, but for some reason I'm not having any same luck with the same patched 2.4.23 version when using Kerberos authentication with SASL-GSSAPI.
If I compare the two squeeze systems -- clear-text vs. SASL-GSSAPI -- while the loglevels are both set to -1, and try submitting a similar change on both consumer servers, lines with "parseProxyAuthz" and "PROXYAUTHZ" show up in the syslog of the clear-text system's provider server, but nothing of the sort shows up in the syslog on the SASL-GSSAPI system's provider server.
Instead, when attempting to add two objects -- cn=ccolumbus and uid=ccolumbus -- using the ldapadd utility as uid=admin on the consumer server, I see this kind of stuff in the logs:
======== begin log fragment consumer server ========================
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: read active on 17 Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: connection_get(17) Dec 23 18:54:16 ldapks2 slapd[29862]: connection_get(17): got connid=1003 Dec 23 18:54:16 ldapks2 slapd[29862]: connection_read(17): checking for input on id=1003 Dec 23 18:54:16 ldapks2 slapd[29862]: op tag 0x60, time 1293126856 Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=2 do_bind Dec 23 18:54:16 ldapks2 slapd[29862]: >>> dnPrettyNormal: <> Dec 23 18:54:16 ldapks2 slapd[29862]: <<< dnPrettyNormal: <>, <> Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=2 BIND dn="" method=163 Dec 23 18:54:16 ldapks2 slapd[29862]: do_bind: dn () SASL mech GSSAPI Dec 23 18:54:16 ldapks2 slapd[29862]: ==> sasl_bind: dn="" mech=<continuing> datalen=32 Dec 23 18:54:16 ldapks2 slapd[29862]: SASL Canonicalize [conn=1003]: authcid="admin" Dec 23 18:54:16 ldapks2 slapd[29862]: slap_sasl_getdn: conn 1003 id=admin [len=5] Dec 23 18:54:16 ldapks2 slapd[29862]: slap_sasl_getdn: u:id converted to uid=admin,cn=EXAMPLE.COM,cn=GSSAPI,cn=auth Dec 23 18:54:16 ldapks2 slapd[29862]: >>> dnNormalize: <uid=admin,cn=EXAMPLE.COM,cn=GSSAPI,cn=auth> Dec 23 18:54:16 ldapks2 slapd[29862]: <<< dnNormalize: <uid=admin,cn=example.com,cn=gssapi,cn=auth> Dec 23 18:54:16 ldapks2 slapd[29862]: ==>slap_sasl2dn: converting SASL name uid=admin,cn=example.com,cn=gssapi,cn=auth to a DN Dec 23 18:54:16 ldapks2 slapd[29862]: [rw] authid: "uid=admin,cn=example.com,cn=gssapi,cn=auth" -> "uid=admin,ou=people,dc=example,dc=com" Dec 23 18:54:16 ldapks2 slapd[29862]: slap_parseURI: parsing uid=admin,ou=people,dc=example,dc=com Dec 23 18:54:16 ldapks2 slapd[29862]: >>> dnNormalize: <uid=admin,ou=people,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: <<< dnNormalize: <uid=admin,ou=people,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: <==slap_sasl2dn: Converted SASL name to uid=admin,ou=people,dc=example,dc=com Dec 23 18:54:16 ldapks2 slapd[29862]: slap_sasl_getdn: dn:id converted to uid=admin,ou=people,dc=example,dc=com Dec 23 18:54:16 ldapks2 slapd[29862]: SASL Canonicalize [conn=1003]: slapAuthcDN="uid=admin,ou=people,dc=example,dc=com" Dec 23 18:54:16 ldapks2 slapd[29862]: SASL proxy authorize [conn=1003]: authcid="admin@EXAMPLE.COM" authzid="admin@EXAMPLE.COM" Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=2 BIND authcid="admin@EXAMPLE.COM" authzid="admin@EXAMPLE.COM" Dec 23 18:54:16 ldapks2 slapd[29862]: SASL Authorize [conn=1003]: proxy authorization allowed authzDN="" Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_sasl: err=0 len=-1 Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=2 BIND dn="uid=admin,ou=people,dc=example,dc=com" mech=GSSAPI sasl_ssf=56 ssf=56 Dec 23 18:54:16 ldapks2 slapd[29862]: do_bind: SASL/GSSAPI bind: dn="uid=admin,ou=people,dc=example,dc=com" sasl_ssf=56 Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_response: msgid=3 tag=97 err=0 Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=2 RESULT tag=97 err=0 text= Dec 23 18:54:16 ldapks2 slapd[29862]: <== slap_sasl_bind: rc=0 Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on 1 descriptor Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on: Dec 23 18:54:16 ldapks2 slapd[29862]: Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on 1 descriptor Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on: Dec 23 18:54:16 ldapks2 slapd[29862]: 17r Dec 23 18:54:16 ldapks2 slapd[29862]: Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: read active on 17 Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: connection_get(17) Dec 23 18:54:16 ldapks2 slapd[29862]: connection_get(17): got connid=1003 Dec 23 18:54:16 ldapks2 slapd[29862]: connection_read(17): checking for input on id=1003 Dec 23 18:54:16 ldapks2 slapd[29862]: op tag 0x68, time 1293126856 Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=3 do_add Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=3 do_add: dn (cn=ccolumbus,ou=groups,dc=example,dc=com) Dec 23 18:54:16 ldapks2 slapd[29862]: >>> dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: <<< dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com>, <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=3 ADD dn="cn=ccolumbus,ou=groups,dc=example,dc=com" Dec 23 18:54:16 ldapks2 slapd[29862]: bdb_dn2entry("cn=ccolumbus,ou=groups,dc=example,dc=com") Dec 23 18:54:16 ldapks2 slapd[29862]: => hdb_dn2id("cn=ccolumbus,ou=groups,dc=example,dc=com") Dec 23 18:54:16 ldapks2 slapd[29862]: <= hdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found (-30988) Dec 23 18:54:16 ldapks2 slapd[29862]: hdb_referrals: tag=104 target="cn=ccolumbus,ou=groups,dc=example,dc=com" matched="ou=groups,dc=example,dc=com" Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on 1 descriptor Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on: Dec 23 18:54:16 ldapks2 slapd[29862]: Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: conn=1003 op=3 p=3 Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: err=10 matched="" text="" Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: referral="ldap://ldapks.example.com:389/cn=ccolumbus,ou=groups,dc=example,dc=com" Dec 23 18:54:16 ldapks2 slapd[29862]: >>> dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: <<< dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com>, <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: ldap_back_db_open: URI=ldap://ldapks.example.com:389 Dec 23 18:54:16 ldapks2 slapd[29862]: ==> ldap_back_add("cn=ccolumbus,ou=groups,dc=example,dc=com") Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: conn=1003 op=3 p=3 Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: err=8 matched="" text="modifications require authentication" Dec 23 18:54:16 ldapks2 slapd[29862]: <== ldap_back_add("cn=ccolumbus,ou=groups,dc=example,dc=com"): 8 Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: conn=1003 op=3 p=3 Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: err=8 matched="" text="" Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_response: msgid=4 tag=105 err=8 Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on 1 descriptor Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on: Dec 23 18:54:16 ldapks2 slapd[29862]: 17r
======== end log fragment consumer server ==========================
The only thing I think looks strange in the above is this line:
SASL Authorize [conn=1003]: proxy authorization allowed authzDN=""
Why is the authzDN empty?
======== begin log fragment provider server ========================
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on 1 descriptor Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on: Dec 23 18:54:16 ldapks1 slapd[1265]: Dec 23 18:54:16 ldapks1 slapd[1265]: slap_listener_activate(8): Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=8 busy Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: >>> slap_listener(ldap:///) Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: listen=8, new connection on 18 Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: added 18r (active) listener=(nil) Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 fd=18 ACCEPT from IP=192.168.2.56:43112 (IP=0.0.0.0:389) Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on 2 descriptors Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on: Dec 23 18:54:16 ldapks1 slapd[1265]: 18r Dec 23 18:54:16 ldapks1 slapd[1265]: Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: read active on 18 Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: connection_get(18) Dec 23 18:54:16 ldapks1 slapd[1265]: connection_get(18): got connid=1004 Dec 23 18:54:16 ldapks1 slapd[1265]: connection_read(18): checking for input on id=1004 Dec 23 18:54:16 ldapks1 slapd[1265]: op tag 0x60, time 1293126856 Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=0 do_bind Dec 23 18:54:16 ldapks1 slapd[1265]: >>> dnPrettyNormal: <> Dec 23 18:54:16 ldapks1 slapd[1265]: <<< dnPrettyNormal: <>, <> Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=0 BIND dn="" method=128 Dec 23 18:54:16 ldapks1 slapd[1265]: do_bind: version=3 dn="" method=128 Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_result: conn=1004 op=0 p=3 Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_result: err=0 matched="" text="" Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_response: msgid=1 tag=97 err=0 Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=0 RESULT tag=97 err=0 text= Dec 23 18:54:16 ldapks1 slapd[1265]: do_bind: v3 anonymous bind Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on 1 descriptor Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on: Dec 23 18:54:16 ldapks1 slapd[1265]: Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on 1 descriptor Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on: Dec 23 18:54:16 ldapks1 slapd[1265]: 18r Dec 23 18:54:16 ldapks1 slapd[1265]: Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: read active on 18 Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: connection_get(18) Dec 23 18:54:16 ldapks1 slapd[1265]: connection_get(18): got connid=1004 Dec 23 18:54:16 ldapks1 slapd[1265]: connection_read(18): checking for input on id=1004 Dec 23 18:54:16 ldapks1 slapd[1265]: op tag 0x68, time 1293126856 Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=1 do_add Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=1 do_add: dn (cn=ccolumbus,ou=groups,dc=example,dc=com) Dec 23 18:54:16 ldapks1 slapd[1265]: >>> dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks1 slapd[1265]: <<< dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com>, <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=1 ADD dn="cn=ccolumbus,ou=groups,dc=example,dc=com" Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_result: conn=1004 op=1 p=3 Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_result: err=8 matched="" text="modifications require authentication" Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_response: msgid=2 tag=105 err=8 Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=1 RESULT tag=105 err=8 text=modifications require authentication Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on 1 descriptor Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on:
======== end log fragment provider server ==========================
The ldapadd command on the consumer server gives:
adding new entry "cn=ccolumbus,ou=groups,dc=example,dc=com" ldap_add: Strong(er) authentication required (8)
Some more background info. In the DIT, the consumer server is represented by and authorized to function as a proxy via this object:
dn: cn=ldapks2,ou=consumers,dc=example,dc=com cn: ldapks2 objectClass: simpleSecurityObject objectClass: organizationalRole description: LDAP server2 replicator authzTo: dn.regex:^uid=[^,]+,ou=people,dc=example,dc=com$ userPassword:: e0NSWVBUfSo= structuralObjectClass: organizationalRole entryUUID: d939b140-a341-102f-8cd1-6f46e6760f2b creatorsName: uid=admin,ou=people,dc=example,dc=com createTimestamp: 20101224003819Z entryCSN: 20101224003819.303636Z#000000#000#000000 modifiersName: uid=admin,ou=people,dc=example,dc=com modifyTimestamp: 20101224003819Z
When the consumer, ldapks2, synchronizes with the provider, ldapks1, the consumer also shows up in the syslog on the provider server as cn=ldapks2,ou=consumers,dc=example,dc=com. That's a good sign, although after adding the relevant olcAuthzRegexp on the provider, it began to work that way after I had restarted slapd.
On the provider, the cn=config DIT looks like this:
======== begin cn=config DIT fragment provider server ==============
dn: cn=config objectClass: olcGlobal cn: config olcArgsFile: /var/run/slapd/slapd.args olcAuthzPolicy: to olcAuthzRegexp: {0}uid=ldap/([^/.]+).example.com,cn=example.com,cn=gssapi,cn= auth cn=$1,ou=consumers,dc=example,dc=com olcAuthzRegexp: {1}uid=([^,]+),cn=example.com,cn=gssapi,cn=auth uid=$1,ou=peop le,dc=example,dc=com olcLogLevel: stats olcPidFile: /var/run/slapd/slapd.pid olcSaslRealm: EXAMPLE.COM olcToolThreads: 1
dn: olcDatabase={1}hdb,cn=config objectClass: olcDatabaseConfig objectClass: olcHdbConfig olcDatabase: {1}hdb olcDbDirectory: /var/lib/ldap olcSuffix: dc=example,dc=com olcAccess: {0}to attrs=userPassword,shadowLastChange by dn.one="ou=consumers,d c=example,dc=com" read by * none olcAccess: {1}to attrs=loginShell by dn.one="ou=consumers,dc=example,dc=com" r ead by self write by * none olcAccess: {2}to dn.base="" by * read olcAccess: {3}to * by users read by * none olcLastMod: TRUE olcRootDN: uid=admin,ou=people,dc=example,dc=com olcDbCheckpoint: 512 30 olcDbConfig: {0}set_cachesize 0 2097152 0 olcDbConfig: {1}set_lk_max_objects 1500 olcDbConfig: {2}set_lk_max_locks 1500 olcDbConfig: {3}set_lk_max_lockers 1500 olcDbIndex: objectClass eq olcDbIndex: uid eq olcDbIndex: cn eq olcDbIndex: ou eq olcDbIndex: dc eq olcDbIndex: entryUUID eq olcDbIndex: entryCSN eq
======== end cn=config DIT fragment provider server ================
Chaining is enabled on the consumer server:
======== begin cn=config DIT fragment consumer server ==============
dn: cn=module{0},cn=config objectClass: olcModuleList cn: module{0} olcModulePath: /usr/lib/ldap olcModuleLoad: {0}back_hdb olcModuleLoad: {1}back_ldap
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
dn: olcDatabase={1}hdb,cn=config objectClass: olcDatabaseConfig objectClass: olcHdbConfig olcDatabase: {1}hdb olcDbDirectory: /var/lib/ldap olcSuffix: dc=example,dc=com olcAccess: {0}to attrs=userPassword,shadowLastChange by * none olcAccess: {1}to attrs=loginShell by self read by * none olcAccess: {2}to dn.base="" by * read olcAccess: {3}to * by users read by * none olcLastMod: TRUE olcRootDN: cn=manager olcSyncrepl: {0}rid=123 provider="ldap://ldapks.example.com:389/" type=refresh AndPersist retry="60 30 300 +" searchbase="dc=example,dc=com" bindmethod=sasl saslmech=gssapi olcUpdateRef: "ldap://ldapks.example.com:389/" olcDbCheckpoint: 512 30 olcDbConfig: {0}set_cachesize 0 2097152 0 olcDbConfig: {1}set_lk_max_objects 1500 olcDbConfig: {2}set_lk_max_locks 1500 olcDbConfig: {3}set_lk_max_lockers 1500 olcDbIndex: objectClass eq olcDbIndex: entryCSN eq olcDbIndex: entryUUID eq olcDbIndex: uid eq olcDbIndex: cn eq olcDbIndex: ou eq olcDbIndex: dc eq
======== end cn=config DIT fragment consumer server ================
BTW, "ldapks.example.com" is an alias for "ldapks1.example.com."
That's pretty much it, I think. Is this problem due to another bug, or have I made a mistake somewhere?
Thanks,
Jaap