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