EAP-PEAP-MS-CHAPv2: MS-CHAPv2 attributes discarded after proxying

30 Jan 2008

      Hi!

I'm trying to setup the following scheme:

[win_xp]-----[Wi-Fi AP with WPA]-------[FreeRADIUS]--------[home RADIUS server]

FreeRADIUS: 1.1.7

Users being connected to access point must be authenticated against EAP-PEAP-MS-CHAPv2 protocol.
Home RADIUS server can do only MS-CHAPv2 authorization and knows nothing about EAP.
To pass extracted MS-CHAPv2 request from PEAP tunnel I've turned off proxy_tunneled_request_as_eap:

---------eap.conf-------------
peap {
    default_eap_type = mschapv2
    copy_request_to_tunnel = yes
    use_tunneled_reply = yes
    proxy_tunneled_request_as_eap = no
}

--------users-----------------
aaa     FreeRADIUS-Proxied-To == 127.0.0.1, Proxy-To-Realm := "xxx"
         Fall-Through := No

--------proxy.conf------------
realm xxx {
         type            = radius 

         authhost        = 192.168.2.80:1812
         accthost        = 192.168.2.80:1813
         secret          = pretty_secret
} 

------------------------------

Authorization requests are being proxied from FreeRADIUS to home RADIUS server as plain MS-CHAPv2.
Home server authorizes client and passes back MS-MPPE-*-Keys. But FreeRADIUS discards all MS-CHAPv2 attributes from
proxy reply just saying "rlm_eap_mschapv2: Authentication succeeded.".

Here is the response from home server:

rad_recv: Access-Accept packet from host 192.168.2.80:1812, id=0, length=262
Wed Jan 30 15:03:33 2008 : Debug:  proxy: de-allocating 5002a8c0:1812 0
Reply-Message = "ACCESS: GRANTED"
Reply-Message = "AGREEMENT-ID: 587986"
Framed-IP-Address = 192.168.2.56
Framed-IP-Netmask = 255.255.255.255
Framed-Protocol = PPP
MS-CHAP2-Success = 0x00533d37354142314531443945333538353133414541334245443244314630344333384533363742384232
MS-MPPE-Encryption-Policy = 0x00000001
MS-MPPE-Encryption-Types = 0x00000006
MS-MPPE-Recv-Key = 0xadfa59550658460011ffff6aee8df748
MS-MPPE-Send-Key = 0x2f62bd6b536d9e6141790bf5c477a5b8
Service-Type = Framed-User
Reply-Message = "STATUS: 0.00000000"

and the response to Wi-Fi AP before tunnel:

PEAP: Final reply from tunneled session code 11
Reply-Message = "ACCESS: GRANTED"
Reply-Message = "AGREEMENT-ID: 587986"
Framed-IP-Address = 192.168.2.56
Framed-IP-Netmask = 255.255.255.255
Framed-Protocol = PPP
Service-Type = Framed-User
Reply-Message = "STATUS: 0.00000000"
EAP-Message = 0x010700331a0306002e533d37354142314531443945333538353133414541334245443244314630344333384533363742384232
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xbb336a79c074253ad516aa753953f8aa

There is no MS-CHAP2-Success attribute here. So no "rlm_eap_peap: Success" at the end of challenge and no
Access-Accept packet being sent to Wi-Fi AP.

When username is configured locally (i.e. with no proxying request to home server), everything works fine.

Does anyone have such working scheme here?
Please find complete log attached.

-- 
Best wishes,
Dmitry Sergienko (SDA104-RIPE)
Trifle Co., Ltd.

