ERROR: eap_peap: We sent a success, but the client did not agree

5 Oct 2018

      Hi,

I have a problem with a windows 10 client that fails to access our wifi
wpa2 enterprise PEAP-mschapv2.

This is our infrastructure:
CISCO WLC -> PROXY-RADIUS -> AUTH-RADIUS

OS: Debian GNU / Linux 9 (Stretch)
Freeradius 3.0.12 from STABLE repository

I am attaching the output of the raddebug. Analyzing the log I see that the
TLS tunnel is correctly created, mschap authentication goes to good end
(package 12014208)  but then I see this error:

(12014210) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Client rejected our
response. The password is probably incorrect
(12014210) Fri Sep 28 16:27:46 2018: ERROR: eap_peap: We sent a success,
but the client did not agree
(12014210) Fri Sep 28 16:27:46 2018: ERROR: eap: Failed continuing EAP PEAP
(25) session. EAP sub-module failed

and the user can not log in. I can not understand why even if the mschap
authentication was successful, the error above appears. Moreover only this
client complains about the problem, all  others works correctly.

Thanks for your help!

(12014187) Fri Sep 28 16:27:43 2018: Debug: Received Access-Request Id 3
from 130.192.119.80:33713 to 192.168.19.93:1812 length 293
(12014187) Fri Sep 28 16:27:43 2018: Debug:   User-Name = "USER"
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Chargeable-User-Identity =
0x00
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Location-Capable =
Civix-Location
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014187) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port = 13
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014187) Fri Sep 28 16:27:43 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014187) Fri Sep 28 16:27:43 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Airespace-Wlan-Id = 1
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Service-Type = Framed-User
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Framed-MTU = 1300
(12014187) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Type:0 = VLAN
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014187) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message =
0x02020015016d61747469612e6265676f766f657661
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0xf9bd98f7b7c84e260c6dbfaaa97bc62f
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:43 CEST"
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313635
(12014187) Fri Sep 28 16:27:43 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014187) Fri Sep 28 16:27:43 2018: Debug:   authorize {
(12014187) Fri Sep 28 16:27:43 2018: Debug:     policy forbid_win_host_auth
{
(12014187) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014187) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014187) Fri Sep 28 16:27:43 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014187) Fri Sep 28 16:27:43 2018: Debug:     policy normalize_username {
(12014187) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014187) Fri Sep 28 16:27:43 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014187) Fri Sep 28 16:27:43 2018: Debug:          --> USER
(12014187) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014187) Fri Sep 28 16:27:43 2018: Debug:       else {
(12014187) Fri Sep 28 16:27:43 2018: Debug:         [noop] = noop
(12014187) Fri Sep 28 16:27:43 2018: Debug:       } # else = noop
(12014187) Fri Sep 28 16:27:43 2018: Debug:     } # policy
normalize_username = noop
(12014187) Fri Sep 28 16:27:43 2018: Debug:     policy filter_username {
(12014187) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name) {
(12014187) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  -> TRUE
(12014187) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  {
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /) {
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014187) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014187) Fri Sep 28 16:27:43 2018: Debug:       } # if (&User-Name)  =
noop
(12014187) Fri Sep 28 16:27:43 2018: Debug:     } # policy filter_username
= noop
(12014187) Fri Sep 28 16:27:43 2018: Debug:     [preprocess] = ok
(12014187) Fri Sep 28 16:27:43 2018: Debug:     [mschap] = noop
(12014187) Fri Sep 28 16:27:43 2018: Debug: suffix: Checking for suffix
after "@"
(12014187) Fri Sep 28 16:27:43 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014187) Fri Sep 28 16:27:43 2018: Debug: suffix: No such realm "NULL"
(12014187) Fri Sep 28 16:27:43 2018: Debug:     [suffix] = noop
(12014187) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 2 length 21
(12014187) Fri Sep 28 16:27:43 2018: Debug: eap: EAP-Identity reply,
returning 'ok' so we can short-circuit the rest of authorize
(12014187) Fri Sep 28 16:27:43 2018: Debug:     [eap] = ok
(12014187) Fri Sep 28 16:27:43 2018: Debug:   } # authorize = ok
(12014187) Fri Sep 28 16:27:43 2018: Debug: Found Auth-Type = eap
(12014187) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014187) Fri Sep 28 16:27:43 2018: Debug:   authenticate {
(12014187) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent packet with
method EAP Identity (1)
(12014187) Fri Sep 28 16:27:43 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014187) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Initiating new
EAP-TLS session
(12014187) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls start] =
request
(12014187) Fri Sep 28 16:27:43 2018: Debug: eap: Sending EAP Request (code
1) ID 3 length 6
(12014187) Fri Sep 28 16:27:43 2018: Debug: eap: EAP session adding
&reply:State = 0x4a8916764a8a0f76
(12014187) Fri Sep 28 16:27:43 2018: Debug:     [eap] = handled
(12014187) Fri Sep 28 16:27:43 2018: Debug:   } # authenticate = handled
(12014187) Fri Sep 28 16:27:43 2018: Debug: Using Post-Auth-Type Challenge
(12014187) Fri Sep 28 16:27:43 2018: Debug: Post-Auth-Type sub-section not
found.  Ignoring.
(12014187) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014187) Fri Sep 28 16:27:43 2018: Debug: Sent Access-Challenge Id 3 from
192.168.19.93:1812 to 130.192.119.80:33713 length 0
(12014187) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message = 0x010300061920
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014187) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a8916764a8a0f7661caf9ec4798bf13
(12014187) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313635
(12014187) Fri Sep 28 16:27:43 2018: Debug: Finished request

(12014188) Fri Sep 28 16:27:43 2018: Debug: Received Access-Request Id 31
from 130.192.119.80:33713 to 192.168.19.93:1812 length 456
(12014188) Fri Sep 28 16:27:43 2018: Debug:   User-Name = "USER"
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Chargeable-User-Identity =
0x00
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Location-Capable =
Civix-Location
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014188) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port = 13
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014188) Fri Sep 28 16:27:43 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014188) Fri Sep 28 16:27:43 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Airespace-Wlan-Id = 1
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Service-Type = Framed-User
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Framed-MTU = 1300
(12014188) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Type:0 = VLAN
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014188) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message =
0x020300a619800000009c16030300970100009303035bae3a5ea7ccc2962e30c5aefec92da9c3e60e4b9d3bd55a7795a57f6aa5455300002ac02cc02bc030c02f009f009ec024c023c028c027c00ac009c014c013009d009c003d003c0035002f000a01000040000500050100000000000a00080006001d
(12014188) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a8916764a8a0f7661caf9ec4798bf13
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0x96867235312b66c230053355627f173d
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:43 CEST"
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313636
(12014188) Fri Sep 28 16:27:43 2018: Debug: session-state: No cached
attributes
(12014188) Fri Sep 28 16:27:43 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014188) Fri Sep 28 16:27:43 2018: Debug:   authorize {
(12014188) Fri Sep 28 16:27:43 2018: Debug:     policy forbid_win_host_auth
{
(12014188) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014188) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014188) Fri Sep 28 16:27:43 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014188) Fri Sep 28 16:27:43 2018: Debug:     policy normalize_username {
(12014188) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014188) Fri Sep 28 16:27:43 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014188) Fri Sep 28 16:27:43 2018: Debug:          --> USER
(12014188) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014188) Fri Sep 28 16:27:43 2018: Debug:       else {
(12014188) Fri Sep 28 16:27:43 2018: Debug:         [noop] = noop
(12014188) Fri Sep 28 16:27:43 2018: Debug:       } # else = noop
(12014188) Fri Sep 28 16:27:43 2018: Debug:     } # policy
normalize_username = noop
(12014188) Fri Sep 28 16:27:43 2018: Debug:     policy filter_username {
(12014188) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name) {
(12014188) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  -> TRUE
(12014188) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  {
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /) {
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014188) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014188) Fri Sep 28 16:27:43 2018: Debug:       } # if (&User-Name)  =
noop
(12014188) Fri Sep 28 16:27:43 2018: Debug:     } # policy filter_username
= noop
(12014188) Fri Sep 28 16:27:43 2018: Debug:     [preprocess] = ok
(12014188) Fri Sep 28 16:27:43 2018: Debug:     [mschap] = noop
(12014188) Fri Sep 28 16:27:43 2018: Debug: suffix: Checking for suffix
after "@"
(12014188) Fri Sep 28 16:27:43 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014188) Fri Sep 28 16:27:43 2018: Debug: suffix: No such realm "NULL"
(12014188) Fri Sep 28 16:27:43 2018: Debug:     [suffix] = noop
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 3 length 166
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap: Continuing tunnel setup
(12014188) Fri Sep 28 16:27:43 2018: Debug:     [eap] = ok
(12014188) Fri Sep 28 16:27:43 2018: Debug:   } # authorize = ok
(12014188) Fri Sep 28 16:27:43 2018: Debug: Found Auth-Type = eap
(12014188) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014188) Fri Sep 28 16:27:43 2018: Debug:   authenticate {
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap: Finished EAP session with
state 0x4a8916764a8a0f76
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap: Previous EAP request found
for state 0x4a8916764a8a0f76, released from the list
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent packet with
method EAP PEAP (25)
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Continuing EAP-TLS
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Peer indicated
complete TLS record size will be 156 bytes
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Got complete TLS
record (156 bytes)
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls verify] =
length included
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: (other): before SSL
initialization
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: before
SSL initialization
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: before
SSL initialization
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
read client hello
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
write server hello
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
write certificate
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
write key exchange
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
write server done
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: Need to
read more data: SSLv3/TLS write server done
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: In SSL Handshake Phase
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: In SSL Accept mode
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls process] =
handled
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap: Sending EAP Request (code
1) ID 4 length 1014
(12014188) Fri Sep 28 16:27:43 2018: Debug: eap: EAP session adding
&reply:State = 0x4a8916764b8d0f76
(12014188) Fri Sep 28 16:27:43 2018: Debug:     [eap] = handled
(12014188) Fri Sep 28 16:27:43 2018: Debug:   } # authenticate = handled
(12014188) Fri Sep 28 16:27:43 2018: Debug: Using Post-Auth-Type Challenge
(12014188) Fri Sep 28 16:27:43 2018: Debug: Post-Auth-Type sub-section not
found.  Ignoring.
(12014188) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014188) Fri Sep 28 16:27:43 2018: Debug: Sent Access-Challenge Id 31
from 192.168.19.93:1812 to 130.192.119.80:33713 length 0
(12014188) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message =
0x010403f619c000000fa2160303003d020000390303ca0711321a19105799591371046c5540290f34e4d6d9b6c19a2e73ae4aa1c31000c030000011ff01000100000b000403000102001700001603030e000b000dfc000df9000536308205323082041aa00302010202100c0b470919f41d1d2384e8715b
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014188) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a8916764b8d0f7661caf9ec4798bf13
(12014188) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313636
(12014188) Fri Sep 28 16:27:43 2018: Debug: Finished request

