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.
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?
Uncomment set_auth_type = yes in raddb/modules/ldap. Ivan Kalik Kalik Informatika ISP
Leese, MJ (Mark) wrote:
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'.
The "known good" password is also found, and added to the control items. In 2.x, Auth-Type is NOT set to 'ldap' when this happens.
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.
In 2.x, the "pap" module should be listed LAST in the "authorize" section. If it finds a "known good" password is found in the control items, it sets Auth-Type to PAP. This enables you to store passwords in LDAP in many different forms, and to have the largest number of authentication types "just work". It also avoids an extra LDAP bind for authentication. That LDAP bind just isn't necessary.
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.
You haven't put "pap" as the last module in the "authorize" section. Alan DeKok.
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.
Leese, MJ (Mark) wrote:
1. Uncomment "set_auth_type = yes" in raddb/modules/ldap. This was already done but I think it's the default anyway :-)
Then it should work.
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... ... 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?
And the server doesn't find a password.
The Access-Request contains a User-Name and plaintext User-Password. My LDAP server is Active Directory
<sigh> You should have said that at the start. Active Directory isn't an LDAP server. Not really...
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?
Yes.
Is there anything else I can try?
Force Auth-Type := LDAP. ...
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.
So force Auth-Type := LDAP. This will make it do "bind as user". Alan DeKok.
rad_recv: Access-Request packet from host 127.0.0.1 port 32772, id=96, length=27 User-Name = "bill" ..
The Access-Request contains a User-Name and plaintext User-Password.
Well, not on debug you posted.
Is there anything else I can try?
Post the whole debug (server startup, request and processing). Ivan Kalik Kalik Informatika ISP
participants (3)
-
Alan DeKok -
Leese, MJ (Mark) -
tnt＠kalik.net