<div dir="ltr"><div><div><div><div>Hello,<br><br></div>I'm having an issue with our radius server authorising users.<br><br></div>The initial request is fine, the customer connects and receives an IP address....<br><br>
<br>rad_recv: Access-Request packet from host 10.8.13.254 port 1645, id=5, length=236<br> Framed-Protocol = PPP<br> User-Name = "<a href="mailto:michaelr@example.com">michaelr@example.com</a>"<br> CHAP-Password = 0x974cfb5d4d64e91407e0c85a3b1611a584<br>
Calling-Station-Id = "GigabitEthernet 14/0/3.31010096:3101-96#587204450###pppoe 00:04:ed:d1:78:85#QTNITE4025M atm 1/1/04/27:8.35#"<br> Connect-Info = "1000000000"<br> NAS-Port-Type = Virtual<br>
NAS-Port = 501<br> NAS-Port-Id = "Uniq-Sess-ID501"<br> Service-Type = Framed-User<br> NAS-IP-Address = 10.8.13.254<br>Fri Jun 14 11:44:14 2013 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default<br>
Fri Jun 14 11:44:14 2013 : Info: +- entering group authorize {...}<br>Fri Jun 14 11:44:14 2013 : Info: ++[preprocess] returns ok<br>Fri Jun 14 11:44:14 2013 : Info: [chap] Setting 'Auth-Type := CHAP'<br>Fri Jun 14 11:44:14 2013 : Info: ++[chap] returns ok<br>
Fri Jun 14 11:44:14 2013 : Info: ++[mschap] returns noop<br>Fri Jun 14 11:44:14 2013 : Info: ++[digest] returns noop<br>Fri Jun 14 11:44:14 2013 : Info: [suffix] Looking up realm "<a href="http://example.com">example.com</a>" for User-Name = "<a href="mailto:michaelr@example.com">michaelr@example.com</a>"<br>
Fri Jun 14 11:44:14 2013 : Info: [suffix] Found realm "<a href="http://example.com">example.com</a>"<br>Fri Jun 14 11:44:14 2013 : Info: [suffix] Adding Stripped-User-Name = "michaelr"<br>Fri Jun 14 11:44:14 2013 : Info: [suffix] Adding Realm = "<a href="http://example.com">example.com</a>"<br>
Fri Jun 14 11:44:14 2013 : Info: [suffix] Authentication realm is LOCAL.<br>Fri Jun 14 11:44:14 2013 : Info: ++[suffix] returns ok<br>Fri Jun 14 11:44:14 2013 : Info: [eap] No EAP-Message, not doing EAP<br>Fri Jun 14 11:44:14 2013 : Info: ++[eap] returns noop<br>
Fri Jun 14 11:44:14 2013 : Info: [files] users: Matched entry DEFAULT at line 172<br>Fri Jun 14 11:44:14 2013 : Info: ++[files] returns ok<br>Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{Stripped-User-Name} -> michaelr<br>
Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> michaelr<br>Fri Jun 14 11:44:14 2013 : Info: [sql] sql_set_user escaped user --> 'michaelr'<br>Fri Jun 14 11:44:14 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 0<br>
Fri Jun 14 11:44:14 2013 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'michaelr' ORDER BY id<br>
Fri Jun 14 11:44:14 2013 : Info: [sql] User found in radcheck table<br>Fri Jun 14 11:44:14 2013 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'michaelr' ORDER BY id<br>
Fri Jun 14 11:44:14 2013 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'michaelr' ORDER BY priority<br>
Fri Jun 14 11:44:14 2013 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'Layer2-L2TP' ORDER BY id<br>
Fri Jun 14 11:44:14 2013 : Info: [sql] User found in group Layer2-L2TP<br>Fri Jun 14 11:44:14 2013 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'Layer2-L2TP' ORDER BY id<br>
Fri Jun 14 11:44:14 2013 : Debug: rlm_sql (sql): Released sql socket id: 0<br>Fri Jun 14 11:44:14 2013 : Info: ++[sql] returns ok<br>Fri Jun 14 11:44:14 2013 : Info: ++[expiration] returns noop<br>Fri Jun 14 11:44:14 2013 : Info: ++[logintime] returns noop<br>
Fri Jun 14 11:44:14 2013 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP<br>Fri Jun 14 11:44:14 2013 : Info: ++[pap] returns noop<br>Fri Jun 14 11:44:14 2013 : Info: Found Auth-Type = Local<br>Fri Jun 14 11:44:14 2013 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!<br>
Fri Jun 14 11:44:14 2013 : Info: !!! Replacing User-Password in config items with Cleartext-Password. !!!<br>Fri Jun 14 11:44:14 2013 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!<br>
Fri Jun 14 11:44:14 2013 : Info: !!! Please update your configuration so that the "known good" !!!<br>Fri Jun 14 11:44:14 2013 : Info: !!! clear text password is in Cleartext-Password, and not in User-Password. !!!<br>
Fri Jun 14 11:44:14 2013 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!<br>Fri Jun 14 11:44:14 2013 : Info: WARNING: Please update your configuration, and remove 'Auth-Type = Local'<br>
Fri Jun 14 11:44:14 2013 : Info: WARNING: Use the PAP or CHAP modules instead.<br>Fri Jun 14 11:44:14 2013 : Info: CHAP-Password is correct.<br>Fri Jun 14 11:44:14 2013 : Info: # Executing section post-auth from file /etc/freeradius/sites-enabled/default<br>
Fri Jun 14 11:44:14 2013 : Info: +- entering group post-auth {...}<br>Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{Stripped-User-Name} -> michaelr<br>Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> michaelr<br>
Fri Jun 14 11:44:14 2013 : Info: [sql] sql_set_user escaped user --> 'michaelr'<br>Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{User-Password} -><br>Fri Jun 14 11:44:14 2013 : Info: [sql] ... expanding second conditional<br>
Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{Chap-Password} -> 0x974cfb5d4d64e91407e0c85a3b1611a584<br>Fri Jun 14 11:44:14 2013 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '<a href="mailto:michaelr@example.com">michaelr@example.com</a>', '0x974cfb5d4d64e91407e0c85a3b1611a584', 'Access-Accept', '2013-06-14 11:44:14')<br>
Fri Jun 14 11:44:14 2013 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '<a href="mailto:michaelr@example.com">michaelr@example.com</a>', '0x974cfb5d4d64e91407e0c85a3b1611a584', 'Access-Accept', '2013-06-14 11:44:14')<br>
Fri Jun 14 11:44:14 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 4<br>Fri Jun 14 11:44:14 2013 : Debug: rlm_sql (sql): Released sql socket id: 4<br>Fri Jun 14 11:44:14 2013 : Info: ++[sql] returns ok<br>Fri Jun 14 11:44:14 2013 : Info: ++[exec] returns noop<br>
Sending Access-Accept of id 5 to 10.8.13.254 port 1645<br> Framed-Protocol := PPP<br> Framed-Compression = Van-Jacobson-TCP-IP<br> Framed-IP-Address == 10.8.13.193<br> Tunnel-Type:0 := L2TP<br>
Tunnel-Medium-Type:0 := IPv4<br> Service-Type := Framed-User<br> Framed-IP-Netmask := 255.255.255.255<br>Fri Jun 14 11:44:14 2013 : Info: Finished request 20.<br>Fri Jun 14 11:44:14 2013 : Debug: Going to the next request<br>
Fri Jun 14 11:44:14 2013 : Debug: Waking up in 4.9 seconds.<br>Fri Jun 14 11:44:19 2013 : Info: Cleaning up request 20 ID 5 with timestamp +734<br>Fri Jun 14 11:44:19 2013 : Info: Ready to process requests.<br><br><br><br>
<br><br></div>However then the customer disconnects a 2nd later, and the following comes through, which makes no sense at all to me.<br><br><br><br><br><br>rad_recv: Access-Request packet from host 10.8.13.254 port 1645, id=6, length=220<br>
User-Name = "<a href="http://example.com">example.com</a>"<br> User-Password = "cisco"<br> Calling-Station-Id = "GigabitEthernet 14/0/3.31010096:3101-96#587204450###pppoe 00:04:ed:d1:78:85#QTNITE4025M atm 1/1/04/27:8.35#"<br>
Connect-Info = "1000000000"<br> NAS-Port-Type = Virtual<br> NAS-Port = 501<br> NAS-Port-Id = "Uniq-Sess-ID501"<br> Service-Type = Outbound-User<br> NAS-IP-Address = 10.8.13.254<br>
Fri Jun 14 11:44:23 2013 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default<br>Fri Jun 14 11:44:23 2013 : Info: +- entering group authorize {...}<br>Fri Jun 14 11:44:23 2013 : Info: ++[preprocess] returns ok<br>
Fri Jun 14 11:44:23 2013 : Info: ++[chap] returns noop<br>Fri Jun 14 11:44:23 2013 : Info: ++[mschap] returns noop<br>Fri Jun 14 11:44:23 2013 : Info: ++[digest] returns noop<br>Fri Jun 14 11:44:23 2013 : Info: [suffix] No '@' in User-Name = "<a href="http://example.com">example.com</a>", looking up realm NULL<br>
Fri Jun 14 11:44:23 2013 : Info: [suffix] No such realm "NULL"<br>Fri Jun 14 11:44:23 2013 : Info: ++[suffix] returns noop<br>Fri Jun 14 11:44:23 2013 : Info: [eap] No EAP-Message, not doing EAP<br>Fri Jun 14 11:44:23 2013 : Info: ++[eap] returns noop<br>
Fri Jun 14 11:44:23 2013 : Info: [files] users: Matched entry DEFAULT at line 204<br>Fri Jun 14 11:44:23 2013 : Info: ++[files] returns ok<br>Fri Jun 14 11:44:23 2013 : Info: [sql] expand: %{Stripped-User-Name} -><br>
Fri Jun 14 11:44:23 2013 : Info: [sql] ... expanding second conditional<br>Fri Jun 14 11:44:23 2013 : Info: [sql] expand: %{User-Name} -> <a href="http://example.com">example.com</a><br>Fri Jun 14 11:44:23 2013 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> <a href="http://example.com">example.com</a><br>
Fri Jun 14 11:44:23 2013 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> <a href="http://example.com">example.com</a><br>Fri Jun 14 11:44:23 2013 : Info: [sql] sql_set_user escaped user --> '<a href="http://example.com">example.com</a>'<br>
Fri Jun 14 11:44:23 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 3<br>Fri Jun 14 11:44:23 2013 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '<a href="http://example.com">example.com</a>' ORDER BY id<br>
Fri Jun 14 11:44:23 2013 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = '<a href="http://example.com">example.com</a>' ORDER BY priority<br>
Fri Jun 14 11:44:23 2013 : Debug: rlm_sql (sql): Released sql socket id: 3<br>Fri Jun 14 11:44:23 2013 : Info: [sql] User <a href="http://example.com">example.com</a> not found<br>Fri Jun 14 11:44:23 2013 : Info: ++[sql] returns notfound<br>
Fri Jun 14 11:44:23 2013 : Info: ++[expiration] returns noop<br>Fri Jun 14 11:44:23 2013 : Info: ++[logintime] returns noop<br>Fri Jun 14 11:44:23 2013 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this.<br>
Fri Jun 14 11:44:23 2013 : Info: ++[pap] returns noop<br>Fri Jun 14 11:44:23 2013 : Info: Found Auth-Type = Local<br>Fri Jun 14 11:44:23 2013 : Info: WARNING: Please update your configuration, and remove 'Auth-Type = Local'<br>
Fri Jun 14 11:44:23 2013 : Info: WARNING: Use the PAP or CHAP modules instead.<br>Fri Jun 14 11:44:23 2013 : Info: No "known good" password was configured for the user.<br>Fri Jun 14 11:44:23 2013 : Info: As a result, we cannot authenticate the user.<br>
Fri Jun 14 11:44:23 2013 : Info: Failed to authenticate the user.<br>Fri Jun 14 11:44:23 2013 : Info: Using Post-Auth-Type Reject<br>Fri Jun 14 11:44:23 2013 : Info: # Executing group from file /etc/freeradius/sites-enabled/default<br>
Fri Jun 14 11:44:23 2013 : Info: +- entering group REJECT {...}<br>Fri Jun 14 11:44:23 2013 : Info: [attr_filter.access_reject] expand: %{User-Name} -> <a href="http://example.com">example.com</a><br>Fri Jun 14 11:44:23 2013 : Debug: attr_filter: Matched entry DEFAULT at line 11<br>
Fri Jun 14 11:44:23 2013 : Info: ++[attr_filter.access_reject] returns updated<br>Fri Jun 14 11:44:23 2013 : Info: Delaying reject of request 21 for 1 seconds<br>Fri Jun 14 11:44:23 2013 : Debug: Going to the next request<br>
Fri Jun 14 11:44:23 2013 : Debug: Waking up in 0.9 seconds.<br>Fri Jun 14 11:44:24 2013 : Info: Sending delayed reject for request 21<br>Sending Access-Reject of id 6 to 10.8.13.254 port 1645<br>Fri Jun 14 11:44:24 2013 : Debug: Waking up in 4.9 seconds.<br>
Fri Jun 14 11:44:29 2013 : Info: Cleaning up request 21 ID 6 with timestamp +743<br>Fri Jun 14 11:44:29 2013 : Info: Ready to process requests.<br><br><br></div>Where is this coming from, why does the customer initially connect and then disconnect ?<br>
<br><div>Any assistance would be greatly appreciated thanks.<br></div><div><br><br><div> <br></div></div></div>