Mac Auth with MySQL

15 Mar 2010

      Hello,
I'll try to make Mac Authentication with MySQL backend. But I always rejected.
Mac Authentication only works if I add like the following lines into
the /etc/raddb/users.

90:4 C: E5: 6C: 7E: B6 Auth-Type: = Accept

I use OpenBSD 4.6, FreeRadius 2.1.3 and MySQL 5.0.83.
What should I do, to make it work with MySQL ?

mysql> use radius;
Database changed
mysql> select * from radcheck;
+----+-------------------+-----------+----+---------+
| id | username          | attribute | op | value   |
+----+-------------------+-----------+----+---------+
|  2 | 90:4C:E5:6C:7E:B6 | Password  | == | testpwd |
+----+-------------------+-----------+----+---------+
1 row in set (0.00 sec)

mysql> select * from radusergroup;
+-------------------+-----------+----------+
| username          | groupname | priority |
+-------------------+-----------+----------+
| 90:4C:E5:6C:7E:B6 | xs4all    |        1 |
+-------------------+-----------+----------+
1 row in set (0.00 sec)

mysql> select * from radgroupreply;
+----+-----------+-----------+----+--------+
| id | groupname | attribute | op | value  |
+----+-----------+-----------+----+--------+
|  3 | xs4all    | Auth-Type | := | Accept |
+----+-----------+-----------+----+--------+
1 row in set (0.00 sec)

