[mschap] ERROR: User-Name (RC24558\jojo) is not the same as MS-CHAP Name (jojo) from EAP-MSCHAPv2

26 Sep 2011

      I'm hoping someone can help me here.  I've been working for a few days now
trying to figure out what is wrong.  I'm trying to use FreeRadius to
authenticate wireless users.  Apple devices and Windows 7 logs in fine. It
seems these devices send just the username/password.  XP is giving me the
problems.  I have a XP SP3 laptop setup for automatic join of the wireless
network testing. The wireless connection is using WPA - TKIP, PEAP,
MSCHAPv2, Enable Fast Reconnect, Automatically use my Windows logon
name/password, connect to this network automatically. 
I'm testing this way because we eventually will let teachers and students
bring their own laptops and connect to the wireless network.  Going
one-to-one for each student having a laptop is still not affordable. 

I will post my logs.  It seems I can get the user jojo (test user) to
connect and then authorize to ldap. Then authenticate to ldap but once the
eap tunnel is build i get the error. 
[mschap] ERROR: User-Name (RC24558\jojo) is not the same as MS-CHAP Name
(jojo) from EAP-MSCHAPv2 

Thanks for anyone giving me your time on this. 

Here is my log: 

[root@rh6dev sbin]# ./radiusd -XXX 
Mon Sep 26 09:18:24 2011 : Info: FreeRADIUS Version 2.1.11, for host
x86_64-unknown-linux-gnu, built on Jul 19 2011 at 10:04:23 
Mon Sep 26 09:18:24 2011 : Info: Copyright (C) 1999-2009 The FreeRADIUS
server project and contributors. 
Mon Sep 26 09:18:24 2011 : Info: There is NO warranty; not even for
MERCHANTABILITY or FITNESS FOR A 
Mon Sep 26 09:18:24 2011 : Info: PARTICULAR PURPOSE. 
Mon Sep 26 09:18:24 2011 : Info: You may redistribute copies of FreeRADIUS
under the terms of the 
Mon Sep 26 09:18:24 2011 : Info: GNU General Public License v2. 
Mon Sep 26 09:18:24 2011 : Info: Starting - reading configuration files ... 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/radiusd.conf 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/proxy.conf 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/clients.conf 
Mon Sep 26 09:18:24 2011 : Debug: including files in directory
/usr/local/etc/raddb/modules/ 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/pap 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/mschap 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/sqlcounter_expire_on_login 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/ntlm_auth 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/expiration 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/always 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/otp 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/acct_unique 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/preprocess 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/linelog 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/soh 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/radutmp 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/dynamic_clients 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/policy 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/echo 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/logintime 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/attr_filter 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/strip_off_domain 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/unix 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/ldap.orig 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/sradutmp 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/expr 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/perl 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/inner-eap 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/krb5 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/ippool 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/exec 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/attr_rewrite 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/replicate 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/wimax 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/detail.example.com 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/digest 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/mac2vlan 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/sql_log 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/mac2ip 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/detail 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/ldap 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/rediswho 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/counter 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/chap 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/opendirectory 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/pam 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/realm 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/checkval 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/detail.log 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/smbpasswd 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/cui 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/files 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/etc_group 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/redis 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/passwd 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/smsotp 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/eap.conf 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/policy.conf 
Mon Sep 26 09:18:24 2011 : Debug: including files in directory
/usr/local/etc/raddb/sites-enabled/ 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/sites-enabled/control-socket 
Mon Sep 26 09:18:24 2011 : Debug: including configuration file
/usr/local/etc/raddb/sites-enabled/inner-tunnel 
Mon Sep 26 09:18:24 2011 : Debug: main { 
Mon Sep 26 09:18:24 2011 : Debug: allow_core_dumps = no 
Mon Sep 26 09:18:24 2011 : Debug: } 
Mon Sep 26 09:18:24 2011 : Debug: including dictionary file
/usr/local/etc/raddb/dictionary 
Mon Sep 26 09:18:24 2011 : Debug: main { 
Mon Sep 26 09:18:24 2011 : Debug: name = "radiusd" 
Mon Sep 26 09:18:24 2011 : Debug: prefix = "/usr/local" 
Mon Sep 26 09:18:24 2011 : Debug: localstatedir = "/usr/local/var" 
Mon Sep 26 09:18:24 2011 : Debug: sbindir = "/usr/local/sbin" 
Mon Sep 26 09:18:24 2011 : Debug: logdir = "/usr/local/var/log/radius" 
Mon Sep 26 09:18:24 2011 : Debug: run_dir = "/usr/local/var/run/radiusd" 
Mon Sep 26 09:18:24 2011 : Debug: libdir = "/usr/local/lib" 
Mon Sep 26 09:18:24 2011 : Debug: radacctdir =
"/usr/local/var/log/radius/radacct" 
Mon Sep 26 09:18:24 2011 : Debug: hostname_lookups = no 
Mon Sep 26 09:18:24 2011 : Debug: max_request_time = 30 
Mon Sep 26 09:18:24 2011 : Debug: cleanup_delay = 5 
Mon Sep 26 09:18:24 2011 : Debug: max_requests = 1024 
Mon Sep 26 09:18:24 2011 : Debug: pidfile =
"/usr/local/var/run/radiusd/radiusd.pid" 
Mon Sep 26 09:18:24 2011 : Debug: checkrad = "/usr/local/sbin/checkrad" 
Mon Sep 26 09:18:24 2011 : Debug: debug_level = 0 
Mon Sep 26 09:18:24 2011 : Debug: proxy_requests = yes 
Mon Sep 26 09:18:24 2011 : Debug:  log { 
Mon Sep 26 09:18:24 2011 : Debug: stripped_names = no 
Mon Sep 26 09:18:24 2011 : Debug: auth = no 
Mon Sep 26 09:18:24 2011 : Debug: auth_badpass = no 
Mon Sep 26 09:18:24 2011 : Debug: auth_goodpass = no 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug:  security { 
Mon Sep 26 09:18:24 2011 : Debug: max_attributes = 200 
Mon Sep 26 09:18:24 2011 : Debug: reject_delay = 1 
Mon Sep 26 09:18:24 2011 : Debug: status_server = yes 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug: } 
Mon Sep 26 09:18:24 2011 : Debug: radiusd: #### Loading Realms and Home
Servers #### 
Mon Sep 26 09:18:24 2011 : Debug:  proxy server { 
Mon Sep 26 09:18:24 2011 : Debug: retry_delay = 5 
Mon Sep 26 09:18:24 2011 : Debug: retry_count = 3 
Mon Sep 26 09:18:24 2011 : Debug: default_fallback = no 
Mon Sep 26 09:18:24 2011 : Debug: dead_time = 120 
Mon Sep 26 09:18:24 2011 : Debug: wake_all_if_all_dead = no 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug:  home_server localhost { 
Mon Sep 26 09:18:24 2011 : Debug: ipaddr = 127.0.0.1 
Mon Sep 26 09:18:24 2011 : Debug: port = 1812 
Mon Sep 26 09:18:24 2011 : Debug: type = "auth" 
Mon Sep 26 09:18:24 2011 : Debug: secret = "testing123" 
Mon Sep 26 09:18:24 2011 : Debug: response_window = 20 
Mon Sep 26 09:18:24 2011 : Debug: max_outstanding = 65536 
Mon Sep 26 09:18:24 2011 : Debug: require_message_authenticator = yes 
Mon Sep 26 09:18:24 2011 : Debug: zombie_period = 40 
Mon Sep 26 09:18:24 2011 : Debug: status_check = "status-server" 
Mon Sep 26 09:18:24 2011 : Debug: ping_interval = 30 
Mon Sep 26 09:18:24 2011 : Debug: check_interval = 30 
Mon Sep 26 09:18:24 2011 : Debug: num_answers_to_alive = 3 
Mon Sep 26 09:18:24 2011 : Debug: num_pings_to_alive = 3 
Mon Sep 26 09:18:24 2011 : Debug: revive_interval = 120 
Mon Sep 26 09:18:24 2011 : Debug: status_check_timeout = 4 
Mon Sep 26 09:18:24 2011 : Debug:   coa { 
Mon Sep 26 09:18:24 2011 : Debug: irt = 2 
Mon Sep 26 09:18:24 2011 : Debug: mrt = 16 
Mon Sep 26 09:18:24 2011 : Debug: mrc = 5 
Mon Sep 26 09:18:24 2011 : Debug: mrd = 30 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug:  home_server_pool my_auth_failover { 
Mon Sep 26 09:18:24 2011 : Debug: type = fail-over 
Mon Sep 26 09:18:24 2011 : Debug: home_server = localhost 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug:  realm example.com { 
Mon Sep 26 09:18:24 2011 : Debug: auth_pool = my_auth_failover 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug:  realm LOCAL { 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug:  realm ~.* { 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug: radiusd: #### Loading Clients #### 
Mon Sep 26 09:18:24 2011 : Debug:  client localhost { 
Mon Sep 26 09:18:24 2011 : Debug: ipaddr = 127.0.0.1 
Mon Sep 26 09:18:24 2011 : Debug: require_message_authenticator = no 
Mon Sep 26 09:18:24 2011 : Debug: secret = "testing123" 
Mon Sep 26 09:18:24 2011 : Debug: nastype = "other" 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug:  client 10.0.0.0/8 { 
Mon Sep 26 09:18:24 2011 : Debug: require_message_authenticator = no 
Mon Sep 26 09:18:24 2011 : Debug: secret = "testing123" 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug: radiusd: #### Instantiating modules #### 
Mon Sep 26 09:18:24 2011 : Debug:  instantiate { 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_exec, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_exec 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "exec" from
file /usr/local/etc/raddb/modules/exec 
Mon Sep 26 09:18:24 2011 : Debug:   exec { 
Mon Sep 26 09:18:24 2011 : Debug: wait = no 
Mon Sep 26 09:18:24 2011 : Debug: input_pairs = "request" 
Mon Sep 26 09:18:24 2011 : Debug: shell_escape = yes 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_expr, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_expr 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "expr" from
file /usr/local/etc/raddb/modules/expr 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_expiration, checking if
it's valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_expiration 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "expiration"
from file /usr/local/etc/raddb/modules/expiration 
Mon Sep 26 09:18:24 2011 : Debug:   expiration { 
Mon Sep 26 09:18:24 2011 : Debug: reply-message = "Password Has Expired  " 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_logintime, checking if
it's valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_logintime 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "logintime"
from file /usr/local/etc/raddb/modules/logintime 
Mon Sep 26 09:18:24 2011 : Debug:   logintime { 
Mon Sep 26 09:18:24 2011 : Debug: reply-message = "You are calling outside
your allowed timespan  " 
Mon Sep 26 09:18:24 2011 : Debug: minimum-timeout = 60 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug: radiusd: #### Loading Virtual Servers #### 
Mon Sep 26 09:18:24 2011 : Debug: server { # from file
/usr/local/etc/raddb/radiusd.conf 
Mon Sep 26 09:18:24 2011 : Debug:  modules { 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking authenticate {...} for
more modules to load 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_pap, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_pap 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "pap" from
file /usr/local/etc/raddb/modules/pap 
Mon Sep 26 09:18:24 2011 : Debug:   pap { 
Mon Sep 26 09:18:24 2011 : Debug: encryption_scheme = "auto" 
Mon Sep 26 09:18:24 2011 : Debug: auto_header = no 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_chap, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_chap 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "chap" from
file /usr/local/etc/raddb/modules/chap 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_mschap, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_mschap 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "mschap"
from file /usr/local/etc/raddb/modules/mschap 
Mon Sep 26 09:18:24 2011 : Debug:   mschap { 
Mon Sep 26 09:18:24 2011 : Debug: use_mppe = no 
Mon Sep 26 09:18:24 2011 : Debug: require_encryption = no 
Mon Sep 26 09:18:24 2011 : Debug: require_strong = no 
Mon Sep 26 09:18:24 2011 : Debug: with_ntdomain_hack = no 
Mon Sep 26 09:18:24 2011 : Debug: allow_retry = yes 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_digest, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_digest 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "digest"
from file /usr/local/etc/raddb/modules/digest 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_unix, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_unix 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "unix" from
file /usr/local/etc/raddb/modules/unix 
Mon Sep 26 09:18:24 2011 : Debug:   unix { 
Mon Sep 26 09:18:24 2011 : Debug: radwtmp =
"/usr/local/var/log/radius/radwtmp" 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_ldap, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_ldap 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "ldap" from
file /usr/local/etc/raddb/modules/ldap.orig 
Mon Sep 26 09:18:24 2011 : Debug:   ldap { 
Mon Sep 26 09:18:24 2011 : Debug: server = "127.0.0.1" 
Mon Sep 26 09:18:24 2011 : Debug: port = 389 
Mon Sep 26 09:18:24 2011 : Debug: password = "" 
Mon Sep 26 09:18:24 2011 : Debug: identity = "" 
Mon Sep 26 09:18:24 2011 : Debug: net_timeout = 1 
Mon Sep 26 09:18:24 2011 : Debug: timeout = 4 
Mon Sep 26 09:18:24 2011 : Debug: timelimit = 3 
Mon Sep 26 09:18:24 2011 : Debug: tls_mode = no 
Mon Sep 26 09:18:24 2011 : Debug: start_tls = no 
Mon Sep 26 09:18:24 2011 : Debug: tls_require_cert = "allow" 
Mon Sep 26 09:18:24 2011 : Debug:    tls { 
Mon Sep 26 09:18:24 2011 : Debug: start_tls = no 
Mon Sep 26 09:18:24 2011 : Debug: require_cert = "allow" 
Mon Sep 26 09:18:24 2011 : Debug:    } 
Mon Sep 26 09:18:24 2011 : Debug: basedn = "ou=Users,dc=rcsd" 
Mon Sep 26 09:18:24 2011 : Debug: filter =
"(uid=%{%{Stripped-User-Name}:-%{User-Name}})" 
Mon Sep 26 09:18:24 2011 : Debug: base_filter =
"(objectclass=radiusprofile)" 
Mon Sep 26 09:18:24 2011 : Debug: auto_header = no 
Mon Sep 26 09:18:24 2011 : Debug: access_attr = "uid" 
Mon Sep 26 09:18:24 2011 : Debug: access_attr_used_for_allow = yes 
Mon Sep 26 09:18:24 2011 : Debug: groupname_attribute = "cn" 
Mon Sep 26 09:18:24 2011 : Debug: groupmembership_filter =
"(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn})))" 
Mon Sep 26 09:18:24 2011 : Debug: dictionary_mapping =
"/usr/local/etc/raddb/ldap.attrmap" 
Mon Sep 26 09:18:24 2011 : Debug: ldap_debug = 0 
Mon Sep 26 09:18:24 2011 : Debug: ldap_connections_number = 5 
Mon Sep 26 09:18:24 2011 : Debug: compare_check_items = no 
Mon Sep 26 09:18:24 2011 : Debug: do_xlat = yes 
Mon Sep 26 09:18:24 2011 : Debug: set_auth_type = yes 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: Registering ldap_groupcmp for
Ldap-Group 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: Registering ldap_xlat with
xlat_name ldap 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: reading ldap<->radius mappings
from file /usr/local/etc/raddb/ldap.attrmap 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusCheckItem mapped to
RADIUS $GENERIC$ 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusReplyItem mapped to
RADIUS $GENERIC$ 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusAuthType mapped to
RADIUS Auth-Type 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusSimultaneousUse
mapped to RADIUS Simultaneous-Use 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusCalledStationId
mapped to RADIUS Called-Station-Id 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusCallingStationId
mapped to RADIUS Calling-Station-Id 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP lmPassword mapped to RADIUS
LM-Password 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP ntPassword mapped to RADIUS
NT-Password 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP sambaLmPassword mapped to
RADIUS LM-Password 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP sambaNtPassword mapped to
RADIUS NT-Password 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP dBCSPwd mapped to RADIUS
LM-Password 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP userPassword mapped to
RADIUS Password-With-Header 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS
SMB-Account-CTRL-TEXT 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusExpiration mapped to
RADIUS Expiration 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusNASIpAddress mapped
to RADIUS NAS-IP-Address 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusServiceType mapped to
RADIUS Service-Type 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFramedProtocol mapped
to RADIUS Framed-Protocol 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFramedIPAddress
mapped to RADIUS Framed-IP-Address 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFramedIPNetmask
mapped to RADIUS Framed-IP-Netmask 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFramedRoute mapped to
RADIUS Framed-Route 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFramedRouting mapped
to RADIUS Framed-Routing 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFilterId mapped to
RADIUS Filter-Id 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFramedMTU mapped to
RADIUS Framed-MTU 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFramedCompression
mapped to RADIUS Framed-Compression 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusLoginIPHost mapped to
RADIUS Login-IP-Host 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusLoginService mapped
to RADIUS Login-Service 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped
to RADIUS Login-TCP-Port 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusCallbackNumber mapped
to RADIUS Callback-Number 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusCallbackId mapped to
RADIUS Callback-Id 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFramedIPXNetwork
mapped to RADIUS Framed-IPX-Network 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusClass mapped to
RADIUS Class 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusSessionTimeout mapped
to RADIUS Session-Timeout 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusIdleTimeout mapped to
RADIUS Idle-Timeout 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusTerminationAction
mapped to RADIUS Termination-Action 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusLoginLATService
mapped to RADIUS Login-LAT-Service 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusLoginLATNode mapped
to RADIUS Login-LAT-Node 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped
to RADIUS Login-LAT-Group 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink
mapped to RADIUS Framed-AppleTalk-Link 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP
radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone
mapped to RADIUS Framed-AppleTalk-Zone 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusPortLimit mapped to
RADIUS Port-Limit 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusLoginLATPort mapped
to RADIUS Login-LAT-Port 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusReplyMessage mapped
to RADIUS Reply-Message 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusTunnelType mapped to
RADIUS Tunnel-Type 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusTunnelMediumType
mapped to RADIUS Tunnel-Medium-Type 
Mon Sep 26 09:18:24 2011 : Debug: rlm_ldap: LDAP radiusTunnelPrivateGroupId
mapped to RADIUS Tunnel-Private-Group-Id 
Mon Sep 26 09:18:24 2011 : Debug: conns: 0x161fbb0 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_eap, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_eap 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "eap" from
file /usr/local/etc/raddb/eap.conf 
Mon Sep 26 09:18:24 2011 : Debug:   eap { 
Mon Sep 26 09:18:24 2011 : Debug: default_eap_type = "md5" 
Mon Sep 26 09:18:24 2011 : Debug: timer_expire = 60 
Mon Sep 26 09:18:24 2011 : Debug: ignore_unknown_eap_types = no 
Mon Sep 26 09:18:24 2011 : Debug: cisco_accounting_username_bug = no 
Mon Sep 26 09:18:24 2011 : Debug: max_sessions = 4096 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to sub-module rlm_eap_md5 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating eap-md5 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to sub-module rlm_eap_leap 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating eap-leap 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to sub-module rlm_eap_gtc 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating eap-gtc 
Mon Sep 26 09:18:24 2011 : Debug:    gtc { 
Mon Sep 26 09:18:24 2011 : Debug: challenge = "Password: " 
Mon Sep 26 09:18:24 2011 : Debug: auth_type = "PAP" 
Mon Sep 26 09:18:24 2011 : Debug:    } 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to sub-module rlm_eap_tls 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating eap-tls 
Mon Sep 26 09:18:24 2011 : Debug:    tls { 
Mon Sep 26 09:18:24 2011 : Debug: rsa_key_exchange = no 
Mon Sep 26 09:18:24 2011 : Debug: dh_key_exchange = yes 
Mon Sep 26 09:18:24 2011 : Debug: rsa_key_length = 512 
Mon Sep 26 09:18:24 2011 : Debug: dh_key_length = 512 
Mon Sep 26 09:18:24 2011 : Debug: verify_depth = 0 
Mon Sep 26 09:18:24 2011 : Debug: CA_path = "/usr/local/etc/raddb/certs" 
Mon Sep 26 09:18:24 2011 : Debug: pem_file_type = yes 
Mon Sep 26 09:18:24 2011 : Debug: private_key_file =
"/usr/local/etc/raddb/certs/server.pem" 
Mon Sep 26 09:18:24 2011 : Debug: certificate_file =
"/usr/local/etc/raddb/certs/server.pem" 
Mon Sep 26 09:18:24 2011 : Debug: CA_file =
"/usr/local/etc/raddb/certs/ca.pem" 
Mon Sep 26 09:18:24 2011 : Debug: private_key_password = "whatever" 
Mon Sep 26 09:18:24 2011 : Debug: dh_file = "/usr/local/etc/raddb/certs/dh" 
Mon Sep 26 09:18:24 2011 : Debug: random_file =
"/usr/local/etc/raddb/certs/random" 
Mon Sep 26 09:18:24 2011 : Debug: fragment_size = 1024 
Mon Sep 26 09:18:24 2011 : Debug: include_length = yes 
Mon Sep 26 09:18:24 2011 : Debug: check_crl = no 
Mon Sep 26 09:18:24 2011 : Debug: cipher_list = "DEFAULT" 
Mon Sep 26 09:18:24 2011 : Debug: make_cert_command =
"/usr/local/etc/raddb/certs/bootstrap" 
Mon Sep 26 09:18:24 2011 : Debug:     cache { 
Mon Sep 26 09:18:24 2011 : Debug: enable = no 
Mon Sep 26 09:18:24 2011 : Debug: lifetime = 24 
Mon Sep 26 09:18:24 2011 : Debug: max_entries = 255 
Mon Sep 26 09:18:24 2011 : Debug:     } 
Mon Sep 26 09:18:24 2011 : Debug:     verify { 
Mon Sep 26 09:18:24 2011 : Debug:     } 
Mon Sep 26 09:18:24 2011 : Debug:     ocsp { 
Mon Sep 26 09:18:24 2011 : Debug: enable = no 
Mon Sep 26 09:18:24 2011 : Debug: override_cert_url = yes 
Mon Sep 26 09:18:24 2011 : Debug: url = "http://127.0.0.1/ocsp/" 
Mon Sep 26 09:18:24 2011 : Debug:     } 
Mon Sep 26 09:18:24 2011 : Debug:    } 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to sub-module rlm_eap_ttls 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating eap-ttls 
Mon Sep 26 09:18:24 2011 : Debug:    ttls { 
Mon Sep 26 09:18:24 2011 : Debug: default_eap_type = "md5" 
Mon Sep 26 09:18:24 2011 : Debug: copy_request_to_tunnel = no 
Mon Sep 26 09:18:24 2011 : Debug: use_tunneled_reply = no 
Mon Sep 26 09:18:24 2011 : Debug: virtual_server = "inner-tunnel" 
Mon Sep 26 09:18:24 2011 : Debug: include_length = yes 
Mon Sep 26 09:18:24 2011 : Debug:    } 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to sub-module rlm_eap_peap 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating eap-peap 
Mon Sep 26 09:18:24 2011 : Debug:    peap { 
Mon Sep 26 09:18:24 2011 : Debug: default_eap_type = "mschapv2" 
Mon Sep 26 09:18:24 2011 : Debug: copy_request_to_tunnel = yes 
Mon Sep 26 09:18:24 2011 : Debug: use_tunneled_reply = yes 
Mon Sep 26 09:18:24 2011 : Debug: proxy_tunneled_request_as_eap = no 
Mon Sep 26 09:18:24 2011 : Debug: virtual_server = "inner-tunnel" 
Mon Sep 26 09:18:24 2011 : Debug: soh = no 
Mon Sep 26 09:18:24 2011 : Debug:    } 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to sub-module
rlm_eap_mschapv2 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating eap-mschapv2 
Mon Sep 26 09:18:24 2011 : Debug:    mschapv2 { 
Mon Sep 26 09:18:24 2011 : Debug: with_ntdomain_hack = no 
Mon Sep 26 09:18:24 2011 : Debug: send_error = no 
Mon Sep 26 09:18:24 2011 : Debug:    } 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking authorize {...} for more
modules to load 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_preprocess, checking if
it's valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_preprocess 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "preprocess"
from file /usr/local/etc/raddb/modules/preprocess 
Mon Sep 26 09:18:24 2011 : Debug:   preprocess { 
Mon Sep 26 09:18:24 2011 : Debug: huntgroups =
"/usr/local/etc/raddb/huntgroups" 
Mon Sep 26 09:18:24 2011 : Debug: hints = "/usr/local/etc/raddb/hints" 
Mon Sep 26 09:18:24 2011 : Debug: with_ascend_hack = no 
Mon Sep 26 09:18:24 2011 : Debug: ascend_channels_per_line = 23 
Mon Sep 26 09:18:24 2011 : Debug: with_ntdomain_hack = no 
Mon Sep 26 09:18:24 2011 : Debug: with_specialix_jetstream_hack = no 
Mon Sep 26 09:18:24 2011 : Debug: with_cisco_vsa_hack = no 
Mon Sep 26 09:18:24 2011 : Debug: with_alvarion_vsa_hack = no 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_realm, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_realm 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "ntdomain"
from file /usr/local/etc/raddb/modules/realm 
Mon Sep 26 09:18:24 2011 : Debug:   realm ntdomain { 
Mon Sep 26 09:18:24 2011 : Debug: format = "prefix" 
Mon Sep 26 09:18:24 2011 : Debug: delimiter = "\" 
Mon Sep 26 09:18:24 2011 : Debug: ignore_default = no 
Mon Sep 26 09:18:24 2011 : Debug: ignore_null = no 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_files, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_files 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "files" from
file /usr/local/etc/raddb/modules/files 
Mon Sep 26 09:18:24 2011 : Debug:   files { 
Mon Sep 26 09:18:24 2011 : Debug: usersfile = "/usr/local/etc/raddb/users" 
Mon Sep 26 09:18:24 2011 : Debug: acctusersfile =
"/usr/local/etc/raddb/acct_users" 
Mon Sep 26 09:18:24 2011 : Debug: preproxy_usersfile =
"/usr/local/etc/raddb/preproxy_users" 
Mon Sep 26 09:18:24 2011 : Debug: compat = "no" 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking preacct {...} for more
modules to load 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_acct_unique, checking if
it's valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_acct_unique 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module
"acct_unique" from file /usr/local/etc/raddb/modules/acct_unique 
Mon Sep 26 09:18:24 2011 : Debug:   acct_unique { 
Mon Sep 26 09:18:24 2011 : Debug: key = "User-Name, Acct-Session-Id,
NAS-IP-Address, Client-IP-Address, NAS-Port" 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking accounting {...} for
more modules to load 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_detail, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_detail 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "detail"
from file /usr/local/etc/raddb/modules/detail 
Mon Sep 26 09:18:24 2011 : Debug:   detail { 
Mon Sep 26 09:18:24 2011 : Debug: detailfile =
"/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" 
Mon Sep 26 09:18:24 2011 : Debug: header = "%t" 
Mon Sep 26 09:18:24 2011 : Debug: detailperm = 384 
Mon Sep 26 09:18:24 2011 : Debug: dirperm = 493 
Mon Sep 26 09:18:24 2011 : Debug: locking = no 
Mon Sep 26 09:18:24 2011 : Debug: log_packet_header = no 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_radutmp, checking if it's
valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_radutmp 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module "radutmp"
from file /usr/local/etc/raddb/modules/radutmp 
Mon Sep 26 09:18:24 2011 : Debug:   radutmp { 
Mon Sep 26 09:18:24 2011 : Debug: filename =
"/usr/local/var/log/radius/radutmp" 
Mon Sep 26 09:18:24 2011 : Debug: username = "%{User-Name}" 
Mon Sep 26 09:18:24 2011 : Debug: case_sensitive = yes 
Mon Sep 26 09:18:24 2011 : Debug: check_with_nas = yes 
Mon Sep 26 09:18:24 2011 : Debug: perm = 384 
Mon Sep 26 09:18:24 2011 : Debug: callerid = yes 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:     (Loaded rlm_attr_filter, checking if
it's valid) 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Linked to module rlm_attr_filter 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module
"attr_filter.accounting_response" from file
/usr/local/etc/raddb/modules/attr_filter 
Mon Sep 26 09:18:24 2011 : Debug:   attr_filter
attr_filter.accounting_response { 
Mon Sep 26 09:18:24 2011 : Debug: attrsfile =
"/usr/local/etc/raddb/attrs.accounting_response" 
Mon Sep 26 09:18:24 2011 : Debug: key = "%{User-Name}" 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking session {...} for more
modules to load 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking post-proxy {...} for
more modules to load 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking post-auth {...} for more
modules to load 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Instantiating module
"attr_filter.access_reject" from file
/usr/local/etc/raddb/modules/attr_filter 
Mon Sep 26 09:18:24 2011 : Debug:   attr_filter attr_filter.access_reject { 
Mon Sep 26 09:18:24 2011 : Debug: attrsfile =
"/usr/local/etc/raddb/attrs.access_reject" 
Mon Sep 26 09:18:24 2011 : Debug: key = "%{User-Name}" 
Mon Sep 26 09:18:24 2011 : Debug:   } 
Mon Sep 26 09:18:24 2011 : Debug:  } # modules 
Mon Sep 26 09:18:24 2011 : Debug: } # server 
Mon Sep 26 09:18:24 2011 : Debug: server inner-tunnel { # from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel 
Mon Sep 26 09:18:24 2011 : Debug:  modules { 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking authenticate {...} for
more modules to load 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking authorize {...} for more
modules to load 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking session {...} for more
modules to load 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking post-proxy {...} for
more modules to load 
Mon Sep 26 09:18:24 2011 : Debug:  Module: Checking post-auth {...} for more
modules to load 
Mon Sep 26 09:18:24 2011 : Debug:  } # modules 
Mon Sep 26 09:18:24 2011 : Debug: } # server 
Mon Sep 26 09:18:24 2011 : Debug: radiusd: #### Opening IP addresses and
Ports #### 
Mon Sep 26 09:18:24 2011 : Debug: listen { 
Mon Sep 26 09:18:24 2011 : Debug: type = "auth" 
Mon Sep 26 09:18:24 2011 : Debug: ipaddr = * 
Mon Sep 26 09:18:24 2011 : Debug: port = 0 
Mon Sep 26 09:18:24 2011 : Debug: } 
Mon Sep 26 09:18:24 2011 : Debug: listen { 
Mon Sep 26 09:18:24 2011 : Debug: type = "acct" 
Mon Sep 26 09:18:24 2011 : Debug: ipaddr = * 
Mon Sep 26 09:18:24 2011 : Debug: port = 0 
Mon Sep 26 09:18:24 2011 : Debug: } 
Mon Sep 26 09:18:24 2011 : Debug: listen { 
Mon Sep 26 09:18:24 2011 : Debug: type = "control" 
Mon Sep 26 09:18:24 2011 : Debug:  listen { 
Mon Sep 26 09:18:24 2011 : Debug: socket =
"/usr/local/var/run/radiusd/radiusd.sock" 
Mon Sep 26 09:18:24 2011 : Debug:  } 
Mon Sep 26 09:18:24 2011 : Debug: } 
Mon Sep 26 09:18:24 2011 : Debug: listen { 
Mon Sep 26 09:18:24 2011 : Debug: type = "auth" 
Mon Sep 26 09:18:24 2011 : Debug: ipaddr = 127.0.0.1 
Mon Sep 26 09:18:24 2011 : Debug: port = 18120 
Mon Sep 26 09:18:24 2011 : Debug: } 
Mon Sep 26 09:18:24 2011 : Info:  ... adding new socket proxy address * port
57019 
Mon Sep 26 09:18:24 2011 : Debug: Listening on authentication address * port
1645 
Mon Sep 26 09:18:24 2011 : Debug: Listening on accounting address * port
1646 
Mon Sep 26 09:18:24 2011 : Debug: Listening on command file
/usr/local/var/run/radiusd/radiusd.sock 
Mon Sep 26 09:18:24 2011 : Debug: Listening on authentication address
127.0.0.1 port 18120 as server inner-tunnel 
Mon Sep 26 09:18:24 2011 : Debug: Listening on proxy address * port 1647 
Mon Sep 26 09:18:24 2011 : Info: Ready to process requests. 
rad_recv: Access-Request packet from host 10.0.14.36 port 1645, id=142,
length=137 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        Message-Authenticator = 0x10e3b4b217bfc29c1475f84171e6dbcb 
        EAP-Message = 0x0202001101524332343535385c6a6f6a6f 
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[preprocess] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[chap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[digest] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 2 length
17 
Mon Sep 26 09:18:30 2011 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns updated 
Mon Sep 26 09:18:30 2011 : Info: ++[files] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ldap] performing user authorization for
jojo 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand: %{Stripped-User-Name} ->
jojo 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand:
(uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=jojo) 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand: ou=Users,dc=rcsd ->
ou=Users,dc=rcsd 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_get_conn: Checking Id: 0 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_get_conn: Got Id: 0 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] attempting LDAP reconnection 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] (re)connect to 127.0.0.1:389,
authentication 0 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] bind as / to 127.0.0.1:389 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] waiting for bind result ... 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] Bind was successful 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] performing search in
ou=Users,dc=rcsd, with filter (uid=jojo) 
Mon Sep 26 09:18:30 2011 : Info: [ldap] checking if remote access for jojo
is allowed by uid 
Mon Sep 26 09:18:30 2011 : Info: [ldap] looking for check items in
directory... 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] userPassword ->
Password-With-Header == "{SSHA}II8f7AGFYlC1KCv9i1ciQO5U9qNG1RrG" 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] sambaNtPassword -> NT-Password ==
0x3530354139323739434644324639344336353839383035353143464445373335 
Mon Sep 26 09:18:30 2011 : Info: [ldap] looking for reply items in
directory... 
Mon Sep 26 09:18:30 2011 : Info: [ldap] user jojo authorized to use remote
access 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_release_conn: Release Id: 0 
Mon Sep 26 09:18:30 2011 : Info: ++[ldap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[expiration] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[logintime] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [pap] Normalizing NT-Password from hex
encoding 
Mon Sep 26 09:18:30 2011 : Info: [pap] Normalizing SSHA1-Password from
base64 encoding 
Mon Sep 26 09:18:30 2011 : Info: [pap] WARNING: Auth-Type already set.  Not
setting to PAP 
Mon Sep 26 09:18:30 2011 : Info: ++[pap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP Identity 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type md5 
Mon Sep 26 09:18:30 2011 : Debug: rlm_eap_md5: Issuing Challenge 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns handled 
Sending Access-Challenge of id 142 to 10.0.14.36 port 1645 
        EAP-Message = 0x010300160410198263449a37508833162c8ac44e5a51 
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x012a67f1012963b59928657b4c6fcae7 
Mon Sep 26 09:18:30 2011 : Info: Finished request 0. 
Mon Sep 26 09:18:30 2011 : Debug: Going to the next request 
Mon Sep 26 09:18:30 2011 : Debug: Waking up in 4.9 seconds. 
rad_recv: Access-Request packet from host 10.0.14.36 port 1645, id=143,
length=144 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        Message-Authenticator = 0x9c67381470e7af73494b8c783844ccf4 
        EAP-Message = 0x020300060319 
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        State = 0x012a67f1012963b59928657b4c6fcae7 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[preprocess] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[chap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[digest] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 3 length
6 
Mon Sep 26 09:18:30 2011 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns updated 
Mon Sep 26 09:18:30 2011 : Info: ++[files] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ldap] performing user authorization for
jojo 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand: %{Stripped-User-Name} ->
jojo 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand:
(uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=jojo) 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand: ou=Users,dc=rcsd ->
ou=Users,dc=rcsd 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_get_conn: Checking Id: 0 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_get_conn: Got Id: 0 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] performing search in
ou=Users,dc=rcsd, with filter (uid=jojo) 
Mon Sep 26 09:18:30 2011 : Info: [ldap] checking if remote access for jojo
is allowed by uid 
Mon Sep 26 09:18:30 2011 : Info: [ldap] looking for check items in
directory... 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] userPassword ->
Password-With-Header == "{SSHA}II8f7AGFYlC1KCv9i1ciQO5U9qNG1RrG" 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] sambaNtPassword -> NT-Password ==
0x3530354139323739434644324639344336353839383035353143464445373335 
Mon Sep 26 09:18:30 2011 : Info: [ldap] looking for reply items in
directory... 
Mon Sep 26 09:18:30 2011 : Info: [ldap] user jojo authorized to use remote
access 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_release_conn: Release Id: 0 
Mon Sep 26 09:18:30 2011 : Info: ++[ldap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[expiration] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[logintime] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [pap] Normalizing NT-Password from hex
encoding 
Mon Sep 26 09:18:30 2011 : Info: [pap] Normalizing SSHA1-Password from
base64 encoding 
Mon Sep 26 09:18:30 2011 : Info: [pap] WARNING: Auth-Type already set.  Not
setting to PAP 
Mon Sep 26 09:18:30 2011 : Info: ++[pap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] Request found, released from the list 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP NAK 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP-NAK asked for EAP-Type/peap 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type tls 
Mon Sep 26 09:18:30 2011 : Info: [tls] Initiate 
Mon Sep 26 09:18:30 2011 : Info: [tls] Start returned 1 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns handled 
Sending Access-Challenge of id 143 to 10.0.14.36 port 1645 
        EAP-Message = 0x010400061920 
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x012a67f1002e7eb59928657b4c6fcae7 
Mon Sep 26 09:18:30 2011 : Info: Finished request 1. 
Mon Sep 26 09:18:30 2011 : Debug: Going to the next request 
Mon Sep 26 09:18:30 2011 : Debug: Waking up in 4.9 seconds. 
rad_recv: Access-Request packet from host 10.0.14.36 port 1645, id=144,
length=225 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        Message-Authenticator = 0xa8235a77b76131d43120d86ed61dc623 
        EAP-Message =
0x0204005719800000004d16030100480100004403014e80897a12cbc8fd5ed3f727d61573e9cc4e6203f7c622352466a033db02b6d700001600040005000a0009006400620003000600130012006301000005ff01000100
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        State = 0x012a67f1002e7eb59928657b4c6fcae7 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[preprocess] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[chap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[digest] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 4 length
87 
Mon Sep 26 09:18:30 2011 : Info: [eap] Continuing tunnel setup. 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] Request found, released from the list 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP/peap 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type peap 
Mon Sep 26 09:18:30 2011 : Info: [peap] processing EAP-TLS 
Mon Sep 26 09:18:30 2011 : Debug:   TLS Length 77 
Mon Sep 26 09:18:30 2011 : Info: [peap] Length Included 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_verify returned 11 
Mon Sep 26 09:18:30 2011 : Info: [peap]     (other): before/accept
initialization 
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: before/accept
initialization 
Mon Sep 26 09:18:30 2011 : Info: [peap] <<< TLS 1.0 Handshake [length 0048],
ClientHello   
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: SSLv3 read client
hello A 
Mon Sep 26 09:18:30 2011 : Info: [peap] >>> TLS 1.0 Handshake [length 0031],
ServerHello   
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: SSLv3 write server
hello A 
Mon Sep 26 09:18:30 2011 : Info: [peap] >>> TLS 1.0 Handshake [length 085e],
Certificate   
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: SSLv3 write
certificate A 
Mon Sep 26 09:18:30 2011 : Info: [peap] >>> TLS 1.0 Handshake [length 0004],
ServerHelloDone   
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: SSLv3 write server
done A 
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: SSLv3 flush data 
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: Need to read more
data: SSLv3 read client certificate A 
Mon Sep 26 09:18:30 2011 : Debug: In SSL Handshake Phase 
Mon Sep 26 09:18:30 2011 : Debug: In SSL Accept mode   
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_process returned 13 
Mon Sep 26 09:18:30 2011 : Info: [peap] EAPTLS_HANDLED 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns handled 
Sending Access-Challenge of id 144 to 10.0.14.36 port 1645 
        EAP-Message =
0x0105040019c0000008a216030100310200002d03014e8089b6d200a56ce809bc4878ede8000777623ae97bde467adc01c47ff58f1d000004000005ff01000100160301085e0b00085a0008570003a6308203a23082028aa003020102020101300d06092a864886f70d0101040500308193310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c65204365727469666963617465204175
        EAP-Message =
0x74686f72697479301e170d3131303930383138353830365a170d3132303930373138353830365a307c310b3009060355040613024652310f300d0603550408130652616469757331153013060355040a130c4578616d706c6520496e632e312330210603550403131a4578616d706c65205365727665722043657274696669636174653120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d30820122300d06092a864886f70d01010105000382010f003082010a0282010100e4ff2f9b63285ff75dbd766d7b3d6f087510d315e13c260b2c73d9b6ef5f9966798c8523aa2af3ee6a9ec7415443d931da84d2b8748f86
        EAP-Message =
0x86960fc69424d37fc2a181928e203f2a3b3d653c9e625b691000f251e4f33cc2df588d2e97d0cbee194f4d28ef1d4fbf2d45de86c1539c4baa226348f896b8d103e805ff2eadb5f7d12bbbce8308c30b65295e4b56509402814dc4827efab54361ebb7b3a305fee7de90abb8d5bf4af7a12f36bf0e3e67c82177bd36a5f2527f30d82ff44ae6fe3febc256b3d3add88598e45e2b55727a7430008e4f3cad10cb60269fd17ccf0da53a4cea51030ed76d356eb9f605b1b42b0df8b2513c08602a1bbcb1f88cc91db99f0203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d010104050003820101008a0f
        EAP-Message =
0x27d8bc135a3012b7af033199562b962b4215261539176b55de2f8f5c42cd532d91f018c916ac168ae3b298884d3ce7767d078fbc9c1ed73bf973789f6ed5f73e6e5a39e4ae65f00794878c4f8e9ee2e7aa8607549cf40b3eef7e647e8d2dc2aefaffa98b7e8a25201dba8fa1db8e27a78fba99310a51fca5ca1609dcb736299095e7eb9d3f771732586c5894ca51091af5bb8c2069eff219f8ddec540ac1e848ea74e6a62a17eba925b8b3d07761ecfcb191385fbca8712a68176879646958e908e137258b571de151877e8ced15366ef571de2d47af6ffe66951bf56052576b9e99ab438b667df45a878cf99e3a82918fdf26f52001c59cf0e509b20e
        EAP-Message = 0x740004ab308204a73082038f 
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x012a67f1032f7eb59928657b4c6fcae7 
Mon Sep 26 09:18:30 2011 : Info: Finished request 2. 
Mon Sep 26 09:18:30 2011 : Debug: Going to the next request 
Mon Sep 26 09:18:30 2011 : Debug: Waking up in 4.9 seconds. 
rad_recv: Access-Request packet from host 10.0.14.36 port 1645, id=145,
length=144 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        Message-Authenticator = 0x128a1e759f92c4248df2d9ae3b901010 
        EAP-Message = 0x020500061900 
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        State = 0x012a67f1032f7eb59928657b4c6fcae7 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[preprocess] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[chap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[digest] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 5 length
6 
Mon Sep 26 09:18:30 2011 : Info: [eap] Continuing tunnel setup. 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] Request found, released from the list 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP/peap 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type peap 
Mon Sep 26 09:18:30 2011 : Info: [peap] processing EAP-TLS 
Mon Sep 26 09:18:30 2011 : Info: [peap] Received TLS ACK 
Mon Sep 26 09:18:30 2011 : Info: [peap] ACK handshake fragment handler 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_verify returned 1 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_process returned 13 
Mon Sep 26 09:18:30 2011 : Info: [peap] EAPTLS_HANDLED 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns handled 
Sending Access-Challenge of id 145 to 10.0.14.36 port 1645 
        EAP-Message =
0x010603fc1940a003020102020900ce34e34810f39fc0300d06092a864886f70d0101050500308193310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479301e170d3131303930383138353830365a170d3132303930373138353830365a308193310b3009060355040613024652310f300d0603550408130652616469757331
        EAP-Message =
0x12301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f7269747930820122300d06092a864886f70d01010105000382010f003082010a0282010100b723badaa3886218ee4187d712939b8d9c92a1747b5acf4e14c5f11317a6dfbd29dee31432e58738753625f088e369c2ca2601379d1872d9fe39c47b147b0cb3c99c2465b48197d14613b504e737d9db9a5025b3a7708febef7cb625c3ae10439010f185838ed1f1
        EAP-Message =
0x155a2d77de562a531f26214cedadb853d434e24cc404a4c19462d9ff224c7d7b6c5b18bb81b184cce1a81227cd1e241a984792a1cf8d310db502276f22ef198f7ab809d851057aa8b43ee236ece276ff117793806fa0c2f25b93de8c050ba5a4febdc2f3fa6d4dca02fb569db96a98bf37f3dd1f3e20968368c999cd148fb7bfe3c9c4458141ef310dc34a64c5b5843db0f893bc87f09af10203010001a381fb3081f8301d0603551d0e0416041459226d7362797c622ef4b17635053c962f52b3a03081c80603551d230481c03081bd801459226d7362797c622ef4b17635053c962f52b3a0a18199a48196308193310b300906035504061302465231
        EAP-Message =
0x0f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479820900ce34e34810f39fc0300c0603551d13040530030101ff300d06092a864886f70d010105050003820101001fe877f4ce00c41b0030442314a8ade36598b7ced780957a685113406cfac979cd8c9e246f734481ef32f2a3bad3874491d02ad2f77ac2196062ec11d01f92b356e3fc2471fb808423d319
        EAP-Message = 0x17f2104db9d2c871 
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x012a67f1022c7eb59928657b4c6fcae7 
Mon Sep 26 09:18:30 2011 : Info: Finished request 3. 
Mon Sep 26 09:18:30 2011 : Debug: Going to the next request 
Mon Sep 26 09:18:30 2011 : Debug: Waking up in 4.9 seconds. 
rad_recv: Access-Request packet from host 10.0.14.36 port 1645, id=146,
length=144 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        Message-Authenticator = 0x5dcb0fdadd08239b637df5b5c08de666 
        EAP-Message = 0x020600061900 
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        State = 0x012a67f1022c7eb59928657b4c6fcae7 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[preprocess] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[chap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[digest] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 6 length
6 
Mon Sep 26 09:18:30 2011 : Info: [eap] Continuing tunnel setup. 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] Request found, released from the list 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP/peap 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type peap 
Mon Sep 26 09:18:30 2011 : Info: [peap] processing EAP-TLS 
Mon Sep 26 09:18:30 2011 : Info: [peap] Received TLS ACK 
Mon Sep 26 09:18:30 2011 : Info: [peap] ACK handshake fragment handler 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_verify returned 1 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_process returned 13 
Mon Sep 26 09:18:30 2011 : Info: [peap] EAPTLS_HANDLED 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns handled 
Sending Access-Challenge of id 146 to 10.0.14.36 port 1645 
        EAP-Message =
0x010700bc19009b313887ca4ccd81e9b42c703b87cf0cb1a4c272474f5a83338897b5c4e7a1dfc901ff799406f67d5b33b9b7b1e885725bee7990b3b2764128241a615c1d37a72517b68c38ad8bc2887ec4b362da8c99fef4626ce3f6e4d019e59664f5ad2897fa091235485ce5f8d2788ff35f73770308ea8f9d04a328ff068f0d292c32e50d5973e0cf33f195ebde3905c5550e1379a37d43217172b170a59816d6d58036e437d4e23a1eda7fec65a01d7e4616030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x012a67f1052d7eb59928657b4c6fcae7 
Mon Sep 26 09:18:30 2011 : Info: Finished request 4. 
Mon Sep 26 09:18:30 2011 : Debug: Going to the next request 
Mon Sep 26 09:18:30 2011 : Debug: Waking up in 4.9 seconds. 
rad_recv: Access-Request packet from host 10.0.14.36 port 1645, id=147,
length=460 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        Message-Authenticator = 0xc799de7ca48efe8b95ad15af01fff452 
        EAP-Message =
0x020701401980000001361603010106100001020100de9f66dd971d4ed1b91c46d438543181542bab29b2fe26f6cb50bc6115cf0befcc1b651ea327f021c28fe6cedfef51a3c052d3ba6dff7b0901304d1c597b5186fb0733758dbc5ee7f43c5b8e74a1409c275000add661280c070580bda42cdf0690daa59af6646b012404f778dd95c1c7a9317fae4f54c30e726a2cb0db65cea0f00d2e38797080483befd59e037ef8bc75ec0f93f88c082082878eb2b35ef7ecbe269bbde2f966b6bc4c4c9b6fb43f66d9275958d5c35e2904efc246bda614fb404a9fa1b4783e694302a3cdc6574cc0c14d6023b87d97f84e4e40229fdc9e55d85dd4ce240ffda5
        EAP-Message =
0xa95a8ba5362a1af6b5beecf13629299908568d459af0ad141403010001011603010020d146e56e8ece6e02c646c8fa54c95fa9aae4e46c6fc11589c5f8b530d893dc90 
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        State = 0x012a67f1052d7eb59928657b4c6fcae7 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[preprocess] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[chap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[digest] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 7 length
253 
Mon Sep 26 09:18:30 2011 : Info: [eap] Continuing tunnel setup. 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] Request found, released from the list 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP/peap 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type peap 
Mon Sep 26 09:18:30 2011 : Info: [peap] processing EAP-TLS 
Mon Sep 26 09:18:30 2011 : Debug:   TLS Length 310 
Mon Sep 26 09:18:30 2011 : Info: [peap] Length Included 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_verify returned 11 
Mon Sep 26 09:18:30 2011 : Info: [peap] <<< TLS 1.0 Handshake [length 0106],
ClientKeyExchange   
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: SSLv3 read client
key exchange A 
Mon Sep 26 09:18:30 2011 : Info: [peap] <<< TLS 1.0 ChangeCipherSpec [length
0001]   
Mon Sep 26 09:18:30 2011 : Info: [peap] <<< TLS 1.0 Handshake [length 0010],
Finished   
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: SSLv3 read finished
A 
Mon Sep 26 09:18:30 2011 : Info: [peap] >>> TLS 1.0 ChangeCipherSpec [length
0001]   
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: SSLv3 write change
cipher spec A 
Mon Sep 26 09:18:30 2011 : Info: [peap] >>> TLS 1.0 Handshake [length 0010],
Finished   
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: SSLv3 write finished
A 
Mon Sep 26 09:18:30 2011 : Info: [peap]     TLS_accept: SSLv3 flush data 
Mon Sep 26 09:18:30 2011 : Info: [peap]     (other): SSL negotiation
finished successfully 
Mon Sep 26 09:18:30 2011 : Debug: SSL Connection Established 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_process returned 13 
Mon Sep 26 09:18:30 2011 : Info: [peap] EAPTLS_HANDLED 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns handled 
Sending Access-Challenge of id 147 to 10.0.14.36 port 1645 
        EAP-Message =
0x01080031190014030100010116030100200cb7df9ff454fef7de6975717eb852b3df0a34f046ae775c57eeace36c41cf9f 
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x012a67f104227eb59928657b4c6fcae7 
Mon Sep 26 09:18:30 2011 : Info: Finished request 5. 
Mon Sep 26 09:18:30 2011 : Debug: Going to the next request 
Mon Sep 26 09:18:30 2011 : Debug: Waking up in 4.9 seconds. 
rad_recv: Access-Request packet from host 10.0.14.36 port 1645, id=148,
length=144 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        Message-Authenticator = 0x55f77ac864bb3e2f4673aba670ab63ee 
        EAP-Message = 0x020800061900 
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        State = 0x012a67f104227eb59928657b4c6fcae7 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[preprocess] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[chap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[digest] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 8 length
6 
Mon Sep 26 09:18:30 2011 : Info: [eap] Continuing tunnel setup. 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] Request found, released from the list 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP/peap 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type peap 
Mon Sep 26 09:18:30 2011 : Info: [peap] processing EAP-TLS 
Mon Sep 26 09:18:30 2011 : Info: [peap] Received TLS ACK 
Mon Sep 26 09:18:30 2011 : Info: [peap] ACK handshake is finished 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_verify returned 3 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_process returned 3 
Mon Sep 26 09:18:30 2011 : Info: [peap] EAPTLS_SUCCESS 
Mon Sep 26 09:18:30 2011 : Info: [peap] Session established.  Decoding
tunneled attributes. 
Mon Sep 26 09:18:30 2011 : Info: [peap] Peap state TUNNEL ESTABLISHED 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns handled 
Sending Access-Challenge of id 148 to 10.0.14.36 port 1645 
        EAP-Message =
0x010900201900170301001551fd4d3fc3aae6886ccf2a0c4d7fb35a9ef0f18bcf 
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x012a67f107237eb59928657b4c6fcae7 
Mon Sep 26 09:18:30 2011 : Info: Finished request 6. 
Mon Sep 26 09:18:30 2011 : Debug: Going to the next request 
Mon Sep 26 09:18:30 2011 : Debug: Waking up in 4.9 seconds. 
rad_recv: Access-Request packet from host 10.0.14.36 port 1645, id=149,
length=178 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        Message-Authenticator = 0x01057955c90b0ae8feb7658bc951fa8a 
        EAP-Message =
0x020900281900170301001d3bcbbd9b33590050d24629d34fc88147b36f185759dd406a6d3223893b 
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        State = 0x012a67f107237eb59928657b4c6fcae7 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[preprocess] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[chap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[digest] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 9 length
40 
Mon Sep 26 09:18:30 2011 : Info: [eap] Continuing tunnel setup. 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] Request found, released from the list 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP/peap 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type peap 
Mon Sep 26 09:18:30 2011 : Info: [peap] processing EAP-TLS 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_verify returned 7 
Mon Sep 26 09:18:30 2011 : Info: [peap] Done initial handshake 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_process returned 7 
Mon Sep 26 09:18:30 2011 : Info: [peap] EAPTLS_OK 
Mon Sep 26 09:18:30 2011 : Info: [peap] Session established.  Decoding
tunneled attributes. 
Mon Sep 26 09:18:30 2011 : Info: [peap] Peap state WAITING FOR INNER
IDENTITY 
Mon Sep 26 09:18:30 2011 : Info: [peap] Identity - RC24558\jojo 
Mon Sep 26 09:18:30 2011 : Info: [peap] Got inner identity 'RC24558\jojo' 
Mon Sep 26 09:18:30 2011 : Info: [peap] Setting default EAP type for
tunneled EAP session. 
Mon Sep 26 09:18:30 2011 : Info: [peap] Got tunneled request 
        EAP-Message = 0x0209001101524332343535385c6a6f6a6f 
server  { 
Mon Sep 26 09:18:30 2011 : Info: [peap] Setting User-Name to RC24558\jojo 
Sending tunneled request 
        EAP-Message = 0x0209001101524332343535385c6a6f6a6f 
        FreeRADIUS-Proxied-To = 127.0.0.1 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
server inner-tunnel { 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[control] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 9 length
17 
Mon Sep 26 09:18:30 2011 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns updated 
Mon Sep 26 09:18:30 2011 : Info: ++[files] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ldap] performing user authorization for
jojo 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand: %{Stripped-User-Name} ->
jojo 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand:
(uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=jojo) 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand: ou=Users,dc=rcsd ->
ou=Users,dc=rcsd 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_get_conn: Checking Id: 0 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_get_conn: Got Id: 0 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] performing search in
ou=Users,dc=rcsd, with filter (uid=jojo) 
Mon Sep 26 09:18:30 2011 : Info: [ldap] checking if remote access for jojo
is allowed by uid 
Mon Sep 26 09:18:30 2011 : Info: [ldap] looking for check items in
directory... 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] userPassword ->
Password-With-Header == "{SSHA}II8f7AGFYlC1KCv9i1ciQO5U9qNG1RrG" 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] sambaNtPassword -> NT-Password ==
0x3530354139323739434644324639344336353839383035353143464445373335 
Mon Sep 26 09:18:30 2011 : Info: [ldap] looking for reply items in
directory... 
Mon Sep 26 09:18:30 2011 : Info: [ldap] user jojo authorized to use remote
access 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_release_conn: Release Id: 0 
Mon Sep 26 09:18:30 2011 : Info: ++[ldap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[expiration] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[logintime] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [pap] Normalizing NT-Password from hex
encoding 
Mon Sep 26 09:18:30 2011 : Info: [pap] Normalizing SSHA1-Password from
base64 encoding 
Mon Sep 26 09:18:30 2011 : Info: [pap] WARNING: Auth-Type already set.  Not
setting to PAP 
Mon Sep 26 09:18:30 2011 : Info: ++[pap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP Identity 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type mschapv2 
Mon Sep 26 09:18:30 2011 : Debug: rlm_eap_mschapv2: Issuing Challenge 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns handled 
} # server inner-tunnel 
Mon Sep 26 09:18:30 2011 : Info: [peap] Got tunneled reply code 11 
        EAP-Message =
0x010a00261a010a00211072e844cfde1393faca4e9cd22d2517ed524332343535385c6a6f6a6f 
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x2e162f4f2e1c35eccc0848a7af8693ad 
Mon Sep 26 09:18:30 2011 : Info: [peap] Got tunneled reply RADIUS code 11 
        EAP-Message =
0x010a00261a010a00211072e844cfde1393faca4e9cd22d2517ed524332343535385c6a6f6a6f 
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x2e162f4f2e1c35eccc0848a7af8693ad 
Mon Sep 26 09:18:30 2011 : Info: [peap] Got tunneled Access-Challenge 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns handled 
Sending Access-Challenge of id 149 to 10.0.14.36 port 1645 
        EAP-Message =
0x010a003d190017030100321792f8992de0d798730efec62ecb0740acf93865478ea83c9e6336c3a52bc2c11e40d6531d4d1afe9162657c37e759c13ec7 
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x012a67f106207eb59928657b4c6fcae7 
Mon Sep 26 09:18:30 2011 : Info: Finished request 7. 
Mon Sep 26 09:18:30 2011 : Debug: Going to the next request 
Mon Sep 26 09:18:30 2011 : Debug: Waking up in 4.9 seconds. 
rad_recv: Access-Request packet from host 10.0.14.36 port 1645, id=150,
length=224 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        Message-Authenticator = 0xdf7adb26e9e89137de8fc21d4f1a395e 
        EAP-Message =
0x020a00561900170301004b2364a5c487226a0de3b29cfeb4f9c7af4014e404e93a4810495e3cb659e0cafaedd49db8fea2b6db56099cdc0984a91bd22ea44305786530fabb32ef8ae3b02d63052ca72896168659b5dd
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        State = 0x012a67f106207eb59928657b4c6fcae7 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[preprocess] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[chap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[digest] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 10 length
86 
Mon Sep 26 09:18:30 2011 : Info: [eap] Continuing tunnel setup. 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] Request found, released from the list 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP/peap 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type peap 
Mon Sep 26 09:18:30 2011 : Info: [peap] processing EAP-TLS 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_verify returned 7 
Mon Sep 26 09:18:30 2011 : Info: [peap] Done initial handshake 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_process returned 7 
Mon Sep 26 09:18:30 2011 : Info: [peap] EAPTLS_OK 
Mon Sep 26 09:18:30 2011 : Info: [peap] Session established.  Decoding
tunneled attributes. 
Mon Sep 26 09:18:30 2011 : Info: [peap] Peap state phase2 
Mon Sep 26 09:18:30 2011 : Info: [peap] EAP type mschapv2 
Mon Sep 26 09:18:30 2011 : Info: [peap] Got tunneled request 
        EAP-Message =
0x020a003f1a020a003a31c6af5159a443456abed7a200f914b32000000000000000008e0db552067e6773741a27b5fa900f3995ed3e020ded66d9006a6f6a6f 
server  { 
Mon Sep 26 09:18:30 2011 : Info: [peap] Setting User-Name to RC24558\jojo 
Sending tunneled request 
        EAP-Message =
0x020a003f1a020a003a31c6af5159a443456abed7a200f914b32000000000000000008e0db552067e6773741a27b5fa900f3995ed3e020ded66d9006a6f6a6f 
        FreeRADIUS-Proxied-To = 127.0.0.1 
        User-Name = "RC24558\\jojo" 
        State = 0x2e162f4f2e1c35eccc0848a7af8693ad 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
server inner-tunnel { 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[control] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 10 length
63 
Mon Sep 26 09:18:30 2011 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns updated 
Mon Sep 26 09:18:30 2011 : Info: ++[files] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ldap] performing user authorization for
jojo 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand: %{Stripped-User-Name} ->
jojo 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand:
(uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=jojo) 
Mon Sep 26 09:18:30 2011 : Info: [ldap] expand: ou=Users,dc=rcsd ->
ou=Users,dc=rcsd 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_get_conn: Checking Id: 0 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_get_conn: Got Id: 0 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] performing search in
ou=Users,dc=rcsd, with filter (uid=jojo) 
Mon Sep 26 09:18:30 2011 : Info: [ldap] checking if remote access for jojo
is allowed by uid 
Mon Sep 26 09:18:30 2011 : Info: [ldap] looking for check items in
directory... 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] userPassword ->
Password-With-Header == "{SSHA}II8f7AGFYlC1KCv9i1ciQO5U9qNG1RrG" 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] sambaNtPassword -> NT-Password ==
0x3530354139323739434644324639344336353839383035353143464445373335 
Mon Sep 26 09:18:30 2011 : Info: [ldap] looking for reply items in
directory... 
Mon Sep 26 09:18:30 2011 : Info: [ldap] user jojo authorized to use remote
access 
Mon Sep 26 09:18:30 2011 : Debug:   [ldap] ldap_release_conn: Release Id: 0 
Mon Sep 26 09:18:30 2011 : Info: ++[ldap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[expiration] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[logintime] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [pap] Normalizing NT-Password from hex
encoding 
Mon Sep 26 09:18:30 2011 : Info: [pap] Normalizing SSHA1-Password from
base64 encoding 
Mon Sep 26 09:18:30 2011 : Info: [pap] WARNING: Auth-Type already set.  Not
setting to PAP 
Mon Sep 26 09:18:30 2011 : Info: ++[pap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] Request found, released from the list 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP/mschapv2 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type mschapv2 
Mon Sep 26 09:18:30 2011 : Info: [mschapv2] # Executing group from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel 
Mon Sep 26 09:18:30 2011 : Info: [mschapv2] +- entering group MS-CHAP {...} 
Mon Sep 26 09:18:30 2011 : Info: [mschap] No Cleartext-Password configured. 
Cannot create LM-Password. 
Mon Sep 26 09:18:30 2011 : Info: [mschap] Found NT-Password 
Mon Sep 26 09:18:30 2011 : Info: [mschap] ERROR: User-Name (RC24558\jojo) is
not the same as MS-CHAP Name (jojo) from EAP-MSCHAPv2 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns reject 
Mon Sep 26 09:18:30 2011 : Info: [eap] Freeing handler 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns reject 
Mon Sep 26 09:18:30 2011 : Info: Failed to authenticate the user. 
} # server inner-tunnel 
Mon Sep 26 09:18:30 2011 : Info: [peap] Got tunneled reply code 3 
        EAP-Message = 0x040a0004 
        Message-Authenticator = 0x00000000000000000000000000000000 
Mon Sep 26 09:18:30 2011 : Info: [peap] Got tunneled reply RADIUS code 3 
        EAP-Message = 0x040a0004 
        Message-Authenticator = 0x00000000000000000000000000000000 
Mon Sep 26 09:18:30 2011 : Info: [peap] Tunneled authentication was
rejected. 
Mon Sep 26 09:18:30 2011 : Info: [peap] FAILURE 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns handled 
Sending Access-Challenge of id 150 to 10.0.14.36 port 1645 
        EAP-Message =
0x010b00261900170301001b944643d51444d64e2acfa39f31f4d500d4c9671ee00bb2532b3067 
        Message-Authenticator = 0x00000000000000000000000000000000 
        State = 0x012a67f109217eb59928657b4c6fcae7 
Mon Sep 26 09:18:30 2011 : Info: Finished request 8. 
Mon Sep 26 09:18:30 2011 : Debug: Going to the next request 
Mon Sep 26 09:18:30 2011 : Debug: Waking up in 4.9 seconds. 
rad_recv: Access-Request packet from host 10.0.14.36 port 1645, id=151,
length=176 
        User-Name = "RC24558\\jojo" 
        Framed-MTU = 1400 
        Called-Station-Id = "0013.5ffa.57f0" 
        Calling-Station-Id = "0013.ceca.3fb6" 
        Service-Type = Login-User 
        Message-Authenticator = 0x7d8d32826fedff54623bb8f7c4b76818 
        EAP-Message =
0x020b00261900170301001bb32976eb7fbb6643e7c9fc5dee1e4ddcacc7e437fbb7d1a58cfcc2 
        NAS-Port-Type = Wireless-802.11 
        NAS-Port = 15159 
        State = 0x012a67f109217eb59928657b4c6fcae7 
        NAS-IP-Address = 10.0.14.36 
        NAS-Identifier = "ap" 
Mon Sep 26 09:18:30 2011 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authorize {...} 
Mon Sep 26 09:18:30 2011 : Info: ++[preprocess] returns ok 
Mon Sep 26 09:18:30 2011 : Info: ++[chap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[mschap] returns noop 
Mon Sep 26 09:18:30 2011 : Info: ++[digest] returns noop 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Looking up realm "RC24558" for
User-Name = "RC24558\jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Found realm "~.*" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Stripped-User-Name =
"jojo" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Adding Realm = "RC24558" 
Mon Sep 26 09:18:30 2011 : Info: [ntdomain] Authentication realm is LOCAL. 
Mon Sep 26 09:18:30 2011 : Info: ++[ntdomain] returns ok 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP packet type response id 11 length
38 
Mon Sep 26 09:18:30 2011 : Info: [eap] Continuing tunnel setup. 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns ok 
Mon Sep 26 09:18:30 2011 : Info: Found Auth-Type = EAP 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group authenticate {...} 
Mon Sep 26 09:18:30 2011 : Info: [eap] Request found, released from the list 
Mon Sep 26 09:18:30 2011 : Info: [eap] EAP/peap 
Mon Sep 26 09:18:30 2011 : Info: [eap] processing type peap 
Mon Sep 26 09:18:30 2011 : Info: [peap] processing EAP-TLS 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_verify returned 7 
Mon Sep 26 09:18:30 2011 : Info: [peap] Done initial handshake 
Mon Sep 26 09:18:30 2011 : Info: [peap] eaptls_process returned 7 
Mon Sep 26 09:18:30 2011 : Info: [peap] EAPTLS_OK 
Mon Sep 26 09:18:30 2011 : Info: [peap] Session established.  Decoding
tunneled attributes. 
Mon Sep 26 09:18:30 2011 : Info: [peap] Peap state send tlv failure 
Mon Sep 26 09:18:30 2011 : Info: [peap] Received EAP-TLV response. 
Mon Sep 26 09:18:30 2011 : Info: [peap]  The users session was previously
rejected: returning reject (again.) 
Mon Sep 26 09:18:30 2011 : Info: [peap]  *** This means you need to read the
PREVIOUS messages in the debug output 
Mon Sep 26 09:18:30 2011 : Info: [peap]  *** to find out the reason why the
user was rejected. 
Mon Sep 26 09:18:30 2011 : Info: [peap]  *** Look for "reject" or "fail". 
Those earlier messages will tell you. 
Mon Sep 26 09:18:30 2011 : Info: [peap]  *** what went wrong, and how to fix
the problem. 
Mon Sep 26 09:18:30 2011 : Info: [eap] Handler failed in EAP/peap 
Mon Sep 26 09:18:30 2011 : Info: [eap] Failed in EAP select 
Mon Sep 26 09:18:30 2011 : Info: ++[eap] returns invalid 
Mon Sep 26 09:18:30 2011 : Info: Failed to authenticate the user. 
Mon Sep 26 09:18:30 2011 : Info: Using Post-Auth-Type Reject 
Mon Sep 26 09:18:30 2011 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default 
Mon Sep 26 09:18:30 2011 : Info: +- entering group REJECT {...} 
Mon Sep 26 09:18:30 2011 : Info: [attr_filter.access_reject] expand:
%{User-Name} -> RC24558\jojo 
Mon Sep 26 09:18:30 2011 : Debug:  attr_filter: Matched entry DEFAULT at
line 11 
Mon Sep 26 09:18:30 2011 : Info: ++[attr_filter.access_reject] returns
updated 
Mon Sep 26 09:18:30 2011 : Info: Delaying reject of request 9 for 1 seconds 
Mon Sep 26 09:18:30 2011 : Debug: Going to the next request 
Mon Sep 26 09:18:30 2011 : Debug: Waking up in 0.9 seconds. 
Mon Sep 26 09:18:31 2011 : Info: Sending delayed reject for request 9 
Sending Access-Reject of id 151 to 10.0.14.36 port 1645 
        EAP-Message = 0x040b0004 
        Message-Authenticator = 0x00000000000000000000000000000000 
Mon Sep 26 09:18:31 2011 : Debug: Waking up in 3.9 seconds. 
Mon Sep 26 09:18:34 2011 : Debug: Waking up in 1.3 seconds. 
Mon Sep 26 09:18:35 2011 : Info: Cleaning up request 0 ID 142 with timestamp
+6 
Mon Sep 26 09:18:35 2011 : Info: Cleaning up request 1 ID 143 with timestamp
+6 
Mon Sep 26 09:18:35 2011 : Info: Cleaning up request 2 ID 144 with timestamp
+6 
Mon Sep 26 09:18:35 2011 : Info: Cleaning up request 3 ID 145 with timestamp
+6 
Mon Sep 26 09:18:35 2011 : Info: Cleaning up request 4 ID 146 with timestamp
+6 
Mon Sep 26 09:18:35 2011 : Info: Cleaning up request 5 ID 147 with timestamp
+6 
Mon Sep 26 09:18:35 2011 : Info: Cleaning up request 6 ID 148 with timestamp
+6 
Mon Sep 26 09:18:35 2011 : Info: Cleaning up request 7 ID 149 with timestamp
+6 
Mon Sep 26 09:18:35 2011 : Info: Cleaning up request 8 ID 150 with timestamp
+6 
Mon Sep 26 09:18:35 2011 : Debug: Waking up in 1.0 seconds. 
Mon Sep 26 09:18:36 2011 : Info: Cleaning up request 9 ID 151 with timestamp
+6 
Mon Sep 26 09:18:36 2011 : Debug: Waking up in 0.1 seconds. 
Mon Sep 26 09:18:36 2011 : Info: Cleaning up request 10 ID 152 with
timestamp +7 
Mon Sep 26 09:18:37 2011 : Info: Cleaning up request 11 ID 153 with
timestamp +8 
Mon Sep 26 09:18:37 2011 : Info: Cleaning up request 12 ID 154 with
timestamp +8 
Mon Sep 26 09:18:37 2011 : Info: Cleaning up request 13 ID 155 with
timestamp +8 
Mon Sep 26 09:18:37 2011 : Info: Cleaning up request 14 ID 156 with
timestamp +8 
Mon Sep 26 09:18:37 2011 : Info: Cleaning up request 15 ID 157 with
timestamp +8 
Mon Sep 26 09:18:37 2011 : Info: Cleaning up request 16 ID 158 with
timestamp +8 
Mon Sep 26 09:18:37 2011 : Info: Cleaning up request 17 ID 159 with
timestamp +8 
Mon Sep 26 09:18:37 2011 : Info: Cleaning up request 18 ID 160 with
timestamp +8 
Mon Sep 26 09:18:37 2011 : Debug: Waking up in 1.0 seconds. 
Mon Sep 26 09:18:38 2011 : Info: Cleaning up request 19 ID 161 with
timestamp +8 
Mon Sep 26 09:18:38 2011 : Debug: Waking up in 0.1 seconds. 
Mon Sep 26 09:18:38 2011 : Info: Cleaning up request 20 ID 162 with
timestamp +9 
Mon Sep 26 09:18:38 2011 : Info: Cleaning up request 21 ID 163 with
timestamp +9 
Mon Sep 26 09:18:38 2011 : Info: Cleaning up request 22 ID 164 with
timestamp +9 
Mon Sep 26 09:18:38 2011 : Info: Cleaning up request 23 ID 165 with
timestamp +9 
Mon Sep 26 09:18:38 2011 : Info: Cleaning up request 24 ID 166 with
timestamp +9 
Mon Sep 26 09:18:38 2011 : Info: Cleaning up request 25 ID 167 with
timestamp +9 
Mon Sep 26 09:18:38 2011 : Info: Cleaning up request 26 ID 168 with
timestamp +9 
Mon Sep 26 09:18:38 2011 : Info: Cleaning up request 27 ID 169 with
timestamp +9 
Mon Sep 26 09:18:38 2011 : Info: Cleaning up request 28 ID 170 with
timestamp +9 
Mon Sep 26 09:18:38 2011 : Debug: Waking up in 1.0 seconds. 
Mon Sep 26 09:18:39 2011 : Info: Cleaning up request 29 ID 171 with
timestamp +9 
Mon Sep 26 09:18:39 2011 : Info: Ready to process requests. 

--
View this message in context: http://freeradius.1045715.n5.nabble.com/mschap-ERROR-User-Name-RC24558-jojo-...
Sent from the FreeRadius - User mailing list archive at Nabble.com.

[mschap] ERROR: User-Name (RC24558\jojo) is not the same as MS-CHAP Name (jojo) from EAP-MSCHAPv2

scoth