(12014189) Fri Sep 28 16:27:43 2018: Debug: Received Access-Request Id 254
from 130.192.119.80:33713 to 192.168.19.93:1812 length 296
(12014189) Fri Sep 28 16:27:43 2018: Debug:   User-Name = "USER"
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Chargeable-User-Identity =
0x00
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Location-Capable =
Civix-Location
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014189) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port = 13
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014189) Fri Sep 28 16:27:43 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014189) Fri Sep 28 16:27:43 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Airespace-Wlan-Id = 1
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Service-Type = Framed-User
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Framed-MTU = 1300
(12014189) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Type:0 = VLAN
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014189) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message = 0x020400061900
(12014189) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a8916764b8d0f7661caf9ec4798bf13
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0x6157ae71fe63d397936d792731d9612d
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:43 CEST"
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313637
(12014189) Fri Sep 28 16:27:43 2018: Debug: session-state: No cached
attributes
(12014189) Fri Sep 28 16:27:43 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014189) Fri Sep 28 16:27:43 2018: Debug:   authorize {
(12014189) Fri Sep 28 16:27:43 2018: Debug:     policy forbid_win_host_auth
{
(12014189) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014189) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014189) Fri Sep 28 16:27:43 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014189) Fri Sep 28 16:27:43 2018: Debug:     policy normalize_username {
(12014189) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014189) Fri Sep 28 16:27:43 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014189) Fri Sep 28 16:27:43 2018: Debug:          --> USER
(12014189) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014189) Fri Sep 28 16:27:43 2018: Debug:       else {
(12014189) Fri Sep 28 16:27:43 2018: Debug:         [noop] = noop
(12014189) Fri Sep 28 16:27:43 2018: Debug:       } # else = noop
(12014189) Fri Sep 28 16:27:43 2018: Debug:     } # policy
normalize_username = noop
(12014189) Fri Sep 28 16:27:43 2018: Debug:     policy filter_username {
(12014189) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name) {
(12014189) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  -> TRUE
(12014189) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  {
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /) {
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014189) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014189) Fri Sep 28 16:27:43 2018: Debug:       } # if (&User-Name)  =
noop
(12014189) Fri Sep 28 16:27:43 2018: Debug:     } # policy filter_username
= noop
(12014189) Fri Sep 28 16:27:43 2018: Debug:     [preprocess] = ok
(12014189) Fri Sep 28 16:27:43 2018: Debug:     [mschap] = noop
(12014189) Fri Sep 28 16:27:43 2018: Debug: suffix: Checking for suffix
after "@"
(12014189) Fri Sep 28 16:27:43 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014189) Fri Sep 28 16:27:43 2018: Debug: suffix: No such realm "NULL"
(12014189) Fri Sep 28 16:27:43 2018: Debug:     [suffix] = noop
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 4 length 6
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap: Continuing tunnel setup
(12014189) Fri Sep 28 16:27:43 2018: Debug:     [eap] = ok
(12014189) Fri Sep 28 16:27:43 2018: Debug:   } # authorize = ok
(12014189) Fri Sep 28 16:27:43 2018: Debug: Found Auth-Type = eap
(12014189) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014189) Fri Sep 28 16:27:43 2018: Debug:   authenticate {
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap: Finished EAP session with
state 0x4a8916764b8d0f76
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap: Previous EAP request found
for state 0x4a8916764b8d0f76, released from the list
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent packet with
method EAP PEAP (25)
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Continuing EAP-TLS
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Peer ACKed our
handshake fragment
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls verify] =
request
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls process] =
handled
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap: Sending EAP Request (code
1) ID 5 length 1010
(12014189) Fri Sep 28 16:27:43 2018: Debug: eap: EAP session adding
&reply:State = 0x4a891676488c0f76
(12014189) Fri Sep 28 16:27:43 2018: Debug:     [eap] = handled
(12014189) Fri Sep 28 16:27:43 2018: Debug:   } # authenticate = handled
(12014189) Fri Sep 28 16:27:43 2018: Debug: Using Post-Auth-Type Challenge
(12014189) Fri Sep 28 16:27:43 2018: Debug: Post-Auth-Type sub-section not
found.  Ignoring.
(12014189) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014189) Fri Sep 28 16:27:43 2018: Debug: Sent Access-Challenge Id 254
from 192.168.19.93:1812 to 130.192.119.80:33713 length 0
(12014189) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message =
0x010503f2194008060667810c010202306e06082b0601050507010104623060302406082b060105050730018618687474703a2f2f6f6373702e64696769636572742e636f6d303806082b06010505073002862c687474703a2f2f636163657274732e64696769636572742e636f6d2f544552454e415353
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014189) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a891676488c0f7661caf9ec4798bf13
(12014189) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313637
(12014189) Fri Sep 28 16:27:43 2018: Debug: Finished request

(12014190) Fri Sep 28 16:27:43 2018: Debug: Received Access-Request Id 4
from 130.192.119.80:33713 to 192.168.19.93:1812 length 296
(12014190) Fri Sep 28 16:27:43 2018: Debug:   User-Name = "USER"
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Chargeable-User-Identity =
0x00
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Location-Capable =
Civix-Location
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014190) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port = 13
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014190) Fri Sep 28 16:27:43 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014190) Fri Sep 28 16:27:43 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Airespace-Wlan-Id = 1
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Service-Type = Framed-User
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Framed-MTU = 1300
(12014190) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Type:0 = VLAN
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014190) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message = 0x020500061900
(12014190) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a891676488c0f7661caf9ec4798bf13
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0xb11330e666b8f603e83639bc481f4367
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:43 CEST"
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313638
(12014190) Fri Sep 28 16:27:43 2018: Debug: session-state: No cached
attributes
(12014190) Fri Sep 28 16:27:43 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014190) Fri Sep 28 16:27:43 2018: Debug:   authorize {
(12014190) Fri Sep 28 16:27:43 2018: Debug:     policy forbid_win_host_auth
{
(12014190) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014190) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014190) Fri Sep 28 16:27:43 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014190) Fri Sep 28 16:27:43 2018: Debug:     policy normalize_username {
(12014190) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014190) Fri Sep 28 16:27:43 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014190) Fri Sep 28 16:27:43 2018: Debug:          --> USER
(12014190) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014190) Fri Sep 28 16:27:43 2018: Debug:       else {
(12014190) Fri Sep 28 16:27:43 2018: Debug:         [noop] = noop
(12014190) Fri Sep 28 16:27:43 2018: Debug:       } # else = noop
(12014190) Fri Sep 28 16:27:43 2018: Debug:     } # policy
normalize_username = noop
(12014190) Fri Sep 28 16:27:43 2018: Debug:     policy filter_username {
(12014190) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name) {
(12014190) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  -> TRUE
(12014190) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  {
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /) {
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014190) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014190) Fri Sep 28 16:27:43 2018: Debug:       } # if (&User-Name)  =
noop
(12014190) Fri Sep 28 16:27:43 2018: Debug:     } # policy filter_username
= noop
(12014190) Fri Sep 28 16:27:43 2018: Debug:     [preprocess] = ok
(12014190) Fri Sep 28 16:27:43 2018: Debug:     [mschap] = noop
(12014190) Fri Sep 28 16:27:43 2018: Debug: suffix: Checking for suffix
after "@"
(12014190) Fri Sep 28 16:27:43 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014190) Fri Sep 28 16:27:43 2018: Debug: suffix: No such realm "NULL"
(12014190) Fri Sep 28 16:27:43 2018: Debug:     [suffix] = noop
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 5 length 6
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap: Continuing tunnel setup
(12014190) Fri Sep 28 16:27:43 2018: Debug:     [eap] = ok
(12014190) Fri Sep 28 16:27:43 2018: Debug:   } # authorize = ok
(12014190) Fri Sep 28 16:27:43 2018: Debug: Found Auth-Type = eap
(12014190) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014190) Fri Sep 28 16:27:43 2018: Debug:   authenticate {
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap: Finished EAP session with
state 0x4a891676488c0f76
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap: Previous EAP request found
for state 0x4a891676488c0f76, released from the list
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent packet with
method EAP PEAP (25)
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Continuing EAP-TLS
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Peer ACKed our
handshake fragment
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls verify] =
request
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls process] =
handled
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap: Sending EAP Request (code
1) ID 6 length 1010
(12014190) Fri Sep 28 16:27:43 2018: Debug: eap: EAP session adding
&reply:State = 0x4a891676498f0f76
(12014190) Fri Sep 28 16:27:43 2018: Debug:     [eap] = handled
(12014190) Fri Sep 28 16:27:43 2018: Debug:   } # authenticate = handled
(12014190) Fri Sep 28 16:27:43 2018: Debug: Using Post-Auth-Type Challenge
(12014190) Fri Sep 28 16:27:43 2018: Debug: Post-Auth-Type sub-section not
found.  Ignoring.
(12014190) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014190) Fri Sep 28 16:27:43 2018: Debug: Sent Access-Challenge Id 4 from
192.168.19.93:1812 to 130.192.119.80:33713 length 0
(12014190) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message =
0x010603f219401d130101ff040830060101ff020100300e0603551d0f0101ff040403020186307906082b06010505070101046d306b302406082b060105050730018618687474703a2f2f6f6373702e64696769636572742e636f6d304306082b060105050730028637687474703a2f2f63616365727473
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014190) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a891676498f0f7661caf9ec4798bf13
(12014190) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313638
(12014190) Fri Sep 28 16:27:43 2018: Debug: Finished request

