file /var/log/freeradius/radacct/sql-relay: No such file or directory Brent - The reject isn't coming from group check, it fails out when it tries to write to the sql-relay file that doesn't exist. You should turn off sql-relay or configure it. If part of the sql process fails (as I've been painfully doing here with my MT the last two days) the whole process will result in an Access Reject. Notice the reject comes directly after the statement above. Also, any time a "user found in radcheck" is sent, the next query will be processed. Mike Message: 4 Date: Wed, 11 Jun 2014 17:04:30 -0600 From: "Brent Wilkinson" <brent@air2data.com> To: "'FreeRadius users mailing list'" <freeradius-users@lists.freeradius.org> Subject: Radcheck gives Accept but still moves onto Radgroupcheck Message-ID: <000601cf85c9$8104cd50$830e67f0$@com> Content-Type: text/plain; charset="us-ascii" 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