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