September 2018 - Freeradius-Users - lists.freeradius.org

Error Compiling 3.1.x
by Scott Pickles 19 Nov '18

19 Nov '18

I am compiling FreeRADIUS version 3.1.x from source and I get the following error: []# cd freeradius-server-3.1.x[]# ./configure --with-openssl-lib-dir=/usr/local/ssl/lib --with-openssl-include-dir=/usr/local/ssl/include[]# make [ .... SNIP ....] CC src/lib/version.c /usr/bin/ld: /usr/local/ssl/lib/libcrypto.a(md4_dgst.o): relocation R_X86_64_PC32 against undefined symbol `memset@@GLIBC_2.2.5' can not be used when making a shared object; recompile with -fPIC /usr/bin/ld: final link failed: Bad value collect2: error: ld returned 1 exit status make: *** [build/lib/local/libfreeradius-radius.la] Error 1 So I recompile openssl: []# cd openssl-1.0.2d []# ./config -fPIC[]# make[]# make install Trying make again, different module but same suggestion? []# cd freeradius-server-3.1.x[]# make [ .... SNIP ....] CC src/modules/rlm_wimax/rlm_wimax.c /usr/bin/ld: /usr/local/ssl/lib/libcrypto.a(rsaz_exp.o): relocation R_X86_64_32 against `.rodata' can not be used when making a shared object; recompile with -fPIC /usr/local/ssl/lib/libcrypto.a: could not read symbols: Bad value collect2: error: ld returned 1 exit status make: *** [build/lib/local/rlm_wimax.la] Error 1

3 3

smstop with Cisco Wireless
by Paul Aviles 01 Oct '18

01 Oct '18

Hello, I am new to the community and was wondering if anyone has manage to configure freeradius with a Cisco 5508 or 2504 controller for guest authentication with smstop. The goal is to provide a static wep2 password and force the users to enter their cell number where they will receive an sms message for 2 factor authentication. If the number matches, then the user will be authenticated. I currently have regular freeradius and a 2504 working, but missing the smstop/capture/validate part. Anyone with something similar out there? Regards, Paul

2 1

Config FreeRadius (3.0.16) to work with SQL: The Guide is outdated - please helps
by james.ngobui＠gmail.com 01 Oct '18

01 Oct '18

Hello everyone, Recently, I implemented freeradius for our home office. I was able to use the method of editing the user file to add user to authorize them using our network. Now I would like to use mySQL with phpMyAdmin to control and manage other users. So I installed Lamp Stack from here: https://www.digitalocean.com/community/tutorials/how-to-install-linux-apache -mysql-php-lamp-stack-ubuntu-18-04 which basically install Apache server, SQL server and PHP server. I have all 3 up and run OK. Anyway, after that I follow the Guide here to setup the mySQL https://wiki.freeradius.org/guide/SQL-HOWTO-for-freeradius-3.x-on-Debian-Ubu ntu After I finished installing the freeradius-mysql module and created the "radius" database, it shows up in the phpMyAdmin windows. I was excited. However, further more in the Guide, I found a lot of difference/discrepancies in term of file names, location of the files like sql (not sure if sql.conf?). It seems that the Guide is now outdated and pending for update to catch up with the new version of Freeradius file organization As a result, when I attempt to use SQL to authorize the users, the server keeps rejecting my username/password I run radtest and it says "No reply from server" Could someone please instruct me how to start from the scratch again with a proper file's names, locations of each required files, what to edit, etc..? I thank you very much indeed for your support. Again, thanks James --- This email has been checked for viruses by AVG. https://www.avg.com

7 15

pass_all_vps option for rlm_python
by work vlpl 01 Oct '18

01 Oct '18

Hello, I found the not described option `pass_all_vps` for rlm_python module. Is this option intended only for testing? I am asking because neither https://wiki.freeradius.org/modules/Rlm_python page, neither default python config files from `.../raddb/mods-available` does not say anything about this options. I am -- Vladimir

4 7

FreeRADIUS does not recognize device added in the NAS table
by James Ngo 30 Sep '18

30 Sep '18

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

Additional NDS error messages missing in FR3 ?
by Anja Ruckdaeschel 29 Sep '18

29 Sep '18

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

Freeradius dot1x dynamic vlan
by Heikki Lavaste 28 Sep '18

28 Sep '18

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

Old "problem" with backquote and Mikrotik-Rate-Limit (fixed)
by Rafael Labiak Olivastro 28 Sep '18

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

Satus server show statistics per client per client
by Nariman Ibadullaev 28 Sep '18

28 Sep '18

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

Huntgroups and Rejects
by Ing. Andrés Gallo 27 Sep '18

27 Sep '18

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