Wed Jan 30 16:21:17 2008 : Info: Starting - reading configuration files ...
Wed Jan 30 16:21:17 2008 : Debug: reread_config:  reading radiusd.conf
Wed Jan 30 16:21:17 2008 : Debug: Config:   including file: /etc/freeradius/proxy.conf
Wed Jan 30 16:21:17 2008 : Debug: Config:   including file: /etc/freeradius/clients.conf
Wed Jan 30 16:21:17 2008 : Debug: Config:   including file: /etc/freeradius/snmp.conf
Wed Jan 30 16:21:17 2008 : Debug: Config:   including file: /etc/freeradius/eap.conf
Wed Jan 30 16:21:17 2008 : Debug: Config:   including file: /etc/freeradius/sql.conf
Wed Jan 30 16:21:17 2008 : Debug:  main: prefix = "/usr"
Wed Jan 30 16:21:17 2008 : Debug:  main: localstatedir = "/var"
Wed Jan 30 16:21:17 2008 : Debug:  main: logdir = "/var/log/freeradius"
Wed Jan 30 16:21:17 2008 : Debug:  main: libdir = "/usr/lib/freeradius"
Wed Jan 30 16:21:17 2008 : Debug:  main: radacctdir = "/var/log/freeradius/radacct"
Wed Jan 30 16:21:17 2008 : Debug:  main: hostname_lookups = no
Wed Jan 30 16:21:17 2008 : Debug:  main: snmp = no
Wed Jan 30 16:21:17 2008 : Debug:  main: max_request_time = 30
Wed Jan 30 16:21:17 2008 : Debug:  main: cleanup_delay = 5
Wed Jan 30 16:21:17 2008 : Debug:  main: max_requests = 1024
Wed Jan 30 16:21:17 2008 : Debug:  main: delete_blocked_requests = 0
Wed Jan 30 16:21:17 2008 : Debug:  main: port = 0
Wed Jan 30 16:21:17 2008 : Debug:  main: allow_core_dumps = no
Wed Jan 30 16:21:17 2008 : Debug:  main: log_stripped_names = no
Wed Jan 30 16:21:17 2008 : Debug:  main: log_file = "/var/log/freeradius/radius.log"
Wed Jan 30 16:21:17 2008 : Debug:  main: log_auth = no
Wed Jan 30 16:21:17 2008 : Debug:  main: log_auth_badpass = no
Wed Jan 30 16:21:17 2008 : Debug:  main: log_auth_goodpass = no
Wed Jan 30 16:21:17 2008 : Debug:  main: pidfile = "/var/run/freeradius/freeradius.pid"
Wed Jan 30 16:21:17 2008 : Debug:  main: user = "freerad"
Wed Jan 30 16:21:17 2008 : Debug:  main: group = "freerad"
Wed Jan 30 16:21:17 2008 : Debug:  main: usercollide = no
Wed Jan 30 16:21:17 2008 : Debug:  main: lower_user = "no"
Wed Jan 30 16:21:17 2008 : Debug:  main: lower_pass = "no"
Wed Jan 30 16:21:17 2008 : Debug:  main: nospace_user = "no"
Wed Jan 30 16:21:17 2008 : Debug:  main: nospace_pass = "no"
Wed Jan 30 16:21:17 2008 : Debug:  main: checkrad = "/usr/sbin/checkrad"
Wed Jan 30 16:21:17 2008 : Debug:  main: proxy_requests = yes
Wed Jan 30 16:21:17 2008 : Debug:  proxy: retry_delay = 5
Wed Jan 30 16:21:17 2008 : Debug:  proxy: retry_count = 3
Wed Jan 30 16:21:17 2008 : Debug:  proxy: synchronous = no
Wed Jan 30 16:21:17 2008 : Debug:  proxy: default_fallback = yes
Wed Jan 30 16:21:17 2008 : Debug:  proxy: dead_time = 120
Wed Jan 30 16:21:17 2008 : Debug:  proxy: post_proxy_authorize = no
Wed Jan 30 16:21:17 2008 : Debug:  proxy: wake_all_if_all_dead = no
Wed Jan 30 16:21:17 2008 : Debug:  security: max_attributes = 200
Wed Jan 30 16:21:17 2008 : Debug:  security: reject_delay = 1
Wed Jan 30 16:21:17 2008 : Debug:  security: status_server = no
Wed Jan 30 16:21:17 2008 : Debug:  main: debug_level = 0
Wed Jan 30 16:21:17 2008 : Debug: read_config_files:  reading dictionary
Wed Jan 30 16:21:17 2008 : Debug: read_config_files:  reading naslist
Wed Jan 30 16:21:17 2008 : Debug: read_config_files:  reading clients
Wed Jan 30 16:21:17 2008 : Debug: read_config_files:  reading realms
Wed Jan 30 16:21:17 2008 : Debug: radiusd:  entering modules setup
Wed Jan 30 16:21:17 2008 : Debug: Module: Library search path is /usr/lib/freeradius
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded exec 
Wed Jan 30 16:21:17 2008 : Debug:  exec: wait = yes
Wed Jan 30 16:21:17 2008 : Debug:  exec: program = "(null)"
Wed Jan 30 16:21:17 2008 : Debug:  exec: input_pairs = "request"
Wed Jan 30 16:21:17 2008 : Debug:  exec: output_pairs = "(null)"
Wed Jan 30 16:21:17 2008 : Debug:  exec: packet_type = "(null)"
Wed Jan 30 16:21:17 2008 : Info: rlm_exec: Wait=yes but no output defined. Did you mean output=none?
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated exec (exec) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded expr 
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated expr (expr) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded PAP 
Wed Jan 30 16:21:17 2008 : Debug:  pap: encryption_scheme = "crypt"
Wed Jan 30 16:21:17 2008 : Debug:  pap: auto_header = yes
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated pap (pap) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded CHAP 
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated chap (chap) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded MS-CHAP 
Wed Jan 30 16:21:17 2008 : Debug:  mschap: use_mppe = yes
Wed Jan 30 16:21:17 2008 : Debug:  mschap: require_encryption = no
Wed Jan 30 16:21:17 2008 : Debug:  mschap: require_strong = no
Wed Jan 30 16:21:17 2008 : Debug:  mschap: with_ntdomain_hack = no
Wed Jan 30 16:21:17 2008 : Debug:  mschap: passwd = "(null)"
Wed Jan 30 16:21:17 2008 : Debug:  mschap: ntlm_auth = "(null)"
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated mschap (mschap) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded System 
Wed Jan 30 16:21:17 2008 : Debug:  unix: cache = no
Wed Jan 30 16:21:17 2008 : Debug:  unix: passwd = "(null)"
Wed Jan 30 16:21:17 2008 : Debug:  unix: shadow = "/etc/shadow"
Wed Jan 30 16:21:17 2008 : Debug:  unix: group = "(null)"
Wed Jan 30 16:21:17 2008 : Debug:  unix: radwtmp = "/var/log/freeradius/radwtmp"
Wed Jan 30 16:21:17 2008 : Debug:  unix: usegroup = no
Wed Jan 30 16:21:17 2008 : Debug:  unix: cache_reload = 600
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated unix (unix) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded eap 
Wed Jan 30 16:21:17 2008 : Debug:  eap: default_eap_type = "peap"
Wed Jan 30 16:21:17 2008 : Debug:  eap: timer_expire = 60
Wed Jan 30 16:21:17 2008 : Debug:  eap: ignore_unknown_eap_types = no
Wed Jan 30 16:21:17 2008 : Debug:  eap: cisco_accounting_username_bug = no
Wed Jan 30 16:21:17 2008 : Debug: rlm_eap: Loaded and initialized type md5
Wed Jan 30 16:21:17 2008 : Debug: rlm_eap: Loaded and initialized type leap
Wed Jan 30 16:21:17 2008 : Debug:  gtc: challenge = "Password: "
Wed Jan 30 16:21:17 2008 : Debug:  gtc: auth_type = "PAP"
Wed Jan 30 16:21:17 2008 : Debug: rlm_eap: Loaded and initialized type gtc
Wed Jan 30 16:21:17 2008 : Debug:  tls: rsa_key_exchange = no
Wed Jan 30 16:21:17 2008 : Debug:  tls: dh_key_exchange = yes
Wed Jan 30 16:21:17 2008 : Debug:  tls: rsa_key_length = 512
Wed Jan 30 16:21:17 2008 : Debug:  tls: dh_key_length = 512
Wed Jan 30 16:21:17 2008 : Debug:  tls: verify_depth = 0
Wed Jan 30 16:21:17 2008 : Debug:  tls: CA_path = "(null)"
Wed Jan 30 16:21:17 2008 : Debug:  tls: pem_file_type = yes
Wed Jan 30 16:21:17 2008 : Debug:  tls: private_key_file = "/etc/freeradius/certs/cert-srv.pem"
Wed Jan 30 16:21:17 2008 : Debug:  tls: certificate_file = "/etc/freeradius/certs/cert-srv.pem"
Wed Jan 30 16:21:17 2008 : Debug:  tls: CA_file = "/etc/freeradius/certs/demoCA/cacert.pem"
Wed Jan 30 16:21:17 2008 : Debug:  tls: private_key_password = "whatever"
Wed Jan 30 16:21:17 2008 : Debug:  tls: dh_file = "/etc/freeradius/certs/dh"
Wed Jan 30 16:21:17 2008 : Debug:  tls: random_file = "/etc/freeradius/certs/random"
Wed Jan 30 16:21:17 2008 : Debug:  tls: fragment_size = 1024
Wed Jan 30 16:21:17 2008 : Debug:  tls: include_length = yes
Wed Jan 30 16:21:17 2008 : Debug:  tls: check_crl = no
Wed Jan 30 16:21:17 2008 : Debug:  tls: check_cert_cn = "(null)"
Wed Jan 30 16:21:17 2008 : Debug:  tls: cipher_list = "(null)"
Wed Jan 30 16:21:17 2008 : Debug:  tls: check_cert_issuer = "(null)"
Wed Jan 30 16:21:17 2008 : Info: rlm_eap_tls: Loading the certificate file as a chain
Wed Jan 30 16:21:17 2008 : Info: WARNING: rlm_eap_tls: Unable to set DH parameters.  DH cipher suites may not work!
Wed Jan 30 16:21:17 2008 : Debug: WARNING: Fix this by running the OpenSSL command listed in eap.conf
Wed Jan 30 16:21:17 2008 : Debug: rlm_eap: Loaded and initialized type tls
Wed Jan 30 16:21:17 2008 : Debug:  peap: default_eap_type = "mschapv2"
Wed Jan 30 16:21:17 2008 : Debug:  peap: copy_request_to_tunnel = no
Wed Jan 30 16:21:17 2008 : Debug:  peap: use_tunneled_reply = no
Wed Jan 30 16:21:17 2008 : Debug:  peap: proxy_tunneled_request_as_eap = no
Wed Jan 30 16:21:17 2008 : Debug: rlm_eap: Loaded and initialized type peap
Wed Jan 30 16:21:17 2008 : Debug:  mschapv2: with_ntdomain_hack = no
Wed Jan 30 16:21:17 2008 : Debug: rlm_eap: Loaded and initialized type mschapv2
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated eap (eap) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded preprocess 
Wed Jan 30 16:21:17 2008 : Debug:  preprocess: huntgroups = "/etc/freeradius/huntgroups"
Wed Jan 30 16:21:17 2008 : Debug:  preprocess: hints = "/etc/freeradius/hints"
Wed Jan 30 16:21:17 2008 : Debug:  preprocess: with_ascend_hack = no
Wed Jan 30 16:21:17 2008 : Debug:  preprocess: ascend_channels_per_line = 23
Wed Jan 30 16:21:17 2008 : Debug:  preprocess: with_ntdomain_hack = no
Wed Jan 30 16:21:17 2008 : Debug:  preprocess: with_specialix_jetstream_hack = no
Wed Jan 30 16:21:17 2008 : Debug:  preprocess: with_cisco_vsa_hack = no
Wed Jan 30 16:21:17 2008 : Debug:  preprocess: with_alvarion_vsa_hack = no
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated preprocess (preprocess) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded detail 
Wed Jan 30 16:21:17 2008 : Debug:  detail: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d"
Wed Jan 30 16:21:17 2008 : Debug:  detail: detailperm = 384
Wed Jan 30 16:21:17 2008 : Debug:  detail: dirperm = 493
Wed Jan 30 16:21:17 2008 : Debug:  detail: locking = no
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated detail (auth_log) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded attr_filter 
Wed Jan 30 16:21:17 2008 : Debug:  attr_filter: attrsfile = "/etc/freeradius/attrs"
Wed Jan 30 16:21:17 2008 : Error:  rlm_attr_filter: Authorize method will be deprecated.
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated attr_filter (attr_filter) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded realm 
Wed Jan 30 16:21:17 2008 : Debug:  realm: format = "suffix"
Wed Jan 30 16:21:17 2008 : Debug:  realm: delimiter = "@"
Wed Jan 30 16:21:17 2008 : Debug:  realm: ignore_default = no
Wed Jan 30 16:21:17 2008 : Debug:  realm: ignore_null = no
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated realm (suffix) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded files 
Wed Jan 30 16:21:17 2008 : Debug:  files: usersfile = "/etc/freeradius/users"
Wed Jan 30 16:21:17 2008 : Debug:  files: acctusersfile = "/etc/freeradius/acct_users"
Wed Jan 30 16:21:17 2008 : Debug:  files: preproxy_usersfile = "/etc/freeradius/preproxy_users"
Wed Jan 30 16:21:17 2008 : Debug:  files: compat = "no"
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated files (files) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded Acct-Unique-Session-Id 
Wed Jan 30 16:21:17 2008 : Debug:  acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated acct_unique (acct_unique) 
Wed Jan 30 16:21:17 2008 : Debug:  detail: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Wed Jan 30 16:21:17 2008 : Debug:  detail: detailperm = 384
Wed Jan 30 16:21:17 2008 : Debug:  detail: dirperm = 493
Wed Jan 30 16:21:17 2008 : Debug:  detail: locking = no
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated detail (detail) 
Wed Jan 30 16:21:17 2008 : Debug: Module: Loaded radutmp 
Wed Jan 30 16:21:17 2008 : Debug:  radutmp: filename = "/var/log/freeradius/radutmp"
Wed Jan 30 16:21:17 2008 : Debug:  radutmp: username = "%{User-Name}"
Wed Jan 30 16:21:17 2008 : Debug:  radutmp: case_sensitive = yes
Wed Jan 30 16:21:17 2008 : Debug:  radutmp: check_with_nas = yes
Wed Jan 30 16:21:17 2008 : Debug:  radutmp: perm = 384
Wed Jan 30 16:21:17 2008 : Debug:  radutmp: callerid = yes
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated radutmp (radutmp) 
Wed Jan 30 16:21:17 2008 : Debug:  detail: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d"
Wed Jan 30 16:21:17 2008 : Debug:  detail: detailperm = 384
Wed Jan 30 16:21:17 2008 : Debug:  detail: dirperm = 493
Wed Jan 30 16:21:17 2008 : Debug:  detail: locking = no
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated detail (pre_proxy_log) 
Wed Jan 30 16:21:17 2008 : Debug:  detail: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/post-proxy-detail-%Y%m%d"
Wed Jan 30 16:21:17 2008 : Debug:  detail: detailperm = 384
Wed Jan 30 16:21:17 2008 : Debug:  detail: dirperm = 493
Wed Jan 30 16:21:17 2008 : Debug:  detail: locking = no
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated detail (post_proxy_log) 
Wed Jan 30 16:21:17 2008 : Debug:  detail: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d"
Wed Jan 30 16:21:17 2008 : Debug:  detail: detailperm = 384
Wed Jan 30 16:21:17 2008 : Debug:  detail: dirperm = 493
Wed Jan 30 16:21:17 2008 : Debug:  detail: locking = no
Wed Jan 30 16:21:17 2008 : Debug: Module: Instantiated detail (reply_log) 
Wed Jan 30 16:21:17 2008 : Debug: Listening on authentication *:1812
Wed Jan 30 16:21:17 2008 : Debug: Listening on accounting *:1813
Wed Jan 30 16:21:17 2008 : Debug: Listening on proxy *:1814
Wed Jan 30 16:21:17 2008 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 192.168.2.28:1032, id=0, length=184
	Message-Authenticator = 0x95738e03d1fb1c0ceba98dbdf1ab912f
	Service-Type = Framed-User
	User-Name = "aaa"
	Framed-MTU = 1488
	Called-Station-Id = "00-15-E9-AE-B2-BF:WLAN"
	Calling-Station-Id = "00-17-9A-82-C7-7B"
	NAS-Identifier = "WLAN Access Point"
	NAS-Port-Type = Wireless-802.11
	Connect-Info = "CONNECT 54Mbps 802.11g"
	EAP-Message = 0x0200000801616161
	NAS-IP-Address = 192.168.2.28
	NAS-Port = 1
	NAS-Port-Id = "STA port # 1"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 0
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 0
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 0 length 8
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns notfound for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 0
Wed Jan 30 16:21:23 2008 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 0
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jan 30 16:21:23 2008 : Debug: auth: type "EAP"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP Identity
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: processing type tls
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: Initiate
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: Start returned 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 0
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns handled for request 0
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns handled) for request 0
Sending Access-Challenge of id 0 to 192.168.2.28 port 1032
	EAP-Message = 0x010100061920
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x5db289aaf7d6fa0ebe901707a31e963c
Wed Jan 30 16:21:23 2008 : Debug: Finished request 0
Wed Jan 30 16:21:23 2008 : Debug: Going to the next request
Wed Jan 30 16:21:23 2008 : Debug: --- Walking the entire request list ---
Wed Jan 30 16:21:23 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.2.28:1032, id=1, length=306
	Message-Authenticator = 0x47b000110073bbb08377c494b4bd16ef
	Service-Type = Framed-User
	User-Name = "aaa"
	Framed-MTU = 1488
	State = 0x5db289aaf7d6fa0ebe901707a31e963c
	Called-Station-Id = "00-15-E9-AE-B2-BF:WLAN"
	Calling-Station-Id = "00-17-9A-82-C7-7B"
	NAS-Identifier = "WLAN Access Point"
	NAS-Port-Type = Wireless-802.11
	Connect-Info = "CONNECT 54Mbps 802.11g"
	EAP-Message = 0x0201007019800000006616030100610100005d030147a087e3be36eef7e3c8558ad9836ef8545a57ad4ecd31cb1dee537f0217d0a0203285b3ca15b5bc19c4dc749138750ef06e349d1b28dc3864c757ae2d531b31bb001600040005000a000900640062000300060013001200630100
	NAS-IP-Address = 192.168.2.28
	NAS-Port = 1
	NAS-Port-Id = "STA port # 1"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 1
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 1
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 1 length 112
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns notfound for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 1
Wed Jan 30 16:21:23 2008 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 1
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jan 30 16:21:23 2008 : Debug: auth: type "EAP"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Request found, released from the list
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP/peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: processing type peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Authenticate
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: processing TLS
Wed Jan 30 16:21:23 2008 : Debug: rlm_eap_tls:  Length Included
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_verify returned 11 
Wed Jan 30 16:21:23 2008 : Debug:     (other): before/accept initialization 
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: before/accept initialization 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake [length 0061], ClientHello  
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: SSLv3 read client hello A 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake [length 004a], ServerHello  
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: SSLv3 write server hello A 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake [length 0694], Certificate  
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: SSLv3 write certificate A 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone  
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: SSLv3 write server done A 
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: SSLv3 flush data 
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: Need to read more data: SSLv3 read client certificate A
Wed Jan 30 16:21:23 2008 : Debug: In SSL Handshake Phase 
Wed Jan 30 16:21:23 2008 : Debug: In SSL Accept mode  
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_process returned 13 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: EAPTLS_HANDLED
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 1
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns handled for request 1
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns handled) for request 1
Sending Access-Challenge of id 1 to 192.168.2.28 port 1032
	EAP-Message = 0x0102040a19c0000006f1160301004a02000046030147a087e30fe5927afc6e913fc013cdd64421ade59e5e48e0081dec52246dfb5620406d860bab150a348618c2468f0782195f2b7bad6e69a157ff5bbefb9bf70b6e00040016030106940b00069000068d0002cd308202c930820232a003020102020102300d06092a864886f70d010104050030819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f7374311b301906035504031312436c69656e74206365
	EAP-Message = 0x7274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d301e170d3034303132353133323631305a170d3035303132343133323631305a30819b310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f73743119301706035504031310526f6f74206365727469666963617465311f301d06092a864886f70d0109011610726f6f74406578616d706c652e636f6d30819f300d06092a864886f70d010101050003
	EAP-Message = 0x818d0030818902818100dac525422bfedb082629a2cba44b3449c90d0ab462fb72c8434a782098863d7eb7d7e70028c2b7ad555a51cc756cf4fa1d7091615ab450d5289553ae6616aff014a55085d6b8fb4aee98638e426175cdd36c665c63cda177d34920eb30585edc8773999c2980f81ad4638bbbea1c82d054023db7ef24a3ec1c3f6241a903d7f30203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d0101040500038181007a2d921b1cf13bf2982a9178ec9ede6d88edc178a2e8bd40a0a06fb6f0769957884cd7084537083496fd184165293f583c8e8240eb68e042c94b15752e4c07e80d09
	EAP-Message = 0x779afa3dd55c24fa54ac292d77205d1c2477ed30d59f57caf9bd21ff2a8d16cc0911c50e4f295763fcb60efa3c3d2d0e43850f6e6fbe284902f6e83503650003ba308203b63082031fa003020102020100300d06092a864886f70d010104050030819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f7374311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c
	EAP-Message = 0x652e636f6d301e170d3034303132353133323630375a
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x5708202a97e43ae72b2b2c71ba80ada9
Wed Jan 30 16:21:23 2008 : Debug: Finished request 1
Wed Jan 30 16:21:23 2008 : Debug: Going to the next request
Wed Jan 30 16:21:23 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.2.28:1032, id=2, length=200
	Message-Authenticator = 0xc8c00d8115a81d1ef2d1975cd7b7815b
	Service-Type = Framed-User
	User-Name = "aaa"
	Framed-MTU = 1488
	State = 0x5708202a97e43ae72b2b2c71ba80ada9
	Called-Station-Id = "00-15-E9-AE-B2-BF:WLAN"
	Calling-Station-Id = "00-17-9A-82-C7-7B"
	NAS-Identifier = "WLAN Access Point"
	NAS-Port-Type = Wireless-802.11
	Connect-Info = "CONNECT 54Mbps 802.11g"
	EAP-Message = 0x020200061900
	NAS-IP-Address = 192.168.2.28
	NAS-Port = 1
	NAS-Port-Id = "STA port # 1"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 2
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 2
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 2 length 6
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns notfound for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 2
Wed Jan 30 16:21:23 2008 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 2
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jan 30 16:21:23 2008 : Debug: auth: type "EAP"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Request found, released from the list
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP/peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: processing type peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Authenticate
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: processing TLS
Wed Jan 30 16:21:23 2008 : Debug: rlm_eap_tls: Received EAP-TLS ACK message
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: ack handshake fragment handler
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_verify returned 1 
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_process returned 13 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: EAPTLS_HANDLED
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 2
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns handled for request 2
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns handled) for request 2
Sending Access-Challenge of id 2 to 192.168.2.28 port 1032
	EAP-Message = 0x010302f71900170d3036303132343133323630375a30819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f7374311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100d4c5b19724f164acf1ffb189db1c8fbff4f14396ea7cb1e90f78d69451725377895dfe52ccb99b41e8
	EAP-Message = 0x0ddeb58b127a943f4f58cbc562878192fbdc6fece9f871e7c130d35cf5188817e9b133249edd2a1c75d31043ae87553cec7a77ef26aa7d74281db9b77e17c6446c5dd9b188b43250ca0229963722a123a726b00b4027fd0203010001a381ff3081fc301d0603551d0e0416041468d36d3e1ee7bc9d5a057021c363da1365d1ade33081cc0603551d230481c43081c1801468d36d3e1ee7bc9d5a057021c363da1365d1ade3a181a5a481a230819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010
	EAP-Message = 0x060355040b13096c6f63616c686f7374311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d820100300c0603551d13040530030101ff300d06092a864886f70d01010405000381810033c00b66b1e579ef73a06798252dab8d5e5511fc00fd276d80d12f834777c6743fdc2743fca1507704e4bc0979e4f60ac3ad9ee83e6f347369229d1f77229ba2e982359da563024a00163dba6d6c986c0bad28af85132ff8f0d76501bf1b7c2dff658ce1e62c01997b6e64e3e8d4373354ce9912847651539063b85bbc5485c516030100040e000000
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xe6496d844bf69bdcdb1602289e985d94
Wed Jan 30 16:21:23 2008 : Debug: Finished request 2
Wed Jan 30 16:21:23 2008 : Debug: Going to the next request
Wed Jan 30 16:21:23 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.2.28:1032, id=3, length=386
	Message-Authenticator = 0x50eaac0ad7a2fe459a874501a98ac64b
	Service-Type = Framed-User
	User-Name = "aaa"
	Framed-MTU = 1488
	State = 0xe6496d844bf69bdcdb1602289e985d94
	Called-Station-Id = "00-15-E9-AE-B2-BF:WLAN"
	Calling-Station-Id = "00-17-9A-82-C7-7B"
	NAS-Identifier = "WLAN Access Point"
	NAS-Port-Type = Wireless-802.11
	Connect-Info = "CONNECT 54Mbps 802.11g"
	EAP-Message = 0x020300c01980000000b61603010086100000820080bac89a3ea71151d7ad09a69ff4ea8bc2951547167c8ea167fa9c3650285c4b106263fbff6b6b52bbbd6ec2c9eb4b9eb1a19d949ed96f2d81ee59cde3e388b26f6bc5285b71dcf6965e8ced6b59007420c47ac570b12d170c3bf9d3d3a133004a8e7fe37bf4fe4e27ed41982a8eec19682e20fa680c9bd41339e28477bce1d0581403010001011603010020fea0deb5a460a2665fc5b24deae99e753a3ba1a12c198817bb33422ec05227ee
	NAS-IP-Address = 192.168.2.28
	NAS-Port = 1
	NAS-Port-Id = "STA port # 1"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 3
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 3
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 3 length 192
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns notfound for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 3
Wed Jan 30 16:21:23 2008 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 3
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jan 30 16:21:23 2008 : Debug: auth: type "EAP"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Request found, released from the list
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP/peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: processing type peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Authenticate
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: processing TLS
Wed Jan 30 16:21:23 2008 : Debug: rlm_eap_tls:  Length Included
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_verify returned 11 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange  
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: SSLv3 read client key exchange A 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 ChangeCipherSpec [length 0001]  
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake [length 0010], Finished  
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: SSLv3 read finished A 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 ChangeCipherSpec [length 0001]  
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: SSLv3 write change cipher spec A 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake [length 0010], Finished  
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: SSLv3 write finished A 
Wed Jan 30 16:21:23 2008 : Debug:     TLS_accept: SSLv3 flush data 
Wed Jan 30 16:21:23 2008 : Debug:     (other): SSL negotiation finished successfully 
Wed Jan 30 16:21:23 2008 : Debug: SSL Connection Established 
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_process returned 13 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: EAPTLS_HANDLED
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 3
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns handled for request 3
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns handled) for request 3
Sending Access-Challenge of id 3 to 192.168.2.28 port 1032
	EAP-Message = 0x0104003119001403010001011603010020a562e906ef0e8bcc20bdf677cf9488ea9f72210f343b6b2764f4751c5ec28418
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x3882c9b17babca451a6ccc9e89a82d1e
Wed Jan 30 16:21:23 2008 : Debug: Finished request 3
Wed Jan 30 16:21:23 2008 : Debug: Going to the next request
Wed Jan 30 16:21:23 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.2.28:1032, id=4, length=200
	Message-Authenticator = 0x3d2571581a9de91e3544ff7994b3bc4c
	Service-Type = Framed-User
	User-Name = "aaa"
	Framed-MTU = 1488
	State = 0x3882c9b17babca451a6ccc9e89a82d1e
	Called-Station-Id = "00-15-E9-AE-B2-BF:WLAN"
	Calling-Station-Id = "00-17-9A-82-C7-7B"
	NAS-Identifier = "WLAN Access Point"
	NAS-Port-Type = Wireless-802.11
	Connect-Info = "CONNECT 54Mbps 802.11g"
	EAP-Message = 0x020400061900
	NAS-IP-Address = 192.168.2.28
	NAS-Port = 1
	NAS-Port-Id = "STA port # 1"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 4
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 4
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 4 length 6
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns notfound for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 4
Wed Jan 30 16:21:23 2008 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 4
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jan 30 16:21:23 2008 : Debug: auth: type "EAP"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Request found, released from the list
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP/peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: processing type peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Authenticate
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: processing TLS
Wed Jan 30 16:21:23 2008 : Debug: rlm_eap_tls: Received EAP-TLS ACK message
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: ack handshake is finished
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_verify returned 3 
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_process returned 3 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: EAPTLS_SUCCESS
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 4
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns handled for request 4
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns handled) for request 4
Sending Access-Challenge of id 4 to 192.168.2.28 port 1032
	EAP-Message = 0x0105002019001703010015a003beb410bd42441cf8049fc078150a1f62dc13a5
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x6472259ba53a52a47938bbb75daab0fc
Wed Jan 30 16:21:23 2008 : Debug: Finished request 4
Wed Jan 30 16:21:23 2008 : Debug: Going to the next request
Wed Jan 30 16:21:23 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.2.28:1032, id=5, length=225
	Message-Authenticator = 0xfa8d3e5d9994f240fd0ef4158a8c9246
	Service-Type = Framed-User
	User-Name = "aaa"
	Framed-MTU = 1488
	State = 0x6472259ba53a52a47938bbb75daab0fc
	Called-Station-Id = "00-15-E9-AE-B2-BF:WLAN"
	Calling-Station-Id = "00-17-9A-82-C7-7B"
	NAS-Identifier = "WLAN Access Point"
	NAS-Port-Type = Wireless-802.11
	Connect-Info = "CONNECT 54Mbps 802.11g"
	EAP-Message = 0x0205001f19001703010014f2094e78f3e975f48718cbb7d270c92bdeb7b1a5
	NAS-IP-Address = 192.168.2.28
	NAS-Port = 1
	NAS-Port-Id = "STA port # 1"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 5
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 5
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 5 length 31
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns notfound for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 5
Wed Jan 30 16:21:23 2008 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 5
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jan 30 16:21:23 2008 : Debug: auth: type "EAP"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Request found, released from the list
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP/peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: processing type peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Authenticate
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: processing TLS
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_verify returned 7 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: Done initial handshake
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_process returned 7 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: EAPTLS_OK
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Session established.  Decoding tunneled attributes.
  PEAP tunnel data in 0000: 01 61 61 61 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Identity - aaa
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Tunneled data is valid.
  PEAP: Got tunneled EAP-Message
	EAP-Message = 0x0205000801616161
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Got tunneled identity of aaa
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Setting default EAP type for tunneled EAP session.
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Setting User-Name to aaa
  PEAP: Sending tunneled request
	EAP-Message = 0x0205000801616161
	FreeRADIUS-Proxied-To = 127.0.0.1
	User-Name = "aaa"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 5
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/127.0.0.1/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/127.0.0.1/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 5
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 5 length 8
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 5
Wed Jan 30 16:21:23 2008 : Debug:     users: Matched entry aaa at line 85
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns ok for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 5
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 5
  PEAP: Got tunneled reply RADIUS code 0
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Calling authenticate in order to initiate tunneled EAP session.
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP Identity
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: processing type mschapv2
Wed Jan 30 16:21:23 2008 : Info: rlm_eap_mschapv2: Issuing Challenge
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns handled for request 5
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns handled) for request 5
Wed Jan 30 16:21:23 2008 : Debug:     PEAP: Cancelling proxy to realm xxx until the tunneled EAP session has been established
  PEAP: Processing from tunneled session code 0x80147040 11
	EAP-Message = 0x0106001d1a0106001810d705730f12a9595b41ac811cc23eab54616161
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x767993fd4ad4ebf861acdf27ec0a3a8e
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Got tunneled Access-Challenge
  PEAP tunnel data out 0000: 1a 01 06 00 18 10 d7 05 73 0f 12 a9 59 5b 41 ac 
  PEAP tunnel data out 0010: 81 1c c2 3e ab 54 61 61 61 
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 5
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns handled for request 5
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns handled) for request 5
Sending Access-Challenge of id 5 to 192.168.2.28 port 1032
	EAP-Message = 0x01060034190017030100291f8fadaf8be94d9469a30a78fcc2ae5503135fb3588b426d80237b5bb96cd390128aaaeab9af12f9f3
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x46e3664e4d1315184ed1a50e6dc819b3
Wed Jan 30 16:21:23 2008 : Debug: Finished request 5
Wed Jan 30 16:21:23 2008 : Debug: Going to the next request
Wed Jan 30 16:21:23 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.2.28:1032, id=6, length=279
	Message-Authenticator = 0xf24acb657d7e9f0ea425095ba74e861b
	Service-Type = Framed-User
	User-Name = "aaa"
	Framed-MTU = 1488
	State = 0x46e3664e4d1315184ed1a50e6dc819b3
	Called-Station-Id = "00-15-E9-AE-B2-BF:WLAN"
	Calling-Station-Id = "00-17-9A-82-C7-7B"
	NAS-Identifier = "WLAN Access Point"
	NAS-Port-Type = Wireless-802.11
	Connect-Info = "CONNECT 54Mbps 802.11g"
	EAP-Message = 0x020600551900170301004aba2524bee95d3df9b8b22f2250e4c4314a0e52353fd9037b6d96d8010f9811be0f665cae244749d9b0f10fa2d28d5660564fe27284e1f3d92a4222360cf90d70f12d193a481852d84bbe
	NAS-IP-Address = 192.168.2.28
	NAS-Port = 1
	NAS-Port-Id = "STA port # 1"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 6
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 6 length 85
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns notfound for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 6
Wed Jan 30 16:21:23 2008 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jan 30 16:21:23 2008 : Debug: auth: type "EAP"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Request found, released from the list
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP/peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: processing type peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Authenticate
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: processing TLS
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_verify returned 7 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: Done initial handshake
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_process returned 7 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: EAPTLS_OK
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Session established.  Decoding tunneled attributes.
  PEAP tunnel data in 0000: 1a 02 06 00 39 31 54 3b ff a8 dd c0 94 f4 dd 7d 
  PEAP tunnel data in 0010: 68 d5 83 58 3c ef 00 00 00 00 00 00 00 00 37 cc 
  PEAP tunnel data in 0020: 3c cd 31 b8 76 ad 62 b6 16 4c bb b4 7f 0f 87 d0 
  PEAP tunnel data in 0030: 4f 4c 21 56 a1 3d 00 61 61 61 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: EAP type mschapv2
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Tunneled data is valid.
  PEAP: Got tunneled EAP-Message
	EAP-Message = 0x0206003e1a0206003931543bffa8ddc094f4dd7d68d583583cef000000000000000037cc3ccd31b876ad62b6164cbbb47f0f87d04f4c2156a13d00616161
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Setting User-Name to aaa
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Adding old state with 76 79
  PEAP: Sending tunneled request
	EAP-Message = 0x0206003e1a0206003931543bffa8ddc094f4dd7d68d583583cef000000000000000037cc3ccd31b876ad62b6164cbbb47f0f87d04f4c2156a13d00616161
	FreeRADIUS-Proxied-To = 127.0.0.1
	User-Name = "aaa"
	State = 0x767993fd4ad4ebf861acdf27ec0a3a8e
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/127.0.0.1/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/127.0.0.1/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 6
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 6 length 62
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 6
Wed Jan 30 16:21:23 2008 : Debug:     users: Matched entry aaa at line 85
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 6
  PEAP: Got tunneled reply RADIUS code 0
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Calling authenticate in order to initiate tunneled EAP session.
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Request found, released from the list
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP/mschapv2
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: processing type mschapv2
Wed Jan 30 16:21:23 2008 : Debug:   Not-EAP proxy set.  Not composing EAP
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns handled for request 6
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns handled) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Tunneled authentication will be proxied to xxx
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Remembering to do EAP-MS-CHAP-V2 post-proxy.
Wed Jan 30 16:21:23 2008 : Debug:   Tunneled session will be proxied.  Not doing EAP.
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns handled for request 6
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns handled) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   Processing the pre-proxy section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group pre-proxy for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[pre-proxy]: calling files (rlm_files) for request 6
Wed Jan 30 16:21:23 2008 : Debug:     preproxy_users: Matched entry DEFAULT at line 33
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[pre-proxy]: returned from files (rlm_files) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[pre-proxy]: module "files" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[pre-proxy]: calling pre_proxy_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.2.28/pre-proxy-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.2.28/pre-proxy-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[pre-proxy]: returned from pre_proxy_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[pre-proxy]: module "pre_proxy_log" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group pre-proxy (returns ok) for request 6
Wed Jan 30 16:21:23 2008 : Debug:  proxy: creating 5002a8c0:1812
Wed Jan 30 16:21:23 2008 : Debug:  proxy: allocating 5002a8c0:1812 0
Sending Access-Request of id 0 to 192.168.2.80 port 1812
	User-Name = "aaa"
	NAS-IP-Address = 127.0.0.1
	MS-CHAP-Challenge = 0xd705730f12a9595b41ac811cc23eab54
	MS-CHAP2-Response = 0x0661543bffa8ddc094f4dd7d68d583583cef000000000000000037cc3ccd31b876ad62b6164cbbb47f0f87d04f4c2156a13d
	Proxy-State = 0x36
	Service-Type := BOSS4-HomeNet-VPN