radiusd -X -xx

Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:     (Loaded rlm_files, checking if it's valid)
Tue Mar 16 00:38:10 2010 : Debug:  Module: Linked to module rlm_files
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating files
Tue Mar 16 00:38:10 2010 : Debug:   files {
Tue Mar 16 00:38:10 2010 : Debug:       usersfile = "/etc/raddb/users"
Tue Mar 16 00:38:10 2010 : Debug:       acctusersfile = "/etc/raddb/acct_users"
Tue Mar 16 00:38:10 2010 : Debug:       preproxy_usersfile =
"/etc/raddb/preproxy_users"
Tue Mar 16 00:38:10 2010 : Debug:       compat = "no"
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:     (Loaded rlm_sql, checking if it's valid)
Tue Mar 16 00:38:10 2010 : Debug:  Module: Linked to module rlm_sql
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating sql
Tue Mar 16 00:38:10 2010 : Debug:   sql {
Tue Mar 16 00:38:10 2010 : Debug:       driver = "rlm_sql_mysql"
Tue Mar 16 00:38:10 2010 : Debug:       server = "localhost"
Tue Mar 16 00:38:10 2010 : Debug:       port = ""
Tue Mar 16 00:38:10 2010 : Debug:       login = "radius"
Tue Mar 16 00:38:10 2010 : Debug:       password = "passwordradius"
Tue Mar 16 00:38:10 2010 : Debug:       radius_db = "radius"
Tue Mar 16 00:38:10 2010 : Debug:       read_groups = yes
Tue Mar 16 00:38:10 2010 : Debug:       sqltrace = no
Tue Mar 16 00:38:10 2010 : Debug:       sqltracefile =
"/var/log/radius/sqltrace.sql"
Tue Mar 16 00:38:10 2010 : Debug:       readclients = yes
Tue Mar 16 00:38:10 2010 : Debug:       deletestalesessions = yes
Tue Mar 16 00:38:10 2010 : Debug:       num_sql_socks = 5
Tue Mar 16 00:38:10 2010 : Debug:       sql_user_name = "%{User-Name}"
Tue Mar 16 00:38:10 2010 : Debug:       default_user_profile = ""
Tue Mar 16 00:38:10 2010 : Debug:       nas_query = "SELECT id,
nasname, shortname, type, secret FROM nas"
Tue Mar 16 00:38:10 2010 : Debug:       authorize_check_query =
"SELECT id, username, attribute, value, op           FROM radcheck
      WHERE username = '%{SQL-User-Name}'           ORDER BY id"
Tue Mar 16 00:38:10 2010 : Debug:       authorize_reply_query =
"SELECT id, username, attribute, value, op           FROM radreply
      WHERE username = '%{SQL-User-Name}'           ORDER BY id"
Tue Mar 16 00:38:10 2010 : Debug:       authorize_group_check_query =
"SELECT id, groupname, attribute,           Value, op           FROM
radgroupcheck           WHERE groupname = '%{Sql-Group}'
ORDER BY id"
Tue Mar 16 00:38:10 2010 : Debug:       authorize_group_reply_query =
"SELECT id, groupname, attribute,           value, op           FROM
radgroupreply           WHERE groupname = '%{Sql-Group}'
ORDER BY id"
Tue Mar 16 00:38:10 2010 : Debug:       accounting_onoff_query = "
     UPDATE radacct           SET              acctstoptime       =
'%S',              acctsessiontime    =  unix_timestamp('%S') -
                            unix_timestamp(acctstarttime),
 acctterminatecause =  '%{Acct-Terminate-Cause}',
acctstopdelay      =  %{%{Acct-Delay-Time}:-0}           WHERE
acctstoptime IS NULL           AND nasipaddress      =
'%{NAS-IP-Address}'           AND acctstarttime     <= '%S'"
Tue Mar 16 00:38:10 2010 : Debug:       accounting_update_query = "
       UPDATE radacct           SET              framedipaddress =
'%{Framed-IP-Address}',              acctsessiontime     =
'%{Acct-Session-Time}',              acctinputoctets     =
'%{%{Acct-Input-Gigawords}:-0}'  << 32 |
     '%{%{Acct-Input-Octets}:-0}',              acctoutputoctets    =
'%{%{Acct-Output-Gigawords}:-0}' << 32 |
     '%{%{Acct-Output-Octets}:-0}'           WHERE acctsessionid =
'%{Acct-Session-Id}'           AND username        =
'%{SQL-User-Name}'           AND nasipaddress    =
'%{NAS-IP-Address}'"
Tue Mar 16 00:38:10 2010 : Debug:       accounting_update_query_alt =
"           INSERT INTO radacct             (acctsessionid,
acctuniqueid,      username,              realm,
nasipaddress,      nasportid,              nasporttype,
acctstarttime,     acctsessiontime,              acctauthentic,
connectinfo_start, acctinputoctets,              acctoutputoctets,
calledstationid,   callingstationid,              servicetype,
framedprotocol,    framedipaddress,              acctstartdelay,
xascendsessionsvrkey)           VALUES
('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}',
'%{NAS-Port}',              '%{NAS-Port-Type}',
DATE_SUB('%S',                       INTERVAL
(%{%{Acct-Session-Time}:-0} +
%{%{Acct-Delay-Time}:-0}) SECOND),
'%{Acct-Session-Time}',              '%{Acct-Authentic}', '',
    '%{%{Acct-Input-Gigawords}:-0}' << 32 |
'%{%{Acct-Input-Octets}:-0}',
'%{%{Acct-Output-Gigawords}:-0}' << 32 |
'%{%{Acct-Output-Octets}:-0}',              '%{Called-Station-Id}',
'%{Calling-Station-Id}',              '%{Service-Type}',
'%{Framed-Protocol}',              '%{Framed-IP-Address}',
 '0', '%{X-Ascend-Session-Svr-Key}')"
Tue Mar 16 00:38:10 2010 : Debug:       accounting_start_query = "
      INSERT INTO radacct             (acctsessionid,    acctuniqueid,
    username,              realm,            nasipaddress,
nasportid,              nasporttype,      acctstarttime,
acctstoptime,              acctsessiontime,  acctauthentic,
connectinfo_start,              connectinfo_stop, acctinputoctets,
acctoutputoctets,              calledstationid,  callingstationid,
acctterminatecause,              servicetype,      framedprotocol,
framedipaddress,              acctstartdelay,   acctstopdelay,
xascendsessionsvrkey)           VALUES
('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}',
'%{NAS-Port}',              '%{NAS-Port-Type}', '%S', NULL,
  '0', '%{Acct-Authentic}', '%{Connect-Info}',              '', '0',
'0',              '%{Called-Station-Id}', '%{Calling-Station-Id}', '',
             '%{Service-Type}', '%{Framed-Protocol}',
'%{Framed-IP-Address}',              '%{%{Acct-Delay-Time}:-0}', '0',
'%{X-Ascend-Session-Svr-Key}')"
Tue Mar 16 00:38:10 2010 : Debug:       accounting_start_query_alt = "
          UPDATE radacct SET              acctstarttime     = '%S',
          acctstartdelay    = '%{%{Acct-Delay-Time}:-0}',
connectinfo_start = '%{Connect-Info}'           WHERE acctsessionid  =
'%{Acct-Session-Id}'           AND username         =
'%{SQL-User-Name}'           AND nasipaddress     =
'%{NAS-IP-Address}'"
Tue Mar 16 00:38:10 2010 : Debug:       accounting_stop_query = "
     UPDATE radacct SET              acctstoptime       = '%S',
      acctsessiontime    = '%{Acct-Session-Time}',
acctinputoctets    = '%{%{Acct-Input-Gigawords}:-0}' << 32 |
                        '%{%{Acct-Input-Octets}:-0}',
acctoutputoctets   = '%{%{Acct-Output-Gigawords}:-0}' << 32 |
                         '%{%{Acct-Output-Octets}:-0}',
acctterminatecause = '%{Acct-Terminate-Cause}',
acctstopdelay      = '%{%{Acct-Delay-Time}:-0}',
connectinfo_stop   = '%{Connect-Info}'           WHERE acctsessionid
= '%{Acct-Session-Id}'           AND username          =
'%{SQL-User-Name}'           AND nasipaddress      =
'%{NAS-IP-Address}'"
Tue Mar 16 00:38:10 2010 : Debug:       accounting_stop_query_alt = "
         INSERT INTO radacct             (acctsessionid, acctuniqueid,
username,              realm, nasipaddress, nasportid,
nasporttype, acctstarttime, acctstoptime,
acctsessiontime, acctauthentic, connectinfo_start,
connectinfo_stop, acctinputoctets, acctoutputoctets,
calledstationid, callingstationid, acctterminatecause,
servicetype, framedprotocol, framedipaddress,
acctstartdelay, acctstopdelay)           VALUES
('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}',
'%{NAS-Port}',              '%{NAS-Port-Type}',
DATE_SUB('%S',                  INTERVAL (%{%{Acct-Session-Time}:-0} +
                 %{%{Acct-Delay-Time}:-0}) SECOND),              '%S',
'%{Acct-Session-Time}', '%{Acct-Authentic}', '',
'%{Connect-Info}',              '%{%{Acct-Input-Gigawords}:-0}' << 32
|              '%{%{Acct-Input-Octets}:-0}',
'%{%{Acct-Output-Gigawords}:-0}' << 32 |
'%{%{Acct-Output-Octets}:-0}',              '%{Called-Station-Id}',
'%{Calling-Station-Id}',              '%{Acct-Terminate-Cause}',
       '%{Service-Type}', '%{Framed-Protocol}',
'%{Framed-IP-Address}',              '0', '%{%{Acct-Delay-Time}:-0}')"
Tue Mar 16 00:38:10 2010 : Debug:       group_membership_query =
"SELECT groupname           FROM radusergroup           WHERE username
= '%{SQL-User-Name}'           ORDER BY priority"
Tue Mar 16 00:38:10 2010 : Debug:       connect_failure_retry_delay = 60
Tue Mar 16 00:38:10 2010 : Debug:       simul_count_query = ""
Tue Mar 16 00:38:10 2010 : Debug:       simul_verify_query = "SELECT
radacctid, acctsessionid, username,
nasipaddress, nasportid, framedipaddress,
  callingstationid, framedprotocol                                FROM
radacct                                WHERE username =
'%{SQL-User-Name}'                                AND acctstoptime IS
NULL"
Tue Mar 16 00:38:10 2010 : Debug:       postauth_query = "INSERT INTO
radpostauth                           (username, pass, reply,
authdate)                           VALUES (
'%{User-Name}',
'%{%{User-Password}:-%{Chap-Password}}',
'%{reply:Packet-Type}', '%S')"
Tue Mar 16 00:38:10 2010 : Debug:       safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_:
/"
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Info: rlm_sql (sql): Driver rlm_sql_mysql
(module rlm_sql_mysql) loaded and linked
Tue Mar 16 00:38:10 2010 : Info: rlm_sql (sql): Attempting to connect
to radius@localhost:/radius
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): starting 0
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Attempting to connect
rlm_sql_mysql #0
Tue Mar 16 00:38:10 2010 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #0
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Connected new DB handle, #0
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): starting 1
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Attempting to connect
rlm_sql_mysql #1
Tue Mar 16 00:38:10 2010 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #1
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Connected new DB handle, #1
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): starting 2
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Attempting to connect
rlm_sql_mysql #2
Tue Mar 16 00:38:10 2010 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #2
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Connected new DB handle, #2
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): starting 3
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Attempting to connect
rlm_sql_mysql #3
Tue Mar 16 00:38:10 2010 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #3
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Connected new DB handle, #3
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): starting 4
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Attempting to connect
rlm_sql_mysql #4
Tue Mar 16 00:38:10 2010 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #4
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Connected new DB handle, #4
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Processing generate_sql_clients
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql) in
generate_sql_clients: query is SELECT id, nasname, shortname, type,
secret FROM nas
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Reserving sql socket id: 4
Tue Mar 16 00:38:10 2010 : Debug: rlm_sql (sql): Released sql socket id: 4
Tue Mar 16 00:38:10 2010 : Debug:  Module: Checking session {...} for
more modules to load
Tue Mar 16 00:38:10 2010 : Debug:     (Loaded rlm_radutmp, checking if
it's valid)
Tue Mar 16 00:38:10 2010 : Debug:  Module: Linked to module rlm_radutmp
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating radutmp
Tue Mar 16 00:38:10 2010 : Debug:   radutmp {
Tue Mar 16 00:38:10 2010 : Debug:       filename = "/var/log/radius/radutmp"
Tue Mar 16 00:38:10 2010 : Debug:       username = "%{User-Name}"
Tue Mar 16 00:38:10 2010 : Debug:       case_sensitive = yes
Tue Mar 16 00:38:10 2010 : Debug:       check_with_nas = yes
Tue Mar 16 00:38:10 2010 : Debug:       perm = 384
Tue Mar 16 00:38:10 2010 : Debug:       callerid = yes
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:  Module: Checking post-auth {...}
for more modules to load
Tue Mar 16 00:38:10 2010 : Debug:     (Loaded rlm_attr_filter,
checking if it's valid)
Tue Mar 16 00:38:10 2010 : Debug:  Module: Linked to module rlm_attr_filter
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating
attr_filter.access_reject
Tue Mar 16 00:38:10 2010 : Debug:   attr_filter attr_filter.access_reject {
Tue Mar 16 00:38:10 2010 : Debug:       attrsfile =
"/etc/raddb/attrs.access_reject"
Tue Mar 16 00:38:10 2010 : Debug:       key = "%{User-Name}"
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:  }
Tue Mar 16 00:38:10 2010 : Debug: }
Tue Mar 16 00:38:10 2010 : Debug:  modules {
Tue Mar 16 00:38:10 2010 : Debug:  Module: Checking authenticate {...}
for more modules to load
Tue Mar 16 00:38:10 2010 : Debug:     (Loaded rlm_always, checking if
it's valid)
Tue Mar 16 00:38:10 2010 : Debug:  Module: Linked to module rlm_always
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating ok
Tue Mar 16 00:38:10 2010 : Debug:   always ok {
Tue Mar 16 00:38:10 2010 : Debug:       rcode = "ok"
Tue Mar 16 00:38:10 2010 : Debug:       simulcount = 0
Tue Mar 16 00:38:10 2010 : Debug:       mpp = no
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:  Module: Checking authorize {...}
for more modules to load
Tue Mar 16 00:38:10 2010 : Debug:     (Loaded rlm_preprocess, checking
if it's valid)
Tue Mar 16 00:38:10 2010 : Debug:  Module: Linked to module rlm_preprocess
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating preprocess
Tue Mar 16 00:38:10 2010 : Debug:   preprocess {
Tue Mar 16 00:38:10 2010 : Debug:       huntgroups = "/etc/raddb/huntgroups"
Tue Mar 16 00:38:10 2010 : Debug:       hints = "/etc/raddb/hints"
Tue Mar 16 00:38:10 2010 : Debug:       with_ascend_hack = no
Tue Mar 16 00:38:10 2010 : Debug:       ascend_channels_per_line = 23
Tue Mar 16 00:38:10 2010 : Debug:       with_ntdomain_hack = no
Tue Mar 16 00:38:10 2010 : Debug:       with_specialix_jetstream_hack = no
Tue Mar 16 00:38:10 2010 : Debug:       with_cisco_vsa_hack = no
Tue Mar 16 00:38:10 2010 : Debug:       with_alvarion_vsa_hack = no
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:  Module: Checking preacct {...} for
more modules to load
Tue Mar 16 00:38:10 2010 : Debug:     (Loaded rlm_acct_unique,
checking if it's valid)
Tue Mar 16 00:38:10 2010 : Debug:  Module: Linked to module rlm_acct_unique
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating acct_unique
Tue Mar 16 00:38:10 2010 : Debug:   acct_unique {
Tue Mar 16 00:38:10 2010 : Debug:       key = "User-Name,
Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:  Module: Checking accounting {...}
for more modules to load
Tue Mar 16 00:38:10 2010 : Debug:     (Loaded rlm_detail, checking if
it's valid)
Tue Mar 16 00:38:10 2010 : Debug:  Module: Linked to module rlm_detail
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating detail
Tue Mar 16 00:38:10 2010 : Debug:   detail {
Tue Mar 16 00:38:10 2010 : Debug:       detailfile =
"/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Tue Mar 16 00:38:10 2010 : Debug:       header = "%t"
Tue Mar 16 00:38:10 2010 : Debug:       detailperm = 384
Tue Mar 16 00:38:10 2010 : Debug:       dirperm = 493
Tue Mar 16 00:38:10 2010 : Debug:       locking = no
Tue Mar 16 00:38:10 2010 : Debug:       log_packet_header = no
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating
attr_filter.accounting_response
Tue Mar 16 00:38:10 2010 : Debug:   attr_filter
attr_filter.accounting_response {
Tue Mar 16 00:38:10 2010 : Debug:       attrsfile =
"/etc/raddb/attrs.accounting_response"
Tue Mar 16 00:38:10 2010 : Debug:       key = "%{User-Name}"
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:  Module: Checking session {...} for
more modules to load
Tue Mar 16 00:38:10 2010 : Debug:  Module: Checking post-auth {...}
for more modules to load
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating authorized_macs
Tue Mar 16 00:38:10 2010 : Debug:   files authorized_macs {
Tue Mar 16 00:38:10 2010 : Debug:       usersfile = "/etc/raddb/authorized_macs"
Tue Mar 16 00:38:10 2010 : Debug:       compat = "no"
Tue Mar 16 00:38:10 2010 : Debug:       key = "%{Calling-Station-ID}"
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:  Module: Instantiating reject
Tue Mar 16 00:38:10 2010 : Debug:   always reject {
Tue Mar 16 00:38:10 2010 : Debug:       rcode = "reject"
Tue Mar 16 00:38:10 2010 : Debug:       simulcount = 0
Tue Mar 16 00:38:10 2010 : Debug:       mpp = no
Tue Mar 16 00:38:10 2010 : Debug:   }
Tue Mar 16 00:38:10 2010 : Debug:  }
Tue Mar 16 00:38:10 2010 : Debug: radiusd: #### Opening IP addresses
and Ports ####
Tue Mar 16 00:38:10 2010 : Debug: listen {
Tue Mar 16 00:38:10 2010 : Debug:       type = "auth"
Tue Mar 16 00:38:10 2010 : Debug:       ipaddr = *
Tue Mar 16 00:38:10 2010 : Debug:       port = 0
Tue Mar 16 00:38:10 2010 : Debug: }
Tue Mar 16 00:38:10 2010 : Debug: listen {
Tue Mar 16 00:38:10 2010 : Debug:       type = "acct"
Tue Mar 16 00:38:10 2010 : Debug:       ipaddr = *
Tue Mar 16 00:38:10 2010 : Debug:       port = 0
Tue Mar 16 00:38:10 2010 : Debug: }
Tue Mar 16 00:38:10 2010 : Debug: Listening on authentication address
* port 1812
Tue Mar 16 00:38:10 2010 : Debug: Listening on accounting address * port 1813
Tue Mar 16 00:38:10 2010 : Debug: Ready to process requests.
rad_recv: Access-Request packet from host 192.168.0.1 port 47168,
id=20, length=136
        Service-Type = Framed-User
        NAS-Port-Id = "wireless"
        User-Name = "90:4C:E5:6C:7E:B6"
        Calling-Station-Id = "90-4C-E5-6C-7E-B6"
        Called-Station-Id = "00-0C-42-61-4A-99:wireless"
        User-Password = ""
        NAS-Identifier = "wireless"
        NAS-IP-Address = 192.168.0.1
Tue Mar 16 00:40:41 2010 : Info: +- entering group authorize {...}
Tue Mar 16 00:40:41 2010 : Info: ++[preprocess] returns ok
Tue Mar 16 00:40:41 2010 : Info: ++? if ((Service-Type ==
'Call-Check') || (User-Name =~ /^%{Calling-Station-ID}$/i))
Tue Mar 16 00:40:41 2010 : Info: ?? Evaluating (Service-Type ==
'Call-Check') -> FALSE
Tue Mar 16 00:40:41 2010 : Info:        expand:
^%{Calling-Station-ID}$ -> ^90-4C-E5-6C-7E-B6$
Tue Mar 16 00:40:41 2010 : Info: ?? Evaluating (User-Name =~
/^%{Calling-Station-ID}$/i) -> FALSE
Tue Mar 16 00:40:41 2010 : Info: ++? if ((Service-Type ==
'Call-Check') || (User-Name =~ /^%{Calling-Station-ID}$/i)) -> FALSE
Tue Mar 16 00:40:41 2010 : Info: ++[chap] returns noop
Tue Mar 16 00:40:41 2010 : Info: ++[mschap] returns noop
Tue Mar 16 00:40:41 2010 : Info: [suffix] No '@' in User-Name =
"90:4C:E5:6C:7E:B6", looking up realm NULL
Tue Mar 16 00:40:41 2010 : Info: [suffix] No such realm "NULL"
Tue Mar 16 00:40:41 2010 : Info: ++[suffix] returns noop
Tue Mar 16 00:40:41 2010 : Info: ++[unix] returns notfound
Tue Mar 16 00:40:41 2010 : Info: ++[files] returns noop
Tue Mar 16 00:40:41 2010 : Info: [sql]  expand: %{User-Name} ->
90:4C:E5:6C:7E:B6
Tue Mar 16 00:40:41 2010 : Info: [sql] sql_set_user escaped user -->
'90:4C:E5:6C:7E:B6'
Tue Mar 16 00:40:41 2010 : Debug: rlm_sql (sql): Reserving sql socket id: 3
Tue Mar 16 00:40:41 2010 : 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
= '90:4C:E5:6C:7E:B6'           ORDER BY id
Tue Mar 16 00:40:41 2010 : Debug: WARNING: Found User-Password == "...".
Tue Mar 16 00:40:41 2010 : Debug: WARNING: Are you sure you don't mean
Cleartext-Password?
Tue Mar 16 00:40:41 2010 : Debug: WARNING: See "man rlm_pap" for more
information.
Tue Mar 16 00:40:41 2010 : Info: [sql]  expand: SELECT groupname
    FROM radusergroup           WHERE username = '%{SQL-User-Name}'
       ORDER BY priority -> SELECT groupname           FROM
radusergroup           WHERE username = '90:4C:E5:6C:7E:B6'
ORDER BY priority
Tue Mar 16 00:40:41 2010 : 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 = 'xs4all'           ORDER BY id
Tue Mar 16 00:40:41 2010 : Info: [sql] User found in group xs4all
Tue Mar 16 00:40:41 2010 : 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 = 'xs4all'           ORDER BY id
Tue Mar 16 00:40:41 2010 : Debug: rlm_sql (sql): Released sql socket id: 3
Tue Mar 16 00:40:41 2010 : Info: ++[sql] returns ok
Tue Mar 16 00:40:41 2010 : Info: ++[expiration] returns noop
Tue Mar 16 00:40:41 2010 : Info: ++[logintime] returns noop
Tue Mar 16 00:40:41 2010 : Info: No authenticate method (Auth-Type)
configuration found for the request: Rejecting the user
Tue Mar 16 00:40:41 2010 : Info: Failed to authenticate the user.
Tue Mar 16 00:40:41 2010 : Info: Using Post-Auth-Type Reject
Tue Mar 16 00:40:41 2010 : Info: +- entering group REJECT {...}
Tue Mar 16 00:40:41 2010 : Info: [attr_filter.access_reject]
expand: %{User-Name} -> 90:4C:E5:6C:7E:B6
Tue Mar 16 00:40:41 2010 : Debug:  attr_filter: Matched entry DEFAULT at line 11
Tue Mar 16 00:40:41 2010 : Info: ++[attr_filter.access_reject] returns updated
Tue Mar 16 00:40:41 2010 : Info: Delaying reject of request 0 for 1 seconds
Tue Mar 16 00:40:41 2010 : Debug: Going to the next request
Tue Mar 16 00:40:41 2010 : Debug: Waking up in 0.9 seconds.
rad_recv: Access-Request packet from host 192.168.0.1 port 47168,
id=20, length=136
Tue Mar 16 00:40:42 2010 : Info: Waiting to send Access-Reject to
client 0.0.0.0/0 port 47168 - ID: 20
Tue Mar 16 00:40:42 2010 : Debug: Waking up in 0.7 seconds.
rad_recv: Access-Request packet from host 192.168.0.1 port 47168,
id=20, length=136
Tue Mar 16 00:40:42 2010 : Info: Waiting to send Access-Reject to
client 0.0.0.0/0 port 47168 - ID: 20
Tue Mar 16 00:40:42 2010 : Debug: Waking up in 0.3 seconds.
Tue Mar 16 00:40:42 2010 : Info: Sending delayed reject for request 0
Sending Access-Reject of id 20 to 192.168.0.1 port 47168
Tue Mar 16 00:40:42 2010 : Debug: Waking up in 4.9 seconds.
Tue Mar 16 00:40:47 2010 : Info: Cleaning up request 0 ID 20 with timestamp +151
Tue Mar 16 00:40:47 2010 : Debug: Ready to process requests.

Mac Auth with MySQL

Teguh Kurniawan