(12014191) Fri Sep 28 16:27:43 2018: Debug: Received Access-Request Id 76
from 130.192.119.80:33713 to 192.168.19.93:1812 length 296
(12014191) Fri Sep 28 16:27:43 2018: Debug:   User-Name = "USER"
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Chargeable-User-Identity =
0x00
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Location-Capable =
Civix-Location
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014191) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port = 13
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014191) Fri Sep 28 16:27:43 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014191) Fri Sep 28 16:27:43 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Airespace-Wlan-Id = 1
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Service-Type = Framed-User
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Framed-MTU = 1300
(12014191) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Type:0 = VLAN
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014191) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message = 0x020600061900
(12014191) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a891676498f0f7661caf9ec4798bf13
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0xa74588a00ca5aa323596e13a85ac485b
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:43 CEST"
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313639
(12014191) Fri Sep 28 16:27:43 2018: Debug: session-state: No cached
attributes
(12014191) Fri Sep 28 16:27:43 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014191) Fri Sep 28 16:27:43 2018: Debug:   authorize {
(12014191) Fri Sep 28 16:27:43 2018: Debug:     policy forbid_win_host_auth
{
(12014191) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014191) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014191) Fri Sep 28 16:27:43 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014191) Fri Sep 28 16:27:43 2018: Debug:     policy normalize_username {
(12014191) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014191) Fri Sep 28 16:27:43 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014191) Fri Sep 28 16:27:43 2018: Debug:          --> USER
(12014191) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014191) Fri Sep 28 16:27:43 2018: Debug:       else {
(12014191) Fri Sep 28 16:27:43 2018: Debug:         [noop] = noop
(12014191) Fri Sep 28 16:27:43 2018: Debug:       } # else = noop
(12014191) Fri Sep 28 16:27:43 2018: Debug:     } # policy
normalize_username = noop
(12014191) Fri Sep 28 16:27:43 2018: Debug:     policy filter_username {
(12014191) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name) {
(12014191) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  -> TRUE
(12014191) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  {
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /) {
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014191) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014191) Fri Sep 28 16:27:43 2018: Debug:       } # if (&User-Name)  =
noop
(12014191) Fri Sep 28 16:27:43 2018: Debug:     } # policy filter_username
= noop
(12014191) Fri Sep 28 16:27:43 2018: Debug:     [preprocess] = ok
(12014191) Fri Sep 28 16:27:43 2018: Debug:     [mschap] = noop
(12014191) Fri Sep 28 16:27:43 2018: Debug: suffix: Checking for suffix
after "@"
(12014191) Fri Sep 28 16:27:43 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014191) Fri Sep 28 16:27:43 2018: Debug: suffix: No such realm "NULL"
(12014191) Fri Sep 28 16:27:43 2018: Debug:     [suffix] = noop
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 6 length 6
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap: Continuing tunnel setup
(12014191) Fri Sep 28 16:27:43 2018: Debug:     [eap] = ok
(12014191) Fri Sep 28 16:27:43 2018: Debug:   } # authorize = ok
(12014191) Fri Sep 28 16:27:43 2018: Debug: Found Auth-Type = eap
(12014191) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014191) Fri Sep 28 16:27:43 2018: Debug:   authenticate {
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap: Finished EAP session with
state 0x4a891676498f0f76
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap: Previous EAP request found
for state 0x4a891676498f0f76, released from the list
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent packet with
method EAP PEAP (25)
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Continuing EAP-TLS
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Peer ACKed our
handshake fragment
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls verify] =
request
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls process] =
handled
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap: Sending EAP Request (code
1) ID 7 length 996
(12014191) Fri Sep 28 16:27:43 2018: Debug: eap: EAP session adding
&reply:State = 0x4a8916764e8e0f76
(12014191) Fri Sep 28 16:27:43 2018: Debug:     [eap] = handled
(12014191) Fri Sep 28 16:27:43 2018: Debug:   } # authenticate = handled
(12014191) Fri Sep 28 16:27:43 2018: Debug: Using Post-Auth-Type Challenge
(12014191) Fri Sep 28 16:27:43 2018: Debug: Post-Auth-Type sub-section not
found.  Ignoring.
(12014191) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014191) Fri Sep 28 16:27:43 2018: Debug: Sent Access-Challenge Id 76
from 192.168.19.93:1812 to 130.192.119.80:33713 length 0
(12014191) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message =
0x010703e419000282010100ad0e15cee443805cb187f3b760f97112a5aedc269488aaf4cef520392858600cf880daa9159532613cb5b128848a8adc9f0a0c83177a8f90ac8ae779535c31842af60f98323676ccdedd3ca8a2ef6afb21f25261df9f20d71fe2b1d9fe1864d2125b5ff9581835bc47cda136
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014191) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a8916764e8e0f7661caf9ec4798bf13
(12014191) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313639
(12014191) Fri Sep 28 16:27:43 2018: Debug: Finished request

(12014192) Fri Sep 28 16:27:43 2018: Debug: Received Access-Request Id 13
from 130.192.119.80:33713 to 192.168.19.93:1812 length 426
(12014192) Fri Sep 28 16:27:43 2018: Debug:   User-Name = "USER"
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Chargeable-User-Identity =
0x00
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Location-Capable =
Civix-Location
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014192) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port = 13
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014192) Fri Sep 28 16:27:43 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014192) Fri Sep 28 16:27:43 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Airespace-Wlan-Id = 1
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Service-Type = Framed-User
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Framed-MTU = 1300
(12014192) Fri Sep 28 16:27:43 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Type:0 = VLAN
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014192) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message =
0x0207008819800000007e160303004610000042410492cc0a049c313744be89f4fad474e76bf5bbbe8f7630e42dfef34a53dfce8a44ea1e37b1a61895e4776f47577c5b6bda0e3aff2934b6898549ac1b7b3f7c249e14030300010116030300280000000000000000d349e31e6d934aae9a1c69e7478279
(12014192) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a8916764e8e0f7661caf9ec4798bf13
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0x7114901a53f0d646ce8518bec779ec21
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:43 CEST"
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313730
(12014192) Fri Sep 28 16:27:43 2018: Debug: session-state: No cached
attributes
(12014192) Fri Sep 28 16:27:43 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014192) Fri Sep 28 16:27:43 2018: Debug:   authorize {
(12014192) Fri Sep 28 16:27:43 2018: Debug:     policy forbid_win_host_auth
{
(12014192) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014192) Fri Sep 28 16:27:43 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014192) Fri Sep 28 16:27:43 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014192) Fri Sep 28 16:27:43 2018: Debug:     policy normalize_username {
(12014192) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014192) Fri Sep 28 16:27:43 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014192) Fri Sep 28 16:27:43 2018: Debug:          --> USER
(12014192) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014192) Fri Sep 28 16:27:43 2018: Debug:       else {
(12014192) Fri Sep 28 16:27:43 2018: Debug:         [noop] = noop
(12014192) Fri Sep 28 16:27:43 2018: Debug:       } # else = noop
(12014192) Fri Sep 28 16:27:43 2018: Debug:     } # policy
normalize_username = noop
(12014192) Fri Sep 28 16:27:43 2018: Debug:     policy filter_username {
(12014192) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name) {
(12014192) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  -> TRUE
(12014192) Fri Sep 28 16:27:43 2018: Debug:       if (&User-Name)  {
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /) {
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014192) Fri Sep 28 16:27:43 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014192) Fri Sep 28 16:27:43 2018: Debug:       } # if (&User-Name)  =
noop
(12014192) Fri Sep 28 16:27:43 2018: Debug:     } # policy filter_username
= noop
(12014192) Fri Sep 28 16:27:43 2018: Debug:     [preprocess] = ok
(12014192) Fri Sep 28 16:27:43 2018: Debug:     [mschap] = noop
(12014192) Fri Sep 28 16:27:43 2018: Debug: suffix: Checking for suffix
after "@"
(12014192) Fri Sep 28 16:27:43 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014192) Fri Sep 28 16:27:43 2018: Debug: suffix: No such realm "NULL"
(12014192) Fri Sep 28 16:27:43 2018: Debug:     [suffix] = noop
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 7 length 136
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap: Continuing tunnel setup
(12014192) Fri Sep 28 16:27:43 2018: Debug:     [eap] = ok
(12014192) Fri Sep 28 16:27:43 2018: Debug:   } # authorize = ok
(12014192) Fri Sep 28 16:27:43 2018: Debug: Found Auth-Type = eap
(12014192) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014192) Fri Sep 28 16:27:43 2018: Debug:   authenticate {
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap: Finished EAP session with
state 0x4a8916764e8e0f76
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap: Previous EAP request found
for state 0x4a8916764e8e0f76, released from the list
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap: Peer sent packet with
method EAP PEAP (25)
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Continuing EAP-TLS
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Peer indicated
complete TLS record size will be 126 bytes
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: Got complete TLS
record (126 bytes)
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls verify] =
length included
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
write server done
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
read client key exchange
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
read change cipher spec
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
read finished
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
write change cipher spec
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: TLS_accept: SSLv3/TLS
write finished
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: (other): SSL
negotiation finished successfully
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: SSL Connection
Established
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap_peap: [eaptls process] =
handled
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap: Sending EAP Request (code
1) ID 8 length 57
(12014192) Fri Sep 28 16:27:43 2018: Debug: eap: EAP session adding
&reply:State = 0x4a8916764f810f76
(12014192) Fri Sep 28 16:27:43 2018: Debug:     [eap] = handled
(12014192) Fri Sep 28 16:27:43 2018: Debug:   } # authenticate = handled
(12014192) Fri Sep 28 16:27:43 2018: Debug: Using Post-Auth-Type Challenge
(12014192) Fri Sep 28 16:27:43 2018: Debug: Post-Auth-Type sub-section not
found.  Ignoring.
(12014192) Fri Sep 28 16:27:43 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014192) Fri Sep 28 16:27:43 2018: Debug: Sent Access-Challenge Id 13
from 192.168.19.93:1812 to 130.192.119.80:33713 length 0
(12014192) Fri Sep 28 16:27:43 2018: Debug:   EAP-Message =
0x0108003919001403030001011603030028ad1ff295a543d4925d728be01399e83219afc001b8ed4d3ee1772404eecaebf64d10d02295d8db61
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014192) Fri Sep 28 16:27:43 2018: Debug:   State =
0x4a8916764f810f7661caf9ec4798bf13
(12014192) Fri Sep 28 16:27:43 2018: Debug:   Proxy-State = 0x313730
(12014192) Fri Sep 28 16:27:43 2018: Debug: Finished request

