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.comFri 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.comFri 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.comFri 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.
Any assistance would be greatly appreciated thanks.