Radcheck gives Accept but still moves onto Radgroupcheck
Brent Wilkinson
brent at air2data.com
Thu Jun 12 01:04:30 CEST 2014
I am setting up a new Radius server or a mikrotik hotspot system. I am
getting a wierd issue that I have not been able to solve or find hints to
what to do to fix it. I have setup the system with mysql. I see the radcheck
happen and show it retrieved a record. ( I have verified the sql statments
do actually pull something). I am not sending any reply so nothing is found
in that table. At this point from what I understand in reading how the sql
module works at this point it should send back a Access-Accept. Unfortunatly
it does not and continues to do group checks and I end up with a reject.
Hoping someone can give me a idea of what I need to look at or what I can
read up more on to track the issue I am having down.
Here is the debug:
rad_recv: Access-Request packet from host 76.8.212.170 port 36910, id=78,
length=189
NAS-Port-Type = Wireless-802.11
Calling-Station-Id = "1C:4B:D6:A5:CD:BF"
Called-Station-Id = "10631"
NAS-Port-Id = "ether2"
User-Name = "1"
NAS-Port = 2152726611
Acct-Session-Id = "80500053"
Framed-IP-Address = 10.69.103.254
Mikrotik-Host-IP = 10.69.103.254
CHAP-Challenge = 0x95b4afa9e0e37e62da70a83197931d11
CHAP-Password = 0x21b4c5ed3e3175b1b7672103936286b74e
Service-Type = Login-User
WISPr-Logoff-URL = "http://10.69.100.1/logout"
NAS-Identifier = "MikroTik"
NAS-IP-Address = 192.168.99.163
# Executing section authorize from file
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
[chap] Setting 'Auth-Type := CHAP'
++[chap] returns ok
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "1", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
++[files] returns noop
[sql] expand: %{User-Name} -> 1
[sql] sql_set_user escaped user --> '1'
rlm_sql (sql): Reserving sql socket id: 3
[sql] expand: SELECT id, username, attribute, value, op FROM
radcheck WHERE username = '%{SQL-User-Name}' and
PID='%{Called-Station-Id}' ORDER BY id -> SELECT id, username,
attribute, value, op FROM radcheck WHERE username = '1'
and PID='10631' ORDER BY id
rlm_sql_mysql: query: SELECT id, username, attribute, value, op
FROM radcheck WHERE username = '1' and PID='10631' ORDER
BY id
[sql] User found in radcheck table
[sql] expand: SELECT id, username, attribute, value, op FROM
radreply WHERE username = '%{SQL-User-Name}' and
PID='%{Called-Station-Id}' ORDER BY id -> SELECT id, username,
attribute, value, op FROM radreply WHERE username = '1'
and PID='10631' ORDER BY id
rlm_sql_mysql: query: SELECT id, username, attribute, value, op
FROM radreply WHERE username = '1' and PID='10631' ORDER
BY id
[sql] expand: SELECT groupname FROM radusergroup
WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT
groupname FROM radusergroup WHERE username = '1'
ORDER BY priority
rlm_sql_mysql: query: SELECT groupname FROM radusergroup
WHERE username = '1' ORDER BY priority
rlm_sql (sql): Released sql socket id: 3
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING: Auth-Type already set. Not setting to PAP
++[pap] returns noop
Found Auth-Type = CHAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group CHAP {...}
[chap] login attempt by "1" with CHAP password
[chap] Using clear text password "1" for user 1 authentication.
[chap] chap user 1 authenticated succesfully
++[chap] returns ok
# Executing section post-auth from file
/etc/freeradius/sites-enabled/default
+- entering group post-auth {...}
[sql] expand: %{User-Name} -> 1
[sql] sql_set_user escaped user --> '1'
[sql] expand: %{User-Password} ->
[sql] ... expanding second conditional
[sql] expand: %{Chap-Password} -> 0x21b4c5ed3e3175b1b7672103936286b74e
[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 (
'1', '0x21b4c5ed3e3175b1b7672103936286b74e',
'Access-Accept', '2014-06-11 18:42:31')
[sql] expand: /var/log/freeradius/sqltrace.sql ->
/var/log/freeradius/sqltrace.sql
rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth
(username, pass, reply, authdate) VALUES (
'1', '0x21b4c5ed3e3175b1b7672103936286b74e',
'Access-Accept', '2014-06-11 18:42:31')
rlm_sql (sql): Reserving sql socket id: 2
rlm_sql_mysql: query: INSERT INTO radpostauth
(username, pass, reply, authdate) VALUES (
'1', '0x21b4c5ed3e3175b1b7672103936286b74e',
'Access-Accept', '2014-06-11 18:42:31')
rlm_sql (sql): Released sql socket id: 2
++[sql] returns ok
[sql_log] Processing sql_log_postauth
[sql_log] expand: %{User-Name} -> 1
[sql_log] expand: %{%{User-Name}:-DEFAULT} -> 1
[sql_log] sql_set_user escaped user --> '1'
[sql_log] WARNING: Deprecated conditional expansion ":-". See "man unlang"
for details
[sql_log] ... expanding second conditional
[sql_log] expand: Chap-Password -> Chap-Password
[sql_log] 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 ('1',
'Chap-Password', 'Access-Accept', '2014-06-11
18:42:31');
[sql_log] expand: /var/log/freeradius/radacct/sql-relay ->
/var/log/freeradius/radacct/sql-relay
[sql_log] Couldn't open file /var/log/freeradius/radacct/sql-relay: No such
file or directory
++[sql_log] returns fail
Using Post-Auth-Type Reject
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group REJECT {...}
[sql] expand: %{User-Name} -> 1
[sql] sql_set_user escaped user --> '1'
[sql] expand: %{User-Password} ->
[sql] ... expanding second conditional
[sql] expand: %{Chap-Password} -> 0x21b4c5ed3e3175b1b7672103936286b74e
[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 (
'1', '0x21b4c5ed3e3175b1b7672103936286b74e',
'Access-Reject', '2014-06-11 18:42:31')
[sql] expand: /var/log/freeradius/sqltrace.sql ->
/var/log/freeradius/sqltrace.sql
rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth
(username, pass, reply, authdate) VALUES (
'1', '0x21b4c5ed3e3175b1b7672103936286b74e',
'Access-Reject', '2014-06-11 18:42:31')
rlm_sql (sql): Reserving sql socket id: 1
rlm_sql_mysql: query: INSERT INTO radpostauth
(username, pass, reply, authdate) VALUES (
'1', '0x21b4c5ed3e3175b1b7672103936286b74e',
'Access-Reject', '2014-06-11 18:42:31')
rlm_sql (sql): Released sql socket id: 1
++[sql] returns ok
[attr_filter.access_reject] expand: %{User-Name} -> 1
attr_filter: Matched entry DEFAULT at line 11
++[attr_filter.access_reject] returns updated
Delaying reject of request 0 for 1 seconds
Going to the next request
Waking up in 0.9 seconds.
Sending delayed reject for request 0
Sending Access-Reject of id 78 to 76.8.212.170 port 36910
Waking up in 4.9 seconds.
Cleaning up request 0 ID 78 with timestamp +6
Ready to process requests.
Thanks
Brent
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20140611/9f91e681/attachment-0001.html>
More information about the Freeradius-Users
mailing list