[mschap] ERROR: User-Name (RC24558\jojo) is not the same as MS-CHAP Name (jojo) from EAP-MSCHAPv2
scoth
scoth at rcsd.ms
Mon Sep 26 22:51:53 CEST 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 at 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-is-not-the-same-as-MS-CHAP-Name-jojo-from-EAP-MSCHAPv2-tp4842882p4842882.html
Sent from the FreeRadius - User mailing list archive at Nabble.com.
More information about the Freeradius-Users
mailing list