Slow PEAP Response

18 Nov 2005

      Hi all,

             I've setup a WiFi access point on WPA mode, attached to a
PC with chillispot and another computer with Freeradius. My idea is the
following:

- When someone tries to connect to the AP, it will asked for username
and password (PEAP . Mschapv2)
- The response of the wireless client will be send to chillispot
- Chillispot will re-send (proxy) the request to freeradius.

This configuration works fine, but I notice a big time lag between the
Access-Request  and Access-Accept packet (15 - 30 seconds)

I can see that between Access-Request and Accept, some Access-Challenge
packets are sent, which I think are the ones causing the mess.

Some help would be appreciated. I attach a log, hope it helps!

Thanks in advance.

Starting - reading configuration files ...
reread_config:  reading radiusd.conf
Config:   including file: /etc/freeradius/proxy.conf
Config:   including file: /etc/freeradius/clients.conf
Config:   including file: /etc/freeradius/snmp.conf
Config:   including file: /etc/freeradius/eap.conf
Config:   including file: /etc/freeradius/sql.conf
Config:   including file: /etc/freeradius/sqlcounter.conf
 main: prefix = "/usr"
 main: localstatedir = "/var"
 main: logdir = "/var/log/freeradius"
 main: libdir = "/usr/lib/freeradius"
 main: radacctdir = "/var/log/freeradius/radacct"
 main: hostname_lookups = no
 main: snmp = no
 main: max_request_time = 40
 main: cleanup_delay = 5
 main: max_requests = 1024
 main: delete_blocked_requests = 0
 main: port = 1812
 main: allow_core_dumps = no
 main: log_stripped_names = no
 main: log_file = "/var/log/freeradius/radius.log"
 main: log_auth = yes
 main: log_auth_badpass = yes
 main: log_auth_goodpass = yes
 main: pidfile = "/var/run/freeradius/freeradius.pid"
 main: user = "freerad"
 main: group = "freerad"
 main: usercollide = no
 main: lower_user = "no"
 main: lower_pass = "no"
 main: nospace_user = "no"
 main: nospace_pass = "no"
 main: checkrad = "/usr/sbin/checkrad"
 main: proxy_requests = no
 proxy: retry_delay = 5
 proxy: retry_count = 3
 proxy: synchronous = no
 proxy: default_fallback = yes
 proxy: dead_time = 120
 proxy: post_proxy_authorize = yes
 proxy: wake_all_if_all_dead = no
 security: max_attributes = 200
 security: reject_delay = 1
 security: status_server = no
 main: debug_level = 0
read_config_files:  reading dictionary
read_config_files:  reading naslist
Using deprecated naslist file.  Support for this will go away soon.
read_config_files:  reading clients
read_config_files:  reading realms
 listen: port = 1812
 listen: type = "auth"
 listen: port = 1813
 listen: type = "acct"
radiusd:  entering modules setup
Module: Library search path is /usr/lib/freeradius
Module: Loaded exec 
 exec: wait = yes
 exec: program = "(null)"
 exec: input_pairs = "request"
 exec: output_pairs = "(null)"
 exec: packet_type = "(null)"
rlm_exec: Wait=yes but no output defined. Did you mean output=none?
Module: Instantiated exec (exec) 
Module: Loaded expr 
Module: Instantiated expr (expr) 
Module: Loaded PAP 
 pap: encryption_scheme = "crypt"
Module: Instantiated pap (pap) 
Module: Loaded CHAP 
Module: Instantiated chap (chap) 
Module: Loaded MS-CHAP 
 mschap: use_mppe = yes
 mschap: require_encryption = yes
 mschap: require_strong = yes
 mschap: with_ntdomain_hack = no
 mschap: passwd = "(null)"
 mschap: authtype = "MS-CHAP"
 mschap: ntlm_auth = "(null)"
Module: Instantiated mschap (mschap) 
Module: Loaded eap 
 eap: default_eap_type = "peap"
 eap: timer_expire = 60
 eap: ignore_unknown_eap_types = no
 eap: cisco_accounting_username_bug = no
rlm_eap: Loaded and initialized type md5
rlm_eap: Loaded and initialized type leap
 gtc: challenge = "Password: "
 gtc: auth_type = "PAP"
rlm_eap: Loaded and initialized type gtc
 tls: rsa_key_exchange = no
 tls: dh_key_exchange = yes
 tls: rsa_key_length = 512
 tls: dh_key_length = 512
 tls: verify_depth = 0
 tls: CA_path = "(null)"
 tls: pem_file_type = yes
 tls: private_key_file = "/etc/freeradius/certs/cert-srv.pem"
 tls: certificate_file = "/etc/freeradius/certs/cert-srv.pem"
 tls: CA_file = "/etc/freeradius/certs/demoCA/cacert.pem"
 tls: private_key_password = "whatever"
 tls: dh_file = "/etc/freeradius/certs/dh"
 tls: random_file = "/etc/freeradius/certs/random"
 tls: fragment_size = 1024
 tls: include_length = yes
 tls: check_crl = no
 tls: check_cert_cn = "(null)"
rlm_eap: Loaded and initialized type tls
 peap: default_eap_type = "mschapv2"
 peap: copy_request_to_tunnel = no
 peap: use_tunneled_reply = no
 peap: proxy_tunneled_request_as_eap = yes