(12014206) Fri Sep 28 16:27:46 2018: Debug: Received Access-Request Id 114
from 130.192.119.80:33713 to 192.168.19.93:1812 length 296
(12014206) Fri Sep 28 16:27:46 2018: Debug:   User-Name = "USER"
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Chargeable-User-Identity =
0x00
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Location-Capable =
Civix-Location
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014206) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port = 13
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014206) Fri Sep 28 16:27:46 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014206) Fri Sep 28 16:27:46 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Airespace-Wlan-Id = 1
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Service-Type = Framed-User
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Framed-MTU = 1300
(12014206) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Type:0 = VLAN
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014206) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message = 0x020800061900
(12014206) Fri Sep 28 16:27:46 2018: Debug:   State =
0x4a8916764f810f7661caf9ec4798bf13
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x92a0fff2fc7057153e5d6702efc8873d
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:46 CEST"
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Proxy-State = 0x313736
(12014206) Fri Sep 28 16:27:46 2018: Debug: session-state: No cached
attributes
(12014206) Fri Sep 28 16:27:46 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014206) Fri Sep 28 16:27:46 2018: Debug:   authorize {
(12014206) Fri Sep 28 16:27:46 2018: Debug:     policy forbid_win_host_auth
{
(12014206) Fri Sep 28 16:27:46 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014206) Fri Sep 28 16:27:46 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014206) Fri Sep 28 16:27:46 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014206) Fri Sep 28 16:27:46 2018: Debug:     policy normalize_username {
(12014206) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014206) Fri Sep 28 16:27:46 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014206) Fri Sep 28 16:27:46 2018: Debug:          --> USER
(12014206) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014206) Fri Sep 28 16:27:46 2018: Debug:       else {
(12014206) Fri Sep 28 16:27:46 2018: Debug:         [noop] = noop
(12014206) Fri Sep 28 16:27:46 2018: Debug:       } # else = noop
(12014206) Fri Sep 28 16:27:46 2018: Debug:     } # policy
normalize_username = noop
(12014206) Fri Sep 28 16:27:46 2018: Debug:     policy filter_username {
(12014206) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name) {
(12014206) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name)  -> TRUE
(12014206) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name)  {
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~ / /) {
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014206) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014206) Fri Sep 28 16:27:46 2018: Debug:       } # if (&User-Name)  =
noop
(12014206) Fri Sep 28 16:27:46 2018: Debug:     } # policy filter_username
= noop
(12014206) Fri Sep 28 16:27:46 2018: Debug:     [preprocess] = ok
(12014206) Fri Sep 28 16:27:46 2018: Debug:     [mschap] = noop
(12014206) Fri Sep 28 16:27:46 2018: Debug: suffix: Checking for suffix
after "@"
(12014206) Fri Sep 28 16:27:46 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014206) Fri Sep 28 16:27:46 2018: Debug: suffix: No such realm "NULL"
(12014206) Fri Sep 28 16:27:46 2018: Debug:     [suffix] = noop
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 8 length 6
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap: Continuing tunnel setup
(12014206) Fri Sep 28 16:27:46 2018: Debug:     [eap] = ok
(12014206) Fri Sep 28 16:27:46 2018: Debug:   } # authorize = ok
(12014206) Fri Sep 28 16:27:46 2018: Debug: Found Auth-Type = eap
(12014206) Fri Sep 28 16:27:46 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014206) Fri Sep 28 16:27:46 2018: Debug:   authenticate {
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap: Finished EAP session with
state 0x4a8916764f810f76
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap: Previous EAP request found
for state 0x4a8916764f810f76, released from the list
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent packet with
method EAP PEAP (25)
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Continuing EAP-TLS
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Peer ACKed our
handshake fragment.  handshake is finished
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap_peap: [eaptls verify] =
success
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap_peap: [eaptls process] =
success
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Session established.
Decoding tunneled attributes
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap_peap: PEAP state TUNNEL
ESTABLISHED
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap: Sending EAP Request (code
1) ID 9 length 40
(12014206) Fri Sep 28 16:27:46 2018: Debug: eap: EAP session adding
&reply:State = 0x4a8916764c800f76
(12014206) Fri Sep 28 16:27:46 2018: Debug:     [eap] = handled
(12014206) Fri Sep 28 16:27:46 2018: Debug:   } # authenticate = handled
(12014206) Fri Sep 28 16:27:46 2018: Debug: Using Post-Auth-Type Challenge
(12014206) Fri Sep 28 16:27:46 2018: Debug: Post-Auth-Type sub-section not
found.  Ignoring.
(12014206) Fri Sep 28 16:27:46 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014206) Fri Sep 28 16:27:46 2018: Debug: Sent Access-Challenge Id 114
from 192.168.19.93:1812 to 130.192.119.80:33713 length 0
(12014206) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x010900281900170303001dad1ff295a543d493985fec914519565dd6c4a59cb71424a1b6bf75c011
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014206) Fri Sep 28 16:27:46 2018: Debug:   State =
0x4a8916764c800f7661caf9ec4798bf13
(12014206) Fri Sep 28 16:27:46 2018: Debug:   Proxy-State = 0x313736
(12014206) Fri Sep 28 16:27:46 2018: Debug: Finished request

