EAP-PEAP-MS-CHAPv2: MS-CHAPv2 attributes discarded after proxying
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...
This archive was generated by a fusion of
Pipermail (Mailman edition) and
MHonArc.