rlm_eap: Loaded and initialized type peap
 mschapv2: with_ntdomain_hack = no
rlm_eap: Loaded and initialized type mschapv2
Module: Instantiated eap (eap) 
Module: Loaded preprocess 
 preprocess: huntgroups = "/etc/freeradius/huntgroups"
 preprocess: hints = "/etc/freeradius/hints"
 preprocess: with_ascend_hack = no
 preprocess: ascend_channels_per_line = 23
 preprocess: with_ntdomain_hack = no
 preprocess: with_specialix_jetstream_hack = no
 preprocess: with_cisco_vsa_hack = no
Module: Instantiated preprocess (preprocess) 
Module: Loaded realm 
 realm: format = "suffix"
 realm: delimiter = "@"
 realm: ignore_default = no
 realm: ignore_null = no
Module: Instantiated realm (suffix) 
Module: Loaded SQL 
 sql: driver = "rlm_sql_mysql"
 sql: server = "localhost"
 sql: port = ""
 sql: login = "root"
 sql: password = ""
 sql: radius_db = "radius"
 sql: acct_table = "radacct"
 sql: acct_table2 = "radacct"
 sql: authcheck_table = "radcheck"
 sql: authreply_table = "radreply"
 sql: groupcheck_table = "radgroupcheck"
 sql: groupreply_table = "radgroupreply"
 sql: usergroup_table = "usergroup"
 sql: nas_table = "nas"
 sql: dict_table = "dictionary"
 sql: sqltrace = no
 sql: sqltracefile = "/var/log/freeradius/sqltrace.sql"
 sql: readclients = no
 sql: deletestalesessions = yes
 sql: num_sql_socks = 5
 sql: sql_user_name = "%{User-Name}"
 sql: default_user_profile = ""
 sql: query_on_not_found = no
 sql: authorize_check_query = "SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER BY id"
 sql: authorize_reply_query = "SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER BY id"
 sql: authorize_group_check_query = "SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id"
 sql: authorize_group_reply_query = "SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id"
 sql: accounting_onoff_query = "UPDATE radacct SET AcctStopTime='%S', AcctSessionTime=unix_timestamp('%S') - unix_timestamp(AcctStartTime), AcctTerminateCause='%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND AcctStopTime=0 AND NASIPAddress= '%{NAS-IP-Address}' AND AcctStartTime <= '%S'"
 sql: accounting_update_query = "UPDATE radacct ? SET FramedIPAddress = '%{Framed-IP-Address}', ? AcctSessionTime = '%{Acct-Session-Time}', ? AcctInputOctets = '%{Acct-Input-Octets}', ? AcctOutputOctets = '%{Acct-Output-Octets}' ? WHERE AcctSessionId = '%{Acct-Session-Id}' ? AND UserName = '%{SQL-User-Name}' ? AND NASIPAddress= '%{NAS-IP-Address}'"
 sql: 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) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{NAS-Identifier}', '%{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-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0')"
 sql: 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) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{NAS-Identifier}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{Acct-Delay-Time}', '0')"
 sql: accounting_start_query_alt = "UPDATE radacct SET AcctStartTime = '%S', AcctStartDelay = '%{Acct-Delay-Time}', ConnectInfo_start = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'"
 sql: accounting_stop_query = "UPDATE radacct SET AcctStopTime = '%S', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}', AcctTerminateCause = '%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'"
 sql: 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}', '%{NAS-Identifier}', '%{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-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')"
 sql: group_membership_query = "SELECT GroupName FROM usergroup WHERE UserName='%{SQL-User-Name}'"
 sql: connect_failure_retry_delay = 60
 sql: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
 sql: simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
 sql: postauth_table = "radpostauth"
 sql: postauth_query = "INSERT into radpostauth (id, user, pass, reply, date) values ('', '%{User-Name}', '%{User-Password:-Chap-Password}', '%{reply:Packet-Type}', NOW())"
 sql: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
rlm_sql (sql): Attempting to connect to root@localhost:/radius
rlm_sql (sql): starting 0
rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
rlm_sql_mysql: Starting connect to MySQL server for #0
rlm_sql (sql): Connected new DB handle, #0
rlm_sql (sql): starting 1
rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
rlm_sql_mysql: Starting connect to MySQL server for #1
rlm_sql (sql): Connected new DB handle, #1
rlm_sql (sql): starting 2
rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
rlm_sql_mysql: Starting connect to MySQL server for #2
rlm_sql (sql): Connected new DB handle, #2
rlm_sql (sql): starting 3
rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
rlm_sql_mysql: Starting connect to MySQL server for #3
rlm_sql (sql): Connected new DB handle, #3
rlm_sql (sql): starting 4
rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
rlm_sql_mysql: Starting connect to MySQL server for #4
rlm_sql (sql): Connected new DB handle, #4
Module: Instantiated sql (sql) 
Module: Loaded SQL Counter 
 sqlcounter: counter-name = "Max-All-Session-Time"
 sqlcounter: check-name = "Max-All-Session"
 sqlcounter: key = "User-Name"
 sqlcounter: sqlmod-inst = "sql"
 sqlcounter: query = "SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='%{%k}'"
 sqlcounter: reset = "never"
rlm_sqlcounter: Counter attribute Max-All-Session-Time is number 1671
rlm_sqlcounter: Check attribute Max-All-Session is number 1672
rlm_sqlcounter: Current Time: 1132324700 [2005-11-18 15:38:20], Next reset 0 [2005-11-18 15:00:00]
rlm_sqlcounter: Current Time: 1132324700 [2005-11-18 15:38:20], Prev reset 0 [2005-11-18 15:00:00]
Module: Instantiated sqlcounter (noresetcounter) 
 sqlcounter: counter-name = "Daily-Session-Time"
 sqlcounter: check-name = "Max-Daily-Session"
 sqlcounter: key = "User-Name"
 sqlcounter: sqlmod-inst = "sql"
 sqlcounter: query = "SELECT SUM(AcctSessionTime - GREATEST((%b - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='%{%k}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '%b'"
 sqlcounter: reset = "daily"
rlm_sqlcounter: Counter attribute Daily-Session-Time is number 1673
rlm_sqlcounter: Check attribute Max-Daily-Session is number 1674
rlm_sqlcounter: Current Time: 1132324700 [2005-11-18 15:38:20], Next reset 1132354800 [2005-11-19 00:00:00]
rlm_sqlcounter: Current Time: 1132324700 [2005-11-18 15:38:20], Prev reset 1132268400 [2005-11-18 00:00:00]
Module: Instantiated sqlcounter (dailycounter) 
 sqlcounter: counter-name = "Weekly-Session-Time"
 sqlcounter: check-name = "Max-Weekly-Session"
 sqlcounter: key = "User-Name"
 sqlcounter: sqlmod-inst = "sql"
 sqlcounter: query = "SELECT SUM(AcctSessionTime - GREATEST((%b - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='%{%k}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '%b'"
 sqlcounter: reset = "weekly"
rlm_sqlcounter: Counter attribute Weekly-Session-Time is number 1675
rlm_sqlcounter: Check attribute Max-Weekly-Session is number 1676
rlm_sqlcounter: Current Time: 1132324700 [2005-11-18 15:38:20], Next reset 1132441200 [2005-11-20 00:00:00]
rlm_sqlcounter: Current Time: 1132324700 [2005-11-18 15:38:20], Prev reset 1132095600 [2005-11-16 00:00:00]
Module: Instantiated sqlcounter (weeklycounter) 
Module: Loaded Acct-Unique-Session-Id 
 acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Module: Instantiated acct_unique (acct_unique) 
Listening on authentication *:1812
Listening on accounting *:1813
Ready to process requests.
rad_recv: Access-Request packet from host 192.168.0.60:1073, id=40, length=119
	User-Name = "pepe@2"
	EAP-Message = 0x0200000b01706570654032
	Message-Authenticator = 0x857833d01159c2600ffe978685a9a91b
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
  modcall[authorize]: module "preprocess" returns ok for request 0
  modcall[authorize]: module "chap" returns noop for request 0
  modcall[authorize]: module "mschap" returns noop for request 0
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 0
  rlm_eap: EAP packet type response id 0 length 11
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 0
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 4
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 4
  modcall[authorize]: module "sql" returns ok for request 0
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 0
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 0
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 0
modcall: group authorize returns updated for request 0
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 0
  rlm_eap: EAP Identity
  rlm_eap: processing type tls
  rlm_eap_tls: Initiate
  rlm_eap_tls: Start returned 1
  modcall[authenticate]: module "eap" returns handled for request 0
modcall: group authenticate returns handled for request 0
Sending Access-Challenge of id 40 to 192.168.0.60:1073
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x010100061920
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xadcb298af4bf495278c211f174caf89c
Finished request 0
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 0 ID 40 with timestamp 437de76e
Nothing to do.  Sleeping until we see a request.
rad_recv: Access-Request packet from host 192.168.0.60:1073, id=41, length=137
	User-Name = "pepe@2"
	State = 0xadcb298af4bf495278c211f174caf89c
	EAP-Message = 0x0201000b01706570654032
	Message-Authenticator = 0x4a646af076a4511e6afdfdefe12c1d61
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 1
  modcall[authorize]: module "preprocess" returns ok for request 1
  modcall[authorize]: module "chap" returns noop for request 1
  modcall[authorize]: module "mschap" returns noop for request 1
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 1
  rlm_eap: EAP packet type response id 1 length 11
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 1
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 3
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 3
  modcall[authorize]: module "sql" returns ok for request 1
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 1
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 1
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 1
modcall: group authorize returns updated for request 1
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 1
  rlm_eap: EAP Identity
  rlm_eap: processing type tls
  rlm_eap_tls: Initiate
  rlm_eap_tls: Start returned 1
  modcall[authenticate]: module "eap" returns handled for request 1
modcall: group authenticate returns handled for request 1
Sending Access-Challenge of id 41 to 192.168.0.60:1073
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x010200061920
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x44f48eeb7b127abf2beff42a10d3cdfe
Finished request 1
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.60:1073, id=42, length=238
	User-Name = "pepe@2"
	State = 0x44f48eeb7b127abf2beff42a10d3cdfe
	EAP-Message = 0x0202007019800000006616030100610100005d0301437de78c9c477e1463765315632a2eedcf3b7cfd026466252a48d91abbff7b2c20702177294cc65bc47f91dc5b88a9afe252542d652f98c193535be764c68e21bb001600040005000a000900640062000300060013001200630100
	Message-Authenticator = 0x1dfa5161d6212cab559381a910211348
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 2
  modcall[authorize]: module "preprocess" returns ok for request 2
  modcall[authorize]: module "chap" returns noop for request 2
  modcall[authorize]: module "mschap" returns noop for request 2
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 2
  rlm_eap: EAP packet type response id 2 length 112
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 2
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 2
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 2
  modcall[authorize]: module "sql" returns ok for request 2
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 2
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 2
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 2
modcall: group authorize returns updated for request 2
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 2
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
rlm_eap_tls:  Length Included
  eaptls_verify returned 11 
    (other): before/accept initialization 
    TLS_accept: before/accept initialization 
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0061], ClientHello  
    TLS_accept: SSLv3 read client hello A 
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 004a], ServerHello  
    TLS_accept: SSLv3 write server hello A 
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 068f], Certificate  
    TLS_accept: SSLv3 write certificate A 
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone  
    TLS_accept: SSLv3 write server done A 
    TLS_accept: SSLv3 flush data 
    TLS_accept:error in SSLv3 read client certificate A 