(12014207) Fri Sep 28 16:27:46 2018: Debug: Received Access-Request Id 34
from 130.192.119.80:33713 to 192.168.19.93:1812 length 342
(12014207) Fri Sep 28 16:27:46 2018: Debug:   User-Name = "USER"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Chargeable-User-Identity =
0x00
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Location-Capable =
Civix-Location
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port = 13
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014207) Fri Sep 28 16:27:46 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Airespace-Wlan-Id = 1
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Service-Type = Framed-User
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Framed-MTU = 1300
(12014207) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Type:0 = VLAN
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x02090034190017030300290000000000000001cc129720c2092186d6eefa43bb9b9e015b0f486ae1501f8b5074d17be5f9e6743f
(12014207) Fri Sep 28 16:27:46 2018: Debug:   State =
0x4a8916764c800f7661caf9ec4798bf13
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x271d46101a1c2c015fa1b1d233e6f42a
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:46 CEST"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Proxy-State = 0x313737
(12014207) Fri Sep 28 16:27:46 2018: Debug: session-state: No cached
attributes
(12014207) Fri Sep 28 16:27:46 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014207) Fri Sep 28 16:27:46 2018: Debug:   authorize {
(12014207) Fri Sep 28 16:27:46 2018: Debug:     policy forbid_win_host_auth
{
(12014207) Fri Sep 28 16:27:46 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014207) Fri Sep 28 16:27:46 2018: Debug:     policy normalize_username {
(12014207) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014207) Fri Sep 28 16:27:46 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014207) Fri Sep 28 16:27:46 2018: Debug:          --> USER
(12014207) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:       else {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         [noop] = noop
(12014207) Fri Sep 28 16:27:46 2018: Debug:       } # else = noop
(12014207) Fri Sep 28 16:27:46 2018: Debug:     } # policy
normalize_username = noop
(12014207) Fri Sep 28 16:27:46 2018: Debug:     policy filter_username {
(12014207) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name)  -> TRUE
(12014207) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name)  {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~ / /) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:       } # if (&User-Name)  =
noop
(12014207) Fri Sep 28 16:27:46 2018: Debug:     } # policy filter_username
= noop
(12014207) Fri Sep 28 16:27:46 2018: Debug:     [preprocess] = ok
(12014207) Fri Sep 28 16:27:46 2018: Debug:     [mschap] = noop
(12014207) Fri Sep 28 16:27:46 2018: Debug: suffix: Checking for suffix
after "@"
(12014207) Fri Sep 28 16:27:46 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014207) Fri Sep 28 16:27:46 2018: Debug: suffix: No such realm "NULL"
(12014207) Fri Sep 28 16:27:46 2018: Debug:     [suffix] = noop
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 9 length 52
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Continuing tunnel setup
(12014207) Fri Sep 28 16:27:46 2018: Debug:     [eap] = ok
(12014207) Fri Sep 28 16:27:46 2018: Debug:   } # authorize = ok
(12014207) Fri Sep 28 16:27:46 2018: Debug: Found Auth-Type = eap
(12014207) Fri Sep 28 16:27:46 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014207) Fri Sep 28 16:27:46 2018: Debug:   authenticate {
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Finished EAP session with
state 0x4a8916764c800f76
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Previous EAP request found
for state 0x4a8916764c800f76, released from the list
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent packet with
method EAP PEAP (25)
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Continuing EAP-TLS
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: [eaptls verify] = ok
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Done initial handshake
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: [eaptls process] = ok
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Session established.
Decoding tunneled attributes
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: PEAP state WAITING
FOR INNER IDENTITY
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Identity - USER
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Got inner identity
'USER'
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Setting default EAP
type for tunneled EAP session
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Got tunneled request
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   EAP-Message =
0x02090015016d61747469612e6265676f766f657661
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Setting User-Name to
USER
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Sending tunneled
request to inner-tunnel
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   EAP-Message =
0x02090015016d61747469612e6265676f766f657661
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 FreeRADIUS-Proxied-To = 127.0.0.1
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   User-Name = "USER"
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Chargeable-User-Identity = 0x00
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Location-Capable =
Civix-Location
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Calling-Station-Id
= "00-24-54-F2-B4-53"
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-Port = 13
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-IP-Address =
172.31.254.253
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-Identifier =
"wlc-lin"
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Airespace-Wlan-Id =
1
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Service-Type =
Framed-User
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Framed-MTU = 1300
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-Port-Type =
Wireless-802.11
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Tunnel-Type:0 = VLAN
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Tunnel-Medium-Type:0 = IEEE-802
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Tunnel-Private-Group-Id:0 = "940"
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Event-Timestamp =
"Sep 28 2018 16:27:46 CEST"
(12014207) Fri Sep 28 16:27:46 2018: Debug: Virtual server inner-tunnel
received request
(12014207) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x02090015016d61747469612e6265676f766f657661
(12014207) Fri Sep 28 16:27:46 2018: Debug:   FreeRADIUS-Proxied-To =
127.0.0.1
(12014207) Fri Sep 28 16:27:46 2018: Debug:   User-Name = "USER"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Chargeable-User-Identity =
0x00
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Location-Capable =
Civix-Location
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port = 13
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014207) Fri Sep 28 16:27:46 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Airespace-Wlan-Id = 1
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Service-Type = Framed-User
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Framed-MTU = 1300
(12014207) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Type:0 = VLAN
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:46 CEST"
(12014207) Fri Sep 28 16:27:46 2018: WARNING: Outer and inner identities
are the same.  User privacy is compromised.
(12014207) Fri Sep 28 16:27:46 2018: Debug: server inner-tunnel {
(12014207) Fri Sep 28 16:27:46 2018: Debug:   # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/inner-tunnel
(12014207) Fri Sep 28 16:27:46 2018: Debug:     authorize {
(12014207) Fri Sep 28 16:27:46 2018: Debug:       policy filter_username {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name)  -> TRUE
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name)  {
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~ /
/) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~ /
/)  -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@[^@]*@/ ) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.\./ ) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.\./ )  -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if ((&User-Name =~
/@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if ((&User-Name =~
/@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.$/)  {
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.$/)   -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@\./)  {
(12014207) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@\./)   -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:         } # if (&User-Name)  =
notfound
(12014207) Fri Sep 28 16:27:46 2018: Debug:       } # policy
filter_username = notfound
(12014207) Fri Sep 28 16:27:46 2018: Debug:       policy
filter_inner_identity {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if
(!&outer.request:User-Name || !&User-Name) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if
(!&outer.request:User-Name || !&User-Name)  -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if
(&outer.request:User-Name != &User-Name) {
(12014207) Fri Sep 28 16:27:46 2018: Debug:         if
(&outer.request:User-Name != &User-Name)  -> FALSE
(12014207) Fri Sep 28 16:27:46 2018: Debug:       } # policy
filter_inner_identity = notfound
(12014207) Fri Sep 28 16:27:46 2018: Debug:       [chap] = noop
(12014207) Fri Sep 28 16:27:46 2018: Debug:       [mschap] = noop
(12014207) Fri Sep 28 16:27:46 2018: Debug: suffix: Checking for suffix
after "@"
(12014207) Fri Sep 28 16:27:46 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014207) Fri Sep 28 16:27:46 2018: Debug: suffix: No such realm "NULL"
(12014207) Fri Sep 28 16:27:46 2018: Debug:       [suffix] = noop
(12014207) Fri Sep 28 16:27:46 2018: Debug:       update control {
(12014207) Fri Sep 28 16:27:46 2018: Debug:       } # update control = noop
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 9 length 21
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: EAP-Identity reply,
returning 'ok' so we can short-circuit the rest of authorize
(12014207) Fri Sep 28 16:27:46 2018: Debug:       [eap] = ok
(12014207) Fri Sep 28 16:27:46 2018: Debug:     } # authorize = ok
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Found Auth-Type = eap
(12014207) Fri Sep 28 16:27:46 2018: Debug:   # Executing group from file
/etc/freeradius/3.0/sites-enabled/inner-tunnel
(12014207) Fri Sep 28 16:27:46 2018: Debug:     authenticate {
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent packet with
method EAP Identity (1)
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Calling submodule
eap_mschapv2 to process data
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_mschapv2: Issuing Challenge
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Sending EAP Request (code
1) ID 10 length 43
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: EAP session adding
&reply:State = 0xd17b9cafd17186c4
(12014207) Fri Sep 28 16:27:46 2018: Debug:       [eap] = handled
(12014207) Fri Sep 28 16:27:46 2018: Debug:     } # authenticate = handled
(12014207) Fri Sep 28 16:27:46 2018: Debug: } # server inner-tunnel
(12014207) Fri Sep 28 16:27:46 2018: Debug: Virtual server sending reply
(12014207) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x010a002b1a010a0026101e491bc846728e627f87d42331372f0d667265657261646975732d332e302e3132
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014207) Fri Sep 28 16:27:46 2018: Debug:   State =
0xd17b9cafd17186c4a414169edff77c76
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Got tunneled reply
code 11
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   EAP-Message =
0x010a002b1a010a0026101e491bc846728e627f87d42331372f0d667265657261646975732d332e302e3132
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Message-Authenticator = 0x00000000000000000000000000000000
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   State =
0xd17b9cafd17186c4a414169edff77c76
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Got tunneled
Access-Challenge
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: Sending EAP Request (code
1) ID 10 length 74
(12014207) Fri Sep 28 16:27:46 2018: Debug: eap: EAP session adding
&reply:State = 0x4a8916764d830f76
(12014207) Fri Sep 28 16:27:46 2018: Debug:     [eap] = handled
(12014207) Fri Sep 28 16:27:46 2018: Debug:   } # authenticate = handled
(12014207) Fri Sep 28 16:27:46 2018: Debug: Using Post-Auth-Type Challenge
(12014207) Fri Sep 28 16:27:46 2018: Debug: Post-Auth-Type sub-section not
found.  Ignoring.
(12014207) Fri Sep 28 16:27:46 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014207) Fri Sep 28 16:27:46 2018: Debug: Sent Access-Challenge Id 34
from 192.168.19.93:1812 to 130.192.119.80:33713 length 0
(12014207) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x010a004a1900170303003fad1ff295a543d494b2b6f96343807584afc9f5973ba753882cf60d9a68f9ea519be8e97d0b98e137b5e8fad21229717437b422c1d75b5d702f4950ae389880
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014207) Fri Sep 28 16:27:46 2018: Debug:   State =
0x4a8916764d830f7661caf9ec4798bf13
(12014207) Fri Sep 28 16:27:46 2018: Debug:   Proxy-State = 0x313737
(12014207) Fri Sep 28 16:27:46 2018: Debug: Finished request

