Wed Sep 17 12:06:37 2014 : Info: radiusd: FreeRADIUS Version 2.2.5, for host x86_64-unknown-linux-gnu, built on Sep 15 2014 at 13:10:19
Wed Sep 17 12:06:37 2014 : Debug: Server was built with: 
Wed Sep 17 12:06:37 2014 : Debug:   accounting
Wed Sep 17 12:06:37 2014 : Debug:   authentication
Wed Sep 17 12:06:37 2014 : Debug:  WITH_DHCP
Wed Sep 17 12:06:37 2014 : Debug:  WITH_VMPS
Wed Sep 17 12:06:37 2014 : Debug: Server core libs:
Wed Sep 17 12:06:37 2014 : Debug:   ssl: OpenSSL 1.0.1f 6 Jan 2014
Wed Sep 17 12:06:37 2014 : Info: Copyright (C) 1999-2013 The FreeRADIUS server project and contributors.
Wed Sep 17 12:06:37 2014 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Wed Sep 17 12:06:37 2014 : Info: PARTICULAR PURPOSE.
Wed Sep 17 12:06:37 2014 : Info: You may redistribute copies of FreeRADIUS under the terms of the
Wed Sep 17 12:06:37 2014 : Info: GNU General Public License.
Wed Sep 17 12:06:37 2014 : Info: For more information about these matters, see the file named COPYRIGHT.
Wed Sep 17 12:06:37 2014 : Info: Starting - reading configuration files ...
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/radiusd.conf
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/proxy.conf
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/clients.conf
Wed Sep 17 12:06:37 2014 : Debug: including files in directory /usr/local/etc/raddb/modules/
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/detail.example.com
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/checkval
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/echo
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/pap
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/cui
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/krb5
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/smbpasswd
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/realm
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/sradutmp
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/linelog
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/detail.log
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/pam
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/attr_filter
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/otp
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/radutmp
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/ippool
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/logintime
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/inner-eap
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/detail
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/mac2vlan
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/sql_log
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/perl
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/unix
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/wimax
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/ldap
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/dhcp_sqlippool
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/sql/mysql/ippool-dhcp.conf
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/rediswho
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/dynamic_clients
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/digest
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/chap
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/expiration
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/sqlcounter_expire_on_login
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/files
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/mschap
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/passwd
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/policy
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/smsotp
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/preprocess
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/always
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/mac2ip
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/expr
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/exec
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/attr_rewrite
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/ntlm_auth
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/replicate
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/redis
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/radrelay
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/soh
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/opendirectory
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/counter
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/cache
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/acct_unique
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/modules/etc_group
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/eap.conf
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/policy.conf
Wed Sep 17 12:06:37 2014 : Debug: including files in directory /usr/local/etc/raddb/sites-enabled/
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/control-socket
Wed Sep 17 12:06:37 2014 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/default
Wed Sep 17 12:06:37 2014 : Debug: main {
Wed Sep 17 12:06:37 2014 : Debug: 	allow_core_dumps = no
Wed Sep 17 12:06:37 2014 : Debug: }
Wed Sep 17 12:06:37 2014 : Debug: including dictionary file /usr/local/etc/raddb/dictionary
Wed Sep 17 12:06:37 2014 : Debug: main {
Wed Sep 17 12:06:37 2014 : Debug: 	name = "radiusd"
Wed Sep 17 12:06:37 2014 : Debug: 	prefix = "/usr/local"
Wed Sep 17 12:06:37 2014 : Debug: 	localstatedir = "/usr/local/var"
Wed Sep 17 12:06:37 2014 : Debug: 	sbindir = "/usr/local/sbin"
Wed Sep 17 12:06:37 2014 : Debug: 	logdir = "/usr/local/var/log/radius"
Wed Sep 17 12:06:37 2014 : Debug: 	run_dir = "/usr/local/var/run/radiusd"
Wed Sep 17 12:06:37 2014 : Debug: 	libdir = "/usr/local/lib"
Wed Sep 17 12:06:37 2014 : Debug: 	radacctdir = "/usr/local/var/log/radius/radacct"
Wed Sep 17 12:06:37 2014 : Debug: 	hostname_lookups = no
Wed Sep 17 12:06:37 2014 : Debug: 	max_request_time = 30
Wed Sep 17 12:06:37 2014 : Debug: 	cleanup_delay = 5
Wed Sep 17 12:06:37 2014 : Debug: 	max_requests = 1024
Wed Sep 17 12:06:37 2014 : Debug: 	pidfile = "/usr/local/var/run/radiusd/radiusd.pid"
Wed Sep 17 12:06:37 2014 : Debug: 	checkrad = "/usr/local/sbin/checkrad"
Wed Sep 17 12:06:37 2014 : Debug: 	debug_level = 0
Wed Sep 17 12:06:37 2014 : Debug: 	proxy_requests = yes
Wed Sep 17 12:06:37 2014 : Debug:  log {
Wed Sep 17 12:06:37 2014 : Debug:  	stripped_names = no
Wed Sep 17 12:06:37 2014 : Debug:  	auth = no
Wed Sep 17 12:06:37 2014 : Debug:  	auth_badpass = no
Wed Sep 17 12:06:37 2014 : Debug:  	auth_goodpass = no
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug:  security {
Wed Sep 17 12:06:37 2014 : Debug:  	max_attributes = 200
Wed Sep 17 12:06:37 2014 : Debug:  	reject_delay = 1
Wed Sep 17 12:06:37 2014 : Debug:  	status_server = yes
Wed Sep 17 12:06:37 2014 : Debug:  	allow_vulnerable_openssl = yes
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug: }
Wed Sep 17 12:06:37 2014 : Debug: radiusd: #### Loading Realms and Home Servers ####
Wed Sep 17 12:06:37 2014 : Debug:  proxy server {
Wed Sep 17 12:06:37 2014 : Debug:  	retry_delay = 5
Wed Sep 17 12:06:37 2014 : Debug:  	retry_count = 3
Wed Sep 17 12:06:37 2014 : Debug:  	default_fallback = no
Wed Sep 17 12:06:37 2014 : Debug:  	dead_time = 120
Wed Sep 17 12:06:37 2014 : Debug:  	wake_all_if_all_dead = no
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug:  home_server localhost {
Wed Sep 17 12:06:37 2014 : Debug:  	ipaddr = 127.0.0.1
Wed Sep 17 12:06:37 2014 : Debug:  	port = 1812
Wed Sep 17 12:06:37 2014 : Debug:  	type = "auth"
Wed Sep 17 12:06:37 2014 : Debug:  	secret = "testing123"
Wed Sep 17 12:06:37 2014 : Debug:  	response_window = 20
Wed Sep 17 12:06:37 2014 : Debug:  	max_outstanding = 65536
Wed Sep 17 12:06:37 2014 : Debug:  	require_message_authenticator = yes
Wed Sep 17 12:06:37 2014 : Debug:  	zombie_period = 40
Wed Sep 17 12:06:37 2014 : Debug:  	status_check = "status-server"
Wed Sep 17 12:06:37 2014 : Debug:  	ping_interval = 30
Wed Sep 17 12:06:37 2014 : Debug:  	check_interval = 30
Wed Sep 17 12:06:37 2014 : Debug:  	num_answers_to_alive = 3
Wed Sep 17 12:06:37 2014 : Debug:  	num_pings_to_alive = 3
Wed Sep 17 12:06:37 2014 : Debug:  	revive_interval = 120
Wed Sep 17 12:06:37 2014 : Debug:  	status_check_timeout = 4
Wed Sep 17 12:06:37 2014 : Debug:   coa {
Wed Sep 17 12:06:37 2014 : Debug:   	irt = 2
Wed Sep 17 12:06:37 2014 : Debug:   	mrt = 16
Wed Sep 17 12:06:37 2014 : Debug:   	mrc = 5
Wed Sep 17 12:06:37 2014 : Debug:   	mrd = 30
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug:  home_server_pool my_auth_failover {
Wed Sep 17 12:06:37 2014 : Debug: 	type = fail-over
Wed Sep 17 12:06:37 2014 : Debug: 	home_server = localhost
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug:  realm example.com {
Wed Sep 17 12:06:37 2014 : Debug: 	auth_pool = my_auth_failover
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug:  realm LOCAL {
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug: radiusd: #### Loading Clients ####
Wed Sep 17 12:06:37 2014 : Debug:  client localhost {
Wed Sep 17 12:06:37 2014 : Debug:  	ipaddr = 127.0.0.1
Wed Sep 17 12:06:37 2014 : Debug:  	require_message_authenticator = no
Wed Sep 17 12:06:37 2014 : Debug:  	secret = "testing123"
Wed Sep 17 12:06:37 2014 : Debug:  	nastype = "other"
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug:  client 10.10.2.21 {
Wed Sep 17 12:06:37 2014 : Debug:  	require_message_authenticator = no
Wed Sep 17 12:06:37 2014 : Debug:  	secret = "testing123"
Wed Sep 17 12:06:37 2014 : Debug:  	shortname = "planex"
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug: radiusd: #### Instantiating modules ####
Wed Sep 17 12:06:37 2014 : Debug:  instantiate {
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_exec, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_exec
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "exec" from file /usr/local/etc/raddb/modules/exec
Wed Sep 17 12:06:37 2014 : Debug:   exec {
Wed Sep 17 12:06:37 2014 : Debug:   	wait = no
Wed Sep 17 12:06:37 2014 : Debug:   	input_pairs = "request"
Wed Sep 17 12:06:37 2014 : Debug:   	shell_escape = yes
Wed Sep 17 12:06:37 2014 : Debug:   	timeout = 10
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_expr, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_expr
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "expr" from file /usr/local/etc/raddb/modules/expr
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_expiration, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_expiration
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "expiration" from file /usr/local/etc/raddb/modules/expiration
Wed Sep 17 12:06:37 2014 : Debug:   expiration {
Wed Sep 17 12:06:37 2014 : Debug:   	reply-message = "Password Has Expired  "
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_logintime, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_logintime
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "logintime" from file /usr/local/etc/raddb/modules/logintime
Wed Sep 17 12:06:37 2014 : Debug:   logintime {
Wed Sep 17 12:06:37 2014 : Debug:   	reply-message = "You are calling outside your allowed timespan  "
Wed Sep 17 12:06:37 2014 : Debug:   	minimum-timeout = 60
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug: radiusd: #### Loading Virtual Servers ####
Wed Sep 17 12:06:37 2014 : Debug: server { # from file ?????
Wed Sep 17 12:06:37 2014 : Debug:  modules {
Wed Sep 17 12:06:37 2014 : Debug:   Module: Creating Auth-Type = NTLM
Wed Sep 17 12:06:37 2014 : Debug:   Module: Creating Auth-Type = digest
Wed Sep 17 12:06:37 2014 : Debug:   Module: Creating Post-Auth-Type = REJECT
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking authenticate {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "ntlm_auth" from file /usr/local/etc/raddb/modules/ntlm_auth
Wed Sep 17 12:06:37 2014 : Debug:   exec ntlm_auth {
Wed Sep 17 12:06:37 2014 : Debug:   	wait = yes
Wed Sep 17 12:06:37 2014 : Debug:   	program = "/usr/bin/ntlm_auth --request-nt-key --username=%{mschap:User-Name:-None} --domain=%{%{mschap:NT-Domain}:-wifilabs.local} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}"
Wed Sep 17 12:06:37 2014 : Debug:   	input_pairs = "request"
Wed Sep 17 12:06:37 2014 : Debug:   	shell_escape = yes
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_pap, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_pap
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "pap" from file /usr/local/etc/raddb/modules/pap
Wed Sep 17 12:06:37 2014 : Debug:   pap {
Wed Sep 17 12:06:37 2014 : Debug:   	encryption_scheme = "auto"
Wed Sep 17 12:06:37 2014 : Debug:   	auto_header = no
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_eap2, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_eap2
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "eap2" from file /usr/local/etc/raddb/eap.conf
Wed Sep 17 12:06:37 2014 : Debug:   eap2 {
Wed Sep 17 12:06:37 2014 : Debug:   	timer_expire = 60
Wed Sep 17 12:06:37 2014 : Debug:   	cisco_accounting_username_bug = no
Wed Sep 17 12:06:37 2014 : Debug:   	backend_auth = yes
Wed Sep 17 12:06:37 2014 : Debug:    tls {
Wed Sep 17 12:06:37 2014 : Debug:    	ca_cert = "/usr/local/etc/raddb/certs/ca.pem"
Wed Sep 17 12:06:37 2014 : Debug:    	server_cert = "/usr/local/etc/raddb/certs/server.pem"
Wed Sep 17 12:06:37 2014 : Debug:    	private_key_file = "/usr/local/etc/raddb/certs/server.key"
Wed Sep 17 12:06:37 2014 : Debug:    	private_key_password = "whatever"
Wed Sep 17 12:06:37 2014 : Debug:    	dh_file = "/usr/local/etc/raddb/certs/dh"
Wed Sep 17 12:06:37 2014 : Debug:    }
Wed Sep 17 12:06:37 2014 : Debug:    fast {
Wed Sep 17 12:06:37 2014 : Debug:    	pac_opaque_encr_key = "000102030405060708090a0b0c0d0e0f"
Wed Sep 17 12:06:37 2014 : Debug:    	eap_fast_a_id = "tjsys"
Wed Sep 17 12:06:37 2014 : Debug:    	eap_fast_a_id_info = "my_server"
Wed Sep 17 12:06:37 2014 : Debug:    	eap_fast_prov = 3
Wed Sep 17 12:06:37 2014 : Debug:    	pac_key_lifetime = 604800
Wed Sep 17 12:06:37 2014 : Debug:    	pac_key_refresh_time = 86400
Wed Sep 17 12:06:37 2014 : Debug:    }
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_chap, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_chap
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "chap" from file /usr/local/etc/raddb/modules/chap
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_mschap, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_mschap
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "mschap" from file /usr/local/etc/raddb/modules/mschap
Wed Sep 17 12:06:37 2014 : Debug:   mschap {
Wed Sep 17 12:06:37 2014 : Debug:   	use_mppe = yes
Wed Sep 17 12:06:37 2014 : Debug:   	require_encryption = no
Wed Sep 17 12:06:37 2014 : Debug:   	require_strong = no
Wed Sep 17 12:06:37 2014 : Debug:   	with_ntdomain_hack = yes
Wed Sep 17 12:06:37 2014 : Debug:   	ntlm_auth = "/usr/bin/ntlm_auth --request-nt-key --username=%{mschap:User-Name:-None} --domain=%{%{mschap:NT-Domain}:-wifilabs.local} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}"
Wed Sep 17 12:06:37 2014 : Debug:   	allow_retry = yes
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_digest, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_digest
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "digest" from file /usr/local/etc/raddb/modules/digest
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_unix, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_unix
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "unix" from file /usr/local/etc/raddb/modules/unix
Wed Sep 17 12:06:37 2014 : Debug:   unix {
Wed Sep 17 12:06:37 2014 : Debug:   	radwtmp = "/usr/local/var/log/radius/radwtmp"
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_eap, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_eap
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "eap" from file /usr/local/etc/raddb/eap.conf
Wed Sep 17 12:06:37 2014 : Debug:   eap {
Wed Sep 17 12:06:37 2014 : Debug:   	default_eap_type = "md5"
Wed Sep 17 12:06:37 2014 : Debug:   	timer_expire = 60
Wed Sep 17 12:06:37 2014 : Debug:   	ignore_unknown_eap_types = no
Wed Sep 17 12:06:37 2014 : Debug:   	cisco_accounting_username_bug = no
Wed Sep 17 12:06:37 2014 : Debug:   	max_sessions = 1024
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to sub-module rlm_eap_md5
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating eap-md5
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to sub-module rlm_eap_leap
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating eap-leap
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to sub-module rlm_eap_gtc
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating eap-gtc
Wed Sep 17 12:06:37 2014 : Debug:    gtc {
Wed Sep 17 12:06:37 2014 : Debug:    	challenge = "Password: "
Wed Sep 17 12:06:37 2014 : Debug:    	auth_type = "PAP"
Wed Sep 17 12:06:37 2014 : Debug:    }
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to sub-module rlm_eap_tls
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating eap-tls
Wed Sep 17 12:06:37 2014 : Debug:    tls {
Wed Sep 17 12:06:37 2014 : Debug:    	rsa_key_exchange = no
Wed Sep 17 12:06:37 2014 : Debug:    	dh_key_exchange = yes
Wed Sep 17 12:06:37 2014 : Debug:    	rsa_key_length = 512
Wed Sep 17 12:06:37 2014 : Debug:    	dh_key_length = 512
Wed Sep 17 12:06:37 2014 : Debug:    	verify_depth = 0
Wed Sep 17 12:06:37 2014 : Debug:    	CA_path = "/usr/local/etc/raddb/certs"
Wed Sep 17 12:06:37 2014 : Debug:    	pem_file_type = yes
Wed Sep 17 12:06:37 2014 : Debug:    	private_key_file = "/usr/local/etc/raddb/certs/server.pem"
Wed Sep 17 12:06:37 2014 : Debug:    	certificate_file = "/usr/local/etc/raddb/certs/server.pem"
Wed Sep 17 12:06:37 2014 : Debug:    	CA_file = "/usr/local/etc/raddb/certs/ca.pem"
Wed Sep 17 12:06:37 2014 : Debug:    	private_key_password = "whatever"
Wed Sep 17 12:06:37 2014 : Debug:    	dh_file = "/usr/local/etc/raddb/certs/dh"
Wed Sep 17 12:06:37 2014 : Debug:    	fragment_size = 1024
Wed Sep 17 12:06:37 2014 : Debug:    	include_length = yes
Wed Sep 17 12:06:37 2014 : Debug:    	check_crl = no
Wed Sep 17 12:06:37 2014 : Debug:    	cipher_list = "DEFAULT"
Wed Sep 17 12:06:37 2014 : Debug:    	make_cert_command = "/usr/local/etc/raddb/certs/bootstrap"
Wed Sep 17 12:06:37 2014 : Debug:    	ecdh_curve = "prime256v1"
Wed Sep 17 12:06:37 2014 : Debug:     cache {
Wed Sep 17 12:06:37 2014 : Debug:     	enable = no
Wed Sep 17 12:06:37 2014 : Debug:     	lifetime = 24
Wed Sep 17 12:06:37 2014 : Debug:     	max_entries = 255
Wed Sep 17 12:06:37 2014 : Debug:     }
Wed Sep 17 12:06:37 2014 : Debug:     verify {
Wed Sep 17 12:06:37 2014 : Debug:     }
Wed Sep 17 12:06:37 2014 : Debug:     ocsp {
Wed Sep 17 12:06:37 2014 : Debug:     	enable = no
Wed Sep 17 12:06:37 2014 : Debug:     	override_cert_url = yes
Wed Sep 17 12:06:37 2014 : Debug:     	url = "http://127.0.0.1/ocsp/"
Wed Sep 17 12:06:37 2014 : Debug:     	use_nonce = yes
Wed Sep 17 12:06:37 2014 : Debug:     	timeout = 0
Wed Sep 17 12:06:37 2014 : Debug:     	softfail = no
Wed Sep 17 12:06:37 2014 : Debug:     }
Wed Sep 17 12:06:37 2014 : Debug:    }
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to sub-module rlm_eap_ttls
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating eap-ttls
Wed Sep 17 12:06:37 2014 : Debug:    ttls {
Wed Sep 17 12:06:37 2014 : Debug:    	default_eap_type = "md5"
Wed Sep 17 12:06:37 2014 : Debug:    	copy_request_to_tunnel = no
Wed Sep 17 12:06:37 2014 : Debug:    	use_tunneled_reply = no
Wed Sep 17 12:06:37 2014 : Debug:    	virtual_server = "inner-tunnel"
Wed Sep 17 12:06:37 2014 : Debug:    	include_length = yes
Wed Sep 17 12:06:37 2014 : Debug:    }
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to sub-module rlm_eap_peap
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating eap-peap
Wed Sep 17 12:06:37 2014 : Debug:    peap {
Wed Sep 17 12:06:37 2014 : Debug:    	default_eap_type = "mschapv2"
Wed Sep 17 12:06:37 2014 : Debug:    	copy_request_to_tunnel = no
Wed Sep 17 12:06:37 2014 : Debug:    	use_tunneled_reply = no
Wed Sep 17 12:06:37 2014 : Debug:    	proxy_tunneled_request_as_eap = yes
Wed Sep 17 12:06:37 2014 : Debug:    	virtual_server = "inner-tunnel"
Wed Sep 17 12:06:37 2014 : Debug:    	soh = no
Wed Sep 17 12:06:37 2014 : Debug:    }
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to sub-module rlm_eap_mschapv2
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating eap-mschapv2
Wed Sep 17 12:06:37 2014 : Debug:    mschapv2 {
Wed Sep 17 12:06:37 2014 : Debug:    	with_ntdomain_hack = no
Wed Sep 17 12:06:37 2014 : Debug:    	send_error = no
Wed Sep 17 12:06:37 2014 : Debug:    }
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking authorize {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_preprocess, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_preprocess
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "preprocess" from file /usr/local/etc/raddb/modules/preprocess
Wed Sep 17 12:06:37 2014 : Debug:   preprocess {
Wed Sep 17 12:06:37 2014 : Debug:   	huntgroups = "/usr/local/etc/raddb/huntgroups"
Wed Sep 17 12:06:37 2014 : Debug:   	hints = "/usr/local/etc/raddb/hints"
Wed Sep 17 12:06:37 2014 : Debug:   	with_ascend_hack = no
Wed Sep 17 12:06:37 2014 : Debug:   	ascend_channels_per_line = 23
Wed Sep 17 12:06:37 2014 : Debug:   	with_ntdomain_hack = no
Wed Sep 17 12:06:37 2014 : Debug:   	with_specialix_jetstream_hack = no
Wed Sep 17 12:06:37 2014 : Debug:   	with_cisco_vsa_hack = no
Wed Sep 17 12:06:37 2014 : Debug:   	with_alvarion_vsa_hack = no
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug: reading pairlist file /usr/local/etc/raddb/huntgroups
Wed Sep 17 12:06:37 2014 : Debug: reading pairlist file /usr/local/etc/raddb/hints
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_realm, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_realm
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "suffix" from file /usr/local/etc/raddb/modules/realm
Wed Sep 17 12:06:37 2014 : Debug:   realm suffix {
Wed Sep 17 12:06:37 2014 : Debug:   	format = "suffix"
Wed Sep 17 12:06:37 2014 : Debug:   	delimiter = "@"
Wed Sep 17 12:06:37 2014 : Debug:   	ignore_default = no
Wed Sep 17 12:06:37 2014 : Debug:   	ignore_null = no
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_files, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_files
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "files" from file /usr/local/etc/raddb/modules/files
Wed Sep 17 12:06:37 2014 : Debug:   files {
Wed Sep 17 12:06:37 2014 : Debug:   	usersfile = "/usr/local/etc/raddb/users"
Wed Sep 17 12:06:37 2014 : Debug:   	acctusersfile = "/usr/local/etc/raddb/acct_users"
Wed Sep 17 12:06:37 2014 : Debug:   	preproxy_usersfile = "/usr/local/etc/raddb/preproxy_users"
Wed Sep 17 12:06:37 2014 : Debug:   	compat = "no"
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug: reading pairlist file /usr/local/etc/raddb/users
Wed Sep 17 12:06:37 2014 : Debug: reading pairlist file /usr/local/etc/raddb/acct_users
Wed Sep 17 12:06:37 2014 : Debug: reading pairlist file /usr/local/etc/raddb/preproxy_users
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking preacct {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_acct_unique, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_acct_unique
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "acct_unique" from file /usr/local/etc/raddb/modules/acct_unique
Wed Sep 17 12:06:37 2014 : Debug:   acct_unique {
Wed Sep 17 12:06:37 2014 : Debug:   	key = "User-Name, Acct-Session-Id, NAS-IP-Address, NAS-Identifier, NAS-Port"
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking accounting {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_detail, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_detail
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "detail" from file /usr/local/etc/raddb/modules/detail
Wed Sep 17 12:06:37 2014 : Debug:   detail {
Wed Sep 17 12:06:37 2014 : Debug:   	detailfile = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
Wed Sep 17 12:06:37 2014 : Debug:   	header = "%t"
Wed Sep 17 12:06:37 2014 : Debug:   	detailperm = 384
Wed Sep 17 12:06:37 2014 : Debug:   	dirperm = 493
Wed Sep 17 12:06:37 2014 : Debug:   	locking = no
Wed Sep 17 12:06:37 2014 : Debug:   	log_packet_header = no
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_attr_filter, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_attr_filter
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/modules/attr_filter
Wed Sep 17 12:06:37 2014 : Debug:   attr_filter attr_filter.accounting_response {
Wed Sep 17 12:06:37 2014 : Debug:   	attrsfile = "/usr/local/etc/raddb/attrs.accounting_response"
Wed Sep 17 12:06:37 2014 : Debug:   	key = "%{User-Name}"
Wed Sep 17 12:06:37 2014 : Debug:   	relaxed = no
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug: reading pairlist file /usr/local/etc/raddb/attrs.accounting_response
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking session {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:     (Loaded rlm_radutmp, checking if it's valid)
Wed Sep 17 12:06:37 2014 : Debug:  Module: Linked to module rlm_radutmp
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "radutmp" from file /usr/local/etc/raddb/modules/radutmp
Wed Sep 17 12:06:37 2014 : Debug:   radutmp {
Wed Sep 17 12:06:37 2014 : Debug:   	filename = "/usr/local/var/log/radius/radutmp"
Wed Sep 17 12:06:37 2014 : Debug:   	username = "%{User-Name}"
Wed Sep 17 12:06:37 2014 : Debug:   	case_sensitive = yes
Wed Sep 17 12:06:37 2014 : Debug:   	check_with_nas = yes
Wed Sep 17 12:06:37 2014 : Debug:   	perm = 384
Wed Sep 17 12:06:37 2014 : Debug:   	callerid = yes
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking post-proxy {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking post-auth {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:  Module: Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/modules/attr_filter
Wed Sep 17 12:06:37 2014 : Debug:   attr_filter attr_filter.access_reject {
Wed Sep 17 12:06:37 2014 : Debug:   	attrsfile = "/usr/local/etc/raddb/attrs.access_reject"
Wed Sep 17 12:06:37 2014 : Debug:   	key = "%{User-Name}"
Wed Sep 17 12:06:37 2014 : Debug:   	relaxed = no
Wed Sep 17 12:06:37 2014 : Debug:   }
Wed Sep 17 12:06:37 2014 : Debug: reading pairlist file /usr/local/etc/raddb/attrs.access_reject
Wed Sep 17 12:06:37 2014 : Debug:  } # modules
Wed Sep 17 12:06:37 2014 : Debug: } # server
Wed Sep 17 12:06:37 2014 : Debug: server inner-tunnel { # from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Wed Sep 17 12:06:37 2014 : Debug:  modules {
Wed Sep 17 12:06:37 2014 : Debug:   Module: Creating Auth-Type = ntlm_auth
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking authenticate {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking authorize {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking session {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking post-proxy {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:  Module: Checking post-auth {...} for more modules to load
Wed Sep 17 12:06:37 2014 : Debug:  } # modules
Wed Sep 17 12:06:37 2014 : Debug: } # server
Wed Sep 17 12:06:37 2014 : Debug: radiusd: #### Opening IP addresses and Ports ####
Wed Sep 17 12:06:37 2014 : Debug: listen {
Wed Sep 17 12:06:37 2014 : Debug:  	type = "auth"
Wed Sep 17 12:06:37 2014 : Debug:  	ipaddr = *
Wed Sep 17 12:06:37 2014 : Debug:  	port = 0
Wed Sep 17 12:06:37 2014 : Debug: }
Wed Sep 17 12:06:37 2014 : Debug: listen {
Wed Sep 17 12:06:37 2014 : Debug:  	type = "acct"
Wed Sep 17 12:06:37 2014 : Debug:  	ipaddr = *
Wed Sep 17 12:06:37 2014 : Debug:  	port = 0
Wed Sep 17 12:06:37 2014 : Debug: }
Wed Sep 17 12:06:37 2014 : Debug: listen {
Wed Sep 17 12:06:37 2014 : Debug:  	type = "control"
Wed Sep 17 12:06:37 2014 : Debug:  listen {
Wed Sep 17 12:06:37 2014 : Debug:  	socket = "/usr/local/var/run/radiusd/radiusd.sock"
Wed Sep 17 12:06:37 2014 : Debug:  }
Wed Sep 17 12:06:37 2014 : Debug: }
Wed Sep 17 12:06:37 2014 : Debug: listen {
Wed Sep 17 12:06:37 2014 : Debug:   	type = "auth"
Wed Sep 17 12:06:37 2014 : Debug:   	ipaddr = 127.0.0.1
Wed Sep 17 12:06:37 2014 : Debug:   	port = 18120
Wed Sep 17 12:06:37 2014 : Debug: }
Wed Sep 17 12:06:37 2014 : Debug:  ... adding new socket proxy address * port 57509
Wed Sep 17 12:06:37 2014 : Debug: Listening on authentication address * port 1812
Wed Sep 17 12:06:37 2014 : Debug: Listening on accounting address * port 1813
Wed Sep 17 12:06:37 2014 : Debug: Listening on command file /usr/local/var/run/radiusd/radiusd.sock
Wed Sep 17 12:06:37 2014 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel
Wed Sep 17 12:06:37 2014 : Debug: Listening on proxy address * port 1814
Wed Sep 17 12:06:37 2014 : Info: Ready to process requests.
TLS: Trusted root certificate(s) loaded
rad_recv: Access-Request packet from host 10.10.2.21 port 32769, id=0, length=139
	User-Name = "Administrator"
	NAS-IP-Address = 10.10.2.21
	Called-Station-Id = "00904c0dc3c0"
	Calling-Station-Id = "b0df3a213196"
	NAS-Identifier = "00904c0dc3c0"
	NAS-Port = 6
	Framed-MTU = 1400
	NAS-Port-Type = Wireless-802.11
	EAP-Message = 0x020000120141646d696e6973747261746f72
	Message-Authenticator = 0x6edc31d2d5c24e4ab9a7dc76563162f7
Wed Sep 17 12:06:41 2014 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Wed Sep 17 12:06:41 2014 : Info: +group authorize {
Wed Sep 17 12:06:41 2014 : Info: ++[preprocess] = ok
Wed Sep 17 12:06:41 2014 : Info: ++[chap] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[mschap] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[digest] = noop
Wed Sep 17 12:06:41 2014 : Info: [suffix] No '@' in User-Name = "Administrator", looking up realm NULL
Wed Sep 17 12:06:41 2014 : Info: [suffix] No such realm "NULL"
Wed Sep 17 12:06:41 2014 : Info: ++[suffix] = noop
Wed Sep 17 12:06:41 2014 : Info: [eap] EAP packet type response id 0 length 18
Wed Sep 17 12:06:41 2014 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Wed Sep 17 12:06:41 2014 : Info: ++[eap] = updated
Wed Sep 17 12:06:41 2014 : Info: [files] users: Matched entry DEFAULT at line 1
Wed Sep 17 12:06:41 2014 : Info: ++[files] = ok
Wed Sep 17 12:06:41 2014 : Info: ++[expiration] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[logintime] = noop
Wed Sep 17 12:06:41 2014 : Info: [pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Sep 17 12:06:41 2014 : Info: ++[pap] = noop
Wed Sep 17 12:06:41 2014 : Info: +} # group authorize = updated
Wed Sep 17 12:06:41 2014 : Info: Found Auth-Type = EAP
Wed Sep 17 12:06:41 2014 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Wed Sep 17 12:06:41 2014 : Info: +group EAP {
EAP: Server state machine created
EAP: EAP entering state INITIALIZE
EAP: parseEapResp: rxResp=1 respId=0 respMethod=1 respVendor=0 respVendorMethod=0
EAP: EAP entering state PICK_UP_METHOD
EAP: EAP entering state METHOD_RESPONSE
EAP-Identity: Peer identity - hexdump_ascii(len=13):
     41 64 6d 69 6e 69 73 74 72 61 74 6f 72            Administrator   
EAP: EAP entering state SELECT_ACTION
EAP: getDecision: another method available -> CONTINUE
EAP: EAP entering state PROPOSE_METHOD
EAP: getNextMethod: vendor 0 type 43
OpenSSL: cipher suites: ADH-AES128-SHA:AES128-SHA:DHE-RSA-AES128-SHA:RC4-SHA
EAP: EAP entering state METHOD_REQUEST
EAP: building EAP-Request: Identifier 1
EAP-FAST: START -> PHASE1
EAP: EAP entering state SEND_REQUEST
EAP: EAP entering state IDLE
EAP: retransmit timeout 3 seconds (from dynamic back off; retransCount=0)
Wed Sep 17 12:06:41 2014 : Debug: ==> Request
Wed Sep 17 12:06:41 2014 : Info: ++[eap2] = handled
Wed Sep 17 12:06:41 2014 : Info: +} # group EAP = handled
Sending Access-Challenge of id 0 to 10.10.2.21 port 32769
	EAP-Message = 0x0101000f2b2100040005746a737973
	State = 0x8bdc2a12eac6efe846833b075f18905a
	Message-Authenticator = 0x00000000000000000000000000000000
Wed Sep 17 12:06:41 2014 : Info: Finished request 0.
Wed Sep 17 12:06:41 2014 : Debug: Going to the next request
Wed Sep 17 12:06:41 2014 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.10.2.21 port 32769, id=0, length=203
Wed Sep 17 12:06:41 2014 : Info: Cleaning up request 0 ID 0 with timestamp +4
	User-Name = "Administrator"
	NAS-IP-Address = 10.10.2.21
	Called-Station-Id = "00904c0dc3c0"
	Calling-Station-Id = "b0df3a213196"
	NAS-Identifier = "00904c0dc3c0"
	NAS-Port = 6
	Framed-MTU = 1400
	State = 0x8bdc2a12eac6efe846833b075f18905a
	NAS-Port-Type = Wireless-802.11
	EAP-Message = 0x020100402b01160301003501000031030154192b942c524c11750e80d3d26b207024e3ba0b21d4da77927379103574dd3e00000a00340033002f000500ff0100
	Message-Authenticator = 0xffe1e97ba8954dce435d6c3f66de7f37
Wed Sep 17 12:06:41 2014 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Wed Sep 17 12:06:41 2014 : Info: +group authorize {
Wed Sep 17 12:06:41 2014 : Info: ++[preprocess] = ok
Wed Sep 17 12:06:41 2014 : Info: ++[chap] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[mschap] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[digest] = noop
Wed Sep 17 12:06:41 2014 : Info: [suffix] No '@' in User-Name = "Administrator", looking up realm NULL
Wed Sep 17 12:06:41 2014 : Info: [suffix] No such realm "NULL"
Wed Sep 17 12:06:41 2014 : Info: ++[suffix] = noop
Wed Sep 17 12:06:41 2014 : Info: [eap] EAP packet type response id 1 length 64
Wed Sep 17 12:06:41 2014 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Wed Sep 17 12:06:41 2014 : Info: ++[eap] = updated
Wed Sep 17 12:06:41 2014 : Info: [files] users: Matched entry DEFAULT at line 1
Wed Sep 17 12:06:41 2014 : Info: ++[files] = ok
Wed Sep 17 12:06:41 2014 : Info: ++[expiration] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[logintime] = noop
Wed Sep 17 12:06:41 2014 : Info: [pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Sep 17 12:06:41 2014 : Info: ++[pap] = noop
Wed Sep 17 12:06:41 2014 : Info: +} # group authorize = updated
Wed Sep 17 12:06:41 2014 : Info: Found Auth-Type = EAP
Wed Sep 17 12:06:41 2014 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Wed Sep 17 12:06:41 2014 : Info: +group EAP {
Wed Sep 17 12:06:41 2014 : Info: [eap2] Request found, released from the list
EAP: EAP entering state RECEIVED
EAP: parseEapResp: rxResp=1 respId=1 respMethod=43 respVendor=0 respVendorMethod=0
EAP: EAP entering state INTEGRITY_CHECK
EAP: EAP entering state METHOD_RESPONSE
SSL: Received packet(len=64) - Flags 0x01
SSL: Received packet: Flags 0x1 Message Length 0
SSL: (where=0x10 ret=0x1)
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:before/accept initialization
EAP-FAST: SessionTicket callback
EAP-FAST: SessionTicket (PAC-Opaque) - hexdump(len=0): [NULL]
EAP-FAST: Ignore invalid SessionTicket
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:SSLv3 read client hello A
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:SSLv3 write server hello A
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:SSLv3 write key exchange A
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:SSLv3 write server done A
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:SSLv3 flush data
SSL: (where=0x2002 ret=0xffffffff)
SSL: SSL_accept:error in SSLv3 read client certificate A
SSL: SSL_accept - want more data
SSL: 367 bytes pending from ssl_out
EAP: EAP entering state METHOD_REQUEST
EAP: building EAP-Request: Identifier 2
SSL: Generating Request
SSL: Sending out 367 bytes (message sent completely)
EAP: EAP entering state SEND_REQUEST
EAP: EAP entering state IDLE
EAP: retransmit timeout 3 seconds (from dynamic back off; retransCount=0)
Wed Sep 17 12:06:41 2014 : Debug: ==> Request
Wed Sep 17 12:06:41 2014 : Info: ++[eap2] = handled
Wed Sep 17 12:06:41 2014 : Info: +} # group EAP = handled
Sending Access-Challenge of id 0 to 10.10.2.21 port 32769
	EAP-Message = 0x010201752b0116030100510200004d03019bea264d0a4650688415a98c36647ae0f9c3f66858c63acbcf1cdf471d8ac2b120f54d966f7948bd6a2964f6b11c312e474715b576d1b02f8972e3026dccb9517c0034000005ff01000100160301010b0c0001070080de4cb0a195a152c976400f10682e0e44661c747fc84263fa95f672c948d6c9972c4acaf67af770a00b57c825dec1f8f8b775d9dca2aaded3290941987e97e6381323bdb6eba418782505fa13bee56124eca507db525932bf59d821ec6fd94fe0824914d623c8b5a309c1f9bfa6611efcc4531ce93adb2f904d1872b908ea5363000102008019de88e5894bbd3928507a3ca73948ff64
	EAP-Message = 0xfd2effa7b3b790ddee8490d6110701c33756f9257aff9f1a9c9b62b8af10025b223ff81c0875c04efc6d60d85ce40ea3882efac87d57b73736f2193a32833bb48d506f768b23158f7cc1082eca82063f30eb36647c0de221c7df06ca2c6316d2312a5b1b38271eb49e44d1907365d616030100040e000000
	State = 0x937a095447bfdff66f615e837da27188
	Message-Authenticator = 0x00000000000000000000000000000000
Wed Sep 17 12:06:41 2014 : Info: Finished request 1.
Wed Sep 17 12:06:41 2014 : Debug: Going to the next request
Wed Sep 17 12:06:41 2014 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.10.2.21 port 32769, id=0, length=343
Wed Sep 17 12:06:41 2014 : Info: Cleaning up request 1 ID 0 with timestamp +4
	User-Name = "Administrator"
	NAS-IP-Address = 10.10.2.21
	Called-Station-Id = "00904c0dc3c0"
	Calling-Station-Id = "b0df3a213196"
	NAS-Identifier = "00904c0dc3c0"
	NAS-Port = 6
	Framed-MTU = 1400
	State = 0x937a095447bfdff66f615e837da27188
	NAS-Port-Type = Wireless-802.11
	EAP-Message = 0x020200cc2b011603010086100000820080c780bed8e5ad3cce87bb388f5d65f11afd0c1347267b923688189e8fa5462eae76d0da07bcf1c540e82194fd2dc001c87fd27aaf2c3313dd0949e9d7bcc8c3893478b436d47ed726d19ccb81514aea9e9bf734d744ac44751821d212d53fa4bf6e9d9a76ef51a8da802bcb9006efa3e2820c296c668664c57527353fdd1db7431403010001011603010030e039dabde4949e8054bebb08b847852933c849f46075bce8930104da7240fb24bb506a040c8779f83215e6986f1baafc
	Message-Authenticator = 0x512d573323cf40b027b25a6802a0c718
Wed Sep 17 12:06:41 2014 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Wed Sep 17 12:06:41 2014 : Info: +group authorize {
Wed Sep 17 12:06:41 2014 : Info: ++[preprocess] = ok
Wed Sep 17 12:06:41 2014 : Info: ++[chap] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[mschap] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[digest] = noop
Wed Sep 17 12:06:41 2014 : Info: [suffix] No '@' in User-Name = "Administrator", looking up realm NULL
Wed Sep 17 12:06:41 2014 : Info: [suffix] No such realm "NULL"
Wed Sep 17 12:06:41 2014 : Info: ++[suffix] = noop
Wed Sep 17 12:06:41 2014 : Info: [eap] EAP packet type response id 2 length 204
Wed Sep 17 12:06:41 2014 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Wed Sep 17 12:06:41 2014 : Info: ++[eap] = updated
Wed Sep 17 12:06:41 2014 : Info: [files] users: Matched entry DEFAULT at line 1
Wed Sep 17 12:06:41 2014 : Info: ++[files] = ok
Wed Sep 17 12:06:41 2014 : Info: ++[expiration] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[logintime] = noop
Wed Sep 17 12:06:41 2014 : Info: [pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Sep 17 12:06:41 2014 : Info: ++[pap] = noop
Wed Sep 17 12:06:41 2014 : Info: +} # group authorize = updated
Wed Sep 17 12:06:41 2014 : Info: Found Auth-Type = EAP
Wed Sep 17 12:06:41 2014 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Wed Sep 17 12:06:41 2014 : Info: +group EAP {
Wed Sep 17 12:06:41 2014 : Info: [eap2] Request found, released from the list
EAP: EAP entering state RECEIVED
EAP: parseEapResp: rxResp=1 respId=2 respMethod=43 respVendor=0 respVendorMethod=0
EAP: EAP entering state INTEGRITY_CHECK
EAP: EAP entering state METHOD_RESPONSE
SSL: Received packet(len=204) - Flags 0x01
SSL: Received packet: Flags 0x1 Message Length 0
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:SSLv3 read client key exchange A
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:SSLv3 read finished A
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:SSLv3 write change cipher spec A
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:SSLv3 write finished A
SSL: (where=0x2001 ret=0x1)
SSL: SSL_accept:SSLv3 flush data
SSL: (where=0x20 ret=0x1)
SSL: (where=0x2002 ret=0x1)
SSL: 59 bytes pending from ssl_out
EAP: EAP entering state METHOD_REQUEST
EAP: building EAP-Request: Identifier 3
EAP-FAST: Phase1 done, starting Phase2
EAP-FAST: Anonymous provisioning
EAP-FAST: master_secret for key expansion - hexdump(len=48): [REMOVED]
EAP-FAST: session_key_seed (SKS = S-IMCK[0]) - hexdump(len=40): [REMOVED]
EAP-FAST: server_challenge - hexdump(len=16): [REMOVED]
EAP-FAST: client_challenge - hexdump(len=16): [REMOVED]
EAP-FAST: PHASE1 -> PHASE2_START
EAP-FAST: Try to start Phase 2
EAP-FAST: PHASE2_START -> PHASE2_ID
EAP-FAST: Phase 2 EAP-Request - hexdump(len=5): [REMOVED]
EAP-FAST: Add EAP-Payload TLV
EAP-FAST: Encrypting Phase 2 TLVs - hexdump(len=9): [REMOVED]
EAP-FAST: Piggyback Phase 2 data (len=74) with last Phase 1 Message (len=59 used=0)
SSL: Generating Request
SSL: Sending out 133 bytes (message sent completely)
EAP: EAP entering state SEND_REQUEST
EAP: EAP entering state IDLE
EAP: retransmit timeout 3 seconds (from dynamic back off; retransCount=0)
Wed Sep 17 12:06:41 2014 : Debug: ==> Request
Wed Sep 17 12:06:41 2014 : Info: ++[eap2] = handled
Wed Sep 17 12:06:41 2014 : Info: +} # group EAP = handled
Sending Access-Challenge of id 0 to 10.10.2.21 port 32769
	EAP-Message = 0x0103008b2b011403010001011603010030ecbaeb0cb34edb4b5a2ba664ee29b3bc10415f193eea62b87aec7010764b27c9214f353e257ba45d088db01395af31921703010020553bf7bacca0e0deaaab76ced600289fa3cfd5e554f12194366f6daebb9457461703010020bfa25876dc10a3be2823cc57da70dacc00ba36be10cac7d3fab63abc9568da76
	State = 0x168e1d8b4946cac447e29a10af5f74ab
	Message-Authenticator = 0x00000000000000000000000000000000
Wed Sep 17 12:06:41 2014 : Info: Finished request 2.
Wed Sep 17 12:06:41 2014 : Debug: Going to the next request
Wed Sep 17 12:06:41 2014 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.10.2.21 port 32769, id=0, length=198
Wed Sep 17 12:06:41 2014 : Info: Cleaning up request 2 ID 0 with timestamp +4
	User-Name = "Administrator"
	NAS-IP-Address = 10.10.2.21
	Called-Station-Id = "00904c0dc3c0"
	Calling-Station-Id = "b0df3a213196"
	NAS-Identifier = "00904c0dc3c0"
	NAS-Port = 6
	Framed-MTU = 1400
	State = 0x168e1d8b4946cac447e29a10af5f74ab
	NAS-Port-Type = Wireless-802.11
	EAP-Message = 0x0203003b2b01170301003095d9ea11cd8534ccc15833857d3abf3d4cde7bcfd6452e90a6376d38a1fbca5cd8866df13873ced31bcddb01b763a05a
	Message-Authenticator = 0x8436f303447ef2fb778d130a29cde1fe
Wed Sep 17 12:06:41 2014 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Wed Sep 17 12:06:41 2014 : Info: +group authorize {
Wed Sep 17 12:06:41 2014 : Info: ++[preprocess] = ok
Wed Sep 17 12:06:41 2014 : Info: ++[chap] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[mschap] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[digest] = noop
Wed Sep 17 12:06:41 2014 : Info: [suffix] No '@' in User-Name = "Administrator", looking up realm NULL
Wed Sep 17 12:06:41 2014 : Info: [suffix] No such realm "NULL"
Wed Sep 17 12:06:41 2014 : Info: ++[suffix] = noop
Wed Sep 17 12:06:41 2014 : Info: [eap] EAP packet type response id 3 length 59
Wed Sep 17 12:06:41 2014 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Wed Sep 17 12:06:41 2014 : Info: ++[eap] = updated
Wed Sep 17 12:06:41 2014 : Info: [files] users: Matched entry DEFAULT at line 1
Wed Sep 17 12:06:41 2014 : Info: ++[files] = ok
Wed Sep 17 12:06:41 2014 : Info: ++[expiration] = noop
Wed Sep 17 12:06:41 2014 : Info: ++[logintime] = noop
Wed Sep 17 12:06:41 2014 : Info: [pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Sep 17 12:06:41 2014 : Info: ++[pap] = noop
Wed Sep 17 12:06:41 2014 : Info: +} # group authorize = updated
Wed Sep 17 12:06:41 2014 : Info: Found Auth-Type = EAP
Wed Sep 17 12:06:41 2014 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Wed Sep 17 12:06:41 2014 : Info: +group EAP {
Wed Sep 17 12:06:41 2014 : Info: [eap2] Request found, released from the list
EAP: EAP entering state RECEIVED
EAP: parseEapResp: rxResp=1 respId=3 respMethod=43 respVendor=0 respVendorMethod=0
EAP: EAP entering state INTEGRITY_CHECK
EAP: EAP entering state METHOD_RESPONSE
SSL: Received packet(len=59) - Flags 0x01
SSL: Received packet: Flags 0x1 Message Length 0
EAP-FAST: Received 53 bytes encrypted data for Phase 2
EAP-FAST: Decrypted Phase 2 TLVs - hexdump(len=22): [REMOVED]
EAP-FAST: Received Phase 2: TLV type 9 length 18 (mandatory)
EAP-FAST: EAP-Payload TLV - hexdump(len=18): 02 03 00 12 01 41 64 6d 69 6e 69 73 74 72 61 74 6f 72
EAP-FAST: Received Phase 2: code=2 identifier=3 length=18
EAP-Identity: Peer identity - hexdump_ascii(len=13):
     41 64 6d 69 6e 69 73 74 72 61 74 6f 72            Administrator   
EAP-FAST: PHASE2_ID -> PHASE2_METHOD
EAP-FAST: try EAP type 26
EAP: EAP entering state METHOD_REQUEST
EAP: building EAP-Request: Identifier 4
EAP-MSCHAPV2: Challenge - hexdump(len=16): 3f 59 4c c5 b1 d1 bc 71 62 df c1 49 70 6a 03 b7
EAP-FAST: Phase 2 EAP-Request - hexdump(len=33): [REMOVED]
EAP-FAST: Add EAP-Payload TLV
EAP-FAST: Encrypting Phase 2 TLVs - hexdump(len=37): [REMOVED]
SSL: Generating Request
SSL: Sending out 106 bytes (message sent completely)
EAP: EAP entering state SEND_REQUEST
EAP: EAP entering state IDLE
EAP: retransmit timeout 3 seconds (from dynamic back off; retransCount=0)
Wed Sep 17 12:06:41 2014 : Debug: ==> Request
Wed Sep 17 12:06:41 2014 : Info: ++[eap2] = handled
Wed Sep 17 12:06:41 2014 : Info: +} # group EAP = handled
Sending Access-Challenge of id 0 to 10.10.2.21 port 32769
	EAP-Message = 0x010400702b011703010020e4317e67f52197b376755f279b5e6623bba4be4333673a365d6162ddb21e5ba8170301004034291c01a1da6602565ad1e7ed03b4dd5f7a0f12d7f081fbd12e2fffdb304e1c5294279384159b5c2d8d003b3ef0dbfb15cf87af4db208b7259979816ada26c3
	State = 0x9dd8b50daabbda5628fd760dd6fc5d4c
	Message-Authenticator = 0x00000000000000000000000000000000
Wed Sep 17 12:06:41 2014 : Info: Finished request 3.
Wed Sep 17 12:06:41 2014 : Debug: Going to the next request
Wed Sep 17 12:06:41 2014 : Debug: Waking up in 4.9 seconds.
Wed Sep 17 12:06:46 2014 : Info: Cleaning up request 3 ID 0 with timestamp +4
Wed Sep 17 12:06:46 2014 : Info: Ready to process requests.