TTLS authentication is not working on Ubuntu 16.04 Freeradius 2.2.8
Hello, I have installed Freeradius (version 2.2.8) on Ubuntu 16.04 and user authentication is working for MD5, PEAPv0 and TLS authentications. However TTLS authentication is failing. I see from the logs that the group authentication is failing. Is there some configuration that I am missing? This is the client information for the Cisco Authenticator: client 192.168.100.0/24 { require_message_authenticator = no secret = "cisco" shortname = "private-network-1" } This is the debug output from running "freeradius -xX": root@ixia-Qa-Freeradius:/etc/freeradius# freeradius -xX Fri Dec 1 16:21:44 2017 : Info: freeradius: FreeRADIUS Version 2.2.8, for host x86_64-pc-linux-gnu, built on Jul 26 2017 at 15:27:21 Fri Dec 1 16:21:44 2017 : Debug: Server was built with: Fri Dec 1 16:21:44 2017 : Debug: accounting Fri Dec 1 16:21:44 2017 : Debug: authentication Fri Dec 1 16:21:44 2017 : Debug: WITH_DHCP Fri Dec 1 16:21:44 2017 : Debug: WITH_VMPS Fri Dec 1 16:21:44 2017 : Debug: Server core libs: Fri Dec 1 16:21:44 2017 : Debug: ssl: OpenSSL 1.0.2g 1 Mar 2016 Fri Dec 1 16:21:44 2017 : Info: Copyright (C) 1999-2015 The FreeRADIUS server project and contributors. Fri Dec 1 16:21:44 2017 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Fri Dec 1 16:21:44 2017 : Info: PARTICULAR PURPOSE. Fri Dec 1 16:21:44 2017 : Info: You may redistribute copies of FreeRADIUS under the terms of the Fri Dec 1 16:21:44 2017 : Info: GNU General Public License. Fri Dec 1 16:21:44 2017 : Info: For more information about these matters, see the file named COPYRIGHT. Fri Dec 1 16:21:44 2017 : Info: Starting - reading configuration files ... Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/radiusd.conf Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/proxy.conf Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/clients.conf Fri Dec 1 16:21:44 2017 : Debug: including files in directory /etc/freeradius/modules/ Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/exec Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/files Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/unix Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/attr_rewrite Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/ippool Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/ntlm_auth Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/sradutmp Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/radutmp Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/expiration Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/opendirectory Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/etc_group Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/rediswho Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/krb5 Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/policy Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/soh Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/always Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/realm Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/cui Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/dynamic_clients Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/sql_log Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/checkval Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/smsotp Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/echo Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/sqlcounter_expire_on_login Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/dhcp_sqlippool Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/inner-eap Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/cache Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/radrelay Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/counter Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/preprocess Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/linelog Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/detail.log Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/pap Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/chap Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/pam Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/attr_filter Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/ldap Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/replicate Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/redis Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/smbpasswd Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/mac2ip Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/expr Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/mschap Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/detail Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/passwd Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/logintime Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/digest Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/perl Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/detail.example.com Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/mac2vlan Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/otp Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/wimax Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/modules/acct_unique Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/eap.conf Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/policy.conf Fri Dec 1 16:21:44 2017 : Debug: including files in directory /etc/freeradius/sites-enabled/ Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/sites-enabled/default Fri Dec 1 16:21:44 2017 : Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Fri Dec 1 16:21:44 2017 : Debug: main { Fri Dec 1 16:21:44 2017 : Debug: user = "freerad" Fri Dec 1 16:21:44 2017 : Debug: group = "freerad" Fri Dec 1 16:21:44 2017 : Debug: allow_core_dumps = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: including dictionary file /etc/freeradius/dictionary Fri Dec 1 16:21:44 2017 : Debug: main { Fri Dec 1 16:21:44 2017 : Debug: name = "freeradius" Fri Dec 1 16:21:44 2017 : Debug: prefix = "/usr" Fri Dec 1 16:21:44 2017 : Debug: localstatedir = "/var" Fri Dec 1 16:21:44 2017 : Debug: sbindir = "/usr/sbin" Fri Dec 1 16:21:44 2017 : Debug: logdir = "/var/log/freeradius" Fri Dec 1 16:21:44 2017 : Debug: run_dir = "/var/run/freeradius" Fri Dec 1 16:21:44 2017 : Debug: libdir = "/usr/lib/freeradius" Fri Dec 1 16:21:44 2017 : Debug: radacctdir = "/var/log/freeradius/radacct" Fri Dec 1 16:21:44 2017 : Debug: hostname_lookups = no Fri Dec 1 16:21:44 2017 : Debug: max_request_time = 30 Fri Dec 1 16:21:44 2017 : Debug: cleanup_delay = 5 Fri Dec 1 16:21:44 2017 : Debug: max_requests = 1024 Fri Dec 1 16:21:44 2017 : Debug: pidfile = "/var/run/freeradius/freeradius.pid" Fri Dec 1 16:21:44 2017 : Debug: checkrad = "/usr/sbin/checkrad" Fri Dec 1 16:21:44 2017 : Debug: debug_level = 0 Fri Dec 1 16:21:44 2017 : Debug: proxy_requests = yes Fri Dec 1 16:21:44 2017 : Debug: log { Fri Dec 1 16:21:44 2017 : Debug: stripped_names = no Fri Dec 1 16:21:44 2017 : Debug: auth = no Fri Dec 1 16:21:44 2017 : Debug: auth_badpass = no Fri Dec 1 16:21:44 2017 : Debug: auth_goodpass = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: security { Fri Dec 1 16:21:44 2017 : Debug: max_attributes = 200 Fri Dec 1 16:21:44 2017 : Debug: reject_delay = 1 Fri Dec 1 16:21:44 2017 : Debug: status_server = yes Fri Dec 1 16:21:44 2017 : Debug: allow_vulnerable_openssl = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: radiusd: #### Loading Realms and Home Servers #### Fri Dec 1 16:21:44 2017 : Debug: proxy server { Fri Dec 1 16:21:44 2017 : Debug: retry_delay = 5 Fri Dec 1 16:21:44 2017 : Debug: retry_count = 3 Fri Dec 1 16:21:44 2017 : Debug: default_fallback = no Fri Dec 1 16:21:44 2017 : Debug: dead_time = 120 Fri Dec 1 16:21:44 2017 : Debug: wake_all_if_all_dead = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: home_server localhost { Fri Dec 1 16:21:44 2017 : Debug: ipaddr = 127.0.0.1 Fri Dec 1 16:21:44 2017 : Debug: port = 1812 Fri Dec 1 16:21:44 2017 : Debug: type = "auth" Fri Dec 1 16:21:44 2017 : Debug: secret = "testing123" Fri Dec 1 16:21:44 2017 : Debug: response_window = 20 Fri Dec 1 16:21:44 2017 : Debug: max_outstanding = 65536 Fri Dec 1 16:21:44 2017 : Debug: require_message_authenticator = yes Fri Dec 1 16:21:44 2017 : Debug: zombie_period = 40 Fri Dec 1 16:21:44 2017 : Debug: status_check = "status-server" Fri Dec 1 16:21:44 2017 : Debug: ping_interval = 30 Fri Dec 1 16:21:44 2017 : Debug: check_interval = 30 Fri Dec 1 16:21:44 2017 : Debug: num_answers_to_alive = 3 Fri Dec 1 16:21:44 2017 : Debug: num_pings_to_alive = 3 Fri Dec 1 16:21:44 2017 : Debug: revive_interval = 120 Fri Dec 1 16:21:44 2017 : Debug: status_check_timeout = 4 Fri Dec 1 16:21:44 2017 : Debug: coa { Fri Dec 1 16:21:44 2017 : Debug: irt = 2 Fri Dec 1 16:21:44 2017 : Debug: mrt = 16 Fri Dec 1 16:21:44 2017 : Debug: mrc = 5 Fri Dec 1 16:21:44 2017 : Debug: mrd = 30 Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: home_server_pool my_auth_failover { Fri Dec 1 16:21:44 2017 : Debug: type = fail-over Fri Dec 1 16:21:44 2017 : Debug: home_server = localhost Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: realm example.com { Fri Dec 1 16:21:44 2017 : Debug: auth_pool = my_auth_failover Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: realm LOCAL { Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: radiusd: #### Loading Clients #### Fri Dec 1 16:21:44 2017 : Debug: client localhost { Fri Dec 1 16:21:44 2017 : Debug: ipaddr = 127.0.0.1 Fri Dec 1 16:21:44 2017 : Debug: require_message_authenticator = no Fri Dec 1 16:21:44 2017 : Debug: secret = "testing123" Fri Dec 1 16:21:44 2017 : Debug: nastype = "cisco" Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: client 192.168.100.0/24 { Fri Dec 1 16:21:44 2017 : Debug: require_message_authenticator = no Fri Dec 1 16:21:44 2017 : Debug: secret = "cisco" Fri Dec 1 16:21:44 2017 : Debug: shortname = "private-network-1" Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: radiusd: #### Instantiating modules #### Fri Dec 1 16:21:44 2017 : Debug: instantiate { Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_exec, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_exec Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "exec" from file /etc/freeradius/modules/exec Fri Dec 1 16:21:44 2017 : Debug: exec { Fri Dec 1 16:21:44 2017 : Debug: wait = no Fri Dec 1 16:21:44 2017 : Debug: input_pairs = "request" Fri Dec 1 16:21:44 2017 : Debug: shell_escape = yes Fri Dec 1 16:21:44 2017 : Debug: timeout = 10 Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_expr, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_expr Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "expr" from file /etc/freeradius/modules/expr Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_expiration, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_expiration Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "expiration" from file /etc/freeradius/modules/expiration Fri Dec 1 16:21:44 2017 : Debug: expiration { Fri Dec 1 16:21:44 2017 : Debug: reply-message = "Password Has Expired " Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_logintime, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_logintime Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "logintime" from file /etc/freeradius/modules/logintime Fri Dec 1 16:21:44 2017 : Debug: logintime { Fri Dec 1 16:21:44 2017 : Debug: reply-message = "You are calling outside your allowed timespan " Fri Dec 1 16:21:44 2017 : Debug: minimum-timeout = 60 Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: radiusd: #### Loading Virtual Servers #### Fri Dec 1 16:21:44 2017 : Debug: server { # from file /etc/freeradius/radiusd.conf Fri Dec 1 16:21:44 2017 : Debug: modules { Fri Dec 1 16:21:44 2017 : Debug: Module: Creating Auth-Type = digest Fri Dec 1 16:21:44 2017 : Debug: Module: Checking authenticate {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_pap, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_pap Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "pap" from file /etc/freeradius/modules/pap Fri Dec 1 16:21:44 2017 : Debug: pap { Fri Dec 1 16:21:44 2017 : Debug: encryption_scheme = "auto" Fri Dec 1 16:21:44 2017 : Debug: auto_header = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_chap, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_chap Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "chap" from file /etc/freeradius/modules/chap Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_mschap, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_mschap Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "mschap" from file /etc/freeradius/modules/mschap Fri Dec 1 16:21:44 2017 : Debug: mschap { Fri Dec 1 16:21:44 2017 : Debug: use_mppe = yes Fri Dec 1 16:21:44 2017 : Debug: require_encryption = no Fri Dec 1 16:21:44 2017 : Debug: require_strong = no Fri Dec 1 16:21:44 2017 : Debug: with_ntdomain_hack = no Fri Dec 1 16:21:44 2017 : Debug: allow_retry = yes Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_digest, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_digest Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "digest" from file /etc/freeradius/modules/digest Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_pam, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_pam Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "pam" from file /etc/freeradius/modules/pam Fri Dec 1 16:21:44 2017 : Debug: pam { Fri Dec 1 16:21:44 2017 : Debug: pam_auth = "radiusd" Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_unix, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_unix Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "unix" from file /etc/freeradius/modules/unix Fri Dec 1 16:21:44 2017 : Debug: unix { Fri Dec 1 16:21:44 2017 : Debug: radwtmp = "/var/log/freeradius/radwtmp" Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_eap, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_eap Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "eap" from file /etc/freeradius/eap.conf Fri Dec 1 16:21:44 2017 : Debug: eap { Fri Dec 1 16:21:44 2017 : Debug: default_eap_type = "md5" Fri Dec 1 16:21:44 2017 : Debug: timer_expire = 60 Fri Dec 1 16:21:44 2017 : Debug: ignore_unknown_eap_types = no Fri Dec 1 16:21:44 2017 : Debug: cisco_accounting_username_bug = no Fri Dec 1 16:21:44 2017 : Debug: max_sessions = 1024 Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to sub-module rlm_eap_md5 Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating eap-md5 Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to sub-module rlm_eap_leap Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating eap-leap Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to sub-module rlm_eap_gtc Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating eap-gtc Fri Dec 1 16:21:44 2017 : Debug: gtc { Fri Dec 1 16:21:44 2017 : Debug: challenge = "Password: " Fri Dec 1 16:21:44 2017 : Debug: auth_type = "PAP" Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to sub-module rlm_eap_tls Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating eap-tls Fri Dec 1 16:21:44 2017 : Debug: tls { Fri Dec 1 16:21:44 2017 : Debug: rsa_key_exchange = no Fri Dec 1 16:21:44 2017 : Debug: dh_key_exchange = yes Fri Dec 1 16:21:44 2017 : Debug: rsa_key_length = 512 Fri Dec 1 16:21:44 2017 : Debug: dh_key_length = 512 Fri Dec 1 16:21:44 2017 : Debug: verify_depth = 0 Fri Dec 1 16:21:44 2017 : Debug: CA_path = "/etc/freeradius/certs" Fri Dec 1 16:21:44 2017 : Debug: pem_file_type = yes Fri Dec 1 16:21:44 2017 : Debug: private_key_file = "/etc/freeradius/certs/server_key.pem" Fri Dec 1 16:21:44 2017 : Debug: certificate_file = "/etc/freeradius/certs/server_cert.pem" Fri Dec 1 16:21:44 2017 : Debug: CA_file = "/etc/freeradius/certs/root.pem" Fri Dec 1 16:21:44 2017 : Debug: private_key_password = "whatever" Fri Dec 1 16:21:44 2017 : Debug: dh_file = "/etc/freeradius/certs/dh" Fri Dec 1 16:21:44 2017 : Debug: random_file = "/dev/urandom" Fri Dec 1 16:21:44 2017 : Debug: fragment_size = 1024 Fri Dec 1 16:21:44 2017 : Debug: include_length = yes Fri Dec 1 16:21:44 2017 : Debug: check_crl = no Fri Dec 1 16:21:44 2017 : Debug: check_all_crl = no Fri Dec 1 16:21:44 2017 : Debug: cipher_list = "DEFAULT" Fri Dec 1 16:21:44 2017 : Debug: make_cert_command = "/etc/freeradius/certs/bootstrap" Fri Dec 1 16:21:44 2017 : Debug: ecdh_curve = "prime256v1" Fri Dec 1 16:21:44 2017 : Debug: cache { Fri Dec 1 16:21:44 2017 : Debug: enable = no Fri Dec 1 16:21:44 2017 : Debug: lifetime = 24 Fri Dec 1 16:21:44 2017 : Debug: max_entries = 255 Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: verify { Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: ocsp { Fri Dec 1 16:21:44 2017 : Debug: enable = no Fri Dec 1 16:21:44 2017 : Debug: override_cert_url = yes Fri Dec 1 16:21:44 2017 : Debug: url = "http://127.0.0.1/ocsp/" Fri Dec 1 16:21:44 2017 : Debug: use_nonce = yes Fri Dec 1 16:21:44 2017 : Debug: timeout = 0 Fri Dec 1 16:21:44 2017 : Debug: softfail = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to sub-module rlm_eap_ttls Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating eap-ttls Fri Dec 1 16:21:44 2017 : Debug: ttls { Fri Dec 1 16:21:44 2017 : Debug: default_eap_type = "md5" Fri Dec 1 16:21:44 2017 : Debug: copy_request_to_tunnel = no Fri Dec 1 16:21:44 2017 : Debug: use_tunneled_reply = yes Fri Dec 1 16:21:44 2017 : Debug: virtual_server = "inner-tunnel" Fri Dec 1 16:21:44 2017 : Debug: include_length = yes Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to sub-module rlm_eap_peap Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating eap-peap Fri Dec 1 16:21:44 2017 : Debug: peap { Fri Dec 1 16:21:44 2017 : Debug: default_eap_type = "mschapv2" Fri Dec 1 16:21:44 2017 : Debug: copy_request_to_tunnel = no Fri Dec 1 16:21:44 2017 : Debug: use_tunneled_reply = no Fri Dec 1 16:21:44 2017 : Debug: proxy_tunneled_request_as_eap = yes Fri Dec 1 16:21:44 2017 : Debug: virtual_server = "inner-tunnel" Fri Dec 1 16:21:44 2017 : Debug: soh = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to sub-module rlm_eap_mschapv2 Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating eap-mschapv2 Fri Dec 1 16:21:44 2017 : Debug: mschapv2 { Fri Dec 1 16:21:44 2017 : Debug: with_ntdomain_hack = no Fri Dec 1 16:21:44 2017 : Debug: send_error = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: Module: Checking authorize {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_preprocess, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_preprocess Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "preprocess" from file /etc/freeradius/modules/preprocess Fri Dec 1 16:21:44 2017 : Debug: preprocess { Fri Dec 1 16:21:44 2017 : Debug: huntgroups = "/etc/freeradius/huntgroups" Fri Dec 1 16:21:44 2017 : Debug: hints = "/etc/freeradius/hints" Fri Dec 1 16:21:44 2017 : Debug: with_ascend_hack = no Fri Dec 1 16:21:44 2017 : Debug: ascend_channels_per_line = 23 Fri Dec 1 16:21:44 2017 : Debug: with_ntdomain_hack = no Fri Dec 1 16:21:44 2017 : Debug: with_specialix_jetstream_hack = no Fri Dec 1 16:21:44 2017 : Debug: with_cisco_vsa_hack = no Fri Dec 1 16:21:44 2017 : Debug: with_alvarion_vsa_hack = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: reading pairlist file /etc/freeradius/huntgroups Fri Dec 1 16:21:44 2017 : Debug: reading pairlist file /etc/freeradius/hints Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_realm, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_realm Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "suffix" from file /etc/freeradius/modules/realm Fri Dec 1 16:21:44 2017 : Debug: realm suffix { Fri Dec 1 16:21:44 2017 : Debug: format = "suffix" Fri Dec 1 16:21:44 2017 : Debug: delimiter = "@" Fri Dec 1 16:21:44 2017 : Debug: ignore_default = no Fri Dec 1 16:21:44 2017 : Debug: ignore_null = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_files, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_files Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "files" from file /etc/freeradius/modules/files Fri Dec 1 16:21:44 2017 : Debug: files { Fri Dec 1 16:21:44 2017 : Debug: usersfile = "/etc/freeradius/users" Fri Dec 1 16:21:44 2017 : Debug: acctusersfile = "/etc/freeradius/acct_users" Fri Dec 1 16:21:44 2017 : Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users" Fri Dec 1 16:21:44 2017 : Debug: compat = "no" Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: reading pairlist file /etc/freeradius/users Fri Dec 1 16:21:44 2017 : Debug: reading pairlist file /etc/freeradius/acct_users Fri Dec 1 16:21:44 2017 : Debug: reading pairlist file /etc/freeradius/preproxy_users Fri Dec 1 16:21:44 2017 : Debug: Module: Checking preacct {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_acct_unique Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "acct_unique" from file /etc/freeradius/modules/acct_unique Fri Dec 1 16:21:44 2017 : Debug: acct_unique { Fri Dec 1 16:21:44 2017 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, NAS-Identifier, NAS-Port" Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: Module: Checking accounting {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_detail, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_detail Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "detail" from file /etc/freeradius/modules/detail Fri Dec 1 16:21:44 2017 : Debug: detail { Fri Dec 1 16:21:44 2017 : Debug: detailfile = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" Fri Dec 1 16:21:44 2017 : Debug: header = "%t" Fri Dec 1 16:21:44 2017 : Debug: detailperm = 384 Fri Dec 1 16:21:44 2017 : Debug: dirperm = 493 Fri Dec 1 16:21:44 2017 : Debug: locking = no Fri Dec 1 16:21:44 2017 : Debug: log_packet_header = no Fri Dec 1 16:21:44 2017 : Debug: escape_filenames = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_attr_filter, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_attr_filter Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "attr_filter.accounting_response" from file /etc/freeradius/modules/attr_filter Fri Dec 1 16:21:44 2017 : Debug: attr_filter attr_filter.accounting_response { Fri Dec 1 16:21:44 2017 : Debug: attrsfile = "/etc/freeradius/attrs.accounting_response" Fri Dec 1 16:21:44 2017 : Debug: key = "%{User-Name}" Fri Dec 1 16:21:44 2017 : Debug: relaxed = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: reading pairlist file /etc/freeradius/attrs.accounting_response Fri Dec 1 16:21:44 2017 : Debug: Module: Checking session {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: (Loaded rlm_radutmp, checking if it's valid) Fri Dec 1 16:21:44 2017 : Debug: Module: Linked to module rlm_radutmp Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "radutmp" from file /etc/freeradius/modules/radutmp Fri Dec 1 16:21:44 2017 : Debug: radutmp { Fri Dec 1 16:21:44 2017 : Debug: filename = "/var/log/freeradius/radutmp" Fri Dec 1 16:21:44 2017 : Debug: username = "%{User-Name}" Fri Dec 1 16:21:44 2017 : Debug: case_sensitive = yes Fri Dec 1 16:21:44 2017 : Debug: check_with_nas = yes Fri Dec 1 16:21:44 2017 : Debug: perm = 384 Fri Dec 1 16:21:44 2017 : Debug: callerid = yes Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: Module: Checking post-proxy {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: Module: Checking post-auth {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: Module: Instantiating module "attr_filter.access_reject" from file /etc/freeradius/modules/attr_filter Fri Dec 1 16:21:44 2017 : Debug: attr_filter attr_filter.access_reject { Fri Dec 1 16:21:44 2017 : Debug: attrsfile = "/etc/freeradius/attrs.access_reject" Fri Dec 1 16:21:44 2017 : Debug: key = "%{User-Name}" Fri Dec 1 16:21:44 2017 : Debug: relaxed = no Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: reading pairlist file /etc/freeradius/attrs.access_reject Fri Dec 1 16:21:44 2017 : Debug: } # modules Fri Dec 1 16:21:44 2017 : Debug: } # server Fri Dec 1 16:21:44 2017 : Debug: server inner-tunnel { # from file /etc/freeradius/sites-enabled/inner-tunnel Fri Dec 1 16:21:44 2017 : Debug: modules { Fri Dec 1 16:21:44 2017 : Debug: Module: Checking authenticate {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: Module: Checking authorize {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: Module: Checking session {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: Module: Checking post-proxy {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: Module: Checking post-auth {...} for more modules to load Fri Dec 1 16:21:44 2017 : Debug: } # modules Fri Dec 1 16:21:44 2017 : Debug: } # server Fri Dec 1 16:21:44 2017 : Debug: radiusd: #### Opening IP addresses and Ports #### Fri Dec 1 16:21:44 2017 : Debug: listen { Fri Dec 1 16:21:44 2017 : Debug: type = "auth" Fri Dec 1 16:21:44 2017 : Debug: ipaddr = 192.168.100.1 Fri Dec 1 16:21:44 2017 : Debug: port = 1645 Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: listen { Fri Dec 1 16:21:44 2017 : Debug: type = "acct" Fri Dec 1 16:21:44 2017 : Debug: ipaddr = * Fri Dec 1 16:21:44 2017 : Debug: port = 0 Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: listen { Fri Dec 1 16:21:44 2017 : Debug: type = "auth" Fri Dec 1 16:21:44 2017 : Debug: ipaddr = 127.0.0.1 Fri Dec 1 16:21:44 2017 : Debug: port = 18120 Fri Dec 1 16:21:44 2017 : Debug: } Fri Dec 1 16:21:44 2017 : Debug: ... adding new socket proxy address * port 51592 Fri Dec 1 16:21:44 2017 : Debug: Listening on authentication interface ens192 address 192.168.100.1 port 1645 Fri Dec 1 16:21:44 2017 : Debug: Listening on accounting address * port 1813 Fri Dec 1 16:21:44 2017 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel Fri Dec 1 16:21:44 2017 : Debug: Listening on proxy address 192.168.100.1 port 1647 Fri Dec 1 16:21:44 2017 : Info: Ready to process requests. rad_recv: Access-Request packet from host 192.168.100.2 port 1645, id=158, length=152 NAS-IP-Address = 192.168.100.2 NAS-Port = 4 NAS-Port-Type = Ethernet User-Name = "IxiaUser3" Called-Station-Id = "00-0A-F3-30-77-0A" Calling-Station-Id = "46-1B-6D-CC-00-00" Service-Type = Framed-User Framed-MTU = 1500 Calling-Station-Id = "34-36-2d-31-42-2d" EAP-Message = 0x0200000e01497869615573657233 Message-Authenticator = 0x6684f9ff1c0cc8bd674f12581e828f21 Fri Dec 1 16:23:12 2017 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:12 2017 : Info: +group authorize { Fri Dec 1 16:23:12 2017 : Info: ++[preprocess] = ok Fri Dec 1 16:23:12 2017 : Info: ++[chap] = noop Fri Dec 1 16:23:12 2017 : Info: ++[mschap] = noop Fri Dec 1 16:23:12 2017 : Info: ++[digest] = noop Fri Dec 1 16:23:12 2017 : Info: [suffix] No '@' in User-Name = "IxiaUser3", looking up realm NULL Fri Dec 1 16:23:12 2017 : Info: [suffix] No such realm "NULL" Fri Dec 1 16:23:12 2017 : Info: ++[suffix] = noop Fri Dec 1 16:23:12 2017 : Info: [eap] EAP packet type response id 0 length 14 Fri Dec 1 16:23:12 2017 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Fri Dec 1 16:23:12 2017 : Info: ++[eap] = updated Fri Dec 1 16:23:12 2017 : Info: [files] users: Matched entry IxiaUser3 at line 92 Fri Dec 1 16:23:12 2017 : Info: ++[files] = ok Fri Dec 1 16:23:12 2017 : Info: ++[expiration] = noop Fri Dec 1 16:23:12 2017 : Info: ++[logintime] = noop Fri Dec 1 16:23:12 2017 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Fri Dec 1 16:23:12 2017 : Info: ++[pap] = noop Fri Dec 1 16:23:12 2017 : Info: +} # group authorize = updated Fri Dec 1 16:23:12 2017 : Info: Found Auth-Type = EAP Fri Dec 1 16:23:12 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:12 2017 : Info: +group authenticate { Fri Dec 1 16:23:12 2017 : Info: [eap] EAP Identity Fri Dec 1 16:23:12 2017 : Info: [eap] processing type md5 Fri Dec 1 16:23:12 2017 : Debug: rlm_eap_md5: Issuing Challenge Fri Dec 1 16:23:12 2017 : Info: ++[eap] = handled Fri Dec 1 16:23:12 2017 : Info: +} # group authenticate = handled Sending Access-Challenge of id 158 to 192.168.100.2 port 1645 EAP-Message = 0x010100160410dd2045814f787682ebd8a34d7d8d7372 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xf1b684cff1b780881bf75674bfd214cc Fri Dec 1 16:23:12 2017 : Info: Finished request 0. Fri Dec 1 16:23:12 2017 : Debug: Going to the next request Fri Dec 1 16:23:12 2017 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.100.2 port 1645, id=159, length=162 NAS-IP-Address = 192.168.100.2 NAS-Port = 4 NAS-Port-Type = Ethernet User-Name = "IxiaUser3" Called-Station-Id = "00-0A-F3-30-77-0A" Calling-Station-Id = "46-1B-6D-CC-00-00" Service-Type = Framed-User Framed-MTU = 1500 Calling-Station-Id = "34-36-2d-31-42-2d" State = 0xf1b684cff1b780881bf75674bfd214cc EAP-Message = 0x020100060315 Message-Authenticator = 0x338cf6fb73f1b7a8010abf19b874e470 Fri Dec 1 16:23:12 2017 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:12 2017 : Info: +group authorize { Fri Dec 1 16:23:12 2017 : Info: ++[preprocess] = ok Fri Dec 1 16:23:12 2017 : Info: ++[chap] = noop Fri Dec 1 16:23:12 2017 : Info: ++[mschap] = noop Fri Dec 1 16:23:12 2017 : Info: ++[digest] = noop Fri Dec 1 16:23:12 2017 : Info: [suffix] No '@' in User-Name = "IxiaUser3", looking up realm NULL Fri Dec 1 16:23:12 2017 : Info: [suffix] No such realm "NULL" Fri Dec 1 16:23:12 2017 : Info: ++[suffix] = noop Fri Dec 1 16:23:12 2017 : Info: [eap] EAP packet type response id 1 length 6 Fri Dec 1 16:23:12 2017 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Fri Dec 1 16:23:12 2017 : Info: ++[eap] = updated Fri Dec 1 16:23:12 2017 : Info: [files] users: Matched entry IxiaUser3 at line 92 Fri Dec 1 16:23:12 2017 : Info: ++[files] = ok Fri Dec 1 16:23:12 2017 : Info: ++[expiration] = noop Fri Dec 1 16:23:12 2017 : Info: ++[logintime] = noop Fri Dec 1 16:23:12 2017 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Fri Dec 1 16:23:12 2017 : Info: ++[pap] = noop Fri Dec 1 16:23:12 2017 : Info: +} # group authorize = updated Fri Dec 1 16:23:12 2017 : Info: Found Auth-Type = EAP Fri Dec 1 16:23:12 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:12 2017 : Info: +group authenticate { Fri Dec 1 16:23:12 2017 : Info: [eap] Request found, released from the list Fri Dec 1 16:23:12 2017 : Info: [eap] EAP NAK Fri Dec 1 16:23:12 2017 : Info: [eap] EAP-NAK asked for EAP-Type/ttls Fri Dec 1 16:23:12 2017 : Info: [eap] processing type tls Fri Dec 1 16:23:12 2017 : Info: [tls] Initiate Fri Dec 1 16:23:12 2017 : Info: [tls] Start returned 1 Fri Dec 1 16:23:12 2017 : Info: ++[eap] = handled Fri Dec 1 16:23:12 2017 : Info: +} # group authenticate = handled Sending Access-Challenge of id 159 to 192.168.100.2 port 1645 EAP-Message = 0x010200061520 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xf1b684cff0b491881bf75674bfd214cc Fri Dec 1 16:23:12 2017 : Info: Finished request 1. Fri Dec 1 16:23:12 2017 : Debug: Going to the next request Fri Dec 1 16:23:12 2017 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.100.2 port 1645, id=160, length=260 NAS-IP-Address = 192.168.100.2 NAS-Port = 4 NAS-Port-Type = Ethernet User-Name = "IxiaUser3" Called-Station-Id = "00-0A-F3-30-77-0A" Calling-Station-Id = "46-1B-6D-CC-00-00" Service-Type = Framed-User Framed-MTU = 1500 Calling-Station-Id = "34-36-2d-31-42-2d" State = 0xf1b684cff0b491881bf75674bfd214cc EAP-Message = 0x0202006815800000005e16030100590100005503015a212fbc8e3eb147b08cbfa0d9e19720addd4ce3086ba9beb8ffb0c8a65929bf00002800390038003500160013000a00330032002f000700050004001500120009001400110008000600030100000400230000 Message-Authenticator = 0x34befb6d2d79af57abfd6f57b7187fbe Fri Dec 1 16:23:12 2017 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:12 2017 : Info: +group authorize { Fri Dec 1 16:23:12 2017 : Info: ++[preprocess] = ok Fri Dec 1 16:23:12 2017 : Info: ++[chap] = noop Fri Dec 1 16:23:12 2017 : Info: ++[mschap] = noop Fri Dec 1 16:23:12 2017 : Info: ++[digest] = noop Fri Dec 1 16:23:12 2017 : Info: [suffix] No '@' in User-Name = "IxiaUser3", looking up realm NULL Fri Dec 1 16:23:12 2017 : Info: [suffix] No such realm "NULL" Fri Dec 1 16:23:12 2017 : Info: ++[suffix] = noop Fri Dec 1 16:23:12 2017 : Info: [eap] EAP packet type response id 2 length 104 Fri Dec 1 16:23:12 2017 : Info: [eap] Continuing tunnel setup. Fri Dec 1 16:23:12 2017 : Info: ++[eap] = ok Fri Dec 1 16:23:12 2017 : Info: +} # group authorize = ok Fri Dec 1 16:23:12 2017 : Info: Found Auth-Type = EAP Fri Dec 1 16:23:12 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:12 2017 : Info: +group authenticate { Fri Dec 1 16:23:12 2017 : Info: [eap] Request found, released from the list Fri Dec 1 16:23:12 2017 : Info: [eap] EAP/ttls Fri Dec 1 16:23:12 2017 : Info: [eap] processing type ttls Fri Dec 1 16:23:12 2017 : Info: [ttls] Authenticate Fri Dec 1 16:23:12 2017 : Info: [ttls] processing EAP-TLS Fri Dec 1 16:23:12 2017 : Debug: TLS Length 94 Fri Dec 1 16:23:12 2017 : Info: [ttls] Length Included Fri Dec 1 16:23:12 2017 : Info: [ttls] eaptls_verify returned 11 Fri Dec 1 16:23:12 2017 : Info: [ttls] (other): before/accept initialization Fri Dec 1 16:23:12 2017 : Info: [ttls] TLS_accept: before/accept initialization Fri Dec 1 16:23:12 2017 : Info: [ttls] <<< Unknown TLS version [length 0005] Fri Dec 1 16:23:12 2017 : Info: [ttls] <<< TLS 1.0 Handshake [length 0059], ClientHello Fri Dec 1 16:23:12 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:12 2017 : Info: [ttls] >>> Unknown TLS version [length 0005] Fri Dec 1 16:23:12 2017 : Info: [ttls] >>> TLS 1.0 Handshake [length 002a], ServerHello Fri Dec 1 16:23:12 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:12 2017 : Info: [ttls] >>> Unknown TLS version [length 0005] Fri Dec 1 16:23:12 2017 : Info: [ttls] >>> TLS 1.0 Handshake [length 05d9], Certificate Fri Dec 1 16:23:12 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:12 2017 : Info: [ttls] >>> Unknown TLS version [length 0005] Fri Dec 1 16:23:12 2017 : Info: [ttls] >>> TLS 1.0 Handshake [length 020d], ServerKeyExchange Fri Dec 1 16:23:12 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:12 2017 : Info: [ttls] >>> Unknown TLS version [length 0005] Fri Dec 1 16:23:12 2017 : Info: [ttls] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone Fri Dec 1 16:23:12 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:12 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:12 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:12 2017 : Info: [ttls] TLS_accept: Need to read more data: unknown state Fri Dec 1 16:23:12 2017 : Info: [ttls] TLS_accept: Need to read more data: unknown state Fri Dec 1 16:23:12 2017 : Debug: In SSL Handshake Phase Fri Dec 1 16:23:12 2017 : Debug: In SSL Accept mode Fri Dec 1 16:23:12 2017 : Info: [ttls] eaptls_process returned 13 Fri Dec 1 16:23:12 2017 : Info: ++[eap] = handled Fri Dec 1 16:23:12 2017 : Info: +} # group authenticate = handled Sending Access-Challenge of id 160 to 192.168.100.2 port 1645 EAP-Message = 0x0103040015c000000828160301002a0200002603011f860eddbeec439f6ea4e15cbed543b5cf476a6bdcc92d6a67cced012465f9fc0000390016030105d90b0005d50005d2000302308202fe30820267020101300d06092a864886f70d0101050500307c310b300906035504061302494e310c300a06035504080c0344454c310c300a06035504070c0344454c310d300b060355040a0c0449584941310c300a060355040b0c034250533110300e06035504030c07524f4f542d43413122302006092a864886f70d0109011613726f6f742d63614069786961636f6d2e636f6d301e170d3137303430363039353734315a170d32373034303430393537 EAP-Message = 0x34315a30818e310b300906035504061302494e310b300906035504080c025742310c300a06035504070c034b4f4c310d300b060355040a0c0449584941310f300d060355040b0c0649584c4f41443124302206035504030c1b43412d5349474e45442d5253412d324b2d55554e53454355524544311e301c06092a864886f70d010901160f6162634069786961636f6d2e636f6d30820122300d06092a864886f70d01010105000382010f003082010a0282010100b077cde2fd98ef597ea7fecefe933ef103f4d01ee952886fbdd07a71f1305246276357b96ff058afa2495b8799a491464f3c71c3e2f74544957e334b9e45085a3aec3348a393cde6 EAP-Message = 0x750cda5b85aff39feded3427d9da7fbda9463fb846791c79d6ae7cc39d5b9bbc690970ee0d882291c994d32dffae50c4dec1d9b2d87b3e64da8e2bee71615c17ff9fa4f2a6f825565feaea269f866b360cc269cc6fcc3b8ed2bad64f56ba0fb3b182f6103e566d292837337a0364be665117f55f34eef0268b0b8a7d1c1a1d9655e440674c2914f9bc4f3ac598b74662ae33ca279bc7472eadb5453b0aed21bab44809a2e570c1e1ae270f0784193ac3ddd0aa9035a143f10203010001300d06092a864886f70d0101050500038181007e59159785eab0cad7ae6aecae7b544055e426d8e27a6a8eb6e3df882acfd5c947cca2d8438d149df1d756aa78 EAP-Message = 0xf25058cd2d2adca03a7596c06230dac143b3a106dfb8fa32851941940fa96ec4e452394f4053b98142083a429edd58ccd1979987276f74d394f83698930f1544a89dffd753e5724d09bee2ca58e3bc5e36c9690002ca308202c63082022fa003020102020900c922b862fc89e3dd300d06092a864886f70d0101050500307c310b300906035504061302494e310c300a06035504080c0344454c310c300a06035504070c0344454c310d300b060355040a0c0449584941310c300a060355040b0c034250533110300e06035504030c07524f4f542d43413122302006092a864886f70d0109011613726f6f742d63614069786961636f6d2e636f6d301e EAP-Message = 0x170d31373034303630393534 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xf1b684cff3b591881bf75674bfd214cc Fri Dec 1 16:23:12 2017 : Info: Finished request 2. Fri Dec 1 16:23:12 2017 : Debug: Going to the next request Fri Dec 1 16:23:12 2017 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.100.2 port 1645, id=161, length=162 NAS-IP-Address = 192.168.100.2 NAS-Port = 4 NAS-Port-Type = Ethernet User-Name = "IxiaUser3" Called-Station-Id = "00-0A-F3-30-77-0A" Calling-Station-Id = "46-1B-6D-CC-00-00" Service-Type = Framed-User Framed-MTU = 1500 Calling-Station-Id = "34-36-2d-31-42-2d" State = 0xf1b684cff3b591881bf75674bfd214cc EAP-Message = 0x020300061500 Message-Authenticator = 0x2c616da6552b60928e553257d66a78c8 Fri Dec 1 16:23:12 2017 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:12 2017 : Info: +group authorize { Fri Dec 1 16:23:12 2017 : Info: ++[preprocess] = ok Fri Dec 1 16:23:12 2017 : Info: ++[chap] = noop Fri Dec 1 16:23:12 2017 : Info: ++[mschap] = noop Fri Dec 1 16:23:12 2017 : Info: ++[digest] = noop Fri Dec 1 16:23:12 2017 : Info: [suffix] No '@' in User-Name = "IxiaUser3", looking up realm NULL Fri Dec 1 16:23:12 2017 : Info: [suffix] No such realm "NULL" Fri Dec 1 16:23:12 2017 : Info: ++[suffix] = noop Fri Dec 1 16:23:12 2017 : Info: [eap] EAP packet type response id 3 length 6 Fri Dec 1 16:23:12 2017 : Info: [eap] Continuing tunnel setup. Fri Dec 1 16:23:12 2017 : Info: ++[eap] = ok Fri Dec 1 16:23:12 2017 : Info: +} # group authorize = ok Fri Dec 1 16:23:12 2017 : Info: Found Auth-Type = EAP Fri Dec 1 16:23:12 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:12 2017 : Info: +group authenticate { Fri Dec 1 16:23:12 2017 : Info: [eap] Request found, released from the list Fri Dec 1 16:23:12 2017 : Info: [eap] EAP/ttls Fri Dec 1 16:23:12 2017 : Info: [eap] processing type ttls Fri Dec 1 16:23:12 2017 : Info: [ttls] Authenticate Fri Dec 1 16:23:12 2017 : Info: [ttls] processing EAP-TLS Fri Dec 1 16:23:12 2017 : Info: [ttls] Received TLS ACK Fri Dec 1 16:23:12 2017 : Info: [ttls] ACK handshake fragment handler Fri Dec 1 16:23:12 2017 : Info: [ttls] eaptls_verify returned 1 Fri Dec 1 16:23:12 2017 : Info: [ttls] eaptls_process returned 13 Fri Dec 1 16:23:12 2017 : Info: ++[eap] = handled Fri Dec 1 16:23:12 2017 : Info: +} # group authenticate = handled Sending Access-Challenge of id 161 to 192.168.100.2 port 1645 EAP-Message = 0x0104040015c00000082832385a170d3237303430343039353432385a307c310b300906035504061302494e310c300a06035504080c0344454c310c300a06035504070c0344454c310d300b060355040a0c0449584941310c300a060355040b0c034250533110300e06035504030c07524f4f542d43413122302006092a864886f70d0109011613726f6f742d63614069786961636f6d2e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100c0295716be3ef8a96cd64394da8ad891666c738a2dcdff988053105204dc6b7b8e5a855cc0b7e7adf316118e5e3c4ef3c8e580738c92714831b05ecda326b42b76e343f60fa4 EAP-Message = 0xaca9c9ddd74b43ec2eed013bb4e8452ff021d1f716baaa747ef4c5476701dff65ae07a427d598f8c2443ed1134963f7d7a069f7ba8579e34c5ab0203010001a350304e301d0603551d0e04160414ab7804d83f3ef207d8b56558471168fd991e3fc8301f0603551d23041830168014ab7804d83f3ef207d8b56558471168fd991e3fc8300c0603551d13040530030101ff300d06092a864886f70d010105050003818100919c10ff3faf93447b7b7faa384a5210539e5cce7eb1f387f27deaf1acf9677c7d7dd6b4de0daf00e741cfd2423b78c4f0c121ce99549e2b6cc6256115c7ba30c854877db2e64025e75df5f1e043400e10e4ea5cdf3cfc52db EAP-Message = 0xb26dcaa05b350787f705ee60634cdb280259508cfba7315ba658b09672b1cc7df5574beb7f6e86160301020d0c0002090080e987d2b6a373021a4e5359f8fff93f114a6c640d7a2d3da355b271449e073dd165d03bad6909d985e7073e9c4eea8508b5b99445b09fac2412452b0ab34acad5435d5c6d0800cbf6947f44820324e5e617cf0bfab1cdcaa37143bf296e7a19fb5402c830f5cba0af33e866a41dd8913bf07ee1cab3b3b544a2a703921b57fe4b00010200806ce84888bfa51384a4b42496a40029f85ee2c77a157681ab174f96bc6f46e6e1eca0f089f879cc16789b21d028fd30af4a9854b1e98d98589302095fed1eb94cb066855c2d84 EAP-Message = 0x11bbd20328387287cd664b7693dfd25e79271c1eeb01ab72073a8f3a6a1ba26d8f49e41390cc845cf42e387ec8ea5f32834b41098293334ceac6010095c29f5fff4eeb8fcd0b5e3041ca62e9df4fc98312f0d6df5382a16e1a45bb37d461ed0d10966f5d3f956c753b5bdfc0ac1a3cb0b6693392ac02764b8d96845dbd754305990082a6a8e7063c78a8c8d07c537555fcd3966209b81f79f3cc2603192f8510ada3280975fc06dc9b0e545a49129e15d75345179e65752b153ea4d323fd262ada320cd22d3b131bc8fc49cbcaafb34d57c39d91590bc4847cb1d3bf693cf8ba46ee09b3b8ad50ae578ef5e866096cce4b83692c0aa1b7dd7a3cc62d91 EAP-Message = 0x6d0dada9d43dc0327112afd7 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xf1b684cff2b291881bf75674bfd214cc Fri Dec 1 16:23:12 2017 : Info: Finished request 3. Fri Dec 1 16:23:12 2017 : Debug: Going to the next request Fri Dec 1 16:23:12 2017 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.100.2 port 1645, id=162, length=162 NAS-IP-Address = 192.168.100.2 NAS-Port = 4 NAS-Port-Type = Ethernet User-Name = "IxiaUser3" Called-Station-Id = "00-0A-F3-30-77-0A" Calling-Station-Id = "46-1B-6D-CC-00-00" Service-Type = Framed-User Framed-MTU = 1500 Calling-Station-Id = "34-36-2d-31-42-2d" State = 0xf1b684cff2b291881bf75674bfd214cc EAP-Message = 0x020400061500 Message-Authenticator = 0x5e228a19f56f356679f5ff250df22318 Fri Dec 1 16:23:12 2017 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:12 2017 : Info: +group authorize { Fri Dec 1 16:23:12 2017 : Info: ++[preprocess] = ok Fri Dec 1 16:23:12 2017 : Info: ++[chap] = noop Fri Dec 1 16:23:12 2017 : Info: ++[mschap] = noop Fri Dec 1 16:23:12 2017 : Info: ++[digest] = noop Fri Dec 1 16:23:12 2017 : Info: [suffix] No '@' in User-Name = "IxiaUser3", looking up realm NULL Fri Dec 1 16:23:12 2017 : Info: [suffix] No such realm "NULL" Fri Dec 1 16:23:12 2017 : Info: ++[suffix] = noop Fri Dec 1 16:23:12 2017 : Info: [eap] EAP packet type response id 4 length 6 Fri Dec 1 16:23:12 2017 : Info: [eap] Continuing tunnel setup. Fri Dec 1 16:23:12 2017 : Info: ++[eap] = ok Fri Dec 1 16:23:12 2017 : Info: +} # group authorize = ok Fri Dec 1 16:23:12 2017 : Info: Found Auth-Type = EAP Fri Dec 1 16:23:12 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:12 2017 : Info: +group authenticate { Fri Dec 1 16:23:12 2017 : Info: [eap] Request found, released from the list Fri Dec 1 16:23:12 2017 : Info: [eap] EAP/ttls Fri Dec 1 16:23:12 2017 : Info: [eap] processing type ttls Fri Dec 1 16:23:12 2017 : Info: [ttls] Authenticate Fri Dec 1 16:23:12 2017 : Info: [ttls] processing EAP-TLS Fri Dec 1 16:23:12 2017 : Info: [ttls] Received TLS ACK Fri Dec 1 16:23:12 2017 : Info: [ttls] ACK handshake fragment handler Fri Dec 1 16:23:12 2017 : Info: [ttls] eaptls_verify returned 1 Fri Dec 1 16:23:12 2017 : Info: [ttls] eaptls_process returned 13 Fri Dec 1 16:23:12 2017 : Info: ++[eap] = handled Fri Dec 1 16:23:12 2017 : Info: +} # group authenticate = handled Sending Access-Challenge of id 162 to 192.168.100.2 port 1645 EAP-Message = 0x01050046158000000828bafe736b94c5ee50100c15ef3cd0cb1d893df55df17f06b95810f5b69878b98abf524f7ab6dc0501d4b11b0311e2eb42412a7316030100040e000000 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xf1b684cff5b391881bf75674bfd214cc Fri Dec 1 16:23:12 2017 : Info: Finished request 4. Fri Dec 1 16:23:12 2017 : Debug: Going to the next request Fri Dec 1 16:23:12 2017 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.100.2 port 1645, id=163, length=364 NAS-IP-Address = 192.168.100.2 NAS-Port = 4 NAS-Port-Type = Ethernet User-Name = "IxiaUser3" Called-Station-Id = "00-0A-F3-30-77-0A" Calling-Station-Id = "46-1B-6D-CC-00-00" Service-Type = Framed-User Framed-MTU = 1500 Calling-Station-Id = "34-36-2d-31-42-2d" State = 0xf1b684cff5b391881bf75674bfd214cc EAP-Message = 0x020500d01580000000c61603010086100000820080112e892bc29395e716668ae50d54cbc23d6bc0c99cdb3843e95e84ecfb607ec63d6b93e2cc76619c0236c83ba235bb0c606f6b544b7fc4a7cb3d720ee30b8b199baabe03229b263bcef5d8a7c6580cb56eaeeb83e8912f2ed165cd63819f3ab3580dbcdc833587045d36c52e5500a0fa197842e8a9123b6a6bac72c6e9df5d96140301000101160301003099a74e3fe02111c03f218c8ae535322b174fa1436b9cda0bca2db8b28d18c139bd0c744d5f3232d91b54b57d9c974199 Message-Authenticator = 0xbcfcdeeb0f3d459054d61c477a5aa968 Fri Dec 1 16:23:13 2017 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:13 2017 : Info: +group authorize { Fri Dec 1 16:23:13 2017 : Info: ++[preprocess] = ok Fri Dec 1 16:23:13 2017 : Info: ++[chap] = noop Fri Dec 1 16:23:13 2017 : Info: ++[mschap] = noop Fri Dec 1 16:23:13 2017 : Info: ++[digest] = noop Fri Dec 1 16:23:13 2017 : Info: [suffix] No '@' in User-Name = "IxiaUser3", looking up realm NULL Fri Dec 1 16:23:13 2017 : Info: [suffix] No such realm "NULL" Fri Dec 1 16:23:13 2017 : Info: ++[suffix] = noop Fri Dec 1 16:23:13 2017 : Info: [eap] EAP packet type response id 5 length 208 Fri Dec 1 16:23:13 2017 : Info: [eap] Continuing tunnel setup. Fri Dec 1 16:23:13 2017 : Info: ++[eap] = ok Fri Dec 1 16:23:13 2017 : Info: +} # group authorize = ok Fri Dec 1 16:23:13 2017 : Info: Found Auth-Type = EAP Fri Dec 1 16:23:13 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:13 2017 : Info: +group authenticate { Fri Dec 1 16:23:13 2017 : Info: [eap] Request found, released from the list Fri Dec 1 16:23:13 2017 : Info: [eap] EAP/ttls Fri Dec 1 16:23:13 2017 : Info: [eap] processing type ttls Fri Dec 1 16:23:13 2017 : Info: [ttls] Authenticate Fri Dec 1 16:23:13 2017 : Info: [ttls] processing EAP-TLS Fri Dec 1 16:23:13 2017 : Debug: TLS Length 198 Fri Dec 1 16:23:13 2017 : Info: [ttls] Length Included Fri Dec 1 16:23:13 2017 : Info: [ttls] eaptls_verify returned 11 Fri Dec 1 16:23:13 2017 : Info: [ttls] <<< Unknown TLS version [length 0005] Fri Dec 1 16:23:13 2017 : Info: [ttls] <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange Fri Dec 1 16:23:13 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:13 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:13 2017 : Info: [ttls] <<< Unknown TLS version [length 0005] Fri Dec 1 16:23:13 2017 : Info: [ttls] <<< TLS 1.0 ChangeCipherSpec [length 0001] Fri Dec 1 16:23:13 2017 : Info: [ttls] <<< Unknown TLS version [length 0005] Fri Dec 1 16:23:13 2017 : Info: [ttls] <<< TLS 1.0 Handshake [length 0010], Finished Fri Dec 1 16:23:13 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:13 2017 : Info: [ttls] >>> Unknown TLS version [length 0005] Fri Dec 1 16:23:13 2017 : Info: [ttls] >>> TLS 1.0 ChangeCipherSpec [length 0001] Fri Dec 1 16:23:13 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:13 2017 : Info: [ttls] >>> Unknown TLS version [length 0005] Fri Dec 1 16:23:13 2017 : Info: [ttls] >>> TLS 1.0 Handshake [length 0010], Finished Fri Dec 1 16:23:13 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:13 2017 : Info: [ttls] TLS_accept: unknown state Fri Dec 1 16:23:13 2017 : Info: [ttls] (other): SSL negotiation finished successfully Fri Dec 1 16:23:13 2017 : Debug: SSL Connection Established Fri Dec 1 16:23:13 2017 : Info: [ttls] eaptls_process returned 13 Fri Dec 1 16:23:13 2017 : Info: ++[eap] = handled Fri Dec 1 16:23:13 2017 : Info: +} # group authenticate = handled Sending Access-Challenge of id 163 to 192.168.100.2 port 1645 EAP-Message = 0x0106004515800000003b1403010001011603010030312e304121a01ebc22ff4e21ef6f0e501606767c1c85aa6daf0dbdab818caa226318b09fac482933091e67cffa7d0988 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xf1b684cff4b091881bf75674bfd214cc Fri Dec 1 16:23:13 2017 : Info: Finished request 5. Fri Dec 1 16:23:13 2017 : Debug: Going to the next request Fri Dec 1 16:23:13 2017 : Debug: Waking up in 4.3 seconds. rad_recv: Access-Request packet from host 192.168.100.2 port 1645, id=164, length=348 NAS-IP-Address = 192.168.100.2 NAS-Port = 4 NAS-Port-Type = Ethernet User-Name = "IxiaUser3" Called-Station-Id = "00-0A-F3-30-77-0A" Calling-Station-Id = "46-1B-6D-CC-00-00" Service-Type = Framed-User Framed-MTU = 1500 Calling-Station-Id = "34-36-2d-31-42-2d" State = 0xf1b684cff4b091881bf75674bfd214cc EAP-Message = 0x020600c015001703010020841ae00c9f4fe67bdea8770668ffc3311394b948f6d9a7f88fedd20841aa15e5170301009099e4587fae0f7c948f1da6d1f269907ec82a3f5b6b642445d8680ce96052c61992345674ba0f0d3f3ead3498b9bc8b22735271b1197973b7ec584b08f578989fefc7ba2e150a5b989431c0116485b02ef9248610978741ee7a30c192aaabbbf4ab555e833f045d2e89a9a2cbc1d3ac72125922f90b7a9c45176a5b124e8729e8965d7430f3eb3c1bb0b2d5a92c81a944 Message-Authenticator = 0x0f1151665c2472b2f0627e91f8ee74eb Fri Dec 1 16:23:13 2017 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:13 2017 : Info: +group authorize { Fri Dec 1 16:23:13 2017 : Info: ++[preprocess] = ok Fri Dec 1 16:23:13 2017 : Info: ++[chap] = noop Fri Dec 1 16:23:13 2017 : Info: ++[mschap] = noop Fri Dec 1 16:23:13 2017 : Info: ++[digest] = noop Fri Dec 1 16:23:13 2017 : Info: [suffix] No '@' in User-Name = "IxiaUser3", looking up realm NULL Fri Dec 1 16:23:13 2017 : Info: [suffix] No such realm "NULL" Fri Dec 1 16:23:13 2017 : Info: ++[suffix] = noop Fri Dec 1 16:23:13 2017 : Info: [eap] EAP packet type response id 6 length 192 Fri Dec 1 16:23:13 2017 : Info: [eap] Continuing tunnel setup. Fri Dec 1 16:23:13 2017 : Info: ++[eap] = ok Fri Dec 1 16:23:13 2017 : Info: +} # group authorize = ok Fri Dec 1 16:23:13 2017 : Info: Found Auth-Type = EAP Fri Dec 1 16:23:13 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:13 2017 : Info: +group authenticate { Fri Dec 1 16:23:13 2017 : Info: [eap] Request found, released from the list Fri Dec 1 16:23:13 2017 : Info: [eap] EAP/ttls Fri Dec 1 16:23:13 2017 : Info: [eap] processing type ttls Fri Dec 1 16:23:13 2017 : Info: [ttls] Authenticate Fri Dec 1 16:23:13 2017 : Info: [ttls] processing EAP-TLS Fri Dec 1 16:23:13 2017 : Info: [ttls] eaptls_verify returned 7 Fri Dec 1 16:23:13 2017 : Info: [ttls] Done initial handshake Fri Dec 1 16:23:13 2017 : Info: [ttls] <<< Unknown TLS version [length 0005] Fri Dec 1 16:23:13 2017 : Info: [ttls] <<< Unknown TLS version [length 0005] Fri Dec 1 16:23:13 2017 : Info: [ttls] eaptls_process returned 7 Fri Dec 1 16:23:13 2017 : Info: [ttls] Session established. Proceeding to decode tunneled attributes. TTLS tunnel data in 0000: 00 00 00 01 40 00 00 11 49 78 69 61 55 73 65 72 TTLS tunnel data in 0010: 33 00 00 00 00 00 00 0b c0 00 00 1c 00 00 01 37 TTLS tunnel data in 0020: f3 0a 05 db a0 bb c4 8a c4 28 bd e5 ca e3 71 c8 TTLS tunnel data in 0030: 00 00 00 19 c0 00 00 3e 00 00 01 37 f8 00 f3 0a TTLS tunnel data in 0040: 05 db a0 bb c4 8a c4 28 bd e5 ca e3 71 c8 00 00 TTLS tunnel data in 0050: 00 00 00 00 00 00 70 f8 a8 10 a1 02 af 1a 13 2b TTLS tunnel data in 0060: 4b c5 1c 52 96 f2 d2 6f f1 e1 23 ed 75 30 f8 a8 Fri Dec 1 16:23:13 2017 : Info: [ttls] Got tunneled request User-Name = "IxiaUser3" MS-CHAP-Challenge = 0xf30a05dba0bbc48ac428bde5cae371c8 MS-CHAP2-Response = 0xf800f30a05dba0bbc48ac428bde5cae371c8000000000000000070f8a810a102af1a132b4bc51c5296f2d26ff1e123ed7530 FreeRADIUS-Proxied-To = 127.0.0.1 Fri Dec 1 16:23:13 2017 : Info: [ttls] Sending tunneled request User-Name = "IxiaUser3" MS-CHAP-Challenge = 0xf30a05dba0bbc48ac428bde5cae371c8 MS-CHAP2-Response = 0xf800f30a05dba0bbc48ac428bde5cae371c8000000000000000070f8a810a102af1a132b4bc51c5296f2d26ff1e123ed7530 FreeRADIUS-Proxied-To = 127.0.0.1 server inner-tunnel { Fri Dec 1 16:23:13 2017 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-tunnel Fri Dec 1 16:23:13 2017 : Info: +group authorize { Fri Dec 1 16:23:13 2017 : Info: ++[chap] = noop Fri Dec 1 16:23:13 2017 : Info: [mschap] Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Fri Dec 1 16:23:13 2017 : Info: ++[mschap] = ok Fri Dec 1 16:23:13 2017 : Info: [suffix] No '@' in User-Name = "IxiaUser3", looking up realm NULL Fri Dec 1 16:23:13 2017 : Info: [suffix] No such realm "NULL" Fri Dec 1 16:23:13 2017 : Info: ++[suffix] = noop Fri Dec 1 16:23:13 2017 : Info: ++update control { Fri Dec 1 16:23:13 2017 : Info: ++} # update control = noop Fri Dec 1 16:23:13 2017 : Info: [eap] No EAP-Message, not doing EAP Fri Dec 1 16:23:13 2017 : Info: ++[eap] = noop Fri Dec 1 16:23:13 2017 : Info: [files] users: Matched entry IxiaUser3 at line 92 Fri Dec 1 16:23:13 2017 : Info: ++[files] = ok Fri Dec 1 16:23:13 2017 : Info: ++[expiration] = noop Fri Dec 1 16:23:13 2017 : Info: ++[logintime] = noop Fri Dec 1 16:23:13 2017 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Fri Dec 1 16:23:13 2017 : Info: ++[pap] = noop Fri Dec 1 16:23:13 2017 : Info: +} # group authorize = ok Fri Dec 1 16:23:13 2017 : Info: Found Auth-Type = MSCHAP Fri Dec 1 16:23:13 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/inner-tunnel Fri Dec 1 16:23:13 2017 : Info: +group MS-CHAP { Fri Dec 1 16:23:13 2017 : Info: [mschap] Creating challenge hash with username: IxiaUser3 Fri Dec 1 16:23:13 2017 : Info: [mschap] Client is using MS-CHAPv2 for IxiaUser3, we need NT-Password Fri Dec 1 16:23:13 2017 : Info: [mschap] adding MS-CHAPv2 MPPE keys Fri Dec 1 16:23:13 2017 : Info: ++[mschap] = ok Fri Dec 1 16:23:13 2017 : Info: +} # group MS-CHAP = ok Fri Dec 1 16:23:13 2017 : Info: WARNING: Empty post-auth section. Using default return values. Fri Dec 1 16:23:13 2017 : Info: # Executing section post-auth from file /etc/freeradius/sites-enabled/inner-tunnel } # server inner-tunnel Fri Dec 1 16:23:13 2017 : Info: [ttls] Got tunneled reply code Access-Accept MS-CHAP2-Success = 0xf8533d39383035373142344434334232323341394244363144454137434537373232343431324436303335 MS-MPPE-Recv-Key = 0xa9b88bb81e0b4518f84216b64a2674e3 MS-MPPE-Send-Key = 0xf13a52dd26c6912ba4cd89838a0b51a2 MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 Fri Dec 1 16:23:13 2017 : Info: [ttls] Got tunneled Access-Accept Fri Dec 1 16:23:13 2017 : Info: [ttls] Got MS-CHAP2-Success, tunneling it to the client in a challenge. TTLS tunnel data out 0000: 00 00 00 1a c0 00 00 37 00 00 01 37 f8 53 3d 39 TTLS tunnel data out 0010: 38 30 35 37 31 42 34 44 34 33 42 32 32 33 41 39 TTLS tunnel data out 0020: 42 44 36 31 44 45 41 37 43 45 37 37 32 32 34 34 TTLS tunnel data out 0030: 31 32 44 36 30 33 35 00 Fri Dec 1 16:23:13 2017 : Info: [ttls] >>> Unknown TLS version [length 0005] Fri Dec 1 16:23:13 2017 : Info: ++[eap] = handled Fri Dec 1 16:23:13 2017 : Info: +} # group authenticate = handled Sending Access-Challenge of id 164 to 192.168.100.2 port 1645 EAP-Message = 0x0107005f1580000000551703010050fbef1df34d40fe47f95efc844991e1871ba7bdfc136147c1f2669f8ca56eccf1f57f66dc9e20d605c84e1b30535a58666c269037cd61242f88f96f55abe3715dfef3e2bb56f0b1d18c61d4f31de0e8d8 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xf1b684cff7b191881bf75674bfd214cc Fri Dec 1 16:23:13 2017 : Info: Finished request 6. Fri Dec 1 16:23:13 2017 : Debug: Going to the next request Fri Dec 1 16:23:13 2017 : Debug: Waking up in 4.3 seconds. rad_recv: Access-Request packet from host 192.168.100.2 port 1645, id=165, length=162 NAS-IP-Address = 192.168.100.2 NAS-Port = 4 NAS-Port-Type = Ethernet User-Name = "IxiaUser3" Called-Station-Id = "00-0A-F3-30-77-0A" Calling-Station-Id = "46-1B-6D-CC-00-00" Service-Type = Framed-User Framed-MTU = 1500 Calling-Station-Id = "34-36-2d-31-42-2d" State = 0xf1b684cff7b191881bf75674bfd214cc EAP-Message = 0x020700061500 Message-Authenticator = 0x8781ec66fa8734c7aa63c177c1a09eed Fri Dec 1 16:23:13 2017 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:13 2017 : Info: +group authorize { Fri Dec 1 16:23:13 2017 : Info: ++[preprocess] = ok Fri Dec 1 16:23:13 2017 : Info: ++[chap] = noop Fri Dec 1 16:23:13 2017 : Info: ++[mschap] = noop Fri Dec 1 16:23:13 2017 : Info: ++[digest] = noop Fri Dec 1 16:23:13 2017 : Info: [suffix] No '@' in User-Name = "IxiaUser3", looking up realm NULL Fri Dec 1 16:23:13 2017 : Info: [suffix] No such realm "NULL" Fri Dec 1 16:23:13 2017 : Info: ++[suffix] = noop Fri Dec 1 16:23:13 2017 : Info: [eap] EAP packet type response id 7 length 6 Fri Dec 1 16:23:13 2017 : Info: [eap] Continuing tunnel setup. Fri Dec 1 16:23:13 2017 : Info: ++[eap] = ok Fri Dec 1 16:23:13 2017 : Info: +} # group authorize = ok Fri Dec 1 16:23:13 2017 : Info: Found Auth-Type = EAP Fri Dec 1 16:23:13 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:13 2017 : Info: +group authenticate { Fri Dec 1 16:23:13 2017 : Info: [eap] Request found, released from the list Fri Dec 1 16:23:13 2017 : Info: [eap] EAP/ttls Fri Dec 1 16:23:13 2017 : Info: [eap] processing type ttls Fri Dec 1 16:23:13 2017 : Info: [ttls] Authenticate Fri Dec 1 16:23:13 2017 : Info: [ttls] processing EAP-TLS Fri Dec 1 16:23:13 2017 : Info: [ttls] Received TLS ACK Fri Dec 1 16:23:13 2017 : Info: [ttls] ACK default Fri Dec 1 16:23:13 2017 : Error: [ttls] Invalid ACK received: 0 Fri Dec 1 16:23:13 2017 : Info: [ttls] eaptls_verify returned 4 Fri Dec 1 16:23:13 2017 : Info: [ttls] eaptls_process returned 4 Fri Dec 1 16:23:13 2017 : Info: [eap] Handler failed in EAP/ttls Fri Dec 1 16:23:13 2017 : Info: [eap] Failed in EAP select Fri Dec 1 16:23:13 2017 : Info: ++[eap] = invalid Fri Dec 1 16:23:13 2017 : Info: +} # group authenticate = invalid Fri Dec 1 16:23:13 2017 : Info: Failed to authenticate the user. Fri Dec 1 16:23:13 2017 : Info: Using Post-Auth-Type Reject Fri Dec 1 16:23:13 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Fri Dec 1 16:23:13 2017 : Info: +group REJECT { Fri Dec 1 16:23:13 2017 : Info: [eap] Reply already contained an EAP-Message, not inserting EAP-Failure Fri Dec 1 16:23:13 2017 : Info: ++[eap] = noop Fri Dec 1 16:23:13 2017 : Info: [attr_filter.access_reject] expand: %{User-Name} -> IxiaUser3 Fri Dec 1 16:23:13 2017 : Debug: attr_filter: Matched entry DEFAULT at line 11 Fri Dec 1 16:23:13 2017 : Info: ++[attr_filter.access_reject] = updated Fri Dec 1 16:23:13 2017 : Info: +} # group REJECT = updated Fri Dec 1 16:23:13 2017 : Info: Delaying reject of request 7 for 1 seconds Fri Dec 1 16:23:13 2017 : Debug: Going to the next request Fri Dec 1 16:23:13 2017 : Debug: Waking up in 0.9 seconds. Fri Dec 1 16:23:14 2017 : Info: Sending delayed reject for request 7 Sending Access-Reject of id 165 to 192.168.100.2 port 1645 EAP-Message = 0x04070004 Message-Authenticator = 0x00000000000000000000000000000000 Fri Dec 1 16:23:14 2017 : Debug: Waking up in 3.3 seconds. Fri Dec 1 16:23:17 2017 : Info: Cleaning up request 0 ID 158 with timestamp +88 Fri Dec 1 16:23:17 2017 : Info: Cleaning up request 1 ID 159 with timestamp +88 Fri Dec 1 16:23:17 2017 : Info: Cleaning up request 2 ID 160 with timestamp +88 Fri Dec 1 16:23:17 2017 : Info: Cleaning up request 3 ID 161 with timestamp +88 Fri Dec 1 16:23:17 2017 : Info: Cleaning up request 4 ID 162 with timestamp +88 Fri Dec 1 16:23:17 2017 : Debug: Waking up in 0.5 seconds. Fri Dec 1 16:23:18 2017 : Info: Cleaning up request 5 ID 163 with timestamp +89 Fri Dec 1 16:23:18 2017 : Info: Cleaning up request 6 ID 164 with timestamp +89 Fri Dec 1 16:23:18 2017 : Debug: Waking up in 1.0 seconds. Fri Dec 1 16:23:19 2017 : Info: Cleaning up request 7 ID 165 with timestamp +89 Fri Dec 1 16:23:19 2017 : Info: Ready to process requests. With Regards, Smita
On Dec 6, 2017, at 5:36 AM, Smita Selot <SSelot@ixiacom.com> wrote:
I have installed Freeradius (version 2.2.8) on Ubuntu 16.04
v2 is end of life. Please use version 3. It's pre-packaged on Ubuntu.
and user authentication is working for MD5, PEAPv0 and TLS authentications. However TTLS authentication is failing. I see from the logs that the group authentication is failing.
The logs say that the server received an invalid ACK during TLS. It helps to read *all* of the logs.
Is there some configuration that I am missing?
Upgrade to v3.
This is the debug output from running "freeradius -xX":
Please don't do that. All of the docs say to use "-X". Alan DeKok.
participants (2)
-
Alan DeKok -
Smita Selot