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.