initial accept, but then fails
geebs
gweebo at gmail.com
Fri Jun 14 03:56:34 CEST 2013
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 at 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 at 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 at 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 at 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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20130614/12569010/attachment-0001.html>
More information about the Freeradius-Users
mailing list