In SSL Handshake Phase 
In SSL Accept mode  
  eaptls_process returned 13 
  rlm_eap_peap: EAPTLS_HANDLED
  modcall[authenticate]: module "eap" returns handled for request 2
modcall: group authenticate returns handled for request 2
Sending Access-Challenge of id 42 to 192.168.0.60:1073
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x0103040a19c0000006ec160301004a020000460301437de78c47d242f104003e6daeb7662e20359eefa0806b6bf81aeea9c67353c1201257aa2f5f9aed7f8cc1e24c8d3b1c88784a885f5716e86ee39b81cf436754bc000400160301068f0b00068b0006880002cb308202c730820230a003020102020102300d06092a864886f70d010104050030819e310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e3111300f060355040b130870726f6c69616e74311b301906035504031312436c69656e7420636572
	EAP-Message = 0x74696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d301e170d3035303832363136303033375a170d3036303832363136303033375a30819a310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e3111300f060355040b130870726f6c69616e743119301706035504031310526f6f74206365727469666963617465311f301d06092a864886f70d0109011610726f6f74406578616d706c652e636f6d30819f300d06092a864886f70d010101050003818d
	EAP-Message = 0x0030818902818100c6ee8983ba197bc28a363b57d9dfb3ad385efea9129e5e22c816d83e3ec8c6967f69f973fb14a41af5891afce99c8109932062c20ceb474de50b025b63e7c6f9a309825de19ec501dac78e99a443303d643b2d3fc2ddd0251ad8fd1d98a379af656cf87cc33d3229b367b3f36c73f67f6ee4317ca4cd278142867ea13552245b0203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d0101040500038181003f60bc44d4cf6fb76e48204f10a1b712d40551dc958c434ba3a2cc888fcb979afc6410bac8e5c4b80be9b09bddb405128d66fe8915d5707107b5d88d9ad95c98f5ff95cb
	EAP-Message = 0x9e3a666f43430f6b69cccaf6833ed9c328d1862be21e54903998f640f48719130d92fe1a693d9ccf1403f1c7a71f3e20979e02db7f06538611cf9b0f0003b7308203b33082031ca003020102020100300d06092a864886f70d010104050030819e310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e3111300f060355040b130870726f6c69616e74311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e63
	EAP-Message = 0x6f6d301e170d3035303832363136303033355a170d30
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x630601d7e626bc2107f12b000877e2f1
Finished request 2
Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.60:1073, id=43, length=132
	User-Name = "pepe@2"
	State = 0x630601d7e626bc2107f12b000877e2f1
	EAP-Message = 0x020300061900
	Message-Authenticator = 0x573ad1eb594ea60bd0121b357beb3f92
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 3
  modcall[authorize]: module "preprocess" returns ok for request 3
  modcall[authorize]: module "chap" returns noop for request 3
  modcall[authorize]: module "mschap" returns noop for request 3
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 3
  rlm_eap: EAP packet type response id 3 length 6
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 3
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 1
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 1
  modcall[authorize]: module "sql" returns ok for request 3
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 3
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 3
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 3
modcall: group authorize returns updated for request 3
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 3
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
rlm_eap_tls: Received EAP-TLS ACK message
  rlm_eap_tls: ack handshake fragment handler
  eaptls_verify returned 1 
  eaptls_process returned 13 
  rlm_eap_peap: EAPTLS_HANDLED
  modcall[authenticate]: module "eap" returns handled for request 3
