Re: Accounting to MySQL not working

27 May 2010

      I can not find a configuration mistake, the same configuration is 
working with freeradius 2.0.4

If I set "sqltrace = yes", I do not get a trace file in 
/var/log/freeradius with v2.1.8 (this is working with 2.0.4)

Attached is the debug log. Maybe someone has an idea, what is going wrong
Are there any changes between 2.0.4 and 2.1.8 for sql accounting, which 
have to be configured to get accounting into mysql working in 2.1.8?

many thanks
christoph

debian1:/etc/freeradius# freeradius -X
FreeRADIUS Version 2.1.8, for host i486-pc-linux-gnu, built on May 26 2010 at 14:52:49
Copyright (C) 1999-2009 The FreeRADIUS server project and contributors.
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE.
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License v2.
Starting - reading configuration files ...
including configuration file /etc/freeradius/radiusd.conf
including configuration file /etc/freeradius/proxy.conf
including configuration file /etc/freeradius/clients.conf
including files in directory /etc/freeradius/modules/
including configuration file /etc/freeradius/modules/mschap
including configuration file /etc/freeradius/modules/always
including configuration file /etc/freeradius/modules/policy
including configuration file /etc/freeradius/modules/ldap
including configuration file /etc/freeradius/modules/sqlcounter_expire_on_login
including configuration file /etc/freeradius/modules/sradutmp
including configuration file /etc/freeradius/modules/digest
including configuration file /etc/freeradius/modules/expr
including configuration file /etc/freeradius/modules/detail.log
including configuration file /etc/freeradius/modules/smbpasswd
including configuration file /etc/freeradius/modules/detail.example.com
including configuration file /etc/freeradius/modules/inner-eap
including configuration file /etc/freeradius/modules/perl
including configuration file /etc/freeradius/modules/pap
including configuration file /etc/freeradius/modules/ippool
including configuration file /etc/freeradius/modules/wimax
including configuration file /etc/freeradius/modules/realm
including configuration file /etc/freeradius/modules/otp
including configuration file /etc/freeradius/modules/counter
including configuration file /etc/freeradius/modules/attr_rewrite
including configuration file /etc/freeradius/modules/echo
including configuration file /etc/freeradius/modules/krb5
including configuration file /etc/freeradius/modules/exec
including configuration file /etc/freeradius/modules/pam
including configuration file /etc/freeradius/modules/chap
including configuration file /etc/freeradius/modules/linelog
including configuration file /etc/freeradius/modules/unix
including configuration file /etc/freeradius/modules/passwd
including configuration file /etc/freeradius/modules/checkval
including configuration file /etc/freeradius/modules/etc_group
including configuration file /etc/freeradius/modules/ntlm_auth
including configuration file /etc/freeradius/modules/acct_unique
including configuration file /etc/freeradius/modules/sql_log
including configuration file /etc/freeradius/modules/radutmp
including configuration file /etc/freeradius/modules/attr_filter
including configuration file /etc/freeradius/modules/cui
including configuration file /etc/freeradius/modules/files
including configuration file /etc/freeradius/modules/smsotp
including configuration file /etc/freeradius/modules/logintime
including configuration file /etc/freeradius/modules/mac2vlan
including configuration file /etc/freeradius/modules/expiration
including configuration file /etc/freeradius/modules/detail
including configuration file /etc/freeradius/modules/mac2ip
including configuration file /etc/freeradius/modules/preprocess
including configuration file /etc/freeradius/eap.conf
including configuration file /etc/freeradius/sql.conf
including configuration file /etc/freeradius/sql/mysql/dialup.conf
including configuration file /etc/freeradius/policy.conf
including files in directory /etc/freeradius/sites-enabled/
including configuration file /etc/freeradius/sites-enabled/default.original
including configuration file /etc/freeradius/sites-enabled/inner-tunnel.original
including configuration file /etc/freeradius/sites-enabled/inner-tunnel
including configuration file /etc/freeradius/sites-enabled/default
main {
        user = "freerad"
        group = "freerad"
        allow_core_dumps = no
}
including dictionary file /etc/freeradius/dictionary
main {
        prefix = "/usr"
        localstatedir = "/var"
        logdir = "/var/log/freeradius"
        libdir = "/usr/lib/freeradius"
        radacctdir = "/var/log/freeradius/radacct"
        hostname_lookups = no
        max_request_time = 30
        cleanup_delay = 5
        max_requests = 1024
        pidfile = "/var/run/freeradius/freeradius.pid"
        checkrad = "/usr/sbin/checkrad"
        debug_level = 0
        proxy_requests = yes
 log {
        stripped_names = no
        auth = no
        auth_badpass = no
        auth_goodpass = no
 }
 security {
        max_attributes = 200
        reject_delay = 1
        status_server = yes
 }
}
radiusd: #### Loading Realms and Home Servers ####
 proxy server {
        retry_delay = 5
        retry_count = 3
        default_fallback = no
        dead_time = 120
        wake_all_if_all_dead = no
 }
 home_server localhost {
        ipaddr = 127.0.0.1
        port = 1812
        type = "auth"
        secret = "testing123"
        response_window = 20
        max_outstanding = 65536
        require_message_authenticator = no
        zombie_period = 40
        status_check = "status-server"
        ping_interval = 30
        check_interval = 30
        num_answers_to_alive = 3
        num_pings_to_alive = 3
        revive_interval = 120
        status_check_timeout = 4
        irt = 2
        mrt = 16
        mrc = 5
        mrd = 30
 }
 home_server_pool my_auth_failover {
        type = fail-over
        home_server = localhost
 }
 realm example.com {
        auth_pool = my_auth_failover
 }
 realm LOCAL {
 }
radiusd: #### Loading Clients ####
 client localhost {
        ipaddr = 127.0.0.1
        require_message_authenticator = no
        secret = "testing123"
        nastype = "other"
 }
radiusd: #### Instantiating modules ####
 instantiate {
 Module: Linked to module rlm_exec
 Module: Instantiating exec
  exec {
        wait = no
        input_pairs = "request"
        shell_escape = yes
  }
 Module: Linked to module rlm_expr
 Module: Instantiating expr
 Module: Linked to module rlm_expiration
 Module: Instantiating expiration
  expiration {
        reply-message = "Password Has Expired  "
  }
 Module: Linked to module rlm_logintime
 Module: Instantiating logintime
  logintime {
        reply-message = "You are calling outside your allowed timespan  "
        minimum-timeout = 60
  }
 }
