Freeradius Proxy

22 Nov 2013

      Hi all!

I'm trying to configure radius proxy for EAP authentication but I don't 
know what is wrong in my config. I have a Radius server on a Ubuntu 
server with version 2.1.10 and my Radius proxy is a Pfsense with version 
2.2.0.

Authentication works fine on both servers but Pfsense doesn't proxied 
anything packet to the server. There is debug output of Pfsense.

FreeRADIUS Version 2.2.0, for host i386-portbld-freebsd8.3, built on Dec 
20 2012 at 23:43:04
Copyright (C) 1999-2012 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 /usr/pbi/freeradius-i386/etc/raddb/radiusd.conf
including configuration file /usr/pbi/freeradius-i386/etc/raddb/proxy.conf
including configuration file /usr/pbi/freeradius-i386/etc/raddb/clients.conf
including files in directory /usr/pbi/freeradius-i386/etc/raddb/modules/
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/wimax
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/always
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/attr_filter
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/attr_rewrite
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/cache
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/chap
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/checkval
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/counter
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/cui
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/detail
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/detail.example.com
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/detail.log
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/dhcp_sqlippool
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/sql/mysql/ippool-dhcp.conf
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/digest
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/dynamic_clients
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/echo
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/etc_group
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/exec
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/expiration
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/expr
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/files
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/inner-eap
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/ippool
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/krb5
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/ldap
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/linelog
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/otp
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/logintime
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/mac2ip
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/mac2vlan
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/mschap
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/ntlm_auth
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/opendirectory
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/pam
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/pap
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/passwd
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/perl
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/policy
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/preprocess
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/radrelay
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/radutmp
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/realm
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/redis
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/rediswho
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/replicate
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/smbpasswd
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/smsotp
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/soh
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/sql_log
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/sqlcounter_expire_on_login
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/sradutmp
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/unix
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/acct_unique
including configuration file /usr/pbi/freeradius-i386/etc/raddb/modules/motp
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/modules/datacounter_acct
including configuration file /usr/pbi/freeradius-i386/etc/raddb/eap.conf
including configuration file /usr/pbi/freeradius-i386/etc/raddb/sql.conf
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/sql/mysql/dialup.conf
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/sql/mysql/dialup.conf
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/sql/mysql/counter.conf
including configuration file /usr/pbi/freeradius-i386/etc/raddb/policy.conf
including files in directory 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/
including configuration file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
main {
     allow_core_dumps = no
}
including dictionary file /usr/pbi/freeradius-i386/etc/raddb/dictionary
main {
     name = "radiusd"
     prefix = "/usr/pbi/freeradius-i386"
     localstatedir = "/var"
     sbindir = "/usr/pbi/freeradius-i386/sbin"
     logdir = "/var/log"
     run_dir = "/var/run"
     radacctdir = "/var/log/radacct"
     hostname_lookups = no
     max_request_time = 30
     cleanup_delay = 5
     max_requests = 1024
     pidfile = "/var/run/radiusd.pid"
     checkrad = "/usr/pbi/freeradius-i386/sbin/checkrad"
     debug_level = 0
     proxy_requests = yes
  log {
     stripped_names = no
     auth = yes
     auth_badpass = no
     auth_goodpass = no
     msg_badpass = ""
     msg_goodpass = ""
  }
  security {
     max_attributes = 200
     reject_delay = 1
     status_server = no
  }
}
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
  }
  realm NULL {
     authhost = 192.168.1.223:1812
     accthost = 192.168.1.223:1813
     secret = testing123
  }
  realm DEFAULT {
     authhost = 192.168.1.223:1812
     accthost = 192.168.1.223:1813
     secret = testing123
  }
radiusd: #### Loading Clients ####
  client hostapd {
     ipaddr = 172.16.0.2
     require_message_authenticator = no
     secret = "testing123"
     shortname = "hostapd"
     nastype = "other"
  }
radiusd: #### Instantiating modules ####
  instantiate {
  Module: Linked to module rlm_exec
  Module: Instantiating module "exec" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/exec
   exec {
     wait = no
     input_pairs = "request"
     shell_escape = yes
   }
  Module: Linked to module rlm_expr
  Module: Instantiating module "expr" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/expr
  Module: Linked to module rlm_counter
  Module: Instantiating module "daily" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/counter
   counter daily {
     filename = "/var/log/radacct/timecounter/db.daily"
     key = "User-Name"
     reset = "daily"
     count-attribute = "Acct-Session-Time"
     counter-name = "Daily-Session-Time"
     check-name = "Max-Daily-Session"
     reply-name = "Session-Timeout"
     cache-size = 5000
   }
rlm_counter: Counter attribute Daily-Session-Time is number 11273
rlm_counter: Current Time: 1385116609 [2013-11-22 11:36:49], Next reset 
1385161200 [2013-11-23 00:00:00]
  Module: Instantiating module "weekly" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/counter
   counter weekly {
     filename = "/var/log/radacct/timecounter/db.weekly"
     key = "User-Name"
     reset = "weekly"
     count-attribute = "Acct-Session-Time"
     counter-name = "Weekly-Session-Time"
     check-name = "Max-Weekly-Session"
     reply-name = "Session-Timeout"
     cache-size = 5000
   }
rlm_counter: Counter attribute Weekly-Session-Time is number 11275
rlm_counter: Current Time: 1385116609 [2013-11-22 11:36:49], Next reset 
1385247600 [2013-11-24 00:00:00]
  Module: Instantiating module "monthly" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/counter
   counter monthly {
     filename = "/var/log/radacct/timecounter/db.monthly"
     key = "User-Name"
     reset = "monthly"
     count-attribute = "Acct-Session-Time"
     counter-name = "Monthly-Session-Time"
     check-name = "Max-Monthly-Session"
     reply-name = "Session-Timeout"
     cache-size = 5000
   }
rlm_counter: Counter attribute Monthly-Session-Time is number 11277
rlm_counter: Current Time: 1385116609 [2013-11-22 11:36:49], Next reset 
1385852400 [2013-12-01 00:00:00]
  Module: Instantiating module "forever" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/counter
   counter forever {
     filename = "/var/log/radacct/timecounter/db.forever"
     key = "User-Name"
     reset = "never"
     count-attribute = "Acct-Session-Time"
     counter-name = "Forever-Session-Time"
     check-name = "Max-Forever-Session"
     reply-name = "Session-Timeout"
     cache-size = 5000
   }
rlm_counter: Counter attribute Forever-Session-Time is number 11279
rlm_counter: Current Time: 1385116609 [2013-11-22 11:36:49], Next reset 
0 [2013-11-22 11:00:00]
  Module: Linked to module rlm_expiration
  Module: Instantiating module "expiration" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/expiration
   expiration {
     reply-message = "Password Has Expired  "
   }
  Module: Linked to module rlm_logintime
  Module: Instantiating module "logintime" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/logintime
   logintime {
     reply-message = "You are calling outside your allowed timespan "
     minimum-timeout = 60
   }
  }