modcall: group authenticate returns handled for request 3
Sending Access-Challenge of id 43 to 192.168.0.60:1073
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x010402f2190037303832363136303033355a30819e310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e3111300f060355040b130870726f6c69616e74311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100cf72fb84aaf293b1d18f0118a451988e4d09bac8194fb4ec0f6caf5a6c8046b834e081132fffd50c8695568c4c
	EAP-Message = 0xd6932dfd7884dd9d9ddfc324722a3999609b508d473c20294f7e16f41400f115e1f06ee889917afc916aca0e0c9ff1ee4404963f23ac26d2c9e8e3b966ba57d6bdb34ebaf642abd4056b95619f1b2a527a93890203010001a381fe3081fb301d0603551d0e041604148ff45f524e0254e23cc203fc39051fd149e2e4f03081cb0603551d230481c33081c080148ff45f524e0254e23cc203fc39051fd149e2e4f0a181a4a481a130819e310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e3111300f06035504
	EAP-Message = 0x0b130870726f6c69616e74311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d820100300c0603551d13040530030101ff300d06092a864886f70d010104050003818100ae109fc14bf7b5f23b2077f1832e7c45dbc22d4b8c911021e3c95728357f75354c4cf3898a818f0615905ee6cd6366775ccb8f9f71e1b638dc5c479db456247499c8e19b838630de1bdc6e139d196b03466e985afd25371c174492d85c6ac7dc4b14e3f17eae85fecc6b7f065a5cee2ccc86f973ee75a6557c48a8af32301be416030100040e000000
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x0135f183c02deedef2fcbcaeb29b923e
Finished request 3
Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.60:1073, id=44, length=318
	User-Name = "pepe@2"
	State = 0x0135f183c02deedef2fcbcaeb29b923e
	EAP-Message = 0x020400c01980000000b61603010086100000820080b44e0f2d7fa922b899631fc77ccb55028bd696043f9d2deedbd03a8f83f66dfee04fd59e7e8ec730c7b748a740d7e51dec6d5bfdd99d1bdd810bc03568b79805de0a1cb16935f9e2b62780fa705a36bc91cc1a8a7a6cac3f53c29f61668aef3d636a2244f5d5bf6e0f5f7a8823fd1773cad2f01bbbe8b7507eee6aff49e1458314030100010116030100201fbabae2535a9ac3ebf72a654458ab34c571a6f978ee66f532f48c184a1e0de4
	Message-Authenticator = 0x8b376be6308c0c7d9ba4899440a9ab34
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 4
  modcall[authorize]: module "preprocess" returns ok for request 4
  modcall[authorize]: module "chap" returns noop for request 4
  modcall[authorize]: module "mschap" returns noop for request 4
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 4
  rlm_eap: EAP packet type response id 4 length 192
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 4
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 0
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 0
  modcall[authorize]: module "sql" returns ok for request 4
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 4
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 4
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 4
modcall: group authorize returns updated for request 4
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 4
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
rlm_eap_tls:  Length Included
  eaptls_verify returned 11 
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange  
    TLS_accept: SSLv3 read client key exchange A 
  rlm_eap_tls: <<< TLS 1.0 ChangeCipherSpec [length 0001]  
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0010], Finished  
    TLS_accept: SSLv3 read finished A 
  rlm_eap_tls: >>> TLS 1.0 ChangeCipherSpec [length 0001]  
    TLS_accept: SSLv3 write change cipher spec A 
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 0010], Finished  
    TLS_accept: SSLv3 write finished A 
    TLS_accept: SSLv3 flush data 
    (other): SSL negotiation finished successfully 