radiusd: #### Loading Virtual Servers ####
server inner-tunnel {
 modules {
 Module: Checking authenticate {...} for more modules to load
 Module: Linked to module rlm_pap
 Module: Instantiating pap
  pap {
        encryption_scheme = "auto"
        auto_header = no
  }
 Module: Linked to module rlm_chap
 Module: Instantiating chap
 Module: Linked to module rlm_mschap
 Module: Instantiating mschap
  mschap {
        use_mppe = yes
        require_encryption = no
        require_strong = no
        with_ntdomain_hack = no
  }
 Module: Linked to module rlm_unix
 Module: Instantiating unix
  unix {
        radwtmp = "/var/log/freeradius/radwtmp"
  }
 Module: Linked to module rlm_eap
 Module: Instantiating eap
  eap {
        default_eap_type = "tls"
        timer_expire = 60
        ignore_unknown_eap_types = no
        cisco_accounting_username_bug = no
        max_sessions = 4096
  }
 Module: Linked to sub-module rlm_eap_md5
 Module: Instantiating eap-md5
 Module: Linked to sub-module rlm_eap_leap
 Module: Instantiating eap-leap
 Module: Linked to sub-module rlm_eap_gtc
 Module: Instantiating eap-gtc
   gtc {
        challenge = "Password: "
        auth_type = "PAP"
   }
 Module: Linked to sub-module rlm_eap_tls
 Module: Instantiating eap-tls
   tls {
        rsa_key_exchange = no
        dh_key_exchange = yes
        rsa_key_length = 512
        dh_key_length = 512
        verify_depth = 0
        pem_file_type = yes
        private_key_file = "/etc/freeradius/certs/server.key.pem"
        certificate_file = "/etc/freeradius/certs/server.cert.pem"
        CA_file = "/etc/freeradius/certs/cacert.pem"
        private_key_password = "mypassword"
        dh_file = "/etc/freeradius/certs/dh"
        random_file = "/etc/freeradius/certs/random"
        fragment_size = 1024
        include_length = yes
        check_crl = no
        cipher_list = "DEFAULT"
        make_cert_command = "/etc/freeradius/certs/bootstrap"
    cache {
        enable = no
        lifetime = 24
        max_entries = 255
    }
   }
 Module: Linked to sub-module rlm_eap_ttls
 Module: Instantiating eap-ttls
   ttls {
        default_eap_type = "md5"
        copy_request_to_tunnel = no
        use_tunneled_reply = no
        virtual_server = "inner-tunnel"
        include_length = yes
   }
 Module: Linked to sub-module rlm_eap_peap
 Module: Instantiating eap-peap
   peap {
        default_eap_type = "mschapv2"
        copy_request_to_tunnel = no
        use_tunneled_reply = no
        proxy_tunneled_request_as_eap = yes
        virtual_server = "inner-tunnel"
   }
 Module: Linked to sub-module rlm_eap_mschapv2
 Module: Instantiating eap-mschapv2
   mschapv2 {
        with_ntdomain_hack = no
   }
 Module: Checking authorize {...} for more modules to load
 Module: Linked to module rlm_realm
 Module: Instantiating suffix
  realm suffix {
        format = "suffix"
        delimiter = "@"
        ignore_default = no
        ignore_null = no
  }
 Module: Linked to module rlm_files
 Module: Instantiating files
  files {
        usersfile = "/etc/freeradius/users"
        acctusersfile = "/etc/freeradius/acct_users"
        preproxy_usersfile = "/etc/freeradius/preproxy_users"
        compat = "no"
  }
 Module: Checking session {...} for more modules to load
 Module: Linked to module rlm_radutmp
 Module: Instantiating radutmp
  radutmp {
        filename = "/var/log/freeradius/radutmp"
        username = "%{User-Name}"
        case_sensitive = yes
        check_with_nas = yes
        perm = 384
        callerid = yes
  }
 Module: Checking post-proxy {...} for more modules to load
 Module: Checking post-auth {...} for more modules to load
 Module: Linked to module rlm_attr_filter
 Module: Instantiating attr_filter.access_reject
  attr_filter attr_filter.access_reject {
        attrsfile = "/etc/freeradius/attrs.access_reject"
        key = "%{User-Name}"
  }
 } # modules
} # server
server inner-tunnel {
 modules {
 Module: Checking authenticate {...} for more modules to load
 Module: Checking authorize {...} for more modules to load
 Module: Linked to module rlm_sql
 Module: Instantiating sql
  sql {
        driver = "rlm_sql_mysql"
        server = "localhost"
        port = ""
        login = "radius"
        password = "radpass"
        radius_db = "radius"
        read_groups = yes
        sqltrace = yes
        sqltracefile = "/var/log/freeradius/sqltrace.sql"
        readclients = yes
        deletestalesessions = yes
        num_sql_socks = 5
        lifetime = 0
        max_queries = 0
        sql_user_name = "%{User-Name}"
        default_user_profile = ""
        nas_query = "SELECT id, nasname, shortname, type, secret FROM nas"
        authorize_check_query = "SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '%{SQL-User-Name}'           ORDER BY id"
        authorize_reply_query = "SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id"
        authorize_group_check_query = "SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'           ORDER BY id"
        authorize_group_reply_query = "SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = '%{Sql-Group}'           ORDER BY id"
        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'"
        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}'"
        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}')"
        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}')"
        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}'"
        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}'"
        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}')"
        group_membership_query = "SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority"
        connect_failure_retry_delay = 60
        simul_count_query = ""
        simul_verify_query = "SELECT radacctid, acctsessionid, username,                                nasipaddress, nasportid, framedipaddress,                                callingstationid, framedprotocol                                FROM radacct                                WHERE username = '%{SQL-User-Name}'                                AND acctstoptime IS NULL"
        postauth_query = "INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '%{User-Name}',                           '%{%{User-Password}:-%{Chap-Password}}',                           '%{reply:Packet-Type}', '%S')"
        safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
  }
rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
rlm_sql (sql): Attempting to connect to radius@localhost:/radius
rlm_sql (sql): starting 0
rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
rlm_sql_mysql: Starting connect to MySQL server for #0
rlm_sql (sql): Connected new DB handle, #0
rlm_sql (sql): starting 1
rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
rlm_sql_mysql: Starting connect to MySQL server for #1
rlm_sql (sql): Connected new DB handle, #1
rlm_sql (sql): starting 2
rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
rlm_sql_mysql: Starting connect to MySQL server for #2
rlm_sql (sql): Connected new DB handle, #2
rlm_sql (sql): starting 3
rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
rlm_sql_mysql: Starting connect to MySQL server for #3
rlm_sql (sql): Connected new DB handle, #3
rlm_sql (sql): starting 4
rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
rlm_sql_mysql: Starting connect to MySQL server for #4
rlm_sql (sql): Connected new DB handle, #4
rlm_sql (sql): Processing generate_sql_clients
rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret FROM nas
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql_mysql: query:  SELECT id, nasname, shortname, type, secret FROM nas
rlm_sql (sql): Read entry nasname=192.168.1.10,shortname=Cisco_AP,secret=mysecret
rlm_sql (sql): Adding client 192.168.1.10 (Cisco_AP, server=<none>) to clients list
rlm_sql (sql): Read entry nasname=172.31.30.253,shortname=Cisco_AP1231G,secret=mysecret
rlm_sql (sql): Adding client 172.31.30.253 (Cisco_AP1231G, server=<none>) to clients list
rlm_sql (sql): Read entry nasname=172.31.30.248,shortname=Cisco_WS-C2960G-24TC-L,secret=mysecret
rlm_sql (sql): Adding client 172.31.30.248 (Cisco_WS-C2960G-24TC-L, server=<none>) to clients list
rlm_sql (sql): Released sql socket id: 4
 Module: Checking session {...} for more modules to load
 Module: Checking post-proxy {...} for more modules to load
 Module: Checking post-auth {...} for more modules to load
 } # modules
} # server
server {
 modules {
 Module: Checking authenticate {...} for more modules to load
 Module: Checking authorize {...} for more modules to load
 Module: Linked to module rlm_preprocess
 Module: Instantiating preprocess
  preprocess {
        huntgroups = "/etc/freeradius/huntgroups"
        hints = "/etc/freeradius/hints"
        with_ascend_hack = no
        ascend_channels_per_line = 23
        with_ntdomain_hack = no
        with_specialix_jetstream_hack = no
        with_cisco_vsa_hack = no
        with_alvarion_vsa_hack = no
  }
 Module: Checking preacct {...} for more modules to load
 Module: Linked to module rlm_acct_unique
 Module: Instantiating acct_unique
  acct_unique {
        key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
  }
 Module: Checking accounting {...} for more modules to load
 Module: Linked to module rlm_detail
 Module: Instantiating detail
  detail {
        detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
        header = "%t"
        detailperm = 384
        dirperm = 493
        locking = no
        log_packet_header = no
  }
 Module: Instantiating attr_filter.accounting_response
  attr_filter attr_filter.accounting_response {
        attrsfile = "/etc/freeradius/attrs.accounting_response"
        key = "%{User-Name}"
  }
 Module: Checking session {...} for more modules to load
 Module: Checking post-proxy {...} for more modules to load
 Module: Checking post-auth {...} for more modules to load
 } # modules
} # server
radiusd: #### Opening IP addresses and Ports ####
listen {
        type = "auth"
        ipaddr = *
        port = 0
}
listen {
        type = "acct"
        ipaddr = *
        port = 0
}
Listening on authentication address * port 1812
Listening on accounting address * port 1813
Listening on proxy address * port 1814
Ready to process requests.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=42, length=168
        User-Name = "chris"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0x22cfd06dc63fecbf514249a82dbde4bc
        EAP-Message = 0x0202000a016368726973
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "262"
        NAS-Port = 262
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 2 length 10
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[unix] returns notfound
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type tls
[tls] Requiring client certificate
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 42 to 192.168.1.10 port 1645
        EAP-Message = 0x010300060d20
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2a57504e2a545dbe928d38fe8a093633
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=43, length=182
        User-Name = "chris"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0xb4d10334ac7e9423fadf06a64e93148e
        EAP-Message = 0x020300060319
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "262"
        NAS-Port = 262
        State = 0x2a57504e2a545dbe928d38fe8a093633
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 3 length 6
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[unix] returns notfound
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP NAK
[eap] EAP-NAK asked for EAP-Type/peap
[eap] processing type tls
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 43 to 192.168.1.10 port 1645
        EAP-Message = 0x010400061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2a57504e2b5349be928d38fe8a093633
Finished request 1.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=44, length=256
        User-Name = "chris"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0x78cb50ec9624393e3ba785cd6a41707a
        EAP-Message = 0x0204005019800000004616030100410100003d03014bfec8a9af308f129cd86d09c6f33eecf203e7f6c3aaba167d503a5f626e2b8200001600040005000a000900640062000300060013001200630100
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "262"
        NAS-Port = 262
        State = 0x2a57504e2b5349be928d38fe8a093633
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 4 length 80
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 70
[peap] Length Included
[peap] eaptls_verify returned 11
[peap]     (other): before/accept initialization
[peap]     TLS_accept: before/accept initialization
[peap] <<< TLS 1.0 Handshake [length 0041], ClientHello
[peap]     TLS_accept: SSLv3 read client hello A
[peap] >>> TLS 1.0 Handshake [length 002a], ServerHello
[peap]     TLS_accept: SSLv3 write server hello A
[peap] >>> TLS 1.0 Handshake [length 06b2], Certificate
[peap]     TLS_accept: SSLv3 write certificate A
[peap] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
[peap]     TLS_accept: SSLv3 write server done A
[peap]     TLS_accept: SSLv3 flush data
[peap]     TLS_accept: Need to read more data: SSLv3 read client certificate A
In SSL Handshake Phase
In SSL Accept mode
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 44 to 192.168.1.10 port 1645
        EAP-Message = 0x0105040019c0000006ef160301002a0200002603014bfee4dee0768006b29fde90060810230ebda962e851a9a527405f300df187890000040016030106b20b0006ae0006ab000309308203053082026ea003020102020102300d06092a864886f70d0101050500308195310b3009060355040613024154311630140603550408140d4c6f7765725f4175737472696131143012060355040a130b5363687761626c2e6e657431143012060355040b130b5363687761626c2e6e6574311730150603550403130e5363687761626c2e6e65742d43413129302706092a864886f70d010901161a696330376231353440746563686e696b756d2d7769656e2e
        EAP-Message = 0x6174301e170d3130303532333139323131305a170d3131303532333139323131305a307e310b3009060355040613024154311630140603550408140d4c6f7765725f4175737472696131143012060355040a130b5363687761626c2e6e6574311630140603550403130d5261646975732d5365727665723129302706092a864886f70d010901161a696330376231353440746563686e696b756d2d7769656e2e617430819f300d06092a864886f70d010101050003818d0030818902818100c076dfb4ca1826d6f8166a822bf8ef8f05024382a22b0f40cac4d5bcbbeb39b4fea2f247784ad35476e6f15e5d25e1082b7105a216d8b430ecd74ffe12b1
        EAP-Message = 0xd7fc89e68e8a4e1958ef92d3015e1fba2b2e8efac20a7d22d90592c2f374e4ce4be5306cdaa61121145f7e8d972778510bfe3c3b58505a041ee26c77da8e70980c1b0203010001a37b307930090603551d1304023000302c06096086480186f842010d041f161d4f70656e53534c2047656e657261746564204365727469666963617465301d0603551d0e04160414a5a0219f3c3ae954e9bcb791eb6669a1bc8db633301f0603551d23041830168014632dc26d8307decc9b180a907e907fe8f19a2cd1300d06092a864886f70d0101050500038181006808aa2a5dd77a9a228ac9c2b82e8fe4e468e45970677657e0288f23601cd5e79208016f4fd2
        EAP-Message = 0x0037d0a06fe7d7e61f80ffba10155acf394d621d2ffee66633f1b274668dda7bb38a97f76607758fa0ecdac86e7eb51b49e51f6f4bd472c7a87b9d6a5f538d8c540869c3a79ec56b2cd7da9c494386f76e6dcc77c664a44ca84800039c3082039830820301a003020102020100300d06092a864886f70d0101050500308195310b3009060355040613024154311630140603550408140d4c6f7765725f4175737472696131143012060355040a130b5363687761626c2e6e657431143012060355040b130b5363687761626c2e6e6574311730150603550403130e5363687761626c2e6e65742d43413129302706092a864886f70d010901161a696330
        EAP-Message = 0x376231353440746563686e69
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2a57504e285249be928d38fe8a093633
Finished request 2.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=45, length=182
        User-Name = "chris"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0x698467b0d28c3e269d82c5600b82d950
        EAP-Message = 0x020500061900
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "262"
        NAS-Port = 262
        State = 0x2a57504e285249be928d38fe8a093633
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 5 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 45 to 192.168.1.10 port 1645
        EAP-Message = 0x010602ff19006b756d2d7769656e2e6174301e170d3130303532333138323933335a170d3133303532323138323933335a308195310b3009060355040613024154311630140603550408140d4c6f7765725f4175737472696131143012060355040a130b5363687761626c2e6e657431143012060355040b130b5363687761626c2e6e6574311730150603550403130e5363687761626c2e6e65742d43413129302706092a864886f70d010901161a696330376231353440746563686e696b756d2d7769656e2e617430819f300d06092a864886f70d010101050003818d0030818902818100d305ff986137a39af2a65dfbe42d90c224442cf302d6f1
        EAP-Message = 0x7249eab3c9cb0915a470d7553391ac03c815960288d42f632360d53b6837e9a9f5fa3e33726400c94f9d5a20fc360fd7c3bef040082dc27fdbc6106f51451e9985926d0efcf101989391ec314fee1499c34215e9c6cf8a0dcc60034b434f650efd2c13bf3a8757d2d10203010001a381f53081f2301d0603551d0e04160414632dc26d8307decc9b180a907e907fe8f19a2cd13081c20603551d230481ba3081b78014632dc26d8307decc9b180a907e907fe8f19a2cd1a1819ba48198308195310b3009060355040613024154311630140603550408140d4c6f7765725f4175737472696131143012060355040a130b5363687761626c2e6e65743114
        EAP-Message = 0x3012060355040b130b5363687761626c2e6e6574311730150603550403130e5363687761626c2e6e65742d43413129302706092a864886f70d010901161a696330376231353440746563686e696b756d2d7769656e2e6174820100300c0603551d13040530030101ff300d06092a864886f70d0101050500038181009236a8cf95590161376d1becd4213648842298bbe09648a6263465ed08b5325268c5aa5d9fd5fb32319377fe81bfce29f8ad9f9241f35be74d8fbef2a1c29239e97e6835400816845639a076e1f95301d37ce8b3fca6c5b5d3bed63d2f6fe3f5cb1c8648783d01283680551056ea2d919a46c1d98be744b2b65a0834e8f2d25c16
        EAP-Message = 0x030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2a57504e295149be928d38fe8a093633