(12014208) Fri Sep 28 16:27:46 2018: Debug: Received Access-Request Id 199
from 130.192.119.80:33713 to 192.168.19.93:1812 length 396
(12014208) Fri Sep 28 16:27:46 2018: Debug:   User-Name = "USER"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Chargeable-User-Identity =
0x00
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Location-Capable =
Civix-Location
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port = 13
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014208) Fri Sep 28 16:27:46 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Airespace-Wlan-Id = 1
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Service-Type = Framed-User
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Framed-MTU = 1300
(12014208) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Type:0 = VLAN
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x020a006a1900170303005f000000000000000210e73a15c1bc6370114d34f8a46f47d8a421c6234b6a5e4fa1f118283243f0d1fc00dd18be0bd3eb733a5112fd6819bd806f8c61335fa3ddd7c99b5045c78454da1cd74a259538748837440828877a981da96fac673ab2
(12014208) Fri Sep 28 16:27:46 2018: Debug:   State =
0x4a8916764d830f7661caf9ec4798bf13
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x12f38c9312ff1590f52aad1d29c064b6
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:46 CEST"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Proxy-State = 0x313738
(12014208) Fri Sep 28 16:27:46 2018: Debug: session-state: No cached
attributes
(12014208) Fri Sep 28 16:27:46 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014208) Fri Sep 28 16:27:46 2018: Debug:   authorize {
(12014208) Fri Sep 28 16:27:46 2018: Debug:     policy forbid_win_host_auth
{
(12014208) Fri Sep 28 16:27:46 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014208) Fri Sep 28 16:27:46 2018: Debug:     policy normalize_username {
(12014208) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014208) Fri Sep 28 16:27:46 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014208) Fri Sep 28 16:27:46 2018: Debug:          --> USER
(12014208) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:       else {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         [noop] = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:       } # else = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:     } # policy
normalize_username = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:     policy filter_username {
(12014208) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name)  -> TRUE
(12014208) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name)  {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~ / /) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:       } # if (&User-Name)  =
noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:     } # policy filter_username
= noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:     [preprocess] = ok
(12014208) Fri Sep 28 16:27:46 2018: Debug:     [mschap] = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug: suffix: Checking for suffix
after "@"
(12014208) Fri Sep 28 16:27:46 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014208) Fri Sep 28 16:27:46 2018: Debug: suffix: No such realm "NULL"
(12014208) Fri Sep 28 16:27:46 2018: Debug:     [suffix] = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 10 length 106
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Continuing tunnel setup
(12014208) Fri Sep 28 16:27:46 2018: Debug:     [eap] = ok
(12014208) Fri Sep 28 16:27:46 2018: Debug:   } # authorize = ok
(12014208) Fri Sep 28 16:27:46 2018: Debug: Found Auth-Type = eap
(12014208) Fri Sep 28 16:27:46 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014208) Fri Sep 28 16:27:46 2018: Debug:   authenticate {
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Finished EAP session with
state 0x4a8916764d830f76
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Previous EAP request found
for state 0x4a8916764d830f76, released from the list
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent packet with
method EAP PEAP (25)
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Continuing EAP-TLS
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: [eaptls verify] = ok
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Done initial handshake
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: [eaptls process] = ok
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Session established.
Decoding tunneled attributes
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: PEAP state phase2
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: EAP method MSCHAPv2
(26)
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Got tunneled request
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   EAP-Message =
0x020a004b1a020a004631e2af7c69e50b037a8e2c6739d0d8c44c00000000000000006897fcaba602febac38bdb8a4efa8e1d89b8c2b6e74199d0006d61747469612e6265676f766f657661
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Setting User-Name to
USER
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Sending tunneled
request to inner-tunnel
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   EAP-Message =
0x020a004b1a020a004631e2af7c69e50b037a8e2c6739d0d8c44c00000000000000006897fcaba602febac38bdb8a4efa8e1d89b8c2b6e74199d0006d61747469612e6265676f766f657661
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 FreeRADIUS-Proxied-To = 127.0.0.1
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   User-Name = "USER"
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   State =
0xd17b9cafd17186c4a414169edff77c76
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Chargeable-User-Identity = 0x00
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Location-Capable =
Civix-Location
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Calling-Station-Id
= "00-24-54-F2-B4-53"
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-Port = 13
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-IP-Address =
172.31.254.253
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-Identifier =
"wlc-lin"
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Airespace-Wlan-Id =
1
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Service-Type =
Framed-User
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Framed-MTU = 1300
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-Port-Type =
Wireless-802.11
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Tunnel-Type:0 = VLAN
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Tunnel-Medium-Type:0 = IEEE-802
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Tunnel-Private-Group-Id:0 = "940"
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Event-Timestamp =
"Sep 28 2018 16:27:46 CEST"
(12014208) Fri Sep 28 16:27:46 2018: Debug: Virtual server inner-tunnel
received request
(12014208) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x020a004b1a020a004631e2af7c69e50b037a8e2c6739d0d8c44c00000000000000006897fcaba602febac38bdb8a4efa8e1d89b8c2b6e74199d0006d61747469612e6265676f766f657661
(12014208) Fri Sep 28 16:27:46 2018: Debug:   FreeRADIUS-Proxied-To =
127.0.0.1
(12014208) Fri Sep 28 16:27:46 2018: Debug:   User-Name = "USER"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   State =
0xd17b9cafd17186c4a414169edff77c76
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Chargeable-User-Identity =
0x00
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Location-Capable =
Civix-Location
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port = 13
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014208) Fri Sep 28 16:27:46 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Airespace-Wlan-Id = 1
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Service-Type = Framed-User
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Framed-MTU = 1300
(12014208) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Type:0 = VLAN
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:46 CEST"
(12014208) Fri Sep 28 16:27:46 2018: WARNING: Outer and inner identities
are the same.  User privacy is compromised.
(12014208) Fri Sep 28 16:27:46 2018: Debug: server inner-tunnel {
(12014208) Fri Sep 28 16:27:46 2018: Debug:   session-state: No cached
attributes
(12014208) Fri Sep 28 16:27:46 2018: Debug:   # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/inner-tunnel
(12014208) Fri Sep 28 16:27:46 2018: Debug:     authorize {
(12014208) Fri Sep 28 16:27:46 2018: Debug:       policy filter_username {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name)  -> TRUE
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name)  {
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~ /
/) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~ /
/)  -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@[^@]*@/ ) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.\./ ) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.\./ )  -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if ((&User-Name =~
/@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if ((&User-Name =~
/@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.$/)  {
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.$/)   -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@\./)  {
(12014208) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@\./)   -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:         } # if (&User-Name)  =
notfound
(12014208) Fri Sep 28 16:27:46 2018: Debug:       } # policy
filter_username = notfound
(12014208) Fri Sep 28 16:27:46 2018: Debug:       policy
filter_inner_identity {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if
(!&outer.request:User-Name || !&User-Name) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if
(!&outer.request:User-Name || !&User-Name)  -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if
(&outer.request:User-Name != &User-Name) {
(12014208) Fri Sep 28 16:27:46 2018: Debug:         if
(&outer.request:User-Name != &User-Name)  -> FALSE
(12014208) Fri Sep 28 16:27:46 2018: Debug:       } # policy
filter_inner_identity = notfound
(12014208) Fri Sep 28 16:27:46 2018: Debug:       [chap] = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:       [mschap] = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug: suffix: Checking for suffix
after "@"
(12014208) Fri Sep 28 16:27:46 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014208) Fri Sep 28 16:27:46 2018: Debug: suffix: No such realm "NULL"
(12014208) Fri Sep 28 16:27:46 2018: Debug:       [suffix] = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:       update control {
(12014208) Fri Sep 28 16:27:46 2018: Debug:       } # update control = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 10 length 75
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: No EAP Start, assuming
it's an on-going EAP conversation
(12014208) Fri Sep 28 16:27:46 2018: Debug:       [eap] = updated
(12014208) Fri Sep 28 16:27:46 2018: Debug:       [files] = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:       [expiration] = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:       [logintime] = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:       [pap] = noop
(12014208) Fri Sep 28 16:27:46 2018: Debug:     } # authorize = updated
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Found Auth-Type = eap
(12014208) Fri Sep 28 16:27:46 2018: Debug:   # Executing group from file
/etc/freeradius/3.0/sites-enabled/inner-tunnel
(12014208) Fri Sep 28 16:27:46 2018: Debug:     authenticate {
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Finished EAP session with
state 0xd17b9cafd17186c4
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Previous EAP request found
for state 0xd17b9cafd17186c4, released from the list
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent packet with
method EAP MSCHAPv2 (26)
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Calling submodule
eap_mschapv2 to process data
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_mschapv2: # Executing group
from file /etc/freeradius/3.0/sites-enabled/inner-tunnel
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_mschapv2:   authenticate {
(12014208) Fri Sep 28 16:27:46 2018: Debug: mschap: Creating challenge hash
with username: USER
(12014208) Fri Sep 28 16:27:46 2018: Debug: mschap: Client is using
MS-CHAPv2
(12014208) Fri Sep 28 16:27:46 2018: Debug: mschap: EXPAND
%{%{Stripped-User-Name}:-%{%{mschap:User-Name}:-None}}
(12014208) Fri Sep 28 16:27:46 2018: Debug: mschap:    --> USER
(12014208) Fri Sep 28 16:27:46 2018: Debug: mschap: sending authentication
request user='USER' domain='ateneo'
(12014208) Fri Sep 28 16:27:46 2018: Debug: mschap: Authenticated
successfully
(12014208) Fri Sep 28 16:27:46 2018: Debug: mschap: Adding MS-CHAPv2 MPPE
keys
(12014208) Fri Sep 28 16:27:46 2018: Debug:     [mschap] = ok
(12014208) Fri Sep 28 16:27:46 2018: Debug:   } # authenticate = ok
(12014208) Fri Sep 28 16:27:46 2018: Debug: MSCHAP Success
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Sending EAP Request (code
1) ID 11 length 51
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: EAP session adding
&reply:State = 0xd17b9cafd07086c4
(12014208) Fri Sep 28 16:27:46 2018: Debug:       [eap] = handled
(12014208) Fri Sep 28 16:27:46 2018: Debug:     } # authenticate = handled
(12014208) Fri Sep 28 16:27:46 2018: Debug: } # server inner-tunnel
(12014208) Fri Sep 28 16:27:46 2018: Debug: Virtual server sending reply
(12014208) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x010b00331a030a002e533d44364238374641423034413243463344363443334535324336423338374345314639424231334139
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014208) Fri Sep 28 16:27:46 2018: Debug:   State =
0xd17b9cafd07086c4a414169edff77c76
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Got tunneled reply
code 11
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   EAP-Message =
0x010b00331a030a002e533d44364238374641423034413243463344363443334535324336423338374345314639424231334139
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Message-Authenticator = 0x00000000000000000000000000000000
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   State =
0xd17b9cafd07086c4a414169edff77c76
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Got tunneled
Access-Challenge
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: Sending EAP Request (code
1) ID 11 length 82
(12014208) Fri Sep 28 16:27:46 2018: Debug: eap: EAP session adding
&reply:State = 0x4a89167642820f76
(12014208) Fri Sep 28 16:27:46 2018: Debug:     [eap] = handled
(12014208) Fri Sep 28 16:27:46 2018: Debug:   } # authenticate = handled
(12014208) Fri Sep 28 16:27:46 2018: Debug: Using Post-Auth-Type Challenge
(12014208) Fri Sep 28 16:27:46 2018: Debug: Post-Auth-Type sub-section not
found.  Ignoring.
(12014208) Fri Sep 28 16:27:46 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014208) Fri Sep 28 16:27:46 2018: Debug: Sent Access-Challenge Id 199
from 192.168.19.93:1812 to 130.192.119.80:33713 length 0
(12014208) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x010b005219001703030047ad1ff295a543d495b30dda05842023a40d0664a7d1dddae763d5ad58141c61532011d406bae71ac22dc90a0ab35caa9b8fabdd1ad1535887f6ddb7f70a283bca04cb1963cd544d
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014208) Fri Sep 28 16:27:46 2018: Debug:   State =
0x4a89167642820f7661caf9ec4798bf13
(12014208) Fri Sep 28 16:27:46 2018: Debug:   Proxy-State = 0x313738
(12014208) Fri Sep 28 16:27:46 2018: Debug: Finished request

