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