Help with EAP TLS authentication

Hi there Trying to diagnose if I have a router OpenSSL issue, or a config issue (more likely). I've generated a self signed CA which seems to be working, but my new Freeradius 3 (3.0.11) "default" compile doesn't seem to like something.... Here is my radiusd -Xx dump: Tue Sep 20 18:36:13 2016 : Debug: Server was built with: Tue Sep 20 18:36:13 2016 : Debug: accounting : yes Tue Sep 20 18:36:13 2016 : Debug: authentication : yes Tue Sep 20 18:36:13 2016 : Debug: ascend-binary-attributes : yes Tue Sep 20 18:36:13 2016 : Debug: coa : yes Tue Sep 20 18:36:13 2016 : Debug: control-socket : yes Tue Sep 20 18:36:13 2016 : Debug: detail : yes Tue Sep 20 18:36:13 2016 : Debug: dhcp : yes Tue Sep 20 18:36:13 2016 : Debug: dynamic-clients : yes Tue Sep 20 18:36:13 2016 : Debug: osfc2 : no Tue Sep 20 18:36:13 2016 : Debug: proxy : yes Tue Sep 20 18:36:13 2016 : Debug: regex-pcre : no Tue Sep 20 18:36:13 2016 : Debug: regex-posix : yes Tue Sep 20 18:36:13 2016 : Debug: regex-posix-extended : yes Tue Sep 20 18:36:13 2016 : Debug: session-management : yes Tue Sep 20 18:36:13 2016 : Debug: stats : yes Tue Sep 20 18:36:13 2016 : Debug: tcp : yes Tue Sep 20 18:36:13 2016 : Debug: threads : yes Tue Sep 20 18:36:13 2016 : Debug: tls : yes Tue Sep 20 18:36:13 2016 : Debug: unlang : yes Tue Sep 20 18:36:13 2016 : Debug: vmps : yes Tue Sep 20 18:36:13 2016 : Debug: developer : no Tue Sep 20 18:36:13 2016 : Debug: Server core libs: Tue Sep 20 18:36:13 2016 : Debug: freeradius-server : 3.0.11 Tue Sep 20 18:36:13 2016 : Debug: talloc : 2.0.* Tue Sep 20 18:36:13 2016 : Debug: ssl : 1.0.1e release Tue Sep 20 18:36:13 2016 : Debug: Endianness: Tue Sep 20 18:36:13 2016 : Debug: little Tue Sep 20 18:36:13 2016 : Debug: Compilation flags: Tue Sep 20 18:36:13 2016 : Debug: cppflags : Tue Sep 20 18:36:13 2016 : Debug: cflags : -I/usr/src/freeradius-3/freeradius-server-3.0.11 -I/usr/src/freeradius-3/freeradius-server-3.0.11/src -include /usr/src/freeradius-3/freeradius-server-3.0.11/src/freeradius-devel/autoconf.h -include /usr/src/freeradius-3/freeradius-server-3.0.11/src/freeradius-devel/build.h -include /usr/src/freeradius-3/freeradius-server-3.0.11/src/freeradius-devel/features.h -include /usr/src/freeradius-3/freeradius-server-3.0.11/src/freeradius-devel/radpaths.h -fno-strict-aliasing -g -O2 -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -DNDEBUG -DIS_MODULE=1 Tue Sep 20 18:36:13 2016 : Debug: ldflags : Tue Sep 20 18:36:13 2016 : Debug: libs : -lcrypto -lssl -ltalloc -lnsl -lresolv -ldl -lpthread Tue Sep 20 18:36:13 2016 : Debug: Tue Sep 20 18:36:13 2016 : Info: Copyright (C) 1999-2016 The FreeRADIUS server project and contributors Tue Sep 20 18:36:13 2016 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Tue Sep 20 18:36:13 2016 : Info: PARTICULAR PURPOSE Tue Sep 20 18:36:13 2016 : Info: You may redistribute copies of FreeRADIUS under the terms of the Tue Sep 20 18:36:13 2016 : Info: GNU General Public License Tue Sep 20 18:36:13 2016 : Info: For more information about these matters, see the file named COPYRIGHT Tue Sep 20 18:36:13 2016 : Info: Starting - reading configuration files ... Tue Sep 20 18:36:13 2016 : Debug: including dictionary file /usr/local/share/freeradius/dictionary Tue Sep 20 18:36:13 2016 : Debug: including dictionary file /usr/local/share/freeradius/dictionary.dhcp Tue Sep 20 18:36:13 2016 : Debug: including dictionary file /usr/local/share/freeradius/dictionary.vqp Tue Sep 20 18:36:13 2016 : Debug: including dictionary file /usr/local/etc/raddb/dictionary Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/radiusd.conf Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/clients.conf Tue Sep 20 18:36:13 2016 : Debug: including files in directory /usr/local/etc/raddb/mods-enabled/ Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/sradutmp Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/linelog Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/detail.log Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/soh Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/utf8 Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/cache_eap Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/preprocess Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/realm Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/dynamic_clients Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/echo Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/mschap Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/digest Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/pap Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/replicate Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/exec Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/passwd Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/expr Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/files Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/unpack Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/radutmp Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/expiration Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/detail Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/ntlm_auth Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/unix Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/logintime Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/eap Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/chap Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/dhcp Tue Sep 20 18:36:13 2016 : Debug: including files in directory /usr/local/etc/raddb/policy.d/ Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/policy.d/accounting Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/policy.d/debug Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/policy.d/control Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/policy.d/canonicalization Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/policy.d/filter Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/policy.d/cui Tue Sep 20 18:36:13 2016 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Tue Sep 20 18:36:13 2016 : Debug: OPTIMIZING (no == yes) --> FALSE Tue Sep 20 18:36:13 2016 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Tue Sep 20 18:36:13 2016 : Debug: OPTIMIZING (no == yes) --> FALSE Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/policy.d/operator-name Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/policy.d/abfab-tr Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/policy.d/eap Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/policy.d/dhcp Tue Sep 20 18:36:13 2016 : Debug: including files in directory /usr/local/etc/raddb/sites-enabled/ Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:13 2016 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Sep 20 18:36:13 2016 : Debug: main { Tue Sep 20 18:36:13 2016 : Debug: security { Tue Sep 20 18:36:13 2016 : Debug: allow_core_dumps = no Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[462]: The item 'max_attributes' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[480]: The item 'reject_delay' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[500]: The item 'status_server' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[510]: The item 'allow_vulnerable_openssl' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: name = "radiusd" Tue Sep 20 18:36:13 2016 : Debug: prefix = "/usr/local" Tue Sep 20 18:36:13 2016 : Debug: localstatedir = "/usr/local/var" Tue Sep 20 18:36:13 2016 : Debug: logdir = "/usr/local/var/log/radius" Tue Sep 20 18:36:13 2016 : Debug: run_dir = "/usr/local/var/run/radiusd" Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[70]: The item 'cadir' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[74]: The item 'db_dir' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[108]: The item 'libdir' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[119]: The item 'pidfile' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[140]: The item 'correct_escapes' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[194]: The item 'max_request_time' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[213]: The item 'cleanup_delay' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[250]: The item 'hostname_lookups' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[372]: The item 'checkrad' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[529]: The item 'proxy_requests' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: main { Tue Sep 20 18:36:13 2016 : Debug: name = "radiusd" Tue Sep 20 18:36:13 2016 : Debug: prefix = "/usr/local" Tue Sep 20 18:36:13 2016 : Debug: localstatedir = "/usr/local/var" Tue Sep 20 18:36:13 2016 : Debug: sbindir = "/usr/local/sbin" Tue Sep 20 18:36:13 2016 : Debug: logdir = "/usr/local/var/log/radius" Tue Sep 20 18:36:13 2016 : Debug: run_dir = "/usr/local/var/run/radiusd" Tue Sep 20 18:36:13 2016 : Debug: libdir = "/usr/local/lib" Tue Sep 20 18:36:13 2016 : Debug: radacctdir = "/usr/local/var/log/radius/radacct" Tue Sep 20 18:36:13 2016 : Debug: hostname_lookups = no Tue Sep 20 18:36:13 2016 : Debug: max_request_time = 30 Tue Sep 20 18:36:13 2016 : Debug: cleanup_delay = 5 Tue Sep 20 18:36:13 2016 : Debug: max_requests = 16384 Tue Sep 20 18:36:13 2016 : Debug: pidfile = "/usr/local/var/run/radiusd/radiusd.pid" Tue Sep 20 18:36:13 2016 : Debug: checkrad = "/usr/local/sbin/checkrad" Tue Sep 20 18:36:13 2016 : Debug: debug_level = 0 Tue Sep 20 18:36:13 2016 : Debug: proxy_requests = no Tue Sep 20 18:36:13 2016 : Debug: log { Tue Sep 20 18:36:13 2016 : Debug: stripped_names = no Tue Sep 20 18:36:13 2016 : Debug: auth = yes Tue Sep 20 18:36:13 2016 : Debug: auth_badpass = no Tue Sep 20 18:36:13 2016 : Debug: auth_goodpass = no Tue Sep 20 18:36:13 2016 : Debug: colourise = yes Tue Sep 20 18:36:13 2016 : Debug: msg_denied = "You are already logged in - access denied" Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[268]: The item 'destination' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[285]: The item 'file' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[331]: The item 'syslog_facility' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: resources { Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: security { Tue Sep 20 18:36:13 2016 : Debug: max_attributes = 200 Tue Sep 20 18:36:13 2016 : Debug: reject_delay = 1.000000 Tue Sep 20 18:36:13 2016 : Debug: status_server = yes Tue Sep 20 18:36:13 2016 : Debug: allow_vulnerable_openssl = "CVE-2014-0160" Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[70]: The item 'cadir' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[74]: The item 'db_dir' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Warning: /usr/local/etc/raddb/radiusd.conf[140]: The item 'correct_escapes' is defined, but is unused by the configuration Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: radiusd: #### Loading Realms and Home Servers #### Tue Sep 20 18:36:13 2016 : Debug: radiusd: #### Loading Clients #### Tue Sep 20 18:36:13 2016 : Debug: client localhost { Tue Sep 20 18:36:13 2016 : Debug: ipaddr = 127.0.0.1 Tue Sep 20 18:36:13 2016 : Debug: require_message_authenticator = no Tue Sep 20 18:36:13 2016 : Debug: secret = "testing123" Tue Sep 20 18:36:13 2016 : Debug: nas_type = "other" Tue Sep 20 18:36:13 2016 : Debug: proto = "*" Tue Sep 20 18:36:13 2016 : Debug: limit { Tue Sep 20 18:36:13 2016 : Debug: max_connections = 16 Tue Sep 20 18:36:13 2016 : Debug: lifetime = 0 Tue Sep 20 18:36:13 2016 : Debug: idle_timeout = 30 Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Tue Sep 20 18:36:13 2016 : Debug: client localhost_ipv6 { Tue Sep 20 18:36:13 2016 : Debug: ipv6addr = ::1 Tue Sep 20 18:36:13 2016 : Debug: require_message_authenticator = no Tue Sep 20 18:36:13 2016 : Debug: secret = "testing123" Tue Sep 20 18:36:13 2016 : Debug: limit { Tue Sep 20 18:36:13 2016 : Debug: max_connections = 16 Tue Sep 20 18:36:13 2016 : Debug: lifetime = 0 Tue Sep 20 18:36:13 2016 : Debug: idle_timeout = 30 Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Adding client ::1/128 (::1) to prefix tree 128 Tue Sep 20 18:36:13 2016 : Debug: client router-1 { Tue Sep 20 18:36:13 2016 : Debug: ipaddr = 192.168.1.1 Tue Sep 20 18:36:13 2016 : Debug: require_message_authenticator = no Tue Sep 20 18:36:13 2016 : Debug: secret = "<REDACTED>" Tue Sep 20 18:36:13 2016 : Debug: limit { Tue Sep 20 18:36:13 2016 : Debug: max_connections = 16 Tue Sep 20 18:36:13 2016 : Debug: lifetime = 0 Tue Sep 20 18:36:13 2016 : Debug: idle_timeout = 30 Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Adding client 192.168.1.1/32 (192.168.1.1) to prefix tree 32 Tue Sep 20 18:36:13 2016 : Info: Debugger not attached Tue Sep 20 18:36:13 2016 : Debug: # Creating Auth-Type = eap Tue Sep 20 18:36:13 2016 : Debug: # Creating Auth-Type = PAP Tue Sep 20 18:36:13 2016 : Debug: # Creating Auth-Type = CHAP Tue Sep 20 18:36:13 2016 : Debug: # Creating Auth-Type = MS-CHAP Tue Sep 20 18:36:13 2016 : Debug: radiusd: #### Instantiating modules #### Tue Sep 20 18:36:13 2016 : Debug: modules { Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_radutmp with path: /usr/local/lib/rlm_radutmp.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_radutmp, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_radutmp Tue Sep 20 18:36:13 2016 : Debug: # Loading module "sradutmp" from file /usr/local/etc/raddb/mods-enabled/sradutmp Tue Sep 20 18:36:13 2016 : Debug: radutmp sradutmp { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/var/log/radius/sradutmp" Tue Sep 20 18:36:13 2016 : Debug: username = "%{User-Name}" Tue Sep 20 18:36:13 2016 : Debug: case_sensitive = yes Tue Sep 20 18:36:13 2016 : Debug: check_with_nas = yes Tue Sep 20 18:36:13 2016 : Debug: permissions = 420 Tue Sep 20 18:36:13 2016 : Debug: caller_id = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_linelog with path: /usr/local/lib/rlm_linelog.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_linelog, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_linelog Tue Sep 20 18:36:13 2016 : Debug: # Loading module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog Tue Sep 20 18:36:13 2016 : Debug: linelog { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/var/log/radius/linelog" Tue Sep 20 18:36:13 2016 : Debug: escape_filenames = no Tue Sep 20 18:36:13 2016 : Debug: syslog_severity = "info" Tue Sep 20 18:36:13 2016 : Debug: permissions = 384 Tue Sep 20 18:36:13 2016 : Debug: format = "This is a log message for %{User-Name}" Tue Sep 20 18:36:13 2016 : Debug: reference = "messages.%{%{reply:Packet-Type}:-default}" Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "log_accounting" from file /usr/local/etc/raddb/mods-enabled/linelog Tue Sep 20 18:36:13 2016 : Debug: linelog log_accounting { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/var/log/radius/linelog-accounting" Tue Sep 20 18:36:13 2016 : Debug: escape_filenames = no Tue Sep 20 18:36:13 2016 : Debug: syslog_severity = "info" Tue Sep 20 18:36:13 2016 : Debug: permissions = 384 Tue Sep 20 18:36:13 2016 : Debug: format = "" Tue Sep 20 18:36:13 2016 : Debug: reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_detail with path: /usr/local/lib/rlm_detail.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_detail, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_detail Tue Sep 20 18:36:13 2016 : Debug: # Loading module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Sep 20 18:36:13 2016 : Debug: detail auth_log { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" Tue Sep 20 18:36:13 2016 : Debug: header = "%t" Tue Sep 20 18:36:13 2016 : Debug: permissions = 384 Tue Sep 20 18:36:13 2016 : Debug: locking = no Tue Sep 20 18:36:13 2016 : Debug: escape_filenames = no Tue Sep 20 18:36:13 2016 : Debug: log_packet_header = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Sep 20 18:36:13 2016 : Debug: detail reply_log { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" Tue Sep 20 18:36:13 2016 : Debug: header = "%t" Tue Sep 20 18:36:13 2016 : Debug: permissions = 384 Tue Sep 20 18:36:13 2016 : Debug: locking = no Tue Sep 20 18:36:13 2016 : Debug: escape_filenames = no Tue Sep 20 18:36:13 2016 : Debug: log_packet_header = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Sep 20 18:36:13 2016 : Debug: detail pre_proxy_log { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" Tue Sep 20 18:36:13 2016 : Debug: header = "%t" Tue Sep 20 18:36:13 2016 : Debug: permissions = 384 Tue Sep 20 18:36:13 2016 : Debug: locking = no Tue Sep 20 18:36:13 2016 : Debug: escape_filenames = no Tue Sep 20 18:36:13 2016 : Debug: log_packet_header = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Sep 20 18:36:13 2016 : Debug: detail post_proxy_log { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" Tue Sep 20 18:36:13 2016 : Debug: header = "%t" Tue Sep 20 18:36:13 2016 : Debug: permissions = 384 Tue Sep 20 18:36:13 2016 : Debug: locking = no Tue Sep 20 18:36:13 2016 : Debug: escape_filenames = no Tue Sep 20 18:36:13 2016 : Debug: log_packet_header = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_soh with path: /usr/local/lib/rlm_soh.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_soh, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_soh Tue Sep 20 18:36:13 2016 : Debug: # Loading module "soh" from file /usr/local/etc/raddb/mods-enabled/soh Tue Sep 20 18:36:13 2016 : Debug: soh { Tue Sep 20 18:36:13 2016 : Debug: dhcp = yes Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_utf8 with path: /usr/local/lib/rlm_utf8.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_utf8, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_utf8 Tue Sep 20 18:36:13 2016 : Debug: # Loading module "utf8" from file /usr/local/etc/raddb/mods-enabled/utf8 Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_cache with path: /usr/local/lib/rlm_cache.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_cache, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_cache Tue Sep 20 18:36:13 2016 : Debug: # Loading module "cache_eap" from file /usr/local/etc/raddb/mods-enabled/cache_eap Tue Sep 20 18:36:13 2016 : Debug: cache cache_eap { Tue Sep 20 18:36:13 2016 : Debug: driver = "rlm_cache_rbtree" Tue Sep 20 18:36:13 2016 : Debug: key = "%{%{control:State}:-%{%{reply:State}:-%{State}}}" Tue Sep 20 18:36:13 2016 : Debug: ttl = 15 Tue Sep 20 18:36:13 2016 : Debug: max_entries = 0 Tue Sep 20 18:36:13 2016 : Debug: epoch = 0 Tue Sep 20 18:36:13 2016 : Debug: add_stats = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_preprocess with path: /usr/local/lib/rlm_preprocess.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_preprocess, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_preprocess Tue Sep 20 18:36:13 2016 : Debug: # Loading module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess Tue Sep 20 18:36:13 2016 : Debug: preprocess { Tue Sep 20 18:36:13 2016 : Debug: huntgroups = "/usr/local/etc/raddb/mods-config/preprocess/huntgroups" Tue Sep 20 18:36:13 2016 : Debug: hints = "/usr/local/etc/raddb/mods-config/preprocess/hints" Tue Sep 20 18:36:13 2016 : Debug: with_ascend_hack = no Tue Sep 20 18:36:13 2016 : Debug: ascend_channels_per_line = 23 Tue Sep 20 18:36:13 2016 : Debug: with_ntdomain_hack = no Tue Sep 20 18:36:13 2016 : Debug: with_specialix_jetstream_hack = no Tue Sep 20 18:36:13 2016 : Debug: with_cisco_vsa_hack = no Tue Sep 20 18:36:13 2016 : Debug: with_alvarion_vsa_hack = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_realm with path: /usr/local/lib/rlm_realm.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_realm, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_realm Tue Sep 20 18:36:13 2016 : Debug: # Loading module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm Tue Sep 20 18:36:13 2016 : Debug: realm IPASS { Tue Sep 20 18:36:13 2016 : Debug: format = "prefix" Tue Sep 20 18:36:13 2016 : Debug: delimiter = "/" Tue Sep 20 18:36:13 2016 : Debug: ignore_default = no Tue Sep 20 18:36:13 2016 : Debug: ignore_null = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm Tue Sep 20 18:36:13 2016 : Debug: realm suffix { Tue Sep 20 18:36:13 2016 : Debug: format = "suffix" Tue Sep 20 18:36:13 2016 : Debug: delimiter = "@" Tue Sep 20 18:36:13 2016 : Debug: ignore_default = no Tue Sep 20 18:36:13 2016 : Debug: ignore_null = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm Tue Sep 20 18:36:13 2016 : Debug: realm realmpercent { Tue Sep 20 18:36:13 2016 : Debug: format = "suffix" Tue Sep 20 18:36:13 2016 : Debug: delimiter = "%" Tue Sep 20 18:36:13 2016 : Debug: ignore_default = no Tue Sep 20 18:36:13 2016 : Debug: ignore_null = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm Tue Sep 20 18:36:13 2016 : Debug: realm ntdomain { Tue Sep 20 18:36:13 2016 : Debug: format = "prefix" Tue Sep 20 18:36:13 2016 : Debug: delimiter = "\\" Tue Sep 20 18:36:13 2016 : Debug: ignore_default = no Tue Sep 20 18:36:13 2016 : Debug: ignore_null = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_dynamic_clients with path: /usr/local/lib/rlm_dynamic_clients.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_dynamic_clients, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_dynamic_clients Tue Sep 20 18:36:13 2016 : Debug: # Loading module "dynamic_clients" from file /usr/local/etc/raddb/mods-enabled/dynamic_clients Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_exec with path: /usr/local/lib/rlm_exec.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_exec, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_exec Tue Sep 20 18:36:13 2016 : Debug: # Loading module "echo" from file /usr/local/etc/raddb/mods-enabled/echo Tue Sep 20 18:36:13 2016 : Debug: exec echo { Tue Sep 20 18:36:13 2016 : Debug: wait = yes Tue Sep 20 18:36:13 2016 : Debug: program = "/bin/echo %{User-Name}" Tue Sep 20 18:36:13 2016 : Debug: input_pairs = "request" Tue Sep 20 18:36:13 2016 : Debug: output_pairs = "reply" Tue Sep 20 18:36:13 2016 : Debug: shell_escape = yes Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_mschap with path: /usr/local/lib/rlm_mschap.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_mschap, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_mschap Tue Sep 20 18:36:13 2016 : Debug: # Loading module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap Tue Sep 20 18:36:13 2016 : Debug: mschap { Tue Sep 20 18:36:13 2016 : Debug: use_mppe = yes Tue Sep 20 18:36:13 2016 : Debug: require_encryption = no Tue Sep 20 18:36:13 2016 : Debug: require_strong = no Tue Sep 20 18:36:13 2016 : Debug: with_ntdomain_hack = yes Tue Sep 20 18:36:13 2016 : Debug: passchange { Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: allow_retry = yes Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_digest with path: /usr/local/lib/rlm_digest.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_digest, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_digest Tue Sep 20 18:36:13 2016 : Debug: # Loading module "digest" from file /usr/local/etc/raddb/mods-enabled/digest Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_pap with path: /usr/local/lib/rlm_pap.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_pap, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_pap Tue Sep 20 18:36:13 2016 : Debug: # Loading module "pap" from file /usr/local/etc/raddb/mods-enabled/pap Tue Sep 20 18:36:13 2016 : Debug: pap { Tue Sep 20 18:36:13 2016 : Debug: normalise = yes Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_replicate with path: /usr/local/lib/rlm_replicate.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_replicate, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_replicate Tue Sep 20 18:36:13 2016 : Debug: # Loading module "replicate" from file /usr/local/etc/raddb/mods-enabled/replicate Tue Sep 20 18:36:13 2016 : Debug: # Loading module "exec" from file /usr/local/etc/raddb/mods-enabled/exec Tue Sep 20 18:36:13 2016 : Debug: exec { Tue Sep 20 18:36:13 2016 : Debug: wait = no Tue Sep 20 18:36:13 2016 : Debug: input_pairs = "request" Tue Sep 20 18:36:13 2016 : Debug: shell_escape = yes Tue Sep 20 18:36:13 2016 : Debug: timeout = 10 Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_passwd with path: /usr/local/lib/rlm_passwd.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_passwd, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_passwd Tue Sep 20 18:36:13 2016 : Debug: # Loading module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd Tue Sep 20 18:36:13 2016 : Debug: passwd etc_passwd { Tue Sep 20 18:36:13 2016 : Debug: filename = "/etc/passwd" Tue Sep 20 18:36:13 2016 : Debug: format = "*User-Name:Crypt-Password:" Tue Sep 20 18:36:13 2016 : Debug: delimiter = ":" Tue Sep 20 18:36:13 2016 : Debug: ignore_nislike = no Tue Sep 20 18:36:13 2016 : Debug: ignore_empty = yes Tue Sep 20 18:36:13 2016 : Debug: allow_multiple_keys = no Tue Sep 20 18:36:13 2016 : Debug: hash_size = 100 Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_expr with path: /usr/local/lib/rlm_expr.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_expr, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_expr Tue Sep 20 18:36:13 2016 : Debug: # Loading module "expr" from file /usr/local/etc/raddb/mods-enabled/expr Tue Sep 20 18:36:13 2016 : Debug: expr { Tue Sep 20 18:36:13 2016 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_files with path: /usr/local/lib/rlm_files.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_files, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_files Tue Sep 20 18:36:13 2016 : Debug: # Loading module "files" from file /usr/local/etc/raddb/mods-enabled/files Tue Sep 20 18:36:13 2016 : Debug: files { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/etc/raddb/mods-config/files/authorize" Tue Sep 20 18:36:13 2016 : Debug: acctusersfile = "/usr/local/etc/raddb/mods-config/files/accounting" Tue Sep 20 18:36:13 2016 : Debug: preproxy_usersfile = "/usr/local/etc/raddb/mods-config/files/pre-proxy" Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_unpack with path: /usr/local/lib/rlm_unpack.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_unpack, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_unpack Tue Sep 20 18:36:13 2016 : Debug: # Loading module "unpack" from file /usr/local/etc/raddb/mods-enabled/unpack Tue Sep 20 18:36:13 2016 : Debug: # Loading module "radutmp" from file /usr/local/etc/raddb/mods-enabled/radutmp Tue Sep 20 18:36:13 2016 : Debug: radutmp { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/var/log/radius/radutmp" Tue Sep 20 18:36:13 2016 : Debug: username = "%{User-Name}" Tue Sep 20 18:36:13 2016 : Debug: case_sensitive = yes Tue Sep 20 18:36:13 2016 : Debug: check_with_nas = yes Tue Sep 20 18:36:13 2016 : Debug: permissions = 384 Tue Sep 20 18:36:13 2016 : Debug: caller_id = yes Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_expiration with path: /usr/local/lib/rlm_expiration.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_expiration, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_expiration Tue Sep 20 18:36:13 2016 : Debug: # Loading module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_always with path: /usr/local/lib/rlm_always.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_always, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_always Tue Sep 20 18:36:13 2016 : Debug: # Loading module "reject" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: always reject { Tue Sep 20 18:36:13 2016 : Debug: rcode = "reject" Tue Sep 20 18:36:13 2016 : Debug: simulcount = 0 Tue Sep 20 18:36:13 2016 : Debug: mpp = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "fail" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: always fail { Tue Sep 20 18:36:13 2016 : Debug: rcode = "fail" Tue Sep 20 18:36:13 2016 : Debug: simulcount = 0 Tue Sep 20 18:36:13 2016 : Debug: mpp = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "ok" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: always ok { Tue Sep 20 18:36:13 2016 : Debug: rcode = "ok" Tue Sep 20 18:36:13 2016 : Debug: simulcount = 0 Tue Sep 20 18:36:13 2016 : Debug: mpp = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "handled" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: always handled { Tue Sep 20 18:36:13 2016 : Debug: rcode = "handled" Tue Sep 20 18:36:13 2016 : Debug: simulcount = 0 Tue Sep 20 18:36:13 2016 : Debug: mpp = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "invalid" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: always invalid { Tue Sep 20 18:36:13 2016 : Debug: rcode = "invalid" Tue Sep 20 18:36:13 2016 : Debug: simulcount = 0 Tue Sep 20 18:36:13 2016 : Debug: mpp = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "userlock" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: always userlock { Tue Sep 20 18:36:13 2016 : Debug: rcode = "userlock" Tue Sep 20 18:36:13 2016 : Debug: simulcount = 0 Tue Sep 20 18:36:13 2016 : Debug: mpp = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "notfound" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: always notfound { Tue Sep 20 18:36:13 2016 : Debug: rcode = "notfound" Tue Sep 20 18:36:13 2016 : Debug: simulcount = 0 Tue Sep 20 18:36:13 2016 : Debug: mpp = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "noop" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: always noop { Tue Sep 20 18:36:13 2016 : Debug: rcode = "noop" Tue Sep 20 18:36:13 2016 : Debug: simulcount = 0 Tue Sep 20 18:36:13 2016 : Debug: mpp = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "updated" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: always updated { Tue Sep 20 18:36:13 2016 : Debug: rcode = "updated" Tue Sep 20 18:36:13 2016 : Debug: simulcount = 0 Tue Sep 20 18:36:13 2016 : Debug: mpp = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "detail" from file /usr/local/etc/raddb/mods-enabled/detail Tue Sep 20 18:36:13 2016 : Debug: detail { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" Tue Sep 20 18:36:13 2016 : Debug: header = "%t" Tue Sep 20 18:36:13 2016 : Debug: permissions = 384 Tue Sep 20 18:36:13 2016 : Debug: locking = no Tue Sep 20 18:36:13 2016 : Debug: escape_filenames = no Tue Sep 20 18:36:13 2016 : Debug: log_packet_header = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_attr_filter with path: /usr/local/lib/rlm_attr_filter.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_attr_filter, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_attr_filter Tue Sep 20 18:36:13 2016 : Debug: # Loading module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: attr_filter attr_filter.post-proxy { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/post-proxy" Tue Sep 20 18:36:13 2016 : Debug: key = "%{Realm}" Tue Sep 20 18:36:13 2016 : Debug: relaxed = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: attr_filter attr_filter.pre-proxy { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/pre-proxy" Tue Sep 20 18:36:13 2016 : Debug: key = "%{Realm}" Tue Sep 20 18:36:13 2016 : Debug: relaxed = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: attr_filter attr_filter.access_reject { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_reject" Tue Sep 20 18:36:13 2016 : Debug: key = "%{User-Name}" Tue Sep 20 18:36:13 2016 : Debug: relaxed = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: attr_filter attr_filter.access_challenge { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_challenge" Tue Sep 20 18:36:13 2016 : Debug: key = "%{User-Name}" Tue Sep 20 18:36:13 2016 : Debug: relaxed = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: attr_filter attr_filter.accounting_response { Tue Sep 20 18:36:13 2016 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/accounting_response" Tue Sep 20 18:36:13 2016 : Debug: key = "%{User-Name}" Tue Sep 20 18:36:13 2016 : Debug: relaxed = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Loading module "ntlm_auth" from file /usr/local/etc/raddb/mods-enabled/ntlm_auth Tue Sep 20 18:36:13 2016 : Debug: exec ntlm_auth { Tue Sep 20 18:36:13 2016 : Debug: wait = yes Tue Sep 20 18:36:13 2016 : Debug: program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" Tue Sep 20 18:36:13 2016 : Debug: shell_escape = yes Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_unix with path: /usr/local/lib/rlm_unix.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_unix, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_unix Tue Sep 20 18:36:13 2016 : Debug: # Loading module "unix" from file /usr/local/etc/raddb/mods-enabled/unix Tue Sep 20 18:36:13 2016 : Debug: unix { Tue Sep 20 18:36:13 2016 : Debug: radwtmp = "/usr/local/var/log/radius/radwtmp" Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Creating attribute Unix-Group Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_logintime with path: /usr/local/lib/rlm_logintime.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_logintime, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_logintime Tue Sep 20 18:36:13 2016 : Debug: # Loading module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime Tue Sep 20 18:36:13 2016 : Debug: logintime { Tue Sep 20 18:36:13 2016 : Debug: minimum_timeout = 60 Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_eap with path: /usr/local/lib/rlm_eap.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_eap, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_eap Tue Sep 20 18:36:13 2016 : Debug: # Loading module "eap" from file /usr/local/etc/raddb/mods-enabled/eap Tue Sep 20 18:36:13 2016 : Debug: eap { Tue Sep 20 18:36:13 2016 : Debug: default_eap_type = "tls" Tue Sep 20 18:36:13 2016 : Debug: timer_expire = 60 Tue Sep 20 18:36:13 2016 : Debug: ignore_unknown_eap_types = no Tue Sep 20 18:36:13 2016 : Debug: cisco_accounting_username_bug = no Tue Sep 20 18:36:13 2016 : Debug: max_sessions = 16384 Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_chap with path: /usr/local/lib/rlm_chap.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_chap, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_chap Tue Sep 20 18:36:13 2016 : Debug: # Loading module "chap" from file /usr/local/etc/raddb/mods-enabled/chap Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_dhcp with path: /usr/local/lib/rlm_dhcp.so Tue Sep 20 18:36:13 2016 : Debug: Loaded rlm_dhcp, checking if it's valid Tue Sep 20 18:36:13 2016 : Debug: # Loaded module rlm_dhcp Tue Sep 20 18:36:13 2016 : Debug: # Loading module "dhcp" from file /usr/local/etc/raddb/mods-enabled/dhcp Tue Sep 20 18:36:13 2016 : Debug: Adding values for DHCP-Parameter-Request-List Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 1 DHCP-Subnet-Mask Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 2 DHCP-Time-Offset Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 3 DHCP-Router-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 4 DHCP-Time-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 5 DHCP-IEN-116-Name-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 6 DHCP-Domain-Name-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 7 DHCP-Log-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 8 DHCP-Quotes-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 9 DHCP-LPR-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 10 DHCP-Impress-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 11 DHCP-RLP-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 12 DHCP-Hostname Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 13 DHCP-Boot-File-Size Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 14 DHCP-Merit-Dump-File Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 15 DHCP-Domain-Name Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 16 DHCP-Swap-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 17 DHCP-Root-Path Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 18 DHCP-Bootp-Extensions-Path Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 19 DHCP-IP-Forward-Enable Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 20 DHCP-Source-Route-Enable Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 21 DHCP-Policy-Filter Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 22 DHCP-Max-Datagram-Reassembly-Size Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 23 DHCP-Default-IP-TTL Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 24 DHCP-Path-MTU-Aging-Timeout Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 25 DHCP-Path-MTU-Plateau-Table Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 26 DHCP-Interface-MTU-Size Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 27 DHCP-All-Subnets-Are-Local Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 28 DHCP-Broadcast-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 29 DHCP-Perform-Mask-Discovery Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 30 DHCP-Provide-Mask-To-Others Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 31 DHCP-Perform-Router-Discovery Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 32 DHCP-Router-Solicitation-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 33 DHCP-Static-Routes Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 34 DHCP-Trailer-Encapsulation Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 35 DHCP-ARP-Cache-Timeout Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 36 DHCP-Ethernet-Encapsulation Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 37 DHCP-Default-TCP-TTL Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 38 DHCP-Keep-Alive-Interval Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 39 DHCP-Keep-Alive-Garbage Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 40 DHCP-NIS-Domain-Name Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 41 DHCP-NIS-Servers Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 42 DHCP-NTP-Servers Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 43 DHCP-Vendor Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 44 DHCP-NETBIOS-Name-Servers Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 45 DHCP-NETBIOS-Dgm-Dist-Servers Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 46 DHCP-NETBIOS-Node-Type Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 47 DHCP-NETBIOS Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 48 DHCP-X-Window-Font-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 49 DHCP-X-Window-Display-Mgr Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 50 DHCP-Requested-IP-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 51 DHCP-IP-Address-Lease-Time Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 52 DHCP-Overload Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 53 DHCP-Message-Type Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 54 DHCP-DHCP-Server-Identifier Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 55 DHCP-Parameter-Request-List Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 56 DHCP-DHCP-Error-Message Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 57 DHCP-DHCP-Maximum-Msg-Size Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 58 DHCP-Renewal-Time Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 59 DHCP-Rebinding-Time Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 60 DHCP-Vendor-Class-Identifier Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 61 DHCP-Client-Identifier Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 62 DHCP-Netware-Domain-Name Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 63 DHCP-Netware-Sub-Options Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 64 DHCP-NIS-Client-Domain-Name Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 65 DHCP-NIS-Server-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 66 DHCP-TFTP-Server-Name Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 67 DHCP-Boot-File-Name Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 68 DHCP-Home-Agent-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 69 DHCP-SMTP-Server-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 70 DHCP-POP3-Server-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 71 DHCP-NNTP-Server-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 72 DHCP-WWW-Server-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 73 DHCP-Finger-Server-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 74 DHCP-IRC-Server-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 75 DHCP-StreetTalk-Server-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 76 DHCP-STDA-Server-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 77 DHCP-User-Class Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 78 DHCP-Directory-Agent Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 79 DHCP-Service-Scope Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 80 DHCP-Rapid-Commit Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 81 DHCP-Client-FQDN Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 82 DHCP-Relay-Agent-Information Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 83 DHCP-iSNS Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 84 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 85 DHCP-NDS-Servers Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 86 DHCP-NDS-Tree-Name Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 87 DHCP-NDS-Context Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 88 DHCP-BCMS-Server-IPv4-FQDN Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 89 DHCP-BCMS-Server-IPv4-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 90 DHCP-Authentication Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 91 DHCP-Client-Last-Txn-Time Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 92 DHCP-associated-ip Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 93 DHCP-Client-System Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 94 DHCP-Client-NDI Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 95 DHCP-LDAP Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 96 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 97 DHCP-UUID/GUID Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 98 DHCP-User-Auth Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 99 DHCP-GeoConf-Civic Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 100 DHCP-Timezone-Posix Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 101 DHCP-Timezone-Database Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 102 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 103 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 104 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 105 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 106 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 107 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 108 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 109 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 110 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 111 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 112 DHCP-Netinfo-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 113 DHCP-Netinfo-Tag Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 114 DHCP-URL Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 115 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 116 DHCP-Auto-Config Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 117 DHCP-Name-Service-Search Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 118 DHCP-Subnet-Selection-Option Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 119 DHCP-Domain-Search Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 120 DHCP-SIP-Servers-DHCP-Option Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 121 DHCP-Classless-Static-Route Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 122 DHCP-CCC Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 123 DHCP-GeoConf-Option Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 124 DHCP-V-I-Vendor-Class Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 125 DHCP-V-I-Vendor-Specific Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 126 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 127 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 128 DHCP-TFTP-Server-IP-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 129 DHCP-Call-Server-IP-address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 130 DHCP-Vendor-Discrimination-Str Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 131 DHCP-Remote-Stats-Svr-IP-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 132 DHCP-IEEE-802.1P-VLAN-ID Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 133 DHCP-IEEE-802.1Q-L2-Priority Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 134 DHCP-Diffserv-Code-Point Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 135 DHCP-HTTP-Proxy Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 136 DHCP-PANA-Agent Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 137 DHCP-LoST-Server Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 138 DHCP-CAPWAP-AC-IPv4-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 139 DHCP-MoS-IPv4-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 140 DHCP-MoS-IPv4-FQDN Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 141 DHCP-SIP-UA-Configuration-Service-Domains Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 142 DHCP-ANDSF-IPv4-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 143 DHCP-ANDSF-IPv6-Address Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 144 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 145 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 146 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 147 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 148 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 149 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 150 DHCP-TFTP-Server-IPv4-Address Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 151 DHCP-Query-Status-Code Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 152 DHCP-Query-Server-Base-Time Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 153 DHCP-Query-Start-Time-Of-State Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 154 DHCP-Query-Start-Time Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 155 DHCP-Query-End-Time Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 156 DHCP-State Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 157 DHCP-Data-Source Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 158 DHCP-PCP-IPv4-Server-Address Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 159 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 160 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 161 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 162 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 163 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 164 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 165 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 166 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 167 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 168 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 169 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 170 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 171 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 172 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 173 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 174 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 175 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 176 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 177 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 178 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 179 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 180 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 181 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 182 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 183 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 184 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 185 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 186 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 187 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 188 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 189 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 190 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 191 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 192 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 193 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 194 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 195 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 196 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 197 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 198 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 199 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 200 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 201 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 202 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 203 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 204 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 205 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 206 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 207 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 208 DHCP-PXELINUX-Magic Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 209 DHCP-Packet-Format Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 210 DHCP-Path-Prefix Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 211 DHCP-Reboot-Time Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 212 DHCP-6RD Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 213 DHCP-Access-Network-Domain-Name Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 214 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 215 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 216 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 217 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 218 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 219 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 220 DHCP-Virtual-Subnet-Allocation Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 221 DHCP-Virtual-Subnet-Selection Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 222 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 223 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 224 DHCP-Site-specific-0 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 225 DHCP-Site-specific-1 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 226 DHCP-Site-specific-2 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 227 DHCP-Site-specific-3 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 228 DHCP-Site-specific-4 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 229 DHCP-Site-specific-5 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 230 DHCP-Site-specific-6 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 231 DHCP-Site-specific-7 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 232 DHCP-Site-specific-8 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 233 DHCP-Site-specific-9 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 234 DHCP-Site-specific-10 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 235 DHCP-Site-specific-11 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 236 DHCP-Site-specific-12 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 237 DHCP-Site-specific-13 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 238 DHCP-Site-specific-14 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 239 DHCP-Site-specific-15 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 240 DHCP-Site-specific-16 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 241 DHCP-Site-specific-17 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 242 DHCP-Site-specific-18 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 243 DHCP-Site-specific-19 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 244 DHCP-Site-specific-20 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 245 DHCP-Site-specific-21 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 246 DHCP-Site-specific-22 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 247 DHCP-Site-specific-23 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 248 DHCP-Site-specific-24 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 249 DHCP-Site-specific-25 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 250 DHCP-Site-specific-26 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 251 DHCP-Site-specific-27 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 252 DHCP-Site-specific-28 Tue Sep 20 18:36:13 2016 : Debug: Adding DHCP-Parameter-Request-List value 253 DHCP-Site-specific-30 Tue Sep 20 18:36:13 2016 : Debug: No DHCP RFC space attribute at 254 Tue Sep 20 18:36:13 2016 : Debug: instantiate { Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "log_accounting" from file /usr/local/etc/raddb/mods-enabled/linelog Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Sep 20 18:36:13 2016 : Debug: rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "cache_eap" from file /usr/local/etc/raddb/mods-enabled/cache_eap Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_cache_rbtree with path: /usr/local/lib/rlm_cache_rbtree.so Tue Sep 20 18:36:13 2016 : Debug: rlm_cache (cache_eap): Driver rlm_cache_rbtree (module rlm_cache_rbtree) loaded and linked Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess Tue Sep 20 18:36:13 2016 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/huntgroups Tue Sep 20 18:36:13 2016 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/hints Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap Tue Sep 20 18:36:13 2016 : Debug: rlm_mschap (mschap): using internal authentication Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "pap" from file /usr/local/etc/raddb/mods-enabled/pap Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd Tue Sep 20 18:36:13 2016 : Debug: rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "files" from file /usr/local/etc/raddb/mods-enabled/files Tue Sep 20 18:36:13 2016 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/authorize Tue Sep 20 18:36:13 2016 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/accounting Tue Sep 20 18:36:13 2016 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/pre-proxy Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "reject" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "fail" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "ok" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "handled" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "invalid" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "userlock" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "notfound" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "noop" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "updated" from file /usr/local/etc/raddb/mods-enabled/always Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "detail" from file /usr/local/etc/raddb/mods-enabled/detail Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/post-proxy Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/pre-proxy Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_reject Tue Sep 20 18:36:13 2016 : Warning: [/usr/local/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT". Tue Sep 20 18:36:13 2016 : Warning: [/usr/local/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec" found in filter list for realm "DEFAULT". Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_challenge Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Sep 20 18:36:13 2016 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/accounting_response Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime Tue Sep 20 18:36:13 2016 : Debug: # Instantiating module "eap" from file /usr/local/etc/raddb/mods-enabled/eap Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_eap_tls with path: /usr/local/lib/rlm_eap_tls.so Tue Sep 20 18:36:13 2016 : Debug: # Linked to sub-module rlm_eap_tls Tue Sep 20 18:36:13 2016 : Debug: tls { Tue Sep 20 18:36:13 2016 : Debug: tls = "tls-common" Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: tls-config tls-common { Tue Sep 20 18:36:13 2016 : Debug: verify_depth = 0 Tue Sep 20 18:36:13 2016 : Debug: ca_path = "/usr/local/etc/raddb/certs" Tue Sep 20 18:36:13 2016 : Debug: pem_file_type = yes Tue Sep 20 18:36:13 2016 : Debug: private_key_file = "/usr/local/etc/raddb/certs/server.key" Tue Sep 20 18:36:13 2016 : Debug: certificate_file = "/usr/local/etc/raddb/certs/server.crt" Tue Sep 20 18:36:13 2016 : Debug: ca_file = "/usr/local/etc/raddb/certs/ca.pem" Tue Sep 20 18:36:13 2016 : Debug: private_key_password = "<REDACTED>" Tue Sep 20 18:36:13 2016 : Debug: random_file = "/dev/urandom" Tue Sep 20 18:36:13 2016 : Debug: fragment_size = 1024 Tue Sep 20 18:36:13 2016 : Debug: include_length = yes Tue Sep 20 18:36:13 2016 : Debug: auto_chain = yes Tue Sep 20 18:36:13 2016 : Debug: check_crl = no Tue Sep 20 18:36:13 2016 : Debug: check_all_crl = no Tue Sep 20 18:36:13 2016 : Debug: cipher_list = "HIGH" Tue Sep 20 18:36:13 2016 : Debug: ecdh_curve = "prime256v1" Tue Sep 20 18:36:13 2016 : Debug: cache { Tue Sep 20 18:36:13 2016 : Debug: enable = yes Tue Sep 20 18:36:13 2016 : Debug: lifetime = 24 Tue Sep 20 18:36:13 2016 : Debug: max_entries = 255 Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: verify { Tue Sep 20 18:36:13 2016 : Debug: skip_if_ocsp_ok = no Tue Sep 20 18:36:13 2016 : Debug: tmpdir = "/tmp/radiusd" Tue Sep 20 18:36:13 2016 : Debug: client = "/usr/bin/openssl verify -CApath /usr/local/etc/raddb/certs %{TLS-Client-Cert-Filename}" Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: ocsp { Tue Sep 20 18:36:13 2016 : Debug: enable = no Tue Sep 20 18:36:13 2016 : Debug: override_cert_url = yes Tue Sep 20 18:36:13 2016 : Debug: url = "http://127.0.0.1/ocsp/" Tue Sep 20 18:36:13 2016 : Debug: use_nonce = yes Tue Sep 20 18:36:13 2016 : Debug: timeout = 0 Tue Sep 20 18:36:13 2016 : Debug: softfail = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading rlm_eap_ttls with path: /usr/local/lib/rlm_eap_ttls.so Tue Sep 20 18:36:13 2016 : Debug: # Linked to sub-module rlm_eap_ttls Tue Sep 20 18:36:13 2016 : Debug: ttls { Tue Sep 20 18:36:13 2016 : Debug: tls = "tls-common" Tue Sep 20 18:36:13 2016 : Debug: default_eap_type = "md5" Tue Sep 20 18:36:13 2016 : Debug: copy_request_to_tunnel = no Tue Sep 20 18:36:13 2016 : Debug: use_tunneled_reply = no Tue Sep 20 18:36:13 2016 : Debug: virtual_server = "inner-tunnel" Tue Sep 20 18:36:13 2016 : Debug: include_length = no Tue Sep 20 18:36:13 2016 : Debug: require_client_cert = no Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: tls: Using cached TLS configuration from previous invocation Tue Sep 20 18:36:13 2016 : Debug: } # modules Tue Sep 20 18:36:13 2016 : Debug: radiusd: #### Loading Virtual Servers #### Tue Sep 20 18:36:13 2016 : Debug: server { # from file /usr/local/etc/raddb/radiusd.conf Tue Sep 20 18:36:13 2016 : Debug: } # server Tue Sep 20 18:36:13 2016 : Debug: server default { # from file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:13 2016 : Debug: authenticate { Tue Sep 20 18:36:13 2016 : Debug: eap Tue Sep 20 18:36:13 2016 : Debug: } # authenticate Tue Sep 20 18:36:13 2016 : Debug: authorize { Tue Sep 20 18:36:13 2016 : Debug: preprocess Tue Sep 20 18:36:13 2016 : Debug: eap Tue Sep 20 18:36:13 2016 : Debug: } # authorize Tue Sep 20 18:36:13 2016 : Debug: preacct { Tue Sep 20 18:36:13 2016 : Debug: preprocess Tue Sep 20 18:36:13 2016 : Debug: policy acct_unique { Tue Sep 20 18:36:13 2016 : Debug: if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/) { Tue Sep 20 18:36:13 2016 : Debug: update { Tue Sep 20 18:36:13 2016 : Debug: &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}" Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: else { Tue Sep 20 18:36:13 2016 : Debug: update { Tue Sep 20 18:36:13 2016 : Debug: &Acct-Unique-Session-Id := "%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}" Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: suffix Tue Sep 20 18:36:13 2016 : Debug: files Tue Sep 20 18:36:13 2016 : Debug: } # preacct Tue Sep 20 18:36:13 2016 : Debug: accounting { Tue Sep 20 18:36:13 2016 : Debug: detail Tue Sep 20 18:36:13 2016 : Debug: unix Tue Sep 20 18:36:13 2016 : Debug: radutmp Tue Sep 20 18:36:13 2016 : Debug: attr_filter.accounting_response Tue Sep 20 18:36:13 2016 : Debug: } # accounting Tue Sep 20 18:36:13 2016 : Debug: session { Tue Sep 20 18:36:13 2016 : Debug: radutmp Tue Sep 20 18:36:13 2016 : Debug: } # session Tue Sep 20 18:36:13 2016 : Debug: post-auth { Tue Sep 20 18:36:13 2016 : Debug: exec Tue Sep 20 18:36:13 2016 : Debug: group { Tue Sep 20 18:36:13 2016 : Debug: attr_filter.access_reject Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } # post-auth Tue Sep 20 18:36:13 2016 : Debug: } # server default Tue Sep 20 18:36:13 2016 : Debug: server inner-tunnel { # from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Sep 20 18:36:13 2016 : Debug: authenticate { Tue Sep 20 18:36:13 2016 : Debug: group { Tue Sep 20 18:36:13 2016 : Debug: pap Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: group { Tue Sep 20 18:36:13 2016 : Debug: chap Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: group { Tue Sep 20 18:36:13 2016 : Debug: mschap Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: eap Tue Sep 20 18:36:13 2016 : Debug: } # authenticate Tue Sep 20 18:36:13 2016 : Debug: authorize { Tue Sep 20 18:36:13 2016 : Debug: policy filter_username { Tue Sep 20 18:36:13 2016 : Debug: if (&User-Name) { Tue Sep 20 18:36:13 2016 : Debug: if (&User-Name =~ / /) { Tue Sep 20 18:36:13 2016 : Debug: update { Tue Sep 20 18:36:13 2016 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains whitespace' Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: reject Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: if (&User-Name =~ /@[^@]*@/) { Tue Sep 20 18:36:13 2016 : Debug: update { Tue Sep 20 18:36:13 2016 : Debug: &Module-Failure-Message += 'Rejected: Multiple @ in User-Name' Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: reject Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: if (&User-Name =~ /\.\./) { Tue Sep 20 18:36:13 2016 : Debug: update { Tue Sep 20 18:36:13 2016 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s' Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: reject Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) { Tue Sep 20 18:36:13 2016 : Debug: update { Tue Sep 20 18:36:13 2016 : Debug: &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator' Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: reject Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: if (&User-Name =~ /\.$/) { Tue Sep 20 18:36:13 2016 : Debug: update { Tue Sep 20 18:36:13 2016 : Debug: &Module-Failure-Message += 'Rejected: Realm ends with a dot' Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: reject Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: if (&User-Name =~ /@\./) { Tue Sep 20 18:36:13 2016 : Debug: update { Tue Sep 20 18:36:13 2016 : Debug: &Module-Failure-Message += 'Rejected: Realm begins with a dot' Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: reject Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: chap Tue Sep 20 18:36:13 2016 : Debug: mschap Tue Sep 20 18:36:13 2016 : Debug: suffix Tue Sep 20 18:36:13 2016 : Debug: update { Tue Sep 20 18:36:13 2016 : Debug: &control:Proxy-To-Realm := LOCAL Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: eap Tue Sep 20 18:36:13 2016 : Debug: files Tue Sep 20 18:36:13 2016 : Warning: Ignoring "sql" (see raddb/mods-available/README.rst) Tue Sep 20 18:36:13 2016 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Tue Sep 20 18:36:13 2016 : Debug: expiration Tue Sep 20 18:36:13 2016 : Debug: logintime Tue Sep 20 18:36:13 2016 : Debug: pap Tue Sep 20 18:36:13 2016 : Debug: } # authorize Tue Sep 20 18:36:13 2016 : Debug: session { Tue Sep 20 18:36:13 2016 : Debug: radutmp Tue Sep 20 18:36:13 2016 : Debug: } # session Tue Sep 20 18:36:13 2016 : Debug: post-auth { Tue Sep 20 18:36:13 2016 : Debug: group { Tue Sep 20 18:36:13 2016 : Debug: attr_filter.access_reject Tue Sep 20 18:36:13 2016 : Debug: update { Tue Sep 20 18:36:13 2016 : Debug: &outer.session-state:Module-Failure-Message := &Module-Failure-Message Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: } # post-auth Tue Sep 20 18:36:13 2016 : Debug: } # server inner-tunnel Tue Sep 20 18:36:13 2016 : Debug: Created signal pipe. Read end FD 5, write end FD 6 Tue Sep 20 18:36:13 2016 : Debug: radiusd: #### Opening IP addresses and Ports #### Tue Sep 20 18:36:13 2016 : Debug: Loading proto_auth with path: /usr/local/lib/proto_auth.so Tue Sep 20 18:36:13 2016 : Debug: Loading proto_auth failed: /usr/local/lib/proto_auth.so: cannot open shared object file: No such file or directory - No such file or directory Tue Sep 20 18:36:13 2016 : Debug: Loading library using linker search path(s) Tue Sep 20 18:36:13 2016 : Debug: Defaults : /lib:/usr/lib Tue Sep 20 18:36:13 2016 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Tue Sep 20 18:36:13 2016 : Debug: listen { Tue Sep 20 18:36:13 2016 : Debug: type = "auth" Tue Sep 20 18:36:13 2016 : Debug: ipaddr = * Tue Sep 20 18:36:13 2016 : Debug: port = 1812 Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Loading proto_auth with path: /usr/local/lib/proto_auth.so Tue Sep 20 18:36:13 2016 : Debug: Loading proto_auth failed: /usr/local/lib/proto_auth.so: cannot open shared object file: No such file or directory - No such file or directory Tue Sep 20 18:36:13 2016 : Debug: Loading library using linker search path(s) Tue Sep 20 18:36:13 2016 : Debug: Defaults : /lib:/usr/lib Tue Sep 20 18:36:13 2016 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Tue Sep 20 18:36:13 2016 : Debug: listen { Tue Sep 20 18:36:13 2016 : Debug: type = "auth" Tue Sep 20 18:36:13 2016 : Debug: ipaddr = 127.0.0.1 Tue Sep 20 18:36:13 2016 : Debug: port = 18120 Tue Sep 20 18:36:13 2016 : Debug: } Tue Sep 20 18:36:13 2016 : Debug: Listening on auth address * port 1812 bound to server default Tue Sep 20 18:36:13 2016 : Debug: Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel Tue Sep 20 18:36:13 2016 : Info: Ready to process requests Tue Sep 20 18:36:16 2016 : Debug: (0) Received Access-Request Id 0 from 192.168.1.1:12227 to 192.168.1.210:1812 length 139 Tue Sep 20 18:36:16 2016 : Debug: (0) User-Name = "pete@nexus5xp" Tue Sep 20 18:36:16 2016 : Debug: (0) NAS-IP-Address = 192.168.1.1 Tue Sep 20 18:36:16 2016 : Debug: (0) Called-Station-Id = "305a3ac51d20" Tue Sep 20 18:36:16 2016 : Debug: (0) Calling-Station-Id = "64bc0c4b27bf" Tue Sep 20 18:36:16 2016 : Debug: (0) NAS-Identifier = "305a3ac51d20" Tue Sep 20 18:36:16 2016 : Debug: (0) NAS-Port = 83 Tue Sep 20 18:36:16 2016 : Debug: (0) Framed-MTU = 1400 Tue Sep 20 18:36:16 2016 : Debug: (0) NAS-Port-Type = Wireless-802.11 Tue Sep 20 18:36:16 2016 : Debug: (0) EAP-Message = 0x020000120170657465406e65787573357870 Tue Sep 20 18:36:16 2016 : Debug: (0) Message-Authenticator = 0x451b844658c31c179b5e494fec393516 Tue Sep 20 18:36:16 2016 : Debug: (0) session-state: No State attribute Tue Sep 20 18:36:16 2016 : Debug: (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:16 2016 : Debug: (0) authorize { Tue Sep 20 18:36:16 2016 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Tue Sep 20 18:36:16 2016 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Tue Sep 20 18:36:16 2016 : Debug: (0) [preprocess] = ok Tue Sep 20 18:36:16 2016 : Debug: (0) modsingle[authorize]: calling eap (rlm_eap) for request 0 Tue Sep 20 18:36:16 2016 : Debug: (0) eap: Peer sent EAP Response (code 2) ID 0 length 18 Tue Sep 20 18:36:16 2016 : Debug: (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Tue Sep 20 18:36:16 2016 : Debug: (0) modsingle[authorize]: returned from eap (rlm_eap) for request 0 Tue Sep 20 18:36:16 2016 : Debug: (0) [eap] = ok Tue Sep 20 18:36:16 2016 : Debug: (0) } # authorize = ok Tue Sep 20 18:36:16 2016 : Debug: (0) Found Auth-Type = eap Tue Sep 20 18:36:16 2016 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:16 2016 : Debug: (0) authenticate { Tue Sep 20 18:36:16 2016 : Debug: (0) modsingle[authenticate]: calling eap (rlm_eap) for request 0 Tue Sep 20 18:36:16 2016 : Debug: (0) eap: Peer sent packet with method EAP Identity (1) Tue Sep 20 18:36:16 2016 : Debug: (0) eap: Calling submodule eap_tls to process data Tue Sep 20 18:36:16 2016 : Debug: (0) eap_tls: Initiating new EAP-TLS session Tue Sep 20 18:36:16 2016 : Debug: (0) eap_tls: Flushing SSL sessions (of #0) Tue Sep 20 18:36:16 2016 : Debug: (0) eap_tls: Setting verify mode to require certificate from client Tue Sep 20 18:36:16 2016 : Debug: (0) eap_tls: [eaptls start] = request Tue Sep 20 18:36:16 2016 : Debug: (0) eap: Sending EAP Request (code 1) ID 1 length 6 Tue Sep 20 18:36:16 2016 : Debug: (0) eap: EAP session adding &reply:State = 0xc0a4b23ec0a5bf93 Tue Sep 20 18:36:16 2016 : Debug: (0) modsingle[authenticate]: returned from eap (rlm_eap) for request 0 Tue Sep 20 18:36:16 2016 : Debug: (0) [eap] = handled Tue Sep 20 18:36:16 2016 : Debug: (0) } # authenticate = handled Tue Sep 20 18:36:16 2016 : Debug: (0) Using Post-Auth-Type Challenge Tue Sep 20 18:36:16 2016 : Debug: (0) Post-Auth-Type sub-section not found. Ignoring. Tue Sep 20 18:36:16 2016 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:16 2016 : Debug: (0) session-state: Nothing to cache Tue Sep 20 18:36:16 2016 : Debug: (0) Sent Access-Challenge Id 0 from 192.168.1.210:1812 to 192.168.1.1:12227 length 0 Tue Sep 20 18:36:16 2016 : Debug: (0) EAP-Message = 0x010100060d20 Tue Sep 20 18:36:16 2016 : Debug: (0) Message-Authenticator = 0x00000000000000000000000000000000 Tue Sep 20 18:36:16 2016 : Debug: (0) State = 0xc0a4b23ec0a5bf931b6e88d496e35305 Tue Sep 20 18:36:16 2016 : Debug: (0) Finished request Tue Sep 20 18:36:16 2016 : Debug: Waking up in 4.9 seconds. Tue Sep 20 18:36:16 2016 : Debug: (0) Cleaning up request packet ID 0 with timestamp +3 Tue Sep 20 18:36:16 2016 : Debug: (1) Received Access-Request Id 0 from 192.168.1.1:12227 to 192.168.1.210:1812 length 310 Tue Sep 20 18:36:16 2016 : Debug: (1) User-Name = "pete@nexus5xp" Tue Sep 20 18:36:16 2016 : Debug: (1) NAS-IP-Address = 192.168.1.1 Tue Sep 20 18:36:16 2016 : Debug: (1) Called-Station-Id = "305a3ac51d20" Tue Sep 20 18:36:16 2016 : Debug: (1) Calling-Station-Id = "64bc0c4b27bf" Tue Sep 20 18:36:16 2016 : Debug: (1) NAS-Identifier = "305a3ac51d20" Tue Sep 20 18:36:16 2016 : Debug: (1) NAS-Port = 83 Tue Sep 20 18:36:16 2016 : Debug: (1) Framed-MTU = 1400 Tue Sep 20 18:36:16 2016 : Debug: (1) State = 0xc0a4b23ec0a5bf931b6e88d496e35305 Tue Sep 20 18:36:16 2016 : Debug: (1) NAS-Port-Type = Wireless-802.11 Tue Sep 20 18:36:16 2016 : Debug: (1) EAP-Message = 0x020100ab0d0016030100a00100009c03038ef92dd289a9e47a08043ed8d17ba4aadbe9b997be545a3133beddda398a072b00003ec02cc030009fc02bc02f009ecca9cca8c00ac024c014c0280039006bc009c023c013c02700330067c007c011009d009c0035003d002f003c00050004000a01000035ff Tue Sep 20 18:36:16 2016 : Debug: (1) Message-Authenticator = 0x884979e1a62906f3099fec79b717a9e0 Tue Sep 20 18:36:16 2016 : Debug: (1) session-state: No cached attributes Tue Sep 20 18:36:16 2016 : Debug: (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:16 2016 : Debug: (1) authorize { Tue Sep 20 18:36:16 2016 : Debug: (1) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1 Tue Sep 20 18:36:16 2016 : Debug: (1) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1 Tue Sep 20 18:36:16 2016 : Debug: (1) [preprocess] = ok Tue Sep 20 18:36:16 2016 : Debug: (1) modsingle[authorize]: calling eap (rlm_eap) for request 1 Tue Sep 20 18:36:16 2016 : Debug: (1) eap: Peer sent EAP Response (code 2) ID 1 length 171 Tue Sep 20 18:36:16 2016 : Debug: (1) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Sep 20 18:36:16 2016 : Debug: (1) modsingle[authorize]: returned from eap (rlm_eap) for request 1 Tue Sep 20 18:36:16 2016 : Debug: (1) [eap] = updated Tue Sep 20 18:36:16 2016 : Debug: (1) } # authorize = updated Tue Sep 20 18:36:16 2016 : Debug: (1) Found Auth-Type = eap Tue Sep 20 18:36:16 2016 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:16 2016 : Debug: (1) authenticate { Tue Sep 20 18:36:16 2016 : Debug: (1) modsingle[authenticate]: calling eap (rlm_eap) for request 1 Tue Sep 20 18:36:16 2016 : Debug: (1) eap: Expiring EAP session with state 0xc0a4b23ec0a5bf93 Tue Sep 20 18:36:16 2016 : Debug: (1) eap: Finished EAP session with state 0xc0a4b23ec0a5bf93 Tue Sep 20 18:36:16 2016 : Debug: (1) eap: Previous EAP request found for state 0xc0a4b23ec0a5bf93, released from the list Tue Sep 20 18:36:16 2016 : Debug: (1) eap: Peer sent packet with method EAP TLS (13) Tue Sep 20 18:36:16 2016 : Debug: (1) eap: Calling submodule eap_tls to process data Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: Continuing EAP-TLS Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: Peer sent flags --- Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: Got final TLS record fragment (165 bytes) Tue Sep 20 18:36:16 2016 : WARNING: (1) eap_tls: Total received TLS record fragments (165 bytes), does not equal indicated TLS record length (0 bytes) Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: [eaptls verify] = ok Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: Done initial handshake Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: (other): before/accept initialization Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: TLS_accept: before/accept initialization Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: <<< recv TLS 1.2 [length 00a0] Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: TLS_accept: SSLv3 read client hello A Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: >>> send TLS 1.2 [length 0059] Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: TLS_accept: SSLv3 write server hello A Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: >>> send TLS 1.2 [length 0cdc] Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: TLS_accept: SSLv3 write certificate A Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: >>> send TLS 1.2 [length 024d] Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: TLS_accept: SSLv3 write key exchange A Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: >>> send TLS 1.2 [length 00c9] Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: TLS_accept: SSLv3 write certificate request A Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: TLS_accept: SSLv3 flush data Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: TLS_accept: Need to read more data: SSLv3 read client certificate A Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: TLS_accept: Need to read more data: SSLv3 read client certificate A Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: In SSL Handshake Phase Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: In SSL Accept mode Tue Sep 20 18:36:16 2016 : Debug: (1) eap_tls: [eaptls process] = handled Tue Sep 20 18:36:16 2016 : Debug: (1) eap: Sending EAP Request (code 1) ID 2 length 1014 Tue Sep 20 18:36:16 2016 : Debug: (1) eap: EAP session adding &reply:State = 0xc0a4b23ec1a6bf93 Tue Sep 20 18:36:16 2016 : Debug: (1) modsingle[authenticate]: returned from eap (rlm_eap) for request 1 Tue Sep 20 18:36:16 2016 : Debug: (1) [eap] = handled Tue Sep 20 18:36:16 2016 : Debug: (1) } # authenticate = handled Tue Sep 20 18:36:16 2016 : Debug: (1) Using Post-Auth-Type Challenge Tue Sep 20 18:36:16 2016 : Debug: (1) Post-Auth-Type sub-section not found. Ignoring. Tue Sep 20 18:36:16 2016 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:16 2016 : Debug: (1) session-state: Nothing to cache Tue Sep 20 18:36:16 2016 : Debug: (1) Sent Access-Challenge Id 0 from 192.168.1.210:1812 to 192.168.1.1:12227 length 0 Tue Sep 20 18:36:16 2016 : Debug: (1) EAP-Message = 0x010203f60dc00000105f160303005902000055030357e17390030b51541a414f064e44c9021cd20777f90080d0f2895ef078be5a6c2007a47c68a3113cfff90944183774ff03a7cc4540f666f39da6fec2423dcc029ac03000000dff01000100000b0004030001021603030cdc0b000cd8000cd50005de Tue Sep 20 18:36:16 2016 : Debug: (1) Message-Authenticator = 0x00000000000000000000000000000000 Tue Sep 20 18:36:16 2016 : Debug: (1) State = 0xc0a4b23ec1a6bf931b6e88d496e35305 Tue Sep 20 18:36:16 2016 : Debug: (1) Finished request Tue Sep 20 18:36:16 2016 : Debug: Waking up in 4.9 seconds. Tue Sep 20 18:36:16 2016 : Debug: (1) Cleaning up request packet ID 0 with timestamp +3 Tue Sep 20 18:36:16 2016 : Debug: (2) Received Access-Request Id 0 from 192.168.1.1:12227 to 192.168.1.210:1812 length 292 Tue Sep 20 18:36:16 2016 : Debug: (2) User-Name = "pete@nexus5xp" Tue Sep 20 18:36:16 2016 : Debug: (2) NAS-IP-Address = 192.168.1.1 Tue Sep 20 18:36:16 2016 : Debug: (2) Called-Station-Id = "305a3ac51d20" Tue Sep 20 18:36:16 2016 : Debug: (2) Calling-Station-Id = "64bc0c4b27bf" Tue Sep 20 18:36:16 2016 : Debug: (2) NAS-Identifier = "305a3ac51d20" Tue Sep 20 18:36:16 2016 : Debug: (2) NAS-Port = 83 Tue Sep 20 18:36:16 2016 : Debug: (2) Framed-MTU = 1400 Tue Sep 20 18:36:16 2016 : Debug: (2) NAS-Port-Type = Wireless-802.11 Tue Sep 20 18:36:16 2016 : Debug: (2) EAP-Message = 0x020100ab0d0016030100a00100009c03038ef92dd289a9e47a08043ed8d17ba4aadbe9b997be545a3133beddda398a072b00003ec02cc030009fc02bc02f009ecca9cca8c00ac024c014c0280039006bc009c023c013c02700330067c007c011009d009c0035003d002f003c00050004000a01000035ff Tue Sep 20 18:36:16 2016 : Debug: (2) Message-Authenticator = 0x4e74d133cc690394c74156a7d305cf0f Tue Sep 20 18:36:16 2016 : Debug: (2) session-state: No State attribute Tue Sep 20 18:36:16 2016 : Debug: (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:16 2016 : Debug: (2) authorize { Tue Sep 20 18:36:16 2016 : Debug: (2) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2 Tue Sep 20 18:36:16 2016 : Debug: (2) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2 Tue Sep 20 18:36:16 2016 : Debug: (2) [preprocess] = ok Tue Sep 20 18:36:16 2016 : Debug: (2) modsingle[authorize]: calling eap (rlm_eap) for request 2 Tue Sep 20 18:36:16 2016 : Debug: (2) eap: Peer sent EAP Response (code 2) ID 1 length 171 Tue Sep 20 18:36:16 2016 : Debug: (2) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Sep 20 18:36:16 2016 : Debug: (2) modsingle[authorize]: returned from eap (rlm_eap) for request 2 Tue Sep 20 18:36:16 2016 : Debug: (2) [eap] = updated Tue Sep 20 18:36:16 2016 : Debug: (2) } # authorize = updated Tue Sep 20 18:36:16 2016 : Debug: (2) Found Auth-Type = eap Tue Sep 20 18:36:16 2016 : Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:16 2016 : Debug: (2) authenticate { Tue Sep 20 18:36:16 2016 : Debug: (2) modsingle[authenticate]: calling eap (rlm_eap) for request 2 Tue Sep 20 18:36:16 2016 : Debug: (2) eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request Tue Sep 20 18:36:16 2016 : Debug: (2) eap: Failed in handler Tue Sep 20 18:36:16 2016 : Debug: (2) modsingle[authenticate]: returned from eap (rlm_eap) for request 2 Tue Sep 20 18:36:16 2016 : Debug: (2) [eap] = invalid Tue Sep 20 18:36:16 2016 : Debug: (2) } # authenticate = invalid Tue Sep 20 18:36:16 2016 : Debug: (2) Failed to authenticate the user Tue Sep 20 18:36:16 2016 : Auth: (2) Login incorrect: [pete@nexus5xp] (from client router-1 port 83 cli 64bc0c4b27bf) Tue Sep 20 18:36:16 2016 : Debug: (2) Using Post-Auth-Type Reject Tue Sep 20 18:36:16 2016 : Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Sep 20 18:36:16 2016 : Debug: (2) Post-Auth-Type REJECT { Tue Sep 20 18:36:16 2016 : Debug: (2) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 2 Tue Sep 20 18:36:16 2016 : Debug: %{User-Name} Tue Sep 20 18:36:16 2016 : Debug: Parsed xlat tree: Tue Sep 20 18:36:16 2016 : Debug: attribute --> User-Name Tue Sep 20 18:36:16 2016 : Debug: (2) attr_filter.access_reject: EXPAND %{User-Name} Tue Sep 20 18:36:16 2016 : Debug: (2) attr_filter.access_reject: --> pete@nexus5xp Tue Sep 20 18:36:16 2016 : Debug: (2) attr_filter.access_reject: Matched entry DEFAULT at line 11 Tue Sep 20 18:36:16 2016 : Debug: (2) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 2 Tue Sep 20 18:36:16 2016 : Debug: (2) [attr_filter.access_reject] = updated Tue Sep 20 18:36:16 2016 : Debug: (2) } # Post-Auth-Type REJECT = updated Tue Sep 20 18:36:16 2016 : Debug: (2) Delaying response for 1.000000 seconds Tue Sep 20 18:36:16 2016 : Debug: Waking up in 0.6 seconds. Tue Sep 20 18:36:16 2016 : Debug: Waking up in 0.3 seconds. Tue Sep 20 18:36:17 2016 : Debug: (2) Sending delayed response Tue Sep 20 18:36:17 2016 : Debug: (2) Sent Access-Reject Id 0 from 192.168.1.210:1812 to 192.168.1.1:12227 length 20 Tue Sep 20 18:36:17 2016 : Debug: Waking up in 3.9 seconds. Tue Sep 20 18:36:21 2016 : Debug: (2) Cleaning up request packet ID 0 with timestamp +3 Tue Sep 20 18:36:21 2016 : Info: Ready to process requests What am I missing? :) Kind regards Peter