SSL Connection Established 
  eaptls_process returned 13 
  rlm_eap_peap: EAPTLS_HANDLED
  modcall[authenticate]: module "eap" returns handled for request 4
modcall: group authenticate returns handled for request 4
Sending Access-Challenge of id 44 to 192.168.0.60:1073
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x0105003119001403010001011603010020fb8aaf3be131d768a63017854c7c23750e6c689b3de3aa8d272fdb79d41b011e
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x318e792148ca4a99521d65db373fc0a0
Finished request 4
Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.60:1073, id=45, length=132
	User-Name = "pepe@2"
	State = 0x318e792148ca4a99521d65db373fc0a0
	EAP-Message = 0x020500061900
	Message-Authenticator = 0xfc9ba1b28ca7b1da8613a376c436be63
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 5
  modcall[authorize]: module "preprocess" returns ok for request 5
  modcall[authorize]: module "chap" returns noop for request 5
  modcall[authorize]: module "mschap" returns noop for request 5
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 5
  rlm_eap: EAP packet type response id 5 length 6
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 5
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 4
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 4
  modcall[authorize]: module "sql" returns ok for request 5
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 5
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 5
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 5
modcall: group authorize returns updated for request 5
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 5
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
rlm_eap_tls: Received EAP-TLS ACK message
  rlm_eap_tls: ack handshake is finished
  eaptls_verify returned 3 
  eaptls_process returned 3 
  rlm_eap_peap: EAPTLS_SUCCESS
  modcall[authenticate]: module "eap" returns handled for request 5
modcall: group authenticate returns handled for request 5
Sending Access-Challenge of id 45 to 192.168.0.60:1073
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x0106002019001703010015fe2fa6d26ae930b0251a331d2ab21e986276447312
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x9536f209af73db471d6661690c1ccf19
Finished request 5
Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.60:1073, id=46, length=160
	User-Name = "pepe@2"
	State = 0x9536f209af73db471d6661690c1ccf19
	EAP-Message = 0x02060022190017030100173045eca0ddf60d6dfe7599ddd658225a848ee96af9320b
	Message-Authenticator = 0x99fbf2f6fe623bdb5826baf86cf8af83
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 6
  modcall[authorize]: module "preprocess" returns ok for request 6
  modcall[authorize]: module "chap" returns noop for request 6
  modcall[authorize]: module "mschap" returns noop for request 6
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 6
  rlm_eap: EAP packet type response id 6 length 34
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 6
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 3
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 3
  modcall[authorize]: module "sql" returns ok for request 6
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 6
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 6
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 6
modcall: group authorize returns updated for request 6
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 6
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7 
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7 
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: Identity - pepe@2
  rlm_eap_peap: Tunneled data is valid.
  PEAP: Got tunneled EAP-Message
	EAP-Message = 0x0206000b01706570654032
  PEAP: Got tunneled identity of pepe@2
  PEAP: Setting default EAP type for tunneled EAP session.
  PEAP: Setting User-Name to pepe@2
  PEAP: Sending tunneled request
	EAP-Message = 0x0206000b01706570654032
	FreeRADIUS-Proxied-To = 127.0.0.1
	User-Name = "pepe@2"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 6
  modcall[authorize]: module "preprocess" returns ok for request 6
  modcall[authorize]: module "chap" returns noop for request 6
  modcall[authorize]: module "mschap" returns noop for request 6
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 6
  rlm_eap: EAP packet type response id 6 length 11
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 6
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 2
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 2
  modcall[authorize]: module "sql" returns ok for request 6
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 6
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 6
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 6
modcall: group authorize returns updated for request 6
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 6
  rlm_eap: EAP Identity
  rlm_eap: processing type mschapv2
