ldap authentication works on v1.1.4 but fails on 2.1.3

Leese, MJ (Mark) mark.leese at stfc.ac.uk
Sun Mar 15 19:40:40 CET 2009


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