ldap authentication works on v1.1.4 but fails on 2.1.3
Leese, MJ (Mark)
mark.leese at stfc.ac.uk
Mon Mar 16 13:43:53 CET 2009
Hi,
I've been two pieces of advice on this issue (thanks to Ivan and Alan):
1. Uncomment "set_auth_type = yes" in raddb/modules/ldap. This was
already done but I think it's the default anyway :-)
2. List "pap" as the last module in the "authorize" section. Sorry, I
should have said that I'd also tried this. Here is the debug trace with
the pap module listed last...
rad_recv: Access-Request packet from host 127.0.0.1 port 32772,
id=96, length=27
User-Name = "bill"
Mon Mar 16 10:28:26 2009 : Info: +- entering group authorize
{...}
Mon Mar 16 10:28:26 2009 : Info: ++[preprocess] returns ok
Mon Mar 16 10:28:26 2009 : Info: [auth_log] expand:
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d ->
/var/log/radius/radacct/127.0.0.1/auth-detail-20090316
Mon Mar 16 10:28:26 2009 : Info: [auth_log]
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands
to /var/log/radius/radacct/127.0.0.1/auth-detail-20090316
Mon Mar 16 10:28:26 2009 : Info: [auth_log] expand: %t ->
Mon Mar 16 10:28:26 2009
Mon Mar 16 10:28:26 2009 : Info: ++[auth_log] returns ok
Mon Mar 16 10:28:26 2009 : Info: [ldap] performing user
authorization for bill
Mon Mar 16 10:28:26 2009 : Info: [ldap] WARNING: Deprecated
conditional expansion ":-". See "man unlang" for details
Mon Mar 16 10:28:26 2009 : Info: [ldap] expand:
(sAMAccountName=%{Stripped-User-Name:-%{User-Name}}) ->
(sAMAccountName=bill)
Mon Mar 16 10:28:26 2009 : Info: [ldap] expand:
dc=foo,dc=ac,dc=uk -> dc=foo,dc=ac,dc=uk
Mon Mar 16 10:28:26 2009 : Debug: rlm_ldap: ldap_get_conn:
Checking Id: 0
Mon Mar 16 10:28:26 2009 : Debug: rlm_ldap: ldap_get_conn: Got
Id: 0
Mon Mar 16 10:28:26 2009 : Debug: rlm_ldap: attempting LDAP
reconnection
Mon Mar 16 10:28:26 2009 : Debug: rlm_ldap: (re)connect to
ad.foo.ac.uk:389, authentication 0
Mon Mar 16 10:28:26 2009 : Debug: rlm_ldap: bind as / to
ad.foo.ac.uk:389
Mon Mar 16 10:28:26 2009 : Debug: rlm_ldap: waiting for bind
result ...
Mon Mar 16 10:28:26 2009 : Debug: rlm_ldap: Bind was successful
Mon Mar 16 10:28:26 2009 : Debug: rlm_ldap: performing search in
dc=foo,dc=ac,dc=uk, with filter (sAMAccountName=bill)
Mon Mar 16 10:28:26 2009 : Info: [ldap] looking for check items
in directory...
Mon Mar 16 10:28:26 2009 : Info: [ldap] looking for reply items
in directory...
Mon Mar 16 10:28:26 2009 : Debug: WARNING: No "known good"
password was found in LDAP. Are you sure that the user is configured
correctly?
Mon Mar 16 10:28:26 2009 : Info: [ldap] user bill authorized to
use remote access
Mon Mar 16 10:28:26 2009 : Debug: rlm_ldap: ldap_release_conn:
Release Id: 0
Mon Mar 16 10:28:26 2009 : Info: ++[ldap] returns ok
Mon Mar 16 10:28:26 2009 : Info: ++[expiration] returns noop
Mon Mar 16 10:28:26 2009 : Info: ++[logintime] returns noop
Mon Mar 16 10:28:26 2009 : Info: [pap] WARNING! No "known good"
password found for the user. Authentication may fail because of this.
Mon Mar 16 10:28:26 2009 : Info: ++[pap] returns noop
Mon Mar 16 10:28:26 2009 : Info: No authenticate method
(Auth-Type) configuration found for the request: Rejecting the user
Mon Mar 16 10:28:26 2009 : Info: Failed to authenticate the
user.
Mon Mar 16 10:28:26 2009 : Auth: Login incorrect: [bill] (from
client localNas port 0)
Mon Mar 16 10:28:26 2009 : Info: Using Post-Auth-Type Reject
Mon Mar 16 10:28:26 2009 : Info: +- entering group REJECT {...}
Mon Mar 16 10:28:26 2009 : Info: [attr_filter.access_reject]
expand: %{User-Name} -> bill
Mon Mar 16 10:28:26 2009 : Debug: attr_filter: Matched entry
DEFAULT at line 11
Mon Mar 16 10:28:26 2009 : Info: ++[attr_filter.access_reject]
returns updated
Mon Mar 16 10:28:26 2009 : Info: Delaying reject of request 0
for 1 seconds
Mon Mar 16 10:28:26 2009 : Debug: Going to the next request
Mon Mar 16 10:28:26 2009 : Debug: Waking up in 0.9 seconds.
Mon Mar 16 10:28:27 2009 : Info: Sending delayed reject for
request 0
Sending Access-Reject of id 96 to 127.0.0.1 port 32772
Mon Mar 16 10:28:27 2009 : Debug: Waking up in 4.9 seconds.
Mon Mar 16 10:28:32 2009 : Info: Cleaning up request 0 ID 96
with timestamp +87
Mon Mar 16 10:28:32 2009 : Debug: Ready to process requests.
The Access-Request contains a User-Name and plaintext User-Password. My
LDAP server is Active Directory so I don't think it returns anything in
the userPassword attribute, so I guess this is why PAP also fails to
find a "known good" password?
Is there anything else I can try?
Thanks again,
Mark.
> -----Original Message-----
> From: Leese, MJ (Mark)
> Sent: 15 March 2009 18:41
> To: 'freeradius-users at lists.freeradius.org'
> Subject: ldap authentication works on v1.1.4 but fails on 2.1.3
>
> Hi,
>
> I've been successfully using FreeRADIUS 1.1.4 to authenticate
> users against Active Directory using LDAP and a plaintext password.
>
> In the authorize section FreeRADIUS anonymously binds to our
> LDAP server (Active Directory) and searches for the user
> identified in the Access-Request (in my case we change the
> default search filter to 'sAMAccountName' as our AD doesn't
> contain 'uid'). If a match is found I think the user's full
> Distinguised Name (e.g. CN=bill,DC=foo,DC=ac,DC=uk) is added
> to the list of check items, and Auth-Type is set to 'ldap'.
> In the authenticate section, FreeRADIUS binds to the LDAP
> server using the user's full DN and the password supplied in
> the Access-Request. If the bind is successful, the user is
> authenticated because the password must have been correct.
>
> I've recently updated a server to FreeRADIUS 2.1.3 and all
> authentications now fail. LDAP is not set as the
> authentication method during the authorize section. I don't
> know why as I can't seen any configuration options which I've
> set differently between the two versions. I still get the
> debug message "Info: [ldap] user <username> authorized to use
> remote access" in the authorize section, so this suggests
> that the anonymous bind and search work ok.
>
> Does any one have any ideas? Have I made a stupid
> configuration error, or did I miss something in the latest
> documentation?
>
> Thanks in advance for any help,
>
> Mark.
>
>
> This is the debug output for version 1.1.4...
>
> rad_recv: Access-Request packet from host
> 127.0.0.1:56359, id=216, length=45
> User-Name = "bill"
> User-Password = "blahblah"
> Sun Mar 15 18:07:11 2009 : Debug: Processing the
> authorize section of radiusd.conf
> Sun Mar 15 18:07:11 2009 : Debug: modcall: entering
> group authorize for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: calling preprocess (rlm_preprocess) for
> request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: returned from preprocess
> (rlm_preprocess) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: modcall[authorize]:
> module "preprocess" returns ok for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: calling chap (rlm_chap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: returned from chap (rlm_chap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: modcall[authorize]:
> module "chap" returns noop for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: calling mschap (rlm_mschap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: returned from mschap (rlm_mschap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: modcall[authorize]:
> module "mschap" returns noop for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: calling digest (rlm_digest) for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: returned from digest (rlm_digest) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: modcall[authorize]:
> module "digest" returns noop for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: calling eap (rlm_eap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: rlm_eap: No
> EAP-Message, not doing EAP
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: returned from eap (rlm_eap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: modcall[authorize]:
> module "eap" returns noop for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: calling ldap (rlm_ldap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: - authorize
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: performing
> user authorization for bill
> Sun Mar 15 18:07:11 2009 : Debug: radius_xlat:
> '(sAMAccountName=bill)'
> Sun Mar 15 18:07:11 2009 : Debug: radius_xlat:
> 'dc=foo,dc=ac,dc=uk'
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap:
> ldap_get_conn: Checking Id: 0
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap:
> ldap_get_conn: Got Id: 0
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: attempting
> LDAP reconnection
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: (re)connect
> to ad.foo.ac.uk:389, authentication 0
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: bind as /
> to ad.foo.ac.uk:389
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: waiting for
> bind result ...
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: Bind was successful
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: performing
> search in dc=foo,dc=ac,dc=uk, with filter (sAMAccountName=bill)
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: looking for
> check items in directory...
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: looking for
> reply items in directory...
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: Setting
> Auth-Type = ldap
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: user bill
> authorized to use remote access
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap:
> ldap_release_conn: Release Id: 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: returned from ldap (rlm_ldap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: modcall[authorize]:
> module "ldap" returns ok for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: calling pap (rlm_pap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: rlm_pap: WARNING! No
> "known good" password found for the user. Authentication may
> fail because of this.
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authorize]: returned from pap (rlm_pap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: modcall[authorize]:
> module "pap" returns noop for request 0
> Sun Mar 15 18:07:11 2009 : Debug: modcall: leaving
> group authorize (returns ok) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: rad_check_password:
> Found Auth-Type ldap
> Sun Mar 15 18:07:11 2009 : Debug: auth: type "LDAP"
> Sun Mar 15 18:07:11 2009 : Debug: Processing the
> authenticate section of radiusd.conf
> Sun Mar 15 18:07:11 2009 : Debug: modcall: entering
> group LDAP for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authenticate]: calling ldap (rlm_ldap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: - authenticate
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: login
> attempt by "bill" with password "blahblah"
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: user DN:
> CN=bill,dc=foo,dc=ac,dc=uk
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: (re)connect
> to ad.foo.ac.uk:389, authentication 1
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: bind as
> CN=bill,dc=foo,dc=ac,dc=uk/blahblah to ad.foo.ac.uk:389
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: waiting for
> bind result ...
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: Bind was successful
> Sun Mar 15 18:07:11 2009 : Debug: rlm_ldap: user bill
> authenticated succesfully
> Sun Mar 15 18:07:11 2009 : Debug:
> modsingle[authenticate]: returned from ldap (rlm_ldap) for request 0
> Sun Mar 15 18:07:11 2009 : Debug:
> modcall[authenticate]: module "ldap" returns ok for request 0
> Sun Mar 15 18:07:11 2009 : Debug: modcall: leaving
> group LDAP (returns ok) for request 0
> Sun Mar 15 18:07:11 2009 : Auth: Login OK: [bill] (from
> client localNas port 0)
> Sending Access-Accept of id 216 to 127.0.0.1 port 56359
> Sun Mar 15 18:07:11 2009 : Debug: Finished request 0
> Sun Mar 15 18:07:11 2009 : Debug: Going to the next request
> Sun Mar 15 18:07:11 2009 : Debug: --- Walking the
> entire request list ---
> Sun Mar 15 18:07:11 2009 : Debug: Waking up in 6 seconds...
> Sun Mar 15 18:07:17 2009 : Debug: --- Walking the
> entire request list ---
> Sun Mar 15 18:07:17 2009 : Debug: Cleaning up request 0
> ID 216 with timestamp 49bd43cf
> Sun Mar 15 18:07:17 2009 : Debug: Nothing to do.
> Sleeping until we see a request.
>
>
>
> And this is the debug output for version 2.1.3...
>
> rad_recv: Access-Request packet from host 127.0.0.1
> port 32787, id=186, length=27
> User-Name = "bill"
> Sun Mar 15 17:59:37 2009 : Info: +- entering group
> authorize {...}
> Sun Mar 15 17:59:37 2009 : Info: ++[preprocess] returns ok
> Sun Mar 15 17:59:37 2009 : Info: [auth_log] expand:
> /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%
> d -> /var/log/radius/radacct/127.0.0.1/auth-detail-20090315
> Sun Mar 15 17:59:37 2009 : Info: [auth_log]
> /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%
> d expands to /var/log/radius/radacct/127.0.0.1/auth-detail-20090315
> Sun Mar 15 17:59:37 2009 : Info: [auth_log] expand:
> %t -> Sun Mar 15 17:59:37 2009
> Sun Mar 15 17:59:37 2009 : Info: ++[auth_log] returns ok
> Sun Mar 15 17:59:37 2009 : Info: [ldap] performing user
> authorization for bill
> Sun Mar 15 17:59:37 2009 : Info: [ldap] WARNING:
> Deprecated conditional expansion ":-". See "man unlang" for details
> Sun Mar 15 17:59:37 2009 : Info: [ldap] expand:
> (sAMAccountName=%{Stripped-User-Name:-%{User-Name}}) ->
> (sAMAccountName=bill)
> Sun Mar 15 17:59:37 2009 : Info: [ldap] expand:
> dc=foo,dc=ac,dc=uk -> dc=foo,dc=ac,dc=uk
> Sun Mar 15 17:59:37 2009 : Debug: rlm_ldap:
> ldap_get_conn: Checking Id: 0
> Sun Mar 15 17:59:37 2009 : Debug: rlm_ldap:
> ldap_get_conn: Got Id: 0
> Sun Mar 15 17:59:37 2009 : Debug: rlm_ldap: attempting
> LDAP reconnection
> Sun Mar 15 17:59:37 2009 : Debug: rlm_ldap: (re)connect
> to logon02.fed.cclrc.ac.uk:389, authentication 0
> Sun Mar 15 17:59:38 2009 : Debug: rlm_ldap: bind as /
> to logon02.fed.cclrc.ac.uk:389
> Sun Mar 15 17:59:38 2009 : Debug: rlm_ldap: waiting for
> bind result ...
> Sun Mar 15 17:59:38 2009 : Debug: rlm_ldap: Bind was successful
> Sun Mar 15 17:59:38 2009 : Debug: rlm_ldap: performing
> search in dc=foo,dc=ac,dc=uk, with filter (sAMAccountName=bill)
> Sun Mar 15 17:59:38 2009 : Info: [ldap] looking for
> check items in directory...
> Sun Mar 15 17:59:38 2009 : Info: [ldap] looking for
> reply items in directory...
> Sun Mar 15 17:59:38 2009 : Debug: WARNING: No "known
> good" password was found in LDAP. Are you sure that the user
> is configured correctly?
> Sun Mar 15 17:59:38 2009 : Info: [ldap] user bill
> authorized to use remote access
> Sun Mar 15 17:59:38 2009 : Debug: rlm_ldap:
> ldap_release_conn: Release Id: 0
> Sun Mar 15 17:59:38 2009 : Info: ++[ldap] returns ok
> Sun Mar 15 17:59:38 2009 : Info: ++[expiration] returns noop
> Sun Mar 15 17:59:38 2009 : Info: ++[logintime] returns noop
> Sun Mar 15 17:59:38 2009 : Info: No authenticate method
> (Auth-Type) configuration found for the request: Rejecting the user
> Sun Mar 15 17:59:38 2009 : Info: Failed to authenticate
> the user.
> Sun Mar 15 17:59:38 2009 : Auth: Login incorrect:
> [bill] (from client localNas port 0)
> Sun Mar 15 17:59:38 2009 : Info: Using Post-Auth-Type Reject
> Sun Mar 15 17:59:38 2009 : Info: +- entering group REJECT {...}
> Sun Mar 15 17:59:38 2009 : Info:
> [attr_filter.access_reject] expand: %{User-Name} -> bill
> Sun Mar 15 17:59:38 2009 : Debug: attr_filter: Matched
> entry DEFAULT at line 11
> Sun Mar 15 17:59:38 2009 : Info:
> ++[attr_filter.access_reject] returns updated
> Sun Mar 15 17:59:38 2009 : Info: Delaying reject of
> request 0 for 1 seconds
> Sun Mar 15 17:59:38 2009 : Debug: Going to the next request
> Sun Mar 15 17:59:38 2009 : Debug: Waking up in 0.9 seconds.
> Sun Mar 15 17:59:38 2009 : Info: Sending delayed reject
> for request 0
> Sending Access-Reject of id 186 to 127.0.0.1 port 32787
> Sun Mar 15 17:59:38 2009 : Debug: Waking up in 4.9 seconds.
> Sun Mar 15 17:59:43 2009 : Info: Cleaning up request 0
> ID 186 with timestamp +91
> Sun Mar 15 17:59:43 2009 : Debug: Ready to process requests.
>
More information about the Freeradius-Users
mailing list