Freeradius-Users
Threads by month
- ----- 2026 -----
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2025 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2024 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2023 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2022 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2021 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2020 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2019 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2018 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2017 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2016 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2015 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2014 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2013 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2012 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2011 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2010 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2009 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2008 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2007 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2006 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2005 -----
- December
- November
- October
- September
- August
- July
- June
- May
- 27050 discussions
Hello,
Is there a way to use more than 1 keytab and SPN in a FreeRADIUS configuration (I mean on the same FreeRADIUS server)?
If so, how to do it?
Thank you.
Ce message contient des informations confidentielles à l'intention exclusive du destinataire. Il ne peut être utilisé, divulgué ou copié de quelconque façon que ce soit par une personne autre que le destinataire désigné. Si vous n'êtes pas le destinataire désigné, merci de contacter l'expéditeur et d'effacer ce message. L'expéditeur de ce message n'est pas mandaté à représenter le Parlement européen. Dès lors, ce message ne constitue pas nécessairement le point de vue officiel du Parlement européen, ni un engagement juridique opposable à ce dernier.
This message contains confidential information intended solely for the attention of the named addressee. It may not be used, disclosed or copied in any way whatsoever by anyone else than the intended addressee. If you are not the intended addressee, please contact the sender and delete this message. The sender of this message is not authorized to represent the European Parliament and therefore this message does not necessarily reflect the official position of the European Parliament and is not legally binding upon it.
2
2
Hello everyone,
I was able to setup the FreeRADIUS server to authorise the user to our
office wireless network.
We have another pop-up office, which is VPN-ed to our main office. All
devices of the both offices are able to see each other.
Main office: 10.11.11.0/24
Pop-up office: 10:23.23.0/24
I create new record in the NAS table, with information pertaining to our
wireless AP at the pop-up office.
I uncomment the NAS in the sql.conf file
I restart the server
I started the server in debug log.
The address 10.23.23.54 is the IP address of the Access Point in the pop-up
office.
The details of the devices I added manually in the NAS table, according to
its fields
ID: 22
Nasname: PopUpOff
Shortname: TestAP
Type: other
Port: 1812
Secret: test123
Server: 10.23.23.54
Community: Null
Description: RADIUS Client
Below is the log file content. I highlight one Error that is failed to
resolve the Nasname PopUpOff to IPv4, etc.... so I changed to the NAS IP
address but that did not work either.
But it keeps saying it is ignoring the auth request... etc...
Do I have to put these in the clients.conf file as well? But that would
defeat the SQL purpose I guess?
Any help would be appreciated
---------------------------------------------------------------------------------------------------
Sat Sep 29 18:06:41 2018 : Info: rlm_sql (sql): Opening additional
connection (31), 1 of 31 pending slots used
Sat Sep 29 18:16:13 2018 : Info: Signalled to terminate
Sat Sep 29 18:16:13 2018 : Info: Exiting normally
Sat Sep 29 18:16:13 2018 : Info: rlm_sql (sql): Closing connection (31)
Sat Sep 29 18:16:13 2018 : Info: rlm_sql (sql): Closing connection (30)
Sat Sep 29 18:34:19 2018 : Info: Debugger not attached
Sat Sep 29 18:34:19 2018 : Info: rlm_sql (sql): Driver rlm_sql_mysql
(module rlm_sql_mysql) loaded and linked
Sat Sep 29 18:34:19 2018 : Warning:
[/etc/freeradius/3.0/mods-config/attr_filter/access_reject]:11 Check item
"FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT".
Sat Sep 29 18:34:19 2018 : Warning:
[/etc/freeradius/3.0/mods-config/attr_filter/access_reject]:11 Check item
"FreeRADIUS-Response-Delay-USec" found in filter list for realm "DEFAULT".
Sat Sep 29 18:34:19 2018 : Info: rlm_sql_mysql: libmysql version: 5.7.23
Sat Sep 29 18:34:19 2018 : Info: rlm_sql (sql): Attempting to connect to
database "radius"
Sat Sep 29 18:34:19 2018 : Info: rlm_sql (sql): Opening additional
connection (0), 1 of 32 pending slots used
Sat Sep 29 18:34:19 2018 : Info: rlm_sql (sql): Opening additional
connection (1), 1 of 31 pending slots used
Sat Sep 29 18:34:19 2018 : Info: rlm_sql (sql): Opening additional
connection (2), 1 of 30 pending slots used
Sat Sep 29 18:34:19 2018 : Info: rlm_sql (sql): Opening additional
connection (3), 1 of 29 pending slots used
Sat Sep 29 18:34:19 2018 : Info: rlm_sql (sql): Opening additional
connection (4), 1 of 28 pending slots used
*Sat Sep 29 18:34:19 2018 : Error: Failed resolving "PopUpOff" to IPv4
address: Name or service not known*
Sat Sep 29 18:34:19 2018 : Info: Need 5 more connections to reach 10 spares
Sat Sep 29 18:34:19 2018 : Info: rlm_sql (sql): Opening additional
connection (5), 1 of 27 pending slots used
Sat Sep 29 18:34:19 2018 : Info: Loaded virtual server <default>
Sat Sep 29 18:34:19 2018 : Warning: Ignoring "ldap" (see
raddb/mods-available/README.rst)
Sat Sep 29 18:34:19 2018 : Info: # Skipping contents of 'if' as it is
always 'false' -- /etc/freeradius/3.0/sites-enabled/inner-tunnel:331
Sat Sep 29 18:34:19 2018 : Info: Loaded virtual server inner-tunnel
Sat Sep 29 18:34:19 2018 : Info: Loaded virtual server default
Sat Sep 29 18:34:19 2018 : Info: Ready to process requests
Sat Sep 29 18:34:29 2018 : Error: Ignoring request to auth address * port
1812 bound to server default from unknown client 10.23.23.54 port 57553
proto udp
Sat Sep 29 18:34:32 2018 : Error: Ignoring request to auth address * port
1812 bound to server default from unknown client 10.23.23.54 port 57553
proto udp
Sat Sep 29 18:34:34 2018 : Error: Ignoring request to auth address * port
1812 bound to server default from unknown client 10.23.23.54 port 57553
proto udp
Sat Sep 29 18:34:37 2018 : Error: Ignoring request to auth address * port
1812 bound to server default from unknown client 10.2.2.54 port 57553 proto
udp
Sat Sep 29 18:34:38 2018 : Error: Ignoring request to auth address * port
1812 bound to server default from unknown client 10.23.23.54 port 57553
proto udp
Sat Sep 29 18:34:42 2018 : Error: Ignoring request to auth address * port
1812 bound to server default from unknown client 10.23.23.54 port 37297
proto udp
Sat Sep 29 18:34:43 2018 : Error: Ignoring request to auth address * port
1812 bound to server default from unknown client 10.23.23.54 port 57553
proto udp
Sat Sep 29 18:34:45 2018 : Error: Ignoring request to auth address * port
1812 bound to server default from unknown client 10.23.23.54 port 37297
proto udp
Sat Sep 29 18:57:29 2018 : Info: Signalled to terminate
Sat Sep 29 18:57:29 2018 : Info: Exiting normally
Sat Sep 29 18:57:29 2018 : Info: rlm_sql (sql): Closing connection (5)
Sat Sep 29 18:57:29 2018 : Info: rlm_sql (sql): Closing connection (4)
Sat Sep 29 18:57:29 2018 : Info: rlm_sql (sql): Closing connection (3)
Sat Sep 29 18:57:29 2018 : Info: rlm_sql (sql): Closing connection (2)
Sat Sep 29 18:57:29 2018 : Info: rlm_sql (sql): Closing connection (1)
Sat Sep 29 18:57:29 2018 : Info: rlm_sql (sql): Closing connection (0)
3
2
Hi there!
With FR2 you could acesss the NDS error messages, e.g.
NDS error: no additional information available (-338)
NDS error: failed authentication (-669)
NDS error: login lockout (-197)
...
and log them.
In FR3 I still can see them with
ldap_debug = 0xFFFF
All I get e.g. with Module-Failure-Message is
Bind was not permitted: Server was unwilling to perform
which is the LDAP Error Code 53, which is okay, but I'd really like to log the additional messages, because
it's really useful...
Is there a way to still access those and log them in radius.log ....?
Thank you very much.
Ciao Anja
2
3
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 =~ /(a)(.+)\.(.+)$/) {
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 =~ /(a)\./) {
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 =~ /(a)(.+)\.(.+)$/) {
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 =~ /(a)\./) {
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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (0) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (1) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (1) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (2) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (3) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (3) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (4) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (4) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (5) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (5) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (6) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (6) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (7) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (7) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (7) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (7) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (8) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (8) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (8) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (8) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (9) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (9) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (9) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (9) if (&User-Name =~ /(a)\./) -> 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 !~ /(a)(.+)\.(.+)$/)) {
Fri Sep 28 14:54:44 2018 : Debug: (10) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) {
Fri Sep 28 14:54:44 2018 : Debug: (10) if (&User-Name =~ /(a)\./) -> 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
2
2
28 Sep '18
Hello Alan,
I was facing a problem with backquotes and the Mikrotik-Rate-Limit atribute, this problem happened when I put something like “%{sql: select....}” in the attribute´s value, everything worked fine BUT in the final result the backquotes is not removed, causing problems in the NAS.
Well, at first sight I thought that was a FreeRadius problem, BUT it wasn´t. FreeRadius is so well forged that sometimes we need to do a deep dive into it to figure out how to overcome some “problems”.
So, this is what I did to “fix” this, note that NOTHING WAS CHANGED in FreeRadius source code, just the CONFIGURATION was done to adapt everything.
1 – Create a new file called “/usr/bin/echo2” with following contents and make it executable (chmod 755 /usr/sbin/echo2):
#!/bin/bash
echo $1 | sed -r "s/\`//g"
2 – Edit file /etc/raddb/sites-available/default and ADD the following in the post-auth section:
if (reply:Mikrotik-Rate-Limit =~ /.*\`$/i) {
update reply {
&Mikrotik-Rate-Limit := `/usr/bin/echo2 %{0}`
}
}
3 – Restart radius.
So, the “1” is just a way to execute echo and sed together, because “inside” the FreeRadius conf this doesn´t work, number “2” just identify where exist backquotes in the EXPANSION of the atribute, and, in afirmative case, remove they.
SO SIMPLE....
Again, thanks a lot for the work with FreeRadius, you and your team deserve all my respects.
Best regards,
Rafael Labiak Olivastro
http://www.vigo.com.br
2
2
Hello.
My implementation.
2 NAS(client - 172.20.1.38 and 172.20.1.40) send auth requests to one
FreeRadius.(10.20.18.109)
NAS defined in sql(nas table.)
Satatus server enabled and listen on 18121 port.
Satus Server
server status {
listen {
type = status
ipaddr = 127.0.0.1
port = 18121
}
client admin {
ipaddr = 127.0.0.1
secret = adminsecret
}
authorize {
ok
Autz-Type Status-Server {
ok
}
}
}
Follow type of request send to the Status Server is global (no something
change if I change "FreeRADIUS-Stats-Client-IP-Address = 172.20.1.38" )
echo "Message-Authenticator = 0x00, FreeRADIUS-Statistics-Type = 35,
FreeRADIUS-Stats-Client-IP-Address = 172.20.1.38
,FreeRADIUS-Stats-Server-IP-Address = 10.20.18.109,
FreeRADIUS-Stats-Server-Port = 1812 " | radclient -x localhost:18121 status
adminsecret
Sending Status-Server of id 49 to 127.0.0.1 port 18121
Message-Authenticator = 0x00000000000000000000000000000000
FreeRADIUS-Statistics-Type = 35
FreeRADIUS-Stats-Client-IP-Address = 172.20.1.38
FreeRADIUS-Stats-Server-IP-Address = 10.20.18.109
FreeRADIUS-Stats-Server-Port = 1812
rad_recv: Access-Accept packet from host 127.0.0.1 port 18121, id=49,
length=224
FreeRADIUS-Total-Access-Requests = 1
FreeRADIUS-Total-Access-Accepts = 1
FreeRADIUS-Total-Access-Rejects = 0
FreeRADIUS-Total-Access-Challenges = 0
FreeRADIUS-Total-Auth-Responses = 1
FreeRADIUS-Total-Auth-Duplicate-Requests = 0
FreeRADIUS-Total-Auth-Malformed-Requests = 0
FreeRADIUS-Total-Auth-Invalid-Requests = 0
FreeRADIUS-Total-Auth-Dropped-Requests = 0
FreeRADIUS-Total-Auth-Unknown-Types = 0
FreeRADIUS-Total-Accounting-Requests = 0
FreeRADIUS-Total-Accounting-Responses = 0
FreeRADIUS-Total-Acct-Duplicate-Requests = 0
FreeRADIUS-Total-Acct-Malformed-Requests = 0
FreeRADIUS-Total-Acct-Invalid-Requests = 0
FreeRADIUS-Total-Acct-Dropped-Requests = 0
FreeRADIUS-Total-Acct-Unknown-Types = 0
Question:
Is it possible to observe statistics per client ? (not global stats)
2
3
Hello
We are trying to make two groups of users, General and FixedIP ( IPFIJA ).
To achieve that, we want to set a group of NASes to the General Group,
serving any customer.
And only one NAS, to get ONLY the 'IP-FIJA' customers. Rejecting others.
This way, if customer G1 in General group hits the NAS in NAS-Fixed_IP
(IPFIJA), it's rejected.
And customer F1, in FixedIP group, hits NAS-General, also rejected.
Code in 'default' is:
update request {
Huntgroup-Name := "%{sql:SELECT groupname FROM radhuntgroup WHERE
nasipaddress='%{NAS-IP-Address}'}"
}
#
if (Huntgroup-Name == "IPFIJA" && SQL-Group != "IP-FIJA") {
reject
}
Works great this way.
The question is if there's any way to 'silent' the rejects for the
particular case of 'Wrong NAS/Wrong group'.
Mean, once customer G1 request auth to NAS-Fixed_IP, instead of 'log'
the reject, silently discard it.
Because besides the RadPostAuth table whose inserts can be handled by
some 'if ..then' like above, the server status ( polled by SNMP
statistics ) grows a lot in such cases.
Regards
Andres
2
2
Hi All,
I configured a redundant block for two instances of the sql module as described in the radius.conf file.
redundant redundant_sql_default {
sql_primary_default
sql_secondary_default
handled
}
sql_primary_default and sql_secondary_default are two instances of the sql module.
It works if I call it as a module in the authorize stream but does not accept it in an expansion.
update control {
Tmp-String-1 := "%{redundant_sql_default: SELECT VENDOR_ID||'~'||VALUE||'~'||VPDN_VENDOR_CODING_ID FROM NAS a, NAS_TAG b, VPDN_LAC l WHERE A.ID = B.NAS_ID (+) AND B.NAS_TAG_NAME_ID (+) = 1 AND A.ID = L.NAS_ID (+) AND A.IP_ADDR_TXT = '%{NAS-IP-Address}'}"
}
The service start gives this error.
Sep 27 16:17:26 freeradiusmi radiusd[8798]: /etc/raddb/policy.d/windtre-nas-policy[12]: Failed parsing expanded string:
Sep 27 16:17:26 freeradiusmi radiusd[8798]: /etc/raddb/policy.d/windtre-nas-policy[12]: %{redundant_sql_default: SELECT VENDOR_ID||'~'||VALUE||'~'||VPDN_VENDOR_CODING_I
Sep 27 16:17:26 freeradiusmi radiusd[8798]: /etc/raddb/policy.d/windtre-nas-policy[12]: ^ Unknown module
Sep 27 16:17:26 freeradiusmi systemd[1]: radiusd.service: control process exited, code=exited status=1
Sep 27 16:17:26 freeradiusmi systemd[1]: Failed to start FreeRADIUS multi-protocol policy server.
-- Subject: Unit radiusd.service has failed
What am I doing wrong?
Best Regards
Andrea
2
1
Hi All,
I would like to log failed login attempts, so I can see the username that was
tried. Is there a simple way to do this? Setting auth=yes in radiusd.conf also
logs all successful attempts.
So basically, I'd like to see lines like this one:
Mon Sep 24 13:24:16 2018 : Auth: (34876) Login incorrect (mschap: FAILED: No NT/LM-Password. Cannot perform authentication): [username/<via Auth-Type = eap>] (from client unifi port 0 via TLS tunnel)
but not
Mon Sep 24 13:15:03 2018 : Auth: (34866) Login OK: [username] (from client unifi port 123456789 cli 00-00-11-22-33-44)
Any suggestions on how to achieve this or something similar would be much appreciated.
Not directly related, but somewhat: When auth=no is set, and a login fails (be
it due to a wrong username, or wrong passphrase), I get the following in the log:
Mon Sep 24 13:24:16 2018 : Info: (34877) eap_peap: This means you need to read the PREVIOUS messages in the debug output
Mon Sep 24 13:24:16 2018 : Info: (34877) eap_peap: to find out the reason why the user was rejected
Mon Sep 24 13:24:16 2018 : Info: (34877) eap_peap: Look for "reject" or "fail". Those earlier messages will tell you
Mon Sep 24 13:24:16 2018 : Info: (34877) eap_peap: what went wrong, and how to fix the problem
And that's all! There are *no previous* messages. There four lines are all that
I get. I assume this means that something on my side is misconfigured, like an
"if all else fails, reject" kind of statement?
Thanks for the help!
Cheers
HC
3
9
dynamic_clients // Required attribute "FreeRADIUS-Client-Secret" is missing
by Osvaldo T Crispim Filho 27 Sep '18
by Osvaldo T Crispim Filho 27 Sep '18
27 Sep '18
Why is not he finding the "secret"?
==============================
Freeradius 3.0.18
Debian 9 amd64
==============================
Table nas:
id | nasname | shortname | type | ports | secret | server | community
----+-------------+-----------+-------+-------+--------+--------+-----------
1 | 172.20.0.20 | ap-20 | other | | 123123 | |
2 | 172.20.0.21 | ap-21 | other | | 123123 | |
(2 rows)
=========================
fradius1:~$ psql -h localhost -d radius -U radius -W -c "select secret from
nas where nasname = '172.20.0.21';"
Password for user radius:
secret
--------
123123
(1 row)
==========================
freeradius -X:
Ready to process requests
(0) server dynamic_clients {
(0) # Executing section authorize from file
/etc/freeradius/sites-enabled/dynamic-clients
(0) authorize {
(0) if ("%{sql: SELECT nasname FROM nas WHERE nasname =
'%{Packet-Src-IP-Address}'}") {
(0) EXPAND %{User-Name}
(0) -->
(0) SQL-User-Name set to ''
rlm_sql (sql): Reserved connection (3)
(0) Executing select query: SELECT nasname FROM nas WHERE nasname =
'172.20.0.21'
(0) SQL query returned no results
rlm_sql (sql): Released connection (3)
Need 2 more connections to reach 10 spares
rlm_sql (sql): Opening additional connection (8), 1 of 24 pending slots used
(0) EXPAND %{sql: SELECT nasname FROM nas WHERE nasname =
'%{Packet-Src-IP-Address}'}
(0) -->
(0) if ("%{sql: SELECT nasname FROM nas WHERE nasname =
'%{Packet-Src-IP-Address}'}") -> FALSE
(0) [ok] = ok
(0) } # authorize = ok
(0) } # server dynamic_clients
(0) Converting control list to client fields
*(0) ERROR: Cannot add client 172.20.0.21 <http://172.20.0.21>: Required
attribute "FreeRADIUS-Client-Secret" is missing*
Ignoring request to auth address * port 1812 bound to server default from
unknown client 172.20.0.21 port 45122 proto udp
Ready to process requests
--
- Osvaldo T Crispim Filho -
2
2