v3.0.8: Failure message does not appear in radius.log
Lai Fu Keung
tfklai at hku.hk
Tue Jun 30 11:21:36 CEST 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
More information about the Freeradius-Users
mailing list