rlm_eap_mschapv2: Issuing Challenge
  modcall[authenticate]: module "eap" returns handled for request 6
modcall: group authenticate returns handled for request 6
  PEAP: Got tunneled reply RADIUS code 11
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x010700201a0107001b10b213538d45b54607359136841d21cd4e706570654032
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x9ad4e2cb9ccc41c387a83f1a583a5cc6
  PEAP: Processing from tunneled session code 0x8195e98 11
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x010700201a0107001b10b213538d45b54607359136841d21cd4e706570654032
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x9ad4e2cb9ccc41c387a83f1a583a5cc6
  PEAP: Got tunneled Access-Challenge
  modcall[authenticate]: module "eap" returns handled for request 6
modcall: group authenticate returns handled for request 6
Sending Access-Challenge of id 46 to 192.168.0.60:1073
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x010700371900170301002c90dea7fae9d3fd3068a980b88680a49040190263a42fcbcd216788495d2a1ffd012db65afc4de325665a4b06
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x2f0f2513c0e24410475061f7dae9845b
Finished request 6
Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.60:1073, id=47, length=214
	User-Name = "pepe@2"
	State = 0x2f0f2513c0e24410475061f7dae9845b
	EAP-Message = 0x020700581900170301004d8e5bc2cd2ffba4f8366dbcc1887c252b8d1980b4a2b28957ee340b8c4444212ac2eff1e1f0deebda90c27f789b0a1ed58aa5ce8a29dce3837abc4178c3e3638af2c1edf6ceda9094cd38c2eb58
	Message-Authenticator = 0x969c39d3e86698103a2943310e7a2135
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 7
  modcall[authorize]: module "preprocess" returns ok for request 7
  modcall[authorize]: module "chap" returns noop for request 7
  modcall[authorize]: module "mschap" returns noop for request 7
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 7
  rlm_eap: EAP packet type response id 7 length 88
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 7
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 1
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 1
  modcall[authorize]: module "sql" returns ok for request 7
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 7
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 7
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 7
modcall: group authorize returns updated for request 7
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 7
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7 
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7 
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: EAP type mschapv2
  rlm_eap_peap: Tunneled data is valid.
  PEAP: Got tunneled EAP-Message
	EAP-Message = 0x020700411a0207003c3109c02a1f16600f0b7ebf8c57dd72463a00000000000000006c8a834a001b1ede7a7c25e3ac21ebd9586849f1dff5c25a00706570654032
  PEAP: Setting User-Name to pepe@2
  PEAP: Adding old state with 9a d4
  PEAP: Sending tunneled request
	EAP-Message = 0x020700411a0207003c3109c02a1f16600f0b7ebf8c57dd72463a00000000000000006c8a834a001b1ede7a7c25e3ac21ebd9586849f1dff5c25a00706570654032
	FreeRADIUS-Proxied-To = 127.0.0.1
	User-Name = "pepe@2"
	State = 0x9ad4e2cb9ccc41c387a83f1a583a5cc6
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 7
  modcall[authorize]: module "preprocess" returns ok for request 7
  modcall[authorize]: module "chap" returns noop for request 7
  modcall[authorize]: module "mschap" returns noop for request 7
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 7
  rlm_eap: EAP packet type response id 7 length 65
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 7
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 0
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 0
  modcall[authorize]: module "sql" returns ok for request 7
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 7
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 7
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 7
modcall: group authorize returns updated for request 7
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 7
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/mschapv2
  rlm_eap: processing type mschapv2
  Processing the authenticate section of radiusd.conf
modcall: entering group Auth-Type for request 7
  rlm_mschap: Told to do MS-CHAPv2 for pepe@2 with NT-Password
rlm_mschap: adding MS-CHAPv2 MPPE keys
  modcall[authenticate]: module "mschap" returns ok for request 7
modcall: group Auth-Type returns ok for request 7
MSCHAP Success 
  modcall[authenticate]: module "eap" returns handled for request 7
