Freeradius dot1x dynamic vlan

28 Sep 2018

      Hi,

What I'm trying to do is to get freeradius to return the vlan for authenticated user.
User does get authenticated but no vlan is returned. If I add

update reply {

                  &Tunnel-Medium-Type := "IEEE-802"
                 &Tunnel-Type := "VLAN"
                 &Tunnel-Private-Group-Id := "100"

everything works. Is there a way of just returning what is listed under the user?
If not, is there a way to update the reply based on the user specific vlan?

User:

heikki    Cleartext-Password := "linux"
             Service-Type = Framed-User,
             Tunnel-Type = VLAN ,
             Tunnel-Medium-Type = IEEE-802 ,
             Tunnel-Private-Group-ID = 100

   Fri Sep 28 14:54:29 2018 : Debug: Server was built with:
Fri Sep 28 14:54:29 2018 : Debug:   accounting               : yes
Fri Sep 28 14:54:29 2018 : Debug:   authentication           : yes
Fri Sep 28 14:54:29 2018 : Debug:   ascend-binary-attributes : yes
Fri Sep 28 14:54:29 2018 : Debug:   coa                      : yes
Fri Sep 28 14:54:29 2018 : Debug:   control-socket           : yes
Fri Sep 28 14:54:29 2018 : Debug:   detail                   : yes
Fri Sep 28 14:54:29 2018 : Debug:   dhcp                     : yes
Fri Sep 28 14:54:29 2018 : Debug:   dynamic-clients          : yes
Fri Sep 28 14:54:29 2018 : Debug:   osfc2                    : no
Fri Sep 28 14:54:29 2018 : Debug:   proxy                    : yes
Fri Sep 28 14:54:29 2018 : Debug:   regex-pcre               : yes
Fri Sep 28 14:54:29 2018 : Debug:   regex-posix              : no
Fri Sep 28 14:54:29 2018 : Debug:   regex-posix-extended     : no
Fri Sep 28 14:54:29 2018 : Debug:   session-management       : yes
Fri Sep 28 14:54:29 2018 : Debug:   stats                    : yes
Fri Sep 28 14:54:29 2018 : Debug:   tcp                      : yes
Fri Sep 28 14:54:29 2018 : Debug:   threads                  : yes
Fri Sep 28 14:54:29 2018 : Debug:   tls                      : yes
Fri Sep 28 14:54:29 2018 : Debug:   unlang                   : yes
Fri Sep 28 14:54:29 2018 : Debug:   vmps                     : yes
Fri Sep 28 14:54:29 2018 : Debug:   developer                : no
Fri Sep 28 14:54:29 2018 : Debug: Server core libs:
Fri Sep 28 14:54:29 2018 : Debug:   freeradius-server        : 3.0.17
Fri Sep 28 14:54:29 2018 : Debug:   talloc                   : 2.1.*
Fri Sep 28 14:54:29 2018 : Debug:   ssl                      : 1.0.2k release
Fri Sep 28 14:54:29 2018 : Debug:   pcre                     : 8.32 2012-11-30
Fri Sep 28 14:54:29 2018 : Debug: Endianness:
Fri Sep 28 14:54:29 2018 : Debug:   little
Fri Sep 28 14:54:29 2018 : Debug: Compilation flags:
Fri Sep 28 14:54:29 2018 : Debug:   cppflags :
Fri Sep 28 14:54:29 2018 : Debug:   cflags   : -I. -Isrc -include src/freeradius-devel/autoconf.h -include src/freeradius-devel/build.h -include src/freeradius-devel/features.h -include src/freeradius-devel/radpaths.h -fno-strict-aliasing -Wno-date-time -g -O2 -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -DNDEBUG -DIS_MODULE=1
Fri Sep 28 14:54:29 2018 : Debug:   ldflags  :
Fri Sep 28 14:54:29 2018 : Debug:   libs     : -lcrypto -lssl -ltalloc -lpcre -lnsl -lresolv -ldl -lpthread
Fri Sep 28 14:54:29 2018 : Debug:
Fri Sep 28 14:54:29 2018 : Info: FreeRADIUS Version 3.0.17
Fri Sep 28 14:54:29 2018 : Info: Copyright (C) 1999-2017 The FreeRADIUS server project and contributors
Fri Sep 28 14:54:29 2018 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Fri Sep 28 14:54:29 2018 : Info: PARTICULAR PURPOSE
Fri Sep 28 14:54:29 2018 : Info: You may redistribute copies of FreeRADIUS under the terms of the
Fri Sep 28 14:54:29 2018 : Info: GNU General Public License
Fri Sep 28 14:54:29 2018 : Info: For more information about these matters, see the file named COPYRIGHT
Fri Sep 28 14:54:29 2018 : Info: Starting - reading configuration files ...
Fri Sep 28 14:54:29 2018 : Debug: including dictionary file /usr/local/share/freeradius/dictionary
Fri Sep 28 14:54:29 2018 : Debug: including dictionary file /usr/local/share/freeradius/dictionary.dhcp
Fri Sep 28 14:54:29 2018 : Debug: including dictionary file /usr/local/share/freeradius/dictionary.vqp
Fri Sep 28 14:54:29 2018 : Debug: including dictionary file /etc/raddb/dictionary
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/radiusd.conf
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/proxy.conf
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/clients.conf
Fri Sep 28 14:54:29 2018 : Debug: including files in directory /etc/raddb/mods-enabled/
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/cache_eap
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/chap
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/date
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/detail
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/detail.log
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/digest
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/dynamic_clients
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/eap
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/echo
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/exec
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/expiration
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/expr
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/files
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/linelog
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/logintime
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/mschap
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/ntlm_auth
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/pap
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/passwd
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/preprocess
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/radutmp
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/realm
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/replicate
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/soh
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/sradutmp
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/unix
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/unpack
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/utf8
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/mods-enabled/authorized_macs
Fri Sep 28 14:54:29 2018 : Debug: including files in directory /etc/raddb/policy.d/
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/abfab-tr
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/accounting
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/control
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/cui
Fri Sep 28 14:54:29 2018 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE
Fri Sep 28 14:54:29 2018 : Debug: OPTIMIZING (no == yes) --> FALSE
Fri Sep 28 14:54:29 2018 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE
Fri Sep 28 14:54:29 2018 : Debug: OPTIMIZING (no == yes) --> FALSE
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/debug
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/dhcp
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/eap
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/moonshot-targeted-ids
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/operator-name
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/canonicalization
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/policy.d/filter
Fri Sep 28 14:54:29 2018 : Debug: including files in directory /etc/raddb/sites-enabled/
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/sites-enabled/inner-tunnel
Fri Sep 28 14:54:29 2018 : Debug: including configuration file /etc/raddb/sites-enabled/control-socket
Fri Sep 28 14:54:29 2018 : Debug: main {
Fri Sep 28 14:54:29 2018 : Debug:  security {
Fri Sep 28 14:54:29 2018 : Debug:   allow_core_dumps = no
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[424]: The item 'max_attributes' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[442]: The item 'reject_delay' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[462]: The item 'status_server' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[472]: The item 'allow_vulnerable_openssl' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug:  name = "radiusd"
Fri Sep 28 14:54:29 2018 : Debug:  prefix = "/usr/local"
Fri Sep 28 14:54:29 2018 : Debug:  localstatedir = "/usr/local/var"
Fri Sep 28 14:54:29 2018 : Debug:  logdir = "/usr/local/var/log/radius"
Fri Sep 28 14:54:29 2018 : Debug:  run_dir = "/usr/local/var/run/radiusd"
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[74]: The item 'db_dir' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[108]: The item 'libdir' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[119]: The item 'pidfile' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[140]: The item 'correct_escapes' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[194]: The item 'max_request_time' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[213]: The item 'cleanup_delay' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[250]: The item 'hostname_lookups' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[334]: The item 'checkrad' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[491]: The item 'proxy_requests' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Debug: }
Fri Sep 28 14:54:29 2018 : Debug: main {
Fri Sep 28 14:54:29 2018 : Debug:  name = "radiusd"
Fri Sep 28 14:54:29 2018 : Debug:  prefix = "/usr/local"
Fri Sep 28 14:54:29 2018 : Debug:  localstatedir = "/usr/local/var"
Fri Sep 28 14:54:29 2018 : Debug:  sbindir = "/usr/local/sbin"
Fri Sep 28 14:54:29 2018 : Debug:  logdir = "/usr/local/var/log/radius"
Fri Sep 28 14:54:29 2018 : Debug:  run_dir = "/usr/local/var/run/radiusd"
Fri Sep 28 14:54:29 2018 : Debug:  libdir = "/usr/local/lib"
Fri Sep 28 14:54:29 2018 : Debug:  radacctdir = "/usr/local/var/log/radius/radacct"
Fri Sep 28 14:54:29 2018 : Debug:  hostname_lookups = no
Fri Sep 28 14:54:29 2018 : Debug:  max_request_time = 30
Fri Sep 28 14:54:29 2018 : Debug:  cleanup_delay = 5
Fri Sep 28 14:54:29 2018 : Debug:  max_requests = 16384
Fri Sep 28 14:54:29 2018 : Debug:  pidfile = "/usr/local/var/run/radiusd/radiusd.pid"
Fri Sep 28 14:54:29 2018 : Debug:  checkrad = "/usr/local/sbin/checkrad"
Fri Sep 28 14:54:29 2018 : Debug:  debug_level = 0
Fri Sep 28 14:54:29 2018 : Debug:  proxy_requests = yes
Fri Sep 28 14:54:29 2018 : Debug:  log {
Fri Sep 28 14:54:29 2018 : Debug:   stripped_names = no
Fri Sep 28 14:54:29 2018 : Debug:   auth = no
Fri Sep 28 14:54:29 2018 : Debug:   auth_badpass = no
Fri Sep 28 14:54:29 2018 : Debug:   auth_goodpass = no
Fri Sep 28 14:54:29 2018 : Debug:   colourise = yes
Fri Sep 28 14:54:29 2018 : Debug:   msg_denied = "You are already logged in - access denied"
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[268]: The item 'destination' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[285]: The item 'file' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[293]: The item 'syslog_facility' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug:  resources {
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug:  security {
Fri Sep 28 14:54:29 2018 : Debug:   max_attributes = 200
Fri Sep 28 14:54:29 2018 : Debug:   reject_delay = 1.000000
Fri Sep 28 14:54:29 2018 : Debug:   status_server = yes
Fri Sep 28 14:54:29 2018 : Debug:   allow_vulnerable_openssl = "no"
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[74]: The item 'db_dir' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Warning: /etc/raddb/radiusd.conf[140]: The item 'correct_escapes' is defined, but is unused by the configuration
Fri Sep 28 14:54:29 2018 : Debug: }
Fri Sep 28 14:54:29 2018 : Debug: radiusd: #### Loading Realms and Home Servers ####
Fri Sep 28 14:54:29 2018 : Debug:  proxy server {
Fri Sep 28 14:54:29 2018 : Debug:   retry_delay = 5
Fri Sep 28 14:54:29 2018 : Debug:   retry_count = 3
Fri Sep 28 14:54:29 2018 : Debug:   default_fallback = no
Fri Sep 28 14:54:29 2018 : Debug:   dead_time = 120
Fri Sep 28 14:54:29 2018 : Debug:   wake_all_if_all_dead = no
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug:  home_server localhost {
Fri Sep 28 14:54:29 2018 : Debug:   ipaddr = 127.0.0.1
Fri Sep 28 14:54:29 2018 : Debug:   port = 1812
Fri Sep 28 14:54:29 2018 : Debug:   type = "auth"
Fri Sep 28 14:54:29 2018 : Debug:   secret = "testing123"
Fri Sep 28 14:54:29 2018 : Debug:   response_window = 20.000000
Fri Sep 28 14:54:29 2018 : Debug:   response_timeouts = 1
Fri Sep 28 14:54:29 2018 : Debug:   max_outstanding = 65536
Fri Sep 28 14:54:29 2018 : Debug:   zombie_period = 40
Fri Sep 28 14:54:29 2018 : Debug:   status_check = "status-server"
Fri Sep 28 14:54:29 2018 : Debug:   ping_interval = 30
Fri Sep 28 14:54:29 2018 : Debug:   check_interval = 30
Fri Sep 28 14:54:29 2018 : Debug:   check_timeout = 4
Fri Sep 28 14:54:29 2018 : Debug:   num_answers_to_alive = 3
Fri Sep 28 14:54:29 2018 : Debug:   revive_interval = 120
Fri Sep 28 14:54:29 2018 : Debug:   limit {
Fri Sep 28 14:54:29 2018 : Debug:    max_connections = 16
Fri Sep 28 14:54:29 2018 : Debug:    max_requests = 0
Fri Sep 28 14:54:29 2018 : Debug:    lifetime = 0
Fri Sep 28 14:54:29 2018 : Debug:    idle_timeout = 0
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   coa {
Fri Sep 28 14:54:29 2018 : Debug:    irt = 2
Fri Sep 28 14:54:29 2018 : Debug:    mrt = 16
Fri Sep 28 14:54:29 2018 : Debug:    mrc = 5
Fri Sep 28 14:54:29 2018 : Debug:    mrd = 30
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug:  home_server_pool my_auth_failover {
Fri Sep 28 14:54:29 2018 : Debug:  type = fail-over
Fri Sep 28 14:54:29 2018 : Debug:  home_server = localhost
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug:  realm example.com {
Fri Sep 28 14:54:29 2018 : Debug:  auth_pool = my_auth_failover
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug:  realm LOCAL {
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug: radiusd: #### Loading Clients ####
Fri Sep 28 14:54:29 2018 : Debug:  client localhost {
Fri Sep 28 14:54:29 2018 : Debug:   ipaddr = 127.0.0.1
Fri Sep 28 14:54:29 2018 : Debug:   require_message_authenticator = no
Fri Sep 28 14:54:29 2018 : Debug:   secret = "testing123"
Fri Sep 28 14:54:29 2018 : Debug:   nas_type = "other"
Fri Sep 28 14:54:29 2018 : Debug:   proto = "*"
Fri Sep 28 14:54:29 2018 : Debug:   limit {
Fri Sep 28 14:54:29 2018 : Debug:    max_connections = 16
Fri Sep 28 14:54:29 2018 : Debug:    lifetime = 0
Fri Sep 28 14:54:29 2018 : Debug:    idle_timeout = 30
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32
Fri Sep 28 14:54:29 2018 : Debug:  client radtest {
Fri Sep 28 14:54:29 2018 : Debug:   ipaddr = 10.24.28.17
Fri Sep 28 14:54:29 2018 : Debug:   require_message_authenticator = no
Fri Sep 28 14:54:29 2018 : Debug:   secret = "linux"
Fri Sep 28 14:54:29 2018 : Debug:   limit {
Fri Sep 28 14:54:29 2018 : Debug:    max_connections = 16
Fri Sep 28 14:54:29 2018 : Debug:    lifetime = 0
Fri Sep 28 14:54:29 2018 : Debug:    idle_timeout = 30
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug: Adding client 10.24.28.17/32 (10.24.28.17) to prefix tree 32
Fri Sep 28 14:54:29 2018 : Debug:  client n3k {
Fri Sep 28 14:54:29 2018 : Debug:   ipaddr = 172.28.14.103
Fri Sep 28 14:54:29 2018 : Debug:   require_message_authenticator = no
Fri Sep 28 14:54:29 2018 : Debug:   secret = "linux"
Fri Sep 28 14:54:29 2018 : Debug:   limit {
Fri Sep 28 14:54:29 2018 : Debug:    max_connections = 16
Fri Sep 28 14:54:29 2018 : Debug:    lifetime = 0
Fri Sep 28 14:54:29 2018 : Debug:    idle_timeout = 30
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug: Adding client 172.28.14.103/32 (172.28.14.103) to prefix tree 32
Fri Sep 28 14:54:29 2018 : Debug:  client localhost_ipv6 {
Fri Sep 28 14:54:29 2018 : Debug:   ipv6addr = ::1
Fri Sep 28 14:54:29 2018 : Debug:   require_message_authenticator = no
Fri Sep 28 14:54:29 2018 : Debug:   secret = "testing123"
Fri Sep 28 14:54:29 2018 : Debug:   limit {
Fri Sep 28 14:54:29 2018 : Debug:    max_connections = 16
Fri Sep 28 14:54:29 2018 : Debug:    lifetime = 0
Fri Sep 28 14:54:29 2018 : Debug:    idle_timeout = 30
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug: Adding client ::1/128 (::1) to prefix tree 128
Fri Sep 28 14:54:29 2018 : Info: Debugger not attached
Fri Sep 28 14:54:29 2018 : Debug:  # Creating Auth-Type = mschap
Fri Sep 28 14:54:29 2018 : Debug:  # Creating Auth-Type = digest
Fri Sep 28 14:54:29 2018 : Debug:  # Creating Auth-Type = eap
Fri Sep 28 14:54:29 2018 : Debug:  # Creating Auth-Type = PAP
Fri Sep 28 14:54:29 2018 : Debug:  # Creating Auth-Type = CHAP
Fri Sep 28 14:54:29 2018 : Debug:  # Creating Auth-Type = MS-CHAP
Fri Sep 28 14:54:29 2018 : Debug: radiusd: #### Instantiating modules ####
Fri Sep 28 14:54:29 2018 : Debug:  modules {
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_always, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_always
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "reject" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   always reject {
Fri Sep 28 14:54:29 2018 : Debug:    rcode = "reject"
Fri Sep 28 14:54:29 2018 : Debug:    simulcount = 0
Fri Sep 28 14:54:29 2018 : Debug:    mpp = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "fail" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   always fail {
Fri Sep 28 14:54:29 2018 : Debug:    rcode = "fail"
Fri Sep 28 14:54:29 2018 : Debug:    simulcount = 0
Fri Sep 28 14:54:29 2018 : Debug:    mpp = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "ok" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   always ok {
Fri Sep 28 14:54:29 2018 : Debug:    rcode = "ok"
Fri Sep 28 14:54:29 2018 : Debug:    simulcount = 0
Fri Sep 28 14:54:29 2018 : Debug:    mpp = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "handled" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   always handled {
Fri Sep 28 14:54:29 2018 : Debug:    rcode = "handled"
Fri Sep 28 14:54:29 2018 : Debug:    simulcount = 0
Fri Sep 28 14:54:29 2018 : Debug:    mpp = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "invalid" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   always invalid {
Fri Sep 28 14:54:29 2018 : Debug:    rcode = "invalid"
Fri Sep 28 14:54:29 2018 : Debug:    simulcount = 0
Fri Sep 28 14:54:29 2018 : Debug:    mpp = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "userlock" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   always userlock {
Fri Sep 28 14:54:29 2018 : Debug:    rcode = "userlock"
Fri Sep 28 14:54:29 2018 : Debug:    simulcount = 0
Fri Sep 28 14:54:29 2018 : Debug:    mpp = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "notfound" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   always notfound {
Fri Sep 28 14:54:29 2018 : Debug:    rcode = "notfound"
Fri Sep 28 14:54:29 2018 : Debug:    simulcount = 0
Fri Sep 28 14:54:29 2018 : Debug:    mpp = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "noop" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   always noop {
Fri Sep 28 14:54:29 2018 : Debug:    rcode = "noop"
Fri Sep 28 14:54:29 2018 : Debug:    simulcount = 0
Fri Sep 28 14:54:29 2018 : Debug:    mpp = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "updated" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   always updated {
Fri Sep 28 14:54:29 2018 : Debug:    rcode = "updated"
Fri Sep 28 14:54:29 2018 : Debug:    simulcount = 0
Fri Sep 28 14:54:29 2018 : Debug:    mpp = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_attr_filter, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_attr_filter
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "attr_filter.post-proxy" from file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug:   attr_filter attr_filter.post-proxy {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/etc/raddb/mods-config/attr_filter/post-proxy"
Fri Sep 28 14:54:29 2018 : Debug:    key = "%{Realm}"
Fri Sep 28 14:54:29 2018 : Debug:    relaxed = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "attr_filter.pre-proxy" from file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug:   attr_filter attr_filter.pre-proxy {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/etc/raddb/mods-config/attr_filter/pre-proxy"
Fri Sep 28 14:54:29 2018 : Debug:    key = "%{Realm}"
Fri Sep 28 14:54:29 2018 : Debug:    relaxed = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "attr_filter.access_reject" from file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug:   attr_filter attr_filter.access_reject {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/etc/raddb/mods-config/attr_filter/access_reject"
Fri Sep 28 14:54:29 2018 : Debug:    key = "%{User-Name}"
Fri Sep 28 14:54:29 2018 : Debug:    relaxed = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "attr_filter.access_challenge" from file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug:   attr_filter attr_filter.access_challenge {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/etc/raddb/mods-config/attr_filter/access_challenge"
Fri Sep 28 14:54:29 2018 : Debug:    key = "%{User-Name}"
Fri Sep 28 14:54:29 2018 : Debug:    relaxed = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "attr_filter.accounting_response" from file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug:   attr_filter attr_filter.accounting_response {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/etc/raddb/mods-config/attr_filter/accounting_response"
Fri Sep 28 14:54:29 2018 : Debug:    key = "%{User-Name}"
Fri Sep 28 14:54:29 2018 : Debug:    relaxed = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_cache, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_cache
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "cache_eap" from file /etc/raddb/mods-enabled/cache_eap
Fri Sep 28 14:54:29 2018 : Debug:   cache cache_eap {
Fri Sep 28 14:54:29 2018 : Debug:    driver = "rlm_cache_rbtree"
Fri Sep 28 14:54:29 2018 : Debug:    key = "%{%{control:State}:-%{%{reply:State}:-%{State}}}"
Fri Sep 28 14:54:29 2018 : Debug:    ttl = 15
Fri Sep 28 14:54:29 2018 : Debug:    max_entries = 0
Fri Sep 28 14:54:29 2018 : Debug:    epoch = 0
Fri Sep 28 14:54:29 2018 : Debug:    add_stats = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_chap, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_chap
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "chap" from file /etc/raddb/mods-enabled/chap
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_date, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_date
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "date" from file /etc/raddb/mods-enabled/date
Fri Sep 28 14:54:29 2018 : Debug:   date {
Fri Sep 28 14:54:29 2018 : Debug:    format = "%b %e %Y %H:%M:%S %Z"
Fri Sep 28 14:54:29 2018 : Debug:    utc = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_detail, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_detail
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "detail" from file /etc/raddb/mods-enabled/detail
Fri Sep 28 14:54:29 2018 : Debug:   detail {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
Fri Sep 28 14:54:29 2018 : Debug:    header = "%t"
Fri Sep 28 14:54:29 2018 : Debug:    permissions = 384
Fri Sep 28 14:54:29 2018 : Debug:    locking = no
Fri Sep 28 14:54:29 2018 : Debug:    escape_filenames = no
Fri Sep 28 14:54:29 2018 : Debug:    log_packet_header = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "auth_log" from file /etc/raddb/mods-enabled/detail.log
Fri Sep 28 14:54:29 2018 : Debug:   detail auth_log {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d"
Fri Sep 28 14:54:29 2018 : Debug:    header = "%t"
Fri Sep 28 14:54:29 2018 : Debug:    permissions = 384
Fri Sep 28 14:54:29 2018 : Debug:    locking = no
Fri Sep 28 14:54:29 2018 : Debug:    escape_filenames = no
Fri Sep 28 14:54:29 2018 : Debug:    log_packet_header = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "reply_log" from file /etc/raddb/mods-enabled/detail.log
Fri Sep 28 14:54:29 2018 : Debug:   detail reply_log {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d"
Fri Sep 28 14:54:29 2018 : Debug:    header = "%t"
Fri Sep 28 14:54:29 2018 : Debug:    permissions = 384
Fri Sep 28 14:54:29 2018 : Debug:    locking = no
Fri Sep 28 14:54:29 2018 : Debug:    escape_filenames = no
Fri Sep 28 14:54:29 2018 : Debug:    log_packet_header = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "pre_proxy_log" from file /etc/raddb/mods-enabled/detail.log
Fri Sep 28 14:54:29 2018 : Debug:   detail pre_proxy_log {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d"
Fri Sep 28 14:54:29 2018 : Debug:    header = "%t"
Fri Sep 28 14:54:29 2018 : Debug:    permissions = 384
Fri Sep 28 14:54:29 2018 : Debug:    locking = no
Fri Sep 28 14:54:29 2018 : Debug:    escape_filenames = no
Fri Sep 28 14:54:29 2018 : Debug:    log_packet_header = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "post_proxy_log" from file /etc/raddb/mods-enabled/detail.log
Fri Sep 28 14:54:29 2018 : Debug:   detail post_proxy_log {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d"
Fri Sep 28 14:54:29 2018 : Debug:    header = "%t"
Fri Sep 28 14:54:29 2018 : Debug:    permissions = 384
Fri Sep 28 14:54:29 2018 : Debug:    locking = no
Fri Sep 28 14:54:29 2018 : Debug:    escape_filenames = no
Fri Sep 28 14:54:29 2018 : Debug:    log_packet_header = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_digest, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_digest
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "digest" from file /etc/raddb/mods-enabled/digest
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_dynamic_clients, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_dynamic_clients
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "dynamic_clients" from file /etc/raddb/mods-enabled/dynamic_clients
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_eap, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_eap
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "eap" from file /etc/raddb/mods-enabled/eap
Fri Sep 28 14:54:29 2018 : Debug:   eap {
Fri Sep 28 14:54:29 2018 : Debug:    default_eap_type = "md5"
Fri Sep 28 14:54:29 2018 : Debug:    timer_expire = 60
Fri Sep 28 14:54:29 2018 : Debug:    ignore_unknown_eap_types = no
Fri Sep 28 14:54:29 2018 : Debug:    cisco_accounting_username_bug = no
Fri Sep 28 14:54:29 2018 : Debug:    max_sessions = 16384
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_exec, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_exec
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "echo" from file /etc/raddb/mods-enabled/echo
Fri Sep 28 14:54:29 2018 : Debug:   exec echo {
Fri Sep 28 14:54:29 2018 : Debug:    wait = yes
Fri Sep 28 14:54:29 2018 : Debug:    program = "/bin/echo %{User-Name}"
Fri Sep 28 14:54:29 2018 : Debug:    input_pairs = "request"
Fri Sep 28 14:54:29 2018 : Debug:    output_pairs = "reply"
Fri Sep 28 14:54:29 2018 : Debug:    shell_escape = yes
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "exec" from file /etc/raddb/mods-enabled/exec
Fri Sep 28 14:54:29 2018 : Debug:   exec {
Fri Sep 28 14:54:29 2018 : Debug:    wait = no
Fri Sep 28 14:54:29 2018 : Debug:    input_pairs = "request"
Fri Sep 28 14:54:29 2018 : Debug:    shell_escape = yes
Fri Sep 28 14:54:29 2018 : Debug:    timeout = 10
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_expiration, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_expiration
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "expiration" from file /etc/raddb/mods-enabled/expiration
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_expr, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_expr
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "expr" from file /etc/raddb/mods-enabled/expr
Fri Sep 28 14:54:29 2018 : Debug:   expr {
Fri Sep 28 14:54:29 2018 : Debug:    safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôoeùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔOEÙÛÜY"
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_files, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_files
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "files" from file /etc/raddb/mods-enabled/files
Fri Sep 28 14:54:29 2018 : Debug:   files {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/etc/raddb/mods-config/files/authorize"
Fri Sep 28 14:54:29 2018 : Debug:    acctusersfile = "/etc/raddb/mods-config/files/accounting"
Fri Sep 28 14:54:29 2018 : Debug:    preproxy_usersfile = "/etc/raddb/mods-config/files/pre-proxy"
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_linelog, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_linelog
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "linelog" from file /etc/raddb/mods-enabled/linelog
Fri Sep 28 14:54:29 2018 : Debug:   linelog {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/usr/local/var/log/radius/linelog"
Fri Sep 28 14:54:29 2018 : Debug:    escape_filenames = no
Fri Sep 28 14:54:29 2018 : Debug:    syslog_severity = "info"
Fri Sep 28 14:54:29 2018 : Debug:    permissions = 384
Fri Sep 28 14:54:29 2018 : Debug:    format = "This is a log message for %{User-Name}"
Fri Sep 28 14:54:29 2018 : Debug:    reference = "messages.%{%{reply:Packet-Type}:-default}"
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "log_accounting" from file /etc/raddb/mods-enabled/linelog
Fri Sep 28 14:54:29 2018 : Debug:   linelog log_accounting {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/usr/local/var/log/radius/linelog-accounting"
Fri Sep 28 14:54:29 2018 : Debug:    escape_filenames = no
Fri Sep 28 14:54:29 2018 : Debug:    syslog_severity = "info"
Fri Sep 28 14:54:29 2018 : Debug:    permissions = 384
Fri Sep 28 14:54:29 2018 : Debug:    format = ""
Fri Sep 28 14:54:29 2018 : Debug:    reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}"
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_logintime, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_logintime
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "logintime" from file /etc/raddb/mods-enabled/logintime
Fri Sep 28 14:54:29 2018 : Debug:   logintime {
Fri Sep 28 14:54:29 2018 : Debug:    minimum_timeout = 60
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_mschap, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_mschap
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "mschap" from file /etc/raddb/mods-enabled/mschap
Fri Sep 28 14:54:29 2018 : Debug:   mschap {
Fri Sep 28 14:54:29 2018 : Debug:    use_mppe = yes
Fri Sep 28 14:54:29 2018 : Debug:    require_encryption = no
Fri Sep 28 14:54:29 2018 : Debug:    require_strong = no
Fri Sep 28 14:54:29 2018 : Debug:    with_ntdomain_hack = yes
Fri Sep 28 14:54:29 2018 : Debug:    passchange {
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:    allow_retry = yes
Fri Sep 28 14:54:29 2018 : Debug:    winbind_retry_with_normalised_username = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "ntlm_auth" from file /etc/raddb/mods-enabled/ntlm_auth
Fri Sep 28 14:54:29 2018 : Debug:   exec ntlm_auth {
Fri Sep 28 14:54:29 2018 : Debug:    wait = yes
Fri Sep 28 14:54:29 2018 : Debug:    program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}"
Fri Sep 28 14:54:29 2018 : Debug:    shell_escape = yes
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_pap, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_pap
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "pap" from file /etc/raddb/mods-enabled/pap
Fri Sep 28 14:54:29 2018 : Debug:   pap {
Fri Sep 28 14:54:29 2018 : Debug:    normalise = yes
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_passwd, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_passwd
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "etc_passwd" from file /etc/raddb/mods-enabled/passwd
Fri Sep 28 14:54:29 2018 : Debug:   passwd etc_passwd {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/etc/passwd"
Fri Sep 28 14:54:29 2018 : Debug:    format = "*User-Name:Crypt-Password:"
Fri Sep 28 14:54:29 2018 : Debug:    delimiter = ":"
Fri Sep 28 14:54:29 2018 : Debug:    ignore_nislike = no
Fri Sep 28 14:54:29 2018 : Debug:    ignore_empty = yes
Fri Sep 28 14:54:29 2018 : Debug:    allow_multiple_keys = no
Fri Sep 28 14:54:29 2018 : Debug:    hash_size = 100
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_preprocess, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_preprocess
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "preprocess" from file /etc/raddb/mods-enabled/preprocess
Fri Sep 28 14:54:29 2018 : Debug:   preprocess {
Fri Sep 28 14:54:29 2018 : Debug:    huntgroups = "/etc/raddb/mods-config/preprocess/huntgroups"
Fri Sep 28 14:54:29 2018 : Debug:    hints = "/etc/raddb/mods-config/preprocess/hints"
Fri Sep 28 14:54:29 2018 : Debug:    with_ascend_hack = no
Fri Sep 28 14:54:29 2018 : Debug:    ascend_channels_per_line = 23
Fri Sep 28 14:54:29 2018 : Debug:    with_ntdomain_hack = no
Fri Sep 28 14:54:29 2018 : Debug:    with_specialix_jetstream_hack = no
Fri Sep 28 14:54:29 2018 : Debug:    with_cisco_vsa_hack = no
Fri Sep 28 14:54:29 2018 : Debug:    with_alvarion_vsa_hack = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_radutmp, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_radutmp
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "radutmp" from file /etc/raddb/mods-enabled/radutmp
Fri Sep 28 14:54:29 2018 : Debug:   radutmp {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/usr/local/var/log/radius/radutmp"
Fri Sep 28 14:54:29 2018 : Debug:    username = "%{User-Name}"
Fri Sep 28 14:54:29 2018 : Debug:    case_sensitive = yes
Fri Sep 28 14:54:29 2018 : Debug:    check_with_nas = yes
Fri Sep 28 14:54:29 2018 : Debug:    permissions = 384
Fri Sep 28 14:54:29 2018 : Debug:    caller_id = yes
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_realm, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_realm
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "IPASS" from file /etc/raddb/mods-enabled/realm
Fri Sep 28 14:54:29 2018 : Debug:   realm IPASS {
Fri Sep 28 14:54:29 2018 : Debug:    format = "prefix"
Fri Sep 28 14:54:29 2018 : Debug:    delimiter = "/"
Fri Sep 28 14:54:29 2018 : Debug:    ignore_default = no
Fri Sep 28 14:54:29 2018 : Debug:    ignore_null = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "suffix" from file /etc/raddb/mods-enabled/realm
Fri Sep 28 14:54:29 2018 : Debug:   realm suffix {
Fri Sep 28 14:54:29 2018 : Debug:    format = "suffix"
Fri Sep 28 14:54:29 2018 : Debug:    delimiter = "@"
Fri Sep 28 14:54:29 2018 : Debug:    ignore_default = no
Fri Sep 28 14:54:29 2018 : Debug:    ignore_null = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "realmpercent" from file /etc/raddb/mods-enabled/realm
Fri Sep 28 14:54:29 2018 : Debug:   realm realmpercent {
Fri Sep 28 14:54:29 2018 : Debug:    format = "suffix"
Fri Sep 28 14:54:29 2018 : Debug:    delimiter = "%"
Fri Sep 28 14:54:29 2018 : Debug:    ignore_default = no
Fri Sep 28 14:54:29 2018 : Debug:    ignore_null = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "ntdomain" from file /etc/raddb/mods-enabled/realm
Fri Sep 28 14:54:29 2018 : Debug:   realm ntdomain {
Fri Sep 28 14:54:29 2018 : Debug:    format = "prefix"
Fri Sep 28 14:54:29 2018 : Debug:    delimiter = "\\"
Fri Sep 28 14:54:29 2018 : Debug:    ignore_default = no
Fri Sep 28 14:54:29 2018 : Debug:    ignore_null = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_replicate, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_replicate
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "replicate" from file /etc/raddb/mods-enabled/replicate
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_soh, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_soh
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "soh" from file /etc/raddb/mods-enabled/soh
Fri Sep 28 14:54:29 2018 : Debug:   soh {
Fri Sep 28 14:54:29 2018 : Debug:    dhcp = yes
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "sradutmp" from file /etc/raddb/mods-enabled/sradutmp
Fri Sep 28 14:54:29 2018 : Debug:   radutmp sradutmp {
Fri Sep 28 14:54:29 2018 : Debug:    filename = "/usr/local/var/log/radius/sradutmp"
Fri Sep 28 14:54:29 2018 : Debug:    username = "%{User-Name}"
Fri Sep 28 14:54:29 2018 : Debug:    case_sensitive = yes
Fri Sep 28 14:54:29 2018 : Debug:    check_with_nas = yes
Fri Sep 28 14:54:29 2018 : Debug:    permissions = 420
Fri Sep 28 14:54:29 2018 : Debug:    caller_id = no
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_unix, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_unix
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "unix" from file /etc/raddb/mods-enabled/unix
Fri Sep 28 14:54:29 2018 : Debug:   unix {
Fri Sep 28 14:54:29 2018 : Debug:    radwtmp = "/usr/local/var/log/radius/radwtmp"
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: Creating attribute Unix-Group
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_unpack, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_unpack
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "unpack" from file /etc/raddb/mods-enabled/unpack
Fri Sep 28 14:54:29 2018 : Debug: Loaded rlm_utf8, checking if it's valid
Fri Sep 28 14:54:29 2018 : Debug:   # Loaded module rlm_utf8
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "utf8" from file /etc/raddb/mods-enabled/utf8
Fri Sep 28 14:54:29 2018 : Debug:   # Loading module "authorized_macs" from file /etc/raddb/mods-enabled/authorized_macs
Fri Sep 28 14:54:29 2018 : Debug:   files authorized_macs {
Fri Sep 28 14:54:29 2018 : Debug:    usersfile = "/etc/raddb/authorized_macs"
Fri Sep 28 14:54:29 2018 : Debug:    key = "%{Calling-Station-ID}"
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   instantiate {
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "reject" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "fail" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "ok" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "handled" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "invalid" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "userlock" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "notfound" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "noop" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "updated" from file /etc/raddb/mods-enabled/always
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "attr_filter.post-proxy" from file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/mods-config/attr_filter/post-proxy
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "attr_filter.pre-proxy" from file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/mods-config/attr_filter/pre-proxy
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "attr_filter.access_reject" from file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/mods-config/attr_filter/access_reject
Fri Sep 28 14:54:29 2018 : Warning: [/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay"  found in filter list for realm "DEFAULT".
Fri Sep 28 14:54:29 2018 : Warning: [/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec"  found in filter list for realm "DEFAULT".
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "attr_filter.access_challenge" from file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/mods-config/attr_filter/access_challenge
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "attr_filter.accounting_response" from file /etc/raddb/mods-enabled/attr_filter
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/mods-config/attr_filter/accounting_response
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "cache_eap" from file /etc/raddb/mods-enabled/cache_eap
Fri Sep 28 14:54:29 2018 : Debug: rlm_cache (cache_eap): Driver rlm_cache_rbtree (module rlm_cache_rbtree) loaded and linked
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "detail" from file /etc/raddb/mods-enabled/detail
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "auth_log" from file /etc/raddb/mods-enabled/detail.log
Fri Sep 28 14:54:29 2018 : Debug: rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "reply_log" from file /etc/raddb/mods-enabled/detail.log
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "pre_proxy_log" from file /etc/raddb/mods-enabled/detail.log
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "post_proxy_log" from file /etc/raddb/mods-enabled/detail.log
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "eap" from file /etc/raddb/mods-enabled/eap
Fri Sep 28 14:54:29 2018 : Debug:    # Linked to sub-module rlm_eap_md5
Fri Sep 28 14:54:29 2018 : Debug:    # Linked to sub-module rlm_eap_leap
Fri Sep 28 14:54:29 2018 : Debug:    # Linked to sub-module rlm_eap_gtc
Fri Sep 28 14:54:29 2018 : Debug:    gtc {
Fri Sep 28 14:54:29 2018 : Debug:     challenge = "Password: "
Fri Sep 28 14:54:29 2018 : Debug:     auth_type = "PAP"
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:    # Linked to sub-module rlm_eap_tls
Fri Sep 28 14:54:29 2018 : Debug:    tls {
Fri Sep 28 14:54:29 2018 : Debug:     tls = "tls-common"
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:    tls-config tls-common {
Fri Sep 28 14:54:29 2018 : Debug:     verify_depth = 0
Fri Sep 28 14:54:29 2018 : Debug:     ca_path = "/etc/raddb/certs"
Fri Sep 28 14:54:29 2018 : Debug:     pem_file_type = yes
Fri Sep 28 14:54:29 2018 : Debug:     private_key_file = "/etc/raddb/certs/server.pem"
Fri Sep 28 14:54:29 2018 : Debug:     certificate_file = "/etc/raddb/certs/server.pem"
Fri Sep 28 14:54:29 2018 : Debug:     ca_file = "/etc/raddb/certs/ca.pem"
Fri Sep 28 14:54:29 2018 : Debug:     private_key_password = "whatever"
Fri Sep 28 14:54:29 2018 : Debug:     dh_file = "/etc/raddb/certs/dh"
Fri Sep 28 14:54:29 2018 : Debug:     fragment_size = 1024
Fri Sep 28 14:54:29 2018 : Debug:     include_length = yes
Fri Sep 28 14:54:29 2018 : Debug:     auto_chain = yes
Fri Sep 28 14:54:29 2018 : Debug:     check_crl = no
Fri Sep 28 14:54:29 2018 : Debug:     check_all_crl = no
Fri Sep 28 14:54:29 2018 : Debug:     cipher_list = "DEFAULT"
Fri Sep 28 14:54:29 2018 : Debug:     cipher_server_preference = no
Fri Sep 28 14:54:29 2018 : Debug:     ecdh_curve = "prime256v1"
Fri Sep 28 14:54:29 2018 : Debug:     tls_max_version = ""
Fri Sep 28 14:54:29 2018 : Debug:     tls_min_version = "1.0"
Fri Sep 28 14:54:29 2018 : Debug:     cache {
Fri Sep 28 14:54:29 2018 : Debug:      enable = no
Fri Sep 28 14:54:29 2018 : Debug:      lifetime = 24
Fri Sep 28 14:54:29 2018 : Debug:      max_entries = 255
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     verify {
Fri Sep 28 14:54:29 2018 : Debug:      skip_if_ocsp_ok = no
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     ocsp {
Fri Sep 28 14:54:29 2018 : Debug:      enable = no
Fri Sep 28 14:54:29 2018 : Debug:      override_cert_url = yes
Fri Sep 28 14:54:29 2018 : Debug:      url = "http://127.0.0.1/ocsp/"
Fri Sep 28 14:54:29 2018 : Debug:      use_nonce = yes
Fri Sep 28 14:54:29 2018 : Debug:      timeout = 0
Fri Sep 28 14:54:29 2018 : Debug:      softfail = no
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:    # Linked to sub-module rlm_eap_ttls
Fri Sep 28 14:54:29 2018 : Debug:    ttls {
Fri Sep 28 14:54:29 2018 : Debug:     tls = "tls-common"
Fri Sep 28 14:54:29 2018 : Debug:     default_eap_type = "md5"
Fri Sep 28 14:54:29 2018 : Debug:     copy_request_to_tunnel = yes
Fri Sep 28 14:54:29 2018 : Debug:     use_tunneled_reply = no
Fri Sep 28 14:54:29 2018 : Debug:     virtual_server = "inner-tunnel"
Fri Sep 28 14:54:29 2018 : Debug:     include_length = yes
Fri Sep 28 14:54:29 2018 : Debug:     require_client_cert = no
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug: tls: Using cached TLS configuration from previous invocation
Fri Sep 28 14:54:29 2018 : Debug:    # Linked to sub-module rlm_eap_peap
Fri Sep 28 14:54:29 2018 : Debug:    peap {
Fri Sep 28 14:54:29 2018 : Debug:     tls = "tls-common"
Fri Sep 28 14:54:29 2018 : Debug:     default_eap_type = "mschapv2"
Fri Sep 28 14:54:29 2018 : Debug:     copy_request_to_tunnel = no
Fri Sep 28 14:54:29 2018 : Debug:     use_tunneled_reply = no
Fri Sep 28 14:54:29 2018 : Debug:     proxy_tunneled_request_as_eap = yes
Fri Sep 28 14:54:29 2018 : Debug:     virtual_server = "inner-tunnel"
Fri Sep 28 14:54:29 2018 : Debug:     soh = no
Fri Sep 28 14:54:29 2018 : Debug:     require_client_cert = no
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug: tls: Using cached TLS configuration from previous invocation
Fri Sep 28 14:54:29 2018 : Debug:    # Linked to sub-module rlm_eap_mschapv2
Fri Sep 28 14:54:29 2018 : Debug:    mschapv2 {
Fri Sep 28 14:54:29 2018 : Debug:     with_ntdomain_hack = no
Fri Sep 28 14:54:29 2018 : Debug:     send_error = no
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "expiration" from file /etc/raddb/mods-enabled/expiration
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "files" from file /etc/raddb/mods-enabled/files
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/mods-config/files/authorize
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/mods-config/files/accounting
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/mods-config/files/pre-proxy
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "linelog" from file /etc/raddb/mods-enabled/linelog
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "log_accounting" from file /etc/raddb/mods-enabled/linelog
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "logintime" from file /etc/raddb/mods-enabled/logintime
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "mschap" from file /etc/raddb/mods-enabled/mschap
Fri Sep 28 14:54:29 2018 : Debug: rlm_mschap (mschap): using internal authentication
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "pap" from file /etc/raddb/mods-enabled/pap
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "etc_passwd" from file /etc/raddb/mods-enabled/passwd
Fri Sep 28 14:54:29 2018 : Debug: rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "preprocess" from file /etc/raddb/mods-enabled/preprocess
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/mods-config/preprocess/huntgroups
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/mods-config/preprocess/hints
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "IPASS" from file /etc/raddb/mods-enabled/realm
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "suffix" from file /etc/raddb/mods-enabled/realm
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "realmpercent" from file /etc/raddb/mods-enabled/realm
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "ntdomain" from file /etc/raddb/mods-enabled/realm
Fri Sep 28 14:54:29 2018 : Debug:   # Instantiating module "authorized_macs" from file /etc/raddb/mods-enabled/authorized_macs
Fri Sep 28 14:54:29 2018 : Debug: reading pairlist file /etc/raddb/authorized_macs
Fri Sep 28 14:54:29 2018 : Debug:  } # modules
Fri Sep 28 14:54:29 2018 : Debug: radiusd: #### Loading Virtual Servers ####
Fri Sep 28 14:54:29 2018 : Debug: server { # from file /etc/raddb/radiusd.conf
Fri Sep 28 14:54:29 2018 : Debug: } # server
Fri Sep 28 14:54:29 2018 : Debug: server default { # from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:29 2018 : Debug:  # Loading authenticate {...}
Fri Sep 28 14:54:29 2018 : Debug:   mschap
Fri Sep 28 14:54:29 2018 : Debug:   digest
Fri Sep 28 14:54:29 2018 : Debug:   eap
Fri Sep 28 14:54:29 2018 : Debug:  # Loading authorize {...}
Fri Sep 28 14:54:29 2018 : Debug:   policy filter_username {
Fri Sep 28 14:54:29 2018 : Debug:    if (&User-Name) {
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ / /) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: User-Name contains whitespace'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ /@[^@]*@/) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: Multiple @ in User-Name'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ /\.\./) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ /\.$/) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: Realm ends with a dot'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ /@\./) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: Realm begins with a dot'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   preprocess
Fri Sep 28 14:54:29 2018 : Debug:   chap
Fri Sep 28 14:54:29 2018 : Debug:   mschap
Fri Sep 28 14:54:29 2018 : Debug:   digest
Fri Sep 28 14:54:29 2018 : Debug:   suffix
Fri Sep 28 14:54:29 2018 : Debug:   eap
Fri Sep 28 14:54:29 2018 : Debug:   files
Fri Sep 28 14:54:29 2018 : Warning: Ignoring "sql" (see raddb/mods-available/README.rst)
Fri Sep 28 14:54:29 2018 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst)
Fri Sep 28 14:54:29 2018 : Debug:   expiration
Fri Sep 28 14:54:29 2018 : Debug:   logintime
Fri Sep 28 14:54:29 2018 : Debug:   pap
Fri Sep 28 14:54:29 2018 : Debug:  # Loading preacct {...}
Fri Sep 28 14:54:29 2018 : Debug:   preprocess
Fri Sep 28 14:54:29 2018 : Debug:   policy acct_unique {
Fri Sep 28 14:54:29 2018 : Debug:    update {
Fri Sep 28 14:54:29 2018 : Debug:     &Tmp-String-9 := "ai:"
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:    if ("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/ && "%{string:&Class}" =~ /^ai:([0-9a-f]{32})/) {
Fri Sep 28 14:54:29 2018 : Debug:     update {
Fri Sep 28 14:54:29 2018 : Debug:      &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}"
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:    else {
Fri Sep 28 14:54:29 2018 : Debug:     update {
Fri Sep 28 14:54:29 2018 : Debug:      &Acct-Unique-Session-Id := "%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}"
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   suffix
Fri Sep 28 14:54:29 2018 : Debug:   files
Fri Sep 28 14:54:29 2018 : Debug:  # Loading accounting {...}
Fri Sep 28 14:54:29 2018 : Debug:   detail
Fri Sep 28 14:54:29 2018 : Debug:   unix
Fri Sep 28 14:54:29 2018 : Debug:   exec
Fri Sep 28 14:54:29 2018 : Debug:   attr_filter.accounting_response
Fri Sep 28 14:54:29 2018 : Debug:  # Loading post-proxy {...}
Fri Sep 28 14:54:29 2018 : Debug:   eap
Fri Sep 28 14:54:29 2018 : Debug:  # Loading post-auth {...}
Fri Sep 28 14:54:29 2018 : Debug:   update {
Fri Sep 28 14:54:29 2018 : Debug:    &reply:[*] += &session-state:[*]
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   exec
Fri Sep 28 14:54:29 2018 : Debug:   policy remove_reply_message_if_eap {
Fri Sep 28 14:54:29 2018 : Debug:    if (&reply:EAP-Message && &reply:Reply-Message) {
Fri Sep 28 14:54:29 2018 : Debug:     update {
Fri Sep 28 14:54:29 2018 : Debug:      &reply:Reply-Message !* ANY
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:    else {
Fri Sep 28 14:54:29 2018 : Debug:     noop
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: } # server default
Fri Sep 28 14:54:29 2018 : Debug: server inner-tunnel { # from file /etc/raddb/sites-enabled/inner-tunnel
Fri Sep 28 14:54:29 2018 : Debug:  # Loading authenticate {...}
Fri Sep 28 14:54:29 2018 : Debug:   mschap
Fri Sep 28 14:54:29 2018 : Debug:   eap
Fri Sep 28 14:54:29 2018 : Debug:  # Loading authorize {...}
Fri Sep 28 14:54:29 2018 : Debug:   policy filter_username {
Fri Sep 28 14:54:29 2018 : Debug:    if (&User-Name) {
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ / /) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: User-Name contains whitespace'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ /@[^@]*@/) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: Multiple @ in User-Name'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ /\.\./) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ /\.$/) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: Realm ends with a dot'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:     if (&User-Name =~ /@\./) {
Fri Sep 28 14:54:29 2018 : Debug:      update {
Fri Sep 28 14:54:29 2018 : Debug:       &Module-Failure-Message += 'Rejected: Realm begins with a dot'
Fri Sep 28 14:54:29 2018 : Debug:      }
Fri Sep 28 14:54:29 2018 : Debug:      reject
Fri Sep 28 14:54:29 2018 : Debug:     }
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   chap
Fri Sep 28 14:54:29 2018 : Debug:   mschap
Fri Sep 28 14:54:29 2018 : Debug:   suffix
Fri Sep 28 14:54:29 2018 : Debug:   update {
Fri Sep 28 14:54:29 2018 : Debug:    &control:Proxy-To-Realm := LOCAL
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug:   eap
Fri Sep 28 14:54:29 2018 : Debug:   files
Fri Sep 28 14:54:29 2018 : Debug:   expiration
Fri Sep 28 14:54:29 2018 : Debug:   logintime
Fri Sep 28 14:54:29 2018 : Debug:   pap
Fri Sep 28 14:54:29 2018 : Debug:  # Loading session {...}
Fri Sep 28 14:54:29 2018 : Debug:   radutmp
Fri Sep 28 14:54:29 2018 : Debug:  # Loading post-proxy {...}
Fri Sep 28 14:54:29 2018 : Debug:   eap
Fri Sep 28 14:54:29 2018 : Debug:  # Loading post-auth {...}
Fri Sep 28 14:54:29 2018 : Info:  # Skipping contents of 'if' as it is always 'false' -- /etc/raddb/sites-enabled/inner-tunnel:331
Fri Sep 28 14:54:29 2018 : Debug:   if (false) {
Fri Sep 28 14:54:29 2018 : Debug:   }
Fri Sep 28 14:54:29 2018 : Debug: } # server inner-tunnel
Fri Sep 28 14:54:29 2018 : Debug: radiusd: #### Opening IP addresses and Ports ####
Fri Sep 28 14:54:29 2018 : Debug: listen {
Fri Sep 28 14:54:29 2018 : Debug:   type = "control"
Fri Sep 28 14:54:29 2018 : Debug:  listen {
Fri Sep 28 14:54:29 2018 : Debug:   socket = "/usr/local/var/run/radiusd/radiusd.sock"
Fri Sep 28 14:54:29 2018 : Debug:   mode = "rw"
Fri Sep 28 14:54:29 2018 : Debug:   peercred = yes
Fri Sep 28 14:54:29 2018 : Debug:  }
Fri Sep 28 14:54:29 2018 : Debug: }
Fri Sep 28 14:54:29 2018 : Debug: listen {
Fri Sep 28 14:54:29 2018 : Debug:    type = "auth"
Fri Sep 28 14:54:29 2018 : Debug:    ipaddr = *
Fri Sep 28 14:54:29 2018 : Debug:    port = 0
Fri Sep 28 14:54:29 2018 : Debug:    limit {
Fri Sep 28 14:54:29 2018 : Debug:     max_connections = 16
Fri Sep 28 14:54:29 2018 : Debug:     lifetime = 0
Fri Sep 28 14:54:29 2018 : Debug:     idle_timeout = 30
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug: }
Fri Sep 28 14:54:29 2018 : Debug: listen {
Fri Sep 28 14:54:29 2018 : Debug:    type = "acct"
Fri Sep 28 14:54:29 2018 : Debug:    ipaddr = *
Fri Sep 28 14:54:29 2018 : Debug:    port = 0
Fri Sep 28 14:54:29 2018 : Debug:    limit {
Fri Sep 28 14:54:29 2018 : Debug:     max_connections = 16
Fri Sep 28 14:54:29 2018 : Debug:     lifetime = 0
Fri Sep 28 14:54:29 2018 : Debug:     idle_timeout = 30
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug: }
Fri Sep 28 14:54:29 2018 : Debug: listen {
Fri Sep 28 14:54:29 2018 : Debug:    type = "auth"
Fri Sep 28 14:54:29 2018 : Debug:    ipv6addr = ::
Fri Sep 28 14:54:29 2018 : Debug:    port = 0
Fri Sep 28 14:54:29 2018 : Debug:    limit {
Fri Sep 28 14:54:29 2018 : Debug:     max_connections = 16
Fri Sep 28 14:54:29 2018 : Debug:     lifetime = 0
Fri Sep 28 14:54:29 2018 : Debug:     idle_timeout = 30
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug: }
Fri Sep 28 14:54:29 2018 : Debug: listen {
Fri Sep 28 14:54:29 2018 : Debug:    type = "acct"
Fri Sep 28 14:54:29 2018 : Debug:    ipv6addr = ::
Fri Sep 28 14:54:29 2018 : Debug:    port = 0
Fri Sep 28 14:54:29 2018 : Debug:    limit {
Fri Sep 28 14:54:29 2018 : Debug:     max_connections = 16
Fri Sep 28 14:54:29 2018 : Debug:     lifetime = 0
Fri Sep 28 14:54:29 2018 : Debug:     idle_timeout = 30
Fri Sep 28 14:54:29 2018 : Debug:    }
Fri Sep 28 14:54:29 2018 : Debug: }
Fri Sep 28 14:54:29 2018 : Debug: listen {
Fri Sep 28 14:54:29 2018 : Debug:    type = "auth"
Fri Sep 28 14:54:29 2018 : Debug:    ipaddr = 127.0.0.1
Fri Sep 28 14:54:29 2018 : Debug:    port = 18120
Fri Sep 28 14:54:29 2018 : Debug: }
Fri Sep 28 14:54:29 2018 : Debug: Listening on command file /usr/local/var/run/radiusd/radiusd.sock
Fri Sep 28 14:54:29 2018 : Debug: Listening on auth address * port 1812 bound to server default
Fri Sep 28 14:54:29 2018 : Debug: Listening on acct address * port 1813 bound to server default
Fri Sep 28 14:54:29 2018 : Debug: Listening on auth address :: port 1812 bound to server default
Fri Sep 28 14:54:29 2018 : Debug: Listening on acct address :: port 1813 bound to server default
Fri Sep 28 14:54:29 2018 : Debug: Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel
Fri Sep 28 14:54:29 2018 : Debug: Opened new proxy socket 'proxy address * port 51723'
Fri Sep 28 14:54:29 2018 : Debug: Listening on proxy address * port 51723
Fri Sep 28 14:54:29 2018 : Debug: Opened new proxy socket 'proxy address :: port 59994'
Fri Sep 28 14:54:29 2018 : Debug: Listening on proxy address :: port 59994
Fri Sep 28 14:54:29 2018 : Info: Ready to process requests
Fri Sep 28 14:54:44 2018 : Debug: (0) Received Access-Request Id 157 from 172.28.14.103:58252 to 10.24.28.195:1812 length 138
Fri Sep 28 14:54:44 2018 : Debug: (0)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (0)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (0)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (0)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (0)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (0)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (0)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (0)   EAP-Message = 0x0201000b016865696b6b69
Fri Sep 28 14:54:44 2018 : Debug: (0)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (0)   Message-Authenticator = 0xff1e07248065e28bb88c59058e3270c4
Fri Sep 28 14:54:44 2018 : Debug: (0) session-state: No State attribute
Fri Sep 28 14:54:44 2018 : Debug: (0) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (0)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (0)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (0)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (0)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (0)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (0)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (0)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (0)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (0)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (0)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (0)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (0)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (0)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (0)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (0)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (0)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (0)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (0)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (0)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (0)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (0)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (0)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (0)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (0) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (0) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (0) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (0)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (0) eap: Peer sent EAP Response (code 2) ID 1 length 11
Fri Sep 28 14:54:44 2018 : Debug: (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (0)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (0)   } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (0) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (0) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (0)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (0) eap: Peer sent packet with method EAP Identity (1)
Fri Sep 28 14:54:44 2018 : Debug: (0) eap: Calling submodule eap_md5 to process data
Fri Sep 28 14:54:44 2018 : Debug: (0) eap_md5: Issuing MD5 Challenge
Fri Sep 28 14:54:44 2018 : Debug: (0) eap: Sending EAP Request (code 1) ID 2 length 22
Fri Sep 28 14:54:44 2018 : Debug: (0) eap: EAP session adding &reply:State = 0x5d1f0a7f5d1d0e6e
Fri Sep 28 14:54:44 2018 : Debug: (0)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (0)     [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (0)   } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (0) Using Post-Auth-Type Challenge
Fri Sep 28 14:54:44 2018 : Debug: (0) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (0)   Challenge { ... } # empty sub-section is ignored
Fri Sep 28 14:54:44 2018 : Debug: (0) session-state: Nothing to cache
Fri Sep 28 14:54:44 2018 : Debug: (0) Sent Access-Challenge Id 157 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (0)   EAP-Message = 0x010200160410d4630744f861c612eb6cdbe8a5698318
Fri Sep 28 14:54:44 2018 : Debug: (0)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (0)   State = 0x5d1f0a7f5d1d0e6e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (0) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:44 2018 : Debug: (1) Received Access-Request Id 158 from 172.28.14.103:58252 to 10.24.28.195:1812 length 151
Fri Sep 28 14:54:44 2018 : Debug: (1)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (1)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (1)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (1)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (1)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (1)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (1)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (1)   State = 0x5d1f0a7f5d1d0e6e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (1)   EAP-Message = 0x020200060319
Fri Sep 28 14:54:44 2018 : Debug: (1)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (1)   Message-Authenticator = 0x21e9f7200a88dce6707dcab169661974
Fri Sep 28 14:54:44 2018 : Debug: (1) session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (1) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (1)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (1)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (1)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (1)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (1)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (1)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (1)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (1)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (1)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (1)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (1)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (1)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (1)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (1)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (1)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (1)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (1)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (1)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (1)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (1) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (1) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (1) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (1) eap: Peer sent EAP Response (code 2) ID 2 length 6
Fri Sep 28 14:54:44 2018 : Debug: (1) eap: No EAP Start, assuming it's an on-going EAP conversation
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [eap] = updated
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: calling files (rlm_files)
Fri Sep 28 14:54:44 2018 : Debug: (1) files: users: Matched entry heikki at line 5
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: returned from files (rlm_files)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [files] = ok
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: calling expiration (rlm_expiration)
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: returned from expiration (rlm_expiration)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [expiration] = noop
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: calling logintime (rlm_logintime)
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: returned from logintime (rlm_logintime)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [logintime] = noop
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: calling pap (rlm_pap)
Fri Sep 28 14:54:44 2018 : WARNING: (1) pap: Auth-Type already set.  Not setting to PAP
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authorize]: returned from pap (rlm_pap)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [pap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (1)   } # authorize = updated
Fri Sep 28 14:54:44 2018 : Debug: (1) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (1) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (1)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (1) eap: Expiring EAP session with state 0x5d1f0a7f5d1d0e6e
Fri Sep 28 14:54:44 2018 : Debug: (1) eap: Finished EAP session with state 0x5d1f0a7f5d1d0e6e
Fri Sep 28 14:54:44 2018 : Debug: (1) eap: Previous EAP request found for state 0x5d1f0a7f5d1d0e6e, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (1) eap: Peer sent packet with method EAP NAK (3)
Fri Sep 28 14:54:44 2018 : Debug: (1) eap: Found mutually acceptable type PEAP (25)
Fri Sep 28 14:54:44 2018 : Debug: (1) eap: Calling submodule eap_peap to process data
Fri Sep 28 14:54:44 2018 : Debug: (1) eap_peap: Initiating new EAP-TLS session
Fri Sep 28 14:54:44 2018 : Debug: (1) eap_peap: [eaptls start] = request
Fri Sep 28 14:54:44 2018 : Debug: (1) eap: Sending EAP Request (code 1) ID 3 length 6
Fri Sep 28 14:54:44 2018 : Debug: (1) eap: EAP session adding &reply:State = 0x5d1f0a7f5c1c136e
Fri Sep 28 14:54:44 2018 : Debug: (1)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (1)     [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (1)   } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (1) Using Post-Auth-Type Challenge
Fri Sep 28 14:54:44 2018 : Debug: (1) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (1)   Challenge { ... } # empty sub-section is ignored
Fri Sep 28 14:54:44 2018 : Debug: (1) session-state: Nothing to cache
Fri Sep 28 14:54:44 2018 : Debug: (1) Sent Access-Challenge Id 158 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (1)   Service-Type = Framed-User
Fri Sep 28 14:54:44 2018 : Debug: (1)   Tunnel-Type = VLAN
Fri Sep 28 14:54:44 2018 : Debug: (1)   Tunnel-Medium-Type = IEEE-802
Fri Sep 28 14:54:44 2018 : Debug: (1)   Tunnel-Private-Group-Id = "100"
Fri Sep 28 14:54:44 2018 : Debug: (1)   EAP-Message = 0x010300061920
Fri Sep 28 14:54:44 2018 : Debug: (1)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (1)   State = 0x5d1f0a7f5c1c136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (1) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:44 2018 : Debug: (2) Received Access-Request Id 159 from 172.28.14.103:58252 to 10.24.28.195:1812 length 442
Fri Sep 28 14:54:44 2018 : Debug: (2)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (2)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (2)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (2)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (2)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (2)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (2)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (2)   State = 0x5d1f0a7f5c1c136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (2)   EAP-Message = 0x0203012719800000011d1603010118010001140303fbfc4846887ef11198f6335f96d16b7c0335e2ab002b3be2dbd3dfa84a53fd000000acc030c02cc028c024c014c00a00a500a300a1009f006b006a0069006800390038003700360088008700860085c032c02ec02ac026c00fc005009d003d003500
Fri Sep 28 14:54:44 2018 : Debug: (2)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (2)   Message-Authenticator = 0xfb588291c073dea17914bcaa9a17543f
Fri Sep 28 14:54:44 2018 : Debug: (2) session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (2) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (2)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (2)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (2)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (2)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (2)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (2)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (2)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (2)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (2)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (2)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (2)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (2)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (2)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (2)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (2)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (2)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (2)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (2)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (2)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (2)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (2)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (2)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (2)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (2) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (2) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (2) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (2)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (2) eap: Peer sent EAP Response (code 2) ID 3 length 295
Fri Sep 28 14:54:44 2018 : Debug: (2) eap: Continuing tunnel setup
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (2)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (2)   } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (2) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (2) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (2)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (2) eap: Expiring EAP session with state 0x5d1f0a7f5c1c136e
Fri Sep 28 14:54:44 2018 : Debug: (2) eap: Finished EAP session with state 0x5d1f0a7f5c1c136e
Fri Sep 28 14:54:44 2018 : Debug: (2) eap: Previous EAP request found for state 0x5d1f0a7f5c1c136e, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (2) eap: Peer sent packet with method EAP PEAP (25)
Fri Sep 28 14:54:44 2018 : Debug: (2) eap: Calling submodule eap_peap to process data
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: Continuing EAP-TLS
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: Peer sent flags --L
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: Peer indicated complete TLS record size will be 285 bytes
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: Got complete TLS record (285 bytes)
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: [eaptls verify] = length included
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: (other): before/accept initialization
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: TLS_accept: before/accept initialization
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: <<< recv TLS 1.2  [length 0118]
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: TLS_accept: SSLv3 read client hello A
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: >>> send TLS 1.2  [length 003e]
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: TLS_accept: SSLv3 write server hello A
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: >>> send TLS 1.2  [length 08d3]
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: TLS_accept: SSLv3 write certificate A
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: >>> send TLS 1.2  [length 014d]
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: TLS_accept: SSLv3 write key exchange A
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: >>> send TLS 1.2  [length 0004]
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: TLS_accept: SSLv3 write server done A
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: TLS_accept: SSLv3 flush data
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: TLS_accept: SSLv3 read client certificate A
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: TLS_accept: Need to read more data: SSLv3 read client key exchange A
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: TLS_accept: Need to read more data: SSLv3 read client key exchange A
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: In SSL Handshake Phase
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: In SSL Accept mode
Fri Sep 28 14:54:44 2018 : Debug: (2) eap_peap: [eaptls process] = handled
Fri Sep 28 14:54:44 2018 : Debug: (2) eap: Sending EAP Request (code 1) ID 4 length 1004
Fri Sep 28 14:54:44 2018 : Debug: (2) eap: EAP session adding &reply:State = 0x5d1f0a7f5f1b136e
Fri Sep 28 14:54:44 2018 : Debug: (2)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (2)     [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (2)   } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (2) Using Post-Auth-Type Challenge
Fri Sep 28 14:54:44 2018 : Debug: (2) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (2)   Challenge { ... } # empty sub-section is ignored
Fri Sep 28 14:54:44 2018 : Debug: (2) session-state: Nothing to cache
Fri Sep 28 14:54:44 2018 : Debug: (2) Sent Access-Challenge Id 159 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (2)   EAP-Message = 0x010403ec19c000000a76160303003e0200003a03037e6ffdf4c26d757b099ea9dc487b268863840b0152866e8238f9efaaa7dadb6900c030000012ff01000100000b000403000102000f00010116030308d30b0008cf0008cc0003de308203da308202c2a003020102020101300d06092a864886f70d01
Fri Sep 28 14:54:44 2018 : Debug: (2)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (2)   State = 0x5d1f0a7f5f1b136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (2) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:44 2018 : Debug: (3) Received Access-Request Id 160 from 172.28.14.103:58252 to 10.24.28.195:1812 length 151
Fri Sep 28 14:54:44 2018 : Debug: (3)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (3)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (3)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (3)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (3)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (3)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (3)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (3)   State = 0x5d1f0a7f5f1b136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (3)   EAP-Message = 0x020400061900
Fri Sep 28 14:54:44 2018 : Debug: (3)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (3)   Message-Authenticator = 0xb6bd586adfda9a8fd6ae8eed592dd622
Fri Sep 28 14:54:44 2018 : Debug: (3) session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (3) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (3)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (3)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (3)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (3)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (3)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (3)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (3)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (3)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (3)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (3)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (3)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (3)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (3)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (3)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (3)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (3)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (3)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (3)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (3)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (3)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (3)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (3)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (3)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (3) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (3) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (3) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (3)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (3) eap: Peer sent EAP Response (code 2) ID 4 length 6
Fri Sep 28 14:54:44 2018 : Debug: (3) eap: Continuing tunnel setup
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (3)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (3)   } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (3) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (3) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (3)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (3) eap: Expiring EAP session with state 0x5d1f0a7f5f1b136e
Fri Sep 28 14:54:44 2018 : Debug: (3) eap: Finished EAP session with state 0x5d1f0a7f5f1b136e
Fri Sep 28 14:54:44 2018 : Debug: (3) eap: Previous EAP request found for state 0x5d1f0a7f5f1b136e, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (3) eap: Peer sent packet with method EAP PEAP (25)
Fri Sep 28 14:54:44 2018 : Debug: (3) eap: Calling submodule eap_peap to process data
Fri Sep 28 14:54:44 2018 : Debug: (3) eap_peap: Continuing EAP-TLS
Fri Sep 28 14:54:44 2018 : Debug: (3) eap_peap: Peer sent flags ---
Fri Sep 28 14:54:44 2018 : Debug: (3) eap_peap: Peer ACKed our handshake fragment
Fri Sep 28 14:54:44 2018 : Debug: (3) eap_peap: [eaptls verify] = request
Fri Sep 28 14:54:44 2018 : Debug: (3) eap_peap: [eaptls process] = handled
Fri Sep 28 14:54:44 2018 : Debug: (3) eap: Sending EAP Request (code 1) ID 5 length 1000
Fri Sep 28 14:54:44 2018 : Debug: (3) eap: EAP session adding &reply:State = 0x5d1f0a7f5e1a136e
Fri Sep 28 14:54:44 2018 : Debug: (3)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (3)     [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (3)   } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (3) Using Post-Auth-Type Challenge
Fri Sep 28 14:54:44 2018 : Debug: (3) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (3)   Challenge { ... } # empty sub-section is ignored
Fri Sep 28 14:54:44 2018 : Debug: (3) session-state: Nothing to cache
Fri Sep 28 14:54:44 2018 : Debug: (3) Sent Access-Challenge Id 160 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (3)   EAP-Message = 0x010503e8194069c19db99c5a8b33c9fdd0a82c423eac9b9379fb1c3fe3c450e70d8f24ba5f16bbb331c0d14c5584fe99511d47ad112c8cbc9ca7d37efc43569ec342d318a9f465a14c6e36d218b9d0fd5edef0960004e8308204e4308203cca003020102020900891c89bca4538a6a300d06092a864886
Fri Sep 28 14:54:44 2018 : Debug: (3)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (3)   State = 0x5d1f0a7f5e1a136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (3) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:44 2018 : Debug: (4) Received Access-Request Id 161 from 172.28.14.103:58252 to 10.24.28.195:1812 length 151
Fri Sep 28 14:54:44 2018 : Debug: (4)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (4)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (4)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (4)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (4)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (4)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (4)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (4)   State = 0x5d1f0a7f5e1a136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (4)   EAP-Message = 0x020500061900
Fri Sep 28 14:54:44 2018 : Debug: (4)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (4)   Message-Authenticator = 0x0ee3aba4d58ee71087ce76910700ff77
Fri Sep 28 14:54:44 2018 : Debug: (4) session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (4) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (4)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (4)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (4)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (4)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (4)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (4)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (4)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (4)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (4)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (4)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (4)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (4)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (4)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (4)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (4)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (4)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (4)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (4)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (4)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (4)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (4)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (4)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (4)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (4) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (4) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (4) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (4)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (4) eap: Peer sent EAP Response (code 2) ID 5 length 6
Fri Sep 28 14:54:44 2018 : Debug: (4) eap: Continuing tunnel setup
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (4)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (4)   } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (4) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (4) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (4)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (4) eap: Expiring EAP session with state 0x5d1f0a7f5e1a136e
Fri Sep 28 14:54:44 2018 : Debug: (4) eap: Finished EAP session with state 0x5d1f0a7f5e1a136e
Fri Sep 28 14:54:44 2018 : Debug: (4) eap: Previous EAP request found for state 0x5d1f0a7f5e1a136e, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (4) eap: Peer sent packet with method EAP PEAP (25)
Fri Sep 28 14:54:44 2018 : Debug: (4) eap: Calling submodule eap_peap to process data
Fri Sep 28 14:54:44 2018 : Debug: (4) eap_peap: Continuing EAP-TLS
Fri Sep 28 14:54:44 2018 : Debug: (4) eap_peap: Peer sent flags ---
Fri Sep 28 14:54:44 2018 : Debug: (4) eap_peap: Peer ACKed our handshake fragment
Fri Sep 28 14:54:44 2018 : Debug: (4) eap_peap: [eaptls verify] = request
Fri Sep 28 14:54:44 2018 : Debug: (4) eap_peap: [eaptls process] = handled
Fri Sep 28 14:54:44 2018 : Debug: (4) eap: Sending EAP Request (code 1) ID 6 length 696
Fri Sep 28 14:54:44 2018 : Debug: (4) eap: EAP session adding &reply:State = 0x5d1f0a7f5919136e
Fri Sep 28 14:54:44 2018 : Debug: (4)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (4)     [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (4)   } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (4) Using Post-Auth-Type Challenge
Fri Sep 28 14:54:44 2018 : Debug: (4) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (4)   Challenge { ... } # empty sub-section is ignored
Fri Sep 28 14:54:44 2018 : Debug: (4) session-state: Nothing to cache
Fri Sep 28 14:54:44 2018 : Debug: (4) Sent Access-Challenge Id 161 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (4)   EAP-Message = 0x010602b81900130101ff040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e6f72672f6578616d706c655f63612e63726c300d06092a864886f70d01010b0500038201010006479acad62f998dedbeaeee779f83c28e772ee358e361026e83
Fri Sep 28 14:54:44 2018 : Debug: (4)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (4)   State = 0x5d1f0a7f5919136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (4) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:44 2018 : Debug: (5) Received Access-Request Id 162 from 172.28.14.103:58252 to 10.24.28.195:1812 length 281
Fri Sep 28 14:54:44 2018 : Debug: (5)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (5)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (5)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (5)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (5)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (5)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (5)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (5)   State = 0x5d1f0a7f5919136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (5)   EAP-Message = 0x0206008819800000007e1603030046100000424104776f30418b22245e9d4a2a02b22ad787e5b818ea6de963071adea11ecc76e8fbe7bc12b9ceae9f1257642c73c32a30c0db42267d8ae8a471e231681b58a359dd1403030001011603030028f53b29a854334c4727a5b4dd46ad256af5bd35e8b2da62
Fri Sep 28 14:54:44 2018 : Debug: (5)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (5)   Message-Authenticator = 0x7526d12a099b2a802446b55cedb91da1
Fri Sep 28 14:54:44 2018 : Debug: (5) session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (5) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (5)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (5)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (5)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (5)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (5)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (5)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (5)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (5)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (5)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (5)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (5)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (5)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (5)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (5)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (5)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (5)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (5)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (5)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (5)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (5)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (5)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (5)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (5)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (5) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (5) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (5) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (5)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (5) eap: Peer sent EAP Response (code 2) ID 6 length 136
Fri Sep 28 14:54:44 2018 : Debug: (5) eap: Continuing tunnel setup
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (5)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (5)   } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (5) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (5) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (5)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (5) eap: Expiring EAP session with state 0x5d1f0a7f5919136e
Fri Sep 28 14:54:44 2018 : Debug: (5) eap: Finished EAP session with state 0x5d1f0a7f5919136e
Fri Sep 28 14:54:44 2018 : Debug: (5) eap: Previous EAP request found for state 0x5d1f0a7f5919136e, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (5) eap: Peer sent packet with method EAP PEAP (25)
Fri Sep 28 14:54:44 2018 : Debug: (5) eap: Calling submodule eap_peap to process data
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: Continuing EAP-TLS
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: Peer sent flags --L
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: Peer indicated complete TLS record size will be 126 bytes
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: Got complete TLS record (126 bytes)
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: [eaptls verify] = length included
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: <<< recv TLS 1.2  [length 0046]
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: TLS_accept: SSLv3 read client key exchange A
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: TLS_accept: SSLv3 read certificate verify A
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: <<< recv TLS 1.2  [length 0001]
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: <<< recv TLS 1.2  [length 0010]
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: TLS_accept: SSLv3 read finished A
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: >>> send TLS 1.2  [length 0001]
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: TLS_accept: SSLv3 write change cipher spec A
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: >>> send TLS 1.2  [length 0010]
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: TLS_accept: SSLv3 write finished A
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: TLS_accept: SSLv3 flush data
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: (other): SSL negotiation finished successfully
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: SSL Connection Established
Fri Sep 28 14:54:44 2018 : Debug: (5) eap_peap: [eaptls process] = handled
Fri Sep 28 14:54:44 2018 : Debug: (5) eap: Sending EAP Request (code 1) ID 7 length 57
Fri Sep 28 14:54:44 2018 : Debug: (5) eap: EAP session adding &reply:State = 0x5d1f0a7f5818136e
Fri Sep 28 14:54:44 2018 : Debug: (5)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (5)     [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (5)   } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (5) Using Post-Auth-Type Challenge
Fri Sep 28 14:54:44 2018 : Debug: (5) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (5)   Challenge { ... } # empty sub-section is ignored
Fri Sep 28 14:54:44 2018 : Debug: (5) session-state: Nothing to cache
Fri Sep 28 14:54:44 2018 : Debug: (5) Sent Access-Challenge Id 162 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (5)   EAP-Message = 0x0107003919001403030001011603030028b46fd099b9fcfdcf507db4b0df20a6ac62b0c29b026fb14a4433c00952aba721918cee3d660f43e0
Fri Sep 28 14:54:44 2018 : Debug: (5)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (5)   State = 0x5d1f0a7f5818136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (5) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:44 2018 : Debug: (6) Received Access-Request Id 163 from 172.28.14.103:58252 to 10.24.28.195:1812 length 151
Fri Sep 28 14:54:44 2018 : Debug: (6)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (6)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (6)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (6)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (6)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (6)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (6)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (6)   State = 0x5d1f0a7f5818136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (6)   EAP-Message = 0x020700061900
Fri Sep 28 14:54:44 2018 : Debug: (6)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (6)   Message-Authenticator = 0x57ad97e07e9c3f202609dc78b4fb76ed
Fri Sep 28 14:54:44 2018 : Debug: (6) session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (6) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (6)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (6)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (6)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (6)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (6)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (6)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (6)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (6)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (6)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (6)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (6)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (6)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (6)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (6)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (6)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (6)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (6)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (6)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (6)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (6)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (6)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (6)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (6)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (6) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (6) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (6) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (6)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (6) eap: Peer sent EAP Response (code 2) ID 7 length 6
Fri Sep 28 14:54:44 2018 : Debug: (6) eap: Continuing tunnel setup
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (6)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (6)   } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (6) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (6) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (6)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (6) eap: Expiring EAP session with state 0x5d1f0a7f5818136e
Fri Sep 28 14:54:44 2018 : Debug: (6) eap: Finished EAP session with state 0x5d1f0a7f5818136e
Fri Sep 28 14:54:44 2018 : Debug: (6) eap: Previous EAP request found for state 0x5d1f0a7f5818136e, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (6) eap: Peer sent packet with method EAP PEAP (25)
Fri Sep 28 14:54:44 2018 : Debug: (6) eap: Calling submodule eap_peap to process data
Fri Sep 28 14:54:44 2018 : Debug: (6) eap_peap: Continuing EAP-TLS
Fri Sep 28 14:54:44 2018 : Debug: (6) eap_peap: Peer sent flags ---
Fri Sep 28 14:54:44 2018 : Debug: (6) eap_peap: Peer ACKed our handshake fragment.  handshake is finished
Fri Sep 28 14:54:44 2018 : Debug: (6) eap_peap: [eaptls verify] = success
Fri Sep 28 14:54:44 2018 : Debug: (6) eap_peap: [eaptls process] = success
Fri Sep 28 14:54:44 2018 : Debug: (6) eap_peap: Session established.  Decoding tunneled attributes
Fri Sep 28 14:54:44 2018 : Debug: (6) eap_peap: PEAP state TUNNEL ESTABLISHED
Fri Sep 28 14:54:44 2018 : Debug: (6) eap: Sending EAP Request (code 1) ID 8 length 40
Fri Sep 28 14:54:44 2018 : Debug: (6) eap: EAP session adding &reply:State = 0x5d1f0a7f5b17136e
Fri Sep 28 14:54:44 2018 : Debug: (6)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (6)     [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (6)   } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (6) Using Post-Auth-Type Challenge
Fri Sep 28 14:54:44 2018 : Debug: (6) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (6)   Challenge { ... } # empty sub-section is ignored
Fri Sep 28 14:54:44 2018 : Debug: (6) session-state: Nothing to cache
Fri Sep 28 14:54:44 2018 : Debug: (6) Sent Access-Challenge Id 163 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (6)   EAP-Message = 0x010800281900170303001db46fd099b9fcfdd0fd97480cd431c1bd90cec5258369b3de272234f6d0
Fri Sep 28 14:54:44 2018 : Debug: (6)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (6)   State = 0x5d1f0a7f5b17136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (6) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:44 2018 : Debug: (7) Received Access-Request Id 164 from 172.28.14.103:58252 to 10.24.28.195:1812 length 187
Fri Sep 28 14:54:44 2018 : Debug: (7)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (7)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (7)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (7)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (7)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (7)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (7)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (7)   State = 0x5d1f0a7f5b17136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (7)   EAP-Message = 0x0208002a1900170303001ff53b29a854334c48df750569835e4f565218fb68b97a32ad05858e561374f1
Fri Sep 28 14:54:44 2018 : Debug: (7)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (7)   Message-Authenticator = 0x50fd83391549d3d2d8aa9d1c5ed40618
Fri Sep 28 14:54:44 2018 : Debug: (7) session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (7) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (7)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (7)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (7)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (7)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (7)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (7)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (7)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (7)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (7)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (7)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (7)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (7) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (7) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (7) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (7)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Peer sent EAP Response (code 2) ID 8 length 42
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Continuing tunnel setup
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (7)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (7)   } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (7) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (7) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (7)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Expiring EAP session with state 0x5d1f0a7f5b17136e
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Finished EAP session with state 0x5d1f0a7f5b17136e
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Previous EAP request found for state 0x5d1f0a7f5b17136e, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Peer sent packet with method EAP PEAP (25)
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Calling submodule eap_peap to process data
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Continuing EAP-TLS
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Peer sent flags ---
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: [eaptls verify] = ok
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Done initial handshake
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: [eaptls process] = ok
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Session established.  Decoding tunneled attributes
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: PEAP state WAITING FOR INNER IDENTITY
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Identity - heikki
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Got inner identity 'heikki'
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Setting default EAP type for tunneled EAP session
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Got tunneled request
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap:   EAP-Message = 0x0208000b016865696b6b69
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Setting User-Name to heikki
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Sending tunneled request to inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap:   EAP-Message = 0x0208000b016865696b6b69
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap:   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap:   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (7) Virtual server inner-tunnel received request
Fri Sep 28 14:54:44 2018 : Debug: (7)   EAP-Message = 0x0208000b016865696b6b69
Fri Sep 28 14:54:44 2018 : Debug: (7)   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Sep 28 14:54:44 2018 : Debug: (7)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : WARNING: (7) Outer and inner identities are the same.  User privacy is compromised.
Fri Sep 28 14:54:44 2018 : Debug: (7) server inner-tunnel {
Fri Sep 28 14:54:44 2018 : Debug: (7)   session-state: No State attribute
Fri Sep 28 14:54:44 2018 : Debug: (7)   # Executing section authorize from file /etc/raddb/sites-enabled/inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (7)     authorize {
Fri Sep 28 14:54:44 2018 : Debug: (7)       policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (7)         if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (7)           if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (7)           if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)           if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (7)           if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)           if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (7)           if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (7)           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)           if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (7)           if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)           if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (7)           if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (7)         } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (7)       } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (7)       modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (7)       modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (7)       [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (7)       modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (7)       modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (7)       [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (7)       modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (7) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (7) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (7) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (7)       modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (7)       [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (7)       update control {
Fri Sep 28 14:54:44 2018 : Debug: (7)         &Proxy-To-Realm := LOCAL
Fri Sep 28 14:54:44 2018 : Debug: (7)       } # update control = noop
Fri Sep 28 14:54:44 2018 : Debug: (7)       modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Peer sent EAP Response (code 2) ID 8 length 11
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Fri Sep 28 14:54:44 2018 : Debug: (7)       modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (7)       [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (7)     } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (7)   Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (7)   # Executing group from file /etc/raddb/sites-enabled/inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (7)     authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (7)       modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Peer sent packet with method EAP Identity (1)
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Calling submodule eap_mschapv2 to process data
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_mschapv2: Issuing Challenge
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Sending EAP Request (code 1) ID 9 length 43
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: EAP session adding &reply:State = 0x5a15b9d95a1ca3e4
Fri Sep 28 14:54:44 2018 : Debug: (7)       modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (7)       [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (7)     } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (7) } # server inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (7) Virtual server sending reply
Fri Sep 28 14:54:44 2018 : Debug: (7)   EAP-Message = 0x0109002b1a01090026105b4ca3d5d977c489ac99bf520a695396667265657261646975732d332e302e3137
Fri Sep 28 14:54:44 2018 : Debug: (7)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (7)   State = 0x5a15b9d95a1ca3e4adf1c540016bea60
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Got tunneled reply code 11
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap:   EAP-Message = 0x0109002b1a01090026105b4ca3d5d977c489ac99bf520a695396667265657261646975732d332e302e3137
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap:   State = 0x5a15b9d95a1ca3e4adf1c540016bea60
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Got tunneled reply RADIUS code 11
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap:   EAP-Message = 0x0109002b1a01090026105b4ca3d5d977c489ac99bf520a695396667265657261646975732d332e302e3137
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap:   State = 0x5a15b9d95a1ca3e4adf1c540016bea60
Fri Sep 28 14:54:44 2018 : Debug: (7) eap_peap: Got tunneled Access-Challenge
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: Sending EAP Request (code 1) ID 9 length 74
Fri Sep 28 14:54:44 2018 : Debug: (7) eap: EAP session adding &reply:State = 0x5d1f0a7f5a16136e
Fri Sep 28 14:54:44 2018 : Debug: (7)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (7)     [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (7)   } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (7) Using Post-Auth-Type Challenge
Fri Sep 28 14:54:44 2018 : Debug: (7) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (7)   Challenge { ... } # empty sub-section is ignored
Fri Sep 28 14:54:44 2018 : Debug: (7) session-state: Nothing to cache
Fri Sep 28 14:54:44 2018 : Debug: (7) Sent Access-Challenge Id 164 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (7)   EAP-Message = 0x0109004a1900170303003fb46fd099b9fcfdd1257a3ab418e98a0e7303f784938dbc3ffb458f35a7518133e398fa1f63cbf0968a84362902a50b5cbb05e1f02ee3056ec658ca104b549a
Fri Sep 28 14:54:44 2018 : Debug: (7)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (7)   State = 0x5d1f0a7f5a16136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (7) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:44 2018 : Debug: (8) Received Access-Request Id 165 from 172.28.14.103:58252 to 10.24.28.195:1812 length 241
Fri Sep 28 14:54:44 2018 : Debug: (8)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (8)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (8)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (8)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (8)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (8)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (8)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (8)   State = 0x5d1f0a7f5a16136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (8)   EAP-Message = 0x0209006019001703030055f53b29a854334c49fc392f361f99acaa1c6a395499719cdb20bb18ff725957495ed0d54aa69ebd057ecfedb78105b20e007bf4c3c0b0b45099afca953d200880ce4a15931e08790b75937bfda39b3894aaf9150c2a
Fri Sep 28 14:54:44 2018 : Debug: (8)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (8)   Message-Authenticator = 0xb3fdd34a06693e01f1929dad6fe478f1
Fri Sep 28 14:54:44 2018 : Debug: (8) session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (8) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (8)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (8)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (8)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (8)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (8)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (8)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (8)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (8)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (8)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (8)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (8)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (8) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (8) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (8) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (8)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Peer sent EAP Response (code 2) ID 9 length 96
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Continuing tunnel setup
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (8)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (8)   } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (8) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (8) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (8)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Expiring EAP session with state 0x5a15b9d95a1ca3e4
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Finished EAP session with state 0x5d1f0a7f5a16136e
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Previous EAP request found for state 0x5d1f0a7f5a16136e, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Peer sent packet with method EAP PEAP (25)
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Calling submodule eap_peap to process data
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: Continuing EAP-TLS
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: Peer sent flags ---
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: [eaptls verify] = ok
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: Done initial handshake
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: [eaptls process] = ok
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: Session established.  Decoding tunneled attributes
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: PEAP state phase2
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: EAP method MSCHAPv2 (26)
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: Got tunneled request
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   EAP-Message = 0x020900411a0209003c31d9b34d854dd21a3dd8ba84bdd4fb81c80000000000000000174b392f74982e9a54306388cd387d4a7f71f656dcde6b31006865696b6b69
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: Setting User-Name to heikki
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: Sending tunneled request to inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   EAP-Message = 0x020900411a0209003c31d9b34d854dd21a3dd8ba84bdd4fb81c80000000000000000174b392f74982e9a54306388cd387d4a7f71f656dcde6b31006865696b6b69
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   State = 0x5a15b9d95a1ca3e4adf1c540016bea60
Fri Sep 28 14:54:44 2018 : Debug: (8) Virtual server inner-tunnel received request
Fri Sep 28 14:54:44 2018 : Debug: (8)   EAP-Message = 0x020900411a0209003c31d9b34d854dd21a3dd8ba84bdd4fb81c80000000000000000174b392f74982e9a54306388cd387d4a7f71f656dcde6b31006865696b6b69
Fri Sep 28 14:54:44 2018 : Debug: (8)   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Sep 28 14:54:44 2018 : Debug: (8)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (8)   State = 0x5a15b9d95a1ca3e4adf1c540016bea60
Fri Sep 28 14:54:44 2018 : WARNING: (8) Outer and inner identities are the same.  User privacy is compromised.
Fri Sep 28 14:54:44 2018 : Debug: (8) server inner-tunnel {
Fri Sep 28 14:54:44 2018 : Debug: (8)   session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (8)   # Executing section authorize from file /etc/raddb/sites-enabled/inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (8)     authorize {
Fri Sep 28 14:54:44 2018 : Debug: (8)       policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (8)         if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (8)           if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (8)           if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)           if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (8)           if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)           if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (8)           if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (8)           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)           if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (8)           if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)           if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (8)           if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (8)         } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (8)       } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (8)       [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (8)       [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (8) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (8) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (8) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (8)       [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)       update control {
Fri Sep 28 14:54:44 2018 : Debug: (8)         &Proxy-To-Realm := LOCAL
Fri Sep 28 14:54:44 2018 : Debug: (8)       } # update control = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Peer sent EAP Response (code 2) ID 9 length 65
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: No EAP Start, assuming it's an on-going EAP conversation
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (8)       [eap] = updated
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: calling files (rlm_files)
Fri Sep 28 14:54:44 2018 : Debug: (8) files: users: Matched entry heikki at line 5
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: returned from files (rlm_files)
Fri Sep 28 14:54:44 2018 : Debug: (8)       [files] = ok
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: calling expiration (rlm_expiration)
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: returned from expiration (rlm_expiration)
Fri Sep 28 14:54:44 2018 : Debug: (8)       [expiration] = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: calling logintime (rlm_logintime)
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: returned from logintime (rlm_logintime)
Fri Sep 28 14:54:44 2018 : Debug: (8)       [logintime] = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: calling pap (rlm_pap)
Fri Sep 28 14:54:44 2018 : WARNING: (8) pap: Auth-Type already set.  Not setting to PAP
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authorize]: returned from pap (rlm_pap)
Fri Sep 28 14:54:44 2018 : Debug: (8)       [pap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (8)     } # authorize = updated
Fri Sep 28 14:54:44 2018 : Debug: (8)   Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (8)   # Executing group from file /etc/raddb/sites-enabled/inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (8)     authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Expiring EAP session with state 0x5a15b9d95a1ca3e4
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Finished EAP session with state 0x5a15b9d95a1ca3e4
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Previous EAP request found for state 0x5a15b9d95a1ca3e4, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Peer sent packet with method EAP MSCHAPv2 (26)
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Calling submodule eap_mschapv2 to process data
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_mschapv2: # Executing group from file /etc/raddb/sites-enabled/inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_mschapv2:   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_mschapv2:     modsingle[authenticate]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (8) mschap: Found Cleartext-Password, hashing to create NT-Password
Fri Sep 28 14:54:44 2018 : Debug: (8) mschap: Found Cleartext-Password, hashing to create LM-Password
Fri Sep 28 14:54:44 2018 : Debug: (8) mschap: Creating challenge hash with username: heikki
Fri Sep 28 14:54:44 2018 : Debug: (8) mschap: Client is using MS-CHAPv2
Fri Sep 28 14:54:44 2018 : Debug: (8) mschap: Adding MS-CHAPv2 MPPE keys
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authenticate]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (8)     [mschap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (8)   } # authenticate = ok
Fri Sep 28 14:54:44 2018 : Debug: (8) MSCHAP Success
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Sending EAP Request (code 1) ID 10 length 51
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: EAP session adding &reply:State = 0x5a15b9d95b1fa3e4
Fri Sep 28 14:54:44 2018 : Debug: (8)       modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (8)       [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (8)     } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (8) } # server inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (8) Virtual server sending reply
Fri Sep 28 14:54:44 2018 : Debug: (8)   Service-Type = Framed-User
Fri Sep 28 14:54:44 2018 : Debug: (8)   Tunnel-Type = VLAN
Fri Sep 28 14:54:44 2018 : Debug: (8)   Tunnel-Medium-Type = IEEE-802
Fri Sep 28 14:54:44 2018 : Debug: (8)   Tunnel-Private-Group-Id = "100"
Fri Sep 28 14:54:44 2018 : Debug: (8)   EAP-Message = 0x010a00331a0309002e533d31464243394539304343324645364438313845303836373531423536323936343844334239423443
Fri Sep 28 14:54:44 2018 : Debug: (8)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (8)   State = 0x5a15b9d95b1fa3e4adf1c540016bea60
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: Got tunneled reply code 11
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   Service-Type = Framed-User
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   Tunnel-Type = VLAN
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   Tunnel-Medium-Type = IEEE-802
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   Tunnel-Private-Group-Id = "100"
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   EAP-Message = 0x010a00331a0309002e533d31464243394539304343324645364438313845303836373531423536323936343844334239423443
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   State = 0x5a15b9d95b1fa3e4adf1c540016bea60
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: Got tunneled reply RADIUS code 11
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   Service-Type = Framed-User
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   Tunnel-Type = VLAN
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   Tunnel-Medium-Type = IEEE-802
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   Tunnel-Private-Group-Id = "100"
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   EAP-Message = 0x010a00331a0309002e533d31464243394539304343324645364438313845303836373531423536323936343844334239423443
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap:   State = 0x5a15b9d95b1fa3e4adf1c540016bea60
Fri Sep 28 14:54:44 2018 : Debug: (8) eap_peap: Got tunneled Access-Challenge
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: Sending EAP Request (code 1) ID 10 length 82
Fri Sep 28 14:54:44 2018 : Debug: (8) eap: EAP session adding &reply:State = 0x5d1f0a7f5515136e
Fri Sep 28 14:54:44 2018 : Debug: (8)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (8)     [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (8)   } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (8) Using Post-Auth-Type Challenge
Fri Sep 28 14:54:44 2018 : Debug: (8) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (8)   Challenge { ... } # empty sub-section is ignored
Fri Sep 28 14:54:44 2018 : Debug: (8) session-state: Nothing to cache
Fri Sep 28 14:54:44 2018 : Debug: (8) Sent Access-Challenge Id 165 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (8)   EAP-Message = 0x010a005219001703030047b46fd099b9fcfdd2d8d379ede6a13fa20734722dde9c70dde6b868a66dc020f29d73e88802144f28020f63f5a7ff5ac13a823c944035ff5fe3856960e76ffec0fcfc5f36c20e1c
Fri Sep 28 14:54:44 2018 : Debug: (8)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (8)   State = 0x5d1f0a7f5515136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (8) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:44 2018 : Debug: (9) Received Access-Request Id 166 from 172.28.14.103:58252 to 10.24.28.195:1812 length 182
Fri Sep 28 14:54:44 2018 : Debug: (9)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (9)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (9)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (9)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (9)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (9)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (9)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (9)   State = 0x5d1f0a7f5515136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (9)   EAP-Message = 0x020a00251900170303001af53b29a854334c4a9c0e1f2bf102e891eb404ebaf50b3dfcdc54
Fri Sep 28 14:54:44 2018 : Debug: (9)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (9)   Message-Authenticator = 0x8a4b2d49cd8447205ae2a2d841b18b33
Fri Sep 28 14:54:44 2018 : Debug: (9) session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (9) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (9)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (9)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (9)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (9)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (9)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (9)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (9)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (9)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (9)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (9)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (9)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (9) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (9) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (9) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (9)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Peer sent EAP Response (code 2) ID 10 length 37
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Continuing tunnel setup
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (9)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (9)   } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (9) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (9) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (9)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Expiring EAP session with state 0x5a15b9d95b1fa3e4
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Finished EAP session with state 0x5d1f0a7f5515136e
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Previous EAP request found for state 0x5d1f0a7f5515136e, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Peer sent packet with method EAP PEAP (25)
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Calling submodule eap_peap to process data
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: Continuing EAP-TLS
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: Peer sent flags ---
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: [eaptls verify] = ok
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: Done initial handshake
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: [eaptls process] = ok
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: Session established.  Decoding tunneled attributes
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: PEAP state phase2
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: EAP method MSCHAPv2 (26)
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: Got tunneled request
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   EAP-Message = 0x020a00061a03
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: Setting User-Name to heikki
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: Sending tunneled request to inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   EAP-Message = 0x020a00061a03
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   State = 0x5a15b9d95b1fa3e4adf1c540016bea60
Fri Sep 28 14:54:44 2018 : Debug: (9) Virtual server inner-tunnel received request
Fri Sep 28 14:54:44 2018 : Debug: (9)   EAP-Message = 0x020a00061a03
Fri Sep 28 14:54:44 2018 : Debug: (9)   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Sep 28 14:54:44 2018 : Debug: (9)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (9)   State = 0x5a15b9d95b1fa3e4adf1c540016bea60
Fri Sep 28 14:54:44 2018 : WARNING: (9) Outer and inner identities are the same.  User privacy is compromised.
Fri Sep 28 14:54:44 2018 : Debug: (9) server inner-tunnel {
Fri Sep 28 14:54:44 2018 : Debug: (9)   session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (9)   # Executing section authorize from file /etc/raddb/sites-enabled/inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (9)     authorize {
Fri Sep 28 14:54:44 2018 : Debug: (9)       policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (9)         if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (9)           if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (9)           if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)           if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (9)           if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)           if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (9)           if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (9)           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)           if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (9)           if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)           if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (9)           if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)         } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (9)       } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (9)       [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (9)       [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (9) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (9) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (9) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (9)       [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)       update control {
Fri Sep 28 14:54:44 2018 : Debug: (9)         &Proxy-To-Realm := LOCAL
Fri Sep 28 14:54:44 2018 : Debug: (9)       } # update control = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Peer sent EAP Response (code 2) ID 10 length 6
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: No EAP Start, assuming it's an on-going EAP conversation
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (9)       [eap] = updated
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: calling files (rlm_files)
Fri Sep 28 14:54:44 2018 : Debug: (9) files: users: Matched entry heikki at line 5
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: returned from files (rlm_files)
Fri Sep 28 14:54:44 2018 : Debug: (9)       [files] = ok
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: calling expiration (rlm_expiration)
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: returned from expiration (rlm_expiration)
Fri Sep 28 14:54:44 2018 : Debug: (9)       [expiration] = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: calling logintime (rlm_logintime)
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: returned from logintime (rlm_logintime)
Fri Sep 28 14:54:44 2018 : Debug: (9)       [logintime] = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: calling pap (rlm_pap)
Fri Sep 28 14:54:44 2018 : WARNING: (9) pap: Auth-Type already set.  Not setting to PAP
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authorize]: returned from pap (rlm_pap)
Fri Sep 28 14:54:44 2018 : Debug: (9)       [pap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (9)     } # authorize = updated
Fri Sep 28 14:54:44 2018 : Debug: (9)   Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (9)   # Executing group from file /etc/raddb/sites-enabled/inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (9)     authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Expiring EAP session with state 0x5a15b9d95b1fa3e4
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Finished EAP session with state 0x5a15b9d95b1fa3e4
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Previous EAP request found for state 0x5a15b9d95b1fa3e4, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Peer sent packet with method EAP MSCHAPv2 (26)
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Calling submodule eap_mschapv2 to process data
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Sending EAP Success (code 3) ID 10 length 4
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Freeing handler
Fri Sep 28 14:54:44 2018 : Debug: (9)       modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (9)       [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (9)     } # authenticate = ok
Fri Sep 28 14:54:44 2018 : Debug: (9)   # Executing section post-auth from file /etc/raddb/sites-enabled/inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (9)     post-auth {
Fri Sep 28 14:54:44 2018 : Debug: (9)       if (0) {
Fri Sep 28 14:54:44 2018 : Debug: (9)       if (0)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (9)     } # post-auth = noop
Fri Sep 28 14:54:44 2018 : Debug: (9) } # server inner-tunnel
Fri Sep 28 14:54:44 2018 : Debug: (9) Virtual server sending reply
Fri Sep 28 14:54:44 2018 : Debug: (9)   Service-Type = Framed-User
Fri Sep 28 14:54:44 2018 : Debug: (9)   Tunnel-Type = VLAN
Fri Sep 28 14:54:44 2018 : Debug: (9)   Tunnel-Medium-Type = IEEE-802
Fri Sep 28 14:54:44 2018 : Debug: (9)   Tunnel-Private-Group-Id = "100"
Fri Sep 28 14:54:44 2018 : Debug: (9)   MS-MPPE-Encryption-Policy = Encryption-Allowed
Fri Sep 28 14:54:44 2018 : Debug: (9)   MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
Fri Sep 28 14:54:44 2018 : Debug: (9)   MS-MPPE-Send-Key = 0x0e7294d7bc1d0832c8395d408c2b06d7
Fri Sep 28 14:54:44 2018 : Debug: (9)   MS-MPPE-Recv-Key = 0xa739952fe203d77268ef3975b66cfa9d
Fri Sep 28 14:54:44 2018 : Debug: (9)   EAP-Message = 0x030a0004
Fri Sep 28 14:54:44 2018 : Debug: (9)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (9)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: Got tunneled reply code 2
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   Service-Type = Framed-User
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   Tunnel-Type = VLAN
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   Tunnel-Medium-Type = IEEE-802
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   Tunnel-Private-Group-Id = "100"
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   MS-MPPE-Encryption-Policy = Encryption-Allowed
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   MS-MPPE-Send-Key = 0x0e7294d7bc1d0832c8395d408c2b06d7
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   MS-MPPE-Recv-Key = 0xa739952fe203d77268ef3975b66cfa9d
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   EAP-Message = 0x030a0004
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: Got tunneled reply RADIUS code 2
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   Service-Type = Framed-User
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   Tunnel-Type = VLAN
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   Tunnel-Medium-Type = IEEE-802
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   Tunnel-Private-Group-Id = "100"
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   MS-MPPE-Encryption-Policy = Encryption-Allowed
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   MS-MPPE-Send-Key = 0x0e7294d7bc1d0832c8395d408c2b06d7
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   MS-MPPE-Recv-Key = 0xa739952fe203d77268ef3975b66cfa9d
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   EAP-Message = 0x030a0004
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap:   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: Tunneled authentication was successful
Fri Sep 28 14:54:44 2018 : Debug: (9) eap_peap: SUCCESS
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: Sending EAP Request (code 1) ID 11 length 46
Fri Sep 28 14:54:44 2018 : Debug: (9) eap: EAP session adding &reply:State = 0x5d1f0a7f5414136e
Fri Sep 28 14:54:44 2018 : Debug: (9)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (9)     [eap] = handled
Fri Sep 28 14:54:44 2018 : Debug: (9)   } # authenticate = handled
Fri Sep 28 14:54:44 2018 : Debug: (9) Using Post-Auth-Type Challenge
Fri Sep 28 14:54:44 2018 : Debug: (9) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (9)   Challenge { ... } # empty sub-section is ignored
Fri Sep 28 14:54:44 2018 : Debug: (9) session-state: Nothing to cache
Fri Sep 28 14:54:44 2018 : Debug: (9) Sent Access-Challenge Id 166 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (9)   EAP-Message = 0x010b002e19001703030023b46fd099b9fcfdd31b275c19a35d89ee60df3195abcfbe0c11d0694bc5d6ec201ec9b6
Fri Sep 28 14:54:44 2018 : Debug: (9)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (9)   State = 0x5d1f0a7f5414136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (9) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:44 2018 : Debug: (10) Received Access-Request Id 167 from 172.28.14.103:58252 to 10.24.28.195:1812 length 191
Fri Sep 28 14:54:44 2018 : Debug: (10)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (10)   Called-Station-Id = "f8:b1:56:32:af:cb"
Fri Sep 28 14:54:44 2018 : Debug: (10)   Calling-Station-Id = "002219670F55"
Fri Sep 28 14:54:44 2018 : Debug: (10)   NAS-Port = 1
Fri Sep 28 14:54:44 2018 : Debug: (10)   NAS-Port-Id = "Gigabitethernet1/0/1"
Fri Sep 28 14:54:44 2018 : Debug: (10)   Framed-MTU = 1500
Fri Sep 28 14:54:44 2018 : Debug: (10)   NAS-Port-Type = Ethernet
Fri Sep 28 14:54:44 2018 : Debug: (10)   State = 0x5d1f0a7f5414136e0b48db2d7353f5d0
Fri Sep 28 14:54:44 2018 : Debug: (10)   EAP-Message = 0x020b002e19001703030023f53b29a854334c4b78ba494f10ef71a4f5f8afbecbc1a5c0e521f7f66f45b4c8137ad7
Fri Sep 28 14:54:44 2018 : Debug: (10)   NAS-IP-Address = 172.28.14.103
Fri Sep 28 14:54:44 2018 : Debug: (10)   Message-Authenticator = 0xe67a8e6e104150a5ccc82ed5af2fea50
Fri Sep 28 14:54:44 2018 : Debug: (10) session-state: No cached attributes
Fri Sep 28 14:54:44 2018 : Debug: (10) # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (10)   authorize {
Fri Sep 28 14:54:44 2018 : Debug: (10)     policy filter_username {
Fri Sep 28 14:54:44 2018 : Debug: (10)       if (&User-Name) {
Fri Sep 28 14:54:44 2018 : Debug: (10)       if (&User-Name)  -> TRUE
Fri Sep 28 14:54:44 2018 : Debug: (10)       if (&User-Name)  {
Fri Sep 28 14:54:44 2018 : Debug: (10)         if (&User-Name =~ / /) {
Fri Sep 28 14:54:44 2018 : Debug: (10)         if (&User-Name =~ / /)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (10)         if (&User-Name =~ /@[^@]*@/ ) {
Fri Sep 28 14:54:44 2018 : Debug: (10)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (10)         if (&User-Name =~ /\.\./ ) {
Fri Sep 28 14:54:44 2018 : Debug: (10)         if (&User-Name =~ /\.\./ )  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (10)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
Fri Sep 28 14:54:44 2018 : Debug: (10)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (10)         if (&User-Name =~ /\.$/)  {
Fri Sep 28 14:54:44 2018 : Debug: (10)         if (&User-Name =~ /\.$/)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (10)         if (&User-Name =~ /@\./)  {
Fri Sep 28 14:54:44 2018 : Debug: (10)         if (&User-Name =~ /@\./)   -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (10)       } # if (&User-Name)  = notfound
Fri Sep 28 14:54:44 2018 : Debug: (10)     } # policy filter_username = notfound
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Fri Sep 28 14:54:44 2018 : Debug: (10)     [preprocess] = ok
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: calling chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: returned from chap (rlm_chap)
Fri Sep 28 14:54:44 2018 : Debug: (10)     [chap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: calling mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: returned from mschap (rlm_mschap)
Fri Sep 28 14:54:44 2018 : Debug: (10)     [mschap] = noop
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: calling digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: returned from digest (rlm_digest)
Fri Sep 28 14:54:44 2018 : Debug: (10)     [digest] = noop
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: calling suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (10) suffix: Checking for suffix after "@"
Fri Sep 28 14:54:44 2018 : Debug: (10) suffix: No '@' in User-Name = "heikki", looking up realm NULL
Fri Sep 28 14:54:44 2018 : Debug: (10) suffix: No such realm "NULL"
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: returned from suffix (rlm_realm)
Fri Sep 28 14:54:44 2018 : Debug: (10)     [suffix] = noop
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (10) eap: Peer sent EAP Response (code 2) ID 11 length 46
Fri Sep 28 14:54:44 2018 : Debug: (10) eap: Continuing tunnel setup
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authorize]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (10)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (10)   } # authorize = ok
Fri Sep 28 14:54:44 2018 : Debug: (10) Found Auth-Type = eap
Fri Sep 28 14:54:44 2018 : Debug: (10) # Executing group from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (10)   authenticate {
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authenticate]: calling eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (10) eap: Expiring EAP session with state 0x5d1f0a7f5414136e
Fri Sep 28 14:54:44 2018 : Debug: (10) eap: Finished EAP session with state 0x5d1f0a7f5414136e
Fri Sep 28 14:54:44 2018 : Debug: (10) eap: Previous EAP request found for state 0x5d1f0a7f5414136e, released from the list
Fri Sep 28 14:54:44 2018 : Debug: (10) eap: Peer sent packet with method EAP PEAP (25)
Fri Sep 28 14:54:44 2018 : Debug: (10) eap: Calling submodule eap_peap to process data
Fri Sep 28 14:54:44 2018 : Debug: (10) eap_peap: Continuing EAP-TLS
Fri Sep 28 14:54:44 2018 : Debug: (10) eap_peap: Peer sent flags ---
Fri Sep 28 14:54:44 2018 : Debug: (10) eap_peap: [eaptls verify] = ok
Fri Sep 28 14:54:44 2018 : Debug: (10) eap_peap: Done initial handshake
Fri Sep 28 14:54:44 2018 : Debug: (10) eap_peap: [eaptls process] = ok
Fri Sep 28 14:54:44 2018 : Debug: (10) eap_peap: Session established.  Decoding tunneled attributes
Fri Sep 28 14:54:44 2018 : Debug: (10) eap_peap: PEAP state send tlv success
Fri Sep 28 14:54:44 2018 : Debug: (10) eap_peap: Received EAP-TLV response
Fri Sep 28 14:54:44 2018 : Debug: (10) eap_peap: Success
Fri Sep 28 14:54:44 2018 : Debug: (10) eap: Sending EAP Success (code 3) ID 11 length 4
Fri Sep 28 14:54:44 2018 : Debug: (10) eap: Freeing handler
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[authenticate]: returned from eap (rlm_eap)
Fri Sep 28 14:54:44 2018 : Debug: (10)     [eap] = ok
Fri Sep 28 14:54:44 2018 : Debug: (10)   } # authenticate = ok
Fri Sep 28 14:54:44 2018 : Debug: (10) # Executing section post-auth from file /etc/raddb/sites-enabled/default
Fri Sep 28 14:54:44 2018 : Debug: (10)   post-auth {
Fri Sep 28 14:54:44 2018 : Debug: (10)     update {
Fri Sep 28 14:54:44 2018 : Debug: (10)       No attributes updated
Fri Sep 28 14:54:44 2018 : Debug: (10)     } # update = noop
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[post-auth]: calling exec (rlm_exec)
Fri Sep 28 14:54:44 2018 : Debug: (10)     modsingle[post-auth]: returned from exec (rlm_exec)
Fri Sep 28 14:54:44 2018 : Debug: (10)     [exec] = noop
Fri Sep 28 14:54:44 2018 : Debug: (10)     policy remove_reply_message_if_eap {
Fri Sep 28 14:54:44 2018 : Debug: (10)       if (&reply:EAP-Message && &reply:Reply-Message) {
Fri Sep 28 14:54:44 2018 : Debug: (10)       if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
Fri Sep 28 14:54:44 2018 : Debug: (10)       else {
Fri Sep 28 14:54:44 2018 : Debug: (10)         modsingle[post-auth]: calling noop (rlm_always)
Fri Sep 28 14:54:44 2018 : Debug: (10)         modsingle[post-auth]: returned from noop (rlm_always)
Fri Sep 28 14:54:44 2018 : Debug: (10)         [noop] = noop
Fri Sep 28 14:54:44 2018 : Debug: (10)       } # else = noop
Fri Sep 28 14:54:44 2018 : Debug: (10)     } # policy remove_reply_message_if_eap = noop
Fri Sep 28 14:54:44 2018 : Debug: (10)   } # post-auth = noop
Fri Sep 28 14:54:44 2018 : Debug: (10) Sent Access-Accept Id 167 from 10.24.28.195:1812 to 172.28.14.103:58252 length 0
Fri Sep 28 14:54:44 2018 : Debug: (10)   MS-MPPE-Recv-Key = 0xffaaaefd3eda2dd4fbc9bf2df8a2697548ba63f8eb4f4f119d2f51be40cd093d
Fri Sep 28 14:54:44 2018 : Debug: (10)   MS-MPPE-Send-Key = 0x0fb34fe01b9d953baf5787a9587b074d9d89c6dd5d8c0ada12fec1147efa412b
Fri Sep 28 14:54:44 2018 : Debug: (10)   EAP-Message = 0x030b0004
Fri Sep 28 14:54:44 2018 : Debug: (10)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Sep 28 14:54:44 2018 : Debug: (10)   User-Name = "heikki"
Fri Sep 28 14:54:44 2018 : Debug: (10) Finished request
Fri Sep 28 14:54:44 2018 : Debug: Waking up in 4.9 seconds.
Fri Sep 28 14:54:49 2018 : Debug: (0) Cleaning up request packet ID 157 with timestamp +15
Fri Sep 28 14:54:49 2018 : Debug: (1) Cleaning up request packet ID 158 with timestamp +15
Fri Sep 28 14:54:49 2018 : Debug: (2) Cleaning up request packet ID 159 with timestamp +15
Fri Sep 28 14:54:49 2018 : Debug: (3) Cleaning up request packet ID 160 with timestamp +15
Fri Sep 28 14:54:49 2018 : Debug: (4) Cleaning up request packet ID 161 with timestamp +15
Fri Sep 28 14:54:49 2018 : Debug: (5) Cleaning up request packet ID 162 with timestamp +15
Fri Sep 28 14:54:49 2018 : Debug: (6) Cleaning up request packet ID 163 with timestamp +15
Fri Sep 28 14:54:49 2018 : Debug: (7) Cleaning up request packet ID 164 with timestamp +15
Fri Sep 28 14:54:49 2018 : Debug: (8) Cleaning up request packet ID 165 with timestamp +15
Fri Sep 28 14:54:49 2018 : Debug: (9) Cleaning up request packet ID 166 with timestamp +15
Fri Sep 28 14:54:49 2018 : Debug: (10) Cleaning up request packet ID 167 with timestamp +15
Fri Sep 28 14:54:49 2018 : Info: Ready to process requests

Kind Regards

Heikki Lavaste