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