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