modcall: group authenticate returns handled for request 7
  PEAP: Got tunneled reply RADIUS code 11
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	MS-CHAP2-Success = 0x07533d32434638444439413532323630424533434244373433453635463131384442314544354245433346
	EAP-Message = 0x010800331a0307002e533d32434638444439413532323630424533434244373433453635463131384442314544354245433346
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xc141d8145bc0c0c3eb4cb342e98a1c00
  PEAP: Processing from tunneled session code 0x81c6570 11
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	MS-CHAP2-Success = 0x07533d32434638444439413532323630424533434244373433453635463131384442314544354245433346
	EAP-Message = 0x010800331a0307002e533d32434638444439413532323630424533434244373433453635463131384442314544354245433346
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xc141d8145bc0c0c3eb4cb342e98a1c00
  PEAP: Got tunneled Access-Challenge
  modcall[authenticate]: module "eap" returns handled for request 7
modcall: group authenticate returns handled for request 7
Sending Access-Challenge of id 47 to 192.168.0.60:1073
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x0108004a1900170301003f953fad7bb9effdcd17a252fcbf83a7bca242bceda61e69233a63823bcab595173a4747bcaec6288f8993d9d8804985c44af981f7f621aeac331c2c5e135267
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x0e871d815cf2848f6c103dc30bd58392
Finished request 7
Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.60:1073, id=48, length=155
	User-Name = "pepe@2"
	State = 0x0e871d815cf2848f6c103dc30bd58392
	EAP-Message = 0x0208001d19001703010012565b6eaba4c4e2208e8f8bd19589cc664e86
	Message-Authenticator = 0xe9096396ecc465f095bae11ea5b7b9b8
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 8
  modcall[authorize]: module "preprocess" returns ok for request 8
  modcall[authorize]: module "chap" returns noop for request 8
  modcall[authorize]: module "mschap" returns noop for request 8
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 8
  rlm_eap: EAP packet type response id 8 length 29
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 8
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 4
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 4
  modcall[authorize]: module "sql" returns ok for request 8
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 8
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 8
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 8
modcall: group authorize returns updated for request 8
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 8
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7 
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7 
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: EAP type mschapv2
  rlm_eap_peap: Tunneled data is valid.
  PEAP: Got tunneled EAP-Message
	EAP-Message = 0x020800061a03
  PEAP: Setting User-Name to pepe@2
  PEAP: Adding old state with c1 41
  PEAP: Sending tunneled request
	EAP-Message = 0x020800061a03
	FreeRADIUS-Proxied-To = 127.0.0.1
	User-Name = "pepe@2"
	State = 0xc141d8145bc0c0c3eb4cb342e98a1c00
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 8
  modcall[authorize]: module "preprocess" returns ok for request 8
  modcall[authorize]: module "chap" returns noop for request 8
  modcall[authorize]: module "mschap" returns noop for request 8
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 8
  rlm_eap: EAP packet type response id 8 length 6
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 8
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 3
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 3
  modcall[authorize]: module "sql" returns ok for request 8
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 8
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 8
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 8
modcall: group authorize returns updated for request 8
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 8
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/mschapv2
  rlm_eap: processing type mschapv2
  rlm_eap: Freeing handler
  modcall[authenticate]: module "eap" returns ok for request 8
modcall: group authenticate returns ok for request 8
Login OK: [pepe@2/<no User-Password attribute>] (from client red-privada port 0)
  Processing the post-auth section of radiusd.conf
modcall: entering group post-auth for request 8
rlm_sql (sql): Processing sql_postauth
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'INSERT into radpostauth (id, user, pass, reply, date) values ('', 'pepe@2', 'Chap-Password', 'Access-Accept', NOW())'
rlm_sql (sql) in sql_postauth: query is INSERT into radpostauth (id, user, pass, reply, date) values ('', 'pepe@2', 'Chap-Password', 'Access-Accept', NOW())
rlm_sql (sql): Reserving sql socket id: 2
rlm_sql (sql): Released sql socket id: 2
  modcall[post-auth]: module "sql" returns ok for request 8
modcall: group post-auth returns ok for request 8
  PEAP: Got tunneled reply RADIUS code 2
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x03080004
	Message-Authenticator = 0x00000000000000000000000000000000
	User-Name = "pepe@2"
  PEAP: Processing from tunneled session code 0x81c5300 2
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x03080004
	Message-Authenticator = 0x00000000000000000000000000000000
	User-Name = "pepe@2"
  PEAP: Tunneled authentication was successful.
  rlm_eap_peap: SUCCESS
  modcall[authenticate]: module "eap" returns handled for request 8
modcall: group authenticate returns handled for request 8
Sending Access-Challenge of id 48 to 192.168.0.60:1073
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	EAP-Message = 0x010900261900170301001b61c4c49dbecc0711438c4dd263e268b72bccb3a1dd48341d48fc6c
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xe074f92b1d5a4ab1a12f5a64c28608bb
Finished request 8
Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.60:1073, id=49, length=164
	User-Name = "pepe@2"
	State = 0xe074f92b1d5a4ab1a12f5a64c28608bb
	EAP-Message = 0x020900261900170301001b356512a05ee9918699375d7503609761697f682fd354c9c2a9a996
	Message-Authenticator = 0xb10ea10adf047f9843d7e6594e99c349
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 9
  modcall[authorize]: module "preprocess" returns ok for request 9
  modcall[authorize]: module "chap" returns noop for request 9
  modcall[authorize]: module "mschap" returns noop for request 9
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[authorize]: module "suffix" returns noop for request 9
  rlm_eap: EAP packet type response id 9 length 38
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 9
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pepe@2' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 1
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pepe@2' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'pepe@2' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 1
  modcall[authorize]: module "sql" returns ok for request 9
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 9
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "dailycounter" returns noop for request 9
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "weeklycounter" returns noop for request 9
modcall: group authorize returns updated for request 9
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 9
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7 
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7 
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: Received EAP-TLV response.
  rlm_eap_peap: Tunneled data is valid.
  rlm_eap_peap: Success
  rlm_eap: Freeing handler
  modcall[authenticate]: module "eap" returns ok for request 9
