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@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.