radiusd: #### Loading Virtual Servers ####
server { # from file /usr/pbi/freeradius-i386/etc/raddb/radiusd.conf
  modules {
   Module: Creating Auth-Type = MOTP
   Module: Creating Auth-Type = digest
   Module: Creating Autz-Type = Status-Server
   Module: Creating Acct-Type = Status-Server
   Module: Creating Post-Auth-Type = REJECT
  Module: Checking authenticate {...} for more modules to load
  Module: Linked to module rlm_pap
  Module: Instantiating module "pap" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/pap
   pap {
     encryption_scheme = "auto"
     auto_header = no
   }
  Module: Linked to module rlm_chap
  Module: Instantiating module "chap" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/chap
  Module: Linked to module rlm_mschap
  Module: Instantiating module "mschap" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/mschap
   mschap {
     use_mppe = yes
     require_encryption = no
     require_strong = no
     with_ntdomain_hack = yes
     allow_retry = yes
   }
  Module: Instantiating module "motp" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/motp
   exec motp {
     wait = yes
     program = "/usr/local/bin/bash 
/usr/pbi/freeradius-i386/etc/raddb/scripts/otpverify.sh 
%{request:User-Name} %{request:User-Password} %{reply:MOTP-Init-Secret} 
%{reply:MOTP-PIN} %{reply:MOTP-Offset}"
     input_pairs = "request"
     shell_escape = yes
   }
  Module: Linked to module rlm_digest
  Module: Instantiating module "digest" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/digest
  Module: Linked to module rlm_unix
  Module: Instantiating module "unix" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/unix
   unix {
     radwtmp = "/var/log/radwtmp"
   }
  Module: Linked to module rlm_eap
  Module: Instantiating module "eap" from file 
/usr/pbi/freeradius-i386/etc/raddb/eap.conf
   eap {
     default_eap_type = "peap"
     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
     CA_path = "/usr/pbi/freeradius-i386/etc/raddb/certs"
     pem_file_type = yes
     private_key_file = 
"/usr/pbi/freeradius-i386/etc/raddb/certs/server.pem"
     certificate_file = 
"/usr/pbi/freeradius-i386/etc/raddb/certs/server.pem"
     CA_file = "/usr/pbi/freeradius-i386/etc/raddb/certs/ca.pem"
     private_key_password = "whatever"
     dh_file = "/usr/pbi/freeradius-i386/etc/raddb/certs/dh"
     random_file = "/usr/pbi/freeradius-i386/etc/raddb/certs/random"
     fragment_size = 1024
     include_length = yes
     check_crl = no
     cipher_list = "DEFAULT"
     ecdh_curve = "prime256v1"
     cache {
     enable = no
     lifetime = 24
     max_entries = 255
     }
     verify {
     }
     ocsp {
     enable = no
     override_cert_url = no
     url = "http://127.0.0.1/ocsp/"
     use_nonce = yes
     timeout = 0
     softfail = no
     }
    }
  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 = yes
     include_length = yes
    }
  Module: Linked to sub-module rlm_eap_peap
  Module: Instantiating eap-peap
    peap {
     default_eap_type = "mschapv2"
     copy_request_to_tunnel = yes
     use_tunneled_reply = yes
     proxy_tunneled_request_as_eap = yes
     soh = no
    }
  Module: Linked to sub-module rlm_eap_mschapv2
  Module: Instantiating eap-mschapv2
    mschapv2 {
     with_ntdomain_hack = no
     send_error = no
    }
  Module: Checking authorize {...} for more modules to load
  Module: Linked to module rlm_preprocess
  Module: Instantiating module "preprocess" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/preprocess
   preprocess {
     huntgroups = "/usr/pbi/freeradius-i386/etc/raddb/huntgroups"
     hints = "/usr/pbi/freeradius-i386/etc/raddb/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
   }
reading pairlist file /usr/pbi/freeradius-i386/etc/raddb/huntgroups
reading pairlist file /usr/pbi/freeradius-i386/etc/raddb/hints
  Module: Linked to module rlm_files
  Module: Instantiating module "files" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/files
   files {
     usersfile = "/usr/pbi/freeradius-i386/etc/raddb/users"
     acctusersfile = "/usr/pbi/freeradius-i386/etc/raddb/acct_users"
     preproxy_usersfile = 
"/usr/pbi/freeradius-i386/etc/raddb/preproxy_users"
     compat = "no"
   }
reading pairlist file /usr/pbi/freeradius-i386/etc/raddb/users
reading pairlist file /usr/pbi/freeradius-i386/etc/raddb/acct_users
reading pairlist file /usr/pbi/freeradius-i386/etc/raddb/preproxy_users
  Module: Linked to module rlm_sql
  Module: Instantiating module "sql" from file 
/usr/pbi/freeradius-i386/etc/raddb/sql.conf
   sql {
     driver = "rlm_sql_mysql"
     server = "192.168.1.223"
     port = "3306"
     login = "radius"
     password = "radpass"
     radius_db = "radiusdb"
     read_groups = yes
     sqltrace = no
     sqltracefile = "/var/log/sqltrace.sql"
     readclients = no
     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, server 
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@192.168.1.223:3306/radiusdb
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
  Module: Linked to module rlm_checkval
  Module: Instantiating module "checkval" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/checkval
   checkval {
     item-name = "Calling-Station-Id"
     check-name = "Calling-Station-Id"
     data-type = "string"
     notfound-reject = no
   }
rlm_checkval: Registered name Calling-Station-Id for attribute 31
  Module: Checking preacct {...} for more modules to load
  Module: Linked to module rlm_acct_unique
  Module: Instantiating module "acct_unique" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/acct_unique
   acct_unique {
     key = "User-Name, Acct-Session-Id, NAS-IP-Address, NAS-Identifier, 
NAS-Port"
   }
  Module: Linked to module rlm_realm
  Module: Instantiating module "suffix" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/realm
   realm suffix {
     format = "suffix"
     delimiter = "@"
     ignore_default = no
     ignore_null = yes
   }
  Module: Instantiating module "ntdomain" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/realm
   realm ntdomain {
     format = "prefix"
     delimiter = "\"
     ignore_default = no
     ignore_null = yes
   }
  Module: Checking accounting {...} for more modules to load
  Module: Linked to module rlm_detail
  Module: Instantiating module "detail" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/detail
   detail {
     detailfile = 
"/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
     header = "%t"
     detailperm = 384
     dirperm = 493
     locking = no
     log_packet_header = no
   }
  Module: Instantiating module "datacounterdaily" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/datacounter_acct
   exec datacounterdaily {
     wait = yes
     program = "/bin/sh 
/usr/pbi/freeradius-i386/etc/raddb/scripts/datacounter_acct.sh 
%{request:User-Name} daily %{request:Acct-Input-Octets} 
%{request:Acct-Output-Octets}"
     input_pairs = "request"
     shell_escape = yes
   }
  Module: Instantiating module "datacounterweekly" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/datacounter_acct
   exec datacounterweekly {
     wait = yes
     program = "/bin/sh 
/usr/pbi/freeradius-i386/etc/raddb/scripts/datacounter_acct.sh 
%{request:User-Name} weekly %{request:Acct-Input-Octets} 
%{request:Acct-Output-Octets}"
     input_pairs = "request"
     shell_escape = yes
   }
  Module: Instantiating module "datacountermonthly" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/datacounter_acct
   exec datacountermonthly {
     wait = yes
     program = "/bin/sh 
/usr/pbi/freeradius-i386/etc/raddb/scripts/datacounter_acct.sh 
%{request:User-Name} monthly %{request:Acct-Input-Octets} 
%{request:Acct-Output-Octets}"
     input_pairs = "request"
     shell_escape = yes
   }
  Module: Instantiating module "datacounterforever" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/datacounter_acct
   exec datacounterforever {
     wait = yes
     program = "/bin/sh 
/usr/pbi/freeradius-i386/etc/raddb/scripts/datacounter_acct.sh 
%{request:User-Name} forever %{request:Acct-Input-Octets} 
%{request:Acct-Output-Octets}"
     input_pairs = "request"
     shell_escape = yes
   }
  Module: Linked to module rlm_radutmp
  Module: Instantiating module "radutmp" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/radutmp
   radutmp {
     filename = "/var/log/radutmp"
     username = "%{User-Name}"
     case_sensitive = yes
     check_with_nas = yes
     perm = 384
     callerid = yes
   }
  Module: Linked to module rlm_attr_filter
  Module: Instantiating module "attr_filter.accounting_response" from 
file /usr/pbi/freeradius-i386/etc/raddb/modules/attr_filter
   attr_filter attr_filter.accounting_response {
     attrsfile = 
"/usr/pbi/freeradius-i386/etc/raddb/attrs.accounting_response"
     key = "%{User-Name}"
     relaxed = no
   }
reading pairlist file 
/usr/pbi/freeradius-i386/etc/raddb/attrs.accounting_response
  Module: Checking session {...} for more modules to load
  Module: Checking pre-proxy {...} for more modules to load
  Module: Instantiating module "attr_filter.pre-proxy" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/attr_filter
   attr_filter attr_filter.pre-proxy {
     attrsfile = "/usr/pbi/freeradius-i386/etc/raddb/attrs.pre-proxy"
     key = "%{Realm}"
     relaxed = no
   }
reading pairlist file /usr/pbi/freeradius-i386/etc/raddb/attrs.pre-proxy
  Module: Checking post-proxy {...} for more modules to load
  Module: Instantiating module "attr_filter.post-proxy" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/attr_filter
   attr_filter attr_filter.post-proxy {
     attrsfile = "/usr/pbi/freeradius-i386/etc/raddb/attrs"
     key = "%{Realm}"
     relaxed = no
   }
reading pairlist file /usr/pbi/freeradius-i386/etc/raddb/attrs
  Module: Checking post-auth {...} for more modules to load
  Module: Instantiating module "attr_filter.access_reject" from file 
/usr/pbi/freeradius-i386/etc/raddb/modules/attr_filter
   attr_filter attr_filter.access_reject {
     attrsfile = "/usr/pbi/freeradius-i386/etc/raddb/attrs.access_reject"
     key = "%{User-Name}"
     relaxed = no
   }
reading pairlist file /usr/pbi/freeradius-i386/etc/raddb/attrs.access_reject
  } # modules
} # server
radiusd: #### Opening IP addresses and Ports ####
listen {
     type = "auth"
     ipaddr = 172.16.0.1
     port = 1645
}
listen {
     type = "acct"
     ipaddr = 172.16.0.1
     port = 1646
}
Listening on authentication address 172.16.0.1 port 1645
Listening on accounting address 172.16.0.1 port 1646
Listening on proxy address 172.16.0.1 port 1647
Ready to process requests.
rad_recv: Accounting-Request packet from host 172.16.0.2 port 54960, 
id=0, length=89
     Acct-Status-Type = Accounting-On
     Acct-Authentic = RADIUS
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     Acct-Terminate-Cause = NAS-Reboot
# Executing section preacct from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
     expand: %{Acct-Session-Time} ->
     ... expanding second conditional
     expand: %{Acct-Delay-Time} ->
     ... expanding second conditional
     expand:  %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0} 
