Here is my debug thanks in advance Fri Oct 30 12:01:09 2015 : Info: FreeRADIUS Version 2.1.1, for host x86_64-suse-linux-gnu, built on Feb 25 2013 at 21:56:56 Fri Oct 30 12:01:09 2015 : Info: Copyright (C) 1999-2008 The FreeRADIUS server project and contributors. Fri Oct 30 12:01:09 2015 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Fri Oct 30 12:01:09 2015 : Info: PARTICULAR PURPOSE. Fri Oct 30 12:01:09 2015 : Info: You may redistribute copies of FreeRADIUS under the terms of the Fri Oct 30 12:01:09 2015 : Info: GNU General Public License v2. Fri Oct 30 12:01:09 2015 : Info: Starting - reading configuration files ... Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/radiusd.conf Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/proxy.conf Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/clients.conf Fri Oct 30 12:01:09 2015 : Debug: including files in directory /etc/raddb/modules/ Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/attr_filter Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/attr_rewrite Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/mac2vlan Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/mschap Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/exec Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/etc_group Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/checkval Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/krb5 Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/detail.example.com Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/inner-eap Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/ldap Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/expiration Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/logintime Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/realm Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/passwd Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/always Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/unix Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/sradutmp Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/expr Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/detail Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/mac2ip Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/digest Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/ippool Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/linelog Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/sql_log Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/policy Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/chap Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/pap Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/pam Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/preprocess Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/smbpasswd Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/wimax Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/detail.log Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/acct_unique Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/radutmp Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/counter Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/files Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/modules/echo Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/eap.conf Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/sql.conf Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/sql/mysql/dialup.conf Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/sql/mysql/counter.conf Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/policy.conf Fri Oct 30 12:01:09 2015 : Debug: including files in directory /etc/raddb/sites-enabled/ Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/sites-enabled/inner-tunnel Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/sites-enabled/default Fri Oct 30 12:01:09 2015 : Debug: including configuration file /etc/raddb/sites-enabled/inner-tunnel-bak Fri Oct 30 12:01:09 2015 : Debug: group = radiusd Fri Oct 30 12:01:09 2015 : Debug: user = radiusd Fri Oct 30 12:01:09 2015 : Debug: including dictionary file /etc/raddb/dictionary Fri Oct 30 12:01:09 2015 : Debug: main { Fri Oct 30 12:01:09 2015 : Debug: prefix = "/usr" Fri Oct 30 12:01:09 2015 : Debug: localstatedir = "/var" Fri Oct 30 12:01:09 2015 : Debug: logdir = "/var/log/radius" Fri Oct 30 12:01:09 2015 : Debug: libdir = "/usr/lib64/freeradius" Fri Oct 30 12:01:09 2015 : Debug: radacctdir = "/var/log/radius/radacct" Fri Oct 30 12:01:09 2015 : Debug: hostname_lookups = no Fri Oct 30 12:01:09 2015 : Debug: max_request_time = 30 Fri Oct 30 12:01:09 2015 : Debug: cleanup_delay = 5 Fri Oct 30 12:01:09 2015 : Debug: max_requests = 1024 Fri Oct 30 12:01:09 2015 : Debug: allow_core_dumps = no Fri Oct 30 12:01:09 2015 : Debug: pidfile = "/var/run/radiusd/radiusd.pid" Fri Oct 30 12:01:09 2015 : Debug: checkrad = "/usr/sbin/checkrad" Fri Oct 30 12:01:09 2015 : Debug: debug_level = 0 Fri Oct 30 12:01:09 2015 : Debug: proxy_requests = yes Fri Oct 30 12:01:09 2015 : Debug: log { Fri Oct 30 12:01:09 2015 : Debug: stripped_names = no Fri Oct 30 12:01:09 2015 : Debug: auth = no Fri Oct 30 12:01:09 2015 : Debug: auth_badpass = no Fri Oct 30 12:01:09 2015 : Debug: auth_goodpass = no Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: security { Fri Oct 30 12:01:09 2015 : Debug: max_attributes = 200 Fri Oct 30 12:01:09 2015 : Debug: reject_delay = 1 Fri Oct 30 12:01:09 2015 : Debug: status_server = yes Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: client localhost { Fri Oct 30 12:01:09 2015 : Debug: ipaddr = 127.0.0.1 Fri Oct 30 12:01:09 2015 : Debug: require_message_authenticator = no Fri Oct 30 12:01:09 2015 : Debug: secret = "testing123" Fri Oct 30 12:01:09 2015 : Debug: nastype = "other" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: client x.x.x.11 { Fri Oct 30 12:01:09 2015 : Debug: require_message_authenticator = no Fri Oct 30 12:01:09 2015 : Debug: secret = "testing123" Fri Oct 30 12:01:09 2015 : Debug: shortname = "AP1" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: client x.x.x.12 { Fri Oct 30 12:01:09 2015 : Debug: require_message_authenticator = no Fri Oct 30 12:01:09 2015 : Debug: secret = "testing123" Fri Oct 30 12:01:09 2015 : Debug: shortname = "AP2" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: client x.x.y.0/24 { Fri Oct 30 12:01:09 2015 : Debug: require_message_authenticator = no Fri Oct 30 12:01:09 2015 : Debug: secret = "testing123" Fri Oct 30 12:01:09 2015 : Debug: shortname = "private-network-1" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: client x.x.x.0/24 { Fri Oct 30 12:01:09 2015 : Debug: require_message_authenticator = no Fri Oct 30 12:01:09 2015 : Debug: secret = "testing123" Fri Oct 30 12:01:09 2015 : Debug: shortname = "private-network-2" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: radiusd: #### Loading Realms and Home Servers #### Fri Oct 30 12:01:09 2015 : Debug: proxy server { Fri Oct 30 12:01:09 2015 : Debug: retry_delay = 5 Fri Oct 30 12:01:09 2015 : Debug: retry_count = 3 Fri Oct 30 12:01:09 2015 : Debug: default_fallback = no Fri Oct 30 12:01:09 2015 : Debug: dead_time = 120 Fri Oct 30 12:01:09 2015 : Debug: wake_all_if_all_dead = no Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: home_server localhost { Fri Oct 30 12:01:09 2015 : Debug: ipaddr = 127.0.0.1 Fri Oct 30 12:01:09 2015 : Debug: port = 1812 Fri Oct 30 12:01:09 2015 : Debug: type = "auth" Fri Oct 30 12:01:09 2015 : Debug: secret = "testing123" Fri Oct 30 12:01:09 2015 : Debug: response_window = 20 Fri Oct 30 12:01:09 2015 : Debug: max_outstanding = 65536 Fri Oct 30 12:01:09 2015 : Debug: zombie_period = 40 Fri Oct 30 12:01:09 2015 : Debug: status_check = "status-server" Fri Oct 30 12:01:09 2015 : Debug: ping_interval = 30 Fri Oct 30 12:01:09 2015 : Debug: check_interval = 30 Fri Oct 30 12:01:09 2015 : Debug: num_answers_to_alive = 3 Fri Oct 30 12:01:09 2015 : Debug: num_pings_to_alive = 3 Fri Oct 30 12:01:09 2015 : Debug: revive_interval = 120 Fri Oct 30 12:01:09 2015 : Debug: status_check_timeout = 4 Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: home_server_pool my_auth_failover { Fri Oct 30 12:01:09 2015 : Debug: type = fail-over Fri Oct 30 12:01:09 2015 : Debug: home_server = localhost Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: realm example.com { Fri Oct 30 12:01:09 2015 : Debug: auth_pool = my_auth_failover Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: realm LOCAL { Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: radiusd: #### Instantiating modules #### Fri Oct 30 12:01:09 2015 : Debug: instantiate { Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_exec, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_exec Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating exec Fri Oct 30 12:01:09 2015 : Debug: exec { Fri Oct 30 12:01:09 2015 : Debug: wait = no Fri Oct 30 12:01:09 2015 : Debug: input_pairs = "request" Fri Oct 30 12:01:09 2015 : Debug: shell_escape = yes Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_expr, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_expr Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating expr Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_expiration, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_expiration Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating expiration Fri Oct 30 12:01:09 2015 : Debug: expiration { Fri Oct 30 12:01:09 2015 : Debug: reply-message = "Password Has Expired " Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_logintime, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_logintime Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating logintime Fri Oct 30 12:01:09 2015 : Debug: logintime { Fri Oct 30 12:01:09 2015 : Debug: reply-message = "You are calling outside your allowed timespan " Fri Oct 30 12:01:09 2015 : Debug: minimum-timeout = 60 Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: radiusd: #### Loading Virtual Servers #### Fri Oct 30 12:01:09 2015 : Debug: server inner-tunnel { Fri Oct 30 12:01:09 2015 : Debug: modules { Fri Oct 30 12:01:09 2015 : Debug: Module: Checking authenticate {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_pap, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_pap Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating pap Fri Oct 30 12:01:09 2015 : Debug: pap { Fri Oct 30 12:01:09 2015 : Debug: encryption_scheme = "auto" Fri Oct 30 12:01:09 2015 : Debug: auto_header = yes Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_eap, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_eap Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating eap Fri Oct 30 12:01:09 2015 : Debug: eap { Fri Oct 30 12:01:09 2015 : Debug: default_eap_type = "ttls" Fri Oct 30 12:01:09 2015 : Debug: timer_expire = 60 Fri Oct 30 12:01:09 2015 : Debug: ignore_unknown_eap_types = no Fri Oct 30 12:01:09 2015 : Debug: cisco_accounting_username_bug = no Fri Oct 30 12:01:09 2015 : Debug: max_sessions = 2048 Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to sub-module rlm_eap_md5 Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating eap-md5 Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to sub-module rlm_eap_gtc Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating eap-gtc Fri Oct 30 12:01:09 2015 : Debug: gtc { Fri Oct 30 12:01:09 2015 : Debug: challenge = "Password: " Fri Oct 30 12:01:09 2015 : Debug: auth_type = "PAP" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to sub-module rlm_eap_tls Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating eap-tls Fri Oct 30 12:01:09 2015 : Debug: tls { Fri Oct 30 12:01:09 2015 : Debug: rsa_key_exchange = no Fri Oct 30 12:01:09 2015 : Debug: dh_key_exchange = yes Fri Oct 30 12:01:09 2015 : Debug: rsa_key_length = 512 Fri Oct 30 12:01:09 2015 : Debug: dh_key_length = 512 Fri Oct 30 12:01:09 2015 : Debug: verify_depth = 0 Fri Oct 30 12:01:09 2015 : Debug: pem_file_type = yes Fri Oct 30 12:01:09 2015 : Debug: private_key_file = "/etc/raddb/certs/server.pem" Fri Oct 30 12:01:09 2015 : Debug: certificate_file = "/etc/raddb/certs/server.pem" Fri Oct 30 12:01:09 2015 : Debug: CA_file = "/etc/raddb/certs/ca.pem" Fri Oct 30 12:01:09 2015 : Debug: private_key_password = "whatever" Fri Oct 30 12:01:09 2015 : Debug: dh_file = "/etc/raddb/certs/dh" Fri Oct 30 12:01:09 2015 : Debug: random_file = "/etc/raddb/certs/random" Fri Oct 30 12:01:09 2015 : Debug: fragment_size = 1024 Fri Oct 30 12:01:09 2015 : Debug: include_length = yes Fri Oct 30 12:01:09 2015 : Debug: check_crl = no Fri Oct 30 12:01:09 2015 : Debug: cipher_list = "DEFAULT" Fri Oct 30 12:01:09 2015 : Debug: make_cert_command = "/etc/raddb/certs/bootstrap" Fri Oct 30 12:01:09 2015 : Debug: cache { Fri Oct 30 12:01:09 2015 : Debug: enable = no Fri Oct 30 12:01:09 2015 : Debug: lifetime = 24 Fri Oct 30 12:01:09 2015 : Debug: max_entries = 255 Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to sub-module rlm_eap_ttls Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating eap-ttls Fri Oct 30 12:01:09 2015 : Debug: ttls { Fri Oct 30 12:01:09 2015 : Debug: default_eap_type = "gtc" Fri Oct 30 12:01:09 2015 : Debug: copy_request_to_tunnel = yes Fri Oct 30 12:01:09 2015 : Debug: use_tunneled_reply = yes Fri Oct 30 12:01:09 2015 : Debug: virtual_server = "inner-tunnel" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to sub-module rlm_eap_peap Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating eap-peap Fri Oct 30 12:01:09 2015 : Debug: peap { Fri Oct 30 12:01:09 2015 : Debug: default_eap_type = "mschapv2" Fri Oct 30 12:01:09 2015 : Debug: copy_request_to_tunnel = no Fri Oct 30 12:01:09 2015 : Debug: use_tunneled_reply = no Fri Oct 30 12:01:09 2015 : Debug: proxy_tunneled_request_as_eap = yes Fri Oct 30 12:01:09 2015 : Debug: virtual_server = "inner-tunnel" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to sub-module rlm_eap_mschapv2 Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating eap-mschapv2 Fri Oct 30 12:01:09 2015 : Debug: mschapv2 { Fri Oct 30 12:01:09 2015 : Debug: with_ntdomain_hack = no Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Checking authorize {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_realm, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_realm Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating suffix Fri Oct 30 12:01:09 2015 : Debug: realm suffix { Fri Oct 30 12:01:09 2015 : Debug: format = "suffix" Fri Oct 30 12:01:09 2015 : Debug: delimiter = "@" Fri Oct 30 12:01:09 2015 : Debug: ignore_default = no Fri Oct 30 12:01:09 2015 : Debug: ignore_null = no Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Checking session {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_radutmp, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_radutmp Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating radutmp Fri Oct 30 12:01:09 2015 : Debug: radutmp { Fri Oct 30 12:01:09 2015 : Debug: filename = "/var/log/radius/radutmp" Fri Oct 30 12:01:09 2015 : Debug: username = "%{User-Name}" Fri Oct 30 12:01:09 2015 : Debug: case_sensitive = yes Fri Oct 30 12:01:09 2015 : Debug: check_with_nas = yes Fri Oct 30 12:01:09 2015 : Debug: perm = 384 Fri Oct 30 12:01:09 2015 : Debug: callerid = yes Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Checking post-proxy {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: Module: Checking post-auth {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_attr_filter, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_attr_filter Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating attr_filter.access_reject Fri Oct 30 12:01:09 2015 : Debug: attr_filter attr_filter.access_reject { Fri Oct 30 12:01:09 2015 : Debug: attrsfile = "/etc/raddb/attrs.access_reject" Fri Oct 30 12:01:09 2015 : Debug: key = "%{User-Name}" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: server inner-tunnel { Fri Oct 30 12:01:09 2015 : Debug: modules { Fri Oct 30 12:01:09 2015 : Debug: Module: Checking authenticate {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_chap, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_chap Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating chap Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_mschap, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_mschap Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating mschap Fri Oct 30 12:01:09 2015 : Debug: mschap { Fri Oct 30 12:01:09 2015 : Debug: use_mppe = yes Fri Oct 30 12:01:09 2015 : Debug: require_encryption = no Fri Oct 30 12:01:09 2015 : Debug: require_strong = no Fri Oct 30 12:01:09 2015 : Debug: with_ntdomain_hack = no Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_ldap, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_ldap Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating ldap Fri Oct 30 12:01:09 2015 : Debug: ldap { Fri Oct 30 12:01:09 2015 : Debug: server = "x.x.x.x" Fri Oct 30 12:01:09 2015 : Debug: port = 389 Fri Oct 30 12:01:09 2015 : Debug: password = "xxxxx" Fri Oct 30 12:01:09 2015 : Debug: identity = "xxxxxx" Fri Oct 30 12:01:09 2015 : Debug: net_timeout = 1 Fri Oct 30 12:01:09 2015 : Debug: timeout = 10 Fri Oct 30 12:01:09 2015 : Debug: timelimit = 10 Fri Oct 30 12:01:09 2015 : Debug: tls_mode = no Fri Oct 30 12:01:09 2015 : Debug: start_tls = no Fri Oct 30 12:01:09 2015 : Debug: tls_require_cert = "allow" Fri Oct 30 12:01:09 2015 : Debug: tls { Fri Oct 30 12:01:09 2015 : Debug: start_tls = no Fri Oct 30 12:01:09 2015 : Debug: require_cert = "allow" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: basedn = "xxxx" Fri Oct 30 12:01:09 2015 : Debug: filter = "(uid=%{Stripped-User-Name:-%{User-Name}})" Fri Oct 30 12:01:09 2015 : Debug: base_filter = "(objectclass=radiusprofile)" Fri Oct 30 12:01:09 2015 : Debug: password_attribute = "userPassword" Fri Oct 30 12:01:09 2015 : Debug: auto_header = no Fri Oct 30 12:01:09 2015 : Debug: access_attr_used_for_allow = yes Fri Oct 30 12:01:09 2015 : Debug: groupname_attribute = "cn" Fri Oct 30 12:01:09 2015 : Debug: groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn})))" Fri Oct 30 12:01:09 2015 : Debug: dictionary_mapping = "/etc/raddb/ldap.attrmap" Fri Oct 30 12:01:09 2015 : Debug: ldap_debug = 0 Fri Oct 30 12:01:09 2015 : Debug: ldap_connections_number = 10 Fri Oct 30 12:01:09 2015 : Debug: compare_check_items = no Fri Oct 30 12:01:09 2015 : Debug: do_xlat = yes Fri Oct 30 12:01:09 2015 : Debug: edir_account_policy_check = no Fri Oct 30 12:01:09 2015 : Debug: set_auth_type = yes Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: Registering ldap_groupcmp for Ldap-Group Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: Registering ldap_xlat with xlat_name ldap Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: reading ldap<->radius mappings from file /etc/raddb/ldap.attrmap Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusCheckItem mapped to RADIUS $GENERIC$ Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusReplyItem mapped to RADIUS $GENERIC$ Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusAuthType mapped to RADIUS Auth-Type Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusSimultaneousUse mapped to RADIUS Simultaneous-Use Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusCalledStationId mapped to RADIUS Called-Station-Id Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusCallingStationId mapped to RADIUS Calling-Station-Id Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP lmPassword mapped to RADIUS LM-Password Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP ntPassword mapped to RADIUS NT-Password Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP sambaLmPassword mapped to RADIUS LM-Password Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP sambaNtPassword mapped to RADIUS NT-Password Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP dBCSPwd mapped to RADIUS LM-Password Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP userPassword mapped to RADIUS Password-With-Header Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS SMB-Account-CTRL-TEXT Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusExpiration mapped to RADIUS Expiration Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusNASIpAddress mapped to RADIUS NAS-IP-Address Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusServiceType mapped to RADIUS Service-Type Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedProtocol mapped to RADIUS Framed-Protocol Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedIPAddress mapped to RADIUS Framed-IP-Address Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedIPNetmask mapped to RADIUS Framed-IP-Netmask Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedRoute mapped to RADIUS Framed-Route Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedRouting mapped to RADIUS Framed-Routing Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFilterId mapped to RADIUS Filter-Id Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedMTU mapped to RADIUS Framed-MTU Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedCompression mapped to RADIUS Framed-Compression Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusLoginIPHost mapped to RADIUS Login-IP-Host Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusLoginService mapped to RADIUS Login-Service Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped to RADIUS Login-TCP-Port Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusCallbackNumber mapped to RADIUS Callback-Number Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusCallbackId mapped to RADIUS Callback-Id Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedIPXNetwork mapped to RADIUS Framed-IPX-Network Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusClass mapped to RADIUS Class Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusSessionTimeout mapped to RADIUS Session-Timeout Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusIdleTimeout mapped to RADIUS Idle-Timeout Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusTerminationAction mapped to RADIUS Termination-Action Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusLoginLATService mapped to RADIUS Login-LAT-Service Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusLoginLATNode mapped to RADIUS Login-LAT-Node Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped to RADIUS Login-LAT-Group Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink mapped to RADIUS Framed-AppleTalk-Link Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone mapped to RADIUS Framed-AppleTalk-Zone Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusPortLimit mapped to RADIUS Port-Limit Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusLoginLATPort mapped to RADIUS Login-LAT-Port Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusReplyMessage mapped to RADIUS Reply-Message Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusTunnelType mapped to RADIUS Tunnel-Type Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusTunnelMediumType mapped to RADIUS Tunnel-Medium-Type Fri Oct 30 12:01:09 2015 : Debug: rlm_ldap: LDAP radiusTunnelPrivateGroupId mapped to RADIUS Tunnel-Private-Group-Id Fri Oct 30 12:01:09 2015 : Debug: conns: 0x7f04fd6cdfa0 Fri Oct 30 12:01:09 2015 : Debug: Module: Checking authorize {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_files, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_files Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating files Fri Oct 30 12:01:09 2015 : Debug: files { Fri Oct 30 12:01:09 2015 : Debug: usersfile = "/etc/raddb/users" Fri Oct 30 12:01:09 2015 : Debug: acctusersfile = "/etc/raddb/acct_users" Fri Oct 30 12:01:09 2015 : Debug: preproxy_usersfile = "/etc/raddb/preproxy_users" Fri Oct 30 12:01:09 2015 : Debug: compat = "no" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Checking session {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: Module: Checking post-proxy {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: Module: Checking post-auth {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: modules { Fri Oct 30 12:01:09 2015 : Debug: Module: Checking authenticate {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: Module: Checking authorize {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_preprocess, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_preprocess Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating preprocess Fri Oct 30 12:01:09 2015 : Debug: preprocess { Fri Oct 30 12:01:09 2015 : Debug: huntgroups = "/etc/raddb/huntgroups" Fri Oct 30 12:01:09 2015 : Debug: hints = "/etc/raddb/hints" Fri Oct 30 12:01:09 2015 : Debug: with_ascend_hack = no Fri Oct 30 12:01:09 2015 : Debug: ascend_channels_per_line = 23 Fri Oct 30 12:01:09 2015 : Debug: with_ntdomain_hack = no Fri Oct 30 12:01:09 2015 : Debug: with_specialix_jetstream_hack = no Fri Oct 30 12:01:09 2015 : Debug: with_cisco_vsa_hack = no Fri Oct 30 12:01:09 2015 : Debug: with_alvarion_vsa_hack = no Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Checking preacct {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_acct_unique Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating acct_unique Fri Oct 30 12:01:09 2015 : Debug: acct_unique { Fri Oct 30 12:01:09 2015 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Checking accounting {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_detail, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_detail Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating detail Fri Oct 30 12:01:09 2015 : Debug: detail { Fri Oct 30 12:01:09 2015 : Debug: detailfile = "/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Fri Oct 30 12:01:09 2015 : Debug: header = "%t" Fri Oct 30 12:01:09 2015 : Debug: detailperm = 384 Fri Oct 30 12:01:09 2015 : Debug: dirperm = 493 Fri Oct 30 12:01:09 2015 : Debug: locking = no Fri Oct 30 12:01:09 2015 : Debug: log_packet_header = no Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: (Loaded rlm_unix, checking if it's valid) Fri Oct 30 12:01:09 2015 : Debug: Module: Linked to module rlm_unix Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating unix Fri Oct 30 12:01:09 2015 : Debug: unix { Fri Oct 30 12:01:09 2015 : Debug: radwtmp = "/var/log/radius/radwtmp" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Instantiating attr_filter.accounting_response Fri Oct 30 12:01:09 2015 : Debug: attr_filter attr_filter.accounting_response { Fri Oct 30 12:01:09 2015 : Debug: attrsfile = "/etc/raddb/attrs.accounting_response" Fri Oct 30 12:01:09 2015 : Debug: key = "%{User-Name}" Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Module: Checking session {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: Module: Checking post-auth {...} for more modules to load Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: radiusd: #### Opening IP addresses and Ports #### Fri Oct 30 12:01:09 2015 : Debug: listen { Fri Oct 30 12:01:09 2015 : Debug: type = "auth" Fri Oct 30 12:01:09 2015 : Debug: ipaddr = * Fri Oct 30 12:01:09 2015 : Debug: port = 0 Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: listen { Fri Oct 30 12:01:09 2015 : Debug: type = "acct" Fri Oct 30 12:01:09 2015 : Debug: ipaddr = * Fri Oct 30 12:01:09 2015 : Debug: port = 0 Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: listen { Fri Oct 30 12:01:09 2015 : Debug: type = "auth" Fri Oct 30 12:01:09 2015 : Debug: ipaddr = 127.0.0.1 Fri Oct 30 12:01:09 2015 : Debug: port = 18120 Fri Oct 30 12:01:09 2015 : Debug: } Fri Oct 30 12:01:09 2015 : Debug: Listening on authentication address * port 1812 Fri Oct 30 12:01:09 2015 : Debug: Listening on accounting address * port 1813 Fri Oct 30 12:01:09 2015 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel Fri Oct 30 12:01:09 2015 : Debug: Listening on proxy address * port 1814 Fri Oct 30 12:01:09 2015 : Debug: Ready to process requests. rad_recv: Accounting-Request packet from host x.x.x.11 port 32839, id=114, length=199 Acct-Session-Id = "38724ED6-0000034A" Acct-Status-Type = Stop Acct-Authentic = Local User-Name = "c0bdd1207464" NAS-IP-Address = x.x.x.11 NAS-Identifier = "hello" NAS-Port = 0 Called-Station-Id = "44-94-FC-96-4F-20:dacag" Calling-Station-Id = "C0-BD-D1-20-74-64" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 0Mbps 802.11b" Acct-Session-Time = 441 Acct-Input-Packets = 3960 Acct-Output-Packets = 6679 Acct-Input-Octets = 316751 Acct-Output-Octets = 9186656 Event-Timestamp = "Jan 14 2000 16:18:03 AST" Acct-Terminate-Cause = User-Request Fri Oct 30 12:02:17 2015 : Info: +- entering group preacct {...} Fri Oct 30 12:02:17 2015 : Info: ++[preprocess] returns ok Fri Oct 30 12:02:17 2015 : Info: [acct_unique] Hashing 'NAS-Port = 0,Client-IP-Address = x.x.x.11,NAS-IP-Address = x.x.x.11,Acct-Session-Id = "38724ED6-0000034A",User-Name = "c0bdd1207464"' Fri Oct 30 12:02:17 2015 : Info: [acct_unique] Acct-Unique-Session-ID = "ff0403aade6cdfc0". Fri Oct 30 12:02:17 2015 : Info: ++[acct_unique] returns ok Fri Oct 30 12:02:17 2015 : Info: [suffix] No '@' in User-Name = "c0bdd1207464", looking up realm NULL Fri Oct 30 12:02:17 2015 : Info: [suffix] No such realm "NULL" Fri Oct 30 12:02:17 2015 : Info: ++[suffix] returns noop Fri Oct 30 12:02:17 2015 : Info: ++[files] returns noop Fri Oct 30 12:02:17 2015 : Info: +- entering group accounting {...} Fri Oct 30 12:02:17 2015 : Info: [detail] expand: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/radius/radacct/x.x.x.11/detail-20151030 Fri Oct 30 12:02:17 2015 : Info: [detail] /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/radius/radacct/x.x.x.11/detail-20151030 Fri Oct 30 12:02:17 2015 : Info: [detail] expand: %t -> Fri Oct 30 12:02:17 2015 Fri Oct 30 12:02:17 2015 : Info: ++[detail] returns ok Fri Oct 30 12:02:17 2015 : Info: ++[unix] returns ok Fri Oct 30 12:02:17 2015 : Info: [radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp Fri Oct 30 12:02:17 2015 : Info: [radutmp] expand: %{User-Name} -> c0bdd1207464 Fri Oct 30 12:02:17 2015 : Error: rlm_radutmp: Logout entry for NAS AP1 port 0 has wrong ID Fri Oct 30 12:02:17 2015 : Info: ++[radutmp] returns ok Fri Oct 30 12:02:17 2015 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> c0bdd1207464 Fri Oct 30 12:02:17 2015 : Debug: attr_filter: Matched entry DEFAULT at line 12 Fri Oct 30 12:02:17 2015 : Info: ++[attr_filter.accounting_response] returns updated Sending Accounting-Response of id 114 to x.x.x.11 port 32839 Fri Oct 30 12:02:17 2015 : Info: Finished request 0. Fri Oct 30 12:02:17 2015 : Info: Cleaning up request 0 ID 114 with timestamp +68 Fri Oct 30 12:02:17 2015 : Debug: Going to the next request Fri Oct 30 12:02:17 2015 : Debug: Ready to process requests. rad_recv: Access-Request packet from host x.x.x.11 port 32842, id=61, length=173 User-Name = "sur.name" NAS-IP-Address = x.x.x.11 NAS-Identifier = "hello" NAS-Port = 0 Called-Station-Id = "44-94-FC-96-4F-22:radiu" Calling-Station-Id = "C0-BD-D1-20-74-64" Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 0Mbps 802.11b" EAP-Message = 0x020000130169676f722e626f7264656c616973 Message-Authenticator = 0x6c0c26f29491cc7bb6bf4bd3a77c947d Fri Oct 30 12:02:17 2015 : Info: +- entering group authorize {...} Fri Oct 30 12:02:17 2015 : Info: ++[preprocess] returns ok Fri Oct 30 12:02:17 2015 : Info: [suffix] No '@' in User-Name = "sur.name", looking up realm NULL Fri Oct 30 12:02:17 2015 : Info: [suffix] No such realm "NULL" Fri Oct 30 12:02:17 2015 : Info: ++[suffix] returns noop Fri Oct 30 12:02:17 2015 : Info: [eap] EAP packet type response id 0 length 19 Fri Oct 30 12:02:17 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns updated Fri Oct 30 12:02:17 2015 : Info: [ldap] performing user authorization for sur.name Fri Oct 30 12:02:17 2015 : Info: [ldap] WARNING: Deprecated conditional expansion ":-". See "man unlang" for details Fri Oct 30 12:02:17 2015 : Info: [ldap] expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=sur.name) Fri Oct 30 12:02:17 2015 : Info: [ldap] expand: dc=aviation-civile,dc=gouv,dc=fr -> dc=aviation-civile,dc=gouv,dc=fr Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: attempting LDAP reconnection Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: (re)connect to x.x.x.246:389, authentication 0 Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: bind as uidNumber=1,sn=vvvvvv to x.x.x.x:389 Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: waiting for bind result ... Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: Bind was successful Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: performing search in dc=?, with filter (uid=sur,name) Fri Oct 30 12:02:17 2015 : Info: [ldap] Added User-Password = {SSHA}RFTRrfI+1oC8H3znYttYUy7nkM6Z0gxKIOdInQ== in check items Fri Oct 30 12:02:17 2015 : Info: [ldap] No default NMAS login sequence Fri Oct 30 12:02:17 2015 : Info: [ldap] looking for check items in directory... Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: userPassword -> Password-With-Header == "{SSHA}RFTRrfI+1oC8H3znYttYUy7nkM6Z0gxKIOdInQ==" Fri Oct 30 12:02:17 2015 : Info: [ldap] looking for reply items in directory... Fri Oct 30 12:02:17 2015 : Info: [ldap] user sur.name authorized to use remote access Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Fri Oct 30 12:02:17 2015 : Info: ++[ldap] returns ok Fri Oct 30 12:02:17 2015 : Info: ++[expiration] returns noop Fri Oct 30 12:02:17 2015 : Info: ++[logintime] returns noop Fri Oct 30 12:02:17 2015 : Info: [pap] Normalizing SSHA1-Password from base64 encoding Fri Oct 30 12:02:17 2015 : Info: [pap] Normalizing SSHA1-Password from base64 encoding Fri Oct 30 12:02:17 2015 : Info: [pap] Found existing Auth-Type, not changing it. Fri Oct 30 12:02:17 2015 : Info: ++[pap] returns noop Fri Oct 30 12:02:17 2015 : Info: Found Auth-Type = EAP Fri Oct 30 12:02:17 2015 : Info: +- entering group authenticate {...} Fri Oct 30 12:02:17 2015 : Info: [eap] EAP Identity Fri Oct 30 12:02:17 2015 : Info: [eap] processing type tls Fri Oct 30 12:02:17 2015 : Info: [tls] Initiate Fri Oct 30 12:02:17 2015 : Info: [tls] Start returned 1 Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns handled Sending Access-Challenge of id 61 to x.x.x.11 port 32842 EAP-Message = 0x010100061520 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfb55a41afb54b16008cc31758c0f388b Fri Oct 30 12:02:17 2015 : Info: Finished request 1. Fri Oct 30 12:02:17 2015 : Debug: Going to the next request Fri Oct 30 12:02:17 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host x.x.x.11 port 32842, id=62, length=376 User-Name = "sur.name" NAS-IP-Address = x.x.x.11 NAS-Identifier = "hello" NAS-Port = 0 Called-Station-Id = "44-94-FC-96-4F-22:radiu" Calling-Station-Id = "C0-BD-D1-20-74-64" Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 0Mbps 802.11b" EAP-Message = 0x020100cc150016030100c1010000bd0301f7e68f620de4c71a1ec27a781228a010716b6e0c96358674b77c904328e2f374000054c014c00ac022c02100390038c00fc0050035c012c008c01cc01b00160013c00dc003000ac013c009c01fc01e00330032c00ec004002fc011c007c00cc002000500040015001200090014001100080006000300ff01000040000b000403000102000a00340032000e000d0019000b000c00180009000a00160017000800060007001400150004000500120013000100020003000f00100011 State = 0xfb55a41afb54b16008cc31758c0f388b Message-Authenticator = 0x5df551af2f44dcee4fcd66101de8fba8 Fri Oct 30 12:02:17 2015 : Info: +- entering group authorize {...} Fri Oct 30 12:02:17 2015 : Info: ++[preprocess] returns ok Fri Oct 30 12:02:17 2015 : Info: [suffix] No '@' in User-Name = "sur.name", looking up realm NULL Fri Oct 30 12:02:17 2015 : Info: [suffix] No such realm "NULL" Fri Oct 30 12:02:17 2015 : Info: ++[suffix] returns noop Fri Oct 30 12:02:17 2015 : Info: [eap] EAP packet type response id 1 length 204 Fri Oct 30 12:02:17 2015 : Info: [eap] Continuing tunnel setup. Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns ok Fri Oct 30 12:02:17 2015 : Info: Found Auth-Type = EAP Fri Oct 30 12:02:17 2015 : Info: +- entering group authenticate {...} Fri Oct 30 12:02:17 2015 : Info: [eap] Request found, released from the list Fri Oct 30 12:02:17 2015 : Info: [eap] EAP/ttls Fri Oct 30 12:02:17 2015 : Info: [eap] processing type ttls Fri Oct 30 12:02:17 2015 : Info: [ttls] Authenticate Fri Oct 30 12:02:17 2015 : Info: [ttls] processing EAP-TLS Fri Oct 30 12:02:17 2015 : Info: [ttls] eaptls_verify returned 7 Fri Oct 30 12:02:17 2015 : Info: [ttls] Done initial handshake Fri Oct 30 12:02:17 2015 : Info: [ttls] (other): before/accept initialization Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: before/accept initialization Fri Oct 30 12:02:17 2015 : Info: [ttls] <<< TLS 1.0 Handshake [length 00c1], ClientHello Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 read client hello A Fri Oct 30 12:02:17 2015 : Info: [ttls]>>> TLS 1.0 Handshake [length 0031], ServerHello Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 write server hello A Fri Oct 30 12:02:17 2015 : Info: [ttls]>>> TLS 1.0 Handshake [length 085e], Certificate Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 write certificate A Fri Oct 30 12:02:17 2015 : Info: [ttls]>>> TLS 1.0 Handshake [length 020d], ServerKeyExchange Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 write key exchange A Fri Oct 30 12:02:17 2015 : Info: [ttls]>>> TLS 1.0 Handshake [length 0004], ServerHelloDone Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 write server done A Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 flush data Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: Need to read more data: SSLv3 read client certificate A Fri Oct 30 12:02:17 2015 : Debug: In SSL Handshake Phase Fri Oct 30 12:02:17 2015 : Debug: In SSL Accept mode Fri Oct 30 12:02:17 2015 : Info: [ttls] eaptls_process returned 13 Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns handled Sending Access-Challenge of id 62 to x.x.x.11 port 32842 EAP-Message = 0x0102040015c000000ab416030100310200002d0301563394891c80ada6f8f043a3a06584d6d17b8f761e2e66c5dbf3a2c311654e79000039000005ff01000100160301085e0b00085a0008570003a6308203a23082028aa003020102020101300d06092a864886f70d0101050500308193310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c65204365727469666963617465204175 EAP-Message = 0x74686f72697479301e170d3135303332363135323431355a170d3136303332353135323431355a307c310b3009060355040613024652310f300d0603550408130652616469757331153013060355040a130c4578616d706c6520496e632e312330210603550403131a4578616d706c65205365727665722043657274696669636174653120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d30820122300d06092a864886f70d01010105000382010f003082010a0282010100b844fff9a6811c3f38cdb467277a1c924d43a67b4877c4a66963b058d4a406deac5d604e7d5eaa6fa59099c0f057182823e697bf29c07c EAP-Message = 0x3726501377ea6dbcbee2976f3886987f2e3bf4a3cb36f08ab23c7b2fb1b9692cca6c696795031a0810c393c88a367c007ee6ebccf84e3b4cc0786fef198f81f9b96230ee682fc9761be19fad8bf508fcb1b48e8ea4a39e09be76bbce24440d69b0d705f9ade67051a235583c2ee4a332a04d6d610f4c6e4c9a9cf38c9523e96baac9c9e3a6e96dba142fc38576453428f2d0442ac1d6d13ffe488f7857f79de4d82b90e0e6df121c08d9198313458da67a0750fdf62bab30937fb00f5a02c7a688ae95ad5e17c6959d0203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d0101050500038201010043de EAP-Message = 0x6e366c40df86b2154b222865d9359c7a604848ccedbd034ed063f639910c3b28858e1dbdf1ee7d86f8649741cd479260e9d62d707214570cfc6351053b9463505a863ac892074636cd34ff1b276f824d1dac5f074248e4e392d8ce414ed5a019ad45668bc0e683fdf1753b0cd6e36182d32f39c38b4ceb925a155a7c40b20ec20a1f1a95cf293d396360e2d2f96f65b09cccac9b972b3a1eb22aa194a4b5097c260c80457772463acf3ec095a93b08b3fd4797ad6ee3b9bc4322baf5e9e45eb69d2c48767bcc676147c3a8955128cea4595625bf5ef6c9520585b805b7b5f81a3f8ed7e82613e50388ea011215ba5779ea132244eca81f7d92f898733e EAP-Message = 0x900004ab308204a73082038f Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfb55a41afa57b16008cc31758c0f388b Fri Oct 30 12:02:17 2015 : Info: Finished request 2. Fri Oct 30 12:02:17 2015 : Debug: Going to the next request Fri Oct 30 12:02:17 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host x.x.x.11 port 32842, id=63, length=178 User-Name = "sur.name" NAS-IP-Address = x.x.x.11 NAS-Identifier = "hello" NAS-Port = 0 Called-Station-Id = "44-94-FC-96-4F-22:radiu" Calling-Station-Id = "C0-BD-D1-20-74-64" Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 0Mbps 802.11b" EAP-Message = 0x020200061500 State = 0xfb55a41afa57b16008cc31758c0f388b Message-Authenticator = 0x8d22ff59b913926e07b5af548aed67b6 Fri Oct 30 12:02:17 2015 : Info: +- entering group authorize {...} Fri Oct 30 12:02:17 2015 : Info: ++[preprocess] returns ok Fri Oct 30 12:02:17 2015 : Info: [suffix] No '@' in User-Name = "sur.name", looking up realm NULL Fri Oct 30 12:02:17 2015 : Info: [suffix] No such realm "NULL" Fri Oct 30 12:02:17 2015 : Info: ++[suffix] returns noop Fri Oct 30 12:02:17 2015 : Info: [eap] EAP packet type response id 2 length 6 Fri Oct 30 12:02:17 2015 : Info: [eap] Continuing tunnel setup. Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns ok Fri Oct 30 12:02:17 2015 : Info: Found Auth-Type = EAP Fri Oct 30 12:02:17 2015 : Info: +- entering group authenticate {...} Fri Oct 30 12:02:17 2015 : Info: [eap] Request found, released from the list Fri Oct 30 12:02:17 2015 : Info: [eap] EAP/ttls Fri Oct 30 12:02:17 2015 : Info: [eap] processing type ttls Fri Oct 30 12:02:17 2015 : Info: [ttls] Authenticate Fri Oct 30 12:02:17 2015 : Info: [ttls] processing EAP-TLS Fri Oct 30 12:02:17 2015 : Info: [ttls] Received TLS ACK Fri Oct 30 12:02:17 2015 : Info: [ttls] ACK handshake fragment handler Fri Oct 30 12:02:17 2015 : Info: [ttls] eaptls_verify returned 1 Fri Oct 30 12:02:17 2015 : Info: [ttls] eaptls_process returned 13 Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns handled Sending Access-Challenge of id 63 to x.x.x.11 port 32842 EAP-Message = 0x0103040015c000000ab4a00302010202090093f94d5d0cac2aa0300d06092a864886f70d0101050500308193310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479301e170d3135303332363135323431355a170d3135303432353135323431355a308193310b3009060355040613024652310f300d06035504081306526164 EAP-Message = 0x6975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f7269747930820122300d06092a864886f70d01010105000382010f003082010a0282010100c49330b29b5e20134d7d3873ededd5517c1748f7f04f696842851ee613cb7fda1486278316b8d4066f0d4c4b8545b089797d06c54472b4dcb57b5d8adae391971c8ad4bee68b3d7e969b00187949f98080f6f51ed0905f55fce210fc8b2dc209ae6ee586 EAP-Message = 0xf5412475348fb499a6a333fa9f979659da60edae3cc14a60ea819fbcc72ca0c6240e3694da708bebc09d6e9c34b5267b22661d545eedd1fad36896880006f945152af6a946418496f521ab67d240399d4b61af37317bba906bd8876863173c6b509b02711f6d5e9c65d1b7f35308a70a8518e9768d1c00e5bd0ee4972a30aa9654e3f62bff52a5d76fc0e404d64b405cd60e9ac09fb85654704e27b90203010001a381fb3081f8301d0603551d0e04160414c54d0fa5259b04d3f9dd5d488dbb74243eee2e0b3081c80603551d230481c03081bd8014c54d0fa5259b04d3f9dd5d488dbb74243eee2e0ba18199a48196308193310b3009060355040613 EAP-Message = 0x024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f7269747982090093f94d5d0cac2aa0300c0603551d13040530030101ff300d06092a864886f70d01010505000382010100ad3711f91d43e677827d185b0529e2e97404d2a18be6fe250a6a38ff5ccf0f62019252b909420f09190f7cfd9e5565fe1f515cdc440a205a488330ef44a6ea4677cf888af6ba74 EAP-Message = 0x1d36debba53bf58769e47378 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfb55a41af956b16008cc31758c0f388b Fri Oct 30 12:02:17 2015 : Info: Finished request 3. Fri Oct 30 12:02:17 2015 : Debug: Going to the next request Fri Oct 30 12:02:17 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host x.x.x.11 port 32842, id=64, length=178 User-Name = "sur.name" NAS-IP-Address = x.x.x.11 NAS-Identifier = "hello" NAS-Port = 0 Called-Station-Id = "44-94-FC-96-4F-22:radiu" Calling-Station-Id = "C0-BD-D1-20-74-64" Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 0Mbps 802.11b" EAP-Message = 0x020300061500 State = 0xfb55a41af956b16008cc31758c0f388b Message-Authenticator = 0x6d80b8ae19c36b0c3af449fc48d01c54 Fri Oct 30 12:02:17 2015 : Info: +- entering group authorize {...} Fri Oct 30 12:02:17 2015 : Info: ++[preprocess] returns ok Fri Oct 30 12:02:17 2015 : Info: [suffix] No '@' in User-Name = "sur.name", looking up realm NULL Fri Oct 30 12:02:17 2015 : Info: [suffix] No such realm "NULL" Fri Oct 30 12:02:17 2015 : Info: ++[suffix] returns noop Fri Oct 30 12:02:17 2015 : Info: [eap] EAP packet type response id 3 length 6 Fri Oct 30 12:02:17 2015 : Info: [eap] Continuing tunnel setup. Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns ok Fri Oct 30 12:02:17 2015 : Info: Found Auth-Type = EAP Fri Oct 30 12:02:17 2015 : Info: +- entering group authenticate {...} Fri Oct 30 12:02:17 2015 : Info: [eap] Request found, released from the list Fri Oct 30 12:02:17 2015 : Info: [eap] EAP/ttls Fri Oct 30 12:02:17 2015 : Info: [eap] processing type ttls Fri Oct 30 12:02:17 2015 : Info: [ttls] Authenticate Fri Oct 30 12:02:17 2015 : Info: [ttls] processing EAP-TLS Fri Oct 30 12:02:17 2015 : Info: [ttls] Received TLS ACK Fri Oct 30 12:02:17 2015 : Info: [ttls] ACK handshake fragment handler Fri Oct 30 12:02:17 2015 : Info: [ttls] eaptls_verify returned 1 Fri Oct 30 12:02:17 2015 : Info: [ttls] eaptls_process returned 13 Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns handled Sending Access-Challenge of id 64 to x.x.x.11 port 32842 EAP-Message = 0x010402d2158000000ab4960410c0917b5819c4500b7b3d280f597fe3ae2e75e24c60caca11b8d738afdae08cc2780c9c8e6bc3daddc71e5f391660708818e07ac411c5bf247dda2fb09031fce4447f063d0a94e1d9e34c2493bb53d87618d83e4df56d65bc40b0750890de455d701fd53d617db91490ef004d91f4958ba07d01b3d055075d458892175106f5da4c162f14dc28f74db58b01964a209bfe64a00d4b33c7281359794c45e79ed847fcb49f7db23db2753dfe160301020d0c00020900808fc2fbaffcd9b4253135a756315c9cfa26ea2dc5565f917dafcbbdaa41c6750e7029757257161bf35a0a23306105f63c6848c1cce2e19ef12fa7aa EAP-Message = 0x874ff3d792e3bf5eaa289bfb15f56a93b35cfbab6c088b15442f393ec4ae96ce0a6f3ba1be7c081e09dec793a5e779600bd271c64c71dc3f3a5b8bcefbbe6453c87506eb7b0001020080659d707ba691ec3b87d012471819a4f9d331c8611fc2ea10c37df8e888f9afb7cafcbbae864e3fd23944191230113d2227f1de20d45c658312fa2216287e9ac8b43c7dc2b801a8a90290ba4381347b3e33b9a39c674cc4f616e5409d38a0083e74e7a0bdd5475691ddb48c16fbf6bd2e2de0700d17d25e2e3207a81b198d114b01003f0f0bf04f3b3a3c547cdbce64f9f0a3ac0ce3c2e56ba0cff4e01610f28c01b7b8d116f6ae72ef69e2ac3a5998a09d8eeb EAP-Message = 0xfd43b77418dd6276142c10d5de21d6a3423ebf349a2e432f19d0b54d29ac70b37b0d06fe8355c1819a919c868005d1cd7947d5ea510c544d40812ecbd7d597b6dc075177d931e152e0277dac5a33123170268bc988a0a29e66ca2ad2873c70ce640a5ddf98e6799ebc4e8a28b5b8e912402ac535fc3af0e7d840e8f7009b1a517101a496b9b3a3ea9c2b718cb35de3aac61703b848e02f2cd5fb196a6118e4fc0ab3fbad1f865dc79a4e6e91ba844dbf7e8c3cb8c1a3281508a9a6732240b1874a42d8baf91175577e862341a11f3b16030100040e000000 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfb55a41af851b16008cc31758c0f388b Fri Oct 30 12:02:17 2015 : Info: Finished request 4. Fri Oct 30 12:02:17 2015 : Debug: Going to the next request Fri Oct 30 12:02:17 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host x.x.x.11 port 32842, id=65, length=376 User-Name = "sur.name" NAS-IP-Address = x.x.x.11 NAS-Identifier = "hello" NAS-Port = 0 Called-Station-Id = "44-94-FC-96-4F-22:radiu" Calling-Station-Id = "C0-BD-D1-20-74-64" Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 0Mbps 802.11b" EAP-Message = 0x020400cc150016030100861000008200801e70c713da81c0055ec67136d17d29aa10789c988926167a8994545f99be6836c780ca887aac8e525790d1c09e7007671614fdfff8960834f6a0f3c04e44e648c06e4dbd5c3813fc5fbb2a7c127a13e58c78f6c814a466db187e536b7cec8395ee467dc0d8a6b0b3a309e6a87be7ba8764de3531a03f1e9d4e63261169ff4e2014030100010116030100307b905072b0db6679cba96b0ca4f862ad894a4d364075a95e783e425abe40b83f36b2f17ef580624769a7f83abfb6e606 State = 0xfb55a41af851b16008cc31758c0f388b Message-Authenticator = 0x689fcf867d0bdcb5a3f4b8249d54cb65 Fri Oct 30 12:02:17 2015 : Info: +- entering group authorize {...} Fri Oct 30 12:02:17 2015 : Info: ++[preprocess] returns ok Fri Oct 30 12:02:17 2015 : Info: [suffix] No '@' in User-Name = "sur.name", looking up realm NULL Fri Oct 30 12:02:17 2015 : Info: [suffix] No such realm "NULL" Fri Oct 30 12:02:17 2015 : Info: ++[suffix] returns noop Fri Oct 30 12:02:17 2015 : Info: [eap] EAP packet type response id 4 length 204 Fri Oct 30 12:02:17 2015 : Info: [eap] Continuing tunnel setup. Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns ok Fri Oct 30 12:02:17 2015 : Info: Found Auth-Type = EAP Fri Oct 30 12:02:17 2015 : Info: +- entering group authenticate {...} Fri Oct 30 12:02:17 2015 : Info: [eap] Request found, released from the list Fri Oct 30 12:02:17 2015 : Info: [eap] EAP/ttls Fri Oct 30 12:02:17 2015 : Info: [eap] processing type ttls Fri Oct 30 12:02:17 2015 : Info: [ttls] Authenticate Fri Oct 30 12:02:17 2015 : Info: [ttls] processing EAP-TLS Fri Oct 30 12:02:17 2015 : Info: [ttls] eaptls_verify returned 7 Fri Oct 30 12:02:17 2015 : Info: [ttls] Done initial handshake Fri Oct 30 12:02:17 2015 : Info: [ttls] <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 read client key exchange A Fri Oct 30 12:02:17 2015 : Info: [ttls] <<< TLS 1.0 ChangeCipherSpec [length 0001] Fri Oct 30 12:02:17 2015 : Info: [ttls] <<< TLS 1.0 Handshake [length 0010], Finished Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 read finished A Fri Oct 30 12:02:17 2015 : Info: [ttls]>>> TLS 1.0 ChangeCipherSpec [length 0001] Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 write change cipher spec A Fri Oct 30 12:02:17 2015 : Info: [ttls]>>> TLS 1.0 Handshake [length 0010], Finished Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 write finished A Fri Oct 30 12:02:17 2015 : Info: [ttls] TLS_accept: SSLv3 flush data Fri Oct 30 12:02:17 2015 : Info: [ttls] (other): SSL negotiation finished successfully Fri Oct 30 12:02:17 2015 : Debug: SSL Connection Established Fri Oct 30 12:02:17 2015 : Info: [ttls] eaptls_process returned 13 Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns handled Sending Access-Challenge of id 65 to x.x.x.11 port 32842 EAP-Message = 0x0105004515800000003b1403010001011603010030b216c9f0153800a4fb9df076fc94527d87c55b3775ba38717c12b744e7a36e112c6aeb77b81845075a1e0a50140aa135 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfb55a41aff50b16008cc31758c0f388b Fri Oct 30 12:02:17 2015 : Info: Finished request 5. Fri Oct 30 12:02:17 2015 : Debug: Going to the next request Fri Oct 30 12:02:17 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host x.x.x.11 port 32842, id=66, length=247 User-Name = "sur.name" NAS-IP-Address = x.x.x.11 NAS-Identifier = "hello" NAS-Port = 0 Called-Station-Id = "44-94-FC-96-4F-22:radiu" Calling-Station-Id = "C0-BD-D1-20-74-64" Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 0Mbps 802.11b" EAP-Message = 0x0205004b150017030100402bf295aee05516623c3c5cd0a9ab238b3f9c3d2e1ff5e89b27efb66e3c1f8e1e50dbd4edd47da6946f0e4f1bde3352045124c3ed134890c8361591874bef582f State = 0xfb55a41aff50b16008cc31758c0f388b Message-Authenticator = 0x48419f6825d77b5e661183affc196bef Fri Oct 30 12:02:17 2015 : Info: +- entering group authorize {...} Fri Oct 30 12:02:17 2015 : Info: ++[preprocess] returns ok Fri Oct 30 12:02:17 2015 : Info: [suffix] No '@' in User-Name = "sur.name", looking up realm NULL Fri Oct 30 12:02:17 2015 : Info: [suffix] No such realm "NULL" Fri Oct 30 12:02:17 2015 : Info: ++[suffix] returns noop Fri Oct 30 12:02:17 2015 : Info: [eap] EAP packet type response id 5 length 75 Fri Oct 30 12:02:17 2015 : Info: [eap] Continuing tunnel setup. Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns ok Fri Oct 30 12:02:17 2015 : Info: Found Auth-Type = EAP Fri Oct 30 12:02:17 2015 : Info: +- entering group authenticate {...} Fri Oct 30 12:02:17 2015 : Info: [eap] Request found, released from the list Fri Oct 30 12:02:17 2015 : Info: [eap] EAP/ttls Fri Oct 30 12:02:17 2015 : Info: [eap] processing type ttls Fri Oct 30 12:02:17 2015 : Info: [ttls] Authenticate Fri Oct 30 12:02:17 2015 : Info: [ttls] processing EAP-TLS Fri Oct 30 12:02:17 2015 : Info: [ttls] eaptls_verify returned 7 Fri Oct 30 12:02:17 2015 : Info: [ttls] Done initial handshake Fri Oct 30 12:02:17 2015 : Info: [ttls] eaptls_process returned 7 Fri Oct 30 12:02:17 2015 : Info: [ttls] Session established. Proceeding to decode tunneled attributes. Fri Oct 30 12:02:17 2015 : Info: [ttls] Got tunneled request EAP-Message = 0x020000130169676f722e626f7264656c616973 FreeRADIUS-Proxied-To = 127.0.0.1 Fri Oct 30 12:02:17 2015 : Info: [ttls] Got tunneled identity of sur.name Fri Oct 30 12:02:17 2015 : Info: [ttls] Setting default EAP type for tunneled EAP session. Fri Oct 30 12:02:17 2015 : Info: [ttls] Sending tunneled request EAP-Message = 0x020000130169676f722e626f7264656c616973 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "sur.name" NAS-IP-Address = x.x.x.11 NAS-Identifier = "hello" NAS-Port = 0 Called-Station-Id = "44-94-FC-96-4F-22:radiu" Calling-Station-Id = "C0-BD-D1-20-74-64" Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 0Mbps 802.11b" server inner-tunnel { Fri Oct 30 12:02:17 2015 : Info: +- entering group authorize {...} Fri Oct 30 12:02:17 2015 : Info: [suffix] No '@' in User-Name = "sur.name", looking up realm NULL Fri Oct 30 12:02:17 2015 : Info: [suffix] No such realm "NULL" Fri Oct 30 12:02:17 2015 : Info: ++[suffix] returns noop Fri Oct 30 12:02:17 2015 : Info: ++[control] returns noop Fri Oct 30 12:02:17 2015 : Info: [eap] EAP packet type response id 0 length 19 Fri Oct 30 12:02:17 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns updated Fri Oct 30 12:02:17 2015 : Info: ++[expiration] returns noop Fri Oct 30 12:02:17 2015 : Info: ++[logintime] returns noop Fri Oct 30 12:02:17 2015 : Info: ++[pap] returns noop Fri Oct 30 12:02:17 2015 : Info: ++[mschap] returns noop Fri Oct 30 12:02:17 2015 : Info: [suffix] No '@' in User-Name = "sur.name", looking up realm NULL Fri Oct 30 12:02:17 2015 : Info: [suffix] No such realm "NULL" Fri Oct 30 12:02:17 2015 : Info: ++[suffix] returns noop Fri Oct 30 12:02:17 2015 : Info: ++[control] returns noop Fri Oct 30 12:02:17 2015 : Info: [eap] EAP packet type response id 0 length 19 Fri Oct 30 12:02:17 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns updated Fri Oct 30 12:02:17 2015 : Info: ++[files] returns noop Fri Oct 30 12:02:17 2015 : Info: [ldap] performing user authorization for sur.name Fri Oct 30 12:02:17 2015 : Info: [ldap] WARNING: Deprecated conditional expansion ":-". See "man unlang" for details Fri Oct 30 12:02:17 2015 : Info: [ldap] expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=sur.name) Fri Oct 30 12:02:17 2015 : Info: [ldap] expand: dc=aviation-civile,dc=gouv,dc=fr -> dc=aviation-civile,dc=gouv,dc=fr Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: performing search in dc=aviation-civile,dc=gouv,dc=fr, with filter (uid=sur.name) Fri Oct 30 12:02:17 2015 : Info: [ldap] Added User-Password = {SSHA}RFTRrfI+1oC8H3znYttYUy7nkM6Z0gxKIOdInQ== in check items Fri Oct 30 12:02:17 2015 : Info: [ldap] No default NMAS login sequence Fri Oct 30 12:02:17 2015 : Info: [ldap] looking for check items in directory... Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: userPassword -> Password-With-Header == "{SSHA}RFTRrfI+1oC8H3znYttYUy7nkM6Z0gxKIOdInQ==" Fri Oct 30 12:02:17 2015 : Info: [ldap] looking for reply items in directory... Fri Oct 30 12:02:17 2015 : Info: [ldap] user sur.name authorized to use remote access Fri Oct 30 12:02:17 2015 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Fri Oct 30 12:02:17 2015 : Info: ++[ldap] returns ok Fri Oct 30 12:02:17 2015 : Info: ++[expiration] returns noop Fri Oct 30 12:02:17 2015 : Info: ++[logintime] returns noop Fri Oct 30 12:02:17 2015 : Info: [pap] Normalizing SSHA1-Password from base64 encoding Fri Oct 30 12:02:17 2015 : Info: [pap] Normalizing SSHA1-Password from base64 encoding Fri Oct 30 12:02:17 2015 : Info: [pap] Found existing Auth-Type, not changing it. Fri Oct 30 12:02:17 2015 : Info: ++[pap] returns noop Fri Oct 30 12:02:17 2015 : Info: Found Auth-Type = EAP Fri Oct 30 12:02:17 2015 : Info: Found Auth-Type = EAP Fri Oct 30 12:02:17 2015 : Error: Warning: Found 2 auth-types on request for user 'sur.name' Fri Oct 30 12:02:17 2015 : Info: +- entering group authenticate {...} Fri Oct 30 12:02:17 2015 : Info: [eap] EAP Identity Fri Oct 30 12:02:17 2015 : Info: [eap] processing type gtc Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns handled } # server inner-tunnel Fri Oct 30 12:02:17 2015 : Info: [ttls] Got tunneled reply code 11 EAP-Message = 0x0101000f0650617373776f72643a20 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x549441c15495476ebe4ca443c855f2b0 Fri Oct 30 12:02:17 2015 : Info: [ttls] Got tunneled Access-Challenge Fri Oct 30 12:02:17 2015 : Info: ++[eap] returns handled Sending Access-Challenge of id 66 to x.x.x.11 port 32842 EAP-Message = 0x0106003f158000000035170301003015edd76419bfeb01075988592edd3df4960efb4226c5ea0862cdd579730acc8114521323ad642f22881c5f4a8b9d5f05 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xfb55a41afe53b16008cc31758c0f388b Fri Oct 30 12:02:17 2015 : Info: Finished request 6. Fri Oct 30 12:02:17 2015 : Debug: Going to the next request Fri Oct 30 12:02:17 2015 : Debug: Waking up in 4.8 seconds. Fri Oct 30 12:02:22 2015 : Info: Cleaning up request 1 ID 61 with timestamp +68 Fri Oct 30 12:02:22 2015 : Info: Cleaning up request 2 ID 62 with timestamp +68 Fri Oct 30 12:02:22 2015 : Info: Cleaning up request 3 ID 63 with timestamp +68 Fri Oct 30 12:02:22 2015 : Info: Cleaning up request 4 ID 64 with timestamp +68 Fri Oct 30 12:02:22 2015 : Info: Cleaning up request 5 ID 65 with timestamp +68 Fri Oct 30 12:02:22 2015 : Info: Cleaning up request 6 ID 66 with timestamp +68 Fri Oct 30 12:02:22 2015 : Debug: Ready to process requests. rad_recv: Accounting-Request packet from host x.x.x.11 port 32839, id=115, length=157 Acct-Session-Id = "38724ED6-0000034B" Acct-Status-Type = Start Acct-Authentic = Local User-Name = "c0bdd1207464" NAS-IP-Address = x.x.x.11 NAS-Identifier = "hello" NAS-Port = 0 Called-Station-Id = "44-94-FC-96-4F-20:dacag" Calling-Station-Id = "C0-BD-D1-20-74-64" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 0Mbps 802.11b" Fri Oct 30 12:02:39 2015 : Info: +- entering group preacct {...} Fri Oct 30 12:02:39 2015 : Info: ++[preprocess] returns ok Fri Oct 30 12:02:39 2015 : Info: [acct_unique] Hashing 'NAS-Port = 0,Client-IP-Address = x.x.x.11,NAS-IP-Address = x.x.x.11,Acct-Session-Id = "38724ED6-0000034B",User-Name = "c0bdd1207464"' Fri Oct 30 12:02:39 2015 : Info: [acct_unique] Acct-Unique-Session-ID = "598f2bca49afa3c4". Fri Oct 30 12:02:39 2015 : Info: ++[acct_unique] returns ok Fri Oct 30 12:02:39 2015 : Info: [suffix] No '@' in User-Name = "c0bdd1207464", looking up realm NULL Fri Oct 30 12:02:39 2015 : Info: [suffix] No such realm "NULL" Fri Oct 30 12:02:39 2015 : Info: ++[suffix] returns noop Fri Oct 30 12:02:39 2015 : Info: ++[files] returns noop Fri Oct 30 12:02:39 2015 : Info: +- entering group accounting {...} Fri Oct 30 12:02:39 2015 : Info: [detail] expand: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/radius/radacct/x.x.x.11/detail-20151030 Fri Oct 30 12:02:39 2015 : Info: [detail] /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/radius/radacct/x.x.x.11/detail-20151030 Fri Oct 30 12:02:39 2015 : Info: [detail] expand: %t -> Fri Oct 30 12:02:39 2015 Fri Oct 30 12:02:39 2015 : Info: ++[detail] returns ok Fri Oct 30 12:02:39 2015 : Info: ++[unix] returns ok Fri Oct 30 12:02:39 2015 : Info: [radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp Fri Oct 30 12:02:39 2015 : Info: [radutmp] expand: %{User-Name} -> c0bdd1207464 Fri Oct 30 12:02:39 2015 : Info: ++[radutmp] returns ok Fri Oct 30 12:02:39 2015 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> c0bdd1207464 Fri Oct 30 12:02:39 2015 : Debug: attr_filter: Matched entry DEFAULT at line 12 Fri Oct 30 12:02:39 2015 : Info: ++[attr_filter.accounting_response] returns updated Sending Accounting-Response of id 115 to x.x.x.11 port 32839 Fri Oct 30 12:02:39 2015 : Info: Finished request 7. Fri Oct 30 12:02:39 2015 : Info: Cleaning up request 7 ID 115 with timestamp +90 Fri Oct 30 12:02:39 2015 : Debug: Going to the next request Fri Oct 30 12:02:39 2015 : Debug: Ready to process requests. ----------------------------------------
Subject: Re: eap-ttls-gtc-pap From: aland@deployingradius.com Date: Fri, 30 Oct 2015 08:19:24 -0400 To: freeradius-users@lists.freeradius.org
On Oct 30, 2015, at 8:01 AM, Seike neg <seike@outlook.com> wrote:
Hello I'm having trouble setting an eap-ttls-gtc-pap authentication against an LDAP server. The PAP part is working without problem when I check it with radtest but i can't log with EAP-TTLS-GTC. Anyone can help me please . Thanks in advance.
Here is my pastebin for my conf files:
Can you explain why you're posting the configuration files, when the FAQ, "man" page, web pages, and daily messages on this list say to post the debug output?
Where should we write "POST THE DEBUG OUTPUT" so that you will read it?
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html