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