->  1385116612 - 0 - 0
     expand: %{expr: %l - %{%{Acct-Session-Time}:-0} - 
%{%{Acct-Delay-Time}:-0}} -> 1385116612
++[request] returns ok
[acct_unique] WARNING: Attribute NAS-Port was not found in request, 
unique ID MAY be inconsistent
[acct_unique] WARNING: Attribute Acct-Session-Id was not found in 
request, unique ID MAY be inconsistent
[acct_unique] WARNING: Attribute User-Name was not found in request, 
unique ID MAY be inconsistent
[acct_unique] Hashing ',NAS-Identifier = "myAP",NAS-IP-Address = 
172.16.0.2,,'
[acct_unique] Acct-Unique-Session-ID = "96c937b8b7290e37".
++[acct_unique] returns ok
[suffix] Proxy reply, or no User-Name.  Ignoring.
++[suffix] returns ok
[ntdomain] Proxy reply, or no User-Name.  Ignoring.
++[ntdomain] returns ok
++[files] returns noop
# Executing section accounting from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail]     expand: %{Packet-Src-IP-Address} -> 172.16.0.2
[detail]     expand: 
/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d 
-> /var/log/radacct/172.16.0.2/detail-20131122
[detail] 
/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d 
expands to /var/log/radacct/172.16.0.2/detail-20131122
[detail]     expand: %t -> Fri Nov 22 11:36:52 2013
++[detail] returns ok
rlm_counter: We only run on Accounting-Stop packets.
++[daily] returns noop
rlm_counter: We only run on Accounting-Stop packets.
++[weekly] returns noop
rlm_counter: We only run on Accounting-Stop packets.
++[monthly] returns noop
rlm_counter: We only run on Accounting-Stop packets.
++[forever] returns noop
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type 
== Interim-Update))
?? Evaluating (request:Acct-Status-Type == Stop) -> FALSE
?? Evaluating (request:Acct-Status-Type == Interim-Update) -> FALSE
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type 
== Interim-Update)) -> FALSE
++[unix] returns noop
[radutmp]     expand: /var/log/radutmp -> /var/log/radutmp
rlm_radutmp: NAS hostapd restarted (Accounting-On packet seen)
++[radutmp] returns ok
++- entering policy redundant {...}
[sql] Received Acct On/Off packet
[sql]     expand: %{Acct-Delay-Time} ->
[sql]     ... expanding second conditional
[sql]     expand:           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' ->           UPDATE radacct           SET 
acctstoptime       =  '2013-11-22 11:36:52', acctsessiontime    =  
unix_timestamp('2013-11-22 11:36:52') - 
unix_timestamp(acctstarttime),              acctterminatecause = 
'NAS-Reboot',              acctstopdelay      =  0           WHERE 
acctstoptime IS NULL           AND nasipaddress      = 
'172.16.0.2'           AND acctstarttime     <= '2013-11-22 11:36:52'
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
+++[sql] returns ok
++- policy redundant returns ok
++[exec] returns noop
[attr_filter.accounting_response]     expand: %{User-Name} ->
++[attr_filter.accounting_response] returns noop
Sending Accounting-Response of id 0 to 172.16.0.2 port 54960
Finished request 0.
Cleaning up request 0 ID 0 with timestamp +3
Going to the next request
Ready to process requests.
rad_recv: Access-Request packet from host 172.16.0.2 port 46731, id=1, 
length=184
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     EAP-Message = 0x0269000b01616c67756e6f
     Message-Authenticator = 0x9e1deffbe8b07933f8cb516a197a9bda
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 105 length 11
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
++- entering policy redundant {...}
[sql]     expand: %{User-Name} -> myUser
[sql] sql_set_user escaped user --> 'myUser'
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 = 'myUser'           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 = 'myUser'           ORDER BY id
[sql]     expand: SELECT groupname           FROM radusergroup           
WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT 
groupname           FROM radusergroup           WHERE username = 
'myUser'           ORDER BY priority
[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 = 'VLAN_2'           ORDER BY id
[sql] User found in group VLAN_2
[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 = 'VLAN_2'           ORDER BY id
rlm_sql (sql): Released sql socket id: 3
+++[sql] returns ok
++- policy redundant returns ok
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[daily] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[weekly] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[monthly] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[forever] returns noop
rlm_checkval: Item Name: Calling-Station-Id, Value: 38-EC-E4-7B-2A-85
rlm_checkval: Could not find attribute named Calling-Station-Id in check 
pairs
++[checkval] returns notfound
++[expiration] returns noop
++[logintime] returns noop
[pap] Normalizing NT-Password from hex encoding
[pap] WARNING: Auth-Type already set.  Not setting to PAP
++[pap] returns noop
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type tls
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 1 to 172.16.0.2 port 46731
     Tunnel-Type:0 := VLAN
     Tunnel-Medium-Type:0 := IEEE-802
     Tunnel-Private-Group-Id:0 := "2"
     Acct-Interim-Interval := 600
     EAP-Message = 0x016a00061920
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0xb7b377c8b7d96eb26d0ebbe451557537
Finished request 1.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.16.0.2 port 46731, id=2, 
length=391
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     EAP-Message = 
0x026a00c81980000000be16030100b9010000b50301528f347f21688b21d87841d56e723544bc2e3733aa01f372c845e577e5089a36000048c014c00a00390038c00fc0050035c012c00800160013c00dc003000ac013c00900330032c00ec004002fc011c007c00cc002000500040015001200090014001100080006000300ff01000044000b000403000102000a00340032000100020003000400050006000700080009000a000b000c000d000e000f001000110012001300140015001600170018001900230000
     State = 0xb7b377c8b7d96eb26d0ebbe451557537
     Message-Authenticator = 0x241bfa850843303b3f25396cb3690b69
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 106 length 200
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
   TLS Length 190
[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 00b9], ClientHello
[peap]     TLS_accept: SSLv3 read client hello A
[peap] >>> TLS 1.0 Handshake [length 0031], ServerHello
[peap]     TLS_accept: SSLv3 write server hello A
[peap] >>> TLS 1.0 Handshake [length 085e], Certificate
[peap]     TLS_accept: SSLv3 write certificate A
[peap] >>> TLS 1.0 Handshake [length 020d], ServerKeyExchange
[peap]     TLS_accept: SSLv3 write key exchange 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 2 to 172.16.0.2 port 46731
     EAP-Message = 
0x016b040019c000000ab416030100310200002d0301528f33cfff5e57459fca395f16fe9c2480452c5c1d6d7ef0ab2f7828961f9046000039000005ff01000100160301085e0b00085a0008570003a6308203a23082028aa003020102020101300d06092a864886f70d0101050500308193310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c65204365727469666963617465204175
     EAP-Message = 
0x74686f72697479301e170d3132313232303233343333355a170d3133313232303233343333355a307c310b3009060355040613024652310f300d0603550408130652616469757331153013060355040a130c4578616d706c6520496e632e312330210603550403131a4578616d706c65205365727665722043657274696669636174653120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d30820122300d06092a864886f70d01010105000382010f003082010a0282010100d2610b1ca45e16d0ec30629f9c08d97d3a9eb084e007ad307c31ce99ac0a657ac68a34d2af29391dae89d2011a70dcd600a560fc43dc85
     EAP-Message = 
0xa0056e772b73f9bf04b7790d3196d4f89a0a53cb92369adff66e9d6bba28ce42c06761aea13fdd3b7b8307838a16b8eaa892be1f0e433054caa55c8952a3d3e0c29d8034207373801068c3af09d06b968ece4f529b571e6b42eabba2144102a81fc891419a3052611e4459ee73dd726d5ff4f4a1a70bc06bd06530cd850143c32b8b4df82b2a6b2224b32a88c8dc94f9bbc940f45ec2ed9d1f004b0d2c7d6b6f501f5e2fceead03631690bd644e404e811f633788509e8667dc506747eed55214006c6f6f236f4f3410203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d01010505000382010100523e
     EAP-Message = 
0xa319f376376fd4397159a2544e85089f33c5130ba97a331f31091431140439c248b5f89fa7b4e6ea288cc2da70fd10939e8d3367cce66289aba956fd35224aa94c4e2d69f8b4ffbda96063e564ac31eb680872548028feaeb7e32db57b21e9472b5cadfe56ef68ba2d485c10fff3bfb481f2e09d45a192349fba6778037b3dad59aac8c324e5f06179a26db59912ac600f679496fc2890339d2aeb731facb97d6410478ceacc327beb37201e811aa38595416508f2b9681658e6bf379bba00814d8d2783e1cad9f3b5a8e82baed7acd0053b5647ed1cdaac3d77f6faa9e30a4398346d12fcb0681eb8f3d517c15570df60b2f56649b312b90772da9f4b
     EAP-Message = 0x720004ab308204a73082038f
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0xb7b377c8b6d86eb26d0ebbe451557537
Finished request 2.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.16.0.2 port 46731, id=3, 
length=197
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     EAP-Message = 0x026b00061900
     State = 0xb7b377c8b6d86eb26d0ebbe451557537
     Message-Authenticator = 0xaa36673698fb723042f2bda359589131
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 107 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- 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 3 to 172.16.0.2 port 46731
     EAP-Message = 
0x016c03fc1940a003020102020900da6ca063e714a5eb300d06092a864886f70d0101050500308193310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479301e170d3132313232303233343333355a170d3133313232303233343333355a308193310b3009060355040613024652310f300d0603550408130652616469757331
     EAP-Message = 
0x12301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f7269747930820122300d06092a864886f70d01010105000382010f003082010a02820101009377ea646f5ceefa70cae9d77064deee5fd7af4de18cc755ea507757bfebe35a2664ad9dc67735b3ad3719722b95b250fdc524716658a7ca17f21040d3f5e4dd412061dc9d5e6677f54515cae68534ead380182a4fe2fd98f1bcc15bae48b1c25f3bc099f3ca8bb4
     EAP-Message = 
0x52093375295cd601982dfaab1d0814e755c19fcd969abfc232214b5c1aaa2e06ba7f331690a667938852e4ea1585cbdd9648964116ee6bad7781cf029572252c2ed88d74eef0b5ccd1395d14e9f426732d2fbe55e81679c1b1d77755696597c8797ebf3bc88062c5ae861dacac346c350f79361c2670b4203b916a59fda93d93e614477f141c0d5119f152a0714947a5c72087985590b90d0203010001a381fb3081f8301d0603551d0e04160414f748cc032af05d7417d7d07b1c6156113c2fa4e33081c80603551d230481c03081bd8014f748cc032af05d7417d7d07b1c6156113c2fa4e3a18199a48196308193310b300906035504061302465231
     EAP-Message = 
0x0f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479820900da6ca063e714a5eb300c0603551d13040530030101ff300d06092a864886f70d010105050003820101002141ed49abf513b4eb259428fd866ba0d7d3a14a088cc85b3ea74ea786834ce75b460471562ab775f3eef62a1fca82da5a070d6409a206f7c7d26ed2dd754f72f39d8a4694e93ff72005b6
     EAP-Message = 0xcb22f856226674f1
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0xb7b377c8b5df6eb26d0ebbe451557537
Finished request 3.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.16.0.2 port 46731, id=4, 
length=197
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     EAP-Message = 0x026c00061900
     State = 0xb7b377c8b5df6eb26d0ebbe451557537
     Message-Authenticator = 0x9c70584c1dc06f5e1a61b499f2f41a03
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 108 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- 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 4 to 172.16.0.2 port 46731
     EAP-Message = 
0x016d02ce1900a1e967254d4185a1f8efb0da44685d53c15f69147b58b88b27ac7885316e927b94d35c40d4d28907d237e751834e5c35aaf340e2172ab006fe4f70a31fc02044192510961b8d371f987febde6fb68ced841a1015669bd307318c7b897774c8395c6b034f1af9e6fd08f6917c1c5e261773cba1ab547420ecab6788b91b03c780f14a2b8d7c68e061ffc9990bfd341b721ed7d2e2c98dd8c3fef0e4a1313cf8cc00790befb632000600d4d88229160301020d0c0002090080e6d9244e55f42955571582ad273c461ef82c1f15c6d174c5e1fe64b6d7b652b3272e1827adfd8bf153d89d669366b9a9574b061c847d0072356af464594c2b
     EAP-Message = 
0x6a79c9d6665d0f9e91c6b633489bf07dd0b7d42d0d072c7beeef9a462c6e8fa83de60f55ec7383f3d7b1edb8005002eadb8414cc67005bf3d055aceb27d9251dcb0001020080559f405372465388c11eac577ad9d165541ba70a0d83b2aee00f02a126ddc1e0578b4375601e4e8bbc5138eec3ed6e860624664fce5ae527179a286ab0ac6e7a2e1bc9fee85da9dc6d15ad45ecf45741f6fcb87f77ed0bd58c4a627472ab4d5ebcc09e967a5fa8c5dee2d550346637bc6777f8cb7fa0b22f263d6628b9cbec7e0100cdaa37358603a26ca901e3977d5d0a97fb0ea92b9021dbe2128eee89e4c4d4241d1edfd241e0bee114841be347b93ac45fac06a5a8
     EAP-Message = 
0xf4f77671c83a68d2d76564893d5ca04ac159721939f3953e182d01b2e69692bc43b52fa346bb88589b9c031d6f73a7f8fabe141fb4afb3c1767c756711bbb3ea88992d5ba7d5bb7f809d8dde84d774a25e2cfb5241cc5d713e6a109e072955c857a1979f50a6a3aee4159bfc6a82dcfb7b854aa88809bebdae2208451cf66d7f5db33a33e2998690b109990a9443476fe22e817fc7547cd477369bf6cfef242981e2ceeca3d22636726161dd6a6bd3b409d9aa18a0ad1208d86df19d8bea5d9e24344c691f20d98b30851a16030100040e000000
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0xb7b377c8b4de6eb26d0ebbe451557537
Finished request 4.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.16.0.2 port 46731, id=5, 
length=399
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     EAP-Message = 
0x026d00d01980000000c61603010086100000820080601372e2f7754b43e384e606e9282c37d7e3ccff37736f84ed75a49a4feceb44eabf516c351751147a250ca15fc5b671608eb2ab2d7f4e99ac0687556d6e03889c368fd9858e6be212dbd159ac668abe52dc06d5bb8c32486ad36c97233ac9f09f1e602def8d6d8b882585cd4f5d709e96d99b2b9c8a87ccc58352680a3fed191403010001011603010030fb49dc7ff5b0a283f62b7765cc39d7fb425e374a320b4e42208c6b2fac701ddbc35d258f963076f57be43116d99c641f
     State = 0xb7b377c8b4de6eb26d0ebbe451557537
     Message-Authenticator = 0x8d78ab857f37e829e266f5672d76090a
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 109 length 208
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
   TLS Length 198
[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 5 to 172.16.0.2 port 46731
     EAP-Message = 
0x016e0041190014030100010116030100306b08ce5dea860974f60b36ffd69d22df3affec08d45f809b9d3d5da8750444432458501fe4077fc88db8fa2456b549ef
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0xb7b377c8b3dd6eb26d0ebbe451557537
Finished request 5.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 172.16.0.2 port 46731, id=6, 
length=197
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     EAP-Message = 0x026e00061900
     State = 0xb7b377c8b3dd6eb26d0ebbe451557537
     Message-Authenticator = 0xb9f5278d298cf52522d904fecde1bb85
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 110 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- 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
[peap] Session established.  Decoding tunneled attributes.
[peap] Peap state TUNNEL ESTABLISHED
++[eap] returns handled
Sending Access-Challenge of id 6 to 172.16.0.2 port 46731
     EAP-Message = 
0x016f002b190017030100201042c8ac3a893d457f078fd228c41ccf6e1c6f5a4968af99900248053a4060b8
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0xb7b377c8b2dc6eb26d0ebbe451557537
Finished request 6.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 172.16.0.2 port 46731, id=7, 
length=271
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     EAP-Message = 
0x026f0050190017030100200ee7c4c7c2e71ea7a7ca614dc306ad5b0e820e86bb0dc0f6ba10b4b9aca6f5601703010020f94c3a0475b7373d1eca463aff36317bf4437ce46860afaf399a9c84f8aec9b9
     State = 0xb7b377c8b2dc6eb26d0ebbe451557537
     Message-Authenticator = 0xe2437b8a99ba7bb46e53964f2530173d
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 111 length 80
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- 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] Peap state WAITING FOR INNER IDENTITY
[peap] Identity - myUser
[peap] Got inner identity 'myUser'
[peap] Setting default EAP type for tunneled EAP session.
[peap] Got tunneled request
     EAP-Message = 0x026f000b01616c67756e6f
server  {
[peap] Setting User-Name to myUser
Sending tunneled request
     EAP-Message = 0x026f000b01616c67756e6f
     FreeRADIUS-Proxied-To = 127.0.0.1
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     NAS-IP-Address = 172.16.0.2
server  {
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 111 length 11
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
++- entering policy redundant {...}
[sql]     expand: %{User-Name} -> myUser
[sql] sql_set_user escaped user --> 'myUser'
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 = 'myUser'           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 = 'myUser'           ORDER BY id
[sql]     expand: SELECT groupname           FROM radusergroup           
WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT 
groupname           FROM radusergroup           WHERE username = 
'myUser'           ORDER BY priority
[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 = 'VLAN_2'           ORDER BY id
[sql] User found in group VLAN_2
[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 = 'VLAN_2'           ORDER BY id
rlm_sql (sql): Released sql socket id: 2
+++[sql] returns ok
++- policy redundant returns ok
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[daily] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[weekly] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[monthly] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[forever] returns noop
rlm_checkval: Item Name: Calling-Station-Id, Value: 38-EC-E4-7B-2A-85
rlm_checkval: Could not find attribute named Calling-Station-Id in check 
pairs
++[checkval] returns notfound
++[expiration] returns noop
++[logintime] returns noop
[pap] Normalizing NT-Password from hex encoding
[pap] WARNING: Auth-Type already set.  Not setting to PAP
++[pap] returns noop
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type mschapv2
rlm_eap_mschapv2: Issuing Challenge
++[eap] returns handled
} # server
[peap] Got tunneled reply code 11
     Tunnel-Type:0 := VLAN
     Tunnel-Medium-Type:0 := IEEE-802
     Tunnel-Private-Group-Id:0 := "2"
     Acct-Interim-Interval := 600
     EAP-Message = 
0x017000201a0170001b1066b4cd1cfa1925628bf21ac16870c069616c67756e6f
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0x466def3e461df5a9b4742da332335fbe
[peap] Got tunneled reply RADIUS code 11
     Tunnel-Type:0 := VLAN
     Tunnel-Medium-Type:0 := IEEE-802
     Tunnel-Private-Group-Id:0 := "2"
     Acct-Interim-Interval := 600
     EAP-Message = 
0x017000201a0170001b1066b4cd1cfa1925628bf21ac16870c069616c67756e6f
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0x466def3e461df5a9b4742da332335fbe
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 7 to 172.16.0.2 port 46731
     EAP-Message = 
0x0170004b1900170301004029cda7f66f24f85647b1ea26e5c0e558827d45961f7ed34a711b1b5329eaf52f1dd2acc49b3fafa51ad2a52f56eb31dea90eec9abaccf56d1f866fc04d14c288
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0xb7b377c8b1c36eb26d0ebbe451557537
Finished request 7.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 172.16.0.2 port 46731, id=8, 
length=335
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     EAP-Message = 
0x027000901900170301002082b6317d7e5ae9285add203487ec94890ddb3766844cf7b109b06dfea6e6ff1c17030100603f68beb9784fde085ec580fa03c08b3e94f893c2fa97b8ff9829a1d4b62ae42a69cbada105ca555de76f5e6e56cbce6a9fc175b727fb777e52f3561b1f7df47bfe834fd71665b9c822affb98dcb55d91d44f4846665085dc5823964bae9a3802
     State = 0xb7b377c8b1c36eb26d0ebbe451557537
     Message-Authenticator = 0xd1710eb1156662186da3e1c6946a8d69
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 112 length 144
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- 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] Peap state phase2
[peap] EAP type mschapv2
[peap] Got tunneled request
     EAP-Message = 
0x027000411a0270003c3135e9e440a48f598b6d215a2f87a2abfa00000000000000003534e3ad1124cc76385cc591b15df4a4773c5af247bbf77700616c67756e6f
server  {
[peap] Setting User-Name to myUser
Sending tunneled request
     EAP-Message = 
0x027000411a0270003c3135e9e440a48f598b6d215a2f87a2abfa00000000000000003534e3ad1124cc76385cc591b15df4a4773c5af247bbf77700616c67756e6f
     FreeRADIUS-Proxied-To = 127.0.0.1
     User-Name = "myUser"
     State = 0x466def3e461df5a9b4742da332335fbe
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     NAS-IP-Address = 172.16.0.2
server  {
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 112 length 65
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
++- entering policy redundant {...}
[sql]     expand: %{User-Name} -> myUser
[sql] sql_set_user escaped user --> 'myUser'
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 = 'myUser'           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 = 'myUser'           ORDER BY id
[sql]     expand: SELECT groupname           FROM radusergroup           
WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT 
groupname           FROM radusergroup           WHERE username = 
'myUser'           ORDER BY priority
[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 = 'VLAN_2'           ORDER BY id
[sql] User found in group VLAN_2
[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 = 'VLAN_2'           ORDER BY id
rlm_sql (sql): Released sql socket id: 1
+++[sql] returns ok
++- policy redundant returns ok
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[daily] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[weekly] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[monthly] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[forever] returns noop
rlm_checkval: Item Name: Calling-Station-Id, Value: 38-EC-E4-7B-2A-85
rlm_checkval: Could not find attribute named Calling-Station-Id in check 
pairs
++[checkval] returns notfound
++[expiration] returns noop
++[logintime] returns noop
[pap] Normalizing NT-Password from hex encoding
[pap] WARNING: Auth-Type already set.  Not setting to PAP
++[pap] returns noop
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[mschapv2] # Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
[mschapv2] +- entering group MS-CHAP {...}
[mschap] No Cleartext-Password configured.  Cannot create LM-Password.
[mschap] Found NT-Password
[mschap] Creating challenge hash with username: myUser
[mschap] Client is using MS-CHAPv2 for myUser, we need NT-Password
[mschap] adding MS-CHAPv2 MPPE keys
++[mschap] returns ok
MSCHAP Success
++[eap] returns handled
} # server
[peap] Got tunneled reply code 11
     Tunnel-Type:0 := VLAN
     Tunnel-Medium-Type:0 := IEEE-802
     Tunnel-Private-Group-Id:0 := "2"
     Acct-Interim-Interval := 600
     EAP-Message = 
0x017100331a0370002e533d31434634354137313446454244323043443438424135443131364337314533434341424333394546
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0x466def3e471cf5a9b4742da332335fbe
[peap] Got tunneled reply RADIUS code 11
     Tunnel-Type:0 := VLAN
     Tunnel-Medium-Type:0 := IEEE-802
     Tunnel-Private-Group-Id:0 := "2"
     Acct-Interim-Interval := 600
     EAP-Message = 
0x017100331a0370002e533d31434634354137313446454244323043443438424135443131364337314533434341424333394546
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0x466def3e471cf5a9b4742da332335fbe
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 8 to 172.16.0.2 port 46731
     EAP-Message = 
0x0171005b1900170301005049ac12c1d149ddda90666c752b828051e4e4ae4d5b67edcccc515a0b44967023d9c28fc6cef89571015a09e5d937845658cd9356287badac62fb6cbc2d4e50e1d65f101bd314ce7c1204e8b3789490bf
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0xb7b377c8b0c26eb26d0ebbe451557537
Finished request 8.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 172.16.0.2 port 46731, id=9, 
length=271
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     EAP-Message = 
0x0271005019001703010020b13180ca373aa4a63c92e74c1146946af33dce40d84c9e04dc1cc95a10ea786d1703010020ae3482af4132073c5b03f42a8fedebd6ce35e55cf15c673070c340e08f669539
     State = 0xb7b377c8b0c26eb26d0ebbe451557537
     Message-Authenticator = 0x1e3afd69afd6b7aaadc2c840b34e75ff
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 113 length 80
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- 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] Peap state phase2
[peap] EAP type mschapv2
[peap] Got tunneled request
     EAP-Message = 0x027100061a03
server  {
[peap] Setting User-Name to myUser
Sending tunneled request
     EAP-Message = 0x027100061a03
     FreeRADIUS-Proxied-To = 127.0.0.1
     User-Name = "myUser"
     State = 0x466def3e471cf5a9b4742da332335fbe
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     NAS-IP-Address = 172.16.0.2
server  {
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 113 length 6
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
++- entering policy redundant {...}
[sql]     expand: %{User-Name} -> myUser
[sql] sql_set_user escaped user --> 'myUser'
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 = 'myUser'           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 = 'myUser'           ORDER BY id
[sql]     expand: SELECT groupname           FROM radusergroup           
WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT 
groupname           FROM radusergroup           WHERE username = 
'myUser'           ORDER BY priority
[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 = 'VLAN_2'           ORDER BY id
[sql] User found in group VLAN_2
[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 = 'VLAN_2'           ORDER BY id
rlm_sql (sql): Released sql socket id: 0
+++[sql] returns ok
++- policy redundant returns ok
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[daily] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[weekly] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[monthly] returns noop
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[forever] returns noop
rlm_checkval: Item Name: Calling-Station-Id, Value: 38-EC-E4-7B-2A-85
rlm_checkval: Could not find attribute named Calling-Station-Id in check 
pairs
++[checkval] returns notfound
++[expiration] returns noop
++[logintime] returns noop
[pap] Normalizing NT-Password from hex encoding
[pap] WARNING: Auth-Type already set.  Not setting to PAP
++[pap] returns noop
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[eap] Freeing handler
++[eap] returns ok
     expand:  ->
Login OK: [myUser] (from client hostapd port 1 cli 38-EC-E4-7B-2A-85 via 
TLS tunnel)
# Executing section post-auth from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group post-auth {...}
++[exec] returns noop
} # server
[peap] Got tunneled reply code 2
     Tunnel-Type:0 := VLAN
     Tunnel-Medium-Type:0 := IEEE-802
     Tunnel-Private-Group-Id:0 := "2"
     Acct-Interim-Interval := 600
     MS-MPPE-Encryption-Policy = 0x00000001
     MS-MPPE-Encryption-Types = 0x00000006
     MS-MPPE-Send-Key = 0x32ef5908d99eda655abda54e9bf7f77b
     MS-MPPE-Recv-Key = 0xefb998f7c565cfbeeb73094aff999a41
     EAP-Message = 0x03710004
     Message-Authenticator = 0x00000000000000000000000000000000
     User-Name = "myUser"
[peap] Got tunneled reply RADIUS code 2
     Tunnel-Type:0 := VLAN
     Tunnel-Medium-Type:0 := IEEE-802
     Tunnel-Private-Group-Id:0 := "2"
     Acct-Interim-Interval := 600
     MS-MPPE-Encryption-Policy = 0x00000001
     MS-MPPE-Encryption-Types = 0x00000006
     MS-MPPE-Send-Key = 0x32ef5908d99eda655abda54e9bf7f77b
     MS-MPPE-Recv-Key = 0xefb998f7c565cfbeeb73094aff999a41
     EAP-Message = 0x03710004
     Message-Authenticator = 0x00000000000000000000000000000000
     User-Name = "myUser"
[peap] Tunneled authentication was successful.
[peap] SUCCESS
[peap] Saving tunneled attributes for later
++[eap] returns handled
Sending Access-Challenge of id 9 to 172.16.0.2 port 46731
     EAP-Message = 
0x0172002b190017030100208ba698cacf0345d16f24dee242f6485aff94302d17ac9606e9c13b7c79e9ee61
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0xb7b377c8bfc16eb26d0ebbe451557537
Finished request 9.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 172.16.0.2 port 46731, id=10, 
length=271
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Framed-MTU = 1400
     EAP-Message = 
0x027200501900170301002081edd9ce2846a96f61e004aebc1c5b0a5d2a3dd0cad530f4711a6901030b9af41703010020ded847ebff59e1a46b180780b80f214126a2eff3cff961b77fb40996b44a0852
     State = 0xb7b377c8bfc16eb26d0ebbe451557537
     Message-Authenticator = 0x5037a5c7a61e5b9ee4849c6cd9c4ab93
# Executing section authorize from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[eap] EAP packet type response id 114 length 80
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- 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] Peap state send tlv success
[peap] Received EAP-TLV response.
[peap] Success
[peap] Using saved attributes from the original Access-Accept
     Tunnel-Type:0 := VLAN
     Tunnel-Medium-Type:0 := IEEE-802
     Tunnel-Private-Group-Id:0 := "2"
     Acct-Interim-Interval := 600
     User-Name = "myUser"
[eap] Freeing handler
++[eap] returns ok
     expand:  ->
Login OK: [myUser] (from client hostapd port 1 cli 38-EC-E4-7B-2A-85)
# Executing section post-auth from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group post-auth {...}
++[exec] returns noop
Sending Access-Accept of id 10 to 172.16.0.2 port 46731
     Tunnel-Type:0 := VLAN
     Tunnel-Medium-Type:0 := IEEE-802
     Tunnel-Private-Group-Id:0 := "2"
     Acct-Interim-Interval := 600
     User-Name = "myUser"
     MS-MPPE-Recv-Key = 
0x28788d4e84b809cf23fe1fcdc17f6379e52a10d5175ee8405c3caff2c6f9e30c
     MS-MPPE-Send-Key = 
0xabb187fd1eff53ab37e76c316a81aba98d65b7c83309e29b42cb57b4f5e514b7
     EAP-Message = 0x03720004
     Message-Authenticator = 0x00000000000000000000000000000000
Finished request 10.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Accounting-Request packet from host 172.16.0.2 port 54960, 
id=11, length=178
     Acct-Session-Id = "528F33C3-00000000"
     Acct-Status-Type = Start
     Acct-Authentic = RADIUS
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
# Executing section preacct from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
     expand: %{Acct-Session-Time} ->
     ... expanding second conditional
     expand: %{Acct-Delay-Time} ->
     ... expanding second conditional
     expand:  %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0} 
->  1385116623 - 0 - 0
     expand: %{expr: %l - %{%{Acct-Session-Time}:-0} - 
%{%{Acct-Delay-Time}:-0}} -> 1385116623
++[request] returns ok
[acct_unique] Hashing 'NAS-Port = 1,NAS-Identifier = 
"myAP",NAS-IP-Address = 172.16.0.2,Acct-Session-Id = 
"528F33C3-00000000",User-Name = "myUser"'
[acct_unique] Acct-Unique-Session-ID = "c3ecb1c16ce63600".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "myUser", skipping NULL due to config.
++[suffix] returns noop
[ntdomain] No '\' in User-Name = "myUser", skipping NULL due to config.
++[ntdomain] returns noop
++[files] returns noop
# Executing section accounting from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail]     expand: %{Packet-Src-IP-Address} -> 172.16.0.2
[detail]     expand: 
/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d 
-> /var/log/radacct/172.16.0.2/detail-20131122
[detail] 
/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d 
expands to /var/log/radacct/172.16.0.2/detail-20131122
[detail]     expand: %t -> Fri Nov 22 11:37:03 2013
++[detail] returns ok
rlm_counter: We only run on Accounting-Stop packets.
++[daily] returns noop
rlm_counter: We only run on Accounting-Stop packets.
++[weekly] returns noop
rlm_counter: We only run on Accounting-Stop packets.
++[monthly] returns noop
rlm_counter: We only run on Accounting-Stop packets.
++[forever] returns noop
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type 
== Interim-Update))
?? Evaluating (request:Acct-Status-Type == Stop) -> FALSE
?? Evaluating (request:Acct-Status-Type == Interim-Update) -> FALSE
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type 
== Interim-Update)) -> FALSE
++[unix] returns ok
[radutmp]     expand: /var/log/radutmp -> /var/log/radutmp
[radutmp]     expand: %{User-Name} -> myUser
++[radutmp] returns ok
++- entering policy redundant {...}
[sql]     expand: %{User-Name} -> myUser
[sql] sql_set_user escaped user --> 'myUser'
[sql]     expand: %{Acct-Delay-Time} ->
[sql]     ... expanding second conditional
[sql]     expand:            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}',
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
+++[sql] returns ok
++- policy redundant returns ok
++[exec] returns noop
[attr_filter.accounting_response]     expand: %{User-Name} -> myUser
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 11 to 172.16.0.2 port 54960
Finished request 11.
Cleaning up request 11 ID 11 with timestamp +14
Going to the next request
Waking up in 4.6 seconds.
rad_recv: Accounting-Request packet from host 172.16.0.2 port 54960, 
id=12, length=220
     Acct-Session-Id = "528F33C3-00000000"
     Acct-Status-Type = Stop
     Acct-Authentic = RADIUS
     User-Name = "myUser"
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     NAS-Port = 1
     Calling-Station-Id = "38-EC-E4-7B-2A-85"
     Connect-Info = "CONNECT 54Mbps 802.11g"
     Acct-Session-Id = "528F33C3-00000000"
     Acct-Session-Time = 4
     Acct-Input-Packets = 56
     Acct-Output-Packets = 28
     Acct-Input-Octets = 4425
     Acct-Output-Octets = 6386
     Event-Timestamp = "Nov 22 2013 11:37:07 CET"
     Acct-Terminate-Cause = User-Request
# Executing section preacct from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
     expand: %{Acct-Session-Time} -> 4
     expand: %{Acct-Delay-Time} ->
     ... expanding second conditional
     expand:  %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0} 
->  1385116627 - 4 - 0
     expand: %{expr: %l - %{%{Acct-Session-Time}:-0} - 
%{%{Acct-Delay-Time}:-0}} -> 1385116623
++[request] returns ok
[acct_unique] Hashing 'NAS-Port = 1,NAS-Identifier = 
"myAP",NAS-IP-Address = 172.16.0.2,Acct-Session-Id = 
"528F33C3-00000000",User-Name = "myUser"'
[acct_unique] Acct-Unique-Session-ID = "c3ecb1c16ce63600".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "myUser", skipping NULL due to config.
++[suffix] returns noop
[ntdomain] No '\' in User-Name = "myUser", skipping NULL due to config.
++[ntdomain] returns noop
++[files] returns noop
# Executing section accounting from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail]     expand: %{Packet-Src-IP-Address} -> 172.16.0.2
[detail]     expand: 
/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d 
-> /var/log/radacct/172.16.0.2/detail-20131122
[detail] 
/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d 
expands to /var/log/radacct/172.16.0.2/detail-20131122
[detail]     expand: %t -> Fri Nov 22 11:37:07 2013
++[detail] returns ok
rlm_counter: Packet Unique ID = 'c3ecb1c16ce63600'
rlm_counter: Searching the database for key 'myUser'
rlm_counter: Key found.
rlm_counter: Counter Unique ID = 'a16826b7ad7612e4'
rlm_counter: User=myUser, Counter=126.
rlm_counter: User=myUser, New Counter=130.
rlm_counter: Storing new value in database.
rlm_counter: New value stored successfully.
++[daily] returns ok
rlm_counter: Packet Unique ID = 'c3ecb1c16ce63600'
rlm_counter: Searching the database for key 'myUser'
rlm_counter: Key found.
rlm_counter: Counter Unique ID = 'a16826b7ad7612e4'
rlm_counter: User=myUser, Counter=415.
rlm_counter: User=myUser, New Counter=419.
rlm_counter: Storing new value in database.
rlm_counter: New value stored successfully.
++[weekly] returns ok
rlm_counter: Packet Unique ID = 'c3ecb1c16ce63600'
rlm_counter: Searching the database for key 'myUser'
rlm_counter: Key found.
rlm_counter: Counter Unique ID = 'a16826b7ad7612e4'
rlm_counter: User=myUser, Counter=415.
rlm_counter: User=myUser, New Counter=419.
rlm_counter: Storing new value in database.
rlm_counter: New value stored successfully.
++[monthly] returns ok
rlm_counter: Packet Unique ID = 'c3ecb1c16ce63600'
rlm_counter: Searching the database for key 'myUser'
rlm_counter: Key found.
rlm_counter: Counter Unique ID = 'a16826b7ad7612e4'
rlm_counter: User=myUser, Counter=415.
rlm_counter: User=myUser, New Counter=419.
rlm_counter: Storing new value in database.
rlm_counter: New value stored successfully.
++[forever] returns ok
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type 
== Interim-Update))
?? Evaluating (request:Acct-Status-Type == Stop) -> TRUE
?? Skipping (request:Acct-Status-Type == Interim-Update)
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type 
== Interim-Update)) -> TRUE
++- entering if ((request:Acct-Status-Type == Stop) || 
(request:Acct-Status-Type == Interim-Update)) {...}
[datacounterdaily]     expand: %{request:User-Name} -> myUser
[datacounterdaily]     expand: %{request:Acct-Input-Octets} -> 4425
[datacounterdaily]     expand: %{request:Acct-Output-Octets} -> 6386
Exec-Program output:
Exec-Program: returned: 0
+++[datacounterdaily] returns ok
[datacounterweekly]     expand: %{request:User-Name} -> myUser
[datacounterweekly]     expand: %{request:Acct-Input-Octets} -> 4425
[datacounterweekly]     expand: %{request:Acct-Output-Octets} -> 6386
Exec-Program output:
Exec-Program: returned: 0
+++[datacounterweekly] returns ok
[datacountermonthly]     expand: %{request:User-Name} -> myUser
[datacountermonthly]     expand: %{request:Acct-Input-Octets} -> 4425
[datacountermonthly]     expand: %{request:Acct-Output-Octets} -> 6386
Exec-Program output:
Exec-Program: returned: 0
+++[datacountermonthly] returns ok
[datacounterforever]     expand: %{request:User-Name} -> myUser
[datacounterforever]     expand: %{request:Acct-Input-Octets} -> 4425
[datacounterforever]     expand: %{request:Acct-Output-Octets} -> 6386
Exec-Program output:
Exec-Program: returned: 0
+++[datacounterforever] returns ok
++- if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type 
== Interim-Update)) returns ok
++[unix] returns ok
[radutmp]     expand: /var/log/radutmp -> /var/log/radutmp
[radutmp]     expand: %{User-Name} -> myUser
++[radutmp] returns ok
++- entering policy redundant {...}
[sql]     expand: %{User-Name} -> myUser
[sql] sql_set_user escaped user --> 'myUser'
[sql]     expand: %{Acct-Input-Gigawords} ->
[sql]     ... expanding second conditional
[sql]     expand: %{Acct-Input-Octets} -> 4425
[sql]     expand: %{Acct-Output-Gigawords} ->
[sql]     ... expanding second conditional
[sql]     expand: %{Acct-Output-Octets} -> 6386
[sql]     expand: %{Acct-Delay-Time} ->
[sql]     ... expanding second conditional
[sql]     expand:            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}' 
->            UPDATE radacct SET acctstoptime       = '2013-11-22 
11:37:07', acctsessiontime    = '4',              acctinputoctets    = 
'0' << 32 |                                   '4425', acctoutputoctets   
= '0' << 32 |
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql (sql): Released sql socket id: 3
+++[sql] returns ok
++- policy redundant returns ok
++[exec] returns noop
[attr_filter.accounting_response]     expand: %{User-Name} -> myUser
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 12 to 172.16.0.2 port 54960
Finished request 12.
Cleaning up request 12 ID 12 with timestamp +18
Going to the next request
Waking up in 0.3 seconds.
Cleaning up request 1 ID 1 with timestamp +14
Cleaning up request 2 ID 2 with timestamp +14
Cleaning up request 3 ID 3 with timestamp +14
Cleaning up request 4 ID 4 with timestamp +14
Waking up in 0.1 seconds.
Cleaning up request 5 ID 5 with timestamp +14
Cleaning up request 6 ID 6 with timestamp +14
Cleaning up request 7 ID 7 with timestamp +14
Cleaning up request 8 ID 8 with timestamp +14
Cleaning up request 9 ID 9 with timestamp +14
Cleaning up request 10 ID 10 with timestamp +14
Ready to process requests.
rad_recv: Accounting-Request packet from host 172.16.0.2 port 54960, 
id=13, length=89
     Acct-Status-Type = Accounting-Off
     Acct-Authentic = RADIUS
     NAS-Identifier = "myAP"
     Called-Station-Id = "22-15-6D-84-CB-61:mySSID"
     NAS-Port-Type = Wireless-802.11
     Acct-Terminate-Cause = NAS-Reboot