Finished request 3.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=46, length=368
        User-Name = "chris"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0xfe04315ca4d84902dd13a58bd71dd7f0
        EAP-Message = 0x020600c01980000000b61603010086100000820080a1a442990f66d32b18c6d054886e412902b439cba985eb63f7809bd8394649c93227fbdf089e3f5fef1ff748eee9553341cae08a11fa26a926dd04b973b96b249f51adee496b933ba5bbdd1959f7e4f0d878237f7f859d7e8116e2adf304359fe4ed8b26f7cb678b082ecd50b9e5bba62494cea3c11c6e51f34df4abaefc15ae1403010001011603010020241c787022411a0acff94053f3f00d5a92194ea21d88d6bfcd1700489b165eb2
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "262"
        NAS-Port = 262
        State = 0x2a57504e295149be928d38fe8a093633
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 6 length 192
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 182
[peap] Length Included
[peap] eaptls_verify returned 11
[peap] <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange
[peap]     TLS_accept: SSLv3 read client key exchange A
[peap] <<< TLS 1.0 ChangeCipherSpec [length 0001]
[peap] <<< TLS 1.0 Handshake [length 0010], Finished
[peap]     TLS_accept: SSLv3 read finished A
[peap] >>> TLS 1.0 ChangeCipherSpec [length 0001]
[peap]     TLS_accept: SSLv3 write change cipher spec A
[peap] >>> TLS 1.0 Handshake [length 0010], Finished
[peap]     TLS_accept: SSLv3 write finished A
[peap]     TLS_accept: SSLv3 flush data
[peap]     (other): SSL negotiation finished successfully
SSL Connection Established
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 46 to 192.168.1.10 port 1645
        EAP-Message = 0x010700311900140301000101160301002083c7875a3344c6050c92fcd8e88972a8f8b0ddefc984dad1d20df2671a823f74
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2a57504e2e5049be928d38fe8a093633
Finished request 4.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=47, length=182
        User-Name = "chris"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0xfe1cc5aea07c71076eb9d75df14f9fa1
        EAP-Message = 0x020700061900
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "262"
        NAS-Port = 262
        State = 0x2a57504e2e5049be928d38fe8a093633
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 7 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake is finished
[peap] eaptls_verify returned 3
[peap] eaptls_process returned 3
[peap] EAPTLS_SUCCESS
++[eap] returns handled
Sending Access-Challenge of id 47 to 192.168.1.10 port 1645
        EAP-Message = 0x010800201900170301001537b1ff16f2991962d9e5cdd6622dba1795f0d966f5
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2a57504e2f5f49be928d38fe8a093633
Finished request 5.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=48, length=209
        User-Name = "chris"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0x95f51b2629c891e1d9f2ff4c523e59f2
        EAP-Message = 0x0208002119001703010016d5c2538464285a414d16c0bf45604e1b2d80578d883d
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "262"
        NAS-Port = 262
        State = 0x2a57504e2f5f49be928d38fe8a093633
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 8 length 33
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] Identity - chris
[peap] Got tunneled request
        EAP-Message = 0x0208000a016368726973