(12014209) Fri Sep 28 16:27:46 2018: Debug: Received Access-Request Id 165
from 130.192.119.80:33713 to 192.168.19.93:1812 length 327
(12014209) Fri Sep 28 16:27:46 2018: Debug:   User-Name = "USER"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Chargeable-User-Identity =
0x00
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Location-Capable =
Civix-Location
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port = 13
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014209) Fri Sep 28 16:27:46 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Airespace-Wlan-Id = 1
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Service-Type = Framed-User
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Framed-MTU = 1300
(12014209) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Type:0 = VLAN
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x020b00251900170303001a00000000000000038a42de4b968ff0f4bb626c51eb7b83ea5735
(12014209) Fri Sep 28 16:27:46 2018: Debug:   State =
0x4a89167642820f7661caf9ec4798bf13
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x4bd4ce4907cf523a46b3491550e274b6
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:46 CEST"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Proxy-State = 0x313739
(12014209) Fri Sep 28 16:27:46 2018: Debug: session-state: No cached
attributes
(12014209) Fri Sep 28 16:27:46 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014209) Fri Sep 28 16:27:46 2018: Debug:   authorize {
(12014209) Fri Sep 28 16:27:46 2018: Debug:     policy forbid_win_host_auth
{
(12014209) Fri Sep 28 16:27:46 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014209) Fri Sep 28 16:27:46 2018: Debug:     policy normalize_username {
(12014209) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014209) Fri Sep 28 16:27:46 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014209) Fri Sep 28 16:27:46 2018: Debug:          --> USER
(12014209) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:       else {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         [noop] = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:       } # else = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:     } # policy
normalize_username = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:     policy filter_username {
(12014209) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name)  -> TRUE
(12014209) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name)  {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~ / /) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:       } # if (&User-Name)  =
noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:     } # policy filter_username
= noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:     [preprocess] = ok
(12014209) Fri Sep 28 16:27:46 2018: Debug:     [mschap] = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug: suffix: Checking for suffix
after "@"
(12014209) Fri Sep 28 16:27:46 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014209) Fri Sep 28 16:27:46 2018: Debug: suffix: No such realm "NULL"
(12014209) Fri Sep 28 16:27:46 2018: Debug:     [suffix] = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 11 length 37
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Continuing tunnel setup
(12014209) Fri Sep 28 16:27:46 2018: Debug:     [eap] = ok
(12014209) Fri Sep 28 16:27:46 2018: Debug:   } # authorize = ok
(12014209) Fri Sep 28 16:27:46 2018: Debug: Found Auth-Type = eap
(12014209) Fri Sep 28 16:27:46 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014209) Fri Sep 28 16:27:46 2018: Debug:   authenticate {
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Finished EAP session with
state 0x4a89167642820f76
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Previous EAP request found
for state 0x4a89167642820f76, released from the list
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent packet with
method EAP PEAP (25)
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Continuing EAP-TLS
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: [eaptls verify] = ok
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Done initial handshake
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: [eaptls process] = ok
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Session established.
Decoding tunneled attributes
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: PEAP state phase2
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: EAP method MSCHAPv2
(26)
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Got tunneled request
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   EAP-Message =
0x020b00061a03
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Setting User-Name to
USER
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Sending tunneled
request to inner-tunnel
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   EAP-Message =
0x020b00061a03
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 FreeRADIUS-Proxied-To = 127.0.0.1
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   User-Name = "USER"
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   State =
0xd17b9cafd07086c4a414169edff77c76
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Chargeable-User-Identity = 0x00
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Location-Capable =
Civix-Location
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Calling-Station-Id
= "00-24-54-F2-B4-53"
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-Port = 13
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-IP-Address =
172.31.254.253
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-Identifier =
"wlc-lin"
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Airespace-Wlan-Id =
1
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Service-Type =
Framed-User
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Framed-MTU = 1300
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   NAS-Port-Type =
Wireless-802.11
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Tunnel-Type:0 = VLAN
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Tunnel-Medium-Type:0 = IEEE-802
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Tunnel-Private-Group-Id:0 = "940"
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   Event-Timestamp =
"Sep 28 2018 16:27:46 CEST"
(12014209) Fri Sep 28 16:27:46 2018: Debug: Virtual server inner-tunnel
received request
(12014209) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message = 0x020b00061a03
(12014209) Fri Sep 28 16:27:46 2018: Debug:   FreeRADIUS-Proxied-To =
127.0.0.1
(12014209) Fri Sep 28 16:27:46 2018: Debug:   User-Name = "USER"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   State =
0xd17b9cafd07086c4a414169edff77c76
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Chargeable-User-Identity =
0x00
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Location-Capable =
Civix-Location
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port = 13
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014209) Fri Sep 28 16:27:46 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Airespace-Wlan-Id = 1
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Service-Type = Framed-User
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Framed-MTU = 1300
(12014209) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Type:0 = VLAN
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:46 CEST"
(12014209) Fri Sep 28 16:27:46 2018: WARNING: Outer and inner identities
are the same.  User privacy is compromised.
(12014209) Fri Sep 28 16:27:46 2018: Debug: server inner-tunnel {
(12014209) Fri Sep 28 16:27:46 2018: Debug:   session-state: No cached
attributes
(12014209) Fri Sep 28 16:27:46 2018: Debug:   # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/inner-tunnel
(12014209) Fri Sep 28 16:27:46 2018: Debug:     authorize {
(12014209) Fri Sep 28 16:27:46 2018: Debug:       policy filter_username {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name)  -> TRUE
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name)  {
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~ /
/) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~ /
/)  -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@[^@]*@/ ) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.\./ ) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.\./ )  -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if ((&User-Name =~
/@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if ((&User-Name =~
/@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.$/)  {
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/\.$/)   -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@\./)  {
(12014209) Fri Sep 28 16:27:46 2018: Debug:           if (&User-Name =~
/@\./)   -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:         } # if (&User-Name)  =
notfound
(12014209) Fri Sep 28 16:27:46 2018: Debug:       } # policy
filter_username = notfound
(12014209) Fri Sep 28 16:27:46 2018: Debug:       policy
filter_inner_identity {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if
(!&outer.request:User-Name || !&User-Name) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if
(!&outer.request:User-Name || !&User-Name)  -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if
(&outer.request:User-Name != &User-Name) {
(12014209) Fri Sep 28 16:27:46 2018: Debug:         if
(&outer.request:User-Name != &User-Name)  -> FALSE
(12014209) Fri Sep 28 16:27:46 2018: Debug:       } # policy
filter_inner_identity = notfound
(12014209) Fri Sep 28 16:27:46 2018: Debug:       [chap] = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:       [mschap] = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug: suffix: Checking for suffix
after "@"
(12014209) Fri Sep 28 16:27:46 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014209) Fri Sep 28 16:27:46 2018: Debug: suffix: No such realm "NULL"
(12014209) Fri Sep 28 16:27:46 2018: Debug:       [suffix] = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:       update control {
(12014209) Fri Sep 28 16:27:46 2018: Debug:       } # update control = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 11 length 6
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: No EAP Start, assuming
it's an on-going EAP conversation
(12014209) Fri Sep 28 16:27:46 2018: Debug:       [eap] = updated
(12014209) Fri Sep 28 16:27:46 2018: Debug:       [files] = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:       [expiration] = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:       [logintime] = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:       [pap] = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:     } # authorize = updated
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Found Auth-Type = eap
(12014209) Fri Sep 28 16:27:46 2018: Debug:   # Executing group from file
/etc/freeradius/3.0/sites-enabled/inner-tunnel
(12014209) Fri Sep 28 16:27:46 2018: Debug:     authenticate {
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Finished EAP session with
state 0xd17b9cafd07086c4
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Previous EAP request found
for state 0xd17b9cafd07086c4, released from the list
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent packet with
method EAP MSCHAPv2 (26)
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Calling submodule
eap_mschapv2 to process data
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Sending EAP Success (code
3) ID 11 length 4
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Freeing handler
(12014209) Fri Sep 28 16:27:46 2018: Debug:       [eap] = ok
(12014209) Fri Sep 28 16:27:46 2018: Debug:     } # authenticate = ok
(12014209) Fri Sep 28 16:27:46 2018: Debug:   # Executing section post-auth
from file /etc/freeradius/3.0/sites-enabled/inner-tunnel
(12014209) Fri Sep 28 16:27:46 2018: Debug:     post-auth {
(12014209) Fri Sep 28 16:27:46 2018: Debug:       update {
(12014209) Fri Sep 28 16:27:46 2018: Debug:       } # update = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug:       update
outer.session-state {
(12014209) Fri Sep 28 16:27:46 2018: Debug:       } # update
outer.session-state = noop
(12014209) Fri Sep 28 16:27:46 2018: Debug: unito-linelog-eap: EXPAND
custom.%{%{reply:Packet-Type}:-default}
(12014209) Fri Sep 28 16:27:46 2018: Debug: unito-linelog-eap:    -->
custom.Access-Accept
(12014209) Fri Sep 28 16:27:46 2018: Debug: unito-linelog-eap: EXPAND
ACCEPTED (%{%{Stripped-User-Name}:-%{User-Name}})
(OUTER=%{%{outer.request:User-Name}:-Unknown})
(MAC=%{%{request:Calling-Station-Id}:-Unknown})
(CSID=%{request:Called-Station-Id})
(12014209) Fri Sep 28 16:27:46 2018: Debug: unito-linelog-eap:    -->
ACCEPTED (USER) (OUTER=USER) (MAC=00-24-54-F2-B4-53)
(CSID=053-D-004:unito-wifi)
(12014209) Fri Sep 28 16:27:46 2018: Debug:       [unito-linelog-eap] = ok
(12014209) Fri Sep 28 16:27:46 2018: Debug:     } # post-auth = ok
(12014209) Fri Sep 28 16:27:46 2018: Debug: } # server inner-tunnel
(12014209) Fri Sep 28 16:27:46 2018: Debug: Virtual server sending reply
(12014209) Fri Sep 28 16:27:46 2018: Debug:   MS-MPPE-Encryption-Policy =
Encryption-Allowed
(12014209) Fri Sep 28 16:27:46 2018: Debug:   MS-MPPE-Encryption-Types =
RC4-40or128-bit-Allowed
(12014209) Fri Sep 28 16:27:46 2018: Debug:   MS-MPPE-Send-Key =
0x7266b1a55bb76baa8b669b27a29bcd15
(12014209) Fri Sep 28 16:27:46 2018: Debug:   MS-MPPE-Recv-Key =
0x802d880cd66d80ac457ebbc473566b03
(12014209) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message = 0x030b0004
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014209) Fri Sep 28 16:27:46 2018: Debug:   User-Name = "USER"
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Got tunneled reply
code 2
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 MS-MPPE-Encryption-Policy = Encryption-Allowed
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   MS-MPPE-Send-Key =
0x7266b1a55bb76baa8b669b27a29bcd15
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   MS-MPPE-Recv-Key =
0x802d880cd66d80ac457ebbc473566b03
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   EAP-Message =
0x030b0004
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:
 Message-Authenticator = 0x00000000000000000000000000000000
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap:   User-Name = "USER"
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Tunneled
authentication was successful
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap_peap: SUCCESS
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: Sending EAP Request (code
1) ID 12 length 46
(12014209) Fri Sep 28 16:27:46 2018: Debug: eap: EAP session adding
&reply:State = 0x4a89167643850f76
(12014209) Fri Sep 28 16:27:46 2018: Debug:     [eap] = handled
(12014209) Fri Sep 28 16:27:46 2018: Debug:   } # authenticate = handled
(12014209) Fri Sep 28 16:27:46 2018: Debug: Using Post-Auth-Type Challenge
(12014209) Fri Sep 28 16:27:46 2018: Debug: Post-Auth-Type sub-section not
found.  Ignoring.
(12014209) Fri Sep 28 16:27:46 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014209) Fri Sep 28 16:27:46 2018: Debug: session-state: Saving cached
attributes
(12014209) Fri Sep 28 16:27:46 2018: Debug:   User-Name += "USER"
(12014209) Fri Sep 28 16:27:46 2018: Debug: Sent Access-Challenge Id 165
from 192.168.19.93:1812 to 130.192.119.80:33713 length 0
(12014209) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x010c002e19001703030023ad1ff295a543d4966d076f6ae66986ec710a95864c191a47a4f8f209c35c39af94a296
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014209) Fri Sep 28 16:27:46 2018: Debug:   State =
0x4a89167643850f7661caf9ec4798bf13
(12014209) Fri Sep 28 16:27:46 2018: Debug:   Proxy-State = 0x313739
(12014209) Fri Sep 28 16:27:46 2018: Debug: Finished request

