Help with EAP TLS authentication

20 Sep 2016

      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

Peter Truman

Alan DeKok

Peter Truman

tags

participants (2)