Dears, I would like to make a radius authentication while access to a Network Elements (Nortel ERS 8600). This authentication will be done via LDAP. Everything seems to be ok except that when the request is sent from the Network elements the password is not in clear text and then FreeRadius says that password didn't matches. When I try from RadPing (from my laptop) then my LDAP authentication is OK Can you please help me?
From RadPing
rad_recv: Access-Request packet from host 172.18.113.82 port 3340, id=1, length=48 User-Name = "ebellier" User-Password = "xxxxxxxxxx" Tue Sep 28 14:25:30 2010 : Info: +- entering group authorize {...} Tue Sep 28 14:25:30 2010 : Info: ++[preprocess] returns ok Tue Sep 28 14:25:30 2010 : Info: [auth_log] expand: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/radius/radacct/172.18.113.82/auth-detail-20100928 Tue Sep 28 14:25:30 2010 : Info: [auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/172.18.113.82/auth-detail-20100928 Tue Sep 28 14:25:30 2010 : Info: [auth_log] expand: %t -> Tue Sep 28 14:25:30 2010 Tue Sep 28 14:25:30 2010 : Info: ++[auth_log] returns ok Tue Sep 28 14:25:30 2010 : Info: ++[chap] returns noop Tue Sep 28 14:25:30 2010 : Info: ++[mschap] returns noop Tue Sep 28 14:25:30 2010 : Info: [suffix] No '@' in User-Name = "ebellier", looking up realm NULL Tue Sep 28 14:25:30 2010 : Info: [suffix] Found realm "DEFAULT" Tue Sep 28 14:25:30 2010 : Info: [suffix] Adding Stripped-User-Name = "ebellier" Tue Sep 28 14:25:30 2010 : Info: [suffix] Adding Realm = "DEFAULT" Tue Sep 28 14:25:30 2010 : Info: [suffix] Authentication realm is LOCAL. Tue Sep 28 14:25:30 2010 : Info: ++[suffix] returns ok Tue Sep 28 14:25:30 2010 : Info: [eap] No EAP-Message, not doing EAP Tue Sep 28 14:25:30 2010 : Info: ++[eap] returns noop Tue Sep 28 14:25:30 2010 : Info: ++[unix] returns updated Tue Sep 28 14:25:30 2010 : Debug: [ldap] Entering ldap_groupcmp() Tue Sep 28 14:25:30 2010 : Info: [files] expand: ou=Staff,o=mobistar.be -> ou=Staff,o=mobistar.be Tue Sep 28 14:25:30 2010 : Info: [files] expand: %{Stripped-User-Name} -> ebellier Tue Sep 28 14:25:30 2010 : Info: [files] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=ebellier) Tue Sep 28 14:25:30 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Tue Sep 28 14:25:30 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Tue Sep 28 14:25:30 2010 : Debug: [ldap] performing search in ou=Staff,o=mobistar.be, with filter (uid=ebellier) request done: ld 0x1fb4500 msgid 8 Tue Sep 28 14:25:30 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Tue Sep 28 14:25:30 2010 : Info: [files] expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectClass =GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=uid\3debellier\2cou\3dStaff\2c o\3dmobistar.be))(&(objectClass=GroupOfUniqueNames)(uniquemember=uid\3debell ier\2cou\3dStaff\2c o\3dmobistar.be))) Tue Sep 28 14:25:30 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Tue Sep 28 14:25:30 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Tue Sep 28 14:25:30 2010 : Debug: [ldap] performing search in ou=Staff,o=mobistar.be, with filter (&(cn=GF_FW_networkManagementProdAdmin)(|(&(objectClass=GroupOfNames)(member =uid\3debellier\2cou\3dStaff\2c o\3dmobistar.be))(&(objectClass=GroupOfUniqueNames)(uniquemember=uid\3debell ier\2cou\3dStaff\2c o\3dmobistar.be)))) request done: ld 0x1fb4500 msgid 9 Tue Sep 28 14:25:30 2010 : Debug: rlm_ldap::ldap_groupcmp: User found in group GF_FW_networkManagementProdAdmin Tue Sep 28 14:25:30 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Tue Sep 28 14:25:30 2010 : Info: ++[files] returns noop Tue Sep 28 14:25:30 2010 : Info: [ldap] performing user authorization for ebellier Tue Sep 28 14:25:30 2010 : Info: [ldap] expand: %{Stripped-User-Name} -> ebellier Tue Sep 28 14:25:30 2010 : Info: [ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=ebellier) Tue Sep 28 14:25:30 2010 : Info: [ldap] expand: ou=Staff,o=mobistar.be -> ou=Staff,o=mobistar.be Tue Sep 28 14:25:30 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Tue Sep 28 14:25:30 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Tue Sep 28 14:25:30 2010 : Debug: [ldap] performing search in ou=Staff,o=mobistar.be, with filter (uid=ebellier) request done: ld 0x1fb4500 msgid 10 Tue Sep 28 14:25:30 2010 : Info: [ldap] looking for check items in directory... Tue Sep 28 14:25:30 2010 : Info: [ldap] looking for reply items in directory... Tue Sep 28 14:25:30 2010 : Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Tue Sep 28 14:25:30 2010 : Info: [ldap] Setting Auth-Type = LDAP Tue Sep 28 14:25:30 2010 : Info: [ldap] user ebellier authorized to use remote access Tue Sep 28 14:25:30 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Tue Sep 28 14:25:30 2010 : Info: ++[ldap] returns ok Tue Sep 28 14:25:30 2010 : Info: ++[expiration] returns noop Tue Sep 28 14:25:30 2010 : Info: ++[logintime] returns noop Tue Sep 28 14:25:30 2010 : Info: [pap] Found existing Auth-Type, not changing it. Tue Sep 28 14:25:30 2010 : Info: ++[pap] returns noop Tue Sep 28 14:25:30 2010 : Info: Found Auth-Type = LDAP Tue Sep 28 14:25:30 2010 : Info: +- entering group LDAP {...} Tue Sep 28 14:25:30 2010 : Info: [ldap] login attempt by "ebellier" with password "xxxxxxx" Tue Sep 28 14:25:30 2010 : Info: [ldap] user DN: uid=ebellier,ou=Staff, o=mobistar.be Tue Sep 28 14:25:30 2010 : Debug: [ldap] (re)connect to 192.168.154.50:389, authentication 1 Tue Sep 28 14:25:30 2010 : Debug: [ldap] bind as uid=ebellier,ou=Staff, o=mobistar.be/Mamour20 to 192.168.154.50:389 Tue Sep 28 14:25:30 2010 : Debug: [ldap] waiting for bind result ... request done: ld 0x1fbcdb0 msgid 1 Tue Sep 28 14:25:30 2010 : Debug: [ldap] Bind was successful Tue Sep 28 14:25:30 2010 : Info: [ldap] user ebellier authenticated succesfully Tue Sep 28 14:25:30 2010 : Info: ++[ldap] returns ok Tue Sep 28 14:25:30 2010 : Auth: Login OK: [ebellier/Mamour20] (from client 172.18.113.82/32 port 0) Tue Sep 28 14:25:30 2010 : Info: +- entering group post-auth {...} Tue Sep 28 14:25:30 2010 : Info: [reply_log] expand: /var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d -> /var/log/radius/radacct/172.18.113.82/reply-detail-20100928 Tue Sep 28 14:25:30 2010 : Info: [reply_log] /var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d expands to /var/log/radius/radacct/172.18.113.82/reply-detail-20100928 Tue Sep 28 14:25:30 2010 : Info: [reply_log] expand: %t -> Tue Sep 28 14:25:30 2010 Tue Sep 28 14:25:30 2010 : Info: ++[reply_log] returns ok Tue Sep 28 14:25:30 2010 : Info: ++[exec] returns noop Sending Access-Accept of id 1 to 172.18.113.82 port 3340 Tue Sep 28 14:25:30 2010 : Info: Finished request 3. Tue Sep 28 14:25:30 2010 : Debug: Going to the next request Tue Sep 28 14:25:30 2010 : Debug: Waking up in 4.9 seconds. Tue Sep 28 14:25:35 2010 : Info: Cleaning up request 3 ID 1 with timestamp +176 Tue Sep 28 14:25:35 2010 : Info: Ready to process requests.
From Nortel ERS :
rad_recv: Access-Request packet from host 192.168.250.64 port 4439, id=186, length=60 User-Name = "ebellier" User-Password = "%\357\350\t\310}\341Ú¡9\327F\336F\034\364" NAS-IP-Address = 192.168.250.64 NAS-Port = 1 Tue Sep 28 14:22:40 2010 : Info: +- entering group authorize {...} Tue Sep 28 14:22:40 2010 : Info: ++[preprocess] returns ok Tue Sep 28 14:22:40 2010 : Info: [auth_log] expand: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/radius/radacct/192.168.250.64/auth-detail-20100928 Tue Sep 28 14:22:40 2010 : Info: [auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.250.64/auth-detail-20100928 Tue Sep 28 14:22:40 2010 : Info: [auth_log] expand: %t -> Tue Sep 28 14:22:40 2010 Tue Sep 28 14:22:40 2010 : Info: ++[auth_log] returns ok Tue Sep 28 14:22:40 2010 : Info: ++[chap] returns noop Tue Sep 28 14:22:40 2010 : Info: ++[mschap] returns noop Tue Sep 28 14:22:40 2010 : Info: [suffix] No '@' in User-Name = "ebellier", looking up realm NULL Tue Sep 28 14:22:40 2010 : Info: [suffix] Found realm "DEFAULT" Tue Sep 28 14:22:40 2010 : Info: [suffix] Adding Stripped-User-Name = "ebellier" Tue Sep 28 14:22:40 2010 : Info: [suffix] Adding Realm = "DEFAULT" Tue Sep 28 14:22:40 2010 : Info: [suffix] Authentication realm is LOCAL. Tue Sep 28 14:22:40 2010 : Info: ++[suffix] returns ok Tue Sep 28 14:22:40 2010 : Info: [eap] No EAP-Message, not doing EAP Tue Sep 28 14:22:40 2010 : Info: ++[eap] returns noop Tue Sep 28 14:22:40 2010 : Info: ++[unix] returns updated Tue Sep 28 14:22:40 2010 : Debug: [ldap] Entering ldap_groupcmp() Tue Sep 28 14:22:40 2010 : Info: [files] expand: ou=Staff,o=mobistar.be -> ou=Staff,o=mobistar.be Tue Sep 28 14:22:40 2010 : Info: [files] expand: %{Stripped-User-Name} -> ebellier Tue Sep 28 14:22:40 2010 : Info: [files] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=ebellier) Tue Sep 28 14:22:40 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Tue Sep 28 14:22:40 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Tue Sep 28 14:22:40 2010 : Debug: [ldap] attempting LDAP reconnection Tue Sep 28 14:22:40 2010 : Debug: [ldap] (re)connect to 192.168.154.50:389, authentication 0 Tue Sep 28 14:22:40 2010 : Debug: [ldap] bind as / to 192.168.154.50:389 Tue Sep 28 14:22:40 2010 : Debug: [ldap] waiting for bind result ... request done: ld 0x1fb4500 msgid 1 Tue Sep 28 14:22:40 2010 : Debug: [ldap] Bind was successful Tue Sep 28 14:22:40 2010 : Debug: [ldap] performing search in ou=Staff,o=mobistar.be, with filter (uid=ebellier) request done: ld 0x1fb4500 msgid 2 Tue Sep 28 14:22:40 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Tue Sep 28 14:22:40 2010 : Info: [files] expand: (|(&(objectClass=GroupOfNames)(member=%{control:Ldap-UserDn}))(&(objectClass =GroupOfUniqueNames)(uniquemember=%{control:Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=uid\3debellier\2cou\3dStaff\2c o\3dmobistar.be))(&(objectClass=GroupOfUniqueNames)(uniquemember=uid\3debell ier\2cou\3dStaff\2c o\3dmobistar.be))) Tue Sep 28 14:22:40 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Tue Sep 28 14:22:40 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Tue Sep 28 14:22:40 2010 : Debug: [ldap] performing search in ou=Staff,o=mobistar.be, with filter (&(cn=GF_FW_networkManagementProdAdmin)(|(&(objectClass=GroupOfNames)(member =uid\3debellier\2cou\3dStaff\2c o\3dmobistar.be))(&(objectClass=GroupOfUniqueNames)(uniquemember=uid\3debell ier\2cou\3dStaff\2c o\3dmobistar.be)))) request done: ld 0x1fb4500 msgid 3 Tue Sep 28 14:22:40 2010 : Debug: rlm_ldap::ldap_groupcmp: User found in group GF_FW_networkManagementProdAdmin Tue Sep 28 14:22:40 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Tue Sep 28 14:22:40 2010 : Info: ++[files] returns noop Tue Sep 28 14:22:40 2010 : Info: [ldap] performing user authorization for ebellier Tue Sep 28 14:22:40 2010 : Info: [ldap] expand: %{Stripped-User-Name} -> ebellier Tue Sep 28 14:22:40 2010 : Info: [ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=ebellier) Tue Sep 28 14:22:40 2010 : Info: [ldap] expand: ou=Staff,o=mobistar.be -> ou=Staff,o=mobistar.be Tue Sep 28 14:22:40 2010 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Tue Sep 28 14:22:40 2010 : Debug: [ldap] ldap_get_conn: Got Id: 0 Tue Sep 28 14:22:40 2010 : Debug: [ldap] performing search in ou=Staff,o=mobistar.be, with filter (uid=ebellier) request done: ld 0x1fb4500 msgid 4 Tue Sep 28 14:22:40 2010 : Info: [ldap] looking for check items in directory... Tue Sep 28 14:22:40 2010 : Info: [ldap] looking for reply items in directory... Tue Sep 28 14:22:40 2010 : Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Tue Sep 28 14:22:40 2010 : Info: [ldap] Setting Auth-Type = LDAP Tue Sep 28 14:22:40 2010 : Info: [ldap] user ebellier authorized to use remote access Tue Sep 28 14:22:40 2010 : Debug: [ldap] ldap_release_conn: Release Id: 0 Tue Sep 28 14:22:40 2010 : Info: ++[ldap] returns ok Tue Sep 28 14:22:40 2010 : Info: ++[expiration] returns noop Tue Sep 28 14:22:40 2010 : Info: ++[logintime] returns noop Tue Sep 28 14:22:40 2010 : Info: [pap] Found existing Auth-Type, not changing it. Tue Sep 28 14:22:40 2010 : Info: ++[pap] returns noop Tue Sep 28 14:22:40 2010 : Info: Found Auth-Type = LDAP Tue Sep 28 14:22:40 2010 : Info: +- entering group LDAP {...} Tue Sep 28 14:22:40 2010 : Info: [ldap] login attempt by "ebellier" with password "%ïè È}áÚ¡9×FÞF?ô" Tue Sep 28 14:22:40 2010 : Info: [ldap] user DN: uid=ebellier,ou=Staff, o=mobistar.be Tue Sep 28 14:22:40 2010 : Debug: [ldap] (re)connect to 192.168.154.50:389, authentication 1 Tue Sep 28 14:22:40 2010 : Debug: [ldap] bind as uid=ebellier,ou=Staff, o=mobistar.be/%ïè È}áÚ¡9×FÞF?ô to 192.168.154.50:389 Tue Sep 28 14:22:40 2010 : Debug: [ldap] waiting for bind result ... request done: ld 0x1fbcd90 msgid 1 Tue Sep 28 14:22:40 2010 : Debug: [ldap] Bind failed with invalid credentials Tue Sep 28 14:22:40 2010 : Info: ++[ldap] returns reject Tue Sep 28 14:22:40 2010 : Info: Failed to authenticate the user. Tue Sep 28 14:22:40 2010 : Auth: Login incorrect ( [ldap] Bind as user failed): [ebellier/%\357\350\t\310}\341Ú¡9\327F\336F\034\364] (from client 192.168.250.64 port 1) Tue Sep 28 14:22:40 2010 : Debug: WARNING: Unprintable characters in the password. Double-check the shared secret on the server and the NAS! Tue Sep 28 14:22:40 2010 : Info: Using Post-Auth-Type Reject Tue Sep 28 14:22:40 2010 : Info: +- entering group REJECT {...} Tue Sep 28 14:22:40 2010 : Info: [attr_filter.access_reject] expand: %{User-Name} -> ebellier Tue Sep 28 14:22:40 2010 : Debug: attr_filter: Matched entry DEFAULT at line 11 Tue Sep 28 14:22:40 2010 : Info: ++[attr_filter.access_reject] returns updated Tue Sep 28 14:22:40 2010 : Info: Delaying reject of request 0 for 1 seconds Tue Sep 28 14:22:40 2010 : Debug: Going to the next request Tue Sep 28 14:22:40 2010 : Debug: Waking up in 0.9 seconds. Tue Sep 28 14:22:41 2010 : Info: Sending delayed reject for request 0 Sending Access-Reject of id 186 to 192.168.250.64 port 4439 Tue Sep 28 14:22:41 2010 : Debug: Waking up in 4.9 seconds. Tue Sep 28 14:22:46 2010 : Info: Cleaning up request 0 ID 186 with timestamp +6 Tue Sep 28 14:22:46 2010 : Info: Ready to process requests. <http://k-village/team_members/who_s_who/kpeople01.asp?login=ebellier> Eric Bellière Operation & Integration Expert ITNO/ISO/ISIO/LSS Mobistar NV/SA Avenue Jean Mermoz 32 6041 Gosselies cid:image003.jpg@01C961E5.77656AB0 Tel: +32 (0)2 745 7997 GSM: +32(0)495 55 1343
