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