server  {
  PEAP: Got tunneled identity of chris
  PEAP: Setting default EAP type for tunneled EAP session.
  PEAP: Setting User-Name to chris
Sending tunneled request
        EAP-Message = 0x0208000a016368726973
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "chris"
server inner-tunnel {
+- entering group authorize {...}
++[chap] returns noop
++[mschap] returns noop
++[unix] returns notfound
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 8 length 10
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
[sql]   expand: %{User-Name} -> chris
[sql] sql_set_user escaped user --> 'chris'
rlm_sql (sql): Reserving sql socket id: 3
[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 = 'chris'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = 'chris'           ORDER BY id
[sql]   expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = 'chris'           ORDER BY priority
rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup           WHERE username = 'chris'           ORDER BY priority
rlm_sql (sql): Released sql socket id: 3
[sql] User chris not found
++[sql] returns notfound
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type mschapv2
rlm_eap_mschapv2: Issuing Challenge
++[eap] returns handled
} # server inner-tunnel
[peap] Got tunneled reply code 11
        EAP-Message = 0x0109001f1a0109001a1079f5c25544b00bc0f15b8fbc43a40c3e6368726973
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x4142dcbf414bc68e27f56993db94fcab
[peap] Got tunneled reply RADIUS code 11
        EAP-Message = 0x0109001f1a0109001a1079f5c25544b00bc0f15b8fbc43a40c3e6368726973
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x4142dcbf414bc68e27f56993db94fcab
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 48 to 192.168.1.10 port 1645
        EAP-Message = 0x010900361900170301002b805c707b1f70c6625534c3c2a6e26434026db66d4fdcd89d27ec4a257d2b6ce559622dcda979ce1bfcb4b3
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2a57504e2c5e49be928d38fe8a093633
Finished request 6.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=49, length=263
        User-Name = "chris"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0xce135006c1f2580cee501a2249444c19
        EAP-Message = 0x020900571900170301004c8f55f00e9d272d8ace2d0de9dc62a696b94e82c97e870dc87471faa7bbcc3e92640458000deec8d1e3626335f91cde205ad6ee999c5e642f8dd3efcf1e7df7eb68ab248084208aebde9a4437
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "262"
        NAS-Port = 262
        State = 0x2a57504e2c5e49be928d38fe8a093633
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 9 length 87
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] EAP type mschapv2
[peap] Got tunneled request
        EAP-Message = 0x020900401a0209003b31d9895626ae505b45cc1d66c2c280a51b0000000000000000616262f28d61e3200b280fb86915d4249cda5ce81cb0eb85006368726973
server  {
  PEAP: Setting User-Name to chris
Sending tunneled request
        EAP-Message = 0x020900401a0209003b31d9895626ae505b45cc1d66c2c280a51b0000000000000000616262f28d61e3200b280fb86915d4249cda5ce81cb0eb85006368726973
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "chris"
        State = 0x4142dcbf414bc68e27f56993db94fcab
server inner-tunnel {
+- entering group authorize {...}
++[chap] returns noop
++[mschap] returns noop
++[unix] returns notfound
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 9 length 64
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
[sql]   expand: %{User-Name} -> chris
[sql] sql_set_user escaped user --> 'chris'
rlm_sql (sql): Reserving sql socket id: 2
[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 = 'chris'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = 'chris'           ORDER BY id
[sql]   expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = 'chris'           ORDER BY priority
rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup           WHERE username = 'chris'           ORDER BY priority
rlm_sql (sql): Released sql socket id: 2
[sql] User chris not found
++[sql] returns notfound
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[mschapv2] +- entering group MS-CHAP {...}
[mschap] No Cleartext-Password configured.  Cannot create LM-Password.
[mschap] No Cleartext-Password configured.  Cannot create NT-Password.
[mschap] Told to do MS-CHAPv2 for chris with NT-Password
[mschap] FAILED: No NT/LM-Password.  Cannot perform authentication.
[mschap] FAILED: MS-CHAP2-Response is incorrect
++[mschap] returns reject
[eap] Freeing handler
++[eap] returns reject
Failed to authenticate the user.
} # server inner-tunnel
[peap] Got tunneled reply code 3
        MS-CHAP-Error = "\tE=691 R=1"
        EAP-Message = 0x04090004
        Message-Authenticator = 0x00000000000000000000000000000000
[peap] Got tunneled reply RADIUS code 3
        MS-CHAP-Error = "\tE=691 R=1"
        EAP-Message = 0x04090004
        Message-Authenticator = 0x00000000000000000000000000000000
[peap] Tunneled authentication was rejected.
[peap] FAILURE
++[eap] returns handled
Sending Access-Challenge of id 49 to 192.168.1.10 port 1645
        EAP-Message = 0x010a00261900170301001b9c07a0c0242faf6113db6baa2b33210089aa118dfbbb9751b1cd6d
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x2a57504e2d5d49be928d38fe8a093633
Finished request 7.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=50, length=214
        User-Name = "chris"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0xc639c2cc4551af2bc718150dfa60f892
        EAP-Message = 0x020a00261900170301001b0ce6b16ef513e3b7e6393c2ae7004cf9a398eca7c5d1bd3ab24656
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "262"
        NAS-Port = 262
        State = 0x2a57504e2d5d49be928d38fe8a093633
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chris", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 10 length 38
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] Received EAP-TLV response.
[peap]  Had sent TLV failure.  User was rejected earlier in this session.
[eap] Handler failed in EAP/peap
[eap] Failed in EAP select
++[eap] returns invalid
Failed to authenticate the user.
Using Post-Auth-Type Reject
+- entering group REJECT {...}
[attr_filter.access_reject]     expand: %{User-Name} -> chris
 attr_filter: Matched entry DEFAULT at line 11
++[attr_filter.access_reject] returns updated
Delaying reject of request 8 for 1 seconds
Going to the next request
Waking up in 0.9 seconds.
Sending delayed reject for request 8
Sending Access-Reject of id 50 to 192.168.1.10 port 1645
        EAP-Message = 0x040a0004
        Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 3.7 seconds.
Cleaning up request 0 ID 42 with timestamp +9
Cleaning up request 1 ID 43 with timestamp +9
Cleaning up request 2 ID 44 with timestamp +9
Cleaning up request 3 ID 45 with timestamp +9
Cleaning up request 4 ID 46 with timestamp +9
Cleaning up request 5 ID 47 with timestamp +9
Cleaning up request 6 ID 48 with timestamp +9
Cleaning up request 7 ID 49 with timestamp +10
Waking up in 0.9 seconds.
Cleaning up request 8 ID 50 with timestamp +10
Ready to process requests.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=51, length=174
        User-Name = "chrissql"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0xc37cf023eb2115ac9cdeb0c30aca92ee
        EAP-Message = 0x0202000d01636872697373716c
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 2 length 13
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[unix] returns notfound
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type tls
[tls] Requiring client certificate
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 51 to 192.168.1.10 port 1645
        EAP-Message = 0x010300060d20
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xff17d477ff14d96bf87c1a0825a175c5
Finished request 9.
Going to the next request
Waking up in 4.10 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=52, length=185
        User-Name = "chrissql"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0xf9712edb6aafa44cabbcb1ddd7f55cbb
        EAP-Message = 0x020300060319
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        State = 0xff17d477ff14d96bf87c1a0825a175c5
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 3 length 6
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[unix] returns notfound
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP NAK
[eap] EAP-NAK asked for EAP-Type/peap
[eap] processing type tls
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 52 to 192.168.1.10 port 1645
        EAP-Message = 0x010400061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xff17d477fe13cd6bf87c1a0825a175c5
Finished request 10.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=53, length=259
        User-Name = "chrissql"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0x272e8560693d346925faeb50ac6100f5
        EAP-Message = 0x0204005019800000004616030100410100003d03014bfec8b1333e79f791a11bc64753d36384cea40262b2270174ae0abc45f5677e00001600040005000a000900640062000300060013001200630100
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        State = 0xff17d477fe13cd6bf87c1a0825a175c5
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 4 length 80
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 70
[peap] Length Included
[peap] eaptls_verify returned 11
[peap]     (other): before/accept initialization
[peap]     TLS_accept: before/accept initialization
[peap] <<< TLS 1.0 Handshake [length 0041], ClientHello
[peap]     TLS_accept: SSLv3 read client hello A
[peap] >>> TLS 1.0 Handshake [length 002a], ServerHello
[peap]     TLS_accept: SSLv3 write server hello A
[peap] >>> TLS 1.0 Handshake [length 06b2], Certificate
[peap]     TLS_accept: SSLv3 write certificate A
[peap] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
[peap]     TLS_accept: SSLv3 write server done A
[peap]     TLS_accept: SSLv3 flush data
[peap]     TLS_accept: Need to read more data: SSLv3 read client certificate A
In SSL Handshake Phase
In SSL Accept mode
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 53 to 192.168.1.10 port 1645
        EAP-Message = 0x0105040019c0000006ef160301002a0200002603014bfee4e768ff790f16fa3eb962dee6d2e9cec08b5d7128a63a392713a6bd12e00000040016030106b20b0006ae0006ab000309308203053082026ea003020102020102300d06092a864886f70d0101050500308195310b3009060355040613024154311630140603550408140d4c6f7765725f4175737472696131143012060355040a130b5363687761626c2e6e657431143012060355040b130b5363687761626c2e6e6574311730150603550403130e5363687761626c2e6e65742d43413129302706092a864886f70d010901161a696330376231353440746563686e696b756d2d7769656e2e
        EAP-Message = 0x6174301e170d3130303532333139323131305a170d3131303532333139323131305a307e310b3009060355040613024154311630140603550408140d4c6f7765725f4175737472696131143012060355040a130b5363687761626c2e6e6574311630140603550403130d5261646975732d5365727665723129302706092a864886f70d010901161a696330376231353440746563686e696b756d2d7769656e2e617430819f300d06092a864886f70d010101050003818d0030818902818100c076dfb4ca1826d6f8166a822bf8ef8f05024382a22b0f40cac4d5bcbbeb39b4fea2f247784ad35476e6f15e5d25e1082b7105a216d8b430ecd74ffe12b1
        EAP-Message = 0xd7fc89e68e8a4e1958ef92d3015e1fba2b2e8efac20a7d22d90592c2f374e4ce4be5306cdaa61121145f7e8d972778510bfe3c3b58505a041ee26c77da8e70980c1b0203010001a37b307930090603551d1304023000302c06096086480186f842010d041f161d4f70656e53534c2047656e657261746564204365727469666963617465301d0603551d0e04160414a5a0219f3c3ae954e9bcb791eb6669a1bc8db633301f0603551d23041830168014632dc26d8307decc9b180a907e907fe8f19a2cd1300d06092a864886f70d0101050500038181006808aa2a5dd77a9a228ac9c2b82e8fe4e468e45970677657e0288f23601cd5e79208016f4fd2
        EAP-Message = 0x0037d0a06fe7d7e61f80ffba10155acf394d621d2ffee66633f1b274668dda7bb38a97f76607758fa0ecdac86e7eb51b49e51f6f4bd472c7a87b9d6a5f538d8c540869c3a79ec56b2cd7da9c494386f76e6dcc77c664a44ca84800039c3082039830820301a003020102020100300d06092a864886f70d0101050500308195310b3009060355040613024154311630140603550408140d4c6f7765725f4175737472696131143012060355040a130b5363687761626c2e6e657431143012060355040b130b5363687761626c2e6e6574311730150603550403130e5363687761626c2e6e65742d43413129302706092a864886f70d010901161a696330
        EAP-Message = 0x376231353440746563686e69
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xff17d477fd12cd6bf87c1a0825a175c5
Finished request 11.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=54, length=185
        User-Name = "chrissql"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0x3a801c737ba960f10447e9735062e395
        EAP-Message = 0x020500061900
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        State = 0xff17d477fd12cd6bf87c1a0825a175c5
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 5 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 54 to 192.168.1.10 port 1645
        EAP-Message = 0x010602ff19006b756d2d7769656e2e6174301e170d3130303532333138323933335a170d3133303532323138323933335a308195310b3009060355040613024154311630140603550408140d4c6f7765725f4175737472696131143012060355040a130b5363687761626c2e6e657431143012060355040b130b5363687761626c2e6e6574311730150603550403130e5363687761626c2e6e65742d43413129302706092a864886f70d010901161a696330376231353440746563686e696b756d2d7769656e2e617430819f300d06092a864886f70d010101050003818d0030818902818100d305ff986137a39af2a65dfbe42d90c224442cf302d6f1
        EAP-Message = 0x7249eab3c9cb0915a470d7553391ac03c815960288d42f632360d53b6837e9a9f5fa3e33726400c94f9d5a20fc360fd7c3bef040082dc27fdbc6106f51451e9985926d0efcf101989391ec314fee1499c34215e9c6cf8a0dcc60034b434f650efd2c13bf3a8757d2d10203010001a381f53081f2301d0603551d0e04160414632dc26d8307decc9b180a907e907fe8f19a2cd13081c20603551d230481ba3081b78014632dc26d8307decc9b180a907e907fe8f19a2cd1a1819ba48198308195310b3009060355040613024154311630140603550408140d4c6f7765725f4175737472696131143012060355040a130b5363687761626c2e6e65743114
        EAP-Message = 0x3012060355040b130b5363687761626c2e6e6574311730150603550403130e5363687761626c2e6e65742d43413129302706092a864886f70d010901161a696330376231353440746563686e696b756d2d7769656e2e6174820100300c0603551d13040530030101ff300d06092a864886f70d0101050500038181009236a8cf95590161376d1becd4213648842298bbe09648a6263465ed08b5325268c5aa5d9fd5fb32319377fe81bfce29f8ad9f9241f35be74d8fbef2a1c29239e97e6835400816845639a076e1f95301d37ce8b3fca6c5b5d3bed63d2f6fe3f5cb1c8648783d01283680551056ea2d919a46c1d98be744b2b65a0834e8f2d25c16
        EAP-Message = 0x030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xff17d477fc11cd6bf87c1a0825a175c5
Finished request 12.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=55, length=371
        User-Name = "chrissql"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0x8b1bb6cac177c15b40722b18b1fd8a1f
        EAP-Message = 0x020600c01980000000b616030100861000008200802395ae24d1a20b9353404e5bef9ec4ad7eb7adae1d2cafd1503148374d8a65128e452779378ac55ecbf917a2e858aca61df080c0287bfd5a4c3b68d5e20493accb156d3273352dc78541313650fce6ec5a1964322a78680f80bcbca3efdb20e822eea0c3979bb48f7285d7ade8dd6f7809c1efa22289920be909a45887339d2014030100010116030100206a52fc4373defc01cf675e2bda5231cd7fd9aa0801d4baa12125c66c13128842
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        State = 0xff17d477fc11cd6bf87c1a0825a175c5
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 6 length 192
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 182
[peap] Length Included
[peap] eaptls_verify returned 11
[peap] <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange
[peap]     TLS_accept: SSLv3 read client key exchange A
[peap] <<< TLS 1.0 ChangeCipherSpec [length 0001]
[peap] <<< TLS 1.0 Handshake [length 0010], Finished
[peap]     TLS_accept: SSLv3 read finished A
[peap] >>> TLS 1.0 ChangeCipherSpec [length 0001]
[peap]     TLS_accept: SSLv3 write change cipher spec A
[peap] >>> TLS 1.0 Handshake [length 0010], Finished
[peap]     TLS_accept: SSLv3 write finished A
[peap]     TLS_accept: SSLv3 flush data
[peap]     (other): SSL negotiation finished successfully
SSL Connection Established
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 55 to 192.168.1.10 port 1645
        EAP-Message = 0x0107003119001403010001011603010020e130bde14f6eefa1110355ca0c0e0f68ca66204ef12fae48f914abe84b91c06a
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xff17d477fb10cd6bf87c1a0825a175c5
Finished request 13.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=56, length=185
        User-Name = "chrissql"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0xd025603cedc5734c4c8781e910e1804a
        EAP-Message = 0x020700061900
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        State = 0xff17d477fb10cd6bf87c1a0825a175c5
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 7 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake is finished
[peap] eaptls_verify returned 3
[peap] eaptls_process returned 3
[peap] EAPTLS_SUCCESS
++[eap] returns handled
Sending Access-Challenge of id 56 to 192.168.1.10 port 1645
        EAP-Message = 0x0108002019001703010015b85297a41f7429d4aec9b730b423f7215cd88e2e31
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xff17d477fa1fcd6bf87c1a0825a175c5
Finished request 14.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=57, length=215
        User-Name = "chrissql"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0x870714066e246f79ca03ea191f2c1a75
        EAP-Message = 0x0208002419001703010019f429c37d3b6f891847c78afaad5d27dd0656b071aa6702656d
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        State = 0xff17d477fa1fcd6bf87c1a0825a175c5
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 8 length 36
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] Identity - chrissql
[peap] Got tunneled request
        EAP-Message = 0x0208000d01636872697373716c
server  {
  PEAP: Got tunneled identity of chrissql
  PEAP: Setting default EAP type for tunneled EAP session.
  PEAP: Setting User-Name to chrissql
Sending tunneled request
        EAP-Message = 0x0208000d01636872697373716c
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "chrissql"
server inner-tunnel {
+- entering group authorize {...}
++[chap] returns noop
++[mschap] returns noop
++[unix] returns notfound
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 8 length 13
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
[sql]   expand: %{User-Name} -> chrissql
[sql] sql_set_user escaped user --> 'chrissql'
rlm_sql (sql): Reserving sql socket id: 1
[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 = 'chrissql'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = 'chrissql'           ORDER BY id
[sql] User found in radcheck table
[sql]   expand: SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radreply           WHERE username = 'chrissql'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radreply           WHERE username = 'chrissql'           ORDER BY id
[sql]   expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = 'chrissql'           ORDER BY priority
rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup           WHERE username = 'chrissql'           ORDER BY priority
rlm_sql (sql): Released sql socket id: 1
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
[pap] Found existing Auth-Type, not changing it.
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type mschapv2
rlm_eap_mschapv2: Issuing Challenge
++[eap] returns handled
} # server inner-tunnel
[peap] Got tunneled reply code 11
        EAP-Message = 0x010900221a0109001d10030bdc79736f264c6b0531cc631e8837636872697373716c
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd7164b7bd71f51be0f03eeb40678ccfd
[peap] Got tunneled reply RADIUS code 11
        EAP-Message = 0x010900221a0109001d10030bdc79736f264c6b0531cc631e8837636872697373716c
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd7164b7bd71f51be0f03eeb40678ccfd
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 57 to 192.168.1.10 port 1645
        EAP-Message = 0x010900391900170301002e51c4a2f80ecc00bedba258308b49f01ecdae23669f6097ace8d2acd60afb54b523521dd1146554d5eedbf32466e0
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xff17d477f91ecd6bf87c1a0825a175c5
Finished request 15.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=58, length=269
        User-Name = "chrissql"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0xd8ae10fe6680baa4991a9b08e02c3e49
        EAP-Message = 0x0209005a1900170301004f0b8c081f44aad3068c1e57be1d85784e9880f1d99f54961b6c776ce302093d60d0d587b05a91ef93606a31b9dfadb049c20eb13d83a08f61c2c0457ce15503187dde2201de9cffd9ceab8dfb879c2a
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        State = 0xff17d477f91ecd6bf87c1a0825a175c5
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 9 length 90
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] EAP type mschapv2
[peap] Got tunneled request
        EAP-Message = 0x020900431a0209003e31f4d59f2d0653f8ab78aeb54ffd1c95eb0000000000000000553eed11f53c747e1c76c8b90aeaff6822bcf698cf3f1db600636872697373716c
server  {
  PEAP: Setting User-Name to chrissql
Sending tunneled request
        EAP-Message = 0x020900431a0209003e31f4d59f2d0653f8ab78aeb54ffd1c95eb0000000000000000553eed11f53c747e1c76c8b90aeaff6822bcf698cf3f1db600636872697373716c
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "chrissql"
        State = 0xd7164b7bd71f51be0f03eeb40678ccfd
server inner-tunnel {
+- entering group authorize {...}
++[chap] returns noop
++[mschap] returns noop
++[unix] returns notfound
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 9 length 67
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
[sql]   expand: %{User-Name} -> chrissql
[sql] sql_set_user escaped user --> 'chrissql'
rlm_sql (sql): Reserving sql socket id: 0
[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 = 'chrissql'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = 'chrissql'           ORDER BY id
[sql] User found in radcheck table
[sql]   expand: SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radreply           WHERE username = 'chrissql'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radreply           WHERE username = 'chrissql'           ORDER BY id
[sql]   expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = 'chrissql'           ORDER BY priority
rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup           WHERE username = 'chrissql'           ORDER BY priority
rlm_sql (sql): Released sql socket id: 0
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
[pap] Found existing Auth-Type, not changing it.
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[mschapv2] +- entering group MS-CHAP {...}
[mschap] Told to do MS-CHAPv2 for chrissql with NT-Password
[mschap] adding MS-CHAPv2 MPPE keys
++[mschap] returns ok
MSCHAP Success
++[eap] returns handled
} # server inner-tunnel
[peap] Got tunneled reply code 11
        EAP-Message = 0x010a00331a0309002e533d44463932423543414344423032303644394131394332344342313736464232443432433937394342
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd7164b7bd61c51be0f03eeb40678ccfd
[peap] Got tunneled reply RADIUS code 11
        EAP-Message = 0x010a00331a0309002e533d44463932423543414344423032303644394131394332344342313736464232443432433937394342
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd7164b7bd61c51be0f03eeb40678ccfd
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 58 to 192.168.1.10 port 1645
        EAP-Message = 0x010a004a1900170301003f960e418a51c403a62e94df282d49cc18c5c42ccd44cd23d83c07cf8bb8f8bf6459e72ed2006b80ec3e03a1649d5ccda7a370e25270737044cf9f0fa28daf63
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xff17d477f81dcd6bf87c1a0825a175c5
Finished request 16.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=59, length=208
        User-Name = "chrissql"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0xc4f051d99cfba333e6af5caae58c51ef
        EAP-Message = 0x020a001d1900170301001210d45bc4442d0bb6f5d798628bdca28b1db2
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        State = 0xff17d477f81dcd6bf87c1a0825a175c5
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 10 length 29
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] EAP type mschapv2
[peap] Got tunneled request
        EAP-Message = 0x020a00061a03
server  {
  PEAP: Setting User-Name to chrissql
Sending tunneled request
        EAP-Message = 0x020a00061a03
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "chrissql"
        State = 0xd7164b7bd61c51be0f03eeb40678ccfd
server inner-tunnel {
+- entering group authorize {...}
++[chap] returns noop
++[mschap] returns noop
++[unix] returns notfound
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 10 length 6
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
[sql]   expand: %{User-Name} -> chrissql
[sql] sql_set_user escaped user --> 'chrissql'
rlm_sql (sql): Reserving sql socket id: 4
[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 = 'chrissql'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = 'chrissql'           ORDER BY id
[sql] User found in radcheck table
[sql]   expand: SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radreply           WHERE username = 'chrissql'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radreply           WHERE username = 'chrissql'           ORDER BY id
[sql]   expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = 'chrissql'           ORDER BY priority
rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup           WHERE username = 'chrissql'           ORDER BY priority
rlm_sql (sql): Released sql socket id: 4
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
[pap] Found existing Auth-Type, not changing it.
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[eap] Freeing handler
++[eap] returns ok
  WARNING: Empty section.  Using default return values.
} # server inner-tunnel
[peap] Got tunneled reply code 2
        EAP-Message = 0x030a0004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "chrissql"
[peap] Got tunneled reply RADIUS code 2
        EAP-Message = 0x030a0004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "chrissql"
[peap] Tunneled authentication was successful.
[peap] SUCCESS
++[eap] returns handled
Sending Access-Challenge of id 59 to 192.168.1.10 port 1645
        EAP-Message = 0x010b00261900170301001b481da9778adc27e9a778b283789fcdb2dea1160cadc2e0b6d8d034
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xff17d477f71ccd6bf87c1a0825a175c5
Finished request 17.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 192.168.1.10 port 1645, id=60, length=217
        User-Name = "chrissql"
        Framed-MTU = 1400
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Service-Type = Login-User
        Message-Authenticator = 0x93a6dcbe8bf8cf784cff8de728366edc
        EAP-Message = 0x020b00261900170301001b838dfcacd81aec495b178bd2dd7d121e107067186fb44a1cb9e430
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        State = 0xff17d477f71ccd6bf87c1a0825a175c5
        NAS-IP-Address = 192.168.1.10
        NAS-Identifier = "Cisco_AP"
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 11 length 38
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] Received EAP-TLV response.
[peap] Success
[eap] Freeing handler
++[eap] returns ok
+- entering group post-auth {...}
++[exec] returns noop
Sending Access-Accept of id 60 to 192.168.1.10 port 1645
        MS-MPPE-Recv-Key = 0xafb06b17031c50daa2a990816583d7548fd0876bded1be39402156cb9bd5581e
        MS-MPPE-Send-Key = 0xbe88618fd6a4a85fca914738da461961a40374fce3b6871ef197f830ecf26035
        EAP-Message = 0x030b0004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "chrissql"
Finished request 18.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Accounting-Request packet from host 192.168.1.10 port 1646, id=77, length=234
        Acct-Session-Id = "0000000D"
        Called-Station-Id = "0011.2177.4ad0"
        Calling-Station-Id = "001f.3b1c.b52f"
        Cisco-AVPair = "ssid=radiustestcisco"
        Cisco-AVPair = "vlan-id=0"
        Cisco-AVPair = "nas-location=unspecified"
        User-Name = "chrissql"
        Cisco-AVPair = "connect-progress=Call Up"
        Acct-Authentic = RADIUS
        Acct-Status-Type = Start
        NAS-Port-Type = Wireless-802.11
        Cisco-NAS-Port = "263"
        NAS-Port = 263
        Service-Type = Framed-User
        NAS-IP-Address = 192.168.1.10
        Acct-Delay-Time = 0
+- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 263,Client-IP-Address = 192.168.1.10,NAS-IP-Address = 192.168.1.10,Acct-Session-Id = "0000000D",User-Name = "chrissql"'
[acct_unique] Acct-Unique-Session-ID = "ddc22f8239f447a4".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "chrissql", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[files] returns noop
+- entering group accounting {...}
[detail]        expand: /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/freeradius/radacct/192.168.1.10/detail-20100527
[detail] /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.1.10/detail-20100527
[detail]        expand: %t -> Thu May 27 23:32:23 2010
++[detail] returns ok
++[unix] returns ok
[radutmp]       expand: /var/log/freeradius/radutmp -> /var/log/freeradius/radutmp
[radutmp]       expand: %{User-Name} -> chrissql
++[radutmp] returns ok
[attr_filter.accounting_response]       expand: %{User-Name} -> chrissql
 attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 77 to 192.168.1.10 port 1646
Finished request 19.
Cleaning up request 19 ID 77 with timestamp +18
Going to the next request
Waking up in 4.7 seconds.
Cleaning up request 9 ID 51 with timestamp +18
Cleaning up request 10 ID 52 with timestamp +18
Cleaning up request 11 ID 53 with timestamp +18
Cleaning up request 12 ID 54 with timestamp +18
Cleaning up request 13 ID 55 with timestamp +18
Cleaning up request 14 ID 56 with timestamp +18
Cleaning up request 15 ID 57 with timestamp +18
Cleaning up request 16 ID 58 with timestamp +18
Cleaning up request 17 ID 59 with timestamp +18
Cleaning up request 18 ID 60 with timestamp +18

Ready to process requests.

Christoph Schwabl schrieb:
...
Hello,
I have a small problem with accounting to mysql.
freeradius 2.1.8
mysql  Ver 14.12 Distrib 5.0.51a, for debian-linux-gnu (i486) using readline 5.2
The NAS is sending accounting data, which I can see in:
more /var/log/freeradius/radacct/192.168.1.10/detail-20100526
...
Wed May 26 23:43:57 2010
 Acct-Session-Id = "00000039"
 Called-Station-Id = "0011.2177.0da4"
 Calling-Station-Id = "001f.3b1c.f25b"
 Cisco-AVPair = "ssid=testradius"
 Cisco-AVPair = "vlan-id=0"
 Cisco-AVPair = "nas-location=unspecified"
 User-Name = "testuser"
 Cisco-AVPair = "connect-progress=Call Up"
 Acct-Session-Time = 237
 Acct-Input-Octets = 35971
 Acct-Output-Octets = 64059
 Acct-Input-Packets = 473
 Acct-Output-Packets = 98
 Acct-Authentic = RADIUS
 Acct-Status-Type = Interim-Update
 NAS-Port-Type = Wireless-802.11
 Cisco-NAS-Port = "296"
 NAS-Port = 296
 Service-Type = Framed-User
 NAS-IP-Address = 192.168.1.10
 Acct-Delay-Time = 0
 Acct-Unique-Session-Id = "4d69927723cb56d8"
 Timestamp = 1274910237
 Request-Authenticator = Verified
But I cann't find accounting data in MySQL database.
My configuration is:
radiusd.conf
==================
...
$INCLUDE sql.conf
...
readclients = yes
...
sites-enabled/inner-tunnel
==================
...
authorize {
        chap
        mschap
        unix
        suffix
        update control {
               Proxy-To-Realm := LOCAL
        }
        eap {
                ok = return
        }
        files
        sql
        expiration
        logintime
        pap
}
...
sites-enabled/default
==================
...
authorize {
        preprocess
        chap
        mschap
        suffix
        eap {
                ok = return
        }
        unix
        files
        sql
        expiration
        logintime
        pap
}
...
accounting {
        detail
        unix
        radutmp
        sql
        attr_filter.accounting_response
}
...
Using users (radcheck) and clients (nas) from MySQL are working well.
However, accounting into MySQL is not working.
Anybody an idea?
thx & br
Christoph