# Executing section preacct from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
     expand: %{Acct-Session-Time} ->
     ... expanding second conditional
     expand: %{Acct-Delay-Time} ->
     ... expanding second conditional
     expand:  %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0} 
->  1385116634 - 0 - 0
     expand: %{expr: %l - %{%{Acct-Session-Time}:-0} - 
%{%{Acct-Delay-Time}:-0}} -> 1385116634
++[request] returns ok
[acct_unique] WARNING: Attribute NAS-Port was not found in request, 
unique ID MAY be inconsistent
[acct_unique] WARNING: Attribute Acct-Session-Id was not found in 
request, unique ID MAY be inconsistent
[acct_unique] WARNING: Attribute User-Name was not found in request, 
unique ID MAY be inconsistent
[acct_unique] Hashing ',NAS-Identifier = "myAP",NAS-IP-Address = 
172.16.0.2,,'
[acct_unique] Acct-Unique-Session-ID = "96c937b8b7290e37".
++[acct_unique] returns ok
[suffix] Proxy reply, or no User-Name.  Ignoring.
++[suffix] returns ok
[ntdomain] Proxy reply, or no User-Name.  Ignoring.
++[ntdomain] returns ok
++[files] returns noop
# Executing section accounting from file 
/usr/pbi/freeradius-i386/etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail]     expand: %{Packet-Src-IP-Address} -> 172.16.0.2
[detail]     expand: 
/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d 
-> /var/log/radacct/172.16.0.2/detail-20131122
[detail] 
/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d 
expands to /var/log/radacct/172.16.0.2/detail-20131122
[detail]     expand: %t -> Fri Nov 22 11:37:14 2013
++[detail] returns ok
rlm_counter: We only run on Accounting-Stop packets.
++[daily] returns noop
rlm_counter: We only run on Accounting-Stop packets.
++[weekly] returns noop
rlm_counter: We only run on Accounting-Stop packets.
++[monthly] returns noop
rlm_counter: We only run on Accounting-Stop packets.
++[forever] returns noop
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type 
== Interim-Update))
?? Evaluating (request:Acct-Status-Type == Stop) -> FALSE
?? Evaluating (request:Acct-Status-Type == Interim-Update) -> FALSE
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type 
== Interim-Update)) -> FALSE
++[unix] returns noop
[radutmp]     expand: /var/log/radutmp -> /var/log/radutmp
rlm_radutmp: NAS hostapd rebooted (Accounting-Off packet seen)
++[radutmp] returns ok
++- entering policy redundant {...}
[sql] Received Acct On/Off packet
[sql]     expand: %{Acct-Delay-Time} ->
[sql]     ... expanding second conditional
[sql]     expand:           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' ->           UPDATE radacct           SET 
acctstoptime       =  '2013-11-22 11:37:14', acctsessiontime    =  
unix_timestamp('2013-11-22 11:37:14') - 
unix_timestamp(acctstarttime),              acctterminatecause = 
'NAS-Reboot',              acctstopdelay      =  0           WHERE 
acctstoptime IS NULL           AND nasipaddress      = 
'172.16.0.2'           AND acctstarttime     <= '2013-11-22 11:37:14'
rlm_sql (sql): Reserving sql socket id: 2
rlm_sql (sql): Released sql socket id: 2
+++[sql] returns ok
++- policy redundant returns ok
++[exec] returns noop
[attr_filter.accounting_response]     expand: %{User-Name} ->
++[attr_filter.accounting_response] returns noop
Sending Accounting-Response of id 13 to 172.16.0.2 port 54960
Finished request 13.
Cleaning up request 13 ID 13 with timestamp +25
Going to the next request
Ready to process requests.

Thanks for all. King regards.
Fernando.

Freeradius Proxy

Fernando Pizarro