(12014210) Fri Sep 28 16:27:46 2018: Debug: Received Access-Request Id 247
from 130.192.119.80:33713 to 192.168.19.93:1812 length 336
(12014210) Fri Sep 28 16:27:46 2018: Debug:   User-Name = "USER"
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Chargeable-User-Identity =
0x00
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Location-Capable =
Civix-Location
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Calling-Station-Id =
"00-24-54-F2-B4-53"
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Called-Station-Id =
"053-D-004:unito-wifi"
(12014210) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port = 13
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Cisco-AVPair =
"audit-session-id=ac1ffefd0013f7385bae1886"
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Acct-Session-Id =
"5bae1883/00:24:54:f2:b4:53/1359867"
(12014210) Fri Sep 28 16:27:46 2018: Debug:   NAS-IP-Address =
172.31.254.253
(12014210) Fri Sep 28 16:27:46 2018: Debug:   NAS-Identifier = "wlc-lin"
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Airespace-Wlan-Id = 1
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Service-Type = Framed-User
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Framed-MTU = 1300
(12014210) Fri Sep 28 16:27:46 2018: Debug:   NAS-Port-Type =
Wireless-802.11
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Type:0 = VLAN
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Medium-Type:0 =
IEEE-802
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Tunnel-Private-Group-Id:0 =
"940"
(12014210) Fri Sep 28 16:27:46 2018: Debug:   EAP-Message =
0x020c002e1900170303002300000000000000046d1c6ef9533507adc1bf7af1f99b3c7cad118fac74da98772b4fda
(12014210) Fri Sep 28 16:27:46 2018: Debug:   State =
0x4a89167643850f7661caf9ec4798bf13
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Message-Authenticator =
0x0dbfe7856dbd45f1ddabd9f5ec69f137
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Event-Timestamp = "Sep 28
2018 16:27:46 CEST"
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Proxy-State = 0x313830
(12014210) Fri Sep 28 16:27:46 2018: Debug: Restoring &session-state
(12014210) Fri Sep 28 16:27:46 2018: Debug:   &session-state:User-Name +=
"USER"
(12014210) Fri Sep 28 16:27:46 2018: Debug: # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
(12014210) Fri Sep 28 16:27:46 2018: Debug:   authorize {
(12014210) Fri Sep 28 16:27:46 2018: Debug:     policy forbid_win_host_auth
{
(12014210) Fri Sep 28 16:27:46 2018: Debug:       if ( &User-Name =~
/^host\// ) {
(12014210) Fri Sep 28 16:27:46 2018: Debug:       if ( &User-Name =~
/^host\// )  -> FALSE
(12014210) Fri Sep 28 16:27:46 2018: Debug:     } # policy
forbid_win_host_auth = notfound
(12014210) Fri Sep 28 16:27:46 2018: Debug:     policy normalize_username {
(12014210) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}") {
(12014210) Fri Sep 28 16:27:46 2018: Debug:       EXPAND
%{tolower:%{User-Name}}
(12014210) Fri Sep 28 16:27:46 2018: Debug:          --> USER
(12014210) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name !=
"%{tolower:%{User-Name}}")  -> FALSE
(12014210) Fri Sep 28 16:27:46 2018: Debug:       else {
(12014210) Fri Sep 28 16:27:46 2018: Debug:         [noop] = noop
(12014210) Fri Sep 28 16:27:46 2018: Debug:       } # else = noop
(12014210) Fri Sep 28 16:27:46 2018: Debug:     } # policy
normalize_username = noop
(12014210) Fri Sep 28 16:27:46 2018: Debug:     policy filter_username {
(12014210) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name) {
(12014210) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name)  -> TRUE
(12014210) Fri Sep 28 16:27:46 2018: Debug:       if (&User-Name)  {
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~ / /) {
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~ / /)
-> FALSE
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@[^@]*@/ ) {
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@[^@]*@/ )  -> FALSE
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.\./ ) {
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.\./ )  -> FALSE
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))  {
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSE
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.$/)  {
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/\.$/)   -> FALSE
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@\./)  {
(12014210) Fri Sep 28 16:27:46 2018: Debug:         if (&User-Name =~
/@\./)   -> FALSE
(12014210) Fri Sep 28 16:27:46 2018: Debug:       } # if (&User-Name)  =
noop
(12014210) Fri Sep 28 16:27:46 2018: Debug:     } # policy filter_username
= noop
(12014210) Fri Sep 28 16:27:46 2018: Debug:     [preprocess] = ok
(12014210) Fri Sep 28 16:27:46 2018: Debug:     [mschap] = noop
(12014210) Fri Sep 28 16:27:46 2018: Debug: suffix: Checking for suffix
after "@"
(12014210) Fri Sep 28 16:27:46 2018: Debug: suffix: No '@' in User-Name =
"USER", looking up realm NULL
(12014210) Fri Sep 28 16:27:46 2018: Debug: suffix: No such realm "NULL"
(12014210) Fri Sep 28 16:27:46 2018: Debug:     [suffix] = noop
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent EAP Response
(code 2) ID 12 length 46
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap: Continuing tunnel setup
(12014210) Fri Sep 28 16:27:46 2018: Debug:     [eap] = ok
(12014210) Fri Sep 28 16:27:46 2018: Debug:   } # authorize = ok
(12014210) Fri Sep 28 16:27:46 2018: Debug: Found Auth-Type = eap
(12014210) Fri Sep 28 16:27:46 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014210) Fri Sep 28 16:27:46 2018: Debug:   authenticate {
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap: Expiring EAP session with
state 0x3284a47d328ebe20
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap: Finished EAP session with
state 0x4a89167643850f76
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap: Previous EAP request found
for state 0x4a89167643850f76, released from the list
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap: Peer sent packet with
method EAP PEAP (25)
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap: Calling submodule eap_peap
to process data
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Continuing EAP-TLS
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap_peap: [eaptls verify] = ok
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Done initial handshake
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap_peap: [eaptls process] = ok
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Session established.
Decoding tunneled attributes
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap_peap: PEAP state send tlv
success
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Received EAP-TLV
response
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap_peap: Client rejected our
response.  The password is probably incorrect
(12014210) Fri Sep 28 16:27:46 2018: ERROR: eap_peap: We sent a success,
but the client did not agree
(12014210) Fri Sep 28 16:27:46 2018: ERROR: eap: Failed continuing EAP PEAP
(25) session.  EAP sub-module failed
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap: Sending EAP Failure (code
4) ID 12 length 4
(12014210) Fri Sep 28 16:27:46 2018: Debug: eap: Failed in EAP select
(12014210) Fri Sep 28 16:27:46 2018: Debug:     [eap] = invalid
(12014210) Fri Sep 28 16:27:46 2018: Debug:   } # authenticate = invalid
(12014210) Fri Sep 28 16:27:46 2018: Debug: Failed to authenticate the user
(12014210) Fri Sep 28 16:27:46 2018: Debug: Using Post-Auth-Type Reject
(12014210) Fri Sep 28 16:27:46 2018: Debug: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
(12014210) Fri Sep 28 16:27:46 2018: Debug:   Post-Auth-Type REJECT {
(12014210) Fri Sep 28 16:27:46 2018: Debug: attr_filter.access_reject:
EXPAND %{User-Name}
(12014210) Fri Sep 28 16:27:46 2018: Debug: attr_filter.access_reject:
--> USER
(12014210) Fri Sep 28 16:27:46 2018: Debug: attr_filter.access_reject:
Matched entry DEFAULT at line 11
(12014210) Fri Sep 28 16:27:46 2018: Debug:     [attr_filter.access_reject]
= updated
(12014210) Fri Sep 28 16:27:46 2018: Debug:     [eap] = noop
(12014210) Fri Sep 28 16:27:46 2018: Debug:     policy
remove_reply_message_if_eap {
(12014210) Fri Sep 28 16:27:46 2018: Debug:       if (&reply:EAP-Message &&
&reply:Reply-Message) {
(12014210) Fri Sep 28 16:27:46 2018: Debug:       if (&reply:EAP-Message &&
&reply:Reply-Message)  -> FALSE
(12014210) Fri Sep 28 16:27:46 2018: Debug:       else {
(12014210) Fri Sep 28 16:27:46 2018: Debug:         [noop] = noop
(12014210) Fri Sep 28 16:27:46 2018: Debug:       } # else = noop
(12014210) Fri Sep 28 16:27:46 2018: Debug:     } # policy
remove_reply_message_if_eap = noop
(12014210) Fri Sep 28 16:27:46 2018: Debug:     if (!&EAP-Message) {
(12014210) Fri Sep 28 16:27:46 2018: Debug:     if (!&EAP-Message)  -> FALSE
(12014210) Fri Sep 28 16:27:46 2018: Debug:   } # Post-Auth-Type REJECT =
updated
(12014210) Fri Sep 28 16:27:46 2018: Debug: Delaying response for 1.000000
seconds

(12014209) Fri Sep 28 16:27:46 2018: Debug: Cleaning up request packet ID
165 with timestamp +1919353
(12014210) Fri Sep 28 16:27:47 2018: Debug: Sending delayed response
(12014210) Fri Sep 28 16:27:47 2018: Debug: Sent Access-Reject Id 247 from
192.168.19.93:1812 to 130.192.119.80:33713 length 49
(12014210) Fri Sep 28 16:27:47 2018: Debug:   EAP-Message = 0x040c0004
(12014210) Fri Sep 28 16:27:47 2018: Debug:   Message-Authenticator =
0x00000000000000000000000000000000
(12014210) Fri Sep 28 16:27:47 2018: Debug:   Proxy-State = 0x313830
(12014187) Fri Sep 28 16:27:47 2018: Debug: Cleaning up request packet ID 3
with timestamp +1919350
(12014188) Fri Sep 28 16:27:48 2018: Debug: Cleaning up request packet ID
31 with timestamp +1919350
(12014189) Fri Sep 28 16:27:48 2018: Debug: Cleaning up request packet ID
254 with timestamp +1919350
(12014190) Fri Sep 28 16:27:48 2018: Debug: Cleaning up request packet ID 4
with timestamp +1919350
(12014191) Fri Sep 28 16:27:48 2018: Debug: Cleaning up request packet ID
76 with timestamp +1919350
(12014192) Fri Sep 28 16:27:48 2018: Debug: Cleaning up request packet ID
13 with timestamp +1919350
(12014206) Fri Sep 28 16:27:51 2018: Debug: Cleaning up request packet ID
114 with timestamp +1919353
(12014207) Fri Sep 28 16:27:51 2018: Debug: Cleaning up request packet ID
34 with timestamp +1919353
(12014208) Fri Sep 28 16:27:51 2018: Debug: Cleaning up request packet ID
199 with timestamp +1919353
(12014210) Fri Sep 28 16:27:51 2018: Debug: Cleaning up request packet ID
247 with timestamp +1919353

-- 
****************************************
Marco Santantonio
Direzione Sistemi Informativi, Portale, E-learning
Sezione Fonia, VoIP e WiFi
www.unito.it
****************************************