authentication error message (eap-ttls)

yukou katori k10lie.tech at yahoo.co.uk
Wed Dec 7 17:12:03 CET 2016


Hi,
I'm trying EAP-TTLS.Now I'm testing with wpa_supplicant-2.5 for preparation.But I got the following error.This is freeradius-3.0.11(and openssl-1.0.2g).I didn't customize mods-available/eap at all.
Anybody can suggest what could be wrong?
Regards,
/// error in debug by radiusd -XX:Thu Dec  8 00:32:06 2016 : ERROR: (7) eap: Failed continuing EAP MD5 (4) session.  EAP sub-module failedThu Dec  8 00:32:06 2016 : Debug: (7) eap: Sending EAP Failure (code 4) ID 1 length 4Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Failed in EAP selectThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authenticate]: returned from eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [eap] = invalidThu Dec  8 00:32:06 2016 : Debug: (7)     } # authenticate = invalidThu Dec  8 00:32:06 2016 : Debug: (7)   Failed to authenticate the userThu Dec  8 00:32:06 2016 : Auth: (7)   Login incorrect (eap: Failed continuing EAP MD5 (4) session.  EAP sub-module failed): [eapol_test at aikon.jp] (from client localhost port 0 via TLS tunnel)(snip)Thu Dec  8 00:32:07 2016 : Debug: (7) Sent Access-Reject Id 7 from 127.0.0.1:1812 to 127.0.0.1:54818 length 44
/// compiling command:freeradius:./configure --with-openssl --with-openssl-lib-dir=/usr/local/openssl/lib --with-openssl-include-dir=/usr/local/openssl/includeopenssl:./config shared --prefix=/usr/local/openssl
/// config of wpa_supplicant-2.5cat eap-ttls.confnetwork={        eap=TTLS        identity="eapol_test at aikon.jp"        anonymous_identity="anonymous"        password="tester"        phase2="autheap=MD5"}# https://networkradius.com/doc/FreeRADIUS-Implementation-Ch6.pdf
/// executing command by wpa_supplicant-2.5:./eapol_test -c eap-ttls.conf -s  tester -a 127.0.0.1
/// config of "users":cat /usr/local/etc/raddb/userseapol_test at aikon.jp     Cleartext-Password := "tester"
/// config of "clients.conf"client localhost {        ipaddr                          = 127.0.0.1        proto                           = *        secret                          = tester        require_message_authenticator   = no        nas_type                        = other        limit {                max_connections = 16                lifetime        = 0                idle_timeout    = 30        }}
/// whole debug:Thu Dec  8 00:32:06 2016 : Debug: (0) Received Access-Request Id 0 from 127.0.0.1:54818 to 127.0.0.1:1812 length 126Thu Dec  8 00:32:06 2016 : Debug: (0)   User-Name = "anonymous"Thu Dec  8 00:32:06 2016 : Debug: (0)   NAS-IP-Address = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (0)   Calling-Station-Id = "02-00-00-00-00-01"Thu Dec  8 00:32:06 2016 : Debug: (0)   Framed-MTU = 1400Thu Dec  8 00:32:06 2016 : Debug: (0)   NAS-Port-Type = Wireless-802.11Thu Dec  8 00:32:06 2016 : Debug: (0)   Connect-Info = "CONNECT 11Mbps 802.11b"Thu Dec  8 00:32:06 2016 : Debug: (0)   EAP-Message = 0x0200000e01616e6f6e796d6f7573Thu Dec  8 00:32:06 2016 : Debug: (0)   Message-Authenticator = 0x6a5b44af24891d9347e01cbd71cec798Thu Dec  8 00:32:06 2016 : Debug: (0) session-state: No State attributeThu Dec  8 00:32:06 2016 : Debug: (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (0)   authorize {Thu Dec  8 00:32:06 2016 : Debug: (0)     policy filter_username {Thu Dec  8 00:32:06 2016 : Debug: (0)       if (&User-Name) {Thu Dec  8 00:32:06 2016 : Debug: (0)       if (&User-Name)  -> TRUEThu Dec  8 00:32:06 2016 : Debug: (0)       if (&User-Name)  {Thu Dec  8 00:32:06 2016 : Debug: (0)         if (&User-Name =~ / /) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (0)         if (&User-Name =~ / /)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (0)         if (&User-Name =~ /@[^@]*@/ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (0)         if (&User-Name =~ /@[^@]*@/ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (0)         if (&User-Name =~ /\.\./ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (0)         if (&User-Name =~ /\.\./ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (0)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (0)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (0)         if (&User-Name =~ /\.$/)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (0)         if (&User-Name =~ /\.$/)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (0)         if (&User-Name =~ /@\./)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (0)         if (&User-Name =~ /@\./)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (0)       } # if (&User-Name)  = notfoundThu Dec  8 00:32:06 2016 : Debug: (0)     } # policy filter_username = notfoundThu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     [preprocess] = okThu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: calling chap (rlm_chap) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: returned from chap (rlm_chap) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     [chap] = noopThu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: calling mschap (rlm_mschap) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     [mschap] = noopThu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: calling digest (rlm_digest) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: returned from digest (rlm_digest) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     [digest] = noopThu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: calling suffix (rlm_realm) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0) suffix: Checking for suffix after "@"Thu Dec  8 00:32:06 2016 : Debug: (0) suffix: No '@' in User-Name = "anonymous", looking up realm NULLThu Dec  8 00:32:06 2016 : Debug: (0) suffix: No such realm "NULL"Thu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: returned from suffix (rlm_realm) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     [suffix] = noopThu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: calling eap (rlm_eap) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0) eap: Peer sent EAP Response (code 2) ID 0 length 14Thu Dec  8 00:32:06 2016 : Debug: (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorizeThu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authorize]: returned from eap (rlm_eap) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     [eap] = okThu Dec  8 00:32:06 2016 : Debug: (0)   } # authorize = okThu Dec  8 00:32:06 2016 : Debug: (0) Found Auth-Type = eapThu Dec  8 00:32:06 2016 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (0)   authenticate {Thu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authenticate]: calling eap (rlm_eap) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0) eap: Peer sent packet with method EAP Identity (1)Thu Dec  8 00:32:06 2016 : Debug: (0) eap: Calling submodule eap_md5 to process dataThu Dec  8 00:32:06 2016 : Debug: (0) eap_md5: Issuing MD5 ChallengeThu Dec  8 00:32:06 2016 : Debug: (0) eap: Sending EAP Request (code 1) ID 1 length 22Thu Dec  8 00:32:06 2016 : Debug: (0) eap: EAP session adding &reply:State = 0x10c1717110c075fcThu Dec  8 00:32:06 2016 : Debug: (0)     modsingle[authenticate]: returned from eap (rlm_eap) for request 0Thu Dec  8 00:32:06 2016 : Debug: (0)     [eap] = handledThu Dec  8 00:32:06 2016 : Debug: (0)   } # authenticate = handledThu Dec  8 00:32:06 2016 : Debug: (0) Using Post-Auth-Type ChallengeThu Dec  8 00:32:06 2016 : Debug: (0) Post-Auth-Type sub-section not found.  Ignoring.Thu Dec  8 00:32:06 2016 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (0) session-state: Nothing to cacheThu Dec  8 00:32:06 2016 : Debug: (0) Sent Access-Challenge Id 0 from 127.0.0.1:1812 to 127.0.0.1:54818 length 0Thu Dec  8 00:32:06 2016 : Debug: (0)   EAP-Message = 0x010100160410148be0314430ffefaa02aa4393a87209Thu Dec  8 00:32:06 2016 : Debug: (0)   Message-Authenticator = 0x00000000000000000000000000000000Thu Dec  8 00:32:06 2016 : Debug: (0)   State = 0x10c1717110c075fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (0) Finished requestThu Dec  8 00:32:06 2016 : Debug: Waking up in 4.9 seconds.Thu Dec  8 00:32:06 2016 : Debug: (1) Received Access-Request Id 1 from 127.0.0.1:54818 to 127.0.0.1:1812 length 136Thu Dec  8 00:32:06 2016 : Debug: (1)   User-Name = "anonymous"Thu Dec  8 00:32:06 2016 : Debug: (1)   NAS-IP-Address = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (1)   Calling-Station-Id = "02-00-00-00-00-01"Thu Dec  8 00:32:06 2016 : Debug: (1)   Framed-MTU = 1400Thu Dec  8 00:32:06 2016 : Debug: (1)   NAS-Port-Type = Wireless-802.11Thu Dec  8 00:32:06 2016 : Debug: (1)   Connect-Info = "CONNECT 11Mbps 802.11b"Thu Dec  8 00:32:06 2016 : Debug: (1)   EAP-Message = 0x020100060315Thu Dec  8 00:32:06 2016 : Debug: (1)   State = 0x10c1717110c075fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (1)   Message-Authenticator = 0x931aa8ba75de18053d596ecb4e0fcccdThu Dec  8 00:32:06 2016 : Debug: (1) session-state: No cached attributesThu Dec  8 00:32:06 2016 : Debug: (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (1)   authorize {Thu Dec  8 00:32:06 2016 : Debug: (1)     policy filter_username {Thu Dec  8 00:32:06 2016 : Debug: (1)       if (&User-Name) {Thu Dec  8 00:32:06 2016 : Debug: (1)       if (&User-Name)  -> TRUEThu Dec  8 00:32:06 2016 : Debug: (1)       if (&User-Name)  {Thu Dec  8 00:32:06 2016 : Debug: (1)         if (&User-Name =~ / /) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (1)         if (&User-Name =~ / /)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (1)         if (&User-Name =~ /@[^@]*@/ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (1)         if (&User-Name =~ /@[^@]*@/ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (1)         if (&User-Name =~ /\.\./ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (1)         if (&User-Name =~ /\.\./ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (1)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (1)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (1)         if (&User-Name =~ /\.$/)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (1)         if (&User-Name =~ /\.$/)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (1)         if (&User-Name =~ /@\./)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (1)         if (&User-Name =~ /@\./)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (1)       } # if (&User-Name)  = notfoundThu Dec  8 00:32:06 2016 : Debug: (1)     } # policy filter_username = notfoundThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [preprocess] = okThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: calling chap (rlm_chap) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: returned from chap (rlm_chap) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [chap] = noopThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: calling mschap (rlm_mschap) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [mschap] = noopThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: calling digest (rlm_digest) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: returned from digest (rlm_digest) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [digest] = noopThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: calling suffix (rlm_realm) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1) suffix: Checking for suffix after "@"Thu Dec  8 00:32:06 2016 : Debug: (1) suffix: No '@' in User-Name = "anonymous", looking up realm NULLThu Dec  8 00:32:06 2016 : Debug: (1) suffix: No such realm "NULL"Thu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: returned from suffix (rlm_realm) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [suffix] = noopThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: calling eap (rlm_eap) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1) eap: Peer sent EAP Response (code 2) ID 1 length 6Thu Dec  8 00:32:06 2016 : Debug: (1) eap: No EAP Start, assuming it's an on-going EAP conversationThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: returned from eap (rlm_eap) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [eap] = updatedThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: calling files (rlm_files) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: returned from files (rlm_files) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [files] = noopThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: calling expiration (rlm_expiration) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: returned from expiration (rlm_expiration) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [expiration] = noopThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: calling logintime (rlm_logintime) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: returned from logintime (rlm_logintime) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [logintime] = noopThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: calling pap (rlm_pap) for request 1Thu Dec  8 00:32:06 2016 : WARNING: (1) pap: No "known good" password found for the user.  Not setting Auth-TypeThu Dec  8 00:32:06 2016 : WARNING: (1) pap: Authentication will fail unless a "known good" password is availableThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authorize]: returned from pap (rlm_pap) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [pap] = noopThu Dec  8 00:32:06 2016 : Debug: (1)   } # authorize = updatedThu Dec  8 00:32:06 2016 : Debug: (1) Found Auth-Type = eapThu Dec  8 00:32:06 2016 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (1)   authenticate {Thu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authenticate]: calling eap (rlm_eap) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1) eap: Expiring EAP session with state 0x10c1717110c075fcThu Dec  8 00:32:06 2016 : Debug: (1) eap: Finished EAP session with state 0x10c1717110c075fcThu Dec  8 00:32:06 2016 : Debug: (1) eap: Previous EAP request found for state 0x10c1717110c075fc, released from the listThu Dec  8 00:32:06 2016 : Debug: (1) eap: Peer sent packet with method EAP NAK (3)Thu Dec  8 00:32:06 2016 : Debug: (1) eap: Found mutually acceptable type TTLS (21)Thu Dec  8 00:32:06 2016 : Debug: (1) eap: Calling submodule eap_ttls to process dataThu Dec  8 00:32:06 2016 : Debug: (1) eap_ttls: Initiating new EAP-TLS sessionThu Dec  8 00:32:06 2016 : Debug: (1) eap_ttls: Flushing SSL sessions (of #0)Thu Dec  8 00:32:06 2016 : Debug: (1) eap_ttls: [eaptls start] = requestThu Dec  8 00:32:06 2016 : Debug: (1) eap: Sending EAP Request (code 1) ID 2 length 6Thu Dec  8 00:32:06 2016 : Debug: (1) eap: EAP session adding &reply:State = 0x10c1717111c364fcThu Dec  8 00:32:06 2016 : Debug: (1)     modsingle[authenticate]: returned from eap (rlm_eap) for request 1Thu Dec  8 00:32:06 2016 : Debug: (1)     [eap] = handledThu Dec  8 00:32:06 2016 : Debug: (1)   } # authenticate = handledThu Dec  8 00:32:06 2016 : Debug: (1) Using Post-Auth-Type ChallengeThu Dec  8 00:32:06 2016 : Debug: (1) Post-Auth-Type sub-section not found.  Ignoring.Thu Dec  8 00:32:06 2016 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (1) session-state: Nothing to cacheThu Dec  8 00:32:06 2016 : Debug: (1) Sent Access-Challenge Id 1 from 127.0.0.1:1812 to 127.0.0.1:54818 length 0Thu Dec  8 00:32:06 2016 : Debug: (1)   EAP-Message = 0x010200061520Thu Dec  8 00:32:06 2016 : Debug: (1)   Message-Authenticator = 0x00000000000000000000000000000000Thu Dec  8 00:32:06 2016 : Debug: (1)   State = 0x10c1717111c364fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (1) Finished requestThu Dec  8 00:32:06 2016 : Debug: Waking up in 4.9 seconds.Thu Dec  8 00:32:06 2016 : Debug: (2) Received Access-Request Id 2 from 127.0.0.1:54818 to 127.0.0.1:1812 length 423Thu Dec  8 00:32:06 2016 : Debug: (2)   User-Name = "anonymous"Thu Dec  8 00:32:06 2016 : Debug: (2)   NAS-IP-Address = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (2)   Calling-Station-Id = "02-00-00-00-00-01"Thu Dec  8 00:32:06 2016 : Debug: (2)   Framed-MTU = 1400Thu Dec  8 00:32:06 2016 : Debug: (2)   NAS-Port-Type = Wireless-802.11Thu Dec  8 00:32:06 2016 : Debug: (2)   Connect-Info = "CONNECT 11Mbps 802.11b"Thu Dec  8 00:32:06 2016 : Debug: (2)   EAP-Message = 0x0202012315001603010118010001140303cae0610d1e6b8100c007621e34def0ebe6cf945950b45515aba196cc342a1288000082c030c02cc028c024c014c00a00a3009f006b006a0039003800880087c032c02ec02ac026c00fc005009d003d00350084c012c00800160013c00dc003000ac02fc02bc0Thu Dec  8 00:32:06 2016 : Debug: (2)   State = 0x10c1717111c364fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (2)   Message-Authenticator = 0x910cc0b973e5dbf44407b7281379ebf2Thu Dec  8 00:32:06 2016 : Debug: (2) session-state: No cached attributesThu Dec  8 00:32:06 2016 : Debug: (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (2)   authorize {Thu Dec  8 00:32:06 2016 : Debug: (2)     policy filter_username {Thu Dec  8 00:32:06 2016 : Debug: (2)       if (&User-Name) {Thu Dec  8 00:32:06 2016 : Debug: (2)       if (&User-Name)  -> TRUEThu Dec  8 00:32:06 2016 : Debug: (2)       if (&User-Name)  {Thu Dec  8 00:32:06 2016 : Debug: (2)         if (&User-Name =~ / /) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (2)         if (&User-Name =~ / /)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (2)         if (&User-Name =~ /@[^@]*@/ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (2)         if (&User-Name =~ /@[^@]*@/ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (2)         if (&User-Name =~ /\.\./ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (2)         if (&User-Name =~ /\.\./ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (2)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (2)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (2)         if (&User-Name =~ /\.$/)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (2)         if (&User-Name =~ /\.$/)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (2)         if (&User-Name =~ /@\./)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (2)         if (&User-Name =~ /@\./)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (2)       } # if (&User-Name)  = notfoundThu Dec  8 00:32:06 2016 : Debug: (2)     } # policy filter_username = notfoundThu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     [preprocess] = okThu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: calling chap (rlm_chap) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: returned from chap (rlm_chap) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     [chap] = noopThu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: calling mschap (rlm_mschap) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     [mschap] = noopThu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: calling digest (rlm_digest) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: returned from digest (rlm_digest) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     [digest] = noopThu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: calling suffix (rlm_realm) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2) suffix: Checking for suffix after "@"Thu Dec  8 00:32:06 2016 : Debug: (2) suffix: No '@' in User-Name = "anonymous", looking up realm NULLThu Dec  8 00:32:06 2016 : Debug: (2) suffix: No such realm "NULL"Thu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: returned from suffix (rlm_realm) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     [suffix] = noopThu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: calling eap (rlm_eap) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2) eap: Peer sent EAP Response (code 2) ID 2 length 291Thu Dec  8 00:32:06 2016 : Debug: (2) eap: Continuing tunnel setupThu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authorize]: returned from eap (rlm_eap) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     [eap] = okThu Dec  8 00:32:06 2016 : Debug: (2)   } # authorize = okThu Dec  8 00:32:06 2016 : Debug: (2) Found Auth-Type = eapThu Dec  8 00:32:06 2016 : Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (2)   authenticate {Thu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authenticate]: calling eap (rlm_eap) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2) eap: Expiring EAP session with state 0x10c1717111c364fcThu Dec  8 00:32:06 2016 : Debug: (2) eap: Finished EAP session with state 0x10c1717111c364fcThu Dec  8 00:32:06 2016 : Debug: (2) eap: Previous EAP request found for state 0x10c1717111c364fc, released from the listThu Dec  8 00:32:06 2016 : Debug: (2) eap: Peer sent packet with method EAP TTLS (21)Thu Dec  8 00:32:06 2016 : Debug: (2) eap: Calling submodule eap_ttls to process dataThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: AuthenticateThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: Continuing EAP-TLSThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: Peer sent flags ---Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: [eaptls verify] = okThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: Done initial handshakeThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: (other): before/accept initializationThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: TLS_accept: before/accept initializationThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: <<< recv TLS 1.2  [length 0118]Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: TLS_accept: SSLv3 read client hello AThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: >>> send TLS 1.2  [length 005e]Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: TLS_accept: SSLv3 write server hello AThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: >>> send TLS 1.2  [length 0813]Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: TLS_accept: SSLv3 write certificate AThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: >>> send TLS 1.2  [length 014d]Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: TLS_accept: SSLv3 write key exchange AThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: >>> send TLS 1.2  [length 0004]Thu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: TLS_accept: SSLv3 write server done AThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: TLS_accept: SSLv3 flush dataThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: TLS_accept: SSLv3 read client certificate AThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client key exchange AThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client key exchange AThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: In SSL Handshake PhaseThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: In SSL Accept modeThu Dec  8 00:32:06 2016 : Debug: (2) eap_ttls: [eaptls process] = handledThu Dec  8 00:32:06 2016 : Debug: (2) eap: Sending EAP Request (code 1) ID 3 length 1004Thu Dec  8 00:32:06 2016 : Debug: (2) eap: EAP session adding &reply:State = 0x10c1717112c264fcThu Dec  8 00:32:06 2016 : Debug: (2)     modsingle[authenticate]: returned from eap (rlm_eap) for request 2Thu Dec  8 00:32:06 2016 : Debug: (2)     [eap] = handledThu Dec  8 00:32:06 2016 : Debug: (2)   } # authenticate = handledThu Dec  8 00:32:06 2016 : Debug: (2) Using Post-Auth-Type ChallengeThu Dec  8 00:32:06 2016 : Debug: (2) Post-Auth-Type sub-section not found.  Ignoring.Thu Dec  8 00:32:06 2016 : Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (2) session-state: Nothing to cacheThu Dec  8 00:32:06 2016 : Debug: (2) Sent Access-Challenge Id 2 from 127.0.0.1:1812 to 127.0.0.1:54818 length 0Thu Dec  8 00:32:06 2016 : Debug: (2)   EAP-Message = 0x010303ec15c0000009d6160303005e0200005a03039e4ca71cf04c8e662d2936617c41d9f3a5b54ea05741888a6f933888fec2110d203344cf5126fb4cf727a39331e315f534a64dde1d6d8c12c35b10a710ec96d857c030000012ff01000100000b000403000102000f00010116030308130b00080f00Thu Dec  8 00:32:06 2016 : Debug: (2)   Message-Authenticator = 0x00000000000000000000000000000000Thu Dec  8 00:32:06 2016 : Debug: (2)   State = 0x10c1717112c264fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (2) Finished requestThu Dec  8 00:32:06 2016 : Debug: Waking up in 4.9 seconds.Thu Dec  8 00:32:06 2016 : Debug: (3) Received Access-Request Id 3 from 127.0.0.1:54818 to 127.0.0.1:1812 length 136Thu Dec  8 00:32:06 2016 : Debug: (3)   User-Name = "anonymous"Thu Dec  8 00:32:06 2016 : Debug: (3)   NAS-IP-Address = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (3)   Calling-Station-Id = "02-00-00-00-00-01"Thu Dec  8 00:32:06 2016 : Debug: (3)   Framed-MTU = 1400Thu Dec  8 00:32:06 2016 : Debug: (3)   NAS-Port-Type = Wireless-802.11Thu Dec  8 00:32:06 2016 : Debug: (3)   Connect-Info = "CONNECT 11Mbps 802.11b"Thu Dec  8 00:32:06 2016 : Debug: (3)   EAP-Message = 0x020300061500Thu Dec  8 00:32:06 2016 : Debug: (3)   State = 0x10c1717112c264fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (3)   Message-Authenticator = 0x9f42a30edc80a507954951c07a942441Thu Dec  8 00:32:06 2016 : Debug: (3) session-state: No cached attributesThu Dec  8 00:32:06 2016 : Debug: (3) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (3)   authorize {Thu Dec  8 00:32:06 2016 : Debug: (3)     policy filter_username {Thu Dec  8 00:32:06 2016 : Debug: (3)       if (&User-Name) {Thu Dec  8 00:32:06 2016 : Debug: (3)       if (&User-Name)  -> TRUEThu Dec  8 00:32:06 2016 : Debug: (3)       if (&User-Name)  {Thu Dec  8 00:32:06 2016 : Debug: (3)         if (&User-Name =~ / /) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (3)         if (&User-Name =~ / /)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (3)         if (&User-Name =~ /@[^@]*@/ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (3)         if (&User-Name =~ /@[^@]*@/ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (3)         if (&User-Name =~ /\.\./ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (3)         if (&User-Name =~ /\.\./ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (3)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (3)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (3)         if (&User-Name =~ /\.$/)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (3)         if (&User-Name =~ /\.$/)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (3)         if (&User-Name =~ /@\./)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (3)         if (&User-Name =~ /@\./)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (3)       } # if (&User-Name)  = notfoundThu Dec  8 00:32:06 2016 : Debug: (3)     } # policy filter_username = notfoundThu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     [preprocess] = okThu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: calling chap (rlm_chap) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: returned from chap (rlm_chap) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     [chap] = noopThu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: calling mschap (rlm_mschap) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     [mschap] = noopThu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: calling digest (rlm_digest) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: returned from digest (rlm_digest) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     [digest] = noopThu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: calling suffix (rlm_realm) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3) suffix: Checking for suffix after "@"Thu Dec  8 00:32:06 2016 : Debug: (3) suffix: No '@' in User-Name = "anonymous", looking up realm NULLThu Dec  8 00:32:06 2016 : Debug: (3) suffix: No such realm "NULL"Thu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: returned from suffix (rlm_realm) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     [suffix] = noopThu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: calling eap (rlm_eap) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3) eap: Peer sent EAP Response (code 2) ID 3 length 6Thu Dec  8 00:32:06 2016 : Debug: (3) eap: Continuing tunnel setupThu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authorize]: returned from eap (rlm_eap) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     [eap] = okThu Dec  8 00:32:06 2016 : Debug: (3)   } # authorize = okThu Dec  8 00:32:06 2016 : Debug: (3) Found Auth-Type = eapThu Dec  8 00:32:06 2016 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (3)   authenticate {Thu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authenticate]: calling eap (rlm_eap) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3) eap: Expiring EAP session with state 0x10c1717112c264fcThu Dec  8 00:32:06 2016 : Debug: (3) eap: Finished EAP session with state 0x10c1717112c264fcThu Dec  8 00:32:06 2016 : Debug: (3) eap: Previous EAP request found for state 0x10c1717112c264fc, released from the listThu Dec  8 00:32:06 2016 : Debug: (3) eap: Peer sent packet with method EAP TTLS (21)Thu Dec  8 00:32:06 2016 : Debug: (3) eap: Calling submodule eap_ttls to process dataThu Dec  8 00:32:06 2016 : Debug: (3) eap_ttls: AuthenticateThu Dec  8 00:32:06 2016 : Debug: (3) eap_ttls: Continuing EAP-TLSThu Dec  8 00:32:06 2016 : Debug: (3) eap_ttls: Peer sent flags ---Thu Dec  8 00:32:06 2016 : Debug: (3) eap_ttls: Peer ACKed our handshake fragmentThu Dec  8 00:32:06 2016 : Debug: (3) eap_ttls: [eaptls verify] = requestThu Dec  8 00:32:06 2016 : Debug: (3) eap_ttls: [eaptls process] = handledThu Dec  8 00:32:06 2016 : Debug: (3) eap: Sending EAP Request (code 1) ID 4 length 1004Thu Dec  8 00:32:06 2016 : Debug: (3) eap: EAP session adding &reply:State = 0x10c1717113c564fcThu Dec  8 00:32:06 2016 : Debug: (3)     modsingle[authenticate]: returned from eap (rlm_eap) for request 3Thu Dec  8 00:32:06 2016 : Debug: (3)     [eap] = handledThu Dec  8 00:32:06 2016 : Debug: (3)   } # authenticate = handledThu Dec  8 00:32:06 2016 : Debug: (3) Using Post-Auth-Type ChallengeThu Dec  8 00:32:06 2016 : Debug: (3) Post-Auth-Type sub-section not found.  Ignoring.Thu Dec  8 00:32:06 2016 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (3) session-state: Nothing to cacheThu Dec  8 00:32:06 2016 : Debug: (3) Sent Access-Challenge Id 3 from 127.0.0.1:1812 to 127.0.0.1:54818 length 0Thu Dec  8 00:32:06 2016 : Debug: (3)   EAP-Message = 0x010403ec15c0000009d6add6d7bffc0f82cf52e869ceddc3a2612a034c6143e26901836d38631698ce516bd8bf8bc1a41f19bc403054b7ae6a0ff6bcd57233f0d9771c3123bfc18ca1c19f8b9d2eb9b44e27397129f22af1f806ec15491dbddd9505ff28bda45dfcfb77430f3abad91cc809df05032072Thu Dec  8 00:32:06 2016 : Debug: (3)   Message-Authenticator = 0x00000000000000000000000000000000Thu Dec  8 00:32:06 2016 : Debug: (3)   State = 0x10c1717113c564fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (3) Finished requestThu Dec  8 00:32:06 2016 : Debug: Waking up in 4.9 seconds.Thu Dec  8 00:32:06 2016 : Debug: (4) Received Access-Request Id 4 from 127.0.0.1:54818 to 127.0.0.1:1812 length 136Thu Dec  8 00:32:06 2016 : Debug: (4)   User-Name = "anonymous"Thu Dec  8 00:32:06 2016 : Debug: (4)   NAS-IP-Address = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (4)   Calling-Station-Id = "02-00-00-00-00-01"Thu Dec  8 00:32:06 2016 : Debug: (4)   Framed-MTU = 1400Thu Dec  8 00:32:06 2016 : Debug: (4)   NAS-Port-Type = Wireless-802.11Thu Dec  8 00:32:06 2016 : Debug: (4)   Connect-Info = "CONNECT 11Mbps 802.11b"Thu Dec  8 00:32:06 2016 : Debug: (4)   EAP-Message = 0x020400061500Thu Dec  8 00:32:06 2016 : Debug: (4)   State = 0x10c1717113c564fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (4)   Message-Authenticator = 0x54d84b9e194fc9f2e4f34e2c0e1a757eThu Dec  8 00:32:06 2016 : Debug: (4) session-state: No cached attributesThu Dec  8 00:32:06 2016 : Debug: (4) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (4)   authorize {Thu Dec  8 00:32:06 2016 : Debug: (4)     policy filter_username {Thu Dec  8 00:32:06 2016 : Debug: (4)       if (&User-Name) {Thu Dec  8 00:32:06 2016 : Debug: (4)       if (&User-Name)  -> TRUEThu Dec  8 00:32:06 2016 : Debug: (4)       if (&User-Name)  {Thu Dec  8 00:32:06 2016 : Debug: (4)         if (&User-Name =~ / /) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (4)         if (&User-Name =~ / /)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (4)         if (&User-Name =~ /@[^@]*@/ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (4)         if (&User-Name =~ /@[^@]*@/ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (4)         if (&User-Name =~ /\.\./ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (4)         if (&User-Name =~ /\.\./ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (4)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (4)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (4)         if (&User-Name =~ /\.$/)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (4)         if (&User-Name =~ /\.$/)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (4)         if (&User-Name =~ /@\./)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (4)         if (&User-Name =~ /@\./)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (4)       } # if (&User-Name)  = notfoundThu Dec  8 00:32:06 2016 : Debug: (4)     } # policy filter_username = notfoundThu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     [preprocess] = okThu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: calling chap (rlm_chap) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: returned from chap (rlm_chap) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     [chap] = noopThu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: calling mschap (rlm_mschap) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     [mschap] = noopThu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: calling digest (rlm_digest) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: returned from digest (rlm_digest) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     [digest] = noopThu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: calling suffix (rlm_realm) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4) suffix: Checking for suffix after "@"Thu Dec  8 00:32:06 2016 : Debug: (4) suffix: No '@' in User-Name = "anonymous", looking up realm NULLThu Dec  8 00:32:06 2016 : Debug: (4) suffix: No such realm "NULL"Thu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: returned from suffix (rlm_realm) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     [suffix] = noopThu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: calling eap (rlm_eap) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4) eap: Peer sent EAP Response (code 2) ID 4 length 6Thu Dec  8 00:32:06 2016 : Debug: (4) eap: Continuing tunnel setupThu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authorize]: returned from eap (rlm_eap) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     [eap] = okThu Dec  8 00:32:06 2016 : Debug: (4)   } # authorize = okThu Dec  8 00:32:06 2016 : Debug: (4) Found Auth-Type = eapThu Dec  8 00:32:06 2016 : Debug: (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (4)   authenticate {Thu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authenticate]: calling eap (rlm_eap) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4) eap: Expiring EAP session with state 0x10c1717113c564fcThu Dec  8 00:32:06 2016 : Debug: (4) eap: Finished EAP session with state 0x10c1717113c564fcThu Dec  8 00:32:06 2016 : Debug: (4) eap: Previous EAP request found for state 0x10c1717113c564fc, released from the listThu Dec  8 00:32:06 2016 : Debug: (4) eap: Peer sent packet with method EAP TTLS (21)Thu Dec  8 00:32:06 2016 : Debug: (4) eap: Calling submodule eap_ttls to process dataThu Dec  8 00:32:06 2016 : Debug: (4) eap_ttls: AuthenticateThu Dec  8 00:32:06 2016 : Debug: (4) eap_ttls: Continuing EAP-TLSThu Dec  8 00:32:06 2016 : Debug: (4) eap_ttls: Peer sent flags ---Thu Dec  8 00:32:06 2016 : Debug: (4) eap_ttls: Peer ACKed our handshake fragmentThu Dec  8 00:32:06 2016 : Debug: (4) eap_ttls: [eaptls verify] = requestThu Dec  8 00:32:06 2016 : Debug: (4) eap_ttls: [eaptls process] = handledThu Dec  8 00:32:06 2016 : Debug: (4) eap: Sending EAP Request (code 1) ID 5 length 540Thu Dec  8 00:32:06 2016 : Debug: (4) eap: EAP session adding &reply:State = 0x10c1717114c464fcThu Dec  8 00:32:06 2016 : Debug: (4)     modsingle[authenticate]: returned from eap (rlm_eap) for request 4Thu Dec  8 00:32:06 2016 : Debug: (4)     [eap] = handledThu Dec  8 00:32:06 2016 : Debug: (4)   } # authenticate = handledThu Dec  8 00:32:06 2016 : Debug: (4) Using Post-Auth-Type ChallengeThu Dec  8 00:32:06 2016 : Debug: (4) Post-Auth-Type sub-section not found.  Ignoring.Thu Dec  8 00:32:06 2016 : Debug: (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (4) session-state: Nothing to cacheThu Dec  8 00:32:06 2016 : Debug: (4) Sent Access-Challenge Id 4 from 127.0.0.1:1812 to 127.0.0.1:54818 length 0Thu Dec  8 00:32:06 2016 : Debug: (4)   EAP-Message = 0x0105021c1580000009d6cf3138ddf0922ae5628ffcfed6f592c1d5cca8d32af57f60de724642996952991b8d6f0078f6b530bb3b269c6735e97bb69f59773a5eed5d161a61b433cbfc8264257c2211af3bb752f857422cd4b639c6949edf2cfcdbf6842b7486ae2e5eb3af34e54a0de2ad5167953b036eThu Dec  8 00:32:06 2016 : Debug: (4)   Message-Authenticator = 0x00000000000000000000000000000000Thu Dec  8 00:32:06 2016 : Debug: (4)   State = 0x10c1717114c464fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (4) Finished requestThu Dec  8 00:32:06 2016 : Debug: Waking up in 4.9 seconds.Thu Dec  8 00:32:06 2016 : Debug: (5) Received Access-Request Id 5 from 127.0.0.1:54818 to 127.0.0.1:1812 length 262Thu Dec  8 00:32:06 2016 : Debug: (5)   User-Name = "anonymous"Thu Dec  8 00:32:06 2016 : Debug: (5)   NAS-IP-Address = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (5)   Calling-Station-Id = "02-00-00-00-00-01"Thu Dec  8 00:32:06 2016 : Debug: (5)   Framed-MTU = 1400Thu Dec  8 00:32:06 2016 : Debug: (5)   NAS-Port-Type = Wireless-802.11Thu Dec  8 00:32:06 2016 : Debug: (5)   Connect-Info = "CONNECT 11Mbps 802.11b"Thu Dec  8 00:32:06 2016 : Debug: (5)   EAP-Message = 0x020500841500160303004610000042410463a7f35b4f786657607e68c82ab4c2c506d9b924d1a9d7f7ac206bece71d89b09ef287573206209a61e433957cec614a0ea4a9fbd1f74d408c090a9e9a681a0a14030300010116030300282551dc6df862b4c0b9b3d9966d271166a153c14d3a16888963f35fThu Dec  8 00:32:06 2016 : Debug: (5)   State = 0x10c1717114c464fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (5)   Message-Authenticator = 0x85f0021449b941960ec494ca1f4dfd33Thu Dec  8 00:32:06 2016 : Debug: (5) session-state: No cached attributesThu Dec  8 00:32:06 2016 : Debug: (5) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (5)   authorize {Thu Dec  8 00:32:06 2016 : Debug: (5)     policy filter_username {Thu Dec  8 00:32:06 2016 : Debug: (5)       if (&User-Name) {Thu Dec  8 00:32:06 2016 : Debug: (5)       if (&User-Name)  -> TRUEThu Dec  8 00:32:06 2016 : Debug: (5)       if (&User-Name)  {Thu Dec  8 00:32:06 2016 : Debug: (5)         if (&User-Name =~ / /) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (5)         if (&User-Name =~ / /)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (5)         if (&User-Name =~ /@[^@]*@/ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (5)         if (&User-Name =~ /@[^@]*@/ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (5)         if (&User-Name =~ /\.\./ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (5)         if (&User-Name =~ /\.\./ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (5)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (5)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (5)         if (&User-Name =~ /\.$/)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (5)         if (&User-Name =~ /\.$/)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (5)         if (&User-Name =~ /@\./)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (5)         if (&User-Name =~ /@\./)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (5)       } # if (&User-Name)  = notfoundThu Dec  8 00:32:06 2016 : Debug: (5)     } # policy filter_username = notfoundThu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     [preprocess] = okThu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: calling chap (rlm_chap) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: returned from chap (rlm_chap) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     [chap] = noopThu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: calling mschap (rlm_mschap) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     [mschap] = noopThu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: calling digest (rlm_digest) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: returned from digest (rlm_digest) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     [digest] = noopThu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: calling suffix (rlm_realm) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5) suffix: Checking for suffix after "@"Thu Dec  8 00:32:06 2016 : Debug: (5) suffix: No '@' in User-Name = "anonymous", looking up realm NULLThu Dec  8 00:32:06 2016 : Debug: (5) suffix: No such realm "NULL"Thu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: returned from suffix (rlm_realm) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     [suffix] = noopThu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: calling eap (rlm_eap) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5) eap: Peer sent EAP Response (code 2) ID 5 length 132Thu Dec  8 00:32:06 2016 : Debug: (5) eap: Continuing tunnel setupThu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authorize]: returned from eap (rlm_eap) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     [eap] = okThu Dec  8 00:32:06 2016 : Debug: (5)   } # authorize = okThu Dec  8 00:32:06 2016 : Debug: (5) Found Auth-Type = eapThu Dec  8 00:32:06 2016 : Debug: (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (5)   authenticate {Thu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authenticate]: calling eap (rlm_eap) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5) eap: Expiring EAP session with state 0x10c1717114c464fcThu Dec  8 00:32:06 2016 : Debug: (5) eap: Finished EAP session with state 0x10c1717114c464fcThu Dec  8 00:32:06 2016 : Debug: (5) eap: Previous EAP request found for state 0x10c1717114c464fc, released from the listThu Dec  8 00:32:06 2016 : Debug: (5) eap: Peer sent packet with method EAP TTLS (21)Thu Dec  8 00:32:06 2016 : Debug: (5) eap: Calling submodule eap_ttls to process dataThu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: AuthenticateThu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: Continuing EAP-TLSThu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: Peer sent flags ---Thu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: [eaptls verify] = okThu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: Done initial handshakeThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: <<< recv TLS 1.2  [length 0046]Thu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: TLS_accept: SSLv3 read client key exchange AThu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: TLS_accept: SSLv3 read certificate verify AThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: <<< recv TLS 1.2  [length 0001]Thu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: <<< recv TLS 1.2  [length 0010]Thu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: TLS_accept: SSLv3 read finished AThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: >>> send TLS 1.2  [length 0001]Thu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: TLS_accept: SSLv3 write change cipher spec AThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: >>> send TLS 1.2  [length 0010]Thu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: TLS_accept: SSLv3 write finished AThu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: TLS_accept: SSLv3 flush dataThu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: (other): SSL negotiation finished successfullyThu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: SSL Connection EstablishedThu Dec  8 00:32:06 2016 : Debug: (5) eap_ttls: [eaptls process] = handledThu Dec  8 00:32:06 2016 : Debug: (5) eap: Sending EAP Request (code 1) ID 6 length 61Thu Dec  8 00:32:06 2016 : Debug: (5) eap: EAP session adding &reply:State = 0x10c1717115c764fcThu Dec  8 00:32:06 2016 : Debug: (5)     modsingle[authenticate]: returned from eap (rlm_eap) for request 5Thu Dec  8 00:32:06 2016 : Debug: (5)     [eap] = handledThu Dec  8 00:32:06 2016 : Debug: (5)   } # authenticate = handledThu Dec  8 00:32:06 2016 : Debug: (5) Using Post-Auth-Type ChallengeThu Dec  8 00:32:06 2016 : Debug: (5) Post-Auth-Type sub-section not found.  Ignoring.Thu Dec  8 00:32:06 2016 : Debug: (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (5) session-state: Nothing to cacheThu Dec  8 00:32:06 2016 : Debug: (5) Sent Access-Challenge Id 5 from 127.0.0.1:1812 to 127.0.0.1:54818 length 0Thu Dec  8 00:32:06 2016 : Debug: (5)   EAP-Message = 0x0106003d1580000000331403030001011603030028d5b079448020ce1c9bf134d5880343cb224288a99a70bc4cffb37b4b9c97b647b0b50d6777b89330Thu Dec  8 00:32:06 2016 : Debug: (5)   Message-Authenticator = 0x00000000000000000000000000000000Thu Dec  8 00:32:06 2016 : Debug: (5)   State = 0x10c1717115c764fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (5) Finished requestThu Dec  8 00:32:06 2016 : Debug: Waking up in 4.9 seconds.Thu Dec  8 00:32:06 2016 : Debug: (6) Received Access-Request Id 6 from 127.0.0.1:54818 to 127.0.0.1:1812 length 197Thu Dec  8 00:32:06 2016 : Debug: (6)   User-Name = "anonymous"Thu Dec  8 00:32:06 2016 : Debug: (6)   NAS-IP-Address = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (6)   Calling-Station-Id = "02-00-00-00-00-01"Thu Dec  8 00:32:06 2016 : Debug: (6)   Framed-MTU = 1400Thu Dec  8 00:32:06 2016 : Debug: (6)   NAS-Port-Type = Wireless-802.11Thu Dec  8 00:32:06 2016 : Debug: (6)   Connect-Info = "CONNECT 11Mbps 802.11b"Thu Dec  8 00:32:06 2016 : Debug: (6)   EAP-Message = 0x02060043150017030300382551dc6df862b4c1fb3201bf926b3071e7d350336ff5ef1ff5edc880e6d53e93007d8a60473a076291807fbe200f78dcc8890c11e0700e30Thu Dec  8 00:32:06 2016 : Debug: (6)   State = 0x10c1717115c764fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (6)   Message-Authenticator = 0x4d8fb4e15b352bea3f05a46e1b4dbeb6Thu Dec  8 00:32:06 2016 : Debug: (6) session-state: No cached attributesThu Dec  8 00:32:06 2016 : Debug: (6) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (6)   authorize {Thu Dec  8 00:32:06 2016 : Debug: (6)     policy filter_username {Thu Dec  8 00:32:06 2016 : Debug: (6)       if (&User-Name) {Thu Dec  8 00:32:06 2016 : Debug: (6)       if (&User-Name)  -> TRUEThu Dec  8 00:32:06 2016 : Debug: (6)       if (&User-Name)  {Thu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name =~ / /) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name =~ / /)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name =~ /@[^@]*@/ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name =~ /@[^@]*@/ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name =~ /\.\./ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name =~ /\.\./ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (6)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name =~ /\.$/)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name =~ /\.$/)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name =~ /@\./)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name =~ /@\./)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)       } # if (&User-Name)  = notfoundThu Dec  8 00:32:06 2016 : Debug: (6)     } # policy filter_username = notfoundThu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     [preprocess] = okThu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: calling chap (rlm_chap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: returned from chap (rlm_chap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     [chap] = noopThu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: calling mschap (rlm_mschap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     [mschap] = noopThu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: calling digest (rlm_digest) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: returned from digest (rlm_digest) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     [digest] = noopThu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: calling suffix (rlm_realm) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6) suffix: Checking for suffix after "@"Thu Dec  8 00:32:06 2016 : Debug: (6) suffix: No '@' in User-Name = "anonymous", looking up realm NULLThu Dec  8 00:32:06 2016 : Debug: (6) suffix: No such realm "NULL"Thu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: returned from suffix (rlm_realm) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     [suffix] = noopThu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: calling eap (rlm_eap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6) eap: Peer sent EAP Response (code 2) ID 6 length 67Thu Dec  8 00:32:06 2016 : Debug: (6) eap: Continuing tunnel setupThu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authorize]: returned from eap (rlm_eap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     [eap] = okThu Dec  8 00:32:06 2016 : Debug: (6)   } # authorize = okThu Dec  8 00:32:06 2016 : Debug: (6) Found Auth-Type = eapThu Dec  8 00:32:06 2016 : Debug: (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (6)   authenticate {Thu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authenticate]: calling eap (rlm_eap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6) eap: Expiring EAP session with state 0x10c1717115c764fcThu Dec  8 00:32:06 2016 : Debug: (6) eap: Finished EAP session with state 0x10c1717115c764fcThu Dec  8 00:32:06 2016 : Debug: (6) eap: Previous EAP request found for state 0x10c1717115c764fc, released from the listThu Dec  8 00:32:06 2016 : Debug: (6) eap: Peer sent packet with method EAP TTLS (21)Thu Dec  8 00:32:06 2016 : Debug: (6) eap: Calling submodule eap_ttls to process dataThu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: AuthenticateThu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: Continuing EAP-TLSThu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: Peer sent flags ---Thu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: [eaptls verify] = okThu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: Done initial handshakeThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: [eaptls process] = okThu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: Session established.  Proceeding to decode tunneled attributesThu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: Got tunneled requestThu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls:   EAP-Message = 0x02000018016561706f6c5f74657374406e6f6b69612e6a70Thu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls:   FreeRADIUS-Proxied-To = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: Got tunneled identity of eapol_test at aikon.jpThu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: Setting default EAP type for tunneled EAP sessionThu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: Sending tunneled requestThu Dec  8 00:32:06 2016 : Debug: (6) Virtual server inner-tunnel received requestThu Dec  8 00:32:06 2016 : Debug: (6)   EAP-Message = 0x02000018016561706f6c5f74657374406e6f6b69612e6a70Thu Dec  8 00:32:06 2016 : Debug: (6)   FreeRADIUS-Proxied-To = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (6)   User-Name = "eapol_test at aikon.jp"Thu Dec  8 00:32:06 2016 : Debug: (6) server inner-tunnel {Thu Dec  8 00:32:06 2016 : Debug: (6)   session-state: No State attributeThu Dec  8 00:32:06 2016 : Debug: (6)   # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnelThu Dec  8 00:32:06 2016 : Debug: (6)     authorize {Thu Dec  8 00:32:06 2016 : Debug: (6)       policy filter_username {Thu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name) {Thu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name)  -> TRUEThu Dec  8 00:32:06 2016 : Debug: (6)         if (&User-Name)  {Thu Dec  8 00:32:06 2016 : Debug: (6)           if (&User-Name =~ / /) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (6)           if (&User-Name =~ / /)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)           if (&User-Name =~ /@[^@]*@/ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (6)           if (&User-Name =~ /@[^@]*@/ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)           if (&User-Name =~ /\.\./ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (6)           if (&User-Name =~ /\.\./ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: Adding 1 matchesThu Dec  8 00:32:06 2016 : Debug: Clearing 1 matchesThu Dec  8 00:32:06 2016 : Debug: Adding 3 matchesThu Dec  8 00:32:06 2016 : Debug: (6)           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)           if (&User-Name =~ /\.$/)  {Thu Dec  8 00:32:06 2016 : Debug: Clearing 3 matchesThu Dec  8 00:32:06 2016 : Debug: (6)           if (&User-Name =~ /\.$/)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)           if (&User-Name =~ /@\./)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (6)           if (&User-Name =~ /@\./)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (6)         } # if (&User-Name)  = notfoundThu Dec  8 00:32:06 2016 : Debug: (6)       } # policy filter_username = notfoundThu Dec  8 00:32:06 2016 : Debug: (6)       modsingle[authorize]: calling chap (rlm_chap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)       modsingle[authorize]: returned from chap (rlm_chap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)       [chap] = noopThu Dec  8 00:32:06 2016 : Debug: (6)       modsingle[authorize]: calling mschap (rlm_mschap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)       modsingle[authorize]: returned from mschap (rlm_mschap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)       [mschap] = noopThu Dec  8 00:32:06 2016 : Debug: (6)       modsingle[authorize]: calling suffix (rlm_realm) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6) suffix: Checking for suffix after "@"Thu Dec  8 00:32:06 2016 : Debug: (6) suffix: Looking up realm "aikon.jp" for User-Name = "eapol_test at aikon.jp"Thu Dec  8 00:32:06 2016 : Debug: (6) suffix: No such realm "aikon.jp"Thu Dec  8 00:32:06 2016 : Debug: (6)       modsingle[authorize]: returned from suffix (rlm_realm) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)       [suffix] = noopThu Dec  8 00:32:06 2016 : Debug: (6)       update control {Thu Dec  8 00:32:06 2016 : Debug: (6)         &Proxy-To-Realm := LOCALThu Dec  8 00:32:06 2016 : Debug: (6)       } # update control = noopThu Dec  8 00:32:06 2016 : Debug: (6)       modsingle[authorize]: calling eap (rlm_eap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6) eap: Peer sent EAP Response (code 2) ID 0 length 24Thu Dec  8 00:32:06 2016 : Debug: (6) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorizeThu Dec  8 00:32:06 2016 : Debug: (6)       modsingle[authorize]: returned from eap (rlm_eap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)       [eap] = okThu Dec  8 00:32:06 2016 : Debug: (6)     } # authorize = okThu Dec  8 00:32:06 2016 : Debug: (6)   Found Auth-Type = eapThu Dec  8 00:32:06 2016 : Debug: (6)   # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnelThu Dec  8 00:32:06 2016 : Debug: (6)     authenticate {Thu Dec  8 00:32:06 2016 : Debug: (6)       modsingle[authenticate]: calling eap (rlm_eap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6) eap: Peer sent packet with method EAP Identity (1)Thu Dec  8 00:32:06 2016 : Debug: (6) eap: Calling submodule eap_md5 to process dataThu Dec  8 00:32:06 2016 : Debug: (6) eap_md5: Issuing MD5 ChallengeThu Dec  8 00:32:06 2016 : Debug: (6) eap: Sending EAP Request (code 1) ID 1 length 22Thu Dec  8 00:32:06 2016 : Debug: (6) eap: EAP session adding &reply:State = 0x5848df875849db2aThu Dec  8 00:32:06 2016 : Debug: (6)       modsingle[authenticate]: returned from eap (rlm_eap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)       [eap] = handledThu Dec  8 00:32:06 2016 : Debug: (6)     } # authenticate = handledThu Dec  8 00:32:06 2016 : Debug: (6) } # server inner-tunnelThu Dec  8 00:32:06 2016 : Debug: (6) Virtual server sending replyThu Dec  8 00:32:06 2016 : Debug: (6)   EAP-Message = 0x01010016041046421c99242454f962d77aa1e66b8b5eThu Dec  8 00:32:06 2016 : Debug: (6)   Message-Authenticator = 0x00000000000000000000000000000000Thu Dec  8 00:32:06 2016 : Debug: (6)   State = 0x5848df875849db2ae267ce7fbe5ae0c4Thu Dec  8 00:32:06 2016 : Debug: (6) eap_ttls: Got tunneled Access-ChallengeThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (6) eap: Sending EAP Request (code 1) ID 7 length 71Thu Dec  8 00:32:06 2016 : Debug: (6) eap: EAP session adding &reply:State = 0x10c1717116c664fcThu Dec  8 00:32:06 2016 : Debug: (6)     modsingle[authenticate]: returned from eap (rlm_eap) for request 6Thu Dec  8 00:32:06 2016 : Debug: (6)     [eap] = handledThu Dec  8 00:32:06 2016 : Debug: (6)   } # authenticate = handledThu Dec  8 00:32:06 2016 : Debug: (6) Using Post-Auth-Type ChallengeThu Dec  8 00:32:06 2016 : Debug: (6) Post-Auth-Type sub-section not found.  Ignoring.Thu Dec  8 00:32:06 2016 : Debug: (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (6) session-state: Nothing to cacheThu Dec  8 00:32:06 2016 : Debug: (6) Sent Access-Challenge Id 6 from 127.0.0.1:1812 to 127.0.0.1:54818 length 0Thu Dec  8 00:32:06 2016 : Debug: (6)   EAP-Message = 0x0107004715800000003d1703030038d5b079448020ce1df42a341c4d030197afb3c4041e27f8465ff2d7f896aa3ab4433ffeebe6810b7579683e59ad495d7578d1c571bd339e54Thu Dec  8 00:32:06 2016 : Debug: (6)   Message-Authenticator = 0x00000000000000000000000000000000Thu Dec  8 00:32:06 2016 : Debug: (6)   State = 0x10c1717116c664fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (6) Finished requestThu Dec  8 00:32:06 2016 : Debug: Waking up in 4.9 seconds.Thu Dec  8 00:32:06 2016 : Debug: (7) Received Access-Request Id 7 from 127.0.0.1:54818 to 127.0.0.1:1812 length 197Thu Dec  8 00:32:06 2016 : Debug: (7)   User-Name = "anonymous"Thu Dec  8 00:32:06 2016 : Debug: (7)   NAS-IP-Address = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (7)   Calling-Station-Id = "02-00-00-00-00-01"Thu Dec  8 00:32:06 2016 : Debug: (7)   Framed-MTU = 1400Thu Dec  8 00:32:06 2016 : Debug: (7)   NAS-Port-Type = Wireless-802.11Thu Dec  8 00:32:06 2016 : Debug: (7)   Connect-Info = "CONNECT 11Mbps 802.11b"Thu Dec  8 00:32:06 2016 : Debug: (7)   EAP-Message = 0x02070043150017030300382551dc6df862b4c2cdd2391feaa04414f9442a24998738878a8bdab227da23be15154d2585607e7be9088483a675011b99bb783380c85edbThu Dec  8 00:32:06 2016 : Debug: (7)   State = 0x10c1717116c664fcf2a6f5bbf92adb57Thu Dec  8 00:32:06 2016 : Debug: (7)   Message-Authenticator = 0x3206542628e88eab17036a42d150300bThu Dec  8 00:32:06 2016 : Debug: (7) session-state: No cached attributesThu Dec  8 00:32:06 2016 : Debug: (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (7)   authorize {Thu Dec  8 00:32:06 2016 : Debug: (7)     policy filter_username {Thu Dec  8 00:32:06 2016 : Debug: (7)       if (&User-Name) {Thu Dec  8 00:32:06 2016 : Debug: (7)       if (&User-Name)  -> TRUEThu Dec  8 00:32:06 2016 : Debug: (7)       if (&User-Name)  {Thu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name =~ / /) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name =~ / /)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name =~ /@[^@]*@/ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name =~ /@[^@]*@/ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name =~ /\.\./ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name =~ /\.\./ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (7)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name =~ /\.$/)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name =~ /\.$/)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name =~ /@\./)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name =~ /@\./)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)       } # if (&User-Name)  = notfoundThu Dec  8 00:32:06 2016 : Debug: (7)     } # policy filter_username = notfoundThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     [preprocess] = okThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: calling chap (rlm_chap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: returned from chap (rlm_chap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     [chap] = noopThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: calling mschap (rlm_mschap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     [mschap] = noopThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: calling digest (rlm_digest) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: returned from digest (rlm_digest) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     [digest] = noopThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: calling suffix (rlm_realm) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7) suffix: Checking for suffix after "@"Thu Dec  8 00:32:06 2016 : Debug: (7) suffix: No '@' in User-Name = "anonymous", looking up realm NULLThu Dec  8 00:32:06 2016 : Debug: (7) suffix: No such realm "NULL"Thu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: returned from suffix (rlm_realm) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     [suffix] = noopThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: calling eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Peer sent EAP Response (code 2) ID 7 length 67Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Continuing tunnel setupThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authorize]: returned from eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     [eap] = okThu Dec  8 00:32:06 2016 : Debug: (7)   } # authorize = okThu Dec  8 00:32:06 2016 : Debug: (7) Found Auth-Type = eapThu Dec  8 00:32:06 2016 : Debug: (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (7)   authenticate {Thu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authenticate]: calling eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Expiring EAP session with state 0x5848df875849db2aThu Dec  8 00:32:06 2016 : Debug: (7) eap: Finished EAP session with state 0x10c1717116c664fcThu Dec  8 00:32:06 2016 : Debug: (7) eap: Previous EAP request found for state 0x10c1717116c664fc, released from the listThu Dec  8 00:32:06 2016 : Debug: (7) eap: Peer sent packet with method EAP TTLS (21)Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Calling submodule eap_ttls to process dataThu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls: AuthenticateThu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls: Continuing EAP-TLSThu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls: Peer sent flags ---Thu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls: [eaptls verify] = okThu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls: Done initial handshakeThu Dec  8 00:32:06 2016 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0Thu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls: [eaptls process] = okThu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls: Session established.  Proceeding to decode tunneled attributesThu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls: Got tunneled requestThu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls:   EAP-Message = 0x020100160410247c68784de86a2369dd6851989c7746Thu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls:   FreeRADIUS-Proxied-To = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls: Sending tunneled requestThu Dec  8 00:32:06 2016 : Debug: (7) Virtual server inner-tunnel received requestThu Dec  8 00:32:06 2016 : Debug: (7)   EAP-Message = 0x020100160410247c68784de86a2369dd6851989c7746Thu Dec  8 00:32:06 2016 : Debug: (7)   FreeRADIUS-Proxied-To = 127.0.0.1Thu Dec  8 00:32:06 2016 : Debug: (7)   User-Name = "eapol_test at aikon.jp"Thu Dec  8 00:32:06 2016 : Debug: (7)   State = 0x5848df875849db2ae267ce7fbe5ae0c4Thu Dec  8 00:32:06 2016 : Debug: (7) server inner-tunnel {Thu Dec  8 00:32:06 2016 : Debug: (7)   session-state: No cached attributesThu Dec  8 00:32:06 2016 : Debug: (7)   # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnelThu Dec  8 00:32:06 2016 : Debug: (7)     authorize {Thu Dec  8 00:32:06 2016 : Debug: (7)       policy filter_username {Thu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name) {Thu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name)  -> TRUEThu Dec  8 00:32:06 2016 : Debug: (7)         if (&User-Name)  {Thu Dec  8 00:32:06 2016 : Debug: (7)           if (&User-Name =~ / /) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (7)           if (&User-Name =~ / /)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)           if (&User-Name =~ /@[^@]*@/ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (7)           if (&User-Name =~ /@[^@]*@/ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)           if (&User-Name =~ /\.\./ ) {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (7)           if (&User-Name =~ /\.\./ )  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: Adding 1 matchesThu Dec  8 00:32:06 2016 : Debug: Clearing 1 matchesThu Dec  8 00:32:06 2016 : Debug: Adding 3 matchesThu Dec  8 00:32:06 2016 : Debug: (7)           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)           if (&User-Name =~ /\.$/)  {Thu Dec  8 00:32:06 2016 : Debug: Clearing 3 matchesThu Dec  8 00:32:06 2016 : Debug: (7)           if (&User-Name =~ /\.$/)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)           if (&User-Name =~ /@\./)  {Thu Dec  8 00:32:06 2016 : Debug: No matchesThu Dec  8 00:32:06 2016 : Debug: (7)           if (&User-Name =~ /@\./)   -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)         } # if (&User-Name)  = notfoundThu Dec  8 00:32:06 2016 : Debug: (7)       } # policy filter_username = notfoundThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: calling chap (rlm_chap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: returned from chap (rlm_chap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [chap] = noopThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: calling mschap (rlm_mschap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: returned from mschap (rlm_mschap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [mschap] = noopThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: calling suffix (rlm_realm) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7) suffix: Checking for suffix after "@"Thu Dec  8 00:32:06 2016 : Debug: (7) suffix: Looking up realm "aikon.jp" for User-Name = "eapol_test at aikon.jp"Thu Dec  8 00:32:06 2016 : Debug: (7) suffix: No such realm "aikon.jp"Thu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: returned from suffix (rlm_realm) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [suffix] = noopThu Dec  8 00:32:06 2016 : Debug: (7)       update control {Thu Dec  8 00:32:06 2016 : Debug: (7)         &Proxy-To-Realm := LOCALThu Dec  8 00:32:06 2016 : Debug: (7)       } # update control = noopThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: calling eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Peer sent EAP Response (code 2) ID 1 length 22Thu Dec  8 00:32:06 2016 : Debug: (7) eap: No EAP Start, assuming it's an on-going EAP conversationThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: returned from eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [eap] = updatedThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: calling files (rlm_files) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: returned from files (rlm_files) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [files] = noopThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: calling expiration (rlm_expiration) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: returned from expiration (rlm_expiration) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [expiration] = noopThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: calling logintime (rlm_logintime) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: returned from logintime (rlm_logintime) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [logintime] = noopThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: calling pap (rlm_pap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authorize]: returned from pap (rlm_pap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [pap] = noopThu Dec  8 00:32:06 2016 : Debug: (7)     } # authorize = updatedThu Dec  8 00:32:06 2016 : Debug: (7)   Found Auth-Type = eapThu Dec  8 00:32:06 2016 : Debug: (7)   # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnelThu Dec  8 00:32:06 2016 : Debug: (7)     authenticate {Thu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authenticate]: calling eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Expiring EAP session with state 0x5848df875849db2aThu Dec  8 00:32:06 2016 : Debug: (7) eap: Finished EAP session with state 0x5848df875849db2aThu Dec  8 00:32:06 2016 : Debug: (7) eap: Previous EAP request found for state 0x5848df875849db2a, released from the listThu Dec  8 00:32:06 2016 : Debug: (7) eap: Peer sent packet with method EAP MD5 (4)Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Calling submodule eap_md5 to process dataThu Dec  8 00:32:06 2016 : Debug: (7) eap_md5: Cleartext-Password is required for EAP-MD5 authenticationThu Dec  8 00:32:06 2016 : ERROR: (7) eap: Failed continuing EAP MD5 (4) session.  EAP sub-module failedThu Dec  8 00:32:06 2016 : Debug: (7) eap: Sending EAP Failure (code 4) ID 1 length 4Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Failed in EAP selectThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[authenticate]: returned from eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [eap] = invalidThu Dec  8 00:32:06 2016 : Debug: (7)     } # authenticate = invalidThu Dec  8 00:32:06 2016 : Debug: (7)   Failed to authenticate the userThu Dec  8 00:32:06 2016 : Auth: (7)   Login incorrect (eap: Failed continuing EAP MD5 (4) session.  EAP sub-module failed): [eapol_test at aikon.jp] (from client localhost port 0 via TLS tunnel)Thu Dec  8 00:32:06 2016 : Debug: (7)   Using Post-Auth-Type RejectThu Dec  8 00:32:06 2016 : Debug: (7)   # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnelThu Dec  8 00:32:06 2016 : Debug: (7)     Post-Auth-Type REJECT {Thu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 7Thu Dec  8 00:32:06 2016 : Debug: %{User-Name}Thu Dec  8 00:32:06 2016 : Debug: Parsed xlat tree:Thu Dec  8 00:32:06 2016 : Debug: attribute --> User-NameThu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: EXPAND %{User-Name}Thu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject:    --> eapol_test at aikon.jpThu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: Matched entry DEFAULT at line 11Thu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: EAP-Message = 0x04010004 allowed by EAP-Message =* 0xThu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rulesThu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0xThu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rulesThu Dec  8 00:32:06 2016 : Debug: (7)       modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)       [attr_filter.access_reject] = updatedThu Dec  8 00:32:06 2016 : Debug: (7)       update outer.session-state {Thu Dec  8 00:32:06 2016 : Debug: (7)         &Module-Failure-Message := &request:Module-Failure-Message -> 'eap: Failed continuing EAP MD5 (4) session.  EAP sub-module failed'Thu Dec  8 00:32:06 2016 : Debug: (7)       } # update outer.session-state = noopThu Dec  8 00:32:06 2016 : Debug: (7)     } # Post-Auth-Type REJECT = updatedThu Dec  8 00:32:06 2016 : Debug: (7) } # server inner-tunnelThu Dec  8 00:32:06 2016 : Debug: (7) Virtual server sending replyThu Dec  8 00:32:06 2016 : Debug: (7)   EAP-Message = 0x04010004Thu Dec  8 00:32:06 2016 : Debug: (7)   Message-Authenticator = 0x00000000000000000000000000000000Thu Dec  8 00:32:06 2016 : Debug: (7) eap_ttls: Got tunneled Access-RejectThu Dec  8 00:32:06 2016 : ERROR: (7) eap: Failed continuing EAP TTLS (21) session.  EAP sub-module failedThu Dec  8 00:32:06 2016 : Debug: (7) eap: Sending EAP Failure (code 4) ID 7 length 4Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Failed in EAP selectThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[authenticate]: returned from eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     [eap] = invalidThu Dec  8 00:32:06 2016 : Debug: (7)   } # authenticate = invalidThu Dec  8 00:32:06 2016 : Debug: (7) Failed to authenticate the userThu Dec  8 00:32:06 2016 : Auth: (7) Login incorrect (eap: Failed continuing EAP TTLS (21) session.  EAP sub-module failed): [anonymous] (from client localhost port 0 cli 02-00-00-00-00-01)Thu Dec  8 00:32:06 2016 : Debug: (7) Using Post-Auth-Type RejectThu Dec  8 00:32:06 2016 : Debug: (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/defaultThu Dec  8 00:32:06 2016 : Debug: (7)   Post-Auth-Type REJECT {Thu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 7Thu Dec  8 00:32:06 2016 : Debug: %{User-Name}Thu Dec  8 00:32:06 2016 : Debug: Parsed xlat tree:Thu Dec  8 00:32:06 2016 : Debug: attribute --> User-NameThu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: EXPAND %{User-Name}Thu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject:    --> anonymousThu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: Matched entry DEFAULT at line 11Thu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: EAP-Message = 0x04070004 allowed by EAP-Message =* 0xThu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rulesThu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0xThu Dec  8 00:32:06 2016 : Debug: (7) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rulesThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     [attr_filter.access_reject] = updatedThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[post-auth]: calling eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7) eap: Reply already contained an EAP-Message, not inserting EAP-FailureThu Dec  8 00:32:06 2016 : Debug: (7)     modsingle[post-auth]: returned from eap (rlm_eap) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)     [eap] = noopThu Dec  8 00:32:06 2016 : Debug: (7)     policy remove_reply_message_if_eap {Thu Dec  8 00:32:06 2016 : Debug: (7)       if (&reply:EAP-Message && &reply:Reply-Message) {Thu Dec  8 00:32:06 2016 : Debug: (7)       if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSEThu Dec  8 00:32:06 2016 : Debug: (7)       else {Thu Dec  8 00:32:06 2016 : Debug: (7)         modsingle[post-auth]: calling noop (rlm_always) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)         modsingle[post-auth]: returned from noop (rlm_always) for request 7Thu Dec  8 00:32:06 2016 : Debug: (7)         [noop] = noopThu Dec  8 00:32:06 2016 : Debug: (7)       } # else = noopThu Dec  8 00:32:06 2016 : Debug: (7)     } # policy remove_reply_message_if_eap = noopThu Dec  8 00:32:06 2016 : Debug: (7)   } # Post-Auth-Type REJECT = updatedThu Dec  8 00:32:06 2016 : Debug: (7) Delaying response for 1.000000 secondsThu Dec  8 00:32:06 2016 : Debug: Waking up in 0.3 seconds.Thu Dec  8 00:32:06 2016 : Debug: Waking up in 0.6 seconds.Thu Dec  8 00:32:07 2016 : Debug: (7) Sending delayed responseThu Dec  8 00:32:07 2016 : Debug: (7) Sent Access-Reject Id 7 from 127.0.0.1:1812 to 127.0.0.1:54818 length 44Thu Dec  8 00:32:07 2016 : Debug: (7)   EAP-Message = 0x04070004Thu Dec  8 00:32:07 2016 : Debug: (7)   Message-Authenticator = 0x00000000000000000000000000000000Thu Dec  8 00:32:07 2016 : Debug: Waking up in 3.9 seconds.Thu Dec  8 00:32:11 2016 : Debug: (0) Cleaning up request packet ID 0 with timestamp +204Thu Dec  8 00:32:11 2016 : Debug: (1) Cleaning up request packet ID 1 with timestamp +204Thu Dec  8 00:32:11 2016 : Debug: (2) Cleaning up request packet ID 2 with timestamp +204Thu Dec  8 00:32:11 2016 : Debug: (3) Cleaning up request packet ID 3 with timestamp +204Thu Dec  8 00:32:11 2016 : Debug: (4) Cleaning up request packet ID 4 with timestamp +204Thu Dec  8 00:32:11 2016 : Debug: (5) Cleaning up request packet ID 5 with timestamp +204Thu Dec  8 00:32:11 2016 : Debug: (6) Cleaning up request packet ID 6 with timestamp +204Thu Dec  8 00:32:11 2016 : Debug: (7) Cleaning up request packet ID 7 with timestamp +204Thu Dec  8 00:32:11 2016 : Info: Ready to process requests


More information about the Freeradius-Users mailing list