modcall: group authenticate returns ok for request 9
Login OK: [pepe@2/<no User-Password attribute>] (from client red-privada port 2 cli 00-0E-35-4B-81-90)
  Processing the post-auth section of radiusd.conf
modcall: entering group post-auth for request 9
rlm_sql (sql): Processing sql_postauth
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  'INSERT into radpostauth (id, user, pass, reply, date) values ('', 'pepe@2', 'Chap-Password', 'Access-Accept', NOW())'
rlm_sql (sql) in sql_postauth: query is INSERT into radpostauth (id, user, pass, reply, date) values ('', 'pepe@2', 'Chap-Password', 'Access-Accept', NOW())
rlm_sql (sql): Reserving sql socket id: 0
rlm_sql (sql): Released sql socket id: 0
  modcall[post-auth]: module "sql" returns ok for request 9
modcall: group post-auth returns ok for request 9
Sending Access-Accept of id 49 to 192.168.0.60:1073
	Acct-Interim-Interval := 120
	WISPr-Redirection-URL := "http://www.google.com"
	MS-MPPE-Recv-Key = 0x4159b2279c7d51e213eb98e2520f25feb5189959fe9e22f361fd09de3150fc94
	MS-MPPE-Send-Key = 0x959a95b4adaff8b9c288913548ec358ef34d7913fd7ca4bce905c3e7bc5050de
	EAP-Message = 0x03090004
	Message-Authenticator = 0x00000000000000000000000000000000
	User-Name = "pepe@2"
Finished request 9
Going to the next request
Waking up in 6 seconds...
rad_recv: Accounting-Request packet from host 192.168.0.60:1073, id=50, length=212
	Acct-Status-Type = Start
	User-Name = "pepe@2"
	Calling-Station-Id = "00-0E-35-4B-81-90"
	Called-Station-Id = "00-00-24-C4-54-59"
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 2
	NAS-Port-Id = "00000002"
	NAS-IP-Address = 0.0.0.0
	NAS-Identifier = "19"
	Framed-IP-Address = 192.168.182.6
	Acct-Session-Id = "437de6c800000002"
	WISPr-Location-ID = "isocc=es,cc=34,ac=943,network=Testing_Sarematica"
	WISPr-Location-Name = "Joseba,Sarematica_SL"
  Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 10
  modcall[preacct]: module "preprocess" returns noop for request 10
rlm_acct_unique: Hashing 'NAS-Port = 2,Client-IP-Address = 192.168.0.60,NAS-IP-Address = 0.0.0.0,Acct-Session-Id = "437de6c800000002",User-Name = "pepe@2"'
rlm_acct_unique: Acct-Unique-Session-ID = "44590ef2a760047d".
  modcall[preacct]: module "acct_unique" returns ok for request 10
    rlm_realm: Looking up realm "2" for User-Name = "pepe@2"
    rlm_realm: No such realm "2"
  modcall[preacct]: module "suffix" returns noop for request 10
modcall: group preacct returns ok for request 10
  Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 10
  modcall[accounting]: module "acct_unique" returns noop for request 10
radius_xlat:  'pepe@2'
rlm_sql (sql): sql_set_user escaped user --> 'pepe@2'
radius_xlat:  '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('437de6c800000002', '44590ef2a760047d', 'pepe@2', '19', '0.0.0.0', '2', 'Wireless-802.11', '2005-11-18 15:39:08', '0', '0', '', '', '', '0', '0', '00-00-24-C4-54-59', '00-0E-35-4B-81-90', '', '', '', '192.168.182.6', '', '0')'
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
  modcall[accounting]: module "sql" returns ok for request 10
modcall: group accounting returns ok for request 10
Sending Accounting-Response of id 50 to 192.168.0.60:1073
Finished request 10
Going to the next request
Cleaning up request 10 ID 50 with timestamp 437de78c
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 1 ID 41 with timestamp 437de78c
Cleaning up request 2 ID 42 with timestamp 437de78c
Cleaning up request 3 ID 43 with timestamp 437de78c
Cleaning up request 4 ID 44 with timestamp 437de78c
Cleaning up request 5 ID 45 with timestamp 437de78c
Cleaning up request 6 ID 46 with timestamp 437de78c
Cleaning up request 7 ID 47 with timestamp 437de78c
Cleaning up request 8 ID 48 with timestamp 437de78c
Cleaning up request 9 ID 49 with timestamp 437de78c
Nothing to do.  Sleeping until we see a request.
--- Walking the entire request list ---
Nothing to do.  Sleeping until we see a request.
Exiting...
rlm_sql (sql): Closing sqlsocket 4
rlm_sql (sql): Closing sqlsocket 3
rlm_sql (sql): Closing sqlsocket 2
rlm_sql (sql): Closing sqlsocket 1
rlm_sql (sql): Closing sqlsocket 0

Slow PEAP Response

Joseba Beltrán