Thanks for the reply here is my debug log Looks like it is failing here. Tue Jun 21 09:35:28 2011 : Info: [mschap] No Cleartext-Password configured. Cannot create LM-Password. Tue Jun 21 09:35:28 2011 : Info: [mschap] No Cleartext-Password configured. Cannot create NT-Password. Tue Jun 21 09:35:28 2011 : Info: [mschap] NT Domain delimeter found, should we have enabled with_ntdomain_hack? Tue Jun 21 09:35:28 2011 : Info: [mschap] Told to do MS-CHAPv2 for SQA\Administrator with NT-Password Tue Jun 21 09:35:28 2011 : Info: [mschap] FAILED: No NT/LM-Password. Cannot perform authentication. Tue Jun 21 09:35:28 2011 : Info: [mschap] FAILED: MS-CHAP2-Response is incorrect Tue Jun 21 09:35:28 2011 : Info: ++[mschap] returns reject Tue Jun 21 09:35:28 2011 : Info: [eap] Freeing handler Tue Jun 21 09:35:28 2011 : Info: ++[eap] returns reject root@Ubuntu-FreeRadius:/etc/freeradius# freeradius -X -X -X Tue Jun 21 13:06:55 2011 : Info: FreeRADIUS Version 2.1.8, for host i486-pc-linux-gnu, built on Jan 5 2010 at 02:49:11 Tue Jun 21 13:06:55 2011 : Info: Copyright (C) 1999-2009 The FreeRADIUS server project and contributors. Tue Jun 21 13:06:55 2011 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Tue Jun 21 13:06:55 2011 : Info: PARTICULAR PURPOSE. Tue Jun 21 13:06:55 2011 : Info: You may redistribute copies of FreeRADIUS under the terms of the Tue Jun 21 13:06:55 2011 : Info: GNU General Public License v2. Tue Jun 21 13:06:55 2011 : Info: Starting - reading configuration files ... Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/radiusd.conf Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/proxy.conf Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/clients.conf Tue Jun 21 13:06:55 2011 : Debug: including files in directory /etc/freeradius/modules/ Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/mac2ip Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/sqlcounter_expire_on_login Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/wimax Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/detail.example.com Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/detail.log Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/digest Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/chap Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/pap Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/logintime Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/smsotp Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/ippool Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/sql_log Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/mac2vlan Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/krb5 Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/inner-eap Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/passwd Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/preprocess Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/expr Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/always Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/pam Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/exec Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/unix Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/etc_group Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/policy Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/cui Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/checkval Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/radutmp Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/echo Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/linelog Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/attr_rewrite Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/smbpasswd Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/acct_unique Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/ldap Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/detail Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/realm Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/expiration Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/otp Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/counter Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/ntlm_auth Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/sradutmp Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/mschap Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/perl Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/files Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/modules/attr_filter Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/eap.conf Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/policy.conf Tue Jun 21 13:06:55 2011 : Debug: including files in directory /etc/freeradius/sites-enabled/ Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Tue Jun 21 13:06:55 2011 : Debug: including configuration file /etc/freeradius/sites-enabled/default Tue Jun 21 13:06:55 2011 : Debug: main { Tue Jun 21 13:06:55 2011 : Debug: user = "freerad" Tue Jun 21 13:06:55 2011 : Debug: group = "freerad" Tue Jun 21 13:06:55 2011 : Debug: allow_core_dumps = no Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: including dictionary file /etc/freeradius/dictionary Tue Jun 21 13:06:55 2011 : Debug: main { Tue Jun 21 13:06:55 2011 : Debug: prefix = "/etc" Tue Jun 21 13:06:55 2011 : Debug: localstatedir = "/etc" Tue Jun 21 13:06:55 2011 : Debug: logdir = "/var/log/radius" Tue Jun 21 13:06:55 2011 : Debug: libdir = "/usr/lib/freeradius" Tue Jun 21 13:06:55 2011 : Debug: radacctdir = "/var/log/radius/radacct" Tue Jun 21 13:06:55 2011 : Debug: hostname_lookups = no Tue Jun 21 13:06:55 2011 : Debug: max_request_time = 30 Tue Jun 21 13:06:55 2011 : Debug: cleanup_delay = 5 Tue Jun 21 13:06:55 2011 : Debug: max_requests = 1024 Tue Jun 21 13:06:55 2011 : Debug: pidfile = "/etc/run/freeradius/freeradius.pid" Tue Jun 21 13:06:55 2011 : Debug: checkrad = "/etc/sbin/checkrad" Tue Jun 21 13:06:55 2011 : Debug: debug_level = 0 Tue Jun 21 13:06:55 2011 : Debug: proxy_requests = yes Tue Jun 21 13:06:55 2011 : Debug: log { Tue Jun 21 13:06:55 2011 : Debug: stripped_names = no Tue Jun 21 13:06:55 2011 : Debug: auth = no Tue Jun 21 13:06:55 2011 : Debug: auth_badpass = no Tue Jun 21 13:06:55 2011 : Debug: auth_goodpass = no Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: security { Tue Jun 21 13:06:55 2011 : Debug: max_attributes = 200 Tue Jun 21 13:06:55 2011 : Debug: reject_delay = 1 Tue Jun 21 13:06:55 2011 : Debug: status_server = yes Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: radiusd: #### Loading Realms and Home Servers #### Tue Jun 21 13:06:55 2011 : Debug: proxy server { Tue Jun 21 13:06:55 2011 : Debug: retry_delay = 5 Tue Jun 21 13:06:55 2011 : Debug: retry_count = 3 Tue Jun 21 13:06:55 2011 : Debug: default_fallback = no Tue Jun 21 13:06:55 2011 : Debug: dead_time = 120 Tue Jun 21 13:06:55 2011 : Debug: wake_all_if_all_dead = no Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: home_server localhost { Tue Jun 21 13:06:55 2011 : Debug: ipaddr = 127.0.0.1 Tue Jun 21 13:06:55 2011 : Debug: port = 1812 Tue Jun 21 13:06:55 2011 : Debug: type = "auth" Tue Jun 21 13:06:55 2011 : Debug: secret = "testing123" Tue Jun 21 13:06:55 2011 : Debug: response_window = 20 Tue Jun 21 13:06:55 2011 : Debug: max_outstanding = 65536 Tue Jun 21 13:06:55 2011 : Debug: require_message_authenticator = no Tue Jun 21 13:06:55 2011 : Debug: zombie_period = 40 Tue Jun 21 13:06:55 2011 : Debug: status_check = "status-server" Tue Jun 21 13:06:55 2011 : Debug: ping_interval = 30 Tue Jun 21 13:06:55 2011 : Debug: check_interval = 30 Tue Jun 21 13:06:55 2011 : Debug: num_answers_to_alive = 3 Tue Jun 21 13:06:55 2011 : Debug: num_pings_to_alive = 3 Tue Jun 21 13:06:55 2011 : Debug: revive_interval = 120 Tue Jun 21 13:06:55 2011 : Debug: status_check_timeout = 4 Tue Jun 21 13:06:55 2011 : Debug: irt = 2 Tue Jun 21 13:06:55 2011 : Debug: mrt = 16 Tue Jun 21 13:06:55 2011 : Debug: mrc = 5 Tue Jun 21 13:06:55 2011 : Debug: mrd = 30 Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: home_server_pool my_auth_failover { Tue Jun 21 13:06:55 2011 : Debug: type = fail-over Tue Jun 21 13:06:55 2011 : Debug: home_server = localhost Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: realm example.com { Tue Jun 21 13:06:55 2011 : Debug: auth_pool = my_auth_failover Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: realm LOCAL { Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: radiusd: #### Loading Clients #### Tue Jun 21 13:06:55 2011 : Debug: client localhost { Tue Jun 21 13:06:55 2011 : Debug: ipaddr = 127.0.0.1 Tue Jun 21 13:06:55 2011 : Debug: require_message_authenticator = no Tue Jun 21 13:06:55 2011 : Debug: secret = "testing123" Tue Jun 21 13:06:55 2011 : Debug: nastype = "other" Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: client 192.168.150.0/24 { Tue Jun 21 13:06:55 2011 : Debug: require_message_authenticator = no Tue Jun 21 13:06:55 2011 : Debug: secret = "enterasys" Tue Jun 21 13:06:55 2011 : Debug: shortname = "C3" Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: client 192.168.175.0/24 { Tue Jun 21 13:06:55 2011 : Debug: require_message_authenticator = no Tue Jun 21 13:06:55 2011 : Debug: secret = "enterasys" Tue Jun 21 13:06:55 2011 : Debug: shortname = "C5" Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: client 192.168.200.0/24 { Tue Jun 21 13:06:55 2011 : Debug: require_message_authenticator = no Tue Jun 21 13:06:55 2011 : Debug: secret = "enterasys" Tue Jun 21 13:06:55 2011 : Debug: shortname = "G3" Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: client 192.168.225.0/24 { Tue Jun 21 13:06:55 2011 : Debug: require_message_authenticator = no Tue Jun 21 13:06:55 2011 : Debug: secret = "enterasys" Tue Jun 21 13:06:55 2011 : Debug: shortname = "XSR" Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: client 10.1.146.0/24 { Tue Jun 21 13:06:55 2011 : Debug: require_message_authenticator = no Tue Jun 21 13:06:55 2011 : Debug: secret = "enterasys" Tue Jun 21 13:06:55 2011 : Debug: shortname = "NAT" Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: client 10.1.141.0/24 { Tue Jun 21 13:06:55 2011 : Debug: require_message_authenticator = no Tue Jun 21 13:06:55 2011 : Debug: secret = "enterasys" Tue Jun 21 13:06:55 2011 : Debug: shortname = "tony-network" Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: radiusd: #### Instantiating modules #### Tue Jun 21 13:06:55 2011 : Debug: instantiate { Tue Jun 21 13:06:55 2011 : Debug: (Loaded rlm_exec, checking if it's valid) Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to module rlm_exec Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating exec Tue Jun 21 13:06:55 2011 : Debug: exec { Tue Jun 21 13:06:55 2011 : Debug: wait = no Tue Jun 21 13:06:55 2011 : Debug: input_pairs = "request" Tue Jun 21 13:06:55 2011 : Debug: shell_escape = yes Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: (Loaded rlm_expr, checking if it's valid) Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to module rlm_expr Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating expr Tue Jun 21 13:06:55 2011 : Debug: (Loaded rlm_expiration, checking if it's valid) Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to module rlm_expiration Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating expiration Tue Jun 21 13:06:55 2011 : Debug: expiration { Tue Jun 21 13:06:55 2011 : Debug: reply-message = "Password Has Expired " Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: (Loaded rlm_logintime, checking if it's valid) Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to module rlm_logintime Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating logintime Tue Jun 21 13:06:55 2011 : Debug: logintime { Tue Jun 21 13:06:55 2011 : Debug: reply-message = "You are calling outside your allowed timespan " Tue Jun 21 13:06:55 2011 : Debug: minimum-timeout = 60 Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: radiusd: #### Loading Virtual Servers #### Tue Jun 21 13:06:55 2011 : Debug: server inner-tunnel { Tue Jun 21 13:06:55 2011 : Debug: modules { Tue Jun 21 13:06:55 2011 : Debug: Module: Checking authenticate {...} for more modules to load Tue Jun 21 13:06:55 2011 : Debug: (Loaded rlm_pap, checking if it's valid) Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to module rlm_pap Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating pap Tue Jun 21 13:06:55 2011 : Debug: pap { Tue Jun 21 13:06:55 2011 : Debug: encryption_scheme = "auto" Tue Jun 21 13:06:55 2011 : Debug: auto_header = no Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: (Loaded rlm_chap, checking if it's valid) Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to module rlm_chap Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating chap Tue Jun 21 13:06:55 2011 : Debug: (Loaded rlm_mschap, checking if it's valid) Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to module rlm_mschap Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating mschap Tue Jun 21 13:06:55 2011 : Debug: mschap { Tue Jun 21 13:06:55 2011 : Debug: use_mppe = yes Tue Jun 21 13:06:55 2011 : Debug: require_encryption = no Tue Jun 21 13:06:55 2011 : Debug: require_strong = no Tue Jun 21 13:06:55 2011 : Debug: with_ntdomain_hack = no Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: (Loaded rlm_unix, checking if it's valid) Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to module rlm_unix Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating unix Tue Jun 21 13:06:55 2011 : Debug: unix { Tue Jun 21 13:06:55 2011 : Debug: radwtmp = "/var/log/radius/radwtmp" Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: (Loaded rlm_eap, checking if it's valid) Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to module rlm_eap Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating eap Tue Jun 21 13:06:55 2011 : Debug: eap { Tue Jun 21 13:06:55 2011 : Debug: default_eap_type = "md5" Tue Jun 21 13:06:55 2011 : Debug: timer_expire = 60 Tue Jun 21 13:06:55 2011 : Debug: ignore_unknown_eap_types = no Tue Jun 21 13:06:55 2011 : Debug: cisco_accounting_username_bug = no Tue Jun 21 13:06:55 2011 : Debug: max_sessions = 4096 Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to sub-module rlm_eap_md5 Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating eap-md5 Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to sub-module rlm_eap_leap Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating eap-leap Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to sub-module rlm_eap_gtc Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating eap-gtc Tue Jun 21 13:06:55 2011 : Debug: gtc { Tue Jun 21 13:06:55 2011 : Debug: challenge = "Password: " Tue Jun 21 13:06:55 2011 : Debug: auth_type = "PAP" Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: Module: Linked to sub-module rlm_eap_tls Tue Jun 21 13:06:55 2011 : Debug: Module: Instantiating eap-tls Tue Jun 21 13:06:55 2011 : Debug: tls { Tue Jun 21 13:06:55 2011 : Debug: rsa_key_exchange = no Tue Jun 21 13:06:55 2011 : Debug: dh_key_exchange = yes Tue Jun 21 13:06:55 2011 : Debug: rsa_key_length = 512 Tue Jun 21 13:06:55 2011 : Debug: dh_key_length = 512 Tue Jun 21 13:06:55 2011 : Debug: verify_depth = 0 Tue Jun 21 13:06:55 2011 : Debug: pem_file_type = yes Tue Jun 21 13:06:55 2011 : Debug: private_key_file = "/etc/freeradius/certs/server.pem" Tue Jun 21 13:06:55 2011 : Debug: certificate_file = "/etc/freeradius/certs/server.pem" Tue Jun 21 13:06:55 2011 : Debug: CA_file = "/etc/freeradius/certs/ca.pem" Tue Jun 21 13:06:55 2011 : Debug: private_key_password = "password" Tue Jun 21 13:06:55 2011 : Debug: dh_file = "/etc/freeradius/certs/dh" Tue Jun 21 13:06:55 2011 : Debug: random_file = "/etc/freeradius/certs/random" Tue Jun 21 13:06:55 2011 : Debug: fragment_size = 1024 Tue Jun 21 13:06:55 2011 : Debug: include_length = yes Tue Jun 21 13:06:55 2011 : Debug: check_crl = no Tue Jun 21 13:06:55 2011 : Debug: cipher_list = "DEFAULT" Tue Jun 21 13:06:55 2011 : Debug: make_cert_command = "/etc/freeradius/certs/bootstrap" Tue Jun 21 13:06:55 2011 : Debug: cache { Tue Jun 21 13:06:55 2011 : Debug: enable = no Tue Jun 21 13:06:55 2011 : Debug: lifetime = 24 Tue Jun 21 13:06:55 2011 : Debug: max_entries = 255 Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:55 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Module: Linked to sub-module rlm_eap_ttls Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating eap-ttls Tue Jun 21 13:06:56 2011 : Debug: ttls { Tue Jun 21 13:06:56 2011 : Debug: default_eap_type = "md5" Tue Jun 21 13:06:56 2011 : Debug: copy_request_to_tunnel = no Tue Jun 21 13:06:56 2011 : Debug: use_tunneled_reply = no Tue Jun 21 13:06:56 2011 : Debug: virtual_server = "inner-tunnel" Tue Jun 21 13:06:56 2011 : Debug: include_length = yes Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Module: Linked to sub-module rlm_eap_peap Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating eap-peap Tue Jun 21 13:06:56 2011 : Debug: peap { Tue Jun 21 13:06:56 2011 : Debug: default_eap_type = "mschapv2" Tue Jun 21 13:06:56 2011 : Debug: copy_request_to_tunnel = no Tue Jun 21 13:06:56 2011 : Debug: use_tunneled_reply = no Tue Jun 21 13:06:56 2011 : Debug: proxy_tunneled_request_as_eap = yes Tue Jun 21 13:06:56 2011 : Debug: virtual_server = "inner-tunnel" Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Module: Linked to sub-module rlm_eap_mschapv2 Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating eap-mschapv2 Tue Jun 21 13:06:56 2011 : Debug: mschapv2 { Tue Jun 21 13:06:56 2011 : Debug: with_ntdomain_hack = no Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: (Loaded rlm_realm, checking if it's valid) Tue Jun 21 13:06:56 2011 : Debug: Module: Linked to module rlm_realm Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating suffix Tue Jun 21 13:06:56 2011 : Debug: realm suffix { Tue Jun 21 13:06:56 2011 : Debug: format = "suffix" Tue Jun 21 13:06:56 2011 : Debug: delimiter = "@" Tue Jun 21 13:06:56 2011 : Debug: ignore_default = no Tue Jun 21 13:06:56 2011 : Debug: ignore_null = no Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: (Loaded rlm_files, checking if it's valid) Tue Jun 21 13:06:56 2011 : Debug: Module: Linked to module rlm_files Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating files Tue Jun 21 13:06:56 2011 : Debug: files { Tue Jun 21 13:06:56 2011 : Debug: usersfile = "/etc/freeradius/users" Tue Jun 21 13:06:56 2011 : Debug: acctusersfile = "/etc/freeradius/acct_users" Tue Jun 21 13:06:56 2011 : Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users" Tue Jun 21 13:06:56 2011 : Debug: compat = "no" Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Module: Checking session {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: (Loaded rlm_radutmp, checking if it's valid) Tue Jun 21 13:06:56 2011 : Debug: Module: Linked to module rlm_radutmp Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating radutmp Tue Jun 21 13:06:56 2011 : Debug: radutmp { Tue Jun 21 13:06:56 2011 : Debug: filename = "/var/log/radius/radutmp" Tue Jun 21 13:06:56 2011 : Debug: username = "%{User-Name}" Tue Jun 21 13:06:56 2011 : Debug: case_sensitive = yes Tue Jun 21 13:06:56 2011 : Debug: check_with_nas = yes Tue Jun 21 13:06:56 2011 : Debug: perm = 384 Tue Jun 21 13:06:56 2011 : Debug: callerid = yes Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: Module: Checking post-auth {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: (Loaded rlm_attr_filter, checking if it's valid) Tue Jun 21 13:06:56 2011 : Debug: Module: Linked to module rlm_attr_filter Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating attr_filter.access_reject Tue Jun 21 13:06:56 2011 : Debug: attr_filter attr_filter.access_reject { Tue Jun 21 13:06:56 2011 : Debug: attrsfile = "/etc/freeradius/attrs.access_reject" Tue Jun 21 13:06:56 2011 : Debug: key = "%{User-Name}" Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: } # modules Tue Jun 21 13:06:56 2011 : Debug: } # server Tue Jun 21 13:06:56 2011 : Debug: server { Tue Jun 21 13:06:56 2011 : Debug: modules { Tue Jun 21 13:06:56 2011 : Debug: Module: Checking authenticate {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: (Loaded rlm_preprocess, checking if it's valid) Tue Jun 21 13:06:56 2011 : Debug: Module: Linked to module rlm_preprocess Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating preprocess Tue Jun 21 13:06:56 2011 : Debug: preprocess { Tue Jun 21 13:06:56 2011 : Debug: huntgroups = "/etc/freeradius/huntgroups" Tue Jun 21 13:06:56 2011 : Debug: hints = "/etc/freeradius/hints" Tue Jun 21 13:06:56 2011 : Debug: with_ascend_hack = no Tue Jun 21 13:06:56 2011 : Debug: ascend_channels_per_line = 23 Tue Jun 21 13:06:56 2011 : Debug: with_ntdomain_hack = no Tue Jun 21 13:06:56 2011 : Debug: with_specialix_jetstream_hack = no Tue Jun 21 13:06:56 2011 : Debug: with_cisco_vsa_hack = no Tue Jun 21 13:06:56 2011 : Debug: with_alvarion_vsa_hack = no Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Module: Checking preacct {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Tue Jun 21 13:06:56 2011 : Debug: Module: Linked to module rlm_acct_unique Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating acct_unique Tue Jun 21 13:06:56 2011 : Debug: acct_unique { Tue Jun 21 13:06:56 2011 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Module: Checking accounting {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: (Loaded rlm_detail, checking if it's valid) Tue Jun 21 13:06:56 2011 : Debug: Module: Linked to module rlm_detail Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating detail Tue Jun 21 13:06:56 2011 : Debug: detail { Tue Jun 21 13:06:56 2011 : Debug: detailfile = "/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Tue Jun 21 13:06:56 2011 : Debug: header = "%t" Tue Jun 21 13:06:56 2011 : Debug: detailperm = 384 Tue Jun 21 13:06:56 2011 : Debug: dirperm = 493 Tue Jun 21 13:06:56 2011 : Debug: locking = no Tue Jun 21 13:06:56 2011 : Debug: log_packet_header = no Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Module: Instantiating attr_filter.accounting_response Tue Jun 21 13:06:56 2011 : Debug: attr_filter attr_filter.accounting_response { Tue Jun 21 13:06:56 2011 : Debug: attrsfile = "/etc/freeradius/attrs.accounting_response" Tue Jun 21 13:06:56 2011 : Debug: key = "%{User-Name}" Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Module: Checking session {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: Module: Checking post-auth {...} for more modules to load Tue Jun 21 13:06:56 2011 : Debug: } # modules Tue Jun 21 13:06:56 2011 : Debug: } # server Tue Jun 21 13:06:56 2011 : Debug: radiusd: #### Opening IP addresses and Ports #### Tue Jun 21 13:06:56 2011 : Debug: listen { Tue Jun 21 13:06:56 2011 : Debug: type = "auth" Tue Jun 21 13:06:56 2011 : Debug: ipaddr = 20.1.180.45 Tue Jun 21 13:06:56 2011 : Debug: port = 0 Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: listen { Tue Jun 21 13:06:56 2011 : Debug: type = "acct" Tue Jun 21 13:06:56 2011 : Debug: ipaddr = * Tue Jun 21 13:06:56 2011 : Debug: port = 0 Tue Jun 21 13:06:56 2011 : Debug: } Tue Jun 21 13:06:56 2011 : Debug: Listening on authentication address 20.1.180.45 port 1812 Tue Jun 21 13:06:56 2011 : Debug: Listening on accounting address * port 1813 Tue Jun 21 13:06:56 2011 : Debug: Listening on proxy address 20.1.180.45 port 1814 Tue Jun 21 13:06:56 2011 : Info: Ready to process requests. rad_recv: Access-Request packet from host 192.168.175.60 port 49369, id=49, length=157 User-Name = "SQA\\Administrator" Service-Type = Framed-User Called-Station-Id = "00-1F-45-47-49-84" Calling-Station-Id = "00-18-8B-B9-C2-E3" NAS-IP-Address = 192.168.175.60 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet EAP-Message = 0x02010016015351415c41646d696e6973747261746f72 Message-Authenticator = 0x7c48a72d3cd785ad696afb62b9200c12 Tue Jun 21 13:07:07 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:07 2011 : Info: ++[preprocess] returns ok Tue Jun 21 13:07:07 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:07 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:07 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:07 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:07 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:07 2011 : Info: [eap] EAP packet type response id 1 length 22 Tue Jun 21 13:07:07 2011 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Tue Jun 21 13:07:07 2011 : Info: ++[eap] returns updated Tue Jun 21 13:07:07 2011 : Info: ++[unix] returns notfound Tue Jun 21 13:07:07 2011 : Info: [files] users: Matched entry SQA\Administrator at line 93 Tue Jun 21 13:07:07 2011 : Info: ++[files] returns ok Tue Jun 21 13:07:07 2011 : Info: ++[expiration] returns noop Tue Jun 21 13:07:07 2011 : Info: ++[logintime] returns noop Tue Jun 21 13:07:07 2011 : Info: [pap] Found existing Auth-Type, not changing it. Tue Jun 21 13:07:07 2011 : Info: ++[pap] returns noop Tue Jun 21 13:07:07 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:07 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:07 2011 : Info: [eap] EAP Identity Tue Jun 21 13:07:07 2011 : Info: [eap] processing type md5 Tue Jun 21 13:07:07 2011 : Debug: rlm_eap_md5: Issuing Challenge Tue Jun 21 13:07:07 2011 : Info: ++[eap] returns handled Sending Access-Challenge of id 49 to 192.168.175.60 port 49369 Filter-Id = "Enterasys:version=1:mgmt=su:policy=PEAP" EAP-Message = 0x01020016041098dd3fdd618fe72b12d5e38b61fd54a8 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfa9c4868fa9e4c6ee67926093dbdabe5 Tue Jun 21 13:07:07 2011 : Info: Finished request 0. Tue Jun 21 13:07:07 2011 : Debug: Going to the next request Tue Jun 21 13:07:07 2011 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.175.60 port 49369, id=50, length=159 User-Name = "SQA\\Administrator" Service-Type = Framed-User Called-Station-Id = "00-1F-45-47-49-84" Calling-Station-Id = "00-18-8B-B9-C2-E3" NAS-IP-Address = 192.168.175.60 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet State = 0xfa9c4868fa9e4c6ee67926093dbdabe5 EAP-Message = 0x020200060319 Message-Authenticator = 0x3a89f8cb98339ebc60d975363cae3028 Tue Jun 21 13:07:08 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:08 2011 : Info: ++[preprocess] returns ok Tue Jun 21 13:07:08 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:08 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:08 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:08 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:08 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:08 2011 : Info: [eap] EAP packet type response id 2 length 6 Tue Jun 21 13:07:08 2011 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Tue Jun 21 13:07:08 2011 : Info: ++[eap] returns updated Tue Jun 21 13:07:08 2011 : Info: ++[unix] returns notfound Tue Jun 21 13:07:08 2011 : Info: [files] users: Matched entry SQA\Administrator at line 93 Tue Jun 21 13:07:08 2011 : Info: ++[files] returns ok Tue Jun 21 13:07:08 2011 : Info: ++[expiration] returns noop Tue Jun 21 13:07:08 2011 : Info: ++[logintime] returns noop Tue Jun 21 13:07:08 2011 : Info: [pap] Found existing Auth-Type, not changing it. Tue Jun 21 13:07:08 2011 : Info: ++[pap] returns noop Tue Jun 21 13:07:08 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:08 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:08 2011 : Info: [eap] Request found, released from the list Tue Jun 21 13:07:08 2011 : Info: [eap] EAP NAK Tue Jun 21 13:07:08 2011 : Info: [eap] EAP-NAK asked for EAP-Type/peap Tue Jun 21 13:07:08 2011 : Info: [eap] processing type tls Tue Jun 21 13:07:08 2011 : Info: [tls] Initiate Tue Jun 21 13:07:08 2011 : Info: [tls] Start returned 1 Tue Jun 21 13:07:08 2011 : Info: ++[eap] returns handled Sending Access-Challenge of id 50 to 192.168.175.60 port 49369 Filter-Id = "Enterasys:version=1:mgmt=su:policy=PEAP" EAP-Message = 0x010300061920 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfa9c4868fb9f516ee67926093dbdabe5 Tue Jun 21 13:07:08 2011 : Info: Finished request 1. Tue Jun 21 13:07:08 2011 : Debug: Going to the next request Tue Jun 21 13:07:08 2011 : Debug: Waking up in 3.9 seconds. rad_recv: Access-Request packet from host 192.168.175.60 port 49369, id=51, length=284 User-Name = "SQA\\Administrator" Service-Type = Framed-User Called-Station-Id = "00-1F-45-47-49-84" Calling-Station-Id = "00-18-8B-B9-C2-E3" NAS-IP-Address = 192.168.175.60 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet State = 0xfa9c4868fb9f516ee67926093dbdabe5 EAP-Message = 0x0203008319800000007916030100740100007003014e00d091a8b128b95191d1b28554012484ea27af95f7978c7c88f46677b70cad000018002f00350005000ac013c014c009c00a00320038001300040100002fff010001000000001600140000117371615c61646d696e6973747261746f72000a0006000400170018000b00020100 Message-Authenticator = 0xeebcdd38318368737ff3a493d034627f Tue Jun 21 13:07:08 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:08 2011 : Info: ++[preprocess] returns ok Tue Jun 21 13:07:08 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:08 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:08 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:08 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:08 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:08 2011 : Info: [eap] EAP packet type response id 3 length 131 Tue Jun 21 13:07:08 2011 : Info: [eap] Continuing tunnel setup. Tue Jun 21 13:07:08 2011 : Info: ++[eap] returns ok Tue Jun 21 13:07:08 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:08 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:08 2011 : Info: [eap] Request found, released from the list Tue Jun 21 13:07:08 2011 : Info: [eap] EAP/peap Tue Jun 21 13:07:08 2011 : Info: [eap] processing type peap Tue Jun 21 13:07:08 2011 : Info: [peap] processing EAP-TLS Tue Jun 21 13:07:08 2011 : Debug: TLS Length 121 Tue Jun 21 13:07:08 2011 : Info: [peap] Length Included Tue Jun 21 13:07:08 2011 : Info: [peap] eaptls_verify returned 11 Tue Jun 21 13:07:08 2011 : Info: [peap] (other): before/accept initialization Tue Jun 21 13:07:08 2011 : Info: [peap] TLS_accept: before/accept initialization Tue Jun 21 13:07:08 2011 : Info: [peap] <<< TLS 1.0 Handshake [length 0074], ClientHello Tue Jun 21 13:07:08 2011 : Info: [peap] TLS_accept: SSLv3 read client hello A Tue Jun 21 13:07:08 2011 : Info: [peap] >>> TLS 1.0 Handshake [length 0031], ServerHello Tue Jun 21 13:07:08 2011 : Info: [peap] TLS_accept: SSLv3 write server hello A Tue Jun 21 13:07:08 2011 : Info: [peap] >>> TLS 1.0 Handshake [length 0885], Certificate Tue Jun 21 13:07:08 2011 : Info: [peap] TLS_accept: SSLv3 write certificate A Tue Jun 21 13:07:08 2011 : Info: [peap] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone Tue Jun 21 13:07:08 2011 : Info: [peap] TLS_accept: SSLv3 write server done A Tue Jun 21 13:07:08 2011 : Info: [peap] TLS_accept: SSLv3 flush data Tue Jun 21 13:07:08 2011 : Info: [peap] TLS_accept: Need to read more data: SSLv3 read client certificate A Tue Jun 21 13:07:08 2011 : Debug: In SSL Handshake Phase Tue Jun 21 13:07:08 2011 : Debug: In SSL Accept mode Tue Jun 21 13:07:08 2011 : Info: [peap] eaptls_process returned 13 Tue Jun 21 13:07:08 2011 : Info: [peap] EAPTLS_HANDLED Tue Jun 21 13:07:08 2011 : Info: ++[eap] returns handled Sending Access-Challenge of id 51 to 192.168.175.60 port 49369 EAP-Message = 0x0104040019c0000008c916030100310200002d03014e00cfbcc0b358875c40f5bedd5bb9431cbc6483970c10cf692e41297c8c28c900002f000005ff0100010016030108850b00088100087e0003ba308203b63082029ea003020102020101300d06092a864886f70d0101040500308199310b3009060355040613025553310b3009060355040813024d413110300e06035504071307416e646f766572311b3019060355040a1312456e74657261737973204e6574776f726b733124302206092a864886f70d0109011615737570706f727440656e746572617379732e636f6d312830260603550403131f535141204672656552616469757320526f6f EAP-Message = 0x74204365727469666963617465301e170d3131303531363230333732395a170d3231303531333230333732395a308189310b3009060355040613025553310b3009060355040813024d41311b3019060355040a1312456e74657261737973204e6574776f726b73312a3028060355040313215351412046726565526164697573205365727665722043657274696669636174653124302206092a864886f70d0109011615737570706f727440656e746572617379732e636f6d30820122300d06092a864886f70d01010105000382010f003082010a0282010100c572ff3f1e2c9bf418de5de7529c70601118287b6c825610fa2f814adefde8502fb35f EAP-Message = 0x2e87aef5c5ad67737b8217b9aef1f3b182f40c9933dd9774386b4f59143866b7d4ca2b508e63bf306737d7c3d44ec924c99efe55ba2299b38055e9096f4d0b2e0d57b334171b1a831d2f4876f3a0c423a068e98a2a1d436ba6c1493fc24a2625f9a2880ce3e408acafc5a00db869f9963e34b8beac9ac1f855a4209915077f001d94fc7faf6f875611910726f23984938dc71c318de89f5b3c1db3e6cddae763ae2fde6a82812444535d8312e88ba32fe04976847fac1bc6c27545464bd94e2e552fe4a68929eb172819f59cdcf3dae2bb85c374259b5aa3f1b6b7ecb50203010001a317301530130603551d25040c300a06082b06010505070301300d EAP-Message = 0x06092a864886f70d010104050003820101008e1b34368ebbaa77a13dc485f5aff69b4dbeb68d92644c02709aedab34a68130818ec1607752da5ed29ea77650ae330b10afac8b88d8b23ed8d53f0e40f24fda758ef2add2999fba306f85d7f0e913bc6de50c9d627ab8f17ed741ac4f9d0c3c38a8dfb40191ace57fdd78f0f6d88906fe6841f74642230cd3fef052fcc9dfd4435bac82925b4dfd9f1eda672fe461d0a671f724b1f6c4956d2dbedd6819e1fae49cda141a0d5bc00a62bec5a74f347c35736882ee6a107e97473a75c5c4e2add6390c3dd6e73ce02cc0812f125459b819bcae7bf70cf7a819a4c772302bf681e700af354d3a994009f1d3 EAP-Message = 0x828801a751e8aa4c229cc3ab Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfa9c4868f898516ee67926093dbdabe5 Tue Jun 21 13:07:08 2011 : Info: Finished request 2. Tue Jun 21 13:07:08 2011 : Debug: Going to the next request Tue Jun 21 13:07:08 2011 : Debug: Waking up in 3.9 seconds. rad_recv: Access-Request packet from host 192.168.175.60 port 49369, id=52, length=159 User-Name = "SQA\\Administrator" Service-Type = Framed-User Called-Station-Id = "00-1F-45-47-49-84" Calling-Station-Id = "00-18-8B-B9-C2-E3" NAS-IP-Address = 192.168.175.60 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet State = 0xfa9c4868f898516ee67926093dbdabe5 EAP-Message = 0x020400061900 Message-Authenticator = 0x46755f288c55faef4470fbd80b662371 Tue Jun 21 13:07:08 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:08 2011 : Info: ++[preprocess] returns ok Tue Jun 21 13:07:08 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:08 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:08 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:08 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:08 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:08 2011 : Info: [eap] EAP packet type response id 4 length 6 Tue Jun 21 13:07:08 2011 : Info: [eap] Continuing tunnel setup. Tue Jun 21 13:07:08 2011 : Info: ++[eap] returns ok Tue Jun 21 13:07:08 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:08 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:08 2011 : Info: [eap] Request found, released from the list Tue Jun 21 13:07:08 2011 : Info: [eap] EAP/peap Tue Jun 21 13:07:08 2011 : Info: [eap] processing type peap Tue Jun 21 13:07:08 2011 : Info: [peap] processing EAP-TLS Tue Jun 21 13:07:08 2011 : Info: [peap] Received TLS ACK Tue Jun 21 13:07:08 2011 : Info: [peap] ACK handshake fragment handler Tue Jun 21 13:07:08 2011 : Info: [peap] eaptls_verify returned 1 Tue Jun 21 13:07:08 2011 : Info: [peap] eaptls_process returned 13 Tue Jun 21 13:07:08 2011 : Info: [peap] EAPTLS_HANDLED Tue Jun 21 13:07:08 2011 : Info: ++[eap] returns handled Sending Access-Challenge of id 52 to 192.168.175.60 port 49369 EAP-Message = 0x010503fc1940a7f1e72ff6139a062d0004be308204ba308203a2a003020102020900dbd5d3879aa8ad84300d06092a864886f70d0101050500308199310b3009060355040613025553310b3009060355040813024d413110300e06035504071307416e646f766572311b3019060355040a1312456e74657261737973204e6574776f726b733124302206092a864886f70d0109011615737570706f727440656e746572617379732e636f6d312830260603550403131f535141204672656552616469757320526f6f74204365727469666963617465301e170d3131303531363230333732385a170d3231303531333230333732385a308199310b300906 EAP-Message = 0x0355040613025553310b3009060355040813024d413110300e06035504071307416e646f766572311b3019060355040a1312456e74657261737973204e6574776f726b733124302206092a864886f70d0109011615737570706f727440656e746572617379732e636f6d312830260603550403131f535141204672656552616469757320526f6f7420436572746966696361746530820122300d06092a864886f70d01010105000382010f003082010a0282010100ba5ff7eca38688710d603e1d5cd0da3808e0d1f6cc150c4db2f79381be2c9794b0a30a53418877e2cd5537324f84d306a0e9c47b68d95e2a7c32dbe7a5aa8a6ba088bcf2d6e92522 EAP-Message = 0x87dd001a74c75e3516e85abf7629e1559eaa50930c752d3661d112b615adb7131b916e427abe3c805d4da4e63393c9f000ffc4da814ab997077dc91e6e1c69ccf73f4650f71ac4bea3bca12d445ed9a2a6f3d1fa3e6e136085a8b61234c05b53af6d902a71d2d2dfd1d66ba19dacd4187e71732fa06e65f098bc3e54fdef1940464bb0bcab812f81b0e52ad7936e9fdbb9340687787c7581909201460b56decd0818ea0150a2df97d3d0f37707f34d2723fcdea6f297ed3d0203010001a38201013081fe301d0603551d0e041604145361843fe756ebbfd78b683f7ff0ab9394c237c93081ce0603551d230481c63081c380145361843fe756ebbfd78b EAP-Message = 0x683f7ff0ab9394c237c9a1819fa4819c308199310b3009060355040613025553310b3009060355040813024d413110300e06035504071307416e646f766572311b3019060355040a1312456e74657261737973204e6574776f726b733124302206092a864886f70d0109011615737570706f727440656e746572617379732e636f6d312830260603550403131f535141204672656552616469757320526f6f74204365727469666963617465820900dbd5d3879aa8ad84300c0603551d13040530030101ff300d06092a864886f70d01010505000382010100150875ab6f7d235df9461e53a5eb6af98a6f3f3224216a6272e6a099d028dad4287142d2 EAP-Message = 0x1ba9e41ca593bf7c Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfa9c4868f999516ee67926093dbdabe5 Tue Jun 21 13:07:08 2011 : Info: Finished request 3. Tue Jun 21 13:07:08 2011 : Debug: Going to the next request Tue Jun 21 13:07:08 2011 : Debug: Waking up in 3.9 seconds. rad_recv: Access-Request packet from host 192.168.175.60 port 49369, id=53, length=159 User-Name = "SQA\\Administrator" Service-Type = Framed-User Called-Station-Id = "00-1F-45-47-49-84" Calling-Station-Id = "00-18-8B-B9-C2-E3" NAS-IP-Address = 192.168.175.60 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet State = 0xfa9c4868f999516ee67926093dbdabe5 EAP-Message = 0x020500061900 Message-Authenticator = 0x464d50fa189ac461396230ba78c6f4a8 Tue Jun 21 13:07:08 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:08 2011 : Info: ++[preprocess] returns ok Tue Jun 21 13:07:08 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:08 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:08 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:08 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:08 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:08 2011 : Info: [eap] EAP packet type response id 5 length 6 Tue Jun 21 13:07:08 2011 : Info: [eap] Continuing tunnel setup. Tue Jun 21 13:07:08 2011 : Info: ++[eap] returns ok Tue Jun 21 13:07:08 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:08 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:08 2011 : Info: [eap] Request found, released from the list Tue Jun 21 13:07:08 2011 : Info: [eap] EAP/peap Tue Jun 21 13:07:08 2011 : Info: [eap] processing type peap Tue Jun 21 13:07:08 2011 : Info: [peap] processing EAP-TLS Tue Jun 21 13:07:08 2011 : Info: [peap] Received TLS ACK Tue Jun 21 13:07:08 2011 : Info: [peap] ACK handshake fragment handler Tue Jun 21 13:07:08 2011 : Info: [peap] eaptls_verify returned 1 Tue Jun 21 13:07:08 2011 : Info: [peap] eaptls_process returned 13 Tue Jun 21 13:07:08 2011 : Info: [peap] EAPTLS_HANDLED Tue Jun 21 13:07:08 2011 : Info: ++[eap] returns handled Sending Access-Challenge of id 53 to 192.168.175.60 port 49369 EAP-Message = 0x010600e319009295ba455cbc8a3b52cbde90139c8f9939a1a7bc92170dd2eb28665cb9f662da4df21d1e5a4843e4a82e0b462e31062e41914f9f7aa5166bafeedcaeec0a3dc72ce2170ac9eb8744ff3c66b02275e5d22fde73c9a091c2f92df5b696b2dcd6a2d53eb7237b523e1869a928e8ca794ecc0f3e024af4b9728ad0ccff0a1319e2b2928d874daa8f6783ad4133b7962c23b60dbe05646d7a41b551bf588d3907c769439d6ba29fd099623c59a68c5bb62a5cb463138dfc459c6f5a9b829399d47400f65effc50422500a80896b95226cc41dd0bddc8c16030100040e000000 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfa9c4868fe9a516ee67926093dbdabe5 Tue Jun 21 13:07:08 2011 : Info: Finished request 4. Tue Jun 21 13:07:08 2011 : Debug: Going to the next request Tue Jun 21 13:07:08 2011 : Debug: Waking up in 3.9 seconds. rad_recv: Access-Request packet from host 192.168.175.60 port 49369, id=54, length=491 User-Name = "SQA\\Administrator" Service-Type = Framed-User Called-Station-Id = "00-1F-45-47-49-84" Calling-Station-Id = "00-18-8B-B9-C2-E3" NAS-IP-Address = 192.168.175.60 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet State = 0xfa9c4868fe9a516ee67926093dbdabe5 EAP-Message = 0x0206015019800000014616030101061000010201006016999f497869cf5909a29d539a595236d8d7d481a3d40ee58d8359b5e83d124d0b3a0643a0d2a7f5cc9b6d95ada9df2dcf5d6e0a0e0fa53a55bb52a6e9af7d5b2db3d6784aa0e51f785a039733eb175892a7e334f01d8a7c3ac3754c911184ed12b111f1a386510e7eb7b5190c3928979d9b9488f39a40d1caadc29373eed61c1a7b2b46f19650a6aa90d35d886a2386346066af0c8dd2c9991eeccbca7bd0284d3ded62484352cd7e33b6ba9af835c89c2c0d6d4d813f8ef290ee5a1bee8e8c739344105f47dcecca0d7f2062a2e9916fb33cabd81bb1e07ce0e857e937aef7c503d19ed1e50d EAP-Message = 0x3708883971c2fa73c90267b1e2920e41604d57f2b6f7bf4514030100010116030100309e7acad7a738358a9edf66bde721e2eedcac64b5d76b706f3effa1f95647b968f1c14ba5edc61d6afcb66e17bf07e764 Message-Authenticator = 0x003e2d4dc59da1079886c948b73ca0bc Tue Jun 21 13:07:08 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:08 2011 : Info: ++[preprocess] returns ok Tue Jun 21 13:07:08 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:08 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:08 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:08 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:08 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:08 2011 : Info: [eap] EAP packet type response id 6 length 253 Tue Jun 21 13:07:08 2011 : Info: [eap] Continuing tunnel setup. Tue Jun 21 13:07:08 2011 : Info: ++[eap] returns ok Tue Jun 21 13:07:08 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:08 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:08 2011 : Info: [eap] Request found, released from the list Tue Jun 21 13:07:08 2011 : Info: [eap] EAP/peap Tue Jun 21 13:07:08 2011 : Info: [eap] processing type peap Tue Jun 21 13:07:08 2011 : Info: [peap] processing EAP-TLS Tue Jun 21 13:07:08 2011 : Debug: TLS Length 326 Tue Jun 21 13:07:08 2011 : Info: [peap] Length Included Tue Jun 21 13:07:08 2011 : Info: [peap] eaptls_verify returned 11 Tue Jun 21 13:07:08 2011 : Info: [peap] <<< TLS 1.0 Handshake [length 0106], ClientKeyExchange Tue Jun 21 13:07:09 2011 : Info: [peap] TLS_accept: SSLv3 read client key exchange A Tue Jun 21 13:07:09 2011 : Info: [peap] <<< TLS 1.0 ChangeCipherSpec [length 0001] Tue Jun 21 13:07:09 2011 : Info: [peap] <<< TLS 1.0 Handshake [length 0010], Finished Tue Jun 21 13:07:09 2011 : Info: [peap] TLS_accept: SSLv3 read finished A Tue Jun 21 13:07:09 2011 : Info: [peap] >>> TLS 1.0 ChangeCipherSpec [length 0001] Tue Jun 21 13:07:09 2011 : Info: [peap] TLS_accept: SSLv3 write change cipher spec A Tue Jun 21 13:07:09 2011 : Info: [peap] >>> TLS 1.0 Handshake [length 0010], Finished Tue Jun 21 13:07:09 2011 : Info: [peap] TLS_accept: SSLv3 write finished A Tue Jun 21 13:07:09 2011 : Info: [peap] TLS_accept: SSLv3 flush data Tue Jun 21 13:07:09 2011 : Info: [peap] (other): SSL negotiation finished successfully Tue Jun 21 13:07:09 2011 : Debug: SSL Connection Established Tue Jun 21 13:07:09 2011 : Info: [peap] eaptls_process returned 13 Tue Jun 21 13:07:09 2011 : Info: [peap] EAPTLS_HANDLED Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns handled Sending Access-Challenge of id 54 to 192.168.175.60 port 49369 EAP-Message = 0x010700411900140301000101160301003005e74ab74ce53c43c0e5e3a5fef907ee826f8475864ef53e24b68e420527dd5d923a4909cd77edab2c213b31fca8a275 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfa9c4868ff9b516ee67926093dbdabe5 Tue Jun 21 13:07:09 2011 : Info: Finished request 5. Tue Jun 21 13:07:09 2011 : Debug: Going to the next request Tue Jun 21 13:07:09 2011 : Debug: Waking up in 3.9 seconds. rad_recv: Access-Request packet from host 192.168.175.60 port 49369, id=55, length=159 User-Name = "SQA\\Administrator" Service-Type = Framed-User Called-Station-Id = "00-1F-45-47-49-84" Calling-Station-Id = "00-18-8B-B9-C2-E3" NAS-IP-Address = 192.168.175.60 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet State = 0xfa9c4868ff9b516ee67926093dbdabe5 EAP-Message = 0x020700061900 Message-Authenticator = 0x6c971efaa56daa1eff637df5ea582180 Tue Jun 21 13:07:09 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:09 2011 : Info: ++[preprocess] returns ok Tue Jun 21 13:07:09 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:09 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:09 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:09 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:09 2011 : Info: [eap] EAP packet type response id 7 length 6 Tue Jun 21 13:07:09 2011 : Info: [eap] Continuing tunnel setup. Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns ok Tue Jun 21 13:07:09 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:09 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:09 2011 : Info: [eap] Request found, released from the list Tue Jun 21 13:07:09 2011 : Info: [eap] EAP/peap Tue Jun 21 13:07:09 2011 : Info: [eap] processing type peap Tue Jun 21 13:07:09 2011 : Info: [peap] processing EAP-TLS Tue Jun 21 13:07:09 2011 : Info: [peap] Received TLS ACK Tue Jun 21 13:07:09 2011 : Info: [peap] ACK handshake is finished Tue Jun 21 13:07:09 2011 : Info: [peap] eaptls_verify returned 3 Tue Jun 21 13:07:09 2011 : Info: [peap] eaptls_process returned 3 Tue Jun 21 13:07:09 2011 : Info: [peap] EAPTLS_SUCCESS Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns handled Sending Access-Challenge of id 55 to 192.168.175.60 port 49369 EAP-Message = 0x0108002b19001703010020307286386c83c576eba3c545aeaac56d15a6866f28cfc66225ee2e94150a13cc Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfa9c4868fc94516ee67926093dbdabe5 Tue Jun 21 13:07:09 2011 : Info: Finished request 6. Tue Jun 21 13:07:09 2011 : Debug: Going to the next request Tue Jun 21 13:07:09 2011 : Debug: Waking up in 3.9 seconds. rad_recv: Access-Request packet from host 192.168.175.60 port 49369, id=56, length=212 User-Name = "SQA\\Administrator" Service-Type = Framed-User Called-Station-Id = "00-1F-45-47-49-84" Calling-Station-Id = "00-18-8B-B9-C2-E3" NAS-IP-Address = 192.168.175.60 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet State = 0xfa9c4868fc94516ee67926093dbdabe5 EAP-Message = 0x0208003b190017030100302395e6a16580181d6580543ed5b3cbe68e539544554693a77f8d011cd346f18ddd28d45e51e3b31b55573ac659347af7 Message-Authenticator = 0x38739cdfd3d2f4efee28f4ba4ced2995 Tue Jun 21 13:07:09 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:09 2011 : Info: ++[preprocess] returns ok Tue Jun 21 13:07:09 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:09 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:09 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:09 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:09 2011 : Info: [eap] EAP packet type response id 8 length 59 Tue Jun 21 13:07:09 2011 : Info: [eap] Continuing tunnel setup. Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns ok Tue Jun 21 13:07:09 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:09 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:09 2011 : Info: [eap] Request found, released from the list Tue Jun 21 13:07:09 2011 : Info: [eap] EAP/peap Tue Jun 21 13:07:09 2011 : Info: [eap] processing type peap Tue Jun 21 13:07:09 2011 : Info: [peap] processing EAP-TLS Tue Jun 21 13:07:09 2011 : Info: [peap] eaptls_verify returned 7 Tue Jun 21 13:07:09 2011 : Info: [peap] Done initial handshake Tue Jun 21 13:07:09 2011 : Info: [peap] eaptls_process returned 7 Tue Jun 21 13:07:09 2011 : Info: [peap] EAPTLS_OK Tue Jun 21 13:07:09 2011 : Info: [peap] Session established. Decoding tunneled attributes. PEAP tunnel data in 0000: 01 53 51 41 5c 41 64 6d 69 6e 69 73 74 72 61 74 PEAP tunnel data in 0010: 6f 72 Tue Jun 21 13:07:09 2011 : Info: [peap] Identity - SQA\Administrator Tue Jun 21 13:07:09 2011 : Info: [peap] Got tunneled request EAP-Message = 0x02080016015351415c41646d696e6973747261746f72 server { Tue Jun 21 13:07:09 2011 : Debug: PEAP: Got tunneled identity of SQA\Administrator Tue Jun 21 13:07:09 2011 : Debug: PEAP: Setting default EAP type for tunneled EAP session. Tue Jun 21 13:07:09 2011 : Debug: PEAP: Setting User-Name to SQA\Administrator Sending tunneled request EAP-Message = 0x02080016015351415c41646d696e6973747261746f72 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "SQA\\Administrator" server inner-tunnel { Tue Jun 21 13:07:09 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:09 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[unix] returns notfound Tue Jun 21 13:07:09 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:09 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:09 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[control] returns noop Tue Jun 21 13:07:09 2011 : Info: [eap] EAP packet type response id 8 length 22 Tue Jun 21 13:07:09 2011 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns updated Tue Jun 21 13:07:09 2011 : Info: [files] users: Matched entry SQA\Administrator at line 93 Tue Jun 21 13:07:09 2011 : Info: ++[files] returns ok Tue Jun 21 13:07:09 2011 : Info: ++[expiration] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[logintime] returns noop Tue Jun 21 13:07:09 2011 : Info: [pap] Found existing Auth-Type, not changing it. Tue Jun 21 13:07:09 2011 : Info: ++[pap] returns noop Tue Jun 21 13:07:09 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:09 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:09 2011 : Info: [eap] EAP Identity Tue Jun 21 13:07:09 2011 : Info: [eap] processing type mschapv2 Tue Jun 21 13:07:09 2011 : Debug: rlm_eap_mschapv2: Issuing Challenge Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns handled } # server inner-tunnel Tue Jun 21 13:07:09 2011 : Info: [peap] Got tunneled reply code 11 Filter-Id = "Enterasys:version=1:mgmt=su:policy=PEAP" EAP-Message = 0x0109002b1a0109002610a27cf4de468d1966f93d06a719dcbafa5351415c41646d696e6973747261746f72 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x88616ecc886874cdb68f9ca1d1effce7 Tue Jun 21 13:07:09 2011 : Info: [peap] Got tunneled reply RADIUS code 11 Filter-Id = "Enterasys:version=1:mgmt=su:policy=PEAP" EAP-Message = 0x0109002b1a0109002610a27cf4de468d1966f93d06a719dcbafa5351415c41646d696e6973747261746f72 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x88616ecc886874cdb68f9ca1d1effce7 Tue Jun 21 13:07:09 2011 : Info: [peap] Got tunneled Access-Challenge PEAP tunnel data out 0000: 1a 01 09 00 26 10 a2 7c f4 de 46 8d 19 66 f9 3d PEAP tunnel data out 0010: 06 a7 19 dc ba fa 53 51 41 5c 41 64 6d 69 6e 69 PEAP tunnel data out 0020: 73 74 72 61 74 6f 72 Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns handled Sending Access-Challenge of id 56 to 192.168.175.60 port 49369 EAP-Message = 0x0109004b19001703010040bbbd0ec59148043d95bbb1941fa6cc5a36bb501baeb363227370c720982b909c42d5a2ad750688d595d06db57a0fdec810c437ca264583fb39254ee44c484463 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfa9c4868fd95516ee67926093dbdabe5 Tue Jun 21 13:07:09 2011 : Info: Finished request 7. Tue Jun 21 13:07:09 2011 : Debug: Going to the next request Tue Jun 21 13:07:09 2011 : Debug: Waking up in 3.9 seconds. rad_recv: Access-Request packet from host 192.168.175.60 port 49369, id=57, length=260 User-Name = "SQA\\Administrator" Service-Type = Framed-User Called-Station-Id = "00-1F-45-47-49-84" Calling-Station-Id = "00-18-8B-B9-C2-E3" NAS-IP-Address = 192.168.175.60 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet State = 0xfa9c4868fd95516ee67926093dbdabe5 EAP-Message = 0x0209006b1900170301006074a487ffa037c1d85d8bc5a072044aa56e4caff4a566a1e652469c45eb4389d9b5c41d04c88e504679e64037b3146795fd9867cac8ddc6087a2bf8f8c498f556f1b79b4fd07f501a25c75a7b9fc30f358f7a6630b0cc8d680d6f8a5f5fe62de6 Message-Authenticator = 0xd54e10ca79a6683c4fbf5ca48ac80ce4 Tue Jun 21 13:07:09 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:09 2011 : Info: ++[preprocess] returns ok Tue Jun 21 13:07:09 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:09 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:09 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:09 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:09 2011 : Info: [eap] EAP packet type response id 9 length 107 Tue Jun 21 13:07:09 2011 : Info: [eap] Continuing tunnel setup. Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns ok Tue Jun 21 13:07:09 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:09 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:09 2011 : Info: [eap] Request found, released from the list Tue Jun 21 13:07:09 2011 : Info: [eap] EAP/peap Tue Jun 21 13:07:09 2011 : Info: [eap] processing type peap Tue Jun 21 13:07:09 2011 : Info: [peap] processing EAP-TLS Tue Jun 21 13:07:09 2011 : Info: [peap] eaptls_verify returned 7 Tue Jun 21 13:07:09 2011 : Info: [peap] Done initial handshake Tue Jun 21 13:07:09 2011 : Info: [peap] eaptls_process returned 7 Tue Jun 21 13:07:09 2011 : Info: [peap] EAPTLS_OK Tue Jun 21 13:07:09 2011 : Info: [peap] Session established. Decoding tunneled attributes. PEAP tunnel data in 0000: 1a 02 09 00 47 31 2c 34 8d 35 6c 2a a0 08 19 08 PEAP tunnel data in 0010: a4 aa 14 e0 c9 61 00 00 00 00 00 00 00 00 af f2 PEAP tunnel data in 0020: 48 84 dc 2d d6 d2 b8 f1 4c aa a5 45 eb 27 ed 97 PEAP tunnel data in 0030: ab 70 70 19 d0 ce 00 53 51 41 5c 41 64 6d 69 6e PEAP tunnel data in 0040: 69 73 74 72 61 74 6f 72 Tue Jun 21 13:07:09 2011 : Info: [peap] EAP type mschapv2 Tue Jun 21 13:07:09 2011 : Info: [peap] Got tunneled request EAP-Message = 0x0209004c1a02090047312c348d356c2aa0081908a4aa14e0c9610000000000000000aff24884dc2dd6d2b8f14caaa545eb27ed97ab707019d0ce005351415c41646d696e6973747261746f72 server { Tue Jun 21 13:07:09 2011 : Debug: PEAP: Setting User-Name to SQA\Administrator Sending tunneled request EAP-Message = 0x0209004c1a02090047312c348d356c2aa0081908a4aa14e0c9610000000000000000aff24884dc2dd6d2b8f14caaa545eb27ed97ab707019d0ce005351415c41646d696e6973747261746f72 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "SQA\\Administrator" State = 0x88616ecc886874cdb68f9ca1d1effce7 server inner-tunnel { Tue Jun 21 13:07:09 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:09 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[unix] returns notfound Tue Jun 21 13:07:09 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:09 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:09 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[control] returns noop Tue Jun 21 13:07:09 2011 : Info: [eap] EAP packet type response id 9 length 76 Tue Jun 21 13:07:09 2011 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns updated Tue Jun 21 13:07:09 2011 : Info: [files] users: Matched entry SQA\Administrator at line 93 Tue Jun 21 13:07:09 2011 : Info: ++[files] returns ok Tue Jun 21 13:07:09 2011 : Info: ++[expiration] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[logintime] returns noop Tue Jun 21 13:07:09 2011 : Info: [pap] Found existing Auth-Type, not changing it. Tue Jun 21 13:07:09 2011 : Info: ++[pap] returns noop Tue Jun 21 13:07:09 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:09 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:09 2011 : Info: [eap] Request found, released from the list Tue Jun 21 13:07:09 2011 : Info: [eap] EAP/mschapv2 Tue Jun 21 13:07:09 2011 : Info: [eap] processing type mschapv2 Tue Jun 21 13:07:09 2011 : Info: [mschapv2] +- entering group MS-CHAP {...} Tue Jun 21 13:07:09 2011 : Info: [mschap] NT Domain delimeter found, should we have enabled with_ntdomain_hack? Tue Jun 21 13:07:09 2011 : Info: [mschap] Told to do MS-CHAPv2 for SQA\Administrator with NT-Password Tue Jun 21 13:07:09 2011 : Info: [mschap] FAILED: MS-CHAP2-Response is incorrect Tue Jun 21 13:07:09 2011 : Info: ++[mschap] returns reject Tue Jun 21 13:07:09 2011 : Info: [eap] Freeing handler Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns reject Tue Jun 21 13:07:09 2011 : Info: Failed to authenticate the user. } # server inner-tunnel Tue Jun 21 13:07:09 2011 : Info: [peap] Got tunneled reply code 3 Filter-Id = "Enterasys:version=1:mgmt=su:policy=PEAP" MS-CHAP-Error = "\tE=691 R=1" EAP-Message = 0x04090004 Message-Authenticator = 0x00000000000000000000000000000000 Tue Jun 21 13:07:09 2011 : Info: [peap] Got tunneled reply RADIUS code 3 Filter-Id = "Enterasys:version=1:mgmt=su:policy=PEAP" MS-CHAP-Error = "\tE=691 R=1" EAP-Message = 0x04090004 Message-Authenticator = 0x00000000000000000000000000000000 Tue Jun 21 13:07:09 2011 : Info: [peap] Tunneled authentication was rejected. Tue Jun 21 13:07:09 2011 : Info: [peap] FAILURE Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns handled Sending Access-Challenge of id 57 to 192.168.175.60 port 49369 EAP-Message = 0x010a002b1900170301002044c7f112a20e7ece668519cc758a09bb6e46926c62dacf84d3a7c72f0415add2 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfa9c4868f296516ee67926093dbdabe5 Tue Jun 21 13:07:09 2011 : Info: Finished request 8. Tue Jun 21 13:07:09 2011 : Debug: Going to the next request Tue Jun 21 13:07:09 2011 : Debug: Waking up in 3.8 seconds. rad_recv: Access-Request packet from host 192.168.175.60 port 49369, id=58, length=196 User-Name = "SQA\\Administrator" Service-Type = Framed-User Called-Station-Id = "00-1F-45-47-49-84" Calling-Station-Id = "00-18-8B-B9-C2-E3" NAS-IP-Address = 192.168.175.60 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet State = 0xfa9c4868f296516ee67926093dbdabe5 EAP-Message = 0x020a002b190017030100200689d71259348a130c7e450d070ec394c6f9acbf4065c6b7084ea2baf294e008 Message-Authenticator = 0xfe143df53474b98a2df9289a2429eb30 Tue Jun 21 13:07:09 2011 : Info: +- entering group authorize {...} Tue Jun 21 13:07:09 2011 : Info: ++[preprocess] returns ok Tue Jun 21 13:07:09 2011 : Info: ++[chap] returns noop Tue Jun 21 13:07:09 2011 : Info: ++[mschap] returns noop Tue Jun 21 13:07:09 2011 : Info: [suffix] No '@' in User-Name = "SQA\Administrator", looking up realm NULL Tue Jun 21 13:07:09 2011 : Info: [suffix] No such realm "NULL" Tue Jun 21 13:07:09 2011 : Info: ++[suffix] returns noop Tue Jun 21 13:07:09 2011 : Info: [eap] EAP packet type response id 10 length 43 Tue Jun 21 13:07:09 2011 : Info: [eap] Continuing tunnel setup. Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns ok Tue Jun 21 13:07:09 2011 : Info: Found Auth-Type = EAP Tue Jun 21 13:07:09 2011 : Info: +- entering group authenticate {...} Tue Jun 21 13:07:09 2011 : Info: [eap] Request found, released from the list Tue Jun 21 13:07:09 2011 : Info: [eap] EAP/peap Tue Jun 21 13:07:09 2011 : Info: [eap] processing type peap Tue Jun 21 13:07:09 2011 : Info: [peap] processing EAP-TLS Tue Jun 21 13:07:09 2011 : Info: [peap] eaptls_verify returned 7 Tue Jun 21 13:07:09 2011 : Info: [peap] Done initial handshake Tue Jun 21 13:07:09 2011 : Info: [peap] eaptls_process returned 7 Tue Jun 21 13:07:09 2011 : Info: [peap] EAPTLS_OK Tue Jun 21 13:07:09 2011 : Info: [peap] Session established. Decoding tunneled attributes. PEAP tunnel data in 0000: 02 0a 00 0b 21 80 03 00 02 00 02 Tue Jun 21 13:07:09 2011 : Info: [peap] Received EAP-TLV response. Tue Jun 21 13:07:09 2011 : Info: [peap] Had sent TLV failure. User was rejected earlier in this session. Tue Jun 21 13:07:09 2011 : Info: [eap] Handler failed in EAP/peap Tue Jun 21 13:07:09 2011 : Info: [eap] Failed in EAP select Tue Jun 21 13:07:09 2011 : Info: ++[eap] returns invalid Tue Jun 21 13:07:09 2011 : Info: Failed to authenticate the user. Tue Jun 21 13:07:09 2011 : Info: Using Post-Auth-Type Reject Tue Jun 21 13:07:09 2011 : Info: +- entering group REJECT {...} Tue Jun 21 13:07:09 2011 : Info: [attr_filter.access_reject] expand: %{User-Name} -> SQA\Administrator Tue Jun 21 13:07:09 2011 : Debug: attr_filter: Matched entry DEFAULT at line 11 Tue Jun 21 13:07:09 2011 : Info: ++[attr_filter.access_reject] returns updated Tue Jun 21 13:07:09 2011 : Info: Delaying reject of request 9 for 1 seconds Tue Jun 21 13:07:09 2011 : Debug: Going to the next request Tue Jun 21 13:07:09 2011 : Debug: Waking up in 0.9 seconds. Tue Jun 21 13:07:10 2011 : Info: Sending delayed reject for request 9 Sending Access-Reject of id 58 to 192.168.175.60 port 49369 EAP-Message = 0x040a0004 Message-Authenticator = 0x00000000000000000000000000000000 Tue Jun 21 13:07:10 2011 : Debug: Waking up in 2.8 seconds. Tue Jun 21 13:07:12 2011 : Info: Cleaning up request 0 ID 49 with timestamp +11 Tue Jun 21 13:07:12 2011 : Debug: Waking up in 1.0 seconds. Tue Jun 21 13:07:13 2011 : Info: Cleaning up request 1 ID 50 with timestamp +12 Tue Jun 21 13:07:13 2011 : Info: Cleaning up request 2 ID 51 with timestamp +12 Tue Jun 21 13:07:13 2011 : Info: Cleaning up request 3 ID 52 with timestamp +12 Tue Jun 21 13:07:13 2011 : Info: Cleaning up request 4 ID 53 with timestamp +12 Tue Jun 21 13:07:14 2011 : Info: Cleaning up request 5 ID 54 with timestamp +12 Tue Jun 21 13:07:14 2011 : Info: Cleaning up request 6 ID 55 with timestamp +13 Tue Jun 21 13:07:14 2011 : Info: Cleaning up request 7 ID 56 with timestamp +13 Tue Jun 21 13:07:14 2011 : Info: Cleaning up request 8 ID 57 with timestamp +13 Tue Jun 21 13:07:14 2011 : Debug: Waking up in 1.0 seconds. Tue Jun 21 13:07:15 2011 : Info: Cleaning up request 9 ID 58 with timestamp +13 Tue Jun 21 13:07:15 2011 : Info: Ready to process requests. -- View this message in context: http://freeradius.1045715.n5.nabble.com/How-to-setup-Freeradius-tp4526799p45... Sent from the FreeRadius - User mailing list archive at Nabble.com.