v3.0.8: Failure message does not appear in radius.log
Hi, I am using v3.0.8 for EAP-PEAP-MSCHAPv2 authentication. Login with correct username/password is fine. But for login with incorrect username or password, the failure message "mschap: ERROR: MS-CHAP2-Response is incorrect" does not appear in the final radius.log. I only get this: Login incorrect: [mytest] while I was expecting this: Login incorrect (mschap: MS-CHAP2-Response is incorrect): [mytest] Module-Failure-Message is empty too when I try to do linelog in Post-Auth-Reject. What have I missed in the configration? Debug log follows. I can upload inner-tunnel config. if required. Thanks in advance. Fu (0) Received Access-Request Id 36 from 10.210.123.29:3629 to 10.210.235.64:1812 length 208 (0) User-Name = 'mytest' (0) Framed-MTU = 1450 (0) EAP-Message = 0x0201000b016d7974657374 (0) Message-Authenticator = 0x5ef5fbebae79922073ab55353f8aaa59 (0) Chargeable-User-Identity = 0x00 (0) NAS-IP-Address = 10.210.123.29 (0) NAS-Identifier = 'ITS-TEST' (0) NAS-Port = 33779942 (0) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=2250' (0) NAS-Port-Type = Wireless-802.11 (0) Service-Type = Framed-User (0) Framed-Protocol = PPP (0) Calling-Station-Id = '10-1C-0C-79-26-49' (0) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (0) Acct-Session-Id = '11505301634460' (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (0) authorize { (0) policy filter_username { (0) if (&User-Name =~ / /) { (0) if (&User-Name =~ / /) -> FALSE (0) if (&User-Name =~ /@.*@/ ) { (0) if (&User-Name =~ /@.*@/ ) -> FALSE (0) if (&User-Name =~ /\\.\\./ ) { (0) if (&User-Name =~ /\\.\\./ ) -> FALSE (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (0) if (&User-Name =~ /\\.$/) { (0) if (&User-Name =~ /\\.$/) -> FALSE (0) if (&User-Name =~ /@\\./) { (0) if (&User-Name =~ /@\\./) -> FALSE (0) } # policy filter_username = notfound (0) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (0) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (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.210.123.29/auth-20150630 (0) auth_log: EXPAND %t (0) auth_log: --> Tue Jun 30 16:38:41 2015 (0) [auth_log] = ok (0) [mschap] = noop (0) suffix: Checking for suffix after "@" (0) suffix: No '@' in User-Name = "mytest", looking up realm NULL (0) suffix: Found realm "NULL" (0) suffix: Adding Stripped-User-Name = "mytest" (0) suffix: Adding Realm = "NULL" (0) suffix: Authentication realm is LOCAL (0) [suffix] = ok (0) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (0) EXPAND %{Aruba-Essid-Name} (0) --> (0) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (0) eap: Peer sent code Response (2) ID 1 length 11 (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (0) [eap] = ok (0) } # authorize = ok (0) Found Auth-Type = EAP (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) authenticate { (0) eap: Peer sent method Identity (1) (0) eap: Calling eap_peap to process EAP data (0) eap_peap: Flushing SSL sessions (of #0) (0) eap_peap: Initiate (0) eap_peap: Start returned 1 (0) eap: EAP session adding &reply:State = 0xb8002a16b8023321 (0) [eap] = handled (0) } # authenticate = handled (0) Using Post-Auth-Type Challenge (0) Post-Auth-Type sub-section not found. Ignoring. (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) Sent Access-Challenge Id 36 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (0) EAP-Message = 0x010200061920 (0) Message-Authenticator = 0x00000000000000000000000000000000 (0) State = 0xb8002a16b802332133d295a612409a37 (0) Finished request Waking up in 4.9 seconds. (1) Received Access-Request Id 37 from 10.210.123.29:3629 to 10.210.235.64:1812 length 367 (1) User-Name = 'mytest' (1) Framed-MTU = 1450 (1) EAP-Message = 0x0202009819800000008e1603010089010000850301559255b2a9f020b42bfb6e9e57951f914de87bceaf3b356c31516db4eadf4c6200004a00ffc024c023c00ac009c008c028c027c014c013c012c026c025c005c004c003c02ac029c00fc00ec00d006b0067003900330016003d003c0035002f000ac0 (1) Message-Authenticator = 0x42a035744890fef59847539df9854c9f (1) Chargeable-User-Identity = 0x00 (1) NAS-IP-Address = 10.210.123.29 (1) NAS-Identifier = 'ITS-TEST' (1) NAS-Port = 33779942 (1) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=2250' (1) NAS-Port-Type = Wireless-802.11 (1) Service-Type = Framed-User (1) Framed-Protocol = PPP (1) Calling-Station-Id = '10-1C-0C-79-26-49' (1) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (1) Acct-Session-Id = '11505301634460' (1) State = 0xb8002a16b802332133d295a612409a37 (1) session-state: No cached attributes (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (1) authorize { (1) policy filter_username { (1) if (&User-Name =~ / /) { (1) if (&User-Name =~ / /) -> FALSE (1) if (&User-Name =~ /@.*@/ ) { (1) if (&User-Name =~ /@.*@/ ) -> FALSE (1) if (&User-Name =~ /\\.\\./ ) { (1) if (&User-Name =~ /\\.\\./ ) -> FALSE (1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (1) if (&User-Name =~ /\\.$/) { (1) if (&User-Name =~ /\\.$/) -> FALSE (1) if (&User-Name =~ /@\\./) { (1) if (&User-Name =~ /@\\./) -> FALSE (1) } # policy filter_username = notfound (1) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (1) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (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.210.123.29/auth-20150630 (1) auth_log: EXPAND %t (1) auth_log: --> Tue Jun 30 16:38:41 2015 (1) [auth_log] = ok (1) [mschap] = noop (1) suffix: Checking for suffix after "@" (1) suffix: No '@' in User-Name = "mytest", looking up realm NULL (1) suffix: Found realm "NULL" (1) suffix: Adding Stripped-User-Name = "mytest" (1) suffix: Adding Realm = "NULL" (1) suffix: Authentication realm is LOCAL (1) [suffix] = ok (1) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (1) EXPAND %{Aruba-Essid-Name} (1) --> (1) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (1) eap: Peer sent code Response (2) ID 2 length 152 (1) eap: Continuing tunnel setup (1) [eap] = ok (1) } # authorize = ok (1) Found Auth-Type = EAP (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (1) authenticate { (1) eap: Expiring EAP session with state 0xb8002a16b8023321 (1) eap: Finished EAP session with state 0xb8002a16b8023321 (1) eap: Previous EAP request found for state 0xb8002a16b8023321, released from the list (1) eap: Peer sent method PEAP (25) (1) eap: EAP PEAP (25) (1) eap: Calling eap_peap to process EAP data (1) eap_peap: processing EAP-TLS (1) eap_peap: TLS Length 142 (1) eap_peap: Length Included (1) eap_peap: eaptls_verify returned 11 (1) eap_peap: (other): before/accept initialization (1) eap_peap: TLS_accept: before/accept initialization (1) eap_peap: <<< TLS 1.0 Handshake [length 0089], ClientHello (1) eap_peap: TLS_accept: SSLv3 read client hello A (1) eap_peap: >>> TLS 1.0 Handshake [length 0059], ServerHello (1) eap_peap: TLS_accept: SSLv3 write server hello A (1) eap_peap: >>> TLS 1.0 Handshake [length 0cb2], Certificate (1) eap_peap: TLS_accept: SSLv3 write certificate A (1) eap_peap: >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange (1) eap_peap: TLS_accept: SSLv3 write key exchange A (1) eap_peap: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone (1) eap_peap: TLS_accept: SSLv3 write server done A (1) eap_peap: TLS_accept: SSLv3 flush data (1) eap_peap: TLS_accept: Need to read more data: SSLv3 read client certificate A (1) eap_peap: TLS_accept: Need to read more data: SSLv3 read client certificate A In SSL Handshake Phase In SSL Accept mode (1) eap_peap: eaptls_process returned 13 (1) eap_peap: FR_TLS_HANDLED (1) eap: EAP session adding &reply:State = 0xb8002a16b9033321 (1) [eap] = handled (1) } # authenticate = handled (1) Using Post-Auth-Type Challenge (1) Post-Auth-Type sub-section not found. Ignoring. (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (1) Sent Access-Challenge Id 37 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (1) EAP-Message = 0x010303ec19c000000e6e160301005902000055030155925591c68e2c1bcc1799abb16c902a30a09565eff0e27d68ab22a7e10b0fde20ebdaba7f9ed922848678bdc00894241de12ab724eb6c292dc8076e90cbe463e7c01400000dff01000100000b0004030001021603010cb20b000cae000cab00054c (1) Message-Authenticator = 0x00000000000000000000000000000000 (1) State = 0xb8002a16b903332133d295a612409a37 (1) Finished request Waking up in 4.9 seconds. (2) Received Access-Request Id 38 from 10.210.123.29:3629 to 10.210.235.64:1812 length 221 (2) User-Name = 'mytest' (2) Framed-MTU = 1450 (2) EAP-Message = 0x020300061900 (2) Message-Authenticator = 0x8ae28f5ddd086665c5f0f0cf4328e5b3 (2) Chargeable-User-Identity = 0x00 (2) NAS-IP-Address = 10.210.123.29 (2) NAS-Identifier = 'ITS-TEST' (2) NAS-Port = 33779942 (2) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (2) NAS-Port-Type = Wireless-802.11 (2) Service-Type = Framed-User (2) Framed-Protocol = PPP (2) Calling-Station-Id = '10-1C-0C-79-26-49' (2) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (2) Acct-Session-Id = '11505301634460' (2) State = 0xb8002a16b903332133d295a612409a37 (2) session-state: No cached attributes (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (2) authorize { (2) policy filter_username { (2) if (&User-Name =~ / /) { (2) if (&User-Name =~ / /) -> FALSE (2) if (&User-Name =~ /@.*@/ ) { (2) if (&User-Name =~ /@.*@/ ) -> FALSE (2) if (&User-Name =~ /\\.\\./ ) { (2) if (&User-Name =~ /\\.\\./ ) -> FALSE (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (2) if (&User-Name =~ /\\.$/) { (2) if (&User-Name =~ /\\.$/) -> FALSE (2) if (&User-Name =~ /@\\./) { (2) if (&User-Name =~ /@\\./) -> FALSE (2) } # policy filter_username = notfound (2) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (2) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (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.210.123.29/auth-20150630 (2) auth_log: EXPAND %t (2) auth_log: --> Tue Jun 30 16:38:41 2015 (2) [auth_log] = ok (2) [mschap] = noop (2) suffix: Checking for suffix after "@" (2) suffix: No '@' in User-Name = "mytest", looking up realm NULL (2) suffix: Found realm "NULL" (2) suffix: Adding Stripped-User-Name = "mytest" (2) suffix: Adding Realm = "NULL" (2) suffix: Authentication realm is LOCAL (2) [suffix] = ok (2) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (2) EXPAND %{Aruba-Essid-Name} (2) --> (2) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (2) eap: Peer sent code Response (2) ID 3 length 6 (2) eap: Continuing tunnel setup (2) [eap] = ok (2) } # authorize = ok (2) Found Auth-Type = EAP (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (2) authenticate { (2) eap: Expiring EAP session with state 0xb8002a16b9033321 (2) eap: Finished EAP session with state 0xb8002a16b9033321 (2) eap: Previous EAP request found for state 0xb8002a16b9033321, released from the list (2) eap: Peer sent method PEAP (25) (2) eap: EAP PEAP (25) (2) eap: Calling eap_peap to process EAP data (2) eap_peap: processing EAP-TLS (2) eap_peap: Received TLS ACK (2) eap_peap: Received TLS ACK (2) eap_peap: ACK handshake fragment handler (2) eap_peap: eaptls_verify returned 1 (2) eap_peap: eaptls_process returned 13 (2) eap_peap: FR_TLS_HANDLED (2) eap: EAP session adding &reply:State = 0xb8002a16ba043321 (2) [eap] = handled (2) } # authenticate = handled (2) Using Post-Auth-Type Challenge (2) Post-Auth-Type sub-section not found. Ignoring. (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (2) Sent Access-Challenge Id 38 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (2) EAP-Message = 0x010403e8194006082b0601050507010104693067302c06082b060105050730018620687474703a2f2f677473736c64762d6f6373702e67656f74727573742e636f6d303706082b06010505073002862b687474703a2f2f677473736c64762d6169612e67656f74727573742e636f6d2f677473736c6476 (2) Message-Authenticator = 0x00000000000000000000000000000000 (2) State = 0xb8002a16ba04332133d295a612409a37 (2) Finished request Waking up in 4.9 seconds. (3) Received Access-Request Id 39 from 10.210.123.29:3629 to 10.210.235.64:1812 length 221 (3) User-Name = 'mytest' (3) Framed-MTU = 1450 (3) EAP-Message = 0x020400061900 (3) Message-Authenticator = 0x08de5c8d37eff88ee339c2447c43e240 (3) Chargeable-User-Identity = 0x00 (3) NAS-IP-Address = 10.210.123.29 (3) NAS-Identifier = 'ITS-TEST' (3) NAS-Port = 33779942 (3) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=2250' (3) NAS-Port-Type = Wireless-802.11 (3) Service-Type = Framed-User (3) Framed-Protocol = PPP (3) Calling-Station-Id = '10-1C-0C-79-26-49' (3) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (3) Acct-Session-Id = '11505301634460' (3) State = 0xb8002a16ba04332133d295a612409a37 (3) session-state: No cached attributes (3) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (3) authorize { (3) policy filter_username { (3) if (&User-Name =~ / /) { (3) if (&User-Name =~ / /) -> FALSE (3) if (&User-Name =~ /@.*@/ ) { (3) if (&User-Name =~ /@.*@/ ) -> FALSE (3) if (&User-Name =~ /\\.\\./ ) { (3) if (&User-Name =~ /\\.\\./ ) -> FALSE (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (3) if (&User-Name =~ /\\.$/) { (3) if (&User-Name =~ /\\.$/) -> FALSE (3) if (&User-Name =~ /@\\./) { (3) if (&User-Name =~ /@\\./) -> FALSE (3) } # policy filter_username = notfound (3) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (3) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (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.210.123.29/auth-20150630 (3) auth_log: EXPAND %t (3) auth_log: --> Tue Jun 30 16:38:41 2015 (3) [auth_log] = ok (3) [mschap] = noop (3) suffix: Checking for suffix after "@" (3) suffix: No '@' in User-Name = "mytest", looking up realm NULL (3) suffix: Found realm "NULL" (3) suffix: Adding Stripped-User-Name = "mytest" (3) suffix: Adding Realm = "NULL" (3) suffix: Authentication realm is LOCAL (3) [suffix] = ok (3) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (3) EXPAND %{Aruba-Essid-Name} (3) --> (3) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (3) eap: Peer sent code Response (2) ID 4 length 6 (3) eap: Continuing tunnel setup (3) [eap] = ok (3) } # authorize = ok (3) Found Auth-Type = EAP (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (3) authenticate { (3) eap: Expiring EAP session with state 0xb8002a16ba043321 (3) eap: Finished EAP session with state 0xb8002a16ba043321 (3) eap: Previous EAP request found for state 0xb8002a16ba043321, released from the list (3) eap: Peer sent method PEAP (25) (3) eap: EAP PEAP (25) (3) eap: Calling eap_peap to process EAP data (3) eap_peap: processing EAP-TLS (3) eap_peap: Received TLS ACK (3) eap_peap: Received TLS ACK (3) eap_peap: ACK handshake fragment handler (3) eap_peap: eaptls_verify returned 1 (3) eap_peap: eaptls_process returned 13 (3) eap_peap: FR_TLS_HANDLED (3) eap: EAP session adding &reply:State = 0xb8002a16bb053321 (3) [eap] = handled (3) } # authenticate = handled (3) Using Post-Auth-Type Challenge (3) Post-Auth-Type sub-section not found. Ignoring. (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (3) Sent Access-Challenge Id 39 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (3) EAP-Message = 0x010503e81940150203010001a381d93081d6300e0603551d0f0101ff040403020106301d0603551d0e041604148cf4d9930a47bc00a04ace4b756ea0b6b0b27efc301f0603551d23041830168014c07a98688d89fbab05640c117daa7d65b8cacc4e30120603551d130101ff040830060101ff02010030 (3) Message-Authenticator = 0x00000000000000000000000000000000 (3) State = 0xb8002a16bb05332133d295a612409a37 (3) Finished request Waking up in 4.9 seconds. (4) Received Access-Request Id 40 from 10.210.123.29:3629 to 10.210.235.64:1812 length 221 (4) User-Name = 'mytest' (4) Framed-MTU = 1450 (4) EAP-Message = 0x020500061900 (4) Message-Authenticator = 0xda837ef88f7b38871aaead005e3a54b0 (4) Chargeable-User-Identity = 0x00 (4) NAS-IP-Address = 10.210.123.29 (4) NAS-Identifier = 'ITS-TEST' (4) NAS-Port = 33779942 (4) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (4) NAS-Port-Type = Wireless-802.11 (4) Service-Type = Framed-User (4) Framed-Protocol = PPP (4) Calling-Station-Id = '10-1C-0C-79-26-49' (4) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (4) Acct-Session-Id = '11505301634460' (4) State = 0xb8002a16bb05332133d295a612409a37 (4) session-state: No cached attributes (4) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (4) authorize { (4) policy filter_username { (4) if (&User-Name =~ / /) { (4) if (&User-Name =~ / /) -> FALSE (4) if (&User-Name =~ /@.*@/ ) { (4) if (&User-Name =~ /@.*@/ ) -> FALSE (4) if (&User-Name =~ /\\.\\./ ) { (4) if (&User-Name =~ /\\.\\./ ) -> FALSE (4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (4) if (&User-Name =~ /\\.$/) { (4) if (&User-Name =~ /\\.$/) -> FALSE (4) if (&User-Name =~ /@\\./) { (4) if (&User-Name =~ /@\\./) -> FALSE (4) } # policy filter_username = notfound (4) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (4) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (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.210.123.29/auth-20150630 (4) auth_log: EXPAND %t (4) auth_log: --> Tue Jun 30 16:38:41 2015 (4) [auth_log] = ok (4) [mschap] = noop (4) suffix: Checking for suffix after "@" (4) suffix: No '@' in User-Name = "mytest", looking up realm NULL (4) suffix: Found realm "NULL" (4) suffix: Adding Stripped-User-Name = "mytest" (4) suffix: Adding Realm = "NULL" (4) suffix: Authentication realm is LOCAL (4) [suffix] = ok (4) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (4) EXPAND %{Aruba-Essid-Name} (4) --> (4) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (4) eap: Peer sent code Response (2) ID 5 length 6 (4) eap: Continuing tunnel setup (4) [eap] = ok (4) } # authorize = ok (4) Found Auth-Type = EAP (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (4) authenticate { (4) eap: Expiring EAP session with state 0xb8002a16bb053321 (4) eap: Finished EAP session with state 0xb8002a16bb053321 (4) eap: Previous EAP request found for state 0xb8002a16bb053321, released from the list (4) eap: Peer sent method PEAP (25) (4) eap: EAP PEAP (25) (4) eap: Calling eap_peap to process EAP data (4) eap_peap: processing EAP-TLS (4) eap_peap: Received TLS ACK (4) eap_peap: Received TLS ACK (4) eap_peap: ACK handshake fragment handler (4) eap_peap: eaptls_verify returned 1 (4) eap_peap: eaptls_process returned 13 (4) eap_peap: FR_TLS_HANDLED (4) eap: EAP session adding &reply:State = 0xb8002a16bc063321 (4) [eap] = handled (4) } # authenticate = handled (4) Using Post-Auth-Type Challenge (4) Post-Auth-Type sub-section not found. Ignoring. (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (4) Sent Access-Challenge Id 40 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (4) EAP-Message = 0x010602ce1900f90203010001a3533051300f0603551d130101ff040530030101ff301d0603551d0e04160414c07a98688d89fbab05640c117daa7d65b8cacc4e301f0603551d23041830168014c07a98688d89fbab05640c117daa7d65b8cacc4e300d06092a864886f70d0101050500038201010035e3 (4) Message-Authenticator = 0x00000000000000000000000000000000 (4) State = 0xb8002a16bc06332133d295a612409a37 (4) Finished request Waking up in 4.9 seconds. (5) Received Access-Request Id 41 from 10.210.123.29:3629 to 10.210.235.64:1812 length 359 (5) User-Name = 'mytest' (5) Framed-MTU = 1450 (5) EAP-Message = 0x020600901980000000861603010046100000424104daab08aafa18f5c2c9eb22fc1604897509e5a299ef0ebe092b4a69330d014b443560a4ceea8642f5be01212032dc50db73a8f82362675d08f5ea12ac7ac7b60b14030100010116030100307ffbf690c0dac1e79a7f7d24c5477d4a12aa6d0e99221a (5) Message-Authenticator = 0x1d2150a6f034a5dc3b195884d34e474d (5) Chargeable-User-Identity = 0x00 (5) NAS-IP-Address = 10.210.123.29 (5) NAS-Identifier = 'ITS-TEST' (5) NAS-Port = 33779942 (5) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (5) NAS-Port-Type = Wireless-802.11 (5) Service-Type = Framed-User (5) Framed-Protocol = PPP (5) Calling-Station-Id = '10-1C-0C-79-26-49' (5) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (5) Acct-Session-Id = '11505301634460' (5) State = 0xb8002a16bc06332133d295a612409a37 (5) session-state: No cached attributes (5) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (5) authorize { (5) policy filter_username { (5) if (&User-Name =~ / /) { (5) if (&User-Name =~ / /) -> FALSE (5) if (&User-Name =~ /@.*@/ ) { (5) if (&User-Name =~ /@.*@/ ) -> FALSE (5) if (&User-Name =~ /\\.\\./ ) { (5) if (&User-Name =~ /\\.\\./ ) -> FALSE (5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (5) if (&User-Name =~ /\\.$/) { (5) if (&User-Name =~ /\\.$/) -> FALSE (5) if (&User-Name =~ /@\\./) { (5) if (&User-Name =~ /@\\./) -> FALSE (5) } # policy filter_username = notfound (5) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (5) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (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.210.123.29/auth-20150630 (5) auth_log: EXPAND %t (5) auth_log: --> Tue Jun 30 16:38:41 2015 (5) [auth_log] = ok (5) [mschap] = noop (5) suffix: Checking for suffix after "@" (5) suffix: No '@' in User-Name = "mytest", looking up realm NULL (5) suffix: Found realm "NULL" (5) suffix: Adding Stripped-User-Name = "mytest" (5) suffix: Adding Realm = "NULL" (5) suffix: Authentication realm is LOCAL (5) [suffix] = ok (5) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (5) EXPAND %{Aruba-Essid-Name} (5) --> (5) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (5) eap: Peer sent code Response (2) ID 6 length 144 (5) eap: Continuing tunnel setup (5) [eap] = ok (5) } # authorize = ok (5) Found Auth-Type = EAP (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (5) authenticate { (5) eap: Expiring EAP session with state 0xb8002a16bc063321 (5) eap: Finished EAP session with state 0xb8002a16bc063321 (5) eap: Previous EAP request found for state 0xb8002a16bc063321, released from the list (5) eap: Peer sent method PEAP (25) (5) eap: EAP PEAP (25) (5) eap: Calling eap_peap to process EAP data (5) eap_peap: processing EAP-TLS (5) eap_peap: TLS Length 134 (5) eap_peap: Length Included (5) eap_peap: eaptls_verify returned 11 (5) eap_peap: <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange (5) eap_peap: TLS_accept: SSLv3 read client key exchange A (5) eap_peap: <<< TLS 1.0 ChangeCipherSpec [length 0001] (5) eap_peap: <<< TLS 1.0 Handshake [length 0010], Finished (5) eap_peap: TLS_accept: SSLv3 read finished A (5) eap_peap: >>> TLS 1.0 ChangeCipherSpec [length 0001] (5) eap_peap: TLS_accept: SSLv3 write change cipher spec A (5) eap_peap: >>> TLS 1.0 Handshake [length 0010], Finished (5) eap_peap: TLS_accept: SSLv3 write finished A (5) eap_peap: TLS_accept: SSLv3 flush data TLS: adding session ebdaba7f9ed922848678bdc00894241de12ab724eb6c292dc8076e90cbe463e7 to cache (5) eap_peap: (other): SSL negotiation finished successfully SSL Connection Established (5) eap_peap: eaptls_process returned 13 (5) eap_peap: FR_TLS_HANDLED (5) eap: EAP session adding &reply:State = 0xb8002a16bd073321 (5) [eap] = handled (5) } # authenticate = handled (5) Using Post-Auth-Type Challenge (5) Post-Auth-Type sub-section not found. Ignoring. (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (5) Sent Access-Challenge Id 41 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (5) EAP-Message = 0x0107004119001403010001011603010030cf354b5e12d99508901f44db8ea05526d42a5f671f1ceb081722b1fec033c99b05ebe23bde2c546223aebc064a1e4eea (5) Message-Authenticator = 0x00000000000000000000000000000000 (5) State = 0xb8002a16bd07332133d295a612409a37 (5) Finished request Waking up in 4.8 seconds. (6) Received Access-Request Id 42 from 10.210.123.29:3629 to 10.210.235.64:1812 length 221 (6) User-Name = 'mytest' (6) Framed-MTU = 1450 (6) EAP-Message = 0x020700061900 (6) Message-Authenticator = 0x03b7e4a2a231036e9283d475a4caa3ec (6) Chargeable-User-Identity = 0x00 (6) NAS-IP-Address = 10.210.123.29 (6) NAS-Identifier = 'ITS-TEST' (6) NAS-Port = 33779942 (6) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (6) NAS-Port-Type = Wireless-802.11 (6) Service-Type = Framed-User (6) Framed-Protocol = PPP (6) Calling-Station-Id = '10-1C-0C-79-26-49' (6) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (6) Acct-Session-Id = '11505301634460' (6) State = 0xb8002a16bd07332133d295a612409a37 (6) session-state: No cached attributes (6) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (6) authorize { (6) policy filter_username { (6) if (&User-Name =~ / /) { (6) if (&User-Name =~ / /) -> FALSE (6) if (&User-Name =~ /@.*@/ ) { (6) if (&User-Name =~ /@.*@/ ) -> FALSE (6) if (&User-Name =~ /\\.\\./ ) { (6) if (&User-Name =~ /\\.\\./ ) -> FALSE (6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (6) if (&User-Name =~ /\\.$/) { (6) if (&User-Name =~ /\\.$/) -> FALSE (6) if (&User-Name =~ /@\\./) { (6) if (&User-Name =~ /@\\./) -> FALSE (6) } # policy filter_username = notfound (6) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (6) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (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.210.123.29/auth-20150630 (6) auth_log: EXPAND %t (6) auth_log: --> Tue Jun 30 16:38:41 2015 (6) [auth_log] = ok (6) [mschap] = noop (6) suffix: Checking for suffix after "@" (6) suffix: No '@' in User-Name = "mytest", looking up realm NULL (6) suffix: Found realm "NULL" (6) suffix: Adding Stripped-User-Name = "mytest" (6) suffix: Adding Realm = "NULL" (6) suffix: Authentication realm is LOCAL (6) [suffix] = ok (6) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (6) EXPAND %{Aruba-Essid-Name} (6) --> (6) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (6) eap: Peer sent code Response (2) ID 7 length 6 (6) eap: Continuing tunnel setup (6) [eap] = ok (6) } # authorize = ok (6) Found Auth-Type = EAP (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (6) authenticate { (6) eap: Expiring EAP session with state 0xb8002a16bd073321 (6) eap: Finished EAP session with state 0xb8002a16bd073321 (6) eap: Previous EAP request found for state 0xb8002a16bd073321, released from the list (6) eap: Peer sent method PEAP (25) (6) eap: EAP PEAP (25) (6) eap: Calling eap_peap to process EAP data (6) eap_peap: processing EAP-TLS (6) eap_peap: Received TLS ACK (6) eap_peap: Received TLS ACK (6) eap_peap: ACK handshake is finished (6) eap_peap: eaptls_verify returned 3 (6) eap_peap: eaptls_process returned 3 (6) eap_peap: FR_TLS_SUCCESS (6) eap_peap: Session established. Decoding tunneled attributes (6) eap_peap: PEAP state TUNNEL ESTABLISHED (6) eap: EAP session adding &reply:State = 0xb8002a16be083321 (6) [eap] = handled (6) } # authenticate = handled (6) Using Post-Auth-Type Challenge (6) Post-Auth-Type sub-section not found. Ignoring. (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (6) Sent Access-Challenge Id 42 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (6) EAP-Message = 0x0108002b19001703010020d965153eadcdfd834b3415bebe178548d5f749ba6d9a4c4b316b4d771f57223b (6) Message-Authenticator = 0x00000000000000000000000000000000 (6) State = 0xb8002a16be08332133d295a612409a37 (6) Finished request Waking up in 4.8 seconds. (7) Received Access-Request Id 43 from 10.210.123.29:3629 to 10.210.235.64:1812 length 258 (7) User-Name = 'mytest' (7) Framed-MTU = 1450 (7) EAP-Message = 0x0208002b190017030100205ee29c7181f7daeab27186b96e313d25f613fbf75c9187c43dadb0eef059ef4c (7) Message-Authenticator = 0xcce60a3b273c10f259bd83bb13cb4939 (7) Chargeable-User-Identity = 0x00 (7) NAS-IP-Address = 10.210.123.29 (7) NAS-Identifier = 'ITS-TEST' (7) NAS-Port = 33779942 (7) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (7) NAS-Port-Type = Wireless-802.11 (7) Service-Type = Framed-User (7) Framed-Protocol = PPP (7) Calling-Station-Id = '10-1C-0C-79-26-49' (7) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (7) Acct-Session-Id = '11505301634460' (7) State = 0xb8002a16be08332133d295a612409a37 (7) session-state: No cached attributes (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (7) authorize { (7) policy filter_username { (7) if (&User-Name =~ / /) { (7) if (&User-Name =~ / /) -> FALSE (7) if (&User-Name =~ /@.*@/ ) { (7) if (&User-Name =~ /@.*@/ ) -> FALSE (7) if (&User-Name =~ /\\.\\./ ) { (7) if (&User-Name =~ /\\.\\./ ) -> FALSE (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (7) if (&User-Name =~ /\\.$/) { (7) if (&User-Name =~ /\\.$/) -> FALSE (7) if (&User-Name =~ /@\\./) { (7) if (&User-Name =~ /@\\./) -> FALSE (7) } # policy filter_username = notfound (7) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (7) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (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.210.123.29/auth-20150630 (7) auth_log: EXPAND %t (7) auth_log: --> Tue Jun 30 16:38:41 2015 (7) [auth_log] = ok (7) [mschap] = noop (7) suffix: Checking for suffix after "@" (7) suffix: No '@' in User-Name = "mytest", looking up realm NULL (7) suffix: Found realm "NULL" (7) suffix: Adding Stripped-User-Name = "mytest" (7) suffix: Adding Realm = "NULL" (7) suffix: Authentication realm is LOCAL (7) [suffix] = ok (7) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (7) EXPAND %{Aruba-Essid-Name} (7) --> (7) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (7) eap: Peer sent code Response (2) ID 8 length 43 (7) eap: Continuing tunnel setup (7) [eap] = ok (7) } # authorize = ok (7) Found Auth-Type = EAP (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (7) authenticate { (7) eap: Expiring EAP session with state 0xb8002a16be083321 (7) eap: Finished EAP session with state 0xb8002a16be083321 (7) eap: Previous EAP request found for state 0xb8002a16be083321, released from the list (7) eap: Peer sent method PEAP (25) (7) eap: EAP PEAP (25) (7) eap: Calling eap_peap to process EAP data (7) eap_peap: processing EAP-TLS (7) eap_peap: eaptls_verify returned 7 (7) eap_peap: Done initial handshake (7) eap_peap: eaptls_process returned 7 (7) eap_peap: FR_TLS_OK (7) eap_peap: Session established. Decoding tunneled attributes (7) eap_peap: PEAP state WAITING FOR INNER IDENTITY (7) eap_peap: Identity - mytest (7) eap_peap: Got inner identity 'mytest' (7) eap_peap: Setting default EAP type for tunneled EAP session (7) eap_peap: Got tunneled request (7) eap_peap: EAP-Message = 0x0208000b016d7974657374 (7) eap_peap: Setting User-Name to mytest (7) eap_peap: Sending tunneled request to inner-tunnel (7) eap_peap: EAP-Message = 0x0208000b016d7974657374 (7) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (7) eap_peap: User-Name = 'mytest' (7) Virtual server inner-tunnel received request (7) EAP-Message = 0x0208000b016d7974657374 (7) FreeRADIUS-Proxied-To = 127.0.0.1 (7) User-Name = 'mytest' (7) server inner-tunnel { (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (7) authorize { (7) policy filter_username { (7) if (&User-Name =~ / /) { (7) if (&User-Name =~ / /) -> FALSE (7) if (&User-Name =~ /@.*@/ ) { (7) if (&User-Name =~ /@.*@/ ) -> FALSE (7) if (&User-Name =~ /\\.\\./ ) { (7) if (&User-Name =~ /\\.\\./ ) -> FALSE (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (7) if (&User-Name =~ /\\.$/) { (7) if (&User-Name =~ /\\.$/) -> FALSE (7) if (&User-Name =~ /@\\./) { (7) if (&User-Name =~ /@\\./) -> FALSE (7) } # policy filter_username = notfound (7) [mschap] = noop (7) suffix: Checking for suffix after "@" (7) suffix: No '@' in User-Name = "mytest", looking up realm NULL (7) suffix: Found realm "NULL" (7) suffix: Adding Stripped-User-Name = "mytest" (7) suffix: Adding Realm = "NULL" (7) suffix: Authentication realm is LOCAL (7) [suffix] = ok (7) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') { (7) EXPAND %{Realm} (7) --> NULL (7) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') -> FALSE (7) else { (7) update control { (7) &Proxy-To-Realm := LOCAL (7) } # update control = noop (7) } # else = noop (7) eap: Peer sent code Response (2) ID 8 length 11 (7) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (7) [eap] = ok (7) } # authorize = ok (7) Found Auth-Type = EAP (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (7) authenticate { (7) eap: Peer sent method Identity (1) (7) eap: Calling eap_mschapv2 to process EAP data (7) eap_mschapv2: Issuing Challenge (7) eap: EAP session adding &reply:State = 0xb62146a8b6285c8a (7) [eap] = handled (7) } # authenticate = handled (7) } # server inner-tunnel (7) Virtual server sending reply (7) EAP-Message = 0x0109002a1a0109002510d806e435541f76a81bf76d4ba07cfb3a667265657261646975732d332e302e38 (7) Message-Authenticator = 0x00000000000000000000000000000000 (7) State = 0xb62146a8b6285c8a3fe68614a37a338a (7) eap_peap: Got tunneled reply code 11 (7) eap_peap: EAP-Message = 0x0109002a1a0109002510d806e435541f76a81bf76d4ba07cfb3a667265657261646975732d332e302e38 (7) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (7) eap_peap: State = 0xb62146a8b6285c8a3fe68614a37a338a (7) eap_peap: Got tunneled reply RADIUS code 11 (7) eap_peap: EAP-Message = 0x0109002a1a0109002510d806e435541f76a81bf76d4ba07cfb3a667265657261646975732d332e302e38 (7) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (7) eap_peap: State = 0xb62146a8b6285c8a3fe68614a37a338a (7) eap_peap: Got tunneled Access-Challenge (7) eap: EAP session adding &reply:State = 0xb8002a16bf093321 (7) [eap] = handled (7) } # authenticate = handled (7) Using Post-Auth-Type Challenge (7) Post-Auth-Type sub-section not found. Ignoring. (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (7) Sent Access-Challenge Id 43 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (7) EAP-Message = 0x0109004b190017030100405c844afbd67aa1e344ecf9725c6d6e727a8cc5b3c340fc155069a4150c4b9739e7f54fd75c4ad8c7542786eedd338c3740cbc6b9da5b1e8278c5eb21f54e6c35 (7) Message-Authenticator = 0x00000000000000000000000000000000 (7) State = 0xb8002a16bf09332133d295a612409a37 (7) Finished request Waking up in 4.8 seconds. (8) Received Access-Request Id 44 from 10.210.123.29:3629 to 10.210.235.64:1812 length 322 (8) User-Name = 'mytest' (8) Framed-MTU = 1450 (8) EAP-Message = 0x0209006b19001703010060d0240973b1e837e4960a6ccac86a002917ab9cd054c3b22a82da98cad9e8e84c56c7cec93bb1499708cb05c6c914b86ea9522b58a4e5b33401505daa42c4b40e7350d563f2458393666b4c2cc9e17931d9a301545c74a28405ca6e5bafcd4653 (8) Message-Authenticator = 0x696f809746b8ab1507126d8351be5024 (8) Chargeable-User-Identity = 0x00 (8) NAS-IP-Address = 10.210.123.29 (8) NAS-Identifier = 'ITS-TEST' (8) NAS-Port = 33779942 (8) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=2250' (8) NAS-Port-Type = Wireless-802.11 (8) Service-Type = Framed-User (8) Framed-Protocol = PPP (8) Calling-Station-Id = '10-1C-0C-79-26-49' (8) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (8) Acct-Session-Id = '11505301634460' (8) State = 0xb8002a16bf09332133d295a612409a37 (8) session-state: No cached attributes (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (8) authorize { (8) policy filter_username { (8) if (&User-Name =~ / /) { (8) if (&User-Name =~ / /) -> FALSE (8) if (&User-Name =~ /@.*@/ ) { (8) if (&User-Name =~ /@.*@/ ) -> FALSE (8) if (&User-Name =~ /\\.\\./ ) { (8) if (&User-Name =~ /\\.\\./ ) -> FALSE (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (8) if (&User-Name =~ /\\.$/) { (8) if (&User-Name =~ /\\.$/) -> FALSE (8) if (&User-Name =~ /@\\./) { (8) if (&User-Name =~ /@\\./) -> FALSE (8) } # policy filter_username = notfound (8) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (8) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (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.210.123.29/auth-20150630 (8) auth_log: EXPAND %t (8) auth_log: --> Tue Jun 30 16:38:41 2015 (8) [auth_log] = ok (8) [mschap] = noop (8) suffix: Checking for suffix after "@" (8) suffix: No '@' in User-Name = "mytest", looking up realm NULL (8) suffix: Found realm "NULL" (8) suffix: Adding Stripped-User-Name = "mytest" (8) suffix: Adding Realm = "NULL" (8) suffix: Authentication realm is LOCAL (8) [suffix] = ok (8) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (8) EXPAND %{Aruba-Essid-Name} (8) --> (8) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (8) eap: Peer sent code Response (2) ID 9 length 107 (8) eap: Continuing tunnel setup (8) [eap] = ok (8) } # authorize = ok (8) Found Auth-Type = EAP (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (8) authenticate { (8) eap: Expiring EAP session with state 0xb62146a8b6285c8a (8) eap: Finished EAP session with state 0xb8002a16bf093321 (8) eap: Previous EAP request found for state 0xb8002a16bf093321, released from the list (8) eap: Peer sent method PEAP (25) (8) eap: EAP PEAP (25) (8) eap: Calling eap_peap to process EAP data (8) eap_peap: processing EAP-TLS (8) eap_peap: eaptls_verify returned 7 (8) eap_peap: Done initial handshake (8) eap_peap: eaptls_process returned 7 (8) eap_peap: FR_TLS_OK (8) eap_peap: Session established. Decoding tunneled attributes (8) eap_peap: PEAP state phase2 (8) eap_peap: EAP type MSCHAPv2 (26) (8) eap_peap: Got tunneled request (8) eap_peap: EAP-Message = 0x020900411a0209003c316a2051c2ef6b4f01437a8e0768e8ed840000000000000000c9939c062c9c25dc878baf49c1c1b486042217fc6242c109006d7974657374 (8) eap_peap: Setting User-Name to mytest (8) eap_peap: Sending tunneled request to inner-tunnel (8) eap_peap: EAP-Message = 0x020900411a0209003c316a2051c2ef6b4f01437a8e0768e8ed840000000000000000c9939c062c9c25dc878baf49c1c1b486042217fc6242c109006d7974657374 (8) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (8) eap_peap: User-Name = 'mytest' (8) eap_peap: State = 0xb62146a8b6285c8a3fe68614a37a338a (8) Virtual server inner-tunnel received request (8) EAP-Message = 0x020900411a0209003c316a2051c2ef6b4f01437a8e0768e8ed840000000000000000c9939c062c9c25dc878baf49c1c1b486042217fc6242c109006d7974657374 (8) FreeRADIUS-Proxied-To = 127.0.0.1 (8) User-Name = 'mytest' (8) State = 0xb62146a8b6285c8a3fe68614a37a338a (8) server inner-tunnel { (8) session-state: No cached attributes (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (8) authorize { (8) policy filter_username { (8) if (&User-Name =~ / /) { (8) if (&User-Name =~ / /) -> FALSE (8) if (&User-Name =~ /@.*@/ ) { (8) if (&User-Name =~ /@.*@/ ) -> FALSE (8) if (&User-Name =~ /\\.\\./ ) { (8) if (&User-Name =~ /\\.\\./ ) -> FALSE (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (8) if (&User-Name =~ /\\.$/) { (8) if (&User-Name =~ /\\.$/) -> FALSE (8) if (&User-Name =~ /@\\./) { (8) if (&User-Name =~ /@\\./) -> FALSE (8) } # policy filter_username = notfound (8) [mschap] = noop (8) suffix: Checking for suffix after "@" (8) suffix: No '@' in User-Name = "mytest", looking up realm NULL (8) suffix: Found realm "NULL" (8) suffix: Adding Stripped-User-Name = "mytest" (8) suffix: Adding Realm = "NULL" (8) suffix: Authentication realm is LOCAL (8) [suffix] = ok (8) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') { (8) EXPAND %{Realm} (8) --> NULL (8) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') -> FALSE (8) else { (8) update control { (8) &Proxy-To-Realm := LOCAL (8) } # update control = noop (8) } # else = noop (8) eap: Peer sent code Response (2) ID 9 length 65 (8) eap: No EAP Start, assuming it's an on-going EAP conversation (8) [eap] = updated (8) if (&EAP-Message) { (8) if (&EAP-Message) -> TRUE (8) if (&EAP-Message) { (8) redundant ldap_Portal_redundant { rlm_ldap (ldap_DB_1): Reserved connection (4) (8) ldap_DB_1: EXPAND (&(uid=%{%{Stripped-User-Name}:-%{User-Name}})) (8) ldap_DB_1: --> (&(uid=mytest)) (8) ldap_DB_1: Performing search in "ou=radius,o=test,c=hk" with filter "(&(uid=mytest))", scope "sub" (8) ldap_DB_1: Waiting for search result... (8) ldap_DB_1: Search returned no results rlm_ldap (ldap_DB_1): Released connection (4) rlm_ldap (ldap_DB_1): Closing connection (0), from 2 unused connections (8) [ldap_DB_1] = notfound (8) } # redundant ldap_Portal_redundant = notfound (8) } # if (&EAP-Message) = notfound (8) ... skipping else for request 8: Preceding "if" was taken (8) [expiration] = noop (8) [logintime] = noop (8) [pap] = noop (8) } # authorize = updated (8) Found Auth-Type = EAP (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (8) authenticate { (8) eap: Expiring EAP session with state 0xb62146a8b6285c8a (8) eap: Finished EAP session with state 0xb62146a8b6285c8a (8) eap: Previous EAP request found for state 0xb62146a8b6285c8a, released from the list (8) eap: Peer sent method MSCHAPv2 (26) (8) eap: EAP MSCHAPv2 (26) (8) eap: Calling eap_mschapv2 to process EAP data (8) eap_mschapv2: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (8) eap_mschapv2: Auth-Type MS-CHAP { (8) mschap: WARNING: No Cleartext-Password configured. Cannot create NT-Password (8) mschap: WARNING: No Cleartext-Password configured. Cannot create LM-Password (8) mschap: Creating challenge hash with username: mytest (8) mschap: Client is using MS-CHAPv2 (8) mschap: ERROR: FAILED: No NT/LM-Password. Cannot perform authentication (8) mschap: ERROR: MS-CHAP2-Response is incorrect (8) [mschap] = reject (8) } # Auth-Type MS-CHAP = reject (8) MSCHAP-Error: E=691 R=1 (8) Could not parse new challenge from MS-CHAP-Error: 2 (8) ERROR: MSCHAP Failure (8) eap: EAP session adding &reply:State = 0xb62146a8b72b5c8a (8) [eap] = handled (8) } # authenticate = handled (8) } # server inner-tunnel (8) Virtual server sending reply (8) EAP-Message = 0x010a00121a0409000d453d36393120523d31 (8) Message-Authenticator = 0x00000000000000000000000000000000 (8) State = 0xb62146a8b72b5c8a3fe68614a37a338a (8) eap_peap: Got tunneled reply code 11 (8) eap_peap: EAP-Message = 0x010a00121a0409000d453d36393120523d31 (8) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (8) eap_peap: State = 0xb62146a8b72b5c8a3fe68614a37a338a (8) eap_peap: Got tunneled reply RADIUS code 11 (8) eap_peap: EAP-Message = 0x010a00121a0409000d453d36393120523d31 (8) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (8) eap_peap: State = 0xb62146a8b72b5c8a3fe68614a37a338a (8) eap_peap: Got tunneled Access-Challenge (8) eap: EAP session adding &reply:State = 0xb8002a16b00a3321 (8) [eap] = handled (8) } # authenticate = handled (8) Using Post-Auth-Type Challenge (8) Post-Auth-Type sub-section not found. Ignoring. (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (8) Sent Access-Challenge Id 44 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (8) EAP-Message = 0x010a003b19001703010030df92ce1aac52b4b30ccdffebe206a0cec12b7a3d6c5372f4f5694631578719f749d5aba9df6c3ee020a59e55b53a1390 (8) Message-Authenticator = 0x00000000000000000000000000000000 (8) State = 0xb8002a16b00a332133d295a612409a37 (8) Finished request Waking up in 4.8 seconds. (9) Received Access-Request Id 45 from 10.210.123.29:3629 to 10.210.235.64:1812 length 258 (9) User-Name = 'mytest' (9) Framed-MTU = 1450 (9) EAP-Message = 0x020a002b190017030100209af5ad585c8b395c928213c3ee8b1504f55db4183f261d436e584d6c501d9a9b (9) Message-Authenticator = 0xcf11096137cdd8dbd7aec6683a15595f (9) Chargeable-User-Identity = 0x00 (9) NAS-IP-Address = 10.210.123.29 (9) NAS-Identifier = 'ITS-TEST' (9) NAS-Port = 33779942 (9) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (9) NAS-Port-Type = Wireless-802.11 (9) Service-Type = Framed-User (9) Framed-Protocol = PPP (9) Calling-Station-Id = '10-1C-0C-79-26-49' (9) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (9) Acct-Session-Id = '11505301634460' (9) State = 0xb8002a16b00a332133d295a612409a37 (9) session-state: No cached attributes (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (9) authorize { (9) policy filter_username { (9) if (&User-Name =~ / /) { (9) if (&User-Name =~ / /) -> FALSE (9) if (&User-Name =~ /@.*@/ ) { (9) if (&User-Name =~ /@.*@/ ) -> FALSE (9) if (&User-Name =~ /\\.\\./ ) { (9) if (&User-Name =~ /\\.\\./ ) -> FALSE (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (9) if (&User-Name =~ /\\.$/) { (9) if (&User-Name =~ /\\.$/) -> FALSE (9) if (&User-Name =~ /@\\./) { (9) if (&User-Name =~ /@\\./) -> FALSE (9) } # policy filter_username = notfound (9) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (9) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (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.210.123.29/auth-20150630 (9) auth_log: EXPAND %t (9) auth_log: --> Tue Jun 30 16:38:41 2015 (9) [auth_log] = ok (9) [mschap] = noop (9) suffix: Checking for suffix after "@" (9) suffix: No '@' in User-Name = "mytest", looking up realm NULL (9) suffix: Found realm "NULL" (9) suffix: Adding Stripped-User-Name = "mytest" (9) suffix: Adding Realm = "NULL" (9) suffix: Authentication realm is LOCAL (9) [suffix] = ok (9) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (9) EXPAND %{Aruba-Essid-Name} (9) --> (9) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (9) eap: Peer sent code Response (2) ID 10 length 43 (9) eap: Continuing tunnel setup (9) [eap] = ok (9) } # authorize = ok (9) Found Auth-Type = EAP (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (9) authenticate { (9) eap: Expiring EAP session with state 0xb62146a8b72b5c8a (9) eap: Finished EAP session with state 0xb8002a16b00a3321 (9) eap: Previous EAP request found for state 0xb8002a16b00a3321, released from the list (9) eap: Peer sent method PEAP (25) (9) eap: EAP PEAP (25) (9) eap: Calling eap_peap to process EAP data (9) eap_peap: processing EAP-TLS (9) eap_peap: eaptls_verify returned 7 (9) eap_peap: Done initial handshake (9) eap_peap: eaptls_process returned 7 (9) eap_peap: FR_TLS_OK (9) eap_peap: Session established. Decoding tunneled attributes (9) eap_peap: PEAP state phase2 (9) eap_peap: EAP type MSCHAPv2 (26) (9) eap_peap: Got tunneled request (9) eap_peap: EAP-Message = 0x020a00091a04090004 (9) eap_peap: Setting User-Name to mytest (9) eap_peap: Sending tunneled request to inner-tunnel (9) eap_peap: EAP-Message = 0x020a00091a04090004 (9) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (9) eap_peap: User-Name = 'mytest' (9) eap_peap: State = 0xb62146a8b72b5c8a3fe68614a37a338a (9) Virtual server inner-tunnel received request (9) EAP-Message = 0x020a00091a04090004 (9) FreeRADIUS-Proxied-To = 127.0.0.1 (9) User-Name = 'mytest' (9) State = 0xb62146a8b72b5c8a3fe68614a37a338a (9) server inner-tunnel { (9) session-state: No cached attributes (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (9) authorize { (9) policy filter_username { (9) if (&User-Name =~ / /) { (9) if (&User-Name =~ / /) -> FALSE (9) if (&User-Name =~ /@.*@/ ) { (9) if (&User-Name =~ /@.*@/ ) -> FALSE (9) if (&User-Name =~ /\\.\\./ ) { (9) if (&User-Name =~ /\\.\\./ ) -> FALSE (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (9) if (&User-Name =~ /\\.$/) { (9) if (&User-Name =~ /\\.$/) -> FALSE (9) if (&User-Name =~ /@\\./) { (9) if (&User-Name =~ /@\\./) -> FALSE (9) } # policy filter_username = notfound (9) [mschap] = noop (9) suffix: Checking for suffix after "@" (9) suffix: No '@' in User-Name = "mytest", looking up realm NULL (9) suffix: Found realm "NULL" (9) suffix: Adding Stripped-User-Name = "mytest" (9) suffix: Adding Realm = "NULL" (9) suffix: Authentication realm is LOCAL (9) [suffix] = ok (9) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') { (9) EXPAND %{Realm} (9) --> NULL (9) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') -> FALSE (9) else { (9) update control { (9) &Proxy-To-Realm := LOCAL (9) } # update control = noop (9) } # else = noop (9) eap: Peer sent code Response (2) ID 10 length 9 (9) eap: No EAP Start, assuming it's an on-going EAP conversation (9) [eap] = updated (9) if (&EAP-Message) { (9) if (&EAP-Message) -> TRUE (9) if (&EAP-Message) { (9) redundant ldap_Portal_redundant { rlm_ldap (ldap_DB_1): Reserved connection (4) (9) ldap_DB_1: EXPAND (&(uid=%{%{Stripped-User-Name}:-%{User-Name}})) (9) ldap_DB_1: --> (&(uid=mytest)) (9) ldap_DB_1: Performing search in "ou=radius,o=test,c=hk" with filter "(&(uid=mytest))", scope "sub" (9) ldap_DB_1: Waiting for search result... (9) ldap_DB_1: Search returned no results rlm_ldap (ldap_DB_1): Released connection (4) (9) [ldap_DB_1] = notfound (9) } # redundant ldap_Portal_redundant = notfound (9) } # if (&EAP-Message) = notfound (9) ... skipping else for request 9: Preceding "if" was taken (9) [expiration] = noop (9) [logintime] = noop (9) [pap] = noop (9) } # authorize = updated (9) Found Auth-Type = EAP (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (9) authenticate { (9) eap: Expiring EAP session with state 0xb62146a8b72b5c8a (9) eap: Finished EAP session with state 0xb62146a8b72b5c8a (9) eap: Previous EAP request found for state 0xb62146a8b72b5c8a, released from the list (9) eap: Peer sent method MSCHAPv2 (26) (9) eap: EAP MSCHAPv2 (26) (9) eap: Calling eap_mschapv2 to process EAP data (9) eap: Freeing handler (9) [eap] = reject (9) } # authenticate = reject (9) Failed to authenticate the user (9) Login incorrect: [mytest] (from client radius-test-123.29 port 0 via TLS tunnel) (9) Using Post-Auth-Type Reject (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (9) Post-Auth-Type REJECT { (9) attr_filter.access_reject: EXPAND %{User-Name} (9) attr_filter.access_reject: --> mytest (9) attr_filter.access_reject: Matched entry DEFAULT at line 16 (9) [attr_filter.access_reject] = updated (9) update { (9) EXPAND Login incorrect: %{Module-Failure-Message} (9) --> Login incorrect: (9) &Module-Failure-Message := Login incorrect: (9) } # update = noop (9) linelog: EXPAND messages.%{%{reply:Packet-Type}:-default} (9) linelog: --> messages.Access-Reject (9) linelog: EXPAND /usr/local/var/log/radius/log/linelog-%Y%m%d (9) linelog: --> /usr/local/var/log/radius/log/linelog-20150630 (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}} (9) linelog: --> 2015-06-30 16:38:41,Access-Reject,10.210.123.29,,mytest,,,,Login incorrect: (9) [linelog] = ok (9) } # Post-Auth-Type REJECT = updated (9) } # server inner-tunnel (9) Virtual server sending reply (9) EAP-Message = 0x040a0004 (9) Message-Authenticator = 0x00000000000000000000000000000000 (9) eap_peap: Got tunneled reply code 3 (9) eap_peap: EAP-Message = 0x040a0004 (9) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (9) eap_peap: Got tunneled reply RADIUS code 3 (9) eap_peap: EAP-Message = 0x040a0004 (9) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (9) eap_peap: Tunneled authentication was rejected (9) eap_peap: FAILURE (9) eap: EAP session adding &reply:State = 0xb8002a16b10b3321 (9) [eap] = handled (9) } # authenticate = handled (9) Using Post-Auth-Type Challenge (9) Post-Auth-Type sub-section not found. Ignoring. (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (9) Sent Access-Challenge Id 45 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (9) EAP-Message = 0x010b002b190017030100206881fd9bcb736b457f738468f3088581bb4afa523344876e3aa398a833a2cfb4 (9) Message-Authenticator = 0x00000000000000000000000000000000 (9) State = 0xb8002a16b10b332133d295a612409a37 (9) Finished request Waking up in 4.7 seconds. (0) <done>: Cleaning up request packet ID 36 with timestamp +108 (1) <done>: Cleaning up request packet ID 37 with timestamp +108 (2) <done>: Cleaning up request packet ID 38 with timestamp +108 (3) <done>: Cleaning up request packet ID 39 with timestamp +108 (4) <done>: Cleaning up request packet ID 40 with timestamp +108 (5) <done>: Cleaning up request packet ID 41 with timestamp +108 (6) <done>: Cleaning up request packet ID 42 with timestamp +108 (7) <done>: Cleaning up request packet ID 43 with timestamp +108 (8) <done>: Cleaning up request packet ID 44 with timestamp +108 (9) <done>: Cleaning up request packet ID 45 with timestamp +108 Ready to process requests
Hi,
Login with correct username/password is fine. But for login with incorrect username or password, the failure message "mschap: ERROR: MS-CHAP2-Response is incorrect" does not appear in the final radius.log. I only get this:
thats a module return error message
Login incorrect: [mytest]
while I was expecting this:
Login incorrect (mschap: MS-CHAP2-Response is incorrect): [mytest]
no. you just get basic values with the default config
Module-Failure-Message is empty too when I try to do linelog in Post-Auth-Reject. What have I missed in the configration?
to log the error message you need to add the module failure message to the linelog config %{Module-Failure-Message} alan
Login incorrect: [mytest]
while I was expecting this:
Login incorrect (mschap: MS-CHAP2-Response is incorrect): [mytest]
no. you just get basic values with the default config
I thought the default config should include the failure error message. This was the case when I was using v1.1.8. Sorry for my ignorance, but which attribute is this error message "MS-CHAP2 Response is incorrect" stored? How do I include this error in radius.log? It seems I have no control on the radius.log format.
Module-Failure-Message is empty too when I try to do linelog in Post-Auth-Reject. What have I missed in > the configration?
to log the error message you need to add the module failure message to the linelog config
%{Module-Failure-Message}
Yes, I did. See the debug log below: (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}} But %{Module-Failure-Message} has no value stored. Thanks for any help. Fu
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 alan
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
participants (3)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan Buxey
-
Lai Fu Keung