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: /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