Wed Jan 30 16:21:23 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Accept packet from host 192.168.2.80:1812, id=0, length=262
Wed Jan 30 16:21:23 2008 : Debug:  proxy: de-allocating 5002a8c0:1812 0
	Reply-Message = "ACCESS: GRANTED"
	Reply-Message = "AGREEMENT-ID: 587986"
	Framed-IP-Address = 192.168.2.56
	Framed-IP-Netmask = 255.255.255.255
	Framed-Protocol = PPP
	MS-CHAP2-Success = 0x00533d46344538343746453843323736414341453537393637343835343143384642303742334633303739
	MS-MPPE-Encryption-Policy = 0x00000001
	MS-MPPE-Encryption-Types = 0x00000006
	MS-MPPE-Recv-Key = 0x6b79482763300b5dece7d6ac717d8a21
	MS-MPPE-Send-Key = 0xe23347a646ed9a7a19693881f99ebb37
	Service-Type = Framed-User
	Reply-Message = "STATUS: 0.00000000"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the post-proxy section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group post-proxy for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[post-proxy]: calling post_proxy_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.2.28/post-proxy-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/post-proxy-detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.2.28/post-proxy-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[post-proxy]: returned from post_proxy_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[post-proxy]: module "post_proxy_log" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[post-proxy]: calling eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Passing reply from proxy back into the tunnel.
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Passing reply back for EAP-MS-CHAP-V2 0x801453f8 2
Wed Jan 30 16:21:23 2008 : Debug:   Processing the post-proxy section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group post-proxy for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[post-proxy]: calling post_proxy_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[post-proxy]: returned from post_proxy_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[post-proxy]: module "post_proxy_log" returns noop for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[post-proxy]: calling eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_mschapv2: Passing reply from proxy back into the tunnel 0x801453f8 2.
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_mschapv2: Authentication succeeded.
Wed Jan 30 16:21:23 2008 : Debug: MSCHAP Success 
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[post-proxy]: returned from eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[post-proxy]: module "eap" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group post-proxy (returns ok) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   POST-PROXY 2
Wed Jan 30 16:21:23 2008 : Debug:   Processing the post-auth section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group post-auth for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[post-auth]: calling reply_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/127.0.0.1/reply-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d expands to /var/log/freeradius/radacct/127.0.0.1/reply-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[post-auth]: returned from reply_log (rlm_detail) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[post-auth]: module "reply_log" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group post-auth (returns ok) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   POST-AUTH 2
  PEAP: Final reply from tunneled session code 11
	Reply-Message = "ACCESS: GRANTED"
	Reply-Message = "AGREEMENT-ID: 587986"
	Framed-IP-Address = 192.168.2.56
	Framed-IP-Netmask = 255.255.255.255
	Framed-Protocol = PPP
	Service-Type = Framed-User
	Reply-Message = "STATUS: 0.00000000"
	EAP-Message = 0x010700331a0306002e533d46344538343746453843323736414341453537393637343835343143384642303742334633303739
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x2e6847c5eb9a59e5f7cdbc3d8f082a8f
Wed Jan 30 16:21:23 2008 : Debug:  PEAP: Got reply 11
  PEAP: Processing from tunneled session code 0x80144e58 11
	Reply-Message = "ACCESS: GRANTED"
	Reply-Message = "AGREEMENT-ID: 587986"
	Framed-IP-Address = 192.168.2.56
	Framed-IP-Netmask = 255.255.255.255
	Framed-Protocol = PPP
	Service-Type = Framed-User
	Reply-Message = "STATUS: 0.00000000"
	EAP-Message = 0x010700331a0306002e533d46344538343746453843323736414341453537393637343835343143384642303742334633303739
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x2e6847c5eb9a59e5f7cdbc3d8f082a8f
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Got tunneled Access-Challenge
  PEAP tunnel data out 0000: 1a 03 06 00 2e 53 3d 46 34 45 38 34 37 46 45 38 
  PEAP tunnel data out 0010: 43 32 37 36 41 43 41 45 35 37 39 36 37 34 38 35 
  PEAP tunnel data out 0020: 34 31 43 38 46 42 30 37 42 33 46 33 30 37 39 
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Reply was handled
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[post-proxy]: returned from eap (rlm_eap) for request 6
Wed Jan 30 16:21:23 2008 : Debug:   modcall[post-proxy]: module "eap" returns ok for request 6
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group post-proxy (returns ok) for request 6
Sending Access-Challenge of id 6 to 192.168.2.28 port 1032
	EAP-Message = 0x0107004a1900170301003f3cbae61fe7c97a3500bb9b7aa65a7ebf4dfde9f637ba2a0f53ed7e91716066ab1dac2c590f7476689bf80aacf390629dd56a9d5e9df17b60819fc23938d207
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x8f6fded6f73f89f6c871aa78026be3fe
Wed Jan 30 16:21:23 2008 : Debug: Finished request 6
Wed Jan 30 16:21:23 2008 : Debug: Going to the next request
Wed Jan 30 16:21:23 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.2.28:1032, id=7, length=223
	Message-Authenticator = 0xdf76dfa6cb666f43cae3f55e797a4b95
	Service-Type = Framed-User
	User-Name = "aaa"
	Framed-MTU = 1488
	State = 0x8f6fded6f73f89f6c871aa78026be3fe
	Called-Station-Id = "00-15-E9-AE-B2-BF:WLAN"
	Calling-Station-Id = "00-17-9A-82-C7-7B"
	NAS-Identifier = "WLAN Access Point"
	NAS-Port-Type = Wireless-802.11
	Connect-Info = "CONNECT 54Mbps 802.11g"
	EAP-Message = 0x0207001d19001703010012156f46fa75527ef68f17bb704f8dba1532f7
	NAS-IP-Address = 192.168.2.28
	NAS-Port = 1
	NAS-Port-Id = "STA port # 1"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 7
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.2.28/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 7
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 7 length 29
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns notfound for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 7
Wed Jan 30 16:21:23 2008 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 7
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jan 30 16:21:23 2008 : Debug: auth: type "EAP"
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Request found, released from the list
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP/peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: processing type peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Authenticate
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: processing TLS
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_verify returned 7 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_tls: Done initial handshake
Wed Jan 30 16:21:23 2008 : Debug:   eaptls_process returned 7 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: EAPTLS_OK
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Session established.  Decoding tunneled attributes.
  PEAP tunnel data in 0000: 1a 03 
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: EAP type mschapv2
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap_peap: Tunneled data is valid.
  PEAP: Got tunneled EAP-Message
	EAP-Message = 0x020700061a03
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Setting User-Name to aaa
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Adding old state with 2e 68
  PEAP: Sending tunneled request
	EAP-Message = 0x020700061a03
	FreeRADIUS-Proxied-To = 127.0.0.1
	User-Name = "aaa"
	State = 0x2e6847c5eb9a59e5f7cdbc3d8f082a8f
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authorize section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authorize for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling auth_log (rlm_detail) for request 7
Wed Jan 30 16:21:23 2008 : Debug: radius_xlat:  '/var/log/freeradius/radacct/127.0.0.1/auth-detail-20080130'
Wed Jan 30 16:21:23 2008 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/127.0.0.1/auth-detail-20080130
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "auth_log" returns ok for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling attr_filter (rlm_attr_filter) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from attr_filter (rlm_attr_filter) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "attr_filter" returns noop for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "chap" returns noop for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "mschap" returns noop for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 7
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No '@' in User-Name = "aaa", looking up realm NULL
Wed Jan 30 16:21:23 2008 : Debug:     rlm_realm: No such realm "NULL"
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "suffix" returns noop for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: EAP packet type response id 7 length 6
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "eap" returns updated for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 7
Wed Jan 30 16:21:23 2008 : Debug:     users: Matched entry aaa at line 85
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "files" returns ok for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authorize]: module "pap" returns noop for request 7
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authorize (returns updated) for request 7
  PEAP: Got tunneled reply RADIUS code 0
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Calling authenticate in order to initiate tunneled EAP session.
Wed Jan 30 16:21:23 2008 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jan 30 16:21:23 2008 : Debug: modcall: entering group authenticate for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Request not found in the list
Wed Jan 30 16:21:23 2008 : Error: rlm_eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Failed in handler
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns invalid for request 7
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns invalid) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   PEAP: Can't handle the return code 4
Wed Jan 30 16:21:23 2008 : Debug:  rlm_eap: Handler failed in EAP/peap
Wed Jan 30 16:21:23 2008 : Debug:   rlm_eap: Failed in EAP select
Wed Jan 30 16:21:23 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 7
Wed Jan 30 16:21:23 2008 : Debug:   modcall[authenticate]: module "eap" returns invalid for request 7
Wed Jan 30 16:21:23 2008 : Debug: modcall: leaving group authenticate (returns invalid) for request 7
Wed Jan 30 16:21:23 2008 : Debug: auth: Failed to validate the user.
Wed Jan 30 16:21:23 2008 : Debug: Delaying request 7 for 1 seconds
Wed Jan 30 16:21:23 2008 : Debug: Finished request 7
Wed Jan 30 16:21:23 2008 : Debug: Going to the next request
Wed Jan 30 16:21:23 2008 : Debug: Waking up in 6 seconds...