FreeRadius going through ISA to reach federation

16 Dec 2011

      Hi all,

I have configuring a FreeRadius, and I need to go through a IAS to reach the
eduroam federation. I created a realm for our local domain, created a
DEFAULT proxy for users with other domains pointing to the IAS server, both
are as clients of each other, share the same secret, and also defined a
Remote access policy in IAS.

Tried already some alternatives, and inserted Reply-Message = "Yes", as
suggested on another post in the list.

Despite all the efforts, when talking with the IAS, I receive back the error
Proxy-State = 0x3137.

Any advice?

Best Regards,
Rui Ribeiro

--

freeradius -Xxxxx
Fri Dec 16 12:27:20 2011 : Info: FreeRADIUS Version 2.1.10, for host
i486-pc-linux-gnu, built on Nov 14 2010 at 20:41:03
Fri Dec 16 12:27:20 2011 : Info: Copyright (C) 1999-2009 The FreeRADIUS
server project and contributors.
Fri Dec 16 12:27:20 2011 : Info: There is NO warranty; not even for
MERCHANTABILITY or FITNESS FOR A
Fri Dec 16 12:27:20 2011 : Info: PARTICULAR PURPOSE.
Fri Dec 16 12:27:20 2011 : Info: You may redistribute copies of FreeRADIUS
under the terms of the
Fri Dec 16 12:27:20 2011 : Info: GNU General Public License v2.
Fri Dec 16 12:27:20 2011 : Info: Starting - reading configuration files ...
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/radiusd.conf
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/proxy.conf
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/clients.conf
Fri Dec 16 12:27:20 2011 : Debug: including files in directory
/etc/freeradius/modules/
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/smsotp
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/policy
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/sqlcounter_expire_on_login
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/counter
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/checkval
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/detail
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/radutmp
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/detail.log
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/ntlm_auth
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/mac2ip
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/perl
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/otp
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/ippool
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/linelog
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/detail.example.com
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/attr_rewrite
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/preprocess
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/attr_filter
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/always
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/sql_log
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/smbpasswd
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/files
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/unix
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/ldap
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/sradutmp
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/expiration
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/inner-eap
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/mschap
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/mac2vlan
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/krb5
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/passwd
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/pam
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/realm
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/wimax
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/chap
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/exec
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/expr
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/acct_unique
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/cui
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/opendirectory
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/dynamic_clients
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/echo
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/etc_group
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/pap
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/logintime
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/modules/digest
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/eap.conf
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/policy.conf
Fri Dec 16 12:27:20 2011 : Debug: including files in directory
/etc/freeradius/sites-enabled/
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/sites-enabled/default
Fri Dec 16 12:27:20 2011 : Debug: including configuration file
/etc/freeradius/sites-enabled/inner-tunnel
Fri Dec 16 12:27:20 2011 : Debug: main {
Fri Dec 16 12:27:20 2011 : Debug: 	user = "freerad"
Fri Dec 16 12:27:20 2011 : Debug: 	group = "freerad"
Fri Dec 16 12:27:20 2011 : Debug: 	allow_core_dumps = no
Fri Dec 16 12:27:20 2011 : Debug: }
Fri Dec 16 12:27:20 2011 : Debug: including dictionary file
/etc/freeradius/dictionary
Fri Dec 16 12:27:20 2011 : Debug: main {
Fri Dec 16 12:27:20 2011 : Debug: 	prefix = "/usr"
Fri Dec 16 12:27:20 2011 : Debug: 	localstatedir = "/var"
Fri Dec 16 12:27:20 2011 : Debug: 	logdir = "/var/log/freeradius"
Fri Dec 16 12:27:20 2011 : Debug: 	libdir = "/usr/lib/freeradius"
Fri Dec 16 12:27:20 2011 : Debug: 	radacctdir =
"/var/log/freeradius/radacct"
Fri Dec 16 12:27:20 2011 : Debug: 	hostname_lookups = no
Fri Dec 16 12:27:20 2011 : Debug: 	max_request_time = 30
Fri Dec 16 12:27:20 2011 : Debug: 	cleanup_delay = 5
Fri Dec 16 12:27:20 2011 : Debug: 	max_requests = 1024
Fri Dec 16 12:27:20 2011 : Debug: 	pidfile =
"/var/run/freeradius/freeradius.pid"
Fri Dec 16 12:27:20 2011 : Debug: 	checkrad = "/usr/sbin/checkrad"
Fri Dec 16 12:27:20 2011 : Debug: 	debug_level = 0
Fri Dec 16 12:27:20 2011 : Debug: 	proxy_requests = yes
Fri Dec 16 12:27:20 2011 : Debug:  log {
Fri Dec 16 12:27:20 2011 : Debug: 	stripped_names = no
Fri Dec 16 12:27:20 2011 : Debug: 	auth = no
Fri Dec 16 12:27:20 2011 : Debug: 	auth_badpass = no
Fri Dec 16 12:27:20 2011 : Debug: 	auth_goodpass = no
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug:  security {
Fri Dec 16 12:27:20 2011 : Debug: 	max_attributes = 200
Fri Dec 16 12:27:20 2011 : Debug: 	reject_delay = 0
Fri Dec 16 12:27:20 2011 : Debug: 	status_server = yes
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug: }
Fri Dec 16 12:27:20 2011 : Debug: radiusd: #### Loading Realms and Home
Servers ####
Fri Dec 16 12:27:20 2011 : Debug:  proxy server {
Fri Dec 16 12:27:20 2011 : Debug: 	retry_delay = 5
Fri Dec 16 12:27:20 2011 : Debug: 	retry_count = 1
Fri Dec 16 12:27:20 2011 : Debug: 	default_fallback = no
Fri Dec 16 12:27:20 2011 : Debug: 	dead_time = 120
Fri Dec 16 12:27:20 2011 : Debug: 	wake_all_if_all_dead = no
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug:  realm iscte.pt {
Fri Dec 16 12:27:20 2011 : Debug: 	authhost = LOCAL
Fri Dec 16 12:27:20 2011 : Debug: 	accthost = LOCAL
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug:  realm NULL {
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug:  realm DEFAULT {
Fri Dec 16 12:27:20 2011 : Debug: 	nostrip
Fri Dec 16 12:27:20 2011 : Debug: 	authhost = nut.iscte.intranet:1812
Fri Dec 16 12:27:20 2011 : Debug: 	accthost = nut.iscte.intranet:1813
Fri Dec 16 12:27:20 2011 : Debug: 	secret = xxx
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug: radiusd: #### Loading Clients ####
Fri Dec 16 12:27:20 2011 : Debug:  client localhost {
Fri Dec 16 12:27:20 2011 : Debug: 	ipaddr = 127.0.0.1
Fri Dec 16 12:27:20 2011 : Debug: 	require_message_authenticator = no
Fri Dec 16 12:27:20 2011 : Debug: 	secret = "xxx"
Fri Dec 16 12:27:20 2011 : Debug: 	nastype = "other"
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug:  client 10.10.66.18/32 {
Fri Dec 16 12:27:20 2011 : Debug: 	ipaddr = 10.10.66.18
Fri Dec 16 12:27:20 2011 : Debug: 	netmask = 32
Fri Dec 16 12:27:20 2011 : Debug: 	require_message_authenticator = no
Fri Dec 16 12:27:20 2011 : Debug: 	secret = "xxx"
Fri Dec 16 12:27:20 2011 : Debug: 	shortname = "nut"
Fri Dec 16 12:27:20 2011 : Debug: 	nastype = "other"
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug:  client 10.65.0.0/16 {
Fri Dec 16 12:27:20 2011 : Debug: 	require_message_authenticator = no
Fri Dec 16 12:27:20 2011 : Debug: 	secret = "xxxx"
Fri Dec 16 12:27:20 2011 : Debug: 	shortname = "rede_aps"
Fri Dec 16 12:27:20 2011 : Debug: 	nastype = "cisco"
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug:  client 10.10.32.0/22 {
Fri Dec 16 12:27:20 2011 : Debug: 	require_message_authenticator = no
Fri Dec 16 12:27:20 2011 : Debug: 	secret = "xxx"
Fri Dec 16 12:27:20 2011 : Debug: 	shortname = "eduroam2"
Fri Dec 16 12:27:20 2011 : Debug: 	nastype = "other"
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug: radiusd: #### Instantiating modules ####
Fri Dec 16 12:27:20 2011 : Debug:  instantiate {
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_exec, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_exec
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "exec" from
file /etc/freeradius/modules/exec
Fri Dec 16 12:27:20 2011 : Debug:   exec {
Fri Dec 16 12:27:20 2011 : Debug: 	wait = no
Fri Dec 16 12:27:20 2011 : Debug: 	input_pairs = "request"
Fri Dec 16 12:27:20 2011 : Debug: 	shell_escape = yes
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_expr, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_expr
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "expr" from
file /etc/freeradius/modules/expr
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_expiration, checking if
it's valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_expiration
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "expiration"
from file /etc/freeradius/modules/expiration
Fri Dec 16 12:27:20 2011 : Debug:   expiration {
Fri Dec 16 12:27:20 2011 : Debug: 	reply-message = "Password Has Expired  "
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_logintime, checking if
it's valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_logintime
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "logintime"
from file /etc/freeradius/modules/logintime
Fri Dec 16 12:27:20 2011 : Debug:   logintime {
Fri Dec 16 12:27:20 2011 : Debug: 	reply-message = "You are calling outside
your allowed timespan  "
Fri Dec 16 12:27:20 2011 : Debug: 	minimum-timeout = 60
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:  }
Fri Dec 16 12:27:20 2011 : Debug: radiusd: #### Loading Virtual Servers ####
Fri Dec 16 12:27:20 2011 : Debug: server inner-tunnel { # from file
/etc/freeradius/sites-enabled/inner-tunnel
Fri Dec 16 12:27:20 2011 : Debug:  modules {
Fri Dec 16 12:27:20 2011 : Debug:  Module: Checking authenticate {...} for
more modules to load
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_pap, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_pap
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "pap" from
file /etc/freeradius/modules/pap
Fri Dec 16 12:27:20 2011 : Debug:   pap {
Fri Dec 16 12:27:20 2011 : Debug: 	encryption_scheme = "auto"
Fri Dec 16 12:27:20 2011 : Debug: 	auto_header = no
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_chap, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_chap
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "chap" from
file /etc/freeradius/modules/chap
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_mschap, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_mschap
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "mschap"
from file /etc/freeradius/modules/mschap
Fri Dec 16 12:27:20 2011 : Debug:   mschap {
Fri Dec 16 12:27:20 2011 : Debug: 	use_mppe = yes
Fri Dec 16 12:27:20 2011 : Debug: 	require_encryption = yes
Fri Dec 16 12:27:20 2011 : Debug: 	require_strong = yes
Fri Dec 16 12:27:20 2011 : Debug: 	with_ntdomain_hack = yes
Fri Dec 16 12:27:20 2011 : Debug: 	ntlm_auth = "/usr/bin/ntlm_auth
--request-nt-key --username=%{%{Stripped-User-Name}:-%{User-Name:-None}}
--challenge=%{mschap:Challenge:-00} --domain=IUL
--nt-response=%{mschap:NT-Response:-00}"
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_eap, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_eap
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "eap" from
file /etc/freeradius/eap.conf
Fri Dec 16 12:27:20 2011 : Debug:   eap {
Fri Dec 16 12:27:20 2011 : Debug: 	default_eap_type = "peap"
Fri Dec 16 12:27:20 2011 : Debug: 	timer_expire = 60
Fri Dec 16 12:27:20 2011 : Debug: 	ignore_unknown_eap_types = no
Fri Dec 16 12:27:20 2011 : Debug: 	cisco_accounting_username_bug = no
Fri Dec 16 12:27:20 2011 : Debug: 	max_sessions = 4096
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to sub-module rlm_eap_md5
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating eap-md5
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to sub-module rlm_eap_leap
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating eap-leap
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to sub-module rlm_eap_gtc
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating eap-gtc
Fri Dec 16 12:27:20 2011 : Debug:    gtc {
Fri Dec 16 12:27:20 2011 : Debug: 	challenge = "Password: "
Fri Dec 16 12:27:20 2011 : Debug: 	auth_type = "PAP"
Fri Dec 16 12:27:20 2011 : Debug:    }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to sub-module rlm_eap_tls
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating eap-tls
Fri Dec 16 12:27:20 2011 : Debug:    tls {
Fri Dec 16 12:27:20 2011 : Debug: 	rsa_key_exchange = no
Fri Dec 16 12:27:20 2011 : Debug: 	dh_key_exchange = yes
Fri Dec 16 12:27:20 2011 : Debug: 	rsa_key_length = 512
Fri Dec 16 12:27:20 2011 : Debug: 	dh_key_length = 512
Fri Dec 16 12:27:20 2011 : Debug: 	verify_depth = 0
Fri Dec 16 12:27:20 2011 : Debug: 	CA_path = "/etc/freeradius/certs"
Fri Dec 16 12:27:20 2011 : Debug: 	pem_file_type = yes
Fri Dec 16 12:27:20 2011 : Debug: 	private_key_file =
"/etc/freeradius/certs/server.key"
Fri Dec 16 12:27:20 2011 : Debug: 	certificate_file =
"/etc/freeradius/certs/server.pem"
Fri Dec 16 12:27:20 2011 : Debug: 	CA_file = "/etc/freeradius/certs/ca.pem"
Fri Dec 16 12:27:20 2011 : Debug: 	private_key_password = "xxx"
Fri Dec 16 12:27:20 2011 : Debug: 	dh_file = "/etc/freeradius/certs/dh"
Fri Dec 16 12:27:20 2011 : Debug: 	random_file = "/dev/urandom"
Fri Dec 16 12:27:20 2011 : Debug: 	fragment_size = 1024
Fri Dec 16 12:27:20 2011 : Debug: 	include_length = yes
Fri Dec 16 12:27:20 2011 : Debug: 	check_crl = no
Fri Dec 16 12:27:20 2011 : Debug: 	cipher_list = "DEFAULT"
Fri Dec 16 12:27:20 2011 : Debug: 	make_cert_command =
"/etc/freeradius/certs/bootstrap"
Fri Dec 16 12:27:20 2011 : Debug:     cache {
Fri Dec 16 12:27:20 2011 : Debug: 	enable = no
Fri Dec 16 12:27:20 2011 : Debug: 	lifetime = 24
Fri Dec 16 12:27:20 2011 : Debug: 	max_entries = 255
Fri Dec 16 12:27:20 2011 : Debug:     }
Fri Dec 16 12:27:20 2011 : Debug:     verify {
Fri Dec 16 12:27:20 2011 : Debug:     }
Fri Dec 16 12:27:20 2011 : Debug:    }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to sub-module rlm_eap_ttls
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating eap-ttls
Fri Dec 16 12:27:20 2011 : Debug:    ttls {
Fri Dec 16 12:27:20 2011 : Debug: 	default_eap_type = "mschapv2"
Fri Dec 16 12:27:20 2011 : Debug: 	copy_request_to_tunnel = yes
Fri Dec 16 12:27:20 2011 : Debug: 	use_tunneled_reply = yes
Fri Dec 16 12:27:20 2011 : Debug: 	virtual_server = "inner-tunnel"
Fri Dec 16 12:27:20 2011 : Debug: 	include_length = yes
Fri Dec 16 12:27:20 2011 : Debug:    }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to sub-module rlm_eap_peap
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating eap-peap
Fri Dec 16 12:27:20 2011 : Debug:    peap {
Fri Dec 16 12:27:20 2011 : Debug: 	default_eap_type = "mschapv2"
Fri Dec 16 12:27:20 2011 : Debug: 	copy_request_to_tunnel = yes
Fri Dec 16 12:27:20 2011 : Debug: 	use_tunneled_reply = yes
Fri Dec 16 12:27:20 2011 : Debug: 	proxy_tunneled_request_as_eap = yes
Fri Dec 16 12:27:20 2011 : Debug: 	virtual_server = "inner-tunnel"
Fri Dec 16 12:27:20 2011 : Debug:    }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to sub-module
rlm_eap_mschapv2
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating eap-mschapv2
Fri Dec 16 12:27:20 2011 : Debug:    mschapv2 {
Fri Dec 16 12:27:20 2011 : Debug: 	with_ntdomain_hack = no
Fri Dec 16 12:27:20 2011 : Debug:    }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Checking authorize {...} for more
modules to load
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_realm, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_realm
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "suffix"
from file /etc/freeradius/modules/realm
Fri Dec 16 12:27:20 2011 : Debug:   realm suffix {
Fri Dec 16 12:27:20 2011 : Debug: 	format = "suffix"
Fri Dec 16 12:27:20 2011 : Debug: 	delimiter = "@"
Fri Dec 16 12:27:20 2011 : Debug: 	ignore_default = no
Fri Dec 16 12:27:20 2011 : Debug: 	ignore_null = no
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_files, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_files
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "files" from
file /etc/freeradius/modules/files
Fri Dec 16 12:27:20 2011 : Debug:   files {
Fri Dec 16 12:27:20 2011 : Debug: 	usersfile = "/etc/freeradius/users"
Fri Dec 16 12:27:20 2011 : Debug: 	acctusersfile =
"/etc/freeradius/acct_users"
Fri Dec 16 12:27:20 2011 : Debug: 	preproxy_usersfile =
"/etc/freeradius/preproxy_users"
Fri Dec 16 12:27:20 2011 : Debug: 	compat = "no"
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Checking post-proxy {...} for
more modules to load
Fri Dec 16 12:27:20 2011 : Debug:  Module: Checking post-auth {...} for more
modules to load
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_ldap, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_ldap
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "ldap" from
file /etc/freeradius/modules/ldap
Fri Dec 16 12:27:20 2011 : Debug:   ldap {
Fri Dec 16 12:27:20 2011 : Debug: 	server = "10.10.32.14"
Fri Dec 16 12:27:20 2011 : Debug: 	port = 389
Fri Dec 16 12:27:20 2011 : Debug: 	password = "xxxxxxx"
Fri Dec 16 12:27:20 2011 : Debug: 	identity =
"CN=------,CN=Users,DC=wiscte,DC=wfarm"
Fri Dec 16 12:27:20 2011 : Debug: 	net_timeout = 10
Fri Dec 16 12:27:20 2011 : Debug: 	timeout = 4
Fri Dec 16 12:27:20 2011 : Debug: 	timelimit = 3
Fri Dec 16 12:27:20 2011 : Debug: 	tls_mode = no
Fri Dec 16 12:27:20 2011 : Debug: 	start_tls = no
Fri Dec 16 12:27:20 2011 : Debug: 	tls_require_cert = "allow"
Fri Dec 16 12:27:20 2011 : Debug:    tls {
Fri Dec 16 12:27:20 2011 : Debug: 	start_tls = no
Fri Dec 16 12:27:20 2011 : Debug: 	require_cert = "allow"
Fri Dec 16 12:27:20 2011 : Debug:    }
Fri Dec 16 12:27:20 2011 : Debug: 	basedn = "cn=Users,dc=wiscte,dc=wfarm"
Fri Dec 16 12:27:20 2011 : Debug: 	filter =
"(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})"
Fri Dec 16 12:27:20 2011 : Debug: 	base_filter =
"(objectclass=radiusprofile)"
Fri Dec 16 12:27:20 2011 : Debug: 	auto_header = no
Fri Dec 16 12:27:20 2011 : Debug: 	access_attr_used_for_allow = yes
Fri Dec 16 12:27:20 2011 : Debug: 	rebind = yes
Fri Dec 16 12:27:20 2011 : Debug: 	groupname_attribute = "sAMAccountName"
Fri Dec 16 12:27:20 2011 : Debug: 	groupmembership_filter =
"(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})"
Fri Dec 16 12:27:20 2011 : Debug: 	groupmembership_attribute = "memberOf"
Fri Dec 16 12:27:20 2011 : Debug: 	dictionary_mapping =
"/etc/freeradius/ldap.attrmap"
Fri Dec 16 12:27:20 2011 : Debug: 	ldap_debug = 0
Fri Dec 16 12:27:20 2011 : Debug: 	ldap_connections_number = 5
Fri Dec 16 12:27:20 2011 : Debug: 	compare_check_items = no
Fri Dec 16 12:27:20 2011 : Debug: 	do_xlat = yes
Fri Dec 16 12:27:20 2011 : Debug: 	edir_account_policy_check = no
Fri Dec 16 12:27:20 2011 : Debug: 	set_auth_type = no
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: Registering ldap_groupcmp for
Ldap-Group
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: Registering ldap_xlat with
xlat_name ldap
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: reading ldap<->radius mappings
from file /etc/freeradius/ldap.attrmap
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusCheckItem mapped to
RADIUS $GENERIC$
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusReplyItem mapped to
RADIUS $GENERIC$
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusAuthType mapped to
RADIUS Auth-Type
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusSimultaneousUse
mapped to RADIUS Simultaneous-Use
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusCalledStationId
mapped to RADIUS Called-Station-Id
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusCallingStationId
mapped to RADIUS Calling-Station-Id
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP lmPassword mapped to RADIUS
LM-Password
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP ntPassword mapped to RADIUS
NT-Password
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP sambaLmPassword mapped to
RADIUS LM-Password
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP sambaNtPassword mapped to
RADIUS NT-Password
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP dBCSPwd mapped to RADIUS
LM-Password
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP userPassword mapped to
RADIUS Password-With-Header
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS
SMB-Account-CTRL-TEXT
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusExpiration mapped to
RADIUS Expiration
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusNASIpAddress mapped
to RADIUS NAS-IP-Address
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusServiceType mapped to
RADIUS Service-Type
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFramedProtocol mapped
to RADIUS Framed-Protocol
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFramedIPAddress
mapped to RADIUS Framed-IP-Address
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFramedIPNetmask
mapped to RADIUS Framed-IP-Netmask
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFramedRoute mapped to
RADIUS Framed-Route
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFramedRouting mapped
to RADIUS Framed-Routing
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFilterId mapped to
RADIUS Filter-Id
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFramedMTU mapped to
RADIUS Framed-MTU
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFramedCompression
mapped to RADIUS Framed-Compression
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusLoginIPHost mapped to
RADIUS Login-IP-Host
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusLoginService mapped
to RADIUS Login-Service
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped
to RADIUS Login-TCP-Port
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusCallbackNumber mapped
to RADIUS Callback-Number
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusCallbackId mapped to
RADIUS Callback-Id
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFramedIPXNetwork
mapped to RADIUS Framed-IPX-Network
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusClass mapped to
RADIUS Class
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusSessionTimeout mapped
to RADIUS Session-Timeout
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusIdleTimeout mapped to
RADIUS Idle-Timeout
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusTerminationAction
mapped to RADIUS Termination-Action
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusLoginLATService
mapped to RADIUS Login-LAT-Service
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusLoginLATNode mapped
to RADIUS Login-LAT-Node
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped
to RADIUS Login-LAT-Group
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink
mapped to RADIUS Framed-AppleTalk-Link
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP
radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone
mapped to RADIUS Framed-AppleTalk-Zone
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusPortLimit mapped to
RADIUS Port-Limit
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusLoginLATPort mapped
to RADIUS Login-LAT-Port
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusReplyMessage mapped
to RADIUS Reply-Message
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusTunnelType mapped to
RADIUS Tunnel-Type
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusTunnelMediumType
mapped to RADIUS Tunnel-Medium-Type
Fri Dec 16 12:27:20 2011 : Debug: rlm_ldap: LDAP radiusTunnelPrivateGroupId
mapped to RADIUS Tunnel-Private-Group-Id
Fri Dec 16 12:27:20 2011 : Debug: conns: 0x94f3cd0
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_attr_filter, checking if
it's valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_attr_filter
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module
"attr_filter.access_reject" from file /etc/freeradius/modules/attr_filter
Fri Dec 16 12:27:20 2011 : Debug:   attr_filter attr_filter.access_reject {
Fri Dec 16 12:27:20 2011 : Debug: 	attrsfile =
"/etc/freeradius/attrs.access_reject"
Fri Dec 16 12:27:20 2011 : Debug: 	key = "%{User-Name}"
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:  } # modules
Fri Dec 16 12:27:20 2011 : Debug: } # server
Fri Dec 16 12:27:20 2011 : Debug: server { # from file
/etc/freeradius/radiusd.conf
Fri Dec 16 12:27:20 2011 : Debug:  modules {
Fri Dec 16 12:27:20 2011 : Debug:  Module: Checking authenticate {...} for
more modules to load
Fri Dec 16 12:27:20 2011 : Debug:  Module: Checking authorize {...} for more
modules to load
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_preprocess, checking if
it's valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_preprocess
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "preprocess"
from file /etc/freeradius/modules/preprocess
Fri Dec 16 12:27:20 2011 : Debug:   preprocess {
Fri Dec 16 12:27:20 2011 : Debug: 	huntgroups = "/etc/freeradius/huntgroups"
Fri Dec 16 12:27:20 2011 : Debug: 	hints = "/etc/freeradius/hints"
Fri Dec 16 12:27:20 2011 : Debug: 	with_ascend_hack = no
Fri Dec 16 12:27:20 2011 : Debug: 	ascend_channels_per_line = 23
Fri Dec 16 12:27:20 2011 : Debug: 	with_ntdomain_hack = no
Fri Dec 16 12:27:20 2011 : Debug: 	with_specialix_jetstream_hack = no
Fri Dec 16 12:27:20 2011 : Debug: 	with_cisco_vsa_hack = no
Fri Dec 16 12:27:20 2011 : Debug: 	with_alvarion_vsa_hack = no
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_detail, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_detail
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "auth_log"
from file /etc/freeradius/modules/detail.log
Fri Dec 16 12:27:20 2011 : Debug:   detail auth_log {
Fri Dec 16 12:27:20 2011 : Debug: 	detailfile =
"/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d"
Fri Dec 16 12:27:20 2011 : Debug: 	header = "%t"
Fri Dec 16 12:27:20 2011 : Debug: 	detailperm = 384
Fri Dec 16 12:27:20 2011 : Debug: 	dirperm = 493
Fri Dec 16 12:27:20 2011 : Debug: 	locking = no
Fri Dec 16 12:27:20 2011 : Debug: 	log_packet_header = no
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Checking preacct {...} for more
modules to load
Fri Dec 16 12:27:20 2011 : Debug:  Module: Checking accounting {...} for
more modules to load
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "detail"
from file /etc/freeradius/modules/detail
Fri Dec 16 12:27:20 2011 : Debug:   detail {
Fri Dec 16 12:27:20 2011 : Debug: 	detailfile =
"/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Fri Dec 16 12:27:20 2011 : Debug: 	header = "%t"
Fri Dec 16 12:27:20 2011 : Debug: 	detailperm = 384
Fri Dec 16 12:27:20 2011 : Debug: 	dirperm = 493
Fri Dec 16 12:27:20 2011 : Debug: 	locking = no
Fri Dec 16 12:27:20 2011 : Debug: 	log_packet_header = no
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_unix, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_unix
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "unix" from
file /etc/freeradius/modules/unix
Fri Dec 16 12:27:20 2011 : Debug:   unix {
Fri Dec 16 12:27:20 2011 : Debug: 	radwtmp = "/var/log/freeradius/radwtmp"
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:     (Loaded rlm_always, checking if it's
valid)
Fri Dec 16 12:27:20 2011 : Debug:  Module: Linked to module rlm_always
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module "ok" from
file /etc/freeradius/modules/always
Fri Dec 16 12:27:20 2011 : Debug:   always ok {
Fri Dec 16 12:27:20 2011 : Debug: 	rcode = "ok"
Fri Dec 16 12:27:20 2011 : Debug: 	simulcount = 0
Fri Dec 16 12:27:20 2011 : Debug: 	mpp = no
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module
"attr_filter.accounting_response" from file
/etc/freeradius/modules/attr_filter
Fri Dec 16 12:27:20 2011 : Debug:   attr_filter
attr_filter.accounting_response {
Fri Dec 16 12:27:20 2011 : Debug: 	attrsfile =
"/etc/freeradius/attrs.accounting_response"
Fri Dec 16 12:27:20 2011 : Debug: 	key = "%{User-Name}"
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Checking post-proxy {...} for
more modules to load
Fri Dec 16 12:27:20 2011 : Debug:  Module: Instantiating module
"post_proxy_log" from file /etc/freeradius/modules/detail.log
Fri Dec 16 12:27:20 2011 : Debug:   detail post_proxy_log {
Fri Dec 16 12:27:20 2011 : Debug: 	detailfile =
"/var/log/freeradius/radacct/%{Client-IP-Address}/post-proxy-detail-%Y%m%d"
Fri Dec 16 12:27:20 2011 : Debug: 	header = "%t"
Fri Dec 16 12:27:20 2011 : Debug: 	detailperm = 384
Fri Dec 16 12:27:20 2011 : Debug: 	dirperm = 493
Fri Dec 16 12:27:20 2011 : Debug: 	locking = no
Fri Dec 16 12:27:20 2011 : Debug: 	log_packet_header = no
Fri Dec 16 12:27:20 2011 : Debug:   }
Fri Dec 16 12:27:20 2011 : Debug:  Module: Checking post-auth {...} for more
modules to load
Fri Dec 16 12:27:20 2011 : Debug:  } # modules
Fri Dec 16 12:27:20 2011 : Debug: } # server
Fri Dec 16 12:27:20 2011 : Debug: radiusd: #### Opening IP addresses and
Ports ####
Fri Dec 16 12:27:20 2011 : Debug: listen {
Fri Dec 16 12:27:20 2011 : Debug: 	type = "auth"
Fri Dec 16 12:27:20 2011 : Debug: 	ipaddr = 10.10.32.35
Fri Dec 16 12:27:20 2011 : Debug: 	port = 0
Fri Dec 16 12:27:20 2011 : Debug: }
Fri Dec 16 12:27:20 2011 : Debug: listen {
Fri Dec 16 12:27:20 2011 : Debug: 	type = "acct"
Fri Dec 16 12:27:20 2011 : Debug: 	ipaddr = 10.10.32.35
Fri Dec 16 12:27:20 2011 : Debug: 	port = 0
Fri Dec 16 12:27:20 2011 : Debug: }
Fri Dec 16 12:27:20 2011 : Debug: listen {
Fri Dec 16 12:27:20 2011 : Debug: 	type = "auth"
Fri Dec 16 12:27:20 2011 : Debug: 	ipaddr = 127.0.0.1
Fri Dec 16 12:27:20 2011 : Debug: 	port = 1812
Fri Dec 16 12:27:20 2011 : Debug: }
Fri Dec 16 12:27:20 2011 : Debug: listen {
Fri Dec 16 12:27:20 2011 : Debug: 	type = "acct"
Fri Dec 16 12:27:20 2011 : Debug: 	ipaddr = 127.0.0.1
Fri Dec 16 12:27:20 2011 : Debug: 	port = 1813
Fri Dec 16 12:27:20 2011 : Debug: }
Fri Dec 16 12:27:20 2011 : Debug: Listening on authentication address
10.10.32.35 port 1812
Fri Dec 16 12:27:20 2011 : Debug: Listening on accounting interface eth0
address 10.10.32.35 port 1813
Fri Dec 16 12:27:20 2011 : Debug: Listening on authentication address
127.0.0.1 port 1812 as server inner-tunnel
Fri Dec 16 12:27:20 2011 : Debug: Listening on accounting address 127.0.0.1
port 1813 as server inner-tunnel
Fri Dec 16 12:27:20 2011 : Debug: Listening on proxy address 10.10.32.35
port 1814
Fri Dec 16 12:27:20 2011 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 10.10.32.22 port 1042, id=17,
length=204
	Framed-MTU = 1466
	NAS-IP-Address = 10.0.1.1
	NAS-Identifier = "edu-teste"
	User-Name = "iscte@roam.fccn.pt"
	Service-Type = Framed-User
	NAS-Port = 253
	NAS-Port-Type = Ethernet
	NAS-Port-Id = "wl0"
	Called-Station-Id = "00-17-f2-e1-1b-95"
	Calling-Station-Id = "60-c5-47-8b-ff-46"
	Connect-Info = "CONNECT Ethernet 54Mbps Half duplex"
	EAP-Message = 0x0207001701697363746540726f616d2e6663636e2e7074
	Message-Authenticator = 0x5611cea73ddef4a81a8e8fa85556547b
Fri Dec 16 12:27:21 2011 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Fri Dec 16 12:27:21 2011 : Info: +- entering group authorize {...}
Fri Dec 16 12:27:21 2011 : Info: ++[preprocess] returns ok
Fri Dec 16 12:27:21 2011 : Info: [auth_log] 	expand:
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d ->
/var/log/freeradius/radacct/10.10.32.22/auth-detail-20111216
Fri Dec 16 12:27:21 2011 : Info: [auth_log]
/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands
to /var/log/freeradius/radacct/10.10.32.22/auth-detail-20111216
Fri Dec 16 12:27:21 2011 : Info: [auth_log] 	expand: %t -> Fri Dec 16
12:27:21 2011
Fri Dec 16 12:27:21 2011 : Info: ++[auth_log] returns ok
Fri Dec 16 12:27:21 2011 : Info: ++[request] returns ok
Fri Dec 16 12:27:21 2011 : Info: ++[chap] returns noop
Fri Dec 16 12:27:21 2011 : Info: ++[mschap] returns noop
Fri Dec 16 12:27:21 2011 : Info: [suffix] Looking up realm "roam.fccn.pt"
for User-Name = "iscte@roam.fccn.pt"
Fri Dec 16 12:27:21 2011 : Info: [suffix] Found realm "DEFAULT"
Fri Dec 16 12:27:21 2011 : Info: [suffix] Adding Realm = "DEFAULT"
Fri Dec 16 12:27:21 2011 : Info: [suffix] Proxying request from user iscte
to realm DEFAULT
Fri Dec 16 12:27:21 2011 : Info: [suffix] Preparing to proxy authentication
request to realm "DEFAULT"
Fri Dec 16 12:27:21 2011 : Info: ++[suffix] returns updated
Fri Dec 16 12:27:21 2011 : Info: [eap] Request is supposed to be proxied to
Realm DEFAULT.  Not doing EAP.
Fri Dec 16 12:27:21 2011 : Info: ++[eap] returns noop
Fri Dec 16 12:27:21 2011 : Info: [suffix] Request already proxied.
Ignoring.
Fri Dec 16 12:27:21 2011 : Info: ++[suffix] returns ok
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] Entering ldap_groupcmp()
Fri Dec 16 12:27:21 2011 : Info: [files] 	expand:
cn=Users,dc=wiscte,dc=wfarm -> cn=Users,dc=wiscte,dc=wfarm
Fri Dec 16 12:27:21 2011 : Info: [files] 	expand: %{Stripped-User-Name} ->
Fri Dec 16 12:27:21 2011 : Info: [files] 	... expanding second conditional
Fri Dec 16 12:27:21 2011 : Info: [files] 	expand: %{User-Name} ->
iscte@roam.fccn.pt
Fri Dec 16 12:27:21 2011 : Info: [files] 	expand:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) ->
(sAMAccountName=iscte@roam.fccn.pt)
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] attempting LDAP reconnection
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] (re)connect to 10.10.32.14:389,
authentication 0
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] bind as CN=Rui Fernando Ferreira
Ribeiro,CN=Users,DC=wiscte,DC=wfarm/xxxxxxx to 10.10.32.14:389
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] waiting for bind result ...
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] Bind was successful
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] performing search in
cn=Users,dc=wiscte,dc=wfarm, with filter (sAMAccountName=iscte@roam.fccn.pt)
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] object not found
Fri Dec 16 12:27:21 2011 : Debug: rlm_ldap::ldap_groupcmp: search failed
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] Entering ldap_groupcmp()
Fri Dec 16 12:27:21 2011 : Info: [files] 	expand:
cn=Users,dc=wiscte,dc=wfarm -> cn=Users,dc=wiscte,dc=wfarm
Fri Dec 16 12:27:21 2011 : Info: [files] 	expand: %{Stripped-User-Name} ->
Fri Dec 16 12:27:21 2011 : Info: [files] 	... expanding second conditional
Fri Dec 16 12:27:21 2011 : Info: [files] 	expand: %{User-Name} ->
iscte@roam.fccn.pt
Fri Dec 16 12:27:21 2011 : Info: [files] 	expand:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) ->
(sAMAccountName=iscte@roam.fccn.pt)
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] performing search in
cn=Users,dc=wiscte,dc=wfarm, with filter (sAMAccountName=iscte@roam.fccn.pt)
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] object not found
Fri Dec 16 12:27:21 2011 : Debug: rlm_ldap::ldap_groupcmp: search failed
Fri Dec 16 12:27:21 2011 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Fri Dec 16 12:27:21 2011 : Info: ++[files] returns noop
Fri Dec 16 12:27:21 2011 : Info: ++[expiration] returns noop
Fri Dec 16 12:27:21 2011 : Info: ++[logintime] returns noop
Fri Dec 16 12:27:21 2011 : Info: ++[pap] returns noop
Fri Dec 16 12:27:21 2011 : Info:   WARNING: Empty pre-proxy section.  Using
default return values.
Sending Access-Request of id 251 to 10.10.66.18 port 1812
	Framed-MTU = 1466
	NAS-IP-Address = 10.0.1.1
	NAS-Identifier = "edu-teste"
	User-Name = "iscte@roam.fccn.pt"
	Service-Type = Framed-User
	NAS-Port = 253
	NAS-Port-Type = Ethernet
	NAS-Port-Id = "wl0"
	Called-Station-Id = "00-17-f2-e1-1b-95"
	Calling-Station-Id = "60-c5-47-8b-ff-46"
	Connect-Info = "CONNECT Ethernet 54Mbps Half duplex"
	EAP-Message = 0x0207001701697363746540726f616d2e6663636e2e7074
	Message-Authenticator = 0x00000000000000000000000000000000
	Reply-Message = "Yes"
	Proxy-State = 0x3137
Fri Dec 16 12:27:21 2011 : Info: Proxying request 0 to home server
10.10.66.18 port 1812
Sending Access-Request of id 251 to 10.10.66.18 port 1812
	Framed-MTU = 1466
	NAS-IP-Address = 10.0.1.1
	NAS-Identifier = "edu-teste"
	User-Name = "iscte@roam.fccn.pt"
	Service-Type = Framed-User
	NAS-Port = 253
	NAS-Port-Type = Ethernet
	NAS-Port-Id = "wl0"
	Called-Station-Id = "00-17-f2-e1-1b-95"
	Calling-Station-Id = "60-c5-47-8b-ff-46"
	Connect-Info = "CONNECT Ethernet 54Mbps Half duplex"
	EAP-Message = 0x0207001701697363746540726f616d2e6663636e2e7074
	Message-Authenticator = 0x00000000000000000000000000000000
	Reply-Message = "Yes"
	Proxy-State = 0x3137
Fri Dec 16 12:27:21 2011 : Debug: Going to the next request
Fri Dec 16 12:27:21 2011 : Debug: Waking up in 0.9 seconds.
rad_recv: Access-Reject packet from host 10.10.66.18 port 1812, id=251,
length=24
	Proxy-State = 0x3137
Fri Dec 16 12:27:21 2011 : Info: # Executing section post-proxy from file
/etc/freeradius/sites-enabled/default
Fri Dec 16 12:27:21 2011 : Info: +- entering group post-proxy {...}
Fri Dec 16 12:27:21 2011 : Info: [post_proxy_log] 	expand:
/var/log/freeradius/radacct/%{Client-IP-Address}/post-proxy-detail-%Y%m%d ->
/var/log/freeradius/radacct/10.10.32.22/post-proxy-detail-20111216
Fri Dec 16 12:27:21 2011 : Info: [post_proxy_log]
/var/log/freeradius/radacct/%{Client-IP-Address}/post-proxy-detail-%Y%m%d
expands to
/var/log/freeradius/radacct/10.10.32.22/post-proxy-detail-20111216
Fri Dec 16 12:27:21 2011 : Info: [post_proxy_log] 	expand: %t -> Fri Dec 16
12:27:21 2011
Fri Dec 16 12:27:21 2011 : Info: ++[post_proxy_log] returns ok
Fri Dec 16 12:27:21 2011 : Info: Using Post-Auth-Type Reject
Fri Dec 16 12:27:21 2011 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Fri Dec 16 12:27:21 2011 : Info: +- entering group REJECT {...}
Fri Dec 16 12:27:21 2011 : Info: [attr_filter.access_reject] 	expand:
%{User-Name} -> iscte@roam.fccn.pt
Fri Dec 16 12:27:21 2011 : Debug:  attr_filter: Matched entry DEFAULT at
line 11
Fri Dec 16 12:27:21 2011 : Info: ++[attr_filter.access_reject] returns
updated
Sending Access-Reject of id 17 to 10.10.32.22 port 1042
Fri Dec 16 12:27:21 2011 : Info: Finished request 0.
Fri Dec 16 12:27:21 2011 : Debug: Going to the next request
Fri Dec 16 12:27:21 2011 : Debug: Waking up in 4.9 seconds.