RE: v3.0.8: Failure message does not appear in radius.log

Yes. You need to use eg google to find some recipes and examples. Or the mailing list archives. It's been discussed several times. If the error occurs with a module in the inner- tunnel then it needs to be copied to the outer

Trust me that I have searched mail archives many times and I have done a lot of testings on my server. I really need more hints/pointers/advice. I read that "Multi-packet session state" was first introduced in v3.0.5 to solve this problem: http://lists.freeradius.org/pipermail/freeradius-users/2014-October/074522.h... But I can never get it worked. I see no other articles with similar issue thereafter. I followed the instruction mentioned in the above article. My inner-tunnel has the following lines: post-auth { update { &outer.session-state: += &reply: } update outer.session-state { MS-MPPE-Encryption-Policy !* ANY MS-MPPE-Encryption-Types !* ANY MS-MPPE-Send-Key !* ANY MS-MPPE-Recv-Key !* ANY Message-Authenticator !* ANY EAP-Message !* ANY Proxy-State !* ANY } linelog Post-Auth-Type REJECT { update { &Module-Failure-Message := &request:Module-Failure-Message } linelog } } My default virtual server has the following lines: post auth { update { &reply: += &session-state: } linelog } My linelog tried to retrieve %{Module-Failure-Message} and it returned nothing. What have I missed? Fu Debug log follows: Tue Jul 7 11:34:15 2015 : Debug: (0) Received Access-Request Id 107 from 10.57.123.29:3629 to 10.57.235.64:1812 length 208 Tue Jul 7 11:34:15 2015 : Debug: (0) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (0) Framed-MTU = 1450 Tue Jul 7 11:34:15 2015 : Debug: (0) EAP-Message = 0x0201000b0174666b6c6169 Tue Jul 7 11:34:15 2015 : Debug: (0) Message-Authenticator = 0x07170f2fb97a37e6f27e02daeed9c167 Tue Jul 7 11:34:15 2015 : Debug: (0) Chargeable-User-Identity = 0x00 Tue Jul 7 11:34:15 2015 : Debug: (0) NAS-IP-Address = 10.57.123.29 Tue Jul 7 11:34:15 2015 : Debug: (0) NAS-Identifier = 'ITS-TEST' Tue Jul 7 11:34:15 2015 : Debug: (0) NAS-Port = 33779942 Tue Jul 7 11:34:15 2015 : Debug: (0) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' Tue Jul 7 11:34:15 2015 : Debug: (0) NAS-Port-Type = Wireless-802.11 Tue Jul 7 11:34:15 2015 : Debug: (0) Service-Type = Framed-User Tue Jul 7 11:34:15 2015 : Debug: (0) Framed-Protocol = PPP Tue Jul 7 11:34:15 2015 : Debug: (0) Calling-Station-Id = '10-1C-0C-79-26-49' Tue Jul 7 11:34:15 2015 : Debug: (0) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' Tue Jul 7 11:34:15 2015 : Debug: (0) Acct-Session-Id = '115060711294f0' Tue Jul 7 11:34:15 2015 : Debug: (0) session-state: No State attribute Tue Jul 7 11:34:15 2015 : Debug: (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (0) authorize { Tue Jul 7 11:34:15 2015 : Debug: (0) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (0) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (0) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (0) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (0) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (0) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (0) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (0) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (0) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (0) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (0) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (0) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (0) modsingle[authorize]: calling auth_log (rlm_detail) for request 0 Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/radacct/ Tue Jul 7 11:34:15 2015 : Debug: attribute --> Client-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> /auth- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (0) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (0) auth_log: --> /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: (0) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: %t Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> t Tue Jul 7 11:34:15 2015 : Debug: (0) auth_log: EXPAND %t Tue Jul 7 11:34:15 2015 : Debug: (0) auth_log: --> Tue Jul 7 11:34:15 2015 Tue Jul 7 11:34:15 2015 : Debug: (0) modsingle[authorize]: returned from auth_log (rlm_detail) for request 0 Tue Jul 7 11:34:15 2015 : Debug: (0) [auth_log] = ok Tue Jul 7 11:34:15 2015 : Debug: (0) modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Tue Jul 7 11:34:15 2015 : Debug: (0) modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Tue Jul 7 11:34:15 2015 : Debug: (0) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (0) modsingle[authorize]: calling suffix (rlm_realm) for request 0 Tue Jul 7 11:34:15 2015 : Debug: (0) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (0) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (0) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (0) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (0) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (0) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (0) modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Tue Jul 7 11:34:15 2015 : Debug: (0) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (0) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) { Tue Jul 7 11:34:15 2015 : Debug: (0) EXPAND %{Aruba-Essid-Name} Tue Jul 7 11:34:15 2015 : Debug: (0) --> Tue Jul 7 11:34:15 2015 : Debug: (0) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (0) modsingle[authorize]: calling eap (rlm_eap) for request 0 Tue Jul 7 11:34:15 2015 : Debug: (0) eap: Peer sent code Response (2) ID 1 length 11 Tue Jul 7 11:34:15 2015 : Debug: (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Tue Jul 7 11:34:15 2015 : Debug: (0) modsingle[authorize]: returned from eap (rlm_eap) for request 0 Tue Jul 7 11:34:15 2015 : Debug: (0) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (0) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (0) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (0) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (0) modsingle[authenticate]: calling eap (rlm_eap) for request 0 Tue Jul 7 11:34:15 2015 : Debug: (0) eap: Peer sent method Identity (1) Tue Jul 7 11:34:15 2015 : Debug: (0) eap: Calling eap_peap to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (0) eap_peap: Flushing SSL sessions (of #0) Tue Jul 7 11:34:15 2015 : Debug: (0) eap_peap: Initiate Tue Jul 7 11:34:15 2015 : Debug: (0) eap_peap: Start returned 1 Tue Jul 7 11:34:15 2015 : Debug: (0) eap: EAP session adding &reply:State = 0xd753eb2fd751f204 Tue Jul 7 11:34:15 2015 : Debug: (0) modsingle[authenticate]: returned from eap (rlm_eap) for request 0 Tue Jul 7 11:34:15 2015 : Debug: (0) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (0) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (0) Using Post-Auth-Type Challenge Tue Jul 7 11:34:15 2015 : Debug: (0) Post-Auth-Type sub-section not found. Ignoring. Tue Jul 7 11:34:15 2015 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (0) session-state: Nothing to cache Tue Jul 7 11:34:15 2015 : Debug: (0) Sent Access-Challenge Id 107 from 10.57.235.64:1812 to 10.57.123.29:3629 length 0 Tue Jul 7 11:34:15 2015 : Debug: (0) EAP-Message = 0x010200061920 Tue Jul 7 11:34:15 2015 : Debug: (0) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (0) State = 0xd753eb2fd751f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (0) Finished request Tue Jul 7 11:34:15 2015 : Debug: Waking up in 4.9 seconds. Tue Jul 7 11:34:15 2015 : Debug: (1) Received Access-Request Id 108 from 10.57.123.29:3629 to 10.57.235.64:1812 length 367 Tue Jul 7 11:34:15 2015 : Debug: (1) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (1) Framed-MTU = 1450 Tue Jul 7 11:34:15 2015 : Debug: (1) EAP-Message = 0x0202009819800000008e1603010089010000850301559b48e6e68eb7ade8a75d83d12f5e0920a59221f98a6ec9cd7c78c8e9bace3500004a00ffc024c023c00ac009c008c028c027c014c013c012c026c025c005c004c003c02ac029c00fc00ec00d006b0067003900330016003d003c0035002f000ac0 Tue Jul 7 11:34:15 2015 : Debug: (1) Message-Authenticator = 0xb0b6527fccfc2cc9fbbb31d7e4fd2339 Tue Jul 7 11:34:15 2015 : Debug: (1) Chargeable-User-Identity = 0x00 Tue Jul 7 11:34:15 2015 : Debug: (1) NAS-IP-Address = 10.57.123.29 Tue Jul 7 11:34:15 2015 : Debug: (1) NAS-Identifier = 'ITS-TEST' Tue Jul 7 11:34:15 2015 : Debug: (1) NAS-Port = 33779942 Tue Jul 7 11:34:15 2015 : Debug: (1) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' Tue Jul 7 11:34:15 2015 : Debug: (1) NAS-Port-Type = Wireless-802.11 Tue Jul 7 11:34:15 2015 : Debug: (1) Service-Type = Framed-User Tue Jul 7 11:34:15 2015 : Debug: (1) Framed-Protocol = PPP Tue Jul 7 11:34:15 2015 : Debug: (1) Calling-Station-Id = '10-1C-0C-79-26-49' Tue Jul 7 11:34:15 2015 : Debug: (1) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' Tue Jul 7 11:34:15 2015 : Debug: (1) Acct-Session-Id = '115060711294f0' Tue Jul 7 11:34:15 2015 : Debug: (1) State = 0xd753eb2fd751f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (1) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (1) authorize { Tue Jul 7 11:34:15 2015 : Debug: (1) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (1) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (1) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (1) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (1) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (1) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (1) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (1) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (1) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (1) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (1) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (1) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (1) modsingle[authorize]: calling auth_log (rlm_detail) for request 1 Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/radacct/ Tue Jul 7 11:34:15 2015 : Debug: attribute --> Client-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> /auth- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (1) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (1) auth_log: --> /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: (1) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: %t Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> t Tue Jul 7 11:34:15 2015 : Debug: (1) auth_log: EXPAND %t Tue Jul 7 11:34:15 2015 : Debug: (1) auth_log: --> Tue Jul 7 11:34:15 2015 Tue Jul 7 11:34:15 2015 : Debug: (1) modsingle[authorize]: returned from auth_log (rlm_detail) for request 1 Tue Jul 7 11:34:15 2015 : Debug: (1) [auth_log] = ok Tue Jul 7 11:34:15 2015 : Debug: (1) modsingle[authorize]: calling mschap (rlm_mschap) for request 1 Tue Jul 7 11:34:15 2015 : Debug: (1) modsingle[authorize]: returned from mschap (rlm_mschap) for request 1 Tue Jul 7 11:34:15 2015 : Debug: (1) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (1) modsingle[authorize]: calling suffix (rlm_realm) for request 1 Tue Jul 7 11:34:15 2015 : Debug: (1) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (1) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (1) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (1) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (1) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (1) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (1) modsingle[authorize]: returned from suffix (rlm_realm) for request 1 Tue Jul 7 11:34:15 2015 : Debug: (1) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (1) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) { Tue Jul 7 11:34:15 2015 : Debug: (1) EXPAND %{Aruba-Essid-Name} Tue Jul 7 11:34:15 2015 : Debug: (1) --> Tue Jul 7 11:34:15 2015 : Debug: (1) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (1) modsingle[authorize]: calling eap (rlm_eap) for request 1 Tue Jul 7 11:34:15 2015 : Debug: (1) eap: Peer sent code Response (2) ID 2 length 152 Tue Jul 7 11:34:15 2015 : Debug: (1) eap: Continuing tunnel setup Tue Jul 7 11:34:15 2015 : Debug: (1) modsingle[authorize]: returned from eap (rlm_eap) for request 1 Tue Jul 7 11:34:15 2015 : Debug: (1) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (1) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (1) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (1) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (1) modsingle[authenticate]: calling eap (rlm_eap) for request 1 Tue Jul 7 11:34:15 2015 : Debug: (1) eap: Expiring EAP session with state 0xd753eb2fd751f204 Tue Jul 7 11:34:15 2015 : Debug: (1) eap: Finished EAP session with state 0xd753eb2fd751f204 Tue Jul 7 11:34:15 2015 : Debug: (1) eap: Previous EAP request found for state 0xd753eb2fd751f204, released from the list Tue Jul 7 11:34:15 2015 : Debug: (1) eap: Peer sent method PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (1) eap: EAP PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (1) eap: Calling eap_peap to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: processing EAP-TLS Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: TLS Length 142 Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: Length Included Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: eaptls_verify returned 11 Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: (other): before/accept initialization Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: TLS_accept: before/accept initialization Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: <<< TLS 1.0 Handshake [length 0089], ClientHello Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 read client hello A Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: >>> TLS 1.0 Handshake [length 0059], ServerHello Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 write server hello A Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: >>> TLS 1.0 Handshake [length 0cb2], Certificate Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 write certificate A Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 write key exchange A Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 write server done A Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 flush data Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: TLS_accept: Need to read more data: SSLv3 read client certificate A Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: TLS_accept: Need to read more data: SSLv3 read client certificate A Tue Jul 7 11:34:15 2015 : Debug: In SSL Handshake Phase Tue Jul 7 11:34:15 2015 : Debug: In SSL Accept mode Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: eaptls_process returned 13 Tue Jul 7 11:34:15 2015 : Debug: (1) eap_peap: FR_TLS_HANDLED Tue Jul 7 11:34:15 2015 : Debug: (1) eap: EAP session adding &reply:State = 0xd753eb2fd650f204 Tue Jul 7 11:34:15 2015 : Debug: (1) modsingle[authenticate]: returned from eap (rlm_eap) for request 1 Tue Jul 7 11:34:15 2015 : Debug: (1) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (1) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (1) Using Post-Auth-Type Challenge Tue Jul 7 11:34:15 2015 : Debug: (1) Post-Auth-Type sub-section not found. Ignoring. Tue Jul 7 11:34:15 2015 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (1) session-state: Nothing to cache Tue Jul 7 11:34:15 2015 : Debug: (1) Sent Access-Challenge Id 108 from 10.57.235.64:1812 to 10.57.123.29:3629 length 0 Tue Jul 7 11:34:15 2015 : Debug: (1) EAP-Message = 0x010303ec19c000000e6e1603010059020000550301559b48b7e5a725fd651d813046bddd81674b7f38fceafb9624d32004b56cd11320d6682dd3caa2bb9f8a51285374b41b96cfec72a5ee36538cfb0ce8870947153ac01400000dff01000100000b0004030001021603010cb20b000cae000cab00054c Tue Jul 7 11:34:15 2015 : Debug: (1) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (1) State = 0xd753eb2fd650f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (1) Finished request Tue Jul 7 11:34:15 2015 : Debug: Waking up in 4.9 seconds. Tue Jul 7 11:34:15 2015 : Debug: (2) Received Access-Request Id 109 from 10.57.123.29:3629 to 10.57.235.64:1812 length 221 Tue Jul 7 11:34:15 2015 : Debug: (2) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (2) Framed-MTU = 1450 Tue Jul 7 11:34:15 2015 : Debug: (2) EAP-Message = 0x020300061900 Tue Jul 7 11:34:15 2015 : Debug: (2) Message-Authenticator = 0xcfd03b3b47fdefc07da15ae9b9ded5e4 Tue Jul 7 11:34:15 2015 : Debug: (2) Chargeable-User-Identity = 0x00 Tue Jul 7 11:34:15 2015 : Debug: (2) NAS-IP-Address = 10.57.123.29 Tue Jul 7 11:34:15 2015 : Debug: (2) NAS-Identifier = 'ITS-TEST' Tue Jul 7 11:34:15 2015 : Debug: (2) NAS-Port = 33779942 Tue Jul 7 11:34:15 2015 : Debug: (2) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' Tue Jul 7 11:34:15 2015 : Debug: (2) NAS-Port-Type = Wireless-802.11 Tue Jul 7 11:34:15 2015 : Debug: (2) Service-Type = Framed-User Tue Jul 7 11:34:15 2015 : Debug: (2) Framed-Protocol = PPP Tue Jul 7 11:34:15 2015 : Debug: (2) Calling-Station-Id = '10-1C-0C-79-26-49' Tue Jul 7 11:34:15 2015 : Debug: (2) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' Tue Jul 7 11:34:15 2015 : Debug: (2) Acct-Session-Id = '115060711294f0' Tue Jul 7 11:34:15 2015 : Debug: (2) State = 0xd753eb2fd650f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (2) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (2) authorize { Tue Jul 7 11:34:15 2015 : Debug: (2) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (2) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (2) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (2) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (2) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (2) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (2) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (2) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (2) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (2) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (2) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (2) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (2) modsingle[authorize]: calling auth_log (rlm_detail) for request 2 Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/radacct/ Tue Jul 7 11:34:15 2015 : Debug: attribute --> Client-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> /auth- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (2) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (2) auth_log: --> /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: (2) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: %t Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> t Tue Jul 7 11:34:15 2015 : Debug: (2) auth_log: EXPAND %t Tue Jul 7 11:34:15 2015 : Debug: (2) auth_log: --> Tue Jul 7 11:34:15 2015 Tue Jul 7 11:34:15 2015 : Debug: (2) modsingle[authorize]: returned from auth_log (rlm_detail) for request 2 Tue Jul 7 11:34:15 2015 : Debug: (2) [auth_log] = ok Tue Jul 7 11:34:15 2015 : Debug: (2) modsingle[authorize]: calling mschap (rlm_mschap) for request 2 Tue Jul 7 11:34:15 2015 : Debug: (2) modsingle[authorize]: returned from mschap (rlm_mschap) for request 2 Tue Jul 7 11:34:15 2015 : Debug: (2) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (2) modsingle[authorize]: calling suffix (rlm_realm) for request 2 Tue Jul 7 11:34:15 2015 : Debug: (2) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (2) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (2) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (2) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (2) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (2) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (2) modsingle[authorize]: returned from suffix (rlm_realm) for request 2 Tue Jul 7 11:34:15 2015 : Debug: (2) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (2) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) { Tue Jul 7 11:34:15 2015 : Debug: (2) EXPAND %{Aruba-Essid-Name} Tue Jul 7 11:34:15 2015 : Debug: (2) --> Tue Jul 7 11:34:15 2015 : Debug: (2) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (2) modsingle[authorize]: calling eap (rlm_eap) for request 2 Tue Jul 7 11:34:15 2015 : Debug: (2) eap: Peer sent code Response (2) ID 3 length 6 Tue Jul 7 11:34:15 2015 : Debug: (2) eap: Continuing tunnel setup Tue Jul 7 11:34:15 2015 : Debug: (2) modsingle[authorize]: returned from eap (rlm_eap) for request 2 Tue Jul 7 11:34:15 2015 : Debug: (2) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (2) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (2) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (2) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (2) modsingle[authenticate]: calling eap (rlm_eap) for request 2 Tue Jul 7 11:34:15 2015 : Debug: (2) eap: Expiring EAP session with state 0xd753eb2fd650f204 Tue Jul 7 11:34:15 2015 : Debug: (2) eap: Finished EAP session with state 0xd753eb2fd650f204 Tue Jul 7 11:34:15 2015 : Debug: (2) eap: Previous EAP request found for state 0xd753eb2fd650f204, released from the list Tue Jul 7 11:34:15 2015 : Debug: (2) eap: Peer sent method PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (2) eap: EAP PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (2) eap: Calling eap_peap to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (2) eap_peap: processing EAP-TLS Tue Jul 7 11:34:15 2015 : Debug: (2) eap_peap: Received TLS ACK Tue Jul 7 11:34:15 2015 : Debug: (2) eap_peap: Received TLS ACK Tue Jul 7 11:34:15 2015 : Debug: (2) eap_peap: ACK handshake fragment handler Tue Jul 7 11:34:15 2015 : Debug: (2) eap_peap: eaptls_verify returned 1 Tue Jul 7 11:34:15 2015 : Debug: (2) eap_peap: eaptls_process returned 13 Tue Jul 7 11:34:15 2015 : Debug: (2) eap_peap: FR_TLS_HANDLED Tue Jul 7 11:34:15 2015 : Debug: (2) eap: EAP session adding &reply:State = 0xd753eb2fd557f204 Tue Jul 7 11:34:15 2015 : Debug: (2) modsingle[authenticate]: returned from eap (rlm_eap) for request 2 Tue Jul 7 11:34:15 2015 : Debug: (2) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (2) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (2) Using Post-Auth-Type Challenge Tue Jul 7 11:34:15 2015 : Debug: (2) Post-Auth-Type sub-section not found. Ignoring. Tue Jul 7 11:34:15 2015 : Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (2) session-state: Nothing to cache Tue Jul 7 11:34:15 2015 : Debug: (2) Sent Access-Challenge Id 109 from 10.57.235.64:1812 to 10.57.123.29:3629 length 0 Tue Jul 7 11:34:15 2015 : Debug: (2) EAP-Message = 0x010403e8194006082b0601050507010104693067302c06082b060105050730018620687474703a2f2f677473736c64762d6f6373702e67656f74727573742e636f6d303706082b06010505073002862b687474703a2f2f677473736c64762d6169612e67656f74727573742e636f6d2f677473736c6476 Tue Jul 7 11:34:15 2015 : Debug: (2) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (2) State = 0xd753eb2fd557f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (2) Finished request Tue Jul 7 11:34:15 2015 : Debug: Waking up in 4.9 seconds. Tue Jul 7 11:34:15 2015 : Debug: (3) Received Access-Request Id 110 from 10.57.123.29:3629 to 10.57.235.64:1812 length 221 Tue Jul 7 11:34:15 2015 : Debug: (3) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (3) Framed-MTU = 1450 Tue Jul 7 11:34:15 2015 : Debug: (3) EAP-Message = 0x020400061900 Tue Jul 7 11:34:15 2015 : Debug: (3) Message-Authenticator = 0xdaf561530f1480d99e1c8e8806e83d11 Tue Jul 7 11:34:15 2015 : Debug: (3) Chargeable-User-Identity = 0x00 Tue Jul 7 11:34:15 2015 : Debug: (3) NAS-IP-Address = 10.57.123.29 Tue Jul 7 11:34:15 2015 : Debug: (3) NAS-Identifier = 'ITS-TEST' Tue Jul 7 11:34:15 2015 : Debug: (3) NAS-Port = 33779942 Tue Jul 7 11:34:15 2015 : Debug: (3) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' Tue Jul 7 11:34:15 2015 : Debug: (3) NAS-Port-Type = Wireless-802.11 Tue Jul 7 11:34:15 2015 : Debug: (3) Service-Type = Framed-User Tue Jul 7 11:34:15 2015 : Debug: (3) Framed-Protocol = PPP Tue Jul 7 11:34:15 2015 : Debug: (3) Calling-Station-Id = '10-1C-0C-79-26-49' Tue Jul 7 11:34:15 2015 : Debug: (3) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' Tue Jul 7 11:34:15 2015 : Debug: (3) Acct-Session-Id = '115060711294f0' Tue Jul 7 11:34:15 2015 : Debug: (3) State = 0xd753eb2fd557f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (3) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (3) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (3) authorize { Tue Jul 7 11:34:15 2015 : Debug: (3) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (3) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (3) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (3) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (3) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (3) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (3) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (3) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (3) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (3) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (3) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (3) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (3) modsingle[authorize]: calling auth_log (rlm_detail) for request 3 Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/radacct/ Tue Jul 7 11:34:15 2015 : Debug: attribute --> Client-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> /auth- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (3) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (3) auth_log: --> /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: (3) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: %t Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> t Tue Jul 7 11:34:15 2015 : Debug: (3) auth_log: EXPAND %t Tue Jul 7 11:34:15 2015 : Debug: (3) auth_log: --> Tue Jul 7 11:34:15 2015 Tue Jul 7 11:34:15 2015 : Debug: (3) modsingle[authorize]: returned from auth_log (rlm_detail) for request 3 Tue Jul 7 11:34:15 2015 : Debug: (3) [auth_log] = ok Tue Jul 7 11:34:15 2015 : Debug: (3) modsingle[authorize]: calling mschap (rlm_mschap) for request 3 Tue Jul 7 11:34:15 2015 : Debug: (3) modsingle[authorize]: returned from mschap (rlm_mschap) for request 3 Tue Jul 7 11:34:15 2015 : Debug: (3) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (3) modsingle[authorize]: calling suffix (rlm_realm) for request 3 Tue Jul 7 11:34:15 2015 : Debug: (3) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (3) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (3) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (3) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (3) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (3) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (3) modsingle[authorize]: returned from suffix (rlm_realm) for request 3 Tue Jul 7 11:34:15 2015 : Debug: (3) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (3) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) { Tue Jul 7 11:34:15 2015 : Debug: (3) EXPAND %{Aruba-Essid-Name} Tue Jul 7 11:34:15 2015 : Debug: (3) --> Tue Jul 7 11:34:15 2015 : Debug: (3) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (3) modsingle[authorize]: calling eap (rlm_eap) for request 3 Tue Jul 7 11:34:15 2015 : Debug: (3) eap: Peer sent code Response (2) ID 4 length 6 Tue Jul 7 11:34:15 2015 : Debug: (3) eap: Continuing tunnel setup Tue Jul 7 11:34:15 2015 : Debug: (3) modsingle[authorize]: returned from eap (rlm_eap) for request 3 Tue Jul 7 11:34:15 2015 : Debug: (3) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (3) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (3) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (3) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (3) modsingle[authenticate]: calling eap (rlm_eap) for request 3 Tue Jul 7 11:34:15 2015 : Debug: (3) eap: Expiring EAP session with state 0xd753eb2fd557f204 Tue Jul 7 11:34:15 2015 : Debug: (3) eap: Finished EAP session with state 0xd753eb2fd557f204 Tue Jul 7 11:34:15 2015 : Debug: (3) eap: Previous EAP request found for state 0xd753eb2fd557f204, released from the list Tue Jul 7 11:34:15 2015 : Debug: (3) eap: Peer sent method PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (3) eap: EAP PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (3) eap: Calling eap_peap to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (3) eap_peap: processing EAP-TLS Tue Jul 7 11:34:15 2015 : Debug: (3) eap_peap: Received TLS ACK Tue Jul 7 11:34:15 2015 : Debug: (3) eap_peap: Received TLS ACK Tue Jul 7 11:34:15 2015 : Debug: (3) eap_peap: ACK handshake fragment handler Tue Jul 7 11:34:15 2015 : Debug: (3) eap_peap: eaptls_verify returned 1 Tue Jul 7 11:34:15 2015 : Debug: (3) eap_peap: eaptls_process returned 13 Tue Jul 7 11:34:15 2015 : Debug: (3) eap_peap: FR_TLS_HANDLED Tue Jul 7 11:34:15 2015 : Debug: (3) eap: EAP session adding &reply:State = 0xd753eb2fd456f204 Tue Jul 7 11:34:15 2015 : Debug: (3) modsingle[authenticate]: returned from eap (rlm_eap) for request 3 Tue Jul 7 11:34:15 2015 : Debug: (3) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (3) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (3) Using Post-Auth-Type Challenge Tue Jul 7 11:34:15 2015 : Debug: (3) Post-Auth-Type sub-section not found. Ignoring. Tue Jul 7 11:34:15 2015 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (3) session-state: Nothing to cache Tue Jul 7 11:34:15 2015 : Debug: (3) Sent Access-Challenge Id 110 from 10.57.235.64:1812 to 10.57.123.29:3629 length 0 Tue Jul 7 11:34:15 2015 : Debug: (3) EAP-Message = 0x010503e81940150203010001a381d93081d6300e0603551d0f0101ff040403020106301d0603551d0e041604148cf4d9930a47bc00a04ace4b756ea0b6b0b27efc301f0603551d23041830168014c07a98688d89fbab05640c117daa7d65b8cacc4e30120603551d130101ff040830060101ff02010030 Tue Jul 7 11:34:15 2015 : Debug: (3) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (3) State = 0xd753eb2fd456f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (3) Finished request Tue Jul 7 11:34:15 2015 : Debug: Waking up in 4.9 seconds. Tue Jul 7 11:34:15 2015 : Debug: (4) Received Access-Request Id 111 from 10.57.123.29:3629 to 10.57.235.64:1812 length 221 Tue Jul 7 11:34:15 2015 : Debug: (4) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (4) Framed-MTU = 1450 Tue Jul 7 11:34:15 2015 : Debug: (4) EAP-Message = 0x020500061900 Tue Jul 7 11:34:15 2015 : Debug: (4) Message-Authenticator = 0x9e5f0e54fc15da7a8e15e007165ed2d1 Tue Jul 7 11:34:15 2015 : Debug: (4) Chargeable-User-Identity = 0x00 Tue Jul 7 11:34:15 2015 : Debug: (4) NAS-IP-Address = 10.57.123.29 Tue Jul 7 11:34:15 2015 : Debug: (4) NAS-Identifier = 'ITS-TEST' Tue Jul 7 11:34:15 2015 : Debug: (4) NAS-Port = 33779942 Tue Jul 7 11:34:15 2015 : Debug: (4) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' Tue Jul 7 11:34:15 2015 : Debug: (4) NAS-Port-Type = Wireless-802.11 Tue Jul 7 11:34:15 2015 : Debug: (4) Service-Type = Framed-User Tue Jul 7 11:34:15 2015 : Debug: (4) Framed-Protocol = PPP Tue Jul 7 11:34:15 2015 : Debug: (4) Calling-Station-Id = '10-1C-0C-79-26-49' Tue Jul 7 11:34:15 2015 : Debug: (4) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' Tue Jul 7 11:34:15 2015 : Debug: (4) Acct-Session-Id = '115060711294f0' Tue Jul 7 11:34:15 2015 : Debug: (4) State = 0xd753eb2fd456f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (4) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (4) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (4) authorize { Tue Jul 7 11:34:15 2015 : Debug: (4) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (4) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (4) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (4) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (4) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (4) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (4) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (4) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (4) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (4) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (4) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (4) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (4) modsingle[authorize]: calling auth_log (rlm_detail) for request 4 Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/radacct/ Tue Jul 7 11:34:15 2015 : Debug: attribute --> Client-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> /auth- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (4) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (4) auth_log: --> /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: (4) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: %t Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> t Tue Jul 7 11:34:15 2015 : Debug: (4) auth_log: EXPAND %t Tue Jul 7 11:34:15 2015 : Debug: (4) auth_log: --> Tue Jul 7 11:34:15 2015 Tue Jul 7 11:34:15 2015 : Debug: (4) modsingle[authorize]: returned from auth_log (rlm_detail) for request 4 Tue Jul 7 11:34:15 2015 : Debug: (4) [auth_log] = ok Tue Jul 7 11:34:15 2015 : Debug: (4) modsingle[authorize]: calling mschap (rlm_mschap) for request 4 Tue Jul 7 11:34:15 2015 : Debug: (4) modsingle[authorize]: returned from mschap (rlm_mschap) for request 4 Tue Jul 7 11:34:15 2015 : Debug: (4) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (4) modsingle[authorize]: calling suffix (rlm_realm) for request 4 Tue Jul 7 11:34:15 2015 : Debug: (4) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (4) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (4) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (4) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (4) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (4) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (4) modsingle[authorize]: returned from suffix (rlm_realm) for request 4 Tue Jul 7 11:34:15 2015 : Debug: (4) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (4) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) { Tue Jul 7 11:34:15 2015 : Debug: (4) EXPAND %{Aruba-Essid-Name} Tue Jul 7 11:34:15 2015 : Debug: (4) --> Tue Jul 7 11:34:15 2015 : Debug: (4) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (4) modsingle[authorize]: calling eap (rlm_eap) for request 4 Tue Jul 7 11:34:15 2015 : Debug: (4) eap: Peer sent code Response (2) ID 5 length 6 Tue Jul 7 11:34:15 2015 : Debug: (4) eap: Continuing tunnel setup Tue Jul 7 11:34:15 2015 : Debug: (4) modsingle[authorize]: returned from eap (rlm_eap) for request 4 Tue Jul 7 11:34:15 2015 : Debug: (4) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (4) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (4) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (4) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (4) modsingle[authenticate]: calling eap (rlm_eap) for request 4 Tue Jul 7 11:34:15 2015 : Debug: (4) eap: Expiring EAP session with state 0xd753eb2fd456f204 Tue Jul 7 11:34:15 2015 : Debug: (4) eap: Finished EAP session with state 0xd753eb2fd456f204 Tue Jul 7 11:34:15 2015 : Debug: (4) eap: Previous EAP request found for state 0xd753eb2fd456f204, released from the list Tue Jul 7 11:34:15 2015 : Debug: (4) eap: Peer sent method PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (4) eap: EAP PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (4) eap: Calling eap_peap to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (4) eap_peap: processing EAP-TLS Tue Jul 7 11:34:15 2015 : Debug: (4) eap_peap: Received TLS ACK Tue Jul 7 11:34:15 2015 : Debug: (4) eap_peap: Received TLS ACK Tue Jul 7 11:34:15 2015 : Debug: (4) eap_peap: ACK handshake fragment handler Tue Jul 7 11:34:15 2015 : Debug: (4) eap_peap: eaptls_verify returned 1 Tue Jul 7 11:34:15 2015 : Debug: (4) eap_peap: eaptls_process returned 13 Tue Jul 7 11:34:15 2015 : Debug: (4) eap_peap: FR_TLS_HANDLED Tue Jul 7 11:34:15 2015 : Debug: (4) eap: EAP session adding &reply:State = 0xd753eb2fd355f204 Tue Jul 7 11:34:15 2015 : Debug: (4) modsingle[authenticate]: returned from eap (rlm_eap) for request 4 Tue Jul 7 11:34:15 2015 : Debug: (4) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (4) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (4) Using Post-Auth-Type Challenge Tue Jul 7 11:34:15 2015 : Debug: (4) Post-Auth-Type sub-section not found. Ignoring. Tue Jul 7 11:34:15 2015 : Debug: (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (4) session-state: Nothing to cache Tue Jul 7 11:34:15 2015 : Debug: (4) Sent Access-Challenge Id 111 from 10.57.235.64:1812 to 10.57.123.29:3629 length 0 Tue Jul 7 11:34:15 2015 : Debug: (4) EAP-Message = 0x010602ce1900f90203010001a3533051300f0603551d130101ff040530030101ff301d0603551d0e04160414c07a98688d89fbab05640c117daa7d65b8cacc4e301f0603551d23041830168014c07a98688d89fbab05640c117daa7d65b8cacc4e300d06092a864886f70d0101050500038201010035e3 Tue Jul 7 11:34:15 2015 : Debug: (4) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (4) State = 0xd753eb2fd355f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (4) Finished request Tue Jul 7 11:34:15 2015 : Debug: Waking up in 4.9 seconds. Tue Jul 7 11:34:15 2015 : Debug: (5) Received Access-Request Id 112 from 10.57.123.29:3629 to 10.57.235.64:1812 length 359 Tue Jul 7 11:34:15 2015 : Debug: (5) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (5) Framed-MTU = 1450 Tue Jul 7 11:34:15 2015 : Debug: (5) EAP-Message = 0x02060090198000000086160301004610000042410427ada1840cbb7308fb404d7d7142f80114e9314688fcc559be89908669e545f766e8a3b3df602fbe3d0fe4dab55842ccf18238708e05fd105ef6720f9500de95140301000101160301003049af29e74d71957f85dc2e3b7e4dd60a661d63abac6189 Tue Jul 7 11:34:15 2015 : Debug: (5) Message-Authenticator = 0xe666687c92b2ae7bfe7c5b3cd4fae6f5 Tue Jul 7 11:34:15 2015 : Debug: (5) Chargeable-User-Identity = 0x00 Tue Jul 7 11:34:15 2015 : Debug: (5) NAS-IP-Address = 10.57.123.29 Tue Jul 7 11:34:15 2015 : Debug: (5) NAS-Identifier = 'ITS-TEST' Tue Jul 7 11:34:15 2015 : Debug: (5) NAS-Port = 33779942 Tue Jul 7 11:34:15 2015 : Debug: (5) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' Tue Jul 7 11:34:15 2015 : Debug: (5) NAS-Port-Type = Wireless-802.11 Tue Jul 7 11:34:15 2015 : Debug: (5) Service-Type = Framed-User Tue Jul 7 11:34:15 2015 : Debug: (5) Framed-Protocol = PPP Tue Jul 7 11:34:15 2015 : Debug: (5) Calling-Station-Id = '10-1C-0C-79-26-49' Tue Jul 7 11:34:15 2015 : Debug: (5) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' Tue Jul 7 11:34:15 2015 : Debug: (5) Acct-Session-Id = '115060711294f0' Tue Jul 7 11:34:15 2015 : Debug: (5) State = 0xd753eb2fd355f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (5) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (5) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (5) authorize { Tue Jul 7 11:34:15 2015 : Debug: (5) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (5) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (5) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (5) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (5) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (5) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (5) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (5) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (5) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (5) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (5) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (5) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (5) modsingle[authorize]: calling auth_log (rlm_detail) for request 5 Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/radacct/ Tue Jul 7 11:34:15 2015 : Debug: attribute --> Client-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> /auth- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (5) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (5) auth_log: --> /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: (5) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: %t Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> t Tue Jul 7 11:34:15 2015 : Debug: (5) auth_log: EXPAND %t Tue Jul 7 11:34:15 2015 : Debug: (5) auth_log: --> Tue Jul 7 11:34:15 2015 Tue Jul 7 11:34:15 2015 : Debug: (5) modsingle[authorize]: returned from auth_log (rlm_detail) for request 5 Tue Jul 7 11:34:15 2015 : Debug: (5) [auth_log] = ok Tue Jul 7 11:34:15 2015 : Debug: (5) modsingle[authorize]: calling mschap (rlm_mschap) for request 5 Tue Jul 7 11:34:15 2015 : Debug: (5) modsingle[authorize]: returned from mschap (rlm_mschap) for request 5 Tue Jul 7 11:34:15 2015 : Debug: (5) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (5) modsingle[authorize]: calling suffix (rlm_realm) for request 5 Tue Jul 7 11:34:15 2015 : Debug: (5) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (5) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (5) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (5) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (5) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (5) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (5) modsingle[authorize]: returned from suffix (rlm_realm) for request 5 Tue Jul 7 11:34:15 2015 : Debug: (5) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (5) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) { Tue Jul 7 11:34:15 2015 : Debug: (5) EXPAND %{Aruba-Essid-Name} Tue Jul 7 11:34:15 2015 : Debug: (5) --> Tue Jul 7 11:34:15 2015 : Debug: (5) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (5) modsingle[authorize]: calling eap (rlm_eap) for request 5 Tue Jul 7 11:34:15 2015 : Debug: (5) eap: Peer sent code Response (2) ID 6 length 144 Tue Jul 7 11:34:15 2015 : Debug: (5) eap: Continuing tunnel setup Tue Jul 7 11:34:15 2015 : Debug: (5) modsingle[authorize]: returned from eap (rlm_eap) for request 5 Tue Jul 7 11:34:15 2015 : Debug: (5) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (5) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (5) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (5) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (5) modsingle[authenticate]: calling eap (rlm_eap) for request 5 Tue Jul 7 11:34:15 2015 : Debug: (5) eap: Expiring EAP session with state 0xd753eb2fd355f204 Tue Jul 7 11:34:15 2015 : Debug: (5) eap: Finished EAP session with state 0xd753eb2fd355f204 Tue Jul 7 11:34:15 2015 : Debug: (5) eap: Previous EAP request found for state 0xd753eb2fd355f204, released from the list Tue Jul 7 11:34:15 2015 : Debug: (5) eap: Peer sent method PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (5) eap: EAP PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (5) eap: Calling eap_peap to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: processing EAP-TLS Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: TLS Length 134 Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: Length Included Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: eaptls_verify returned 11 Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: TLS_accept: SSLv3 read client key exchange A Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: <<< TLS 1.0 ChangeCipherSpec [length 0001] Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: <<< TLS 1.0 Handshake [length 0010], Finished Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: TLS_accept: SSLv3 read finished A Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: >>> TLS 1.0 ChangeCipherSpec [length 0001] Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: TLS_accept: SSLv3 write change cipher spec A Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: >>> TLS 1.0 Handshake [length 0010], Finished Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: TLS_accept: SSLv3 write finished A Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: TLS_accept: SSLv3 flush data Tue Jul 7 11:34:15 2015 : Debug: TLS: adding session d6682dd3caa2bb9f8a51285374b41b96cfec72a5ee36538cfb0ce8870947153a to cache Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: (other): SSL negotiation finished successfully Tue Jul 7 11:34:15 2015 : Debug: SSL Connection Established Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: eaptls_process returned 13 Tue Jul 7 11:34:15 2015 : Debug: (5) eap_peap: FR_TLS_HANDLED Tue Jul 7 11:34:15 2015 : Debug: (5) eap: EAP session adding &reply:State = 0xd753eb2fd254f204 Tue Jul 7 11:34:15 2015 : Debug: (5) modsingle[authenticate]: returned from eap (rlm_eap) for request 5 Tue Jul 7 11:34:15 2015 : Debug: (5) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (5) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (5) Using Post-Auth-Type Challenge Tue Jul 7 11:34:15 2015 : Debug: (5) Post-Auth-Type sub-section not found. Ignoring. Tue Jul 7 11:34:15 2015 : Debug: (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (5) session-state: Nothing to cache Tue Jul 7 11:34:15 2015 : Debug: (5) Sent Access-Challenge Id 112 from 10.57.235.64:1812 to 10.57.123.29:3629 length 0 Tue Jul 7 11:34:15 2015 : Debug: (5) EAP-Message = 0x01070041190014030100010116030100305d0fe08d6de455dd36e51d215b8dec203b4ac7787842474837a6cda32aaf0e023c752083d16b67de397bdc875265426b Tue Jul 7 11:34:15 2015 : Debug: (5) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (5) State = 0xd753eb2fd254f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (5) Finished request Tue Jul 7 11:34:15 2015 : Debug: Waking up in 4.8 seconds. Tue Jul 7 11:34:15 2015 : Debug: (6) Received Access-Request Id 113 from 10.57.123.29:3629 to 10.57.235.64:1812 length 221 Tue Jul 7 11:34:15 2015 : Debug: (6) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (6) Framed-MTU = 1450 Tue Jul 7 11:34:15 2015 : Debug: (6) EAP-Message = 0x020700061900 Tue Jul 7 11:34:15 2015 : Debug: (6) Message-Authenticator = 0x1e421929213c1e3347371eaad7dce9e1 Tue Jul 7 11:34:15 2015 : Debug: (6) Chargeable-User-Identity = 0x00 Tue Jul 7 11:34:15 2015 : Debug: (6) NAS-IP-Address = 10.57.123.29 Tue Jul 7 11:34:15 2015 : Debug: (6) NAS-Identifier = 'ITS-TEST' Tue Jul 7 11:34:15 2015 : Debug: (6) NAS-Port = 33779942 Tue Jul 7 11:34:15 2015 : Debug: (6) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' Tue Jul 7 11:34:15 2015 : Debug: (6) NAS-Port-Type = Wireless-802.11 Tue Jul 7 11:34:15 2015 : Debug: (6) Service-Type = Framed-User Tue Jul 7 11:34:15 2015 : Debug: (6) Framed-Protocol = PPP Tue Jul 7 11:34:15 2015 : Debug: (6) Calling-Station-Id = '10-1C-0C-79-26-49' Tue Jul 7 11:34:15 2015 : Debug: (6) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' Tue Jul 7 11:34:15 2015 : Debug: (6) Acct-Session-Id = '115060711294f0' Tue Jul 7 11:34:15 2015 : Debug: (6) State = 0xd753eb2fd254f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (6) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (6) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (6) authorize { Tue Jul 7 11:34:15 2015 : Debug: (6) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (6) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (6) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (6) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (6) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (6) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (6) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (6) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (6) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (6) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (6) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (6) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (6) modsingle[authorize]: calling auth_log (rlm_detail) for request 6 Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/radacct/ Tue Jul 7 11:34:15 2015 : Debug: attribute --> Client-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> /auth- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (6) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (6) auth_log: --> /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: (6) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: %t Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> t Tue Jul 7 11:34:15 2015 : Debug: (6) auth_log: EXPAND %t Tue Jul 7 11:34:15 2015 : Debug: (6) auth_log: --> Tue Jul 7 11:34:15 2015 Tue Jul 7 11:34:15 2015 : Debug: (6) modsingle[authorize]: returned from auth_log (rlm_detail) for request 6 Tue Jul 7 11:34:15 2015 : Debug: (6) [auth_log] = ok Tue Jul 7 11:34:15 2015 : Debug: (6) modsingle[authorize]: calling mschap (rlm_mschap) for request 6 Tue Jul 7 11:34:15 2015 : Debug: (6) modsingle[authorize]: returned from mschap (rlm_mschap) for request 6 Tue Jul 7 11:34:15 2015 : Debug: (6) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (6) modsingle[authorize]: calling suffix (rlm_realm) for request 6 Tue Jul 7 11:34:15 2015 : Debug: (6) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (6) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (6) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (6) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (6) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (6) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (6) modsingle[authorize]: returned from suffix (rlm_realm) for request 6 Tue Jul 7 11:34:15 2015 : Debug: (6) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (6) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) { Tue Jul 7 11:34:15 2015 : Debug: (6) EXPAND %{Aruba-Essid-Name} Tue Jul 7 11:34:15 2015 : Debug: (6) --> Tue Jul 7 11:34:15 2015 : Debug: (6) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (6) modsingle[authorize]: calling eap (rlm_eap) for request 6 Tue Jul 7 11:34:15 2015 : Debug: (6) eap: Peer sent code Response (2) ID 7 length 6 Tue Jul 7 11:34:15 2015 : Debug: (6) eap: Continuing tunnel setup Tue Jul 7 11:34:15 2015 : Debug: (6) modsingle[authorize]: returned from eap (rlm_eap) for request 6 Tue Jul 7 11:34:15 2015 : Debug: (6) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (6) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (6) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (6) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (6) modsingle[authenticate]: calling eap (rlm_eap) for request 6 Tue Jul 7 11:34:15 2015 : Debug: (6) eap: Expiring EAP session with state 0xd753eb2fd254f204 Tue Jul 7 11:34:15 2015 : Debug: (6) eap: Finished EAP session with state 0xd753eb2fd254f204 Tue Jul 7 11:34:15 2015 : Debug: (6) eap: Previous EAP request found for state 0xd753eb2fd254f204, released from the list Tue Jul 7 11:34:15 2015 : Debug: (6) eap: Peer sent method PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (6) eap: EAP PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (6) eap: Calling eap_peap to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (6) eap_peap: processing EAP-TLS Tue Jul 7 11:34:15 2015 : Debug: (6) eap_peap: Received TLS ACK Tue Jul 7 11:34:15 2015 : Debug: (6) eap_peap: Received TLS ACK Tue Jul 7 11:34:15 2015 : Debug: (6) eap_peap: ACK handshake is finished Tue Jul 7 11:34:15 2015 : Debug: (6) eap_peap: eaptls_verify returned 3 Tue Jul 7 11:34:15 2015 : Debug: (6) eap_peap: eaptls_process returned 3 Tue Jul 7 11:34:15 2015 : Debug: (6) eap_peap: FR_TLS_SUCCESS Tue Jul 7 11:34:15 2015 : Debug: (6) eap_peap: Session established. Decoding tunneled attributes Tue Jul 7 11:34:15 2015 : Debug: (6) eap_peap: PEAP state TUNNEL ESTABLISHED Tue Jul 7 11:34:15 2015 : Debug: (6) eap: EAP session adding &reply:State = 0xd753eb2fd15bf204 Tue Jul 7 11:34:15 2015 : Debug: (6) modsingle[authenticate]: returned from eap (rlm_eap) for request 6 Tue Jul 7 11:34:15 2015 : Debug: (6) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (6) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (6) Using Post-Auth-Type Challenge Tue Jul 7 11:34:15 2015 : Debug: (6) Post-Auth-Type sub-section not found. Ignoring. Tue Jul 7 11:34:15 2015 : Debug: (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (6) session-state: Nothing to cache Tue Jul 7 11:34:15 2015 : Debug: (6) Sent Access-Challenge Id 113 from 10.57.235.64:1812 to 10.57.123.29:3629 length 0 Tue Jul 7 11:34:15 2015 : Debug: (6) EAP-Message = 0x0108002b19001703010020e2408a5a290722186a45c25a785d0ce50e327c1e9eacd88d24211172cf87a7b9 Tue Jul 7 11:34:15 2015 : Debug: (6) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (6) State = 0xd753eb2fd15bf204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (6) Finished request Tue Jul 7 11:34:15 2015 : Debug: Waking up in 4.8 seconds. Tue Jul 7 11:34:15 2015 : Debug: (7) Received Access-Request Id 114 from 10.57.123.29:3629 to 10.57.235.64:1812 length 258 Tue Jul 7 11:34:15 2015 : Debug: (7) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (7) Framed-MTU = 1450 Tue Jul 7 11:34:15 2015 : Debug: (7) EAP-Message = 0x0208002b190017030100207907257258400415cc5e58351d16858123106a2ef33f467da8af0218c00bfe5f Tue Jul 7 11:34:15 2015 : Debug: (7) Message-Authenticator = 0x0c1378721ae403a585f638ac5c628af0 Tue Jul 7 11:34:15 2015 : Debug: (7) Chargeable-User-Identity = 0x00 Tue Jul 7 11:34:15 2015 : Debug: (7) NAS-IP-Address = 10.57.123.29 Tue Jul 7 11:34:15 2015 : Debug: (7) NAS-Identifier = 'ITS-TEST' Tue Jul 7 11:34:15 2015 : Debug: (7) NAS-Port = 33779942 Tue Jul 7 11:34:15 2015 : Debug: (7) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' Tue Jul 7 11:34:15 2015 : Debug: (7) NAS-Port-Type = Wireless-802.11 Tue Jul 7 11:34:15 2015 : Debug: (7) Service-Type = Framed-User Tue Jul 7 11:34:15 2015 : Debug: (7) Framed-Protocol = PPP Tue Jul 7 11:34:15 2015 : Debug: (7) Calling-Station-Id = '10-1C-0C-79-26-49' Tue Jul 7 11:34:15 2015 : Debug: (7) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' Tue Jul 7 11:34:15 2015 : Debug: (7) Acct-Session-Id = '115060711294f0' Tue Jul 7 11:34:15 2015 : Debug: (7) State = 0xd753eb2fd15bf204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (7) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (7) authorize { Tue Jul 7 11:34:15 2015 : Debug: (7) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: calling auth_log (rlm_detail) for request 7 Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/radacct/ Tue Jul 7 11:34:15 2015 : Debug: attribute --> Client-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> /auth- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (7) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (7) auth_log: --> /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: (7) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: %t Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> t Tue Jul 7 11:34:15 2015 : Debug: (7) auth_log: EXPAND %t Tue Jul 7 11:34:15 2015 : Debug: (7) auth_log: --> Tue Jul 7 11:34:15 2015 Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: returned from auth_log (rlm_detail) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) [auth_log] = ok Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: calling mschap (rlm_mschap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: returned from mschap (rlm_mschap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: calling suffix (rlm_realm) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: returned from suffix (rlm_realm) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (7) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) { Tue Jul 7 11:34:15 2015 : Debug: (7) EXPAND %{Aruba-Essid-Name} Tue Jul 7 11:34:15 2015 : Debug: (7) --> Tue Jul 7 11:34:15 2015 : Debug: (7) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: calling eap (rlm_eap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) eap: Peer sent code Response (2) ID 8 length 43 Tue Jul 7 11:34:15 2015 : Debug: (7) eap: Continuing tunnel setup Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: returned from eap (rlm_eap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (7) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (7) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (7) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authenticate]: calling eap (rlm_eap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) eap: Expiring EAP session with state 0xd753eb2fd15bf204 Tue Jul 7 11:34:15 2015 : Debug: (7) eap: Finished EAP session with state 0xd753eb2fd15bf204 Tue Jul 7 11:34:15 2015 : Debug: (7) eap: Previous EAP request found for state 0xd753eb2fd15bf204, released from the list Tue Jul 7 11:34:15 2015 : Debug: (7) eap: Peer sent method PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (7) eap: EAP PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (7) eap: Calling eap_peap to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: processing EAP-TLS Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: eaptls_verify returned 7 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Done initial handshake Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: eaptls_process returned 7 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: FR_TLS_OK Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Session established. Decoding tunneled attributes Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: PEAP state WAITING FOR INNER IDENTITY Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Identity - mytest Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Got inner identity 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Setting default EAP type for tunneled EAP session Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Got tunneled request Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: EAP-Message = 0x0208000b0174666b6c6169 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Setting User-Name to mytest Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Sending tunneled request to inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: EAP-Message = 0x0208000b0174666b6c6169 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (7) Virtual server inner-tunnel received request Tue Jul 7 11:34:15 2015 : Debug: (7) EAP-Message = 0x0208000b0174666b6c6169 Tue Jul 7 11:34:15 2015 : Debug: (7) FreeRADIUS-Proxied-To = 127.0.0.1 Tue Jul 7 11:34:15 2015 : Debug: (7) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (7) server inner-tunnel { Tue Jul 7 11:34:15 2015 : Debug: (7) session-state: No State attribute Tue Jul 7 11:34:15 2015 : Debug: (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (7) authorize { Tue Jul 7 11:34:15 2015 : Debug: (7) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (7) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: calling mschap (rlm_mschap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: returned from mschap (rlm_mschap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: calling suffix (rlm_realm) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (7) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: returned from suffix (rlm_realm) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (7) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk' && "%{Realm}" != 'domain.test.hk') { Tue Jul 7 11:34:15 2015 : Debug: (7) EXPAND %{Realm} Tue Jul 7 11:34:15 2015 : Debug: (7) --> NULL Tue Jul 7 11:34:15 2015 : Debug: (7) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk' && "%{Realm}" != 'domain.test.hk') -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (7) else { Tue Jul 7 11:34:15 2015 : Debug: (7) update control { Tue Jul 7 11:34:15 2015 : Debug: (7) &Proxy-To-Realm := LOCAL Tue Jul 7 11:34:15 2015 : Debug: (7) } # update control = noop Tue Jul 7 11:34:15 2015 : Debug: (7) } # else = noop Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: calling eap (rlm_eap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) eap: Peer sent code Response (2) ID 8 length 11 Tue Jul 7 11:34:15 2015 : Debug: (7) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authorize]: returned from eap (rlm_eap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (7) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (7) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (7) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authenticate]: calling eap (rlm_eap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) eap: Peer sent method Identity (1) Tue Jul 7 11:34:15 2015 : Debug: (7) eap: Calling eap_mschapv2 to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (7) eap_mschapv2: Issuing Challenge Tue Jul 7 11:34:15 2015 : Debug: (7) eap: EAP session adding &reply:State = 0x60e8791e60e1636f Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authenticate]: returned from eap (rlm_eap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (7) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (7) } # server inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (7) Virtual server sending reply Tue Jul 7 11:34:15 2015 : Debug: (7) EAP-Message = 0x0109002a1a01090025107261e4f7a366d8d693d01cb82395aa18667265657261646975732d332e302e38 Tue Jul 7 11:34:15 2015 : Debug: (7) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (7) State = 0x60e8791e60e1636f9ec0319b6608f77c Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Got tunneled reply code 11 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: EAP-Message = 0x0109002a1a01090025107261e4f7a366d8d693d01cb82395aa18667265657261646975732d332e302e38 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: State = 0x60e8791e60e1636f9ec0319b6608f77c Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Got tunneled reply RADIUS code 11 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: EAP-Message = 0x0109002a1a01090025107261e4f7a366d8d693d01cb82395aa18667265657261646975732d332e302e38 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: State = 0x60e8791e60e1636f9ec0319b6608f77c Tue Jul 7 11:34:15 2015 : Debug: (7) eap_peap: Got tunneled Access-Challenge Tue Jul 7 11:34:15 2015 : Debug: (7) eap: EAP session adding &reply:State = 0xd753eb2fd05af204 Tue Jul 7 11:34:15 2015 : Debug: (7) modsingle[authenticate]: returned from eap (rlm_eap) for request 7 Tue Jul 7 11:34:15 2015 : Debug: (7) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (7) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (7) Using Post-Auth-Type Challenge Tue Jul 7 11:34:15 2015 : Debug: (7) Post-Auth-Type sub-section not found. Ignoring. Tue Jul 7 11:34:15 2015 : Debug: (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (7) session-state: Nothing to cache Tue Jul 7 11:34:15 2015 : Debug: (7) Sent Access-Challenge Id 114 from 10.57.235.64:1812 to 10.57.123.29:3629 length 0 Tue Jul 7 11:34:15 2015 : Debug: (7) EAP-Message = 0x0109004b190017030100403d790d03630baa02bf081df73c129b0aac245a8994a038bf5f7eb3584a59f61c93c0efaa036a7da0041d7dda381403263c53bc447993b34fa58721d086ab2338 Tue Jul 7 11:34:15 2015 : Debug: (7) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (7) State = 0xd753eb2fd05af204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (7) Finished request Tue Jul 7 11:34:15 2015 : Debug: Waking up in 4.8 seconds. Tue Jul 7 11:34:15 2015 : Debug: (8) Received Access-Request Id 115 from 10.57.123.29:3629 to 10.57.235.64:1812 length 322 Tue Jul 7 11:34:15 2015 : Debug: (8) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (8) Framed-MTU = 1450 Tue Jul 7 11:34:15 2015 : Debug: (8) EAP-Message = 0x0209006b190017030100603392ae0e73456c490af763730ad78d99b24c9be47efb9619fc1acb4993b8e7e60a1173f50aaf3f0371bc4b94f44960f0ec5e1dfb29f839e92194a402a6b4fee43f005b464c24c5ba1371fa1a72d1b6c7debcf76772eaccd62e39d8add70675fc Tue Jul 7 11:34:15 2015 : Debug: (8) Message-Authenticator = 0x71f9fb4dbf9632ed93d952656f538c57 Tue Jul 7 11:34:15 2015 : Debug: (8) Chargeable-User-Identity = 0x00 Tue Jul 7 11:34:15 2015 : Debug: (8) NAS-IP-Address = 10.57.123.29 Tue Jul 7 11:34:15 2015 : Debug: (8) NAS-Identifier = 'ITS-TEST' Tue Jul 7 11:34:15 2015 : Debug: (8) NAS-Port = 33779942 Tue Jul 7 11:34:15 2015 : Debug: (8) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' Tue Jul 7 11:34:15 2015 : Debug: (8) NAS-Port-Type = Wireless-802.11 Tue Jul 7 11:34:15 2015 : Debug: (8) Service-Type = Framed-User Tue Jul 7 11:34:15 2015 : Debug: (8) Framed-Protocol = PPP Tue Jul 7 11:34:15 2015 : Debug: (8) Calling-Station-Id = '10-1C-0C-79-26-49' Tue Jul 7 11:34:15 2015 : Debug: (8) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' Tue Jul 7 11:34:15 2015 : Debug: (8) Acct-Session-Id = '115060711294f0' Tue Jul 7 11:34:15 2015 : Debug: (8) State = 0xd753eb2fd05af204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (8) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (8) authorize { Tue Jul 7 11:34:15 2015 : Debug: (8) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling auth_log (rlm_detail) for request 8 Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/radacct/ Tue Jul 7 11:34:15 2015 : Debug: attribute --> Client-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> /auth- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (8) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (8) auth_log: --> /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: (8) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: %t Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> t Tue Jul 7 11:34:15 2015 : Debug: (8) auth_log: EXPAND %t Tue Jul 7 11:34:15 2015 : Debug: (8) auth_log: --> Tue Jul 7 11:34:15 2015 Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from auth_log (rlm_detail) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [auth_log] = ok Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling mschap (rlm_mschap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from mschap (rlm_mschap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling suffix (rlm_realm) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from suffix (rlm_realm) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (8) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) { Tue Jul 7 11:34:15 2015 : Debug: (8) EXPAND %{Aruba-Essid-Name} Tue Jul 7 11:34:15 2015 : Debug: (8) --> Tue Jul 7 11:34:15 2015 : Debug: (8) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling eap (rlm_eap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Peer sent code Response (2) ID 9 length 107 Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Continuing tunnel setup Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from eap (rlm_eap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (8) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (8) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (8) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authenticate]: calling eap (rlm_eap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Expiring EAP session with state 0x60e8791e60e1636f Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Finished EAP session with state 0xd753eb2fd05af204 Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Previous EAP request found for state 0xd753eb2fd05af204, released from the list Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Peer sent method PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (8) eap: EAP PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Calling eap_peap to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: processing EAP-TLS Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: eaptls_verify returned 7 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: Done initial handshake Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: eaptls_process returned 7 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: FR_TLS_OK Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: Session established. Decoding tunneled attributes Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: PEAP state phase2 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: EAP type MSCHAPv2 (26) Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: Got tunneled request Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: EAP-Message = 0x020900411a0209003c312fc6fbee6a59ca39c65689213c66ccb40000000000000000162cf8210837ddada9cc14ebf1ff884727c57a97aab9f3760074666b6c6169 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: Setting User-Name to mytest Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: Sending tunneled request to inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: EAP-Message = 0x020900411a0209003c312fc6fbee6a59ca39c65689213c66ccb40000000000000000162cf8210837ddada9cc14ebf1ff884727c57a97aab9f3760074666b6c6169 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: State = 0x60e8791e60e1636f9ec0319b6608f77c Tue Jul 7 11:34:15 2015 : Debug: (8) Virtual server inner-tunnel received request Tue Jul 7 11:34:15 2015 : Debug: (8) EAP-Message = 0x020900411a0209003c312fc6fbee6a59ca39c65689213c66ccb40000000000000000162cf8210837ddada9cc14ebf1ff884727c57a97aab9f3760074666b6c6169 Tue Jul 7 11:34:15 2015 : Debug: (8) FreeRADIUS-Proxied-To = 127.0.0.1 Tue Jul 7 11:34:15 2015 : Debug: (8) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (8) State = 0x60e8791e60e1636f9ec0319b6608f77c Tue Jul 7 11:34:15 2015 : Debug: (8) server inner-tunnel { Tue Jul 7 11:34:15 2015 : Debug: (8) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (8) authorize { Tue Jul 7 11:34:15 2015 : Debug: (8) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling mschap (rlm_mschap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from mschap (rlm_mschap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling suffix (rlm_realm) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (8) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from suffix (rlm_realm) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (8) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk' && "%{Realm}" != 'domain.test.hk') { Tue Jul 7 11:34:15 2015 : Debug: (8) EXPAND %{Realm} Tue Jul 7 11:34:15 2015 : Debug: (8) --> NULL Tue Jul 7 11:34:15 2015 : Debug: (8) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk' && "%{Realm}" != 'domain.test.hk') -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (8) else { Tue Jul 7 11:34:15 2015 : Debug: (8) update control { Tue Jul 7 11:34:15 2015 : Debug: (8) &Proxy-To-Realm := LOCAL Tue Jul 7 11:34:15 2015 : Debug: (8) } # update control = noop Tue Jul 7 11:34:15 2015 : Debug: (8) } # else = noop Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling eap (rlm_eap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Peer sent code Response (2) ID 9 length 65 Tue Jul 7 11:34:15 2015 : Debug: (8) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from eap (rlm_eap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [eap] = updated Tue Jul 7 11:34:15 2015 : Debug: (8) if (&EAP-Message) { Tue Jul 7 11:34:15 2015 : Debug: (8) if (&EAP-Message) -> TRUE Tue Jul 7 11:34:15 2015 : Debug: (8) if (&EAP-Message) { Tue Jul 7 11:34:15 2015 : Debug: (8) redundant ldap_Portal_redundant { Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling ldap_DB_1 (rlm_ldap) for request 8 Tue Jul 7 11:34:15 2015 : Info: rlm_ldap (ldap_DB_1): Closing connection (4): Hit idle_timeout, was idle for 215 seconds Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap: Closing libldap handle 0x1e96190 Tue Jul 7 11:34:15 2015 : Info: rlm_ldap (ldap_DB_1): Closing connection (3): Hit idle_timeout, was idle for 215 seconds Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap: Closing libldap handle 0x1e95870 Tue Jul 7 11:34:15 2015 : Info: rlm_ldap (ldap_DB_1): Closing connection (2): Hit idle_timeout, was idle for 215 seconds Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap: Closing libldap handle 0x1e84eb0 Tue Jul 7 11:34:15 2015 : Info: rlm_ldap (ldap_DB_1): Closing connection (1): Hit idle_timeout, was idle for 215 seconds Tue Jul 7 11:34:15 2015 : Warning: rlm_ldap (ldap_DB_1): You probably need to lower "min" Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap: Closing libldap handle 0x1e845e0 Tue Jul 7 11:34:15 2015 : Info: rlm_ldap (ldap_DB_1): Closing connection (0): Hit idle_timeout, was idle for 215 seconds Tue Jul 7 11:34:15 2015 : Warning: rlm_ldap (ldap_DB_1): You probably need to lower "min" Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap: Closing libldap handle 0x1e7bf40 Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): 0 of 0 connections in use. You may need to increase "spare" Tue Jul 7 11:34:15 2015 : Info: rlm_ldap (ldap_DB_1): Opening additional connection (5), 1 of 32 pending slots used Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): Connecting to ldap://10.57.123.30:389 Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): New libldap handle 0x1e7bf40 Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): Waiting for bind result... Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): Bind successful Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): Reserved connection (5) Tue Jul 7 11:34:15 2015 : Debug: (&(uid=%{%{Stripped-User-Name}:-%{User-Name}})(&(!(postOfficeBox=none)))) Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> (&(uid= Tue Jul 7 11:34:15 2015 : Debug: if { Tue Jul 7 11:34:15 2015 : Debug: attribute --> Stripped-User-Name Tue Jul 7 11:34:15 2015 : Debug: } Tue Jul 7 11:34:15 2015 : Debug: else { Tue Jul 7 11:34:15 2015 : Debug: attribute --> User-Name Tue Jul 7 11:34:15 2015 : Debug: } Tue Jul 7 11:34:15 2015 : Debug: literal --> )(&(!(postOfficeBox=none)))) Tue Jul 7 11:34:15 2015 : Debug: (8) ldap_DB_1: EXPAND (&(uid=%{%{Stripped-User-Name}:-%{User-Name}})(&(!(postOfficeBox=none)))) Tue Jul 7 11:34:15 2015 : Debug: (8) ldap_DB_1: --> (&(uid=mytest)(&(!(postOfficeBox=none)))) Tue Jul 7 11:34:15 2015 : Debug: (8) ldap_DB_1: Performing search in "ou=wifi,o=test,c=hk" with filter "(&(uid=mytest)(&(!(postOfficeBox=none))))", scope "sub" Tue Jul 7 11:34:15 2015 : Debug: (8) ldap_DB_1: Waiting for search result... Tue Jul 7 11:34:15 2015 : Debug: (8) ldap_DB_1: User object found at DN "uid=mytest,ou=wifi,o=test,c=hk" Tue Jul 7 11:34:15 2015 : Debug: (8) ldap_DB_1: Processing user attributes Tue Jul 7 11:34:15 2015 : Debug: (8) ldap_DB_1: &control:Password-With-Header += '{CRYPT}$1$LyEitgr2$Ai00nmUxstoU/e1hDPkjL1' Tue Jul 7 11:34:15 2015 : Debug: (8) ldap_DB_1: &control:NT-Password := 0x3944424431303039393541413639453130464635353837393733454432323846 Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): Released connection (5) Tue Jul 7 11:34:15 2015 : Info: rlm_ldap (ldap_DB_1): 0 of 1 connections in use. Need more spares Tue Jul 7 11:34:15 2015 : Info: rlm_ldap (ldap_DB_1): Opening additional connection (6), 1 of 31 pending slots used Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): Connecting to ldap://10.57.123.30:389 Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): New libldap handle 0x1e7c160 Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): Waiting for bind result... Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): Bind successful Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from ldap_DB_1 (rlm_ldap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [ldap_DB_1] = updated Tue Jul 7 11:34:15 2015 : Debug: (8) } # redundant ldap_Portal_redundant = updated Tue Jul 7 11:34:15 2015 : Debug: (8) } # if (&EAP-Message) = updated Tue Jul 7 11:34:15 2015 : Debug: (8) ... skipping else for request 8: Preceding "if" was taken Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling expiration (rlm_expiration) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from expiration (rlm_expiration) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [expiration] = noop Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling logintime (rlm_logintime) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from logintime (rlm_logintime) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [logintime] = noop Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: calling pap (rlm_pap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) pap: Converted: Password-With-Header = '{CRYPT}$1$LyEitgr2$Ai00nmUxstoU/e1hDPkjL1' -> Crypt-Password = '$1$LyEitgr2$Ai00nmUxstoU/e1hDPkjL1' Tue Jul 7 11:34:15 2015 : Debug: (8) pap: Removing &control:Password-With-Header Tue Jul 7 11:34:15 2015 : Debug: (8) pap: Normalizing NT-Password from hex encoding, 32 bytes -> 16 bytes Tue Jul 7 11:34:15 2015 : WARNING: (8) pap: Auth-Type already set. Not setting to PAP Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authorize]: returned from pap (rlm_pap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [pap] = noop Tue Jul 7 11:34:15 2015 : Debug: (8) } # authorize = updated Tue Jul 7 11:34:15 2015 : Debug: (8) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (8) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authenticate]: calling eap (rlm_eap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Expiring EAP session with state 0x60e8791e60e1636f Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Finished EAP session with state 0x60e8791e60e1636f Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Previous EAP request found for state 0x60e8791e60e1636f, released from the list Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Peer sent method MSCHAPv2 (26) Tue Jul 7 11:34:15 2015 : Debug: (8) eap: EAP MSCHAPv2 (26) Tue Jul 7 11:34:15 2015 : Debug: (8) eap: Calling eap_mschapv2 to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (8) eap_mschapv2: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (8) eap_mschapv2: Auth-Type MS-CHAP { Tue Jul 7 11:34:15 2015 : Debug: (8) eap_mschapv2: modsingle[authenticate]: calling mschap (rlm_mschap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) mschap: Found NT-Password Tue Jul 7 11:34:15 2015 : Debug: (8) mschap: Creating challenge hash with username: mytest Tue Jul 7 11:34:15 2015 : Debug: (8) mschap: Client is using MS-CHAPv2 Tue Jul 7 11:34:15 2015 : ERROR: (8) mschap: MS-CHAP2-Response is incorrect Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authenticate]: returned from mschap (rlm_mschap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [mschap] = reject Tue Jul 7 11:34:15 2015 : Debug: (8) } # Auth-Type MS-CHAP = reject Tue Jul 7 11:34:15 2015 : Debug: (8) MSCHAP-Error: E=691 R=1 Tue Jul 7 11:34:15 2015 : Debug: (8) Could not parse new challenge from MS-CHAP-Error: 2 Tue Jul 7 11:34:15 2015 : ERROR: (8) MSCHAP Failure Tue Jul 7 11:34:15 2015 : Debug: (8) eap: EAP session adding &reply:State = 0x60e8791e61e2636f Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authenticate]: returned from eap (rlm_eap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (8) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (8) } # server inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (8) Virtual server sending reply Tue Jul 7 11:34:15 2015 : Debug: (8) EAP-Message = 0x010a00121a0409000d453d36393120523d31 Tue Jul 7 11:34:15 2015 : Debug: (8) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (8) State = 0x60e8791e61e2636f9ec0319b6608f77c Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: Got tunneled reply code 11 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: EAP-Message = 0x010a00121a0409000d453d36393120523d31 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: State = 0x60e8791e61e2636f9ec0319b6608f77c Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: Got tunneled reply RADIUS code 11 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: EAP-Message = 0x010a00121a0409000d453d36393120523d31 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: State = 0x60e8791e61e2636f9ec0319b6608f77c Tue Jul 7 11:34:15 2015 : Debug: (8) eap_peap: Got tunneled Access-Challenge Tue Jul 7 11:34:15 2015 : Debug: (8) eap: EAP session adding &reply:State = 0xd753eb2fdf59f204 Tue Jul 7 11:34:15 2015 : Debug: (8) modsingle[authenticate]: returned from eap (rlm_eap) for request 8 Tue Jul 7 11:34:15 2015 : Debug: (8) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (8) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (8) Using Post-Auth-Type Challenge Tue Jul 7 11:34:15 2015 : Debug: (8) Post-Auth-Type sub-section not found. Ignoring. Tue Jul 7 11:34:15 2015 : Debug: (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (8) session-state: Nothing to cache Tue Jul 7 11:34:15 2015 : Debug: (8) Sent Access-Challenge Id 115 from 10.57.235.64:1812 to 10.57.123.29:3629 length 0 Tue Jul 7 11:34:15 2015 : Debug: (8) EAP-Message = 0x010a003b190017030100308c51fce838f48070648dbfc9a7b5c1dbc331274bb8ddb223d70260530af67cc4bc9cfb37447de221ba0fe514f146e5ce Tue Jul 7 11:34:15 2015 : Debug: (8) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (8) State = 0xd753eb2fdf59f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (8) Finished request Tue Jul 7 11:34:15 2015 : Debug: Waking up in 4.8 seconds. Tue Jul 7 11:34:15 2015 : Debug: (9) Received Access-Request Id 116 from 10.57.123.29:3629 to 10.57.235.64:1812 length 258 Tue Jul 7 11:34:15 2015 : Debug: (9) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (9) Framed-MTU = 1450 Tue Jul 7 11:34:15 2015 : Debug: (9) EAP-Message = 0x020a002b190017030100207f59bfed6b0a5fe05799b4a7b89f31f98709fb063b16153718bc9c1e88c7a721 Tue Jul 7 11:34:15 2015 : Debug: (9) Message-Authenticator = 0xa7bb823fc1579f8de3762d8d40770352 Tue Jul 7 11:34:15 2015 : Debug: (9) Chargeable-User-Identity = 0x00 Tue Jul 7 11:34:15 2015 : Debug: (9) NAS-IP-Address = 10.57.123.29 Tue Jul 7 11:34:15 2015 : Debug: (9) NAS-Identifier = 'ITS-TEST' Tue Jul 7 11:34:15 2015 : Debug: (9) NAS-Port = 33779942 Tue Jul 7 11:34:15 2015 : Debug: (9) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' Tue Jul 7 11:34:15 2015 : Debug: (9) NAS-Port-Type = Wireless-802.11 Tue Jul 7 11:34:15 2015 : Debug: (9) Service-Type = Framed-User Tue Jul 7 11:34:15 2015 : Debug: (9) Framed-Protocol = PPP Tue Jul 7 11:34:15 2015 : Debug: (9) Calling-Station-Id = '10-1C-0C-79-26-49' Tue Jul 7 11:34:15 2015 : Debug: (9) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' Tue Jul 7 11:34:15 2015 : Debug: (9) Acct-Session-Id = '115060711294f0' Tue Jul 7 11:34:15 2015 : Debug: (9) State = 0xd753eb2fdf59f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (9) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (9) authorize { Tue Jul 7 11:34:15 2015 : Debug: (9) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling auth_log (rlm_detail) for request 9 Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/radacct/ Tue Jul 7 11:34:15 2015 : Debug: attribute --> Client-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> /auth- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (9) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (9) auth_log: --> /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: (9) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.57.123.29/auth-20150707 Tue Jul 7 11:34:15 2015 : Debug: %t Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> t Tue Jul 7 11:34:15 2015 : Debug: (9) auth_log: EXPAND %t Tue Jul 7 11:34:15 2015 : Debug: (9) auth_log: --> Tue Jul 7 11:34:15 2015 Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from auth_log (rlm_detail) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [auth_log] = ok Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling mschap (rlm_mschap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from mschap (rlm_mschap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling suffix (rlm_realm) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from suffix (rlm_realm) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (9) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) { Tue Jul 7 11:34:15 2015 : Debug: (9) EXPAND %{Aruba-Essid-Name} Tue Jul 7 11:34:15 2015 : Debug: (9) --> Tue Jul 7 11:34:15 2015 : Debug: (9) if (Called-Station-Id =~ /TEST SSID/ || "%{Aruba-Essid-Name}" =~ /TEST SSID/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling eap (rlm_eap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Peer sent code Response (2) ID 10 length 43 Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Continuing tunnel setup Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from eap (rlm_eap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [eap] = ok Tue Jul 7 11:34:15 2015 : Debug: (9) } # authorize = ok Tue Jul 7 11:34:15 2015 : Debug: (9) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (9) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authenticate]: calling eap (rlm_eap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Expiring EAP session with state 0x60e8791e61e2636f Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Finished EAP session with state 0xd753eb2fdf59f204 Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Previous EAP request found for state 0xd753eb2fdf59f204, released from the list Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Peer sent method PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (9) eap: EAP PEAP (25) Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Calling eap_peap to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: processing EAP-TLS Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: eaptls_verify returned 7 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: Done initial handshake Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: eaptls_process returned 7 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: FR_TLS_OK Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: Session established. Decoding tunneled attributes Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: PEAP state phase2 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: EAP type MSCHAPv2 (26) Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: Got tunneled request Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: EAP-Message = 0x020a00091a04090004 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: Setting User-Name to mytest Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: Sending tunneled request to inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: EAP-Message = 0x020a00091a04090004 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: State = 0x60e8791e61e2636f9ec0319b6608f77c Tue Jul 7 11:34:15 2015 : Debug: (9) Virtual server inner-tunnel received request Tue Jul 7 11:34:15 2015 : Debug: (9) EAP-Message = 0x020a00091a04090004 Tue Jul 7 11:34:15 2015 : Debug: (9) FreeRADIUS-Proxied-To = 127.0.0.1 Tue Jul 7 11:34:15 2015 : Debug: (9) User-Name = 'mytest' Tue Jul 7 11:34:15 2015 : Debug: (9) State = 0x60e8791e61e2636f9ec0319b6608f77c Tue Jul 7 11:34:15 2015 : Debug: (9) server inner-tunnel { Tue Jul 7 11:34:15 2015 : Debug: (9) session-state: No cached attributes Tue Jul 7 11:34:15 2015 : Debug: (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (9) authorize { Tue Jul 7 11:34:15 2015 : Debug: (9) policy filter_username { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ / /) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ / /) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /@.*@/ ) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /@.*@/ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /\\.\\./ ) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /\\.\\./ ) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { Tue Jul 7 11:34:15 2015 : Debug: (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /\\.$/) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /\\.$/) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /@\\./) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&User-Name =~ /@\\./) -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) } # policy filter_username = notfound Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling mschap (rlm_mschap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from mschap (rlm_mschap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [mschap] = noop Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling suffix (rlm_realm) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: Checking for suffix after "@" Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: No '@' in User-Name = "mytest", looking up realm NULL Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: Found realm "NULL" Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: Adding Stripped-User-Name = "mytest" Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: Adding Realm = "NULL" Tue Jul 7 11:34:15 2015 : Debug: (9) suffix: Authentication realm is LOCAL Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from suffix (rlm_realm) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [suffix] = ok Tue Jul 7 11:34:15 2015 : Debug: (9) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk' && "%{Realm}" != 'domain.test.hk') { Tue Jul 7 11:34:15 2015 : Debug: (9) EXPAND %{Realm} Tue Jul 7 11:34:15 2015 : Debug: (9) --> NULL Tue Jul 7 11:34:15 2015 : Debug: (9) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk' && "%{Realm}" != 'domain.test.hk') -> FALSE Tue Jul 7 11:34:15 2015 : Debug: (9) else { Tue Jul 7 11:34:15 2015 : Debug: (9) update control { Tue Jul 7 11:34:15 2015 : Debug: (9) &Proxy-To-Realm := LOCAL Tue Jul 7 11:34:15 2015 : Debug: (9) } # update control = noop Tue Jul 7 11:34:15 2015 : Debug: (9) } # else = noop Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling eap (rlm_eap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Peer sent code Response (2) ID 10 length 9 Tue Jul 7 11:34:15 2015 : Debug: (9) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from eap (rlm_eap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [eap] = updated Tue Jul 7 11:34:15 2015 : Debug: (9) if (&EAP-Message) { Tue Jul 7 11:34:15 2015 : Debug: (9) if (&EAP-Message) -> TRUE Tue Jul 7 11:34:15 2015 : Debug: (9) if (&EAP-Message) { Tue Jul 7 11:34:15 2015 : Debug: (9) redundant ldap_Portal_redundant { Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling ldap_DB_1 (rlm_ldap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): Reserved connection (6) Tue Jul 7 11:34:15 2015 : Debug: (&(uid=%{%{Stripped-User-Name}:-%{User-Name}})(&(!(postOfficeBox=none)))) Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> (&(uid= Tue Jul 7 11:34:15 2015 : Debug: if { Tue Jul 7 11:34:15 2015 : Debug: attribute --> Stripped-User-Name Tue Jul 7 11:34:15 2015 : Debug: } Tue Jul 7 11:34:15 2015 : Debug: else { Tue Jul 7 11:34:15 2015 : Debug: attribute --> User-Name Tue Jul 7 11:34:15 2015 : Debug: } Tue Jul 7 11:34:15 2015 : Debug: literal --> )(&(!(postOfficeBox=none)))) Tue Jul 7 11:34:15 2015 : Debug: (9) ldap_DB_1: EXPAND (&(uid=%{%{Stripped-User-Name}:-%{User-Name}})(&(!(postOfficeBox=none)))) Tue Jul 7 11:34:15 2015 : Debug: (9) ldap_DB_1: --> (&(uid=mytest)(&(!(postOfficeBox=none)))) Tue Jul 7 11:34:15 2015 : Debug: (9) ldap_DB_1: Performing search in "ou=wifi,o=test,c=hk" with filter "(&(uid=mytest)(&(!(postOfficeBox=none))))", scope "sub" Tue Jul 7 11:34:15 2015 : Debug: (9) ldap_DB_1: Waiting for search result... Tue Jul 7 11:34:15 2015 : Debug: (9) ldap_DB_1: User object found at DN "uid=mytest,ou=wifi,o=test,c=hk" Tue Jul 7 11:34:15 2015 : Debug: (9) ldap_DB_1: Processing user attributes Tue Jul 7 11:34:15 2015 : Debug: (9) ldap_DB_1: &control:Password-With-Header += '{CRYPT}$1$LyEitgr2$Ai00nmUxstoU/e1hDPkjL1' Tue Jul 7 11:34:15 2015 : Debug: (9) ldap_DB_1: &control:NT-Password := 0x3944424431303039393541413639453130464635353837393733454432323846 Tue Jul 7 11:34:15 2015 : Debug: rlm_ldap (ldap_DB_1): Released connection (6) Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from ldap_DB_1 (rlm_ldap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [ldap_DB_1] = updated Tue Jul 7 11:34:15 2015 : Debug: (9) } # redundant ldap_Portal_redundant = updated Tue Jul 7 11:34:15 2015 : Debug: (9) } # if (&EAP-Message) = updated Tue Jul 7 11:34:15 2015 : Debug: (9) ... skipping else for request 9: Preceding "if" was taken Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling expiration (rlm_expiration) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from expiration (rlm_expiration) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [expiration] = noop Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling logintime (rlm_logintime) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from logintime (rlm_logintime) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [logintime] = noop Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: calling pap (rlm_pap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) pap: Converted: Password-With-Header = '{CRYPT}$1$LyEitgr2$Ai00nmUxstoU/e1hDPkjL1' -> Crypt-Password = '$1$LyEitgr2$Ai00nmUxstoU/e1hDPkjL1' Tue Jul 7 11:34:15 2015 : Debug: (9) pap: Removing &control:Password-With-Header Tue Jul 7 11:34:15 2015 : Debug: (9) pap: Normalizing NT-Password from hex encoding, 32 bytes -> 16 bytes Tue Jul 7 11:34:15 2015 : WARNING: (9) pap: Auth-Type already set. Not setting to PAP Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authorize]: returned from pap (rlm_pap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [pap] = noop Tue Jul 7 11:34:15 2015 : Debug: (9) } # authorize = updated Tue Jul 7 11:34:15 2015 : Debug: (9) Found Auth-Type = EAP Tue Jul 7 11:34:15 2015 : Debug: (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (9) authenticate { Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authenticate]: calling eap (rlm_eap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Expiring EAP session with state 0x60e8791e61e2636f Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Finished EAP session with state 0x60e8791e61e2636f Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Previous EAP request found for state 0x60e8791e61e2636f, released from the list Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Peer sent method MSCHAPv2 (26) Tue Jul 7 11:34:15 2015 : Debug: (9) eap: EAP MSCHAPv2 (26) Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Calling eap_mschapv2 to process EAP data Tue Jul 7 11:34:15 2015 : Debug: (9) eap: Freeing handler Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authenticate]: returned from eap (rlm_eap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [eap] = reject Tue Jul 7 11:34:15 2015 : Debug: (9) } # authenticate = reject Tue Jul 7 11:34:15 2015 : Debug: (9) Failed to authenticate the user Tue Jul 7 11:34:15 2015 : Auth: (9) Login incorrect: [mytest] (from client h3c-test-123.29 port 0 via TLS tunnel) Tue Jul 7 11:34:15 2015 : Debug: (9) Using Post-Auth-Type Reject Tue Jul 7 11:34:15 2015 : Debug: (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (9) Post-Auth-Type REJECT { Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 9 Tue Jul 7 11:34:15 2015 : Debug: %{User-Name} Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: attribute --> User-Name Tue Jul 7 11:34:15 2015 : Debug: (9) attr_filter.access_reject: EXPAND %{User-Name} Tue Jul 7 11:34:15 2015 : Debug: (9) attr_filter.access_reject: --> mytest Tue Jul 7 11:34:15 2015 : Debug: (9) attr_filter.access_reject: Matched entry DEFAULT at line 16 Tue Jul 7 11:34:15 2015 : Debug: (9) attr_filter.access_reject: EAP-Message = 0x040a0004 allowed by EAP-Message =* 0x Tue Jul 7 11:34:15 2015 : Debug: (9) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules Tue Jul 7 11:34:15 2015 : Debug: (9) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x Tue Jul 7 11:34:15 2015 : Debug: (9) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [attr_filter.access_reject] = updated Tue Jul 7 11:34:15 2015 : Debug: (9) update outer.session-state { Tue Jul 7 11:34:15 2015 : Debug: (9) No attributes updated Tue Jul 7 11:34:15 2015 : Debug: (9) } # update outer.session-state = noop Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[post-auth]: calling linelog (rlm_linelog) for request 9 Tue Jul 7 11:34:15 2015 : Debug: messages.%{%{reply:Packet-Type}:-default} Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> messages. Tue Jul 7 11:34:15 2015 : Debug: if { Tue Jul 7 11:34:15 2015 : Debug: attribute --> Packet-Type Tue Jul 7 11:34:15 2015 : Debug: } Tue Jul 7 11:34:15 2015 : Debug: else { Tue Jul 7 11:34:15 2015 : Debug: literal --> default Tue Jul 7 11:34:15 2015 : Debug: } Tue Jul 7 11:34:15 2015 : Debug: (9) linelog: EXPAND messages.%{%{reply:Packet-Type}:-default} Tue Jul 7 11:34:15 2015 : Debug: (9) linelog: --> messages.Access-Reject Tue Jul 7 11:34:15 2015 : Debug: /usr/local/var/log/radius/log/linelog-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: literal --> /usr/local/var/log/radius/log/linelog- Tue Jul 7 11:34:15 2015 : Debug: percent --> Y Tue Jul 7 11:34:15 2015 : Debug: percent --> m Tue Jul 7 11:34:15 2015 : Debug: percent --> d Tue Jul 7 11:34:15 2015 : Debug: (9) linelog: EXPAND /usr/local/var/log/radius/log/linelog-%Y%m%d Tue Jul 7 11:34:15 2015 : Debug: (9) linelog: --> /usr/local/var/log/radius/log/linelog-20150707 Tue Jul 7 11:34:15 2015 : Debug: %S,%{reply:Packet-Type},%{Packet-Src-IP-Address},%{NAS-IP-Address},%{User-Name},%{Calling-Station-Id},%{%{Aruba-Essid-Name}:-%{Called-Station-Id}},%{reply:Reply-Message},%{%{reply:Module-Failure-Message}:-%{Module-Failure-Message}} Tue Jul 7 11:34:15 2015 : Debug: Parsed xlat tree: Tue Jul 7 11:34:15 2015 : Debug: percent --> S Tue Jul 7 11:34:15 2015 : Debug: literal --> , Tue Jul 7 11:34:15 2015 : Debug: attribute --> Packet-Type Tue Jul 7 11:34:15 2015 : Debug: literal --> , Tue Jul 7 11:34:15 2015 : Debug: attribute --> Packet-Src-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> , Tue Jul 7 11:34:15 2015 : Debug: attribute --> NAS-IP-Address Tue Jul 7 11:34:15 2015 : Debug: literal --> , Tue Jul 7 11:34:15 2015 : Debug: attribute --> User-Name Tue Jul 7 11:34:15 2015 : Debug: literal --> , Tue Jul 7 11:34:15 2015 : Debug: attribute --> Calling-Station-Id Tue Jul 7 11:34:15 2015 : Debug: literal --> , Tue Jul 7 11:34:15 2015 : Debug: if { Tue Jul 7 11:34:15 2015 : Debug: attribute --> Aruba-Essid-Name Tue Jul 7 11:34:15 2015 : Debug: } Tue Jul 7 11:34:15 2015 : Debug: else { Tue Jul 7 11:34:15 2015 : Debug: attribute --> Called-Station-Id Tue Jul 7 11:34:15 2015 : Debug: } Tue Jul 7 11:34:15 2015 : Debug: literal --> , Tue Jul 7 11:34:15 2015 : Debug: attribute --> Reply-Message Tue Jul 7 11:34:15 2015 : Debug: literal --> , Tue Jul 7 11:34:15 2015 : Debug: if { Tue Jul 7 11:34:15 2015 : Debug: attribute --> Module-Failure-Message Tue Jul 7 11:34:15 2015 : Debug: } Tue Jul 7 11:34:15 2015 : Debug: else { Tue Jul 7 11:34:15 2015 : Debug: attribute --> Module-Failure-Message Tue Jul 7 11:34:15 2015 : Debug: } Tue Jul 7 11:34:15 2015 : Debug: (9) linelog: EXPAND %S,%{reply:Packet-Type},%{Packet-Src-IP-Address},%{NAS-IP-Address},%{User-Name},%{Calling-Station-Id},%{%{Aruba-Essid-Name}:-%{Called-Station-Id}},%{reply:Reply-Message},%{%{reply:Module-Failure-Message}:-%{Module-Failure-Message}} Tue Jul 7 11:34:15 2015 : Debug: (9) linelog: --> 2015-07-07 11:34:15,Access-Reject,10.57.123.29,,mytest,,,, Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[post-auth]: returned from linelog (rlm_linelog) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [linelog] = ok Tue Jul 7 11:34:15 2015 : Debug: (9) } # Post-Auth-Type REJECT = updated Tue Jul 7 11:34:15 2015 : Debug: (9) } # server inner-tunnel Tue Jul 7 11:34:15 2015 : Debug: (9) Virtual server sending reply Tue Jul 7 11:34:15 2015 : Debug: (9) EAP-Message = 0x040a0004 Tue Jul 7 11:34:15 2015 : Debug: (9) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: Got tunneled reply code 3 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: EAP-Message = 0x040a0004 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: Got tunneled reply RADIUS code 3 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: EAP-Message = 0x040a0004 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: Tunneled authentication was rejected Tue Jul 7 11:34:15 2015 : Debug: (9) eap_peap: FAILURE Tue Jul 7 11:34:15 2015 : Debug: (9) eap: EAP session adding &reply:State = 0xd753eb2fde58f204 Tue Jul 7 11:34:15 2015 : Debug: (9) modsingle[authenticate]: returned from eap (rlm_eap) for request 9 Tue Jul 7 11:34:15 2015 : Debug: (9) [eap] = handled Tue Jul 7 11:34:15 2015 : Debug: (9) } # authenticate = handled Tue Jul 7 11:34:15 2015 : Debug: (9) Using Post-Auth-Type Challenge Tue Jul 7 11:34:15 2015 : Debug: (9) Post-Auth-Type sub-section not found. Ignoring. Tue Jul 7 11:34:15 2015 : Debug: (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 7 11:34:15 2015 : Debug: (9) session-state: Nothing to cache Tue Jul 7 11:34:15 2015 : Debug: (9) Sent Access-Challenge Id 116 from 10.57.235.64:1812 to 10.57.123.29:3629 length 0 Tue Jul 7 11:34:15 2015 : Debug: (9) EAP-Message = 0x010b002b190017030100201ba9bb14e6e94de92125e71af3ce9aeb9f6b61e5fcb013aeb7e615673e5c9fc6 Tue Jul 7 11:34:15 2015 : Debug: (9) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 7 11:34:15 2015 : Debug: (9) State = 0xd753eb2fde58f204b25a39cc0fba25e4 Tue Jul 7 11:34:15 2015 : Debug: (9) Finished request