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

30 Jun 2015

      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

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

Lai Fu Keung