rlm_cache NT-Password with EAP-PEAP

Sherker, Donald Donald.Sherker at mybrighthouse.com
Fri Feb 27 19:11:27 CET 2015


>Then the debug output you provided is useless?
>
>You need to show two attempts with the same user, so we can see what's happening on the second attempt.
>

I apologize for that.  I have included the debug outputs at the bottom of this message for the same user from the same device.  The only difference is EAP-PEAP vs EAP-TTLS.

>Also, it's PEAP, why not just enable Session-Resumption?

We were working on Session-Resumption or rlm_cache.  We were not able to get Session-Resumption working, but we were having some luck with rlm_cache so we moved forward in that direction.

>
>-Arran
>
>Arran Cudbard-Bell <a.cudbardb at freeradius.org>
>FreeRADIUS development team
>
>FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2

EAP-TTLS:

Fri Feb 27 11:47:46 2015 : Debug: (0) Received Access-Request Id 216 from 24.94.145.173:50154 to 71.46.62.133:1812 length 180
Fri Feb 27 11:47:46 2015 : Debug: (0)   User-Name = 'qaresdon'
Fri Feb 27 11:47:46 2015 : Debug: (0)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:47:46 2015 : Debug: (0)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:47:46 2015 : Debug: (0)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:47:46 2015 : Debug: (0)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:47:46 2015 : Debug: (0)   NAS-Port = 0
Fri Feb 27 11:47:46 2015 : Debug: (0)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:47:46 2015 : Debug: (0)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:47:46 2015 : Debug: (0)   Acct-Session-Id = '54ECEF48-00000184'
Fri Feb 27 11:47:46 2015 : Debug: (0)   Framed-MTU = 1400
Fri Feb 27 11:47:46 2015 : Debug: (0)   EAP-Message = 0x020f000d017161726573646f6e
Fri Feb 27 11:47:46 2015 : Debug: (0)   Message-Authenticator = 0x352ef6f51334f1be3f498321a4e4049a
Fri Feb 27 11:47:46 2015 : Debug: (0) session-state: No State attribute
Fri Feb 27 11:47:46 2015 : Debug: (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:46 2015 : Debug: (0)   authorize {
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     [preprocess] = ok
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: calling chap (rlm_chap) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: returned from chap (rlm_chap) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     [chap] = noop
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: calling mschap (rlm_mschap) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     [mschap] = noop
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: calling digest (rlm_digest) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: returned from digest (rlm_digest) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     [digest] = noop
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: calling suffix (rlm_realm) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0) suffix: Checking for suffix after "@"
Fri Feb 27 11:47:46 2015 : Debug: (0) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:47:46 2015 : Debug: (0) suffix: No such realm "NULL"
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: returned from suffix (rlm_realm) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     [suffix] = noop
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: calling eap (rlm_eap) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0) eap: Peer sent code Response (2) ID 15 length 13
Fri Feb 27 11:47:46 2015 : Debug: (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authorize]: returned from eap (rlm_eap) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     [eap] = ok
Fri Feb 27 11:47:46 2015 : Debug: (0)   } # authorize = ok
Fri Feb 27 11:47:46 2015 : Debug: (0) Found Auth-Type = EAP
Fri Feb 27 11:47:46 2015 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:46 2015 : Debug: (0)   authenticate {
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authenticate]: calling eap (rlm_eap) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0) eap: Peer sent method Identity (1)
Fri Feb 27 11:47:46 2015 : Debug: (0) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:47:46 2015 : Debug: (0) eap_peap: Initiate
Fri Feb 27 11:47:46 2015 : Debug: (0) eap_peap: Start returned 1
Fri Feb 27 11:47:46 2015 : Debug: (0) eap: EAP session adding &reply:State = 0x204f2982205f3066
Fri Feb 27 11:47:46 2015 : Debug: (0)     modsingle[authenticate]: returned from eap (rlm_eap) for request 0
Fri Feb 27 11:47:46 2015 : Debug: (0)     [eap] = handled
Fri Feb 27 11:47:46 2015 : Debug: (0)   } # authenticate = handled
Fri Feb 27 11:47:46 2015 : Debug: (0) session-state: Nothing to cache
Fri Feb 27 11:47:46 2015 : Debug: (0) Sent Access-Challenge Id 216 from 71.46.62.133:1812 to 24.94.145.173:50154 length 64
Fri Feb 27 11:47:46 2015 : Debug: (0)   EAP-Message = 0x011000061920
Fri Feb 27 11:47:46 2015 : Debug: (0)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:47:46 2015 : Debug: (0)   State = 0x204f2982205f30668c4bee58afd4d0c1
Fri Feb 27 11:47:46 2015 : Debug: (0) Finished request
Fri Feb 27 11:47:46 2015 : Debug: Waking up in 0.3 seconds.
Fri Feb 27 11:47:46 2015 : Debug: (1) Received Access-Request Id 217 from 24.94.145.173:50154 to 71.46.62.133:1812 length 191
Fri Feb 27 11:47:46 2015 : Debug: (1)   User-Name = 'qaresdon'
Fri Feb 27 11:47:46 2015 : Debug: (1)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:47:46 2015 : Debug: (1)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:47:46 2015 : Debug: (1)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:47:46 2015 : Debug: (1)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:47:46 2015 : Debug: (1)   NAS-Port = 0
Fri Feb 27 11:47:46 2015 : Debug: (1)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:47:46 2015 : Debug: (1)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:47:46 2015 : Debug: (1)   Acct-Session-Id = '54ECEF48-00000184'
Fri Feb 27 11:47:46 2015 : Debug: (1)   Framed-MTU = 1400
Fri Feb 27 11:47:46 2015 : Debug: (1)   EAP-Message = 0x021000060315
Fri Feb 27 11:47:46 2015 : Debug: (1)   State = 0x204f2982205f30668c4bee58afd4d0c1
Fri Feb 27 11:47:46 2015 : Debug: (1)   Message-Authenticator = 0x350ae249e135c3b369ec550f08d32733
Fri Feb 27 11:47:46 2015 : Debug: (1) session-state: No cached attributes
Fri Feb 27 11:47:46 2015 : Debug: (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:46 2015 : Debug: (1)   authorize {
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [preprocess] = ok
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: calling chap (rlm_chap) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: returned from chap (rlm_chap) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [chap] = noop
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: calling mschap (rlm_mschap) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [mschap] = noop
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: calling digest (rlm_digest) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: returned from digest (rlm_digest) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [digest] = noop
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: calling suffix (rlm_realm) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1) suffix: Checking for suffix after "@"
Fri Feb 27 11:47:46 2015 : Debug: (1) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:47:46 2015 : Debug: (1) suffix: No such realm "NULL"
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: returned from suffix (rlm_realm) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [suffix] = noop
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: calling eap (rlm_eap) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1) eap: Peer sent code Response (2) ID 16 length 6
Fri Feb 27 11:47:46 2015 : Debug: (1) eap: No EAP Start, assuming it's an on-going EAP conversation
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: returned from eap (rlm_eap) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [eap] = updated
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: calling files (rlm_files) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: returned from files (rlm_files) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [files] = noop
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: calling ldap (rlm_ldap) for request 1
Fri Feb 27 11:47:46 2015 : Debug: rlm_ldap (ldap): Reserved connection (4)
Fri Feb 27 11:47:46 2015 : Debug: (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri Feb 27 11:47:46 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:46 2015 : Debug: literal --> (uid=
Fri Feb 27 11:47:46 2015 : Debug: if {
Fri Feb 27 11:47:46 2015 : Debug:       attribute --> Stripped-User-Name
Fri Feb 27 11:47:46 2015 : Debug: }
Fri Feb 27 11:47:46 2015 : Debug: else {
Fri Feb 27 11:47:46 2015 : Debug:       attribute --> User-Name
Fri Feb 27 11:47:46 2015 : Debug: }
Fri Feb 27 11:47:46 2015 : Debug: literal --> )
Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri Feb 27 11:47:46 2015 : Debug: (1) ldap:    --> (uid=qaresdon)
Fri Feb 27 11:47:46 2015 : Debug: ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:47:46 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:46 2015 : Debug: literal --> ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: EXPAND ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:47:46 2015 : Debug: (1) ldap:    --> ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: Performing search in 'ou=Customers,dc=brighthouse,dc=com' with filter '(uid=qaresdon)', scope 'sub'
Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: Waiting for search result...
Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: User object found at DN "rrCustomerID=A6398B1D-9057-4873-B13F-E41B1808B52A,ou=18,ou=Customers,dc=brighthouse,dc=com"
Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: Added eDirectory password.  control:Cleartext-Password += 'xxxxxxxxx'
Fri Feb 27 11:47:46 2015 : Debug: rlm_ldap (ldap): Released connection (4)
Fri Feb 27 11:47:46 2015 : Info: rlm_ldap (ldap): Closing connection (0), from 1 unused connections
Fri Feb 27 11:47:46 2015 : Debug: rlm_ldap: Closing libldap handle 0x1ae5a40
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: returned from ldap (rlm_ldap) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [ldap] = ok
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: calling expiration (rlm_expiration) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: returned from expiration (rlm_expiration) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [expiration] = noop
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: calling logintime (rlm_logintime) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authorize]: returned from logintime (rlm_logintime) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [logintime] = noop
Fri Feb 27 11:47:46 2015 : Debug: (1)   } # authorize = updated
Fri Feb 27 11:47:46 2015 : Debug: (1) Found Auth-Type = EAP
Fri Feb 27 11:47:46 2015 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:46 2015 : Debug: (1)   authenticate {
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authenticate]: calling eap (rlm_eap) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1) eap: Expiring EAP session with state 0x204f2982205f3066
Fri Feb 27 11:47:46 2015 : Debug: (1) eap: Finished EAP session with state 0x204f2982205f3066
Fri Feb 27 11:47:46 2015 : Debug: (1) eap: Previous EAP request found for state 0x204f2982205f3066, released from the list
Fri Feb 27 11:47:46 2015 : Debug: (1) eap: Peer sent method NAK (3)
Fri Feb 27 11:47:46 2015 : Debug: (1) eap: Found mutually acceptable type TTLS (21)
Fri Feb 27 11:47:46 2015 : Debug: (1) eap: Calling eap_ttls to process EAP data
Fri Feb 27 11:47:46 2015 : Debug: (1) eap_ttls: Initiate
Fri Feb 27 11:47:46 2015 : Debug: (1) eap_ttls: Start returned 1
Fri Feb 27 11:47:46 2015 : Debug: (1) eap: EAP session adding &reply:State = 0x204f2982215e3c66
Fri Feb 27 11:47:46 2015 : Debug: (1)     modsingle[authenticate]: returned from eap (rlm_eap) for request 1
Fri Feb 27 11:47:46 2015 : Debug: (1)     [eap] = handled
Fri Feb 27 11:47:46 2015 : Debug: (1)   } # authenticate = handled
Fri Feb 27 11:47:46 2015 : Debug: (1) session-state: Nothing to cache
Fri Feb 27 11:47:46 2015 : Debug: (1) Sent Access-Challenge Id 217 from 71.46.62.133:1812 to 24.94.145.173:50154 length 64
Fri Feb 27 11:47:46 2015 : Debug: (1)   EAP-Message = 0x011100061520
Fri Feb 27 11:47:46 2015 : Debug: (1)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:47:46 2015 : Debug: (1)   State = 0x204f2982215e3c668c4bee58afd4d0c1
Fri Feb 27 11:47:46 2015 : Debug: (1) Finished request
Fri Feb 27 11:47:46 2015 : Debug: Waking up in 0.2 seconds.
Fri Feb 27 11:47:46 2015 : Debug: (2) Received Access-Request Id 218 from 24.94.145.173:50154 to 71.46.62.133:1812 length 381
Fri Feb 27 11:47:46 2015 : Debug: (2)   User-Name = 'qaresdon'
Fri Feb 27 11:47:46 2015 : Debug: (2)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:47:46 2015 : Debug: (2)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:47:46 2015 : Debug: (2)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:47:46 2015 : Debug: (2)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:47:46 2015 : Debug: (2)   NAS-Port = 0
Fri Feb 27 11:47:46 2015 : Debug: (2)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:47:46 2015 : Debug: (2)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:47:46 2015 : Debug: (2)   Acct-Session-Id = '54ECEF48-00000184'
Fri Feb 27 11:47:46 2015 : Debug: (2)   Framed-MTU = 1400
Fri Feb 27 11:47:46 2015 : Debug: (2)   EAP-Message = 0x021100c4150016030100b9010000b5030154f09fb17b997012a57293df71d3e04759962d8e6fb7d3341c14004b24e98f3d000048c014c00a00390038c00fc0050035c012c00800160013c00dc003000ac013c00900330032c00ec004002fc011c007c00cc0020005000400150012000900140011000800
Fri Feb 27 11:47:46 2015 : Debug: (2)   State = 0x204f2982215e3c668c4bee58afd4d0c1
Fri Feb 27 11:47:46 2015 : Debug: (2)   Message-Authenticator = 0xcfe4fe8da219ab3af3d6306699d9b87f
Fri Feb 27 11:47:46 2015 : Debug: (2) session-state: No cached attributes
Fri Feb 27 11:47:46 2015 : Debug: (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:46 2015 : Debug: (2)   authorize {
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     [preprocess] = ok
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: calling chap (rlm_chap) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: returned from chap (rlm_chap) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     [chap] = noop
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: calling mschap (rlm_mschap) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     [mschap] = noop
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: calling digest (rlm_digest) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: returned from digest (rlm_digest) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     [digest] = noop
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: calling suffix (rlm_realm) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2) suffix: Checking for suffix after "@"
Fri Feb 27 11:47:46 2015 : Debug: (2) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:47:46 2015 : Debug: (2) suffix: No such realm "NULL"
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: returned from suffix (rlm_realm) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     [suffix] = noop
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: calling eap (rlm_eap) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2) eap: Peer sent code Response (2) ID 17 length 196
Fri Feb 27 11:47:46 2015 : Debug: (2) eap: Continuing tunnel setup
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authorize]: returned from eap (rlm_eap) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     [eap] = ok
Fri Feb 27 11:47:46 2015 : Debug: (2)   } # authorize = ok
Fri Feb 27 11:47:46 2015 : Debug: (2) Found Auth-Type = EAP
Fri Feb 27 11:47:46 2015 : Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:46 2015 : Debug: (2)   authenticate {
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authenticate]: calling eap (rlm_eap) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2) eap: Expiring EAP session with state 0x204f2982215e3c66
Fri Feb 27 11:47:46 2015 : Debug: (2) eap: Finished EAP session with state 0x204f2982215e3c66
Fri Feb 27 11:47:46 2015 : Debug: (2) eap: Previous EAP request found for state 0x204f2982215e3c66, released from the list
Fri Feb 27 11:47:46 2015 : Debug: (2) eap: Peer sent method TTLS (21)
Fri Feb 27 11:47:46 2015 : Debug: (2) eap: EAP TTLS (21)
Fri Feb 27 11:47:46 2015 : Debug: (2) eap: Calling eap_ttls to process EAP data
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: Authenticate
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: processing EAP-TLS
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: eaptls_verify returned 7
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: Done initial handshake
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: (other): before/accept initialization
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: TLS_accept: before/accept initialization
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: <<< TLS 1.0 Handshake [length 00b9], ClientHello
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: TLS_accept: SSLv3 read client hello A
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: >>> TLS 1.0 Handshake [length 0039], ServerHello
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: TLS_accept: SSLv3 write server hello A
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: >>> TLS 1.0 Handshake [length 0e58], Certificate
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: TLS_accept: SSLv3 write certificate A
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: TLS_accept: SSLv3 write key exchange A
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: TLS_accept: SSLv3 write server done A
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: TLS_accept: SSLv3 flush data
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client certificate A
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client certificate A
Fri Feb 27 11:47:46 2015 : Debug: In SSL Handshake Phase
Fri Feb 27 11:47:46 2015 : Debug: In SSL Accept mode
Fri Feb 27 11:47:46 2015 : Debug: (2) eap_ttls: eaptls_process returned 13
Fri Feb 27 11:47:46 2015 : Debug: (2) eap: EAP session adding &reply:State = 0x204f2982225d3c66
Fri Feb 27 11:47:46 2015 : Debug: (2)     modsingle[authenticate]: returned from eap (rlm_eap) for request 2
Fri Feb 27 11:47:46 2015 : Debug: (2)     [eap] = handled
Fri Feb 27 11:47:46 2015 : Debug: (2)   } # authenticate = handled
Fri Feb 27 11:47:46 2015 : Debug: (2) session-state: Nothing to cache
Fri Feb 27 11:47:46 2015 : Debug: (2) Sent Access-Challenge Id 218 from 71.46.62.133:1812 to 24.94.145.173:50154 length 1448
Fri Feb 27 11:47:46 2015 : Debug: (2)   EAP-Message = 0x0112056415c000000ff4160301003902000035030154f09fb2ceda632faec6aa1156d5c57b9496e8a50656460d50f4ece465c22dc800c01400000dff01000100000b0004030001021603010e580b000e54000e510005213082051d30820405a00302010202044c233c7e300d06092a864886f70d010105
Fri Feb 27 11:47:46 2015 : Debug: (2)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:47:46 2015 : Debug: (2)   State = 0x204f2982225d3c668c4bee58afd4d0c1
Fri Feb 27 11:47:46 2015 : Debug: (2) Finished request
Fri Feb 27 11:47:46 2015 : Debug: Waking up in 0.1 seconds.
Fri Feb 27 11:47:46 2015 : Debug: (3) Received Access-Request Id 219 from 24.94.145.173:50154 to 71.46.62.133:1812 length 191
Fri Feb 27 11:47:46 2015 : Debug: (3)   User-Name = 'qaresdon'
Fri Feb 27 11:47:46 2015 : Debug: (3)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:47:46 2015 : Debug: (3)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:47:46 2015 : Debug: (3)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:47:46 2015 : Debug: (3)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:47:46 2015 : Debug: (3)   NAS-Port = 0
Fri Feb 27 11:47:46 2015 : Debug: (3)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:47:46 2015 : Debug: (3)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:47:46 2015 : Debug: (3)   Acct-Session-Id = '54ECEF48-00000184'
Fri Feb 27 11:47:46 2015 : Debug: (3)   Framed-MTU = 1400
Fri Feb 27 11:47:46 2015 : Debug: (3)   EAP-Message = 0x021200061500
Fri Feb 27 11:47:46 2015 : Debug: (3)   State = 0x204f2982225d3c668c4bee58afd4d0c1
Fri Feb 27 11:47:46 2015 : Debug: (3)   Message-Authenticator = 0x9f82c59ec923d84c532dccde8772cda2
Fri Feb 27 11:47:46 2015 : Debug: (3) session-state: No cached attributes
Fri Feb 27 11:47:46 2015 : Debug: (3) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:46 2015 : Debug: (3)   authorize {
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     [preprocess] = ok
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: calling chap (rlm_chap) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: returned from chap (rlm_chap) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     [chap] = noop
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: calling mschap (rlm_mschap) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     [mschap] = noop
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: calling digest (rlm_digest) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: returned from digest (rlm_digest) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     [digest] = noop
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: calling suffix (rlm_realm) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3) suffix: Checking for suffix after "@"
Fri Feb 27 11:47:46 2015 : Debug: (3) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:47:46 2015 : Debug: (3) suffix: No such realm "NULL"
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: returned from suffix (rlm_realm) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     [suffix] = noop
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: calling eap (rlm_eap) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3) eap: Peer sent code Response (2) ID 18 length 6
Fri Feb 27 11:47:46 2015 : Debug: (3) eap: Continuing tunnel setup
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authorize]: returned from eap (rlm_eap) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     [eap] = ok
Fri Feb 27 11:47:46 2015 : Debug: (3)   } # authorize = ok
Fri Feb 27 11:47:46 2015 : Debug: (3) Found Auth-Type = EAP
Fri Feb 27 11:47:46 2015 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:46 2015 : Debug: (3)   authenticate {
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authenticate]: calling eap (rlm_eap) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3) eap: Expiring EAP session with state 0x204f2982225d3c66
Fri Feb 27 11:47:46 2015 : Debug: (3) eap: Finished EAP session with state 0x204f2982225d3c66
Fri Feb 27 11:47:46 2015 : Debug: (3) eap: Previous EAP request found for state 0x204f2982225d3c66, released from the list
Fri Feb 27 11:47:46 2015 : Debug: (3) eap: Peer sent method TTLS (21)
Fri Feb 27 11:47:46 2015 : Debug: (3) eap: EAP TTLS (21)
Fri Feb 27 11:47:46 2015 : Debug: (3) eap: Calling eap_ttls to process EAP data
Fri Feb 27 11:47:46 2015 : Debug: (3) eap_ttls: Authenticate
Fri Feb 27 11:47:46 2015 : Debug: (3) eap_ttls: processing EAP-TLS
Fri Feb 27 11:47:46 2015 : Debug: (3) eap_ttls: Received TLS ACK
Fri Feb 27 11:47:46 2015 : Debug: (3) eap_ttls: Received TLS ACK
Fri Feb 27 11:47:46 2015 : Debug: (3) eap_ttls: ACK handshake fragment handler
Fri Feb 27 11:47:46 2015 : Debug: (3) eap_ttls: eaptls_verify returned 1
Fri Feb 27 11:47:46 2015 : Debug: (3) eap_ttls: eaptls_process returned 13
Fri Feb 27 11:47:46 2015 : Debug: (3) eap: EAP session adding &reply:State = 0x204f2982235c3c66
Fri Feb 27 11:47:46 2015 : Debug: (3)     modsingle[authenticate]: returned from eap (rlm_eap) for request 3
Fri Feb 27 11:47:46 2015 : Debug: (3)     [eap] = handled
Fri Feb 27 11:47:46 2015 : Debug: (3)   } # authenticate = handled
Fri Feb 27 11:47:46 2015 : Debug: (3) session-state: Nothing to cache
Fri Feb 27 11:47:46 2015 : Debug: (3) Sent Access-Challenge Id 219 from 71.46.62.133:1812 to 24.94.145.173:50154 length 1448
Fri Feb 27 11:47:46 2015 : Debug: (3)   EAP-Message = 0x0113056415c000000ff4f3fa6ff051ec9a0730ea94aaa1596407296688590004f9308204f5308203dda00302010202044c0e8c39300d06092a864886f70d01010505003081b431143012060355040a130b456e74727573742e6e65743140303e060355040b14377777772e656e74727573742e6e65742f
Fri Feb 27 11:47:46 2015 : Debug: (3)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:47:46 2015 : Debug: (3)   State = 0x204f2982235c3c668c4bee58afd4d0c1
Fri Feb 27 11:47:46 2015 : Debug: (3) Finished request
Fri Feb 27 11:47:46 2015 : Debug: Waking up in 0.1 seconds.
Fri Feb 27 11:47:46 2015 : Debug: (4) Received Access-Request Id 220 from 24.94.145.173:50154 to 71.46.62.133:1812 length 191
Fri Feb 27 11:47:46 2015 : Debug: (4)   User-Name = 'qaresdon'
Fri Feb 27 11:47:46 2015 : Debug: (4)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:47:46 2015 : Debug: (4)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:47:46 2015 : Debug: (4)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:47:46 2015 : Debug: (4)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:47:46 2015 : Debug: (4)   NAS-Port = 0
Fri Feb 27 11:47:46 2015 : Debug: (4)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:47:46 2015 : Debug: (4)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:47:46 2015 : Debug: (4)   Acct-Session-Id = '54ECEF48-00000184'
Fri Feb 27 11:47:46 2015 : Debug: (4)   Framed-MTU = 1400
Fri Feb 27 11:47:46 2015 : Debug: (4)   EAP-Message = 0x021300061500
Fri Feb 27 11:47:46 2015 : Debug: (4)   State = 0x204f2982235c3c668c4bee58afd4d0c1
Fri Feb 27 11:47:46 2015 : Debug: (4)   Message-Authenticator = 0x221e5e8b53095d686f4ad64ce74e85c2
Fri Feb 27 11:47:46 2015 : Debug: (4) session-state: No cached attributes
Fri Feb 27 11:47:46 2015 : Debug: (4) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:46 2015 : Debug: (4)   authorize {
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     [preprocess] = ok
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: calling chap (rlm_chap) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: returned from chap (rlm_chap) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     [chap] = noop
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: calling mschap (rlm_mschap) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     [mschap] = noop
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: calling digest (rlm_digest) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: returned from digest (rlm_digest) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     [digest] = noop
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: calling suffix (rlm_realm) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4) suffix: Checking for suffix after "@"
Fri Feb 27 11:47:46 2015 : Debug: (4) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:47:46 2015 : Debug: (4) suffix: No such realm "NULL"
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: returned from suffix (rlm_realm) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     [suffix] = noop
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: calling eap (rlm_eap) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4) eap: Peer sent code Response (2) ID 19 length 6
Fri Feb 27 11:47:46 2015 : Debug: (4) eap: Continuing tunnel setup
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authorize]: returned from eap (rlm_eap) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     [eap] = ok
Fri Feb 27 11:47:46 2015 : Debug: (4)   } # authorize = ok
Fri Feb 27 11:47:46 2015 : Debug: (4) Found Auth-Type = EAP
Fri Feb 27 11:47:46 2015 : Debug: (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:46 2015 : Debug: (4)   authenticate {
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authenticate]: calling eap (rlm_eap) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4) eap: Expiring EAP session with state 0x204f2982235c3c66
Fri Feb 27 11:47:46 2015 : Debug: (4) eap: Finished EAP session with state 0x204f2982235c3c66
Fri Feb 27 11:47:46 2015 : Debug: (4) eap: Previous EAP request found for state 0x204f2982235c3c66, released from the list
Fri Feb 27 11:47:46 2015 : Debug: (4) eap: Peer sent method TTLS (21)
Fri Feb 27 11:47:46 2015 : Debug: (4) eap: EAP TTLS (21)
Fri Feb 27 11:47:46 2015 : Debug: (4) eap: Calling eap_ttls to process EAP data
Fri Feb 27 11:47:46 2015 : Debug: (4) eap_ttls: Authenticate
Fri Feb 27 11:47:46 2015 : Debug: (4) eap_ttls: processing EAP-TLS
Fri Feb 27 11:47:46 2015 : Debug: (4) eap_ttls: Received TLS ACK
Fri Feb 27 11:47:46 2015 : Debug: (4) eap_ttls: Received TLS ACK
Fri Feb 27 11:47:46 2015 : Debug: (4) eap_ttls: ACK handshake fragment handler
Fri Feb 27 11:47:46 2015 : Debug: (4) eap_ttls: eaptls_verify returned 1
Fri Feb 27 11:47:46 2015 : Debug: (4) eap_ttls: eaptls_process returned 13
Fri Feb 27 11:47:46 2015 : Debug: (4) eap: EAP session adding &reply:State = 0x204f2982245b3c66
Fri Feb 27 11:47:46 2015 : Debug: (4)     modsingle[authenticate]: returned from eap (rlm_eap) for request 4
Fri Feb 27 11:47:46 2015 : Debug: (4)     [eap] = handled
Fri Feb 27 11:47:46 2015 : Debug: (4)   } # authenticate = handled
Fri Feb 27 11:47:46 2015 : Debug: (4) session-state: Nothing to cache
Fri Feb 27 11:47:46 2015 : Debug: (4) Sent Access-Challenge Id 220 from 71.46.62.133:1812 to 24.94.145.173:50154 length 1422
Fri Feb 27 11:47:46 2015 : Debug: (4)   EAP-Message = 0x0114054a158000000ff477772e656e74727573742e6e65742f4350535f3230343820696e636f72702e206279207265662e20286c696d697473206c6961622e2931253023060355040b131c286329203139393920456e74727573742e6e6574204c696d69746564313330310603550403132a456e747275
Fri Feb 27 11:47:46 2015 : Debug: (4)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:47:46 2015 : Debug: (4)   State = 0x204f2982245b3c668c4bee58afd4d0c1
Fri Feb 27 11:47:46 2015 : Debug: (4) Finished request
Fri Feb 27 11:47:47 2015 : Debug: Waking up in 4.3 seconds.

Fri Feb 27 11:47:49 2015 : Debug: (5) Received Access-Request Id 221 from 24.94.145.173:50154 to 71.46.62.133:1812 length 325
Fri Feb 27 11:47:49 2015 : Debug: (5)   User-Name = 'qaresdon'
Fri Feb 27 11:47:49 2015 : Debug: (5)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:47:49 2015 : Debug: (5)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:47:49 2015 : Debug: (5)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:47:49 2015 : Debug: (5)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:47:49 2015 : Debug: (5)   NAS-Port = 0
Fri Feb 27 11:47:49 2015 : Debug: (5)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:47:49 2015 : Debug: (5)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:47:49 2015 : Debug: (5)   Acct-Session-Id = '54ECEF48-00000184'
Fri Feb 27 11:47:49 2015 : Debug: (5)   Framed-MTU = 1400
Fri Feb 27 11:47:49 2015 : Debug: (5)   EAP-Message = 0x0214008c15001603010046100000424104c6ff59ecbd2e7d5287728ef70866b5622324a3c64450e9a3ff59475a2400ba003a7234d0aacc3bf5d72f4eb3846c651b61c0a3409dc59f28f5285586e7103bff14030100010116030100303c7fda42cabf457d2cfaa6af65b6e309a9d52088b26654a81f15a1
Fri Feb 27 11:47:49 2015 : Debug: (5)   State = 0x204f2982245b3c668c4bee58afd4d0c1
Fri Feb 27 11:47:49 2015 : Debug: (5)   Message-Authenticator = 0x5837cbf7cda0a8f4f3f10d48fe2d6632
Fri Feb 27 11:47:49 2015 : Debug: (5) session-state: No cached attributes
Fri Feb 27 11:47:49 2015 : Debug: (5) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:49 2015 : Debug: (5)   authorize {
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     [preprocess] = ok
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: calling chap (rlm_chap) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: returned from chap (rlm_chap) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     [chap] = noop
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: calling mschap (rlm_mschap) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     [mschap] = noop
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: calling digest (rlm_digest) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: returned from digest (rlm_digest) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     [digest] = noop
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: calling suffix (rlm_realm) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5) suffix: Checking for suffix after "@"
Fri Feb 27 11:47:49 2015 : Debug: (5) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:47:49 2015 : Debug: (5) suffix: No such realm "NULL"
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: returned from suffix (rlm_realm) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     [suffix] = noop
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: calling eap (rlm_eap) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5) eap: Peer sent code Response (2) ID 20 length 140
Fri Feb 27 11:47:49 2015 : Debug: (5) eap: Continuing tunnel setup
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authorize]: returned from eap (rlm_eap) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     [eap] = ok
Fri Feb 27 11:47:49 2015 : Debug: (5)   } # authorize = ok
Fri Feb 27 11:47:49 2015 : Debug: (5) Found Auth-Type = EAP
Fri Feb 27 11:47:49 2015 : Debug: (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:49 2015 : Debug: (5)   authenticate {
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authenticate]: calling eap (rlm_eap) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5) eap: Expiring EAP session with state 0x204f2982245b3c66
Fri Feb 27 11:47:49 2015 : Debug: (5) eap: Finished EAP session with state 0x204f2982245b3c66
Fri Feb 27 11:47:49 2015 : Debug: (5) eap: Previous EAP request found for state 0x204f2982245b3c66, released from the list
Fri Feb 27 11:47:49 2015 : Debug: (5) eap: Peer sent method TTLS (21)
Fri Feb 27 11:47:49 2015 : Debug: (5) eap: EAP TTLS (21)
Fri Feb 27 11:47:49 2015 : Debug: (5) eap: Calling eap_ttls to process EAP data
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: Authenticate
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: processing EAP-TLS
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: eaptls_verify returned 7
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: Done initial handshake
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: TLS_accept: SSLv3 read client key exchange A
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: <<< TLS 1.0 ChangeCipherSpec [length 0001]
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: <<< TLS 1.0 Handshake [length 0010], Finished
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: TLS_accept: SSLv3 read finished A
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: >>> TLS 1.0 ChangeCipherSpec [length 0001]
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: TLS_accept: SSLv3 write change cipher spec A
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: >>> TLS 1.0 Handshake [length 0010], Finished
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: TLS_accept: SSLv3 write finished A
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: TLS_accept: SSLv3 flush data
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: (other): SSL negotiation finished successfully
Fri Feb 27 11:47:49 2015 : Debug: SSL Connection Established
Fri Feb 27 11:47:49 2015 : Debug: (5) eap_ttls: eaptls_process returned 13
Fri Feb 27 11:47:49 2015 : Debug: (5) eap: EAP session adding &reply:State = 0x204f2982255a3c66
Fri Feb 27 11:47:49 2015 : Debug: (5)     modsingle[authenticate]: returned from eap (rlm_eap) for request 5
Fri Feb 27 11:47:49 2015 : Debug: (5)     [eap] = handled
Fri Feb 27 11:47:49 2015 : Debug: (5)   } # authenticate = handled
Fri Feb 27 11:47:49 2015 : Debug: (5) session-state: Nothing to cache
Fri Feb 27 11:47:49 2015 : Debug: (5) Sent Access-Challenge Id 221 from 71.46.62.133:1812 to 24.94.145.173:50154 length 127
Fri Feb 27 11:47:49 2015 : Debug: (5)   EAP-Message = 0x0115004515800000003b1403010001011603010030ef1a9168c18bbdb7d8d81ec8a81430a71efb715f74b6d18e99232e5e6b8ca2e4d1292a643cd105a8b9ef62cb17f8c99f
Fri Feb 27 11:47:49 2015 : Debug: (5)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:47:49 2015 : Debug: (5)   State = 0x204f2982255a3c668c4bee58afd4d0c1
Fri Feb 27 11:47:49 2015 : Debug: (5) Finished request
Fri Feb 27 11:47:49 2015 : Debug: Waking up in 0.3 seconds.
Fri Feb 27 11:47:49 2015 : Debug: (6) Received Access-Request Id 222 from 24.94.145.173:50154 to 71.46.62.133:1812 length 377
Fri Feb 27 11:47:49 2015 : Debug: (6)   User-Name = 'qaresdon'
Fri Feb 27 11:47:49 2015 : Debug: (6)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:47:49 2015 : Debug: (6)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:47:49 2015 : Debug: (6)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:47:49 2015 : Debug: (6)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:47:49 2015 : Debug: (6)   NAS-Port = 0
Fri Feb 27 11:47:49 2015 : Debug: (6)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:47:49 2015 : Debug: (6)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:47:49 2015 : Debug: (6)   Acct-Session-Id = '54ECEF48-00000184'
Fri Feb 27 11:47:49 2015 : Debug: (6)   Framed-MTU = 1400
Fri Feb 27 11:47:49 2015 : Debug: (6)   EAP-Message = 0x021500c015001703010020a89138440256e2daa07ded2d3ec034263809105ea0b2322343fe6f14b0a0294617030100903fd34fa6097117766f7ec9f7faed812457ea0d521469fdca2a6a6377b57157efd3670ebfa59d368a24a50b44e7d84e1fa3546290cc17e64d1c0fdc15621209a0be2b10c91f6dff
Fri Feb 27 11:47:49 2015 : Debug: (6)   State = 0x204f2982255a3c668c4bee58afd4d0c1
Fri Feb 27 11:47:49 2015 : Debug: (6)   Message-Authenticator = 0xd55d3ec1b632d97371ff5c039c111f5d
Fri Feb 27 11:47:49 2015 : Debug: (6) session-state: No cached attributes
Fri Feb 27 11:47:49 2015 : Debug: (6) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:49 2015 : Debug: (6)   authorize {
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     [preprocess] = ok
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: calling chap (rlm_chap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: returned from chap (rlm_chap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     [chap] = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: calling mschap (rlm_mschap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     [mschap] = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: calling digest (rlm_digest) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: returned from digest (rlm_digest) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     [digest] = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: calling suffix (rlm_realm) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6) suffix: Checking for suffix after "@"
Fri Feb 27 11:47:49 2015 : Debug: (6) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:47:49 2015 : Debug: (6) suffix: No such realm "NULL"
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: returned from suffix (rlm_realm) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     [suffix] = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: calling eap (rlm_eap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6) eap: Peer sent code Response (2) ID 21 length 192
Fri Feb 27 11:47:49 2015 : Debug: (6) eap: Continuing tunnel setup
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authorize]: returned from eap (rlm_eap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     [eap] = ok
Fri Feb 27 11:47:49 2015 : Debug: (6)   } # authorize = ok
Fri Feb 27 11:47:49 2015 : Debug: (6) Found Auth-Type = EAP
Fri Feb 27 11:47:49 2015 : Debug: (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:49 2015 : Debug: (6)   authenticate {
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authenticate]: calling eap (rlm_eap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6) eap: Expiring EAP session with state 0x204f2982255a3c66
Fri Feb 27 11:47:49 2015 : Debug: (6) eap: Finished EAP session with state 0x204f2982255a3c66
Fri Feb 27 11:47:49 2015 : Debug: (6) eap: Previous EAP request found for state 0x204f2982255a3c66, released from the list
Fri Feb 27 11:47:49 2015 : Debug: (6) eap: Peer sent method TTLS (21)
Fri Feb 27 11:47:49 2015 : Debug: (6) eap: EAP TTLS (21)
Fri Feb 27 11:47:49 2015 : Debug: (6) eap: Calling eap_ttls to process EAP data
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: Authenticate
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: processing EAP-TLS
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: eaptls_verify returned 7
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: Done initial handshake
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: eaptls_process returned 7
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: Session established.  Proceeding to decode tunneled attributes
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: Got tunneled request
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls:   User-Name = 'qaresdon'
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls:   MS-CHAP-Challenge = 0xaf2fdf5314c6b2d4080496ccd142e6e1
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls:   MS-CHAP2-Response = 0xd2001d385400b1d0f0200000002b00000057000000000000000066eec45b7cacf02aff803f58e135eecfd4655da4e2ee2efe
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: Sending tunneled request
Fri Feb 27 11:47:49 2015 : Debug: (6) Virtual server received request
Fri Feb 27 11:47:49 2015 : Debug: (6)   User-Name = 'qaresdon'
Fri Feb 27 11:47:49 2015 : Debug: (6)   MS-CHAP-Challenge = 0xaf2fdf5314c6b2d4080496ccd142e6e1
Fri Feb 27 11:47:49 2015 : Debug: (6)   MS-CHAP2-Response = 0xd2001d385400b1d0f0200000002b00000057000000000000000066eec45b7cacf02aff803f58e135eecfd4655da4e2ee2efe
Fri Feb 27 11:47:49 2015 : Debug: (6) server inner-tunnel {
Fri Feb 27 11:47:49 2015 : Debug: (6)   session-state: No State attribute
Fri Feb 27 11:47:49 2015 : Debug: (6)   # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:47:49 2015 : Debug: (6)     authorize {
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: calling suffix (rlm_realm) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6) suffix: Checking for suffix after "@"
Fri Feb 27 11:47:49 2015 : Debug: (6) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:47:49 2015 : Debug: (6) suffix: No such realm "NULL"
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: returned from suffix (rlm_realm) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       [suffix] = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)       update control {
Fri Feb 27 11:47:49 2015 : Debug: (6)         &Proxy-To-Realm := 'LOCAL'
Fri Feb 27 11:47:49 2015 : Debug: (6)       } # update control = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: calling files (rlm_files) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: returned from files (rlm_files) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       [files] = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)       update control {
Fri Feb 27 11:47:49 2015 : Debug: (6)         Cache-Status-Only = yes
Fri Feb 27 11:47:49 2015 : Debug: (6)       } # update control = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: calling cache (rlm_cache) for request 6
Fri Feb 27 11:47:49 2015 : Debug: %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:49 2015 : Debug: attribute --> User-Name
Fri Feb 27 11:47:49 2015 : Debug: attribute --> Calling-Station-Id
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: EXPAND %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:47:49 2015 : Debug: (6) cache:    --> qaresdone899c47233d8
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Mutex acquired
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: No cache entry found for "qaresdone899c47233d8"
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Mutex released
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: returned from cache (rlm_cache) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       [cache] = notfound
Fri Feb 27 11:47:49 2015 : Debug: (6)       if (notfound) {
Fri Feb 27 11:47:49 2015 : Debug: (6)       if (notfound)  -> TRUE
Fri Feb 27 11:47:49 2015 : Debug: (6)       if (notfound)  {
Fri Feb 27 11:47:49 2015 : Debug: (6)         modsingle[authorize]: calling ldap (rlm_ldap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: rlm_ldap (ldap): Reserved connection (4)
Fri Feb 27 11:47:49 2015 : Debug: (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:49 2015 : Debug: literal --> (uid=
Fri Feb 27 11:47:49 2015 : Debug: if {
Fri Feb 27 11:47:49 2015 : Debug:       attribute --> Stripped-User-Name
Fri Feb 27 11:47:49 2015 : Debug: }
Fri Feb 27 11:47:49 2015 : Debug: else {
Fri Feb 27 11:47:49 2015 : Debug:       attribute --> User-Name
Fri Feb 27 11:47:49 2015 : Debug: }
Fri Feb 27 11:47:49 2015 : Debug: literal --> )
Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri Feb 27 11:47:49 2015 : Debug: (6) ldap:    --> (uid=qaresdon)
Fri Feb 27 11:47:49 2015 : Debug: ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:49 2015 : Debug: literal --> ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: EXPAND ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:47:49 2015 : Debug: (6) ldap:    --> ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: Performing search in 'ou=Customers,dc=brighthouse,dc=com' with filter '(uid=qaresdon)', scope 'sub'
Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: Waiting for search result...
Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: User object found at DN "rrCustomerID=A6398B1D-9057-4873-B13F-E41B1808B52A,ou=18,ou=Customers,dc=brighthouse,dc=com"
Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: Added eDirectory password.  control:Cleartext-Password += 'xxxxxxxxx'
Fri Feb 27 11:47:49 2015 : Debug: rlm_ldap (ldap): Released connection (4)
Fri Feb 27 11:47:49 2015 : Debug: (6)         modsingle[authorize]: returned from ldap (rlm_ldap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)         [ldap] = ok
Fri Feb 27 11:47:49 2015 : Debug: (6)       } # if (notfound)  = ok
Fri Feb 27 11:47:49 2015 : Debug: (6)       ... skipping else for request 6: Preceding "if" was taken
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: calling eap (rlm_eap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6) eap: No EAP-Message, not doing EAP
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: returned from eap (rlm_eap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       [eap] = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: calling mschap (rlm_mschap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6) mschap: Found MS-CHAP attributes.  Setting 'Auth-Type  = mschap'
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: returned from mschap (rlm_mschap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       [mschap] = ok
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: calling expiration (rlm_expiration) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: returned from expiration (rlm_expiration) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       [expiration] = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: calling logintime (rlm_logintime) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authorize]: returned from logintime (rlm_logintime) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       [logintime] = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)     } # authorize = ok
Fri Feb 27 11:47:49 2015 : Debug: (6)   Found Auth-Type = MSCHAP
Fri Feb 27 11:47:49 2015 : Debug: (6)   # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:47:49 2015 : Debug: (6)     Auth-Type MS-CHAP {
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authenticate]: calling mschap (rlm_mschap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6) mschap: Found Cleartext-Password, hashing to create NT-Password
Fri Feb 27 11:47:49 2015 : Debug: (6) mschap: Found Cleartext-Password, hashing to create LM-Password
Fri Feb 27 11:47:49 2015 : Debug: (6) mschap: Creating challenge hash with username: qaresdon
Fri Feb 27 11:47:49 2015 : Debug: (6) mschap: Client is using MS-CHAPv2
Fri Feb 27 11:47:49 2015 : Debug: (6) mschap: Adding MS-CHAPv2 MPPE keys
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[authenticate]: returned from mschap (rlm_mschap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       [mschap] = ok
Fri Feb 27 11:47:49 2015 : Debug: (6)     } # Auth-Type MS-CHAP = ok
Fri Feb 27 11:47:49 2015 : Debug: (6)   # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:47:49 2015 : Debug: (6)     post-auth {
Fri Feb 27 11:47:49 2015 : Debug: (6)       policy cui-inner.post-auth {
Fri Feb 27 11:47:49 2015 : Debug: (6)         if (&outer.request:Chargeable-User-Identity &&        (&outer.request:Operator-Name || ('no' != 'yes'))) {
Fri Feb 27 11:47:49 2015 : Debug: (6)         if (&outer.request:Chargeable-User-Identity &&        (&outer.request:Operator-Name || ('no' != 'yes')))  -> FALSE
Fri Feb 27 11:47:49 2015 : Debug: (6)       } # policy cui-inner.post-auth = noop
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[post-auth]: calling cache (rlm_cache) for request 6
Fri Feb 27 11:47:49 2015 : Debug: %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:49 2015 : Debug: attribute --> User-Name
Fri Feb 27 11:47:49 2015 : Debug: attribute --> Calling-Station-Id
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: EXPAND %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:47:49 2015 : Debug: (6) cache:    --> qaresdone899c47233d8
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Mutex acquired
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: No cache entry found for "qaresdone899c47233d8"
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Creating new cache entry
Fri Feb 27 11:47:49 2015 : Debug: %{control:NT-Password}
Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:49 2015 : Debug: attribute --> NT-Password
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: EXPAND %{control:NT-Password}
Fri Feb 27 11:47:49 2015 : Debug: (6) cache:    --> 0x5835048ce94ad0564e29a924a03510ef
Fri Feb 27 11:47:49 2015 : Debug: (6) cache:   control:NT-Password := 0x5835048ce94ad0564e29a924a03510ef
Fri Feb 27 11:47:49 2015 : Debug: %{control:LM-Password}
Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:49 2015 : Debug: attribute --> LM-Password
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: EXPAND %{control:LM-Password}
Fri Feb 27 11:47:49 2015 : Debug: (6) cache:    --> 0xe52cac67419a9a2238f10713b629b565
Fri Feb 27 11:47:49 2015 : Debug: (6) cache:   control:LM-Password := 0xe52cac67419a9a2238f10713b629b565
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Merging cache entry into request
Fri Feb 27 11:47:49 2015 : Debug: (6) cache:   &control:NT-Password := 0x5835048ce94ad0564e29a924a03510ef
Fri Feb 27 11:47:49 2015 : Debug: (6) cache:   &control:LM-Password := 0xe52cac67419a9a2238f10713b629b565
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: FROM 2 TO 6 MAX 8
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: Examining NT-Password
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: OVERWRITING NT-Password FROM 0 TO 4
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: Examining LM-Password
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: OVERWRITING LM-Password FROM 1 TO 5
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: TO in 6 out 6
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[0] = Proxy-To-Realm
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[1] = Ldap-UserDn
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[2] = Cleartext-Password
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[3] = Auth-Type
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[4] = NT-Password
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[5] = LM-Password
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Commited entry, TTL 86400 seconds
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Mutex released
Fri Feb 27 11:47:49 2015 : Debug: (6)       modsingle[post-auth]: returned from cache (rlm_cache) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)       [cache] = updated
Fri Feb 27 11:47:49 2015 : Debug: (6)     } # post-auth = updated
Fri Feb 27 11:47:49 2015 : Debug: (6) } # server inner-tunnel
Fri Feb 27 11:47:49 2015 : Debug: (6) Virtual server sending reply
Fri Feb 27 11:47:49 2015 : Debug: (6)   MS-CHAP2-Success = 0xd2533d36314530323939313234324633454637463032464243383932303731453845303636363339373132
Fri Feb 27 11:47:49 2015 : Debug: (6)   MS-MPPE-Recv-Key = 0x0f43250c72b196e120162ef6248bb3ee
Fri Feb 27 11:47:49 2015 : Debug: (6)   MS-MPPE-Send-Key = 0x201b62ef56ed0c1ff0a7beb46260ed91
Fri Feb 27 11:47:49 2015 : Debug: (6)   MS-MPPE-Encryption-Policy = Encryption-Required
Fri Feb 27 11:47:49 2015 : Debug: (6)   MS-MPPE-Encryption-Types = 4
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: Got tunneled Access-Accept
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: Got MS-CHAP2-Success, tunneling it to the client in a challenge
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: Sending tunneled reply attributes
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls:   MS-CHAP2-Success = 0xd2533d36314530323939313234324633454637463032464243383932303731453845303636363339373132
Fri Feb 27 11:47:49 2015 : Debug: (6) eap: EAP session adding &reply:State = 0x204f298226593c66
Fri Feb 27 11:47:49 2015 : Debug: (6)     modsingle[authenticate]: returned from eap (rlm_eap) for request 6
Fri Feb 27 11:47:49 2015 : Debug: (6)     [eap] = handled
Fri Feb 27 11:47:49 2015 : Debug: (6)   } # authenticate = handled
Fri Feb 27 11:47:49 2015 : Debug: (6) session-state: Nothing to cache
Fri Feb 27 11:47:49 2015 : Debug: (6) Sent Access-Challenge Id 222 from 71.46.62.133:1812 to 24.94.145.173:50154 length 153
Fri Feb 27 11:47:49 2015 : Debug: (6)   EAP-Message = 0x0116005f15800000005517030100500bbcd646b14c483eab6bd7474e470b3a1d615471c7612c204526cadb5bf080f8796bf81253c6bcc95d731a988caa8aa66743d7dc7d2f86f460f4d91b1252a6b8973446461f0cf19a01cb348c9e4848bb
Fri Feb 27 11:47:49 2015 : Debug: (6)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:47:49 2015 : Debug: (6)   State = 0x204f298226593c668c4bee58afd4d0c1
Fri Feb 27 11:47:49 2015 : Debug: (6) Finished request
Fri Feb 27 11:47:49 2015 : Debug: Waking up in 0.2 seconds.
Fri Feb 27 11:47:49 2015 : Debug: (7) Received Access-Request Id 223 from 24.94.145.173:50154 to 71.46.62.133:1812 length 191
Fri Feb 27 11:47:49 2015 : Debug: (7)   User-Name = 'qaresdon'
Fri Feb 27 11:47:49 2015 : Debug: (7)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:47:49 2015 : Debug: (7)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:47:49 2015 : Debug: (7)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:47:49 2015 : Debug: (7)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:47:49 2015 : Debug: (7)   NAS-Port = 0
Fri Feb 27 11:47:49 2015 : Debug: (7)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:47:49 2015 : Debug: (7)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:47:49 2015 : Debug: (7)   Acct-Session-Id = '54ECEF48-00000184'
Fri Feb 27 11:47:49 2015 : Debug: (7)   Framed-MTU = 1400
Fri Feb 27 11:47:49 2015 : Debug: (7)   EAP-Message = 0x021600061500
Fri Feb 27 11:47:49 2015 : Debug: (7)   State = 0x204f298226593c668c4bee58afd4d0c1
Fri Feb 27 11:47:49 2015 : Debug: (7)   Message-Authenticator = 0x88f9758bbbc36c476fea06350ff96944
Fri Feb 27 11:47:49 2015 : Debug: (7) session-state: No cached attributes
Fri Feb 27 11:47:49 2015 : Debug: (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:49 2015 : Debug: (7)   authorize {
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     [preprocess] = ok
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: calling chap (rlm_chap) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: returned from chap (rlm_chap) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     [chap] = noop
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: calling mschap (rlm_mschap) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     [mschap] = noop
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: calling digest (rlm_digest) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: returned from digest (rlm_digest) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     [digest] = noop
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: calling suffix (rlm_realm) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7) suffix: Checking for suffix after "@"
Fri Feb 27 11:47:49 2015 : Debug: (7) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:47:49 2015 : Debug: (7) suffix: No such realm "NULL"
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: returned from suffix (rlm_realm) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     [suffix] = noop
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: calling eap (rlm_eap) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7) eap: Peer sent code Response (2) ID 22 length 6
Fri Feb 27 11:47:49 2015 : Debug: (7) eap: Continuing tunnel setup
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authorize]: returned from eap (rlm_eap) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     [eap] = ok
Fri Feb 27 11:47:49 2015 : Debug: (7)   } # authorize = ok
Fri Feb 27 11:47:49 2015 : Debug: (7) Found Auth-Type = EAP
Fri Feb 27 11:47:49 2015 : Debug: (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:49 2015 : Debug: (7)   authenticate {
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authenticate]: calling eap (rlm_eap) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7) eap: Expiring EAP session with state 0x204f298226593c66
Fri Feb 27 11:47:49 2015 : Debug: (7) eap: Finished EAP session with state 0x204f298226593c66
Fri Feb 27 11:47:49 2015 : Debug: (7) eap: Previous EAP request found for state 0x204f298226593c66, released from the list
Fri Feb 27 11:47:49 2015 : Debug: (7) eap: Peer sent method TTLS (21)
Fri Feb 27 11:47:49 2015 : Debug: (7) eap: EAP TTLS (21)
Fri Feb 27 11:47:49 2015 : Debug: (7) eap: Calling eap_ttls to process EAP data
Fri Feb 27 11:47:49 2015 : Debug: (7) eap_ttls: Authenticate
Fri Feb 27 11:47:49 2015 : Debug: (7) eap_ttls: processing EAP-TLS
Fri Feb 27 11:47:49 2015 : Debug: (7) eap_ttls: Received TLS ACK
Fri Feb 27 11:47:49 2015 : Debug: (7) eap_ttls: Received TLS ACK
Fri Feb 27 11:47:49 2015 : Debug: (7) eap_ttls: ACK handshake is finished
Fri Feb 27 11:47:49 2015 : Debug: (7) eap_ttls: eaptls_verify returned 3
Fri Feb 27 11:47:49 2015 : Debug: (7) eap_ttls: eaptls_process returned 3
Fri Feb 27 11:47:49 2015 : Debug: (7) eap: Freeing handler
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[authenticate]: returned from eap (rlm_eap) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     [eap] = ok
Fri Feb 27 11:47:49 2015 : Debug: (7)   } # authenticate = ok
Fri Feb 27 11:47:49 2015 : Debug: (7) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:47:49 2015 : Debug: (7)   post-auth {
Fri Feb 27 11:47:49 2015 : Debug: (7)     update {
Fri Feb 27 11:47:49 2015 : Debug: (7)       No attributes updated
Fri Feb 27 11:47:49 2015 : Debug: (7)     } # update = noop
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[post-auth]: calling linelog (rlm_linelog) for request 7
Fri Feb 27 11:47:49 2015 : Debug: Accounting-Request.%{%{Acct-Status-Type}:-unknown}
Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:49 2015 : Debug: literal --> Accounting-Request.
Fri Feb 27 11:47:49 2015 : Debug: if {
Fri Feb 27 11:47:49 2015 : Debug:       attribute --> Acct-Status-Type
Fri Feb 27 11:47:49 2015 : Debug: }
Fri Feb 27 11:47:49 2015 : Debug: else {
Fri Feb 27 11:47:49 2015 : Debug:       literal --> unknown
Fri Feb 27 11:47:49 2015 : Debug: }
Fri Feb 27 11:47:49 2015 : Debug: (7) linelog: EXPAND Accounting-Request.%{%{Acct-Status-Type}:-unknown}
Fri Feb 27 11:47:49 2015 : Debug: (7) linelog:    --> Accounting-Request.unknown
Fri Feb 27 11:47:49 2015 : Debug: /var/log/radius/linelog
Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:49 2015 : Debug: literal --> /var/log/radius/linelog
Fri Feb 27 11:47:49 2015 : Debug: (7) linelog: EXPAND /var/log/radius/linelog
Fri Feb 27 11:47:49 2015 : Debug: (7) linelog:    --> /var/log/radius/linelog
Fri Feb 27 11:47:49 2015 : Debug: NAS %{Packet-Src-IP-Address} (%{NAS-IP-Address}) sent unknown Acct-Status-Type %{Acct-Status-Type}
Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:47:49 2015 : Debug: literal --> NAS
Fri Feb 27 11:47:49 2015 : Debug: attribute --> Packet-Src-IP-Address
Fri Feb 27 11:47:49 2015 : Debug: literal -->  (
Fri Feb 27 11:47:49 2015 : Debug: attribute --> NAS-IP-Address
Fri Feb 27 11:47:49 2015 : Debug: literal --> ) sent unknown Acct-Status-Type
Fri Feb 27 11:47:49 2015 : Debug: attribute --> Acct-Status-Type
Fri Feb 27 11:47:49 2015 : Debug: (7) linelog: EXPAND NAS %{Packet-Src-IP-Address} (%{NAS-IP-Address}) sent unknown Acct-Status-Type %{Acct-Status-Type}
Fri Feb 27 11:47:49 2015 : Debug: (7) linelog:    --> NAS 24.94.145.173 (24.94.145.173) sent unknown Acct-Status-Type
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[post-auth]: returned from linelog (rlm_linelog) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     [linelog] = ok
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[post-auth]: calling exec (rlm_exec) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     modsingle[post-auth]: returned from exec (rlm_exec) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)     [exec] = noop
Fri Feb 27 11:47:49 2015 : Debug: (7)     policy remove_reply_message_if_eap {
Fri Feb 27 11:47:49 2015 : Debug: (7)       if (&reply:EAP-Message && &reply:Reply-Message) {
Fri Feb 27 11:47:49 2015 : Debug: (7)       if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
Fri Feb 27 11:47:49 2015 : Debug: (7)       else {
Fri Feb 27 11:47:49 2015 : Debug: (7)         modsingle[post-auth]: calling noop (rlm_always) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)         modsingle[post-auth]: returned from noop (rlm_always) for request 7
Fri Feb 27 11:47:49 2015 : Debug: (7)         [noop] = noop
Fri Feb 27 11:47:49 2015 : Debug: (7)       } # else = noop
Fri Feb 27 11:47:49 2015 : Debug: (7)     } # policy remove_reply_message_if_eap = noop
Fri Feb 27 11:47:49 2015 : Debug: (7)   } # post-auth = ok
Fri Feb 27 11:47:49 2015 : Debug: (7) Sent Access-Accept Id 223 from 71.46.62.133:1812 to 24.94.145.173:50154 length 170
Fri Feb 27 11:47:49 2015 : Debug: (7)   MS-MPPE-Recv-Key = 0xa94ada91d68540debb2cf793bc7b2248ba77c9122fca4e0216f70f7372c1c941
Fri Feb 27 11:47:49 2015 : Debug: (7)   MS-MPPE-Send-Key = 0xc8a95a2451025da064a28b146384cdfb5ecb6d1423896aaf416728e640727217
Fri Feb 27 11:47:49 2015 : Debug: (7)   EAP-Message = 0x03160004
Fri Feb 27 11:47:49 2015 : Debug: (7)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:47:49 2015 : Debug: (7)   User-Name = 'qaresdon'



EAP-PEAP:
Fri Feb 27 11:48:43 2015 : Debug: (0) Received Access-Request Id 224 from 24.94.145.173:50155 to 71.46.62.133:1812 length 180
Fri Feb 27 11:48:43 2015 : Debug: (0)   User-Name = 'qaresdon'
Fri Feb 27 11:48:43 2015 : Debug: (0)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:48:43 2015 : Debug: (0)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:48:43 2015 : Debug: (0)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:48:43 2015 : Debug: (0)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:48:43 2015 : Debug: (0)   NAS-Port = 0
Fri Feb 27 11:48:43 2015 : Debug: (0)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:48:43 2015 : Debug: (0)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:48:43 2015 : Debug: (0)   Acct-Session-Id = '54ECEF48-00000185'
Fri Feb 27 11:48:43 2015 : Debug: (0)   Framed-MTU = 1400
Fri Feb 27 11:48:43 2015 : Debug: (0)   EAP-Message = 0x0276000d017161726573646f6e
Fri Feb 27 11:48:43 2015 : Debug: (0)   Message-Authenticator = 0x2df871fab7b93602aac9a68c61e2e4cb
Fri Feb 27 11:48:43 2015 : Debug: (0) session-state: No State attribute
Fri Feb 27 11:48:43 2015 : Debug: (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:43 2015 : Debug: (0)   authorize {
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     [preprocess] = ok
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: calling chap (rlm_chap) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: returned from chap (rlm_chap) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     [chap] = noop
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: calling mschap (rlm_mschap) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     [mschap] = noop
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: calling digest (rlm_digest) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: returned from digest (rlm_digest) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     [digest] = noop
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: calling suffix (rlm_realm) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:43 2015 : Debug: (0) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:43 2015 : Debug: (0) suffix: No such realm "NULL"
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: returned from suffix (rlm_realm) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     [suffix] = noop
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: calling eap (rlm_eap) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0) eap: Peer sent code Response (2) ID 118 length 13
Fri Feb 27 11:48:43 2015 : Debug: (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authorize]: returned from eap (rlm_eap) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     [eap] = ok
Fri Feb 27 11:48:43 2015 : Debug: (0)   } # authorize = ok
Fri Feb 27 11:48:43 2015 : Debug: (0) Found Auth-Type = EAP
Fri Feb 27 11:48:43 2015 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:43 2015 : Debug: (0)   authenticate {
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authenticate]: calling eap (rlm_eap) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0) eap: Peer sent method Identity (1)
Fri Feb 27 11:48:43 2015 : Debug: (0) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:48:43 2015 : Debug: (0) eap_peap: Initiate
Fri Feb 27 11:48:43 2015 : Debug: (0) eap_peap: Start returned 1
Fri Feb 27 11:48:43 2015 : Debug: (0) eap: EAP session adding &reply:State = 0x43bc3b6943cb22ae
Fri Feb 27 11:48:43 2015 : Debug: (0)     modsingle[authenticate]: returned from eap (rlm_eap) for request 0
Fri Feb 27 11:48:43 2015 : Debug: (0)     [eap] = handled
Fri Feb 27 11:48:43 2015 : Debug: (0)   } # authenticate = handled
Fri Feb 27 11:48:43 2015 : Debug: (0) session-state: Nothing to cache
Fri Feb 27 11:48:43 2015 : Debug: (0) Sent Access-Challenge Id 224 from 71.46.62.133:1812 to 24.94.145.173:50155 length 64
Fri Feb 27 11:48:43 2015 : Debug: (0)   EAP-Message = 0x017700061920
Fri Feb 27 11:48:43 2015 : Debug: (0)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:43 2015 : Debug: (0)   State = 0x43bc3b6943cb22ae11358de93389f275
Fri Feb 27 11:48:43 2015 : Debug: (0) Finished request
Fri Feb 27 11:48:43 2015 : Debug: Waking up in 0.3 seconds.
Fri Feb 27 11:48:43 2015 : Debug: (1) Received Access-Request Id 225 from 24.94.145.173:50155 to 71.46.62.133:1812 length 385
Fri Feb 27 11:48:43 2015 : Debug: (1)   User-Name = 'qaresdon'
Fri Feb 27 11:48:43 2015 : Debug: (1)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:48:43 2015 : Debug: (1)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:48:43 2015 : Debug: (1)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:48:43 2015 : Debug: (1)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:48:43 2015 : Debug: (1)   NAS-Port = 0
Fri Feb 27 11:48:43 2015 : Debug: (1)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:48:43 2015 : Debug: (1)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:48:43 2015 : Debug: (1)   Acct-Session-Id = '54ECEF48-00000185'
Fri Feb 27 11:48:43 2015 : Debug: (1)   Framed-MTU = 1400
Fri Feb 27 11:48:43 2015 : Debug: (1)   EAP-Message = 0x027700c81980000000be16030100b9010000b5030154f09feabdf3ea9c6d5ecce97b79e5502ea898b7e4a91e7cae67cf33462d80dd000048c014c00a00390038c00fc0050035c012c00800160013c00dc003000ac013c00900330032c00ec004002fc011c007c00cc00200050004001500120009001400
Fri Feb 27 11:48:43 2015 : Debug: (1)   State = 0x43bc3b6943cb22ae11358de93389f275
Fri Feb 27 11:48:43 2015 : Debug: (1)   Message-Authenticator = 0x0bcd8c310b2363a798deb6f6fa43dacb
Fri Feb 27 11:48:43 2015 : Debug: (1) session-state: No cached attributes
Fri Feb 27 11:48:43 2015 : Debug: (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:43 2015 : Debug: (1)   authorize {
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     [preprocess] = ok
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: calling chap (rlm_chap) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: returned from chap (rlm_chap) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     [chap] = noop
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: calling mschap (rlm_mschap) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     [mschap] = noop
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: calling digest (rlm_digest) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: returned from digest (rlm_digest) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     [digest] = noop
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: calling suffix (rlm_realm) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:43 2015 : Debug: (1) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:43 2015 : Debug: (1) suffix: No such realm "NULL"
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: returned from suffix (rlm_realm) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     [suffix] = noop
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: calling eap (rlm_eap) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1) eap: Peer sent code Response (2) ID 119 length 200
Fri Feb 27 11:48:43 2015 : Debug: (1) eap: Continuing tunnel setup
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authorize]: returned from eap (rlm_eap) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     [eap] = ok
Fri Feb 27 11:48:43 2015 : Debug: (1)   } # authorize = ok
Fri Feb 27 11:48:43 2015 : Debug: (1) Found Auth-Type = EAP
Fri Feb 27 11:48:43 2015 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:43 2015 : Debug: (1)   authenticate {
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authenticate]: calling eap (rlm_eap) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1) eap: Expiring EAP session with state 0x43bc3b6943cb22ae
Fri Feb 27 11:48:43 2015 : Debug: (1) eap: Finished EAP session with state 0x43bc3b6943cb22ae
Fri Feb 27 11:48:43 2015 : Debug: (1) eap: Previous EAP request found for state 0x43bc3b6943cb22ae, released from the list
Fri Feb 27 11:48:43 2015 : Debug: (1) eap: Peer sent method PEAP (25)
Fri Feb 27 11:48:43 2015 : Debug: (1) eap: EAP PEAP (25)
Fri Feb 27 11:48:43 2015 : Debug: (1) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: processing EAP-TLS
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: TLS Length 190
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: Length Included
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: eaptls_verify returned 11
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: (other): before/accept initialization
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: TLS_accept: before/accept initialization
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: <<< TLS 1.0 Handshake [length 00b9], ClientHello
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 read client hello A
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: >>> TLS 1.0 Handshake [length 0039], ServerHello
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 write server hello A
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: >>> TLS 1.0 Handshake [length 0e58], Certificate
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 write certificate A
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 write key exchange A
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 write server done A
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: TLS_accept: SSLv3 flush data
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: TLS_accept: Need to read more data: SSLv3 read client certificate A
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: TLS_accept: Need to read more data: SSLv3 read client certificate A
Fri Feb 27 11:48:43 2015 : Debug: In SSL Handshake Phase
Fri Feb 27 11:48:43 2015 : Debug: In SSL Accept mode
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: eaptls_process returned 13
Fri Feb 27 11:48:43 2015 : Debug: (1) eap_peap: FR_TLS_HANDLED
Fri Feb 27 11:48:43 2015 : Debug: (1) eap: EAP session adding &reply:State = 0x43bc3b6942c422ae
Fri Feb 27 11:48:43 2015 : Debug: (1)     modsingle[authenticate]: returned from eap (rlm_eap) for request 1
Fri Feb 27 11:48:43 2015 : Debug: (1)     [eap] = handled
Fri Feb 27 11:48:43 2015 : Debug: (1)   } # authenticate = handled
Fri Feb 27 11:48:43 2015 : Debug: (1) session-state: Nothing to cache
Fri Feb 27 11:48:43 2015 : Debug: (1) Sent Access-Challenge Id 225 from 71.46.62.133:1812 to 24.94.145.173:50155 length 1448
Fri Feb 27 11:48:43 2015 : Debug: (1)   EAP-Message = 0x0178056419c000000ff4160301003902000035030154f09feb681c6ba51cd254aa5263ce9d10486dc5fe1a766c3f2aa5dc2c36a9ca00c01400000dff01000100000b0004030001021603010e580b000e54000e510005213082051d30820405a00302010202044c233c7e300d06092a864886f70d010105
Fri Feb 27 11:48:43 2015 : Debug: (1)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:43 2015 : Debug: (1)   State = 0x43bc3b6942c422ae11358de93389f275
Fri Feb 27 11:48:43 2015 : Debug: (1) Finished request
Fri Feb 27 11:48:43 2015 : Debug: Waking up in 0.2 seconds.
Fri Feb 27 11:48:43 2015 : Debug: (2) Received Access-Request Id 226 from 24.94.145.173:50155 to 71.46.62.133:1812 length 191
Fri Feb 27 11:48:43 2015 : Debug: (2)   User-Name = 'qaresdon'
Fri Feb 27 11:48:43 2015 : Debug: (2)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:48:43 2015 : Debug: (2)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:48:43 2015 : Debug: (2)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:48:43 2015 : Debug: (2)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:48:43 2015 : Debug: (2)   NAS-Port = 0
Fri Feb 27 11:48:43 2015 : Debug: (2)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:48:43 2015 : Debug: (2)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:48:43 2015 : Debug: (2)   Acct-Session-Id = '54ECEF48-00000185'
Fri Feb 27 11:48:43 2015 : Debug: (2)   Framed-MTU = 1400
Fri Feb 27 11:48:43 2015 : Debug: (2)   EAP-Message = 0x027800061900
Fri Feb 27 11:48:43 2015 : Debug: (2)   State = 0x43bc3b6942c422ae11358de93389f275
Fri Feb 27 11:48:43 2015 : Debug: (2)   Message-Authenticator = 0x419f17062a6f0402ea3c66d7edf382ff
Fri Feb 27 11:48:43 2015 : Debug: (2) session-state: No cached attributes
Fri Feb 27 11:48:43 2015 : Debug: (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:43 2015 : Debug: (2)   authorize {
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     [preprocess] = ok
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: calling chap (rlm_chap) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: returned from chap (rlm_chap) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     [chap] = noop
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: calling mschap (rlm_mschap) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     [mschap] = noop
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: calling digest (rlm_digest) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: returned from digest (rlm_digest) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     [digest] = noop
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: calling suffix (rlm_realm) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:43 2015 : Debug: (2) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:43 2015 : Debug: (2) suffix: No such realm "NULL"
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: returned from suffix (rlm_realm) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     [suffix] = noop
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: calling eap (rlm_eap) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2) eap: Peer sent code Response (2) ID 120 length 6
Fri Feb 27 11:48:43 2015 : Debug: (2) eap: Continuing tunnel setup
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authorize]: returned from eap (rlm_eap) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     [eap] = ok
Fri Feb 27 11:48:43 2015 : Debug: (2)   } # authorize = ok
Fri Feb 27 11:48:43 2015 : Debug: (2) Found Auth-Type = EAP
Fri Feb 27 11:48:43 2015 : Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:43 2015 : Debug: (2)   authenticate {
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authenticate]: calling eap (rlm_eap) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2) eap: Expiring EAP session with state 0x43bc3b6942c422ae
Fri Feb 27 11:48:43 2015 : Debug: (2) eap: Finished EAP session with state 0x43bc3b6942c422ae
Fri Feb 27 11:48:43 2015 : Debug: (2) eap: Previous EAP request found for state 0x43bc3b6942c422ae, released from the list
Fri Feb 27 11:48:43 2015 : Debug: (2) eap: Peer sent method PEAP (25)
Fri Feb 27 11:48:43 2015 : Debug: (2) eap: EAP PEAP (25)
Fri Feb 27 11:48:43 2015 : Debug: (2) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:48:43 2015 : Debug: (2) eap_peap: processing EAP-TLS
Fri Feb 27 11:48:43 2015 : Debug: (2) eap_peap: Received TLS ACK
Fri Feb 27 11:48:43 2015 : Debug: (2) eap_peap: Received TLS ACK
Fri Feb 27 11:48:43 2015 : Debug: (2) eap_peap: ACK handshake fragment handler
Fri Feb 27 11:48:43 2015 : Debug: (2) eap_peap: eaptls_verify returned 1
Fri Feb 27 11:48:43 2015 : Debug: (2) eap_peap: eaptls_process returned 13
Fri Feb 27 11:48:43 2015 : Debug: (2) eap_peap: FR_TLS_HANDLED
Fri Feb 27 11:48:43 2015 : Debug: (2) eap: EAP session adding &reply:State = 0x43bc3b6941c522ae
Fri Feb 27 11:48:43 2015 : Debug: (2)     modsingle[authenticate]: returned from eap (rlm_eap) for request 2
Fri Feb 27 11:48:43 2015 : Debug: (2)     [eap] = handled
Fri Feb 27 11:48:43 2015 : Debug: (2)   } # authenticate = handled
Fri Feb 27 11:48:43 2015 : Debug: (2) session-state: Nothing to cache
Fri Feb 27 11:48:43 2015 : Debug: (2) Sent Access-Challenge Id 226 from 71.46.62.133:1812 to 24.94.145.173:50155 length 1444
Fri Feb 27 11:48:43 2015 : Debug: (2)   EAP-Message = 0x017905601940f3fa6ff051ec9a0730ea94aaa1596407296688590004f9308204f5308203dda00302010202044c0e8c39300d06092a864886f70d01010505003081b431143012060355040a130b456e74727573742e6e65743140303e060355040b14377777772e656e74727573742e6e65742f4350535f
Fri Feb 27 11:48:43 2015 : Debug: (2)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:43 2015 : Debug: (2)   State = 0x43bc3b6941c522ae11358de93389f275
Fri Feb 27 11:48:43 2015 : Debug: (2) Finished request
Fri Feb 27 11:48:43 2015 : Debug: Waking up in 0.1 seconds.
Fri Feb 27 11:48:43 2015 : Debug: (3) Received Access-Request Id 227 from 24.94.145.173:50155 to 71.46.62.133:1812 length 191
Fri Feb 27 11:48:43 2015 : Debug: (3)   User-Name = 'qaresdon'
Fri Feb 27 11:48:43 2015 : Debug: (3)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:48:43 2015 : Debug: (3)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:48:43 2015 : Debug: (3)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:48:43 2015 : Debug: (3)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:48:43 2015 : Debug: (3)   NAS-Port = 0
Fri Feb 27 11:48:43 2015 : Debug: (3)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:48:43 2015 : Debug: (3)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:48:43 2015 : Debug: (3)   Acct-Session-Id = '54ECEF48-00000185'
Fri Feb 27 11:48:43 2015 : Debug: (3)   Framed-MTU = 1400
Fri Feb 27 11:48:43 2015 : Debug: (3)   EAP-Message = 0x027900061900
Fri Feb 27 11:48:43 2015 : Debug: (3)   State = 0x43bc3b6941c522ae11358de93389f275
Fri Feb 27 11:48:43 2015 : Debug: (3)   Message-Authenticator = 0x7c859c81b0ed2f35fcc34558fd0ee33b
Fri Feb 27 11:48:43 2015 : Debug: (3) session-state: No cached attributes
Fri Feb 27 11:48:43 2015 : Debug: (3) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:43 2015 : Debug: (3)   authorize {
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     [preprocess] = ok
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: calling chap (rlm_chap) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: returned from chap (rlm_chap) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     [chap] = noop
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: calling mschap (rlm_mschap) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     [mschap] = noop
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: calling digest (rlm_digest) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: returned from digest (rlm_digest) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     [digest] = noop
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: calling suffix (rlm_realm) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:43 2015 : Debug: (3) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:43 2015 : Debug: (3) suffix: No such realm "NULL"
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: returned from suffix (rlm_realm) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     [suffix] = noop
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: calling eap (rlm_eap) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3) eap: Peer sent code Response (2) ID 121 length 6
Fri Feb 27 11:48:43 2015 : Debug: (3) eap: Continuing tunnel setup
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authorize]: returned from eap (rlm_eap) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     [eap] = ok
Fri Feb 27 11:48:43 2015 : Debug: (3)   } # authorize = ok
Fri Feb 27 11:48:43 2015 : Debug: (3) Found Auth-Type = EAP
Fri Feb 27 11:48:43 2015 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:43 2015 : Debug: (3)   authenticate {
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authenticate]: calling eap (rlm_eap) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3) eap: Expiring EAP session with state 0x43bc3b6941c522ae
Fri Feb 27 11:48:43 2015 : Debug: (3) eap: Finished EAP session with state 0x43bc3b6941c522ae
Fri Feb 27 11:48:43 2015 : Debug: (3) eap: Previous EAP request found for state 0x43bc3b6941c522ae, released from the list
Fri Feb 27 11:48:43 2015 : Debug: (3) eap: Peer sent method PEAP (25)
Fri Feb 27 11:48:43 2015 : Debug: (3) eap: EAP PEAP (25)
Fri Feb 27 11:48:43 2015 : Debug: (3) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:48:43 2015 : Debug: (3) eap_peap: processing EAP-TLS
Fri Feb 27 11:48:43 2015 : Debug: (3) eap_peap: Received TLS ACK
Fri Feb 27 11:48:43 2015 : Debug: (3) eap_peap: Received TLS ACK
Fri Feb 27 11:48:43 2015 : Debug: (3) eap_peap: ACK handshake fragment handler
Fri Feb 27 11:48:43 2015 : Debug: (3) eap_peap: eaptls_verify returned 1
Fri Feb 27 11:48:43 2015 : Debug: (3) eap_peap: eaptls_process returned 13
Fri Feb 27 11:48:43 2015 : Debug: (3) eap_peap: FR_TLS_HANDLED
Fri Feb 27 11:48:43 2015 : Debug: (3) eap: EAP session adding &reply:State = 0x43bc3b6940c622ae
Fri Feb 27 11:48:43 2015 : Debug: (3)     modsingle[authenticate]: returned from eap (rlm_eap) for request 3
Fri Feb 27 11:48:43 2015 : Debug: (3)     [eap] = handled
Fri Feb 27 11:48:43 2015 : Debug: (3)   } # authenticate = handled
Fri Feb 27 11:48:43 2015 : Debug: (3) session-state: Nothing to cache
Fri Feb 27 11:48:43 2015 : Debug: (3) Sent Access-Challenge Id 227 from 71.46.62.133:1812 to 24.94.145.173:50155 length 1418
Fri Feb 27 11:48:43 2015 : Debug: (3)   EAP-Message = 0x017a0546190077772e656e74727573742e6e65742f4350535f3230343820696e636f72702e206279207265662e20286c696d697473206c6961622e2931253023060355040b131c286329203139393920456e74727573742e6e6574204c696d69746564313330310603550403132a456e74727573742e6e
Fri Feb 27 11:48:43 2015 : Debug: (3)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:43 2015 : Debug: (3)   State = 0x43bc3b6940c622ae11358de93389f275
Fri Feb 27 11:48:43 2015 : Debug: (3) Finished request
Fri Feb 27 11:48:43 2015 : Debug: Waking up in 0.1 seconds.
Fri Feb 27 11:48:43 2015 : Debug: (4) Received Access-Request Id 228 from 24.94.145.173:50155 to 71.46.62.133:1812 length 329
Fri Feb 27 11:48:43 2015 : Debug: (4)   User-Name = 'qaresdon'
Fri Feb 27 11:48:43 2015 : Debug: (4)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:48:43 2015 : Debug: (4)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:48:43 2015 : Debug: (4)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:48:43 2015 : Debug: (4)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:48:43 2015 : Debug: (4)   NAS-Port = 0
Fri Feb 27 11:48:43 2015 : Debug: (4)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:48:43 2015 : Debug: (4)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:48:43 2015 : Debug: (4)   Acct-Session-Id = '54ECEF48-00000185'
Fri Feb 27 11:48:43 2015 : Debug: (4)   Framed-MTU = 1400
Fri Feb 27 11:48:43 2015 : Debug: (4)   EAP-Message = 0x027a00901980000000861603010046100000424104803348866a6e6f8ad30a762c0bbf64bf080581fa5b07610e5322ace24522608dd8a386e022a7f9650a6d9c1272fc2113de7a534114636527b205435cc86de2d91403010001011603010030add691281c44821485829298cd46a46c7118a96d85a753
Fri Feb 27 11:48:43 2015 : Debug: (4)   State = 0x43bc3b6940c622ae11358de93389f275
Fri Feb 27 11:48:43 2015 : Debug: (4)   Message-Authenticator = 0x0b75f005e5983b11afa351d560ad76a8
Fri Feb 27 11:48:43 2015 : Debug: (4) session-state: No cached attributes
Fri Feb 27 11:48:43 2015 : Debug: (4) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:43 2015 : Debug: (4)   authorize {
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     [preprocess] = ok
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: calling chap (rlm_chap) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: returned from chap (rlm_chap) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     [chap] = noop
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: calling mschap (rlm_mschap) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     [mschap] = noop
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: calling digest (rlm_digest) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: returned from digest (rlm_digest) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     [digest] = noop
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: calling suffix (rlm_realm) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:43 2015 : Debug: (4) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:43 2015 : Debug: (4) suffix: No such realm "NULL"
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: returned from suffix (rlm_realm) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     [suffix] = noop
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: calling eap (rlm_eap) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4) eap: Peer sent code Response (2) ID 122 length 144
Fri Feb 27 11:48:43 2015 : Debug: (4) eap: Continuing tunnel setup
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authorize]: returned from eap (rlm_eap) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     [eap] = ok
Fri Feb 27 11:48:43 2015 : Debug: (4)   } # authorize = ok
Fri Feb 27 11:48:43 2015 : Debug: (4) Found Auth-Type = EAP
Fri Feb 27 11:48:43 2015 : Debug: (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:43 2015 : Debug: (4)   authenticate {
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authenticate]: calling eap (rlm_eap) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4) eap: Expiring EAP session with state 0x43bc3b6940c622ae
Fri Feb 27 11:48:43 2015 : Debug: (4) eap: Finished EAP session with state 0x43bc3b6940c622ae
Fri Feb 27 11:48:43 2015 : Debug: (4) eap: Previous EAP request found for state 0x43bc3b6940c622ae, released from the list
Fri Feb 27 11:48:43 2015 : Debug: (4) eap: Peer sent method PEAP (25)
Fri Feb 27 11:48:43 2015 : Debug: (4) eap: EAP PEAP (25)
Fri Feb 27 11:48:43 2015 : Debug: (4) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: processing EAP-TLS
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: TLS Length 134
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: Length Included
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: eaptls_verify returned 11
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: TLS_accept: SSLv3 read client key exchange A
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: <<< TLS 1.0 ChangeCipherSpec [length 0001]
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: <<< TLS 1.0 Handshake [length 0010], Finished
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: TLS_accept: SSLv3 read finished A
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: >>> TLS 1.0 ChangeCipherSpec [length 0001]
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: TLS_accept: SSLv3 write change cipher spec A
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: >>> TLS 1.0 Handshake [length 0010], Finished
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: TLS_accept: SSLv3 write finished A
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: TLS_accept: SSLv3 flush data
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: (other): SSL negotiation finished successfully
Fri Feb 27 11:48:43 2015 : Debug: SSL Connection Established
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: eaptls_process returned 13
Fri Feb 27 11:48:43 2015 : Debug: (4) eap_peap: FR_TLS_HANDLED
Fri Feb 27 11:48:43 2015 : Debug: (4) eap: EAP session adding &reply:State = 0x43bc3b6947c722ae
Fri Feb 27 11:48:43 2015 : Debug: (4)     modsingle[authenticate]: returned from eap (rlm_eap) for request 4
Fri Feb 27 11:48:43 2015 : Debug: (4)     [eap] = handled
Fri Feb 27 11:48:43 2015 : Debug: (4)   } # authenticate = handled
Fri Feb 27 11:48:43 2015 : Debug: (4) session-state: Nothing to cache
Fri Feb 27 11:48:43 2015 : Debug: (4) Sent Access-Challenge Id 228 from 71.46.62.133:1812 to 24.94.145.173:50155 length 123
Fri Feb 27 11:48:43 2015 : Debug: (4)   EAP-Message = 0x017b004119001403010001011603010030ef4c19b55c657f8ff6c637ec72128819272aeb07655a85753dd99d6ff1b79706345e65ca8ae7c3a6ac649703f7ee3684
Fri Feb 27 11:48:43 2015 : Debug: (4)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:43 2015 : Debug: (4)   State = 0x43bc3b6947c722ae11358de93389f275
Fri Feb 27 11:48:43 2015 : Debug: (4) Finished request
Fri Feb 27 11:48:44 2015 : Debug: (5) Received Access-Request Id 229 from 24.94.145.173:50155 to 71.46.62.133:1812 length 191
Fri Feb 27 11:48:44 2015 : Debug: (5)   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (5)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:48:44 2015 : Debug: (5)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:48:44 2015 : Debug: (5)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:48:44 2015 : Debug: (5)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:48:44 2015 : Debug: (5)   NAS-Port = 0
Fri Feb 27 11:48:44 2015 : Debug: (5)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:48:44 2015 : Debug: (5)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:48:44 2015 : Debug: (5)   Acct-Session-Id = '54ECEF48-00000185'
Fri Feb 27 11:48:44 2015 : Debug: (5)   Framed-MTU = 1400
Fri Feb 27 11:48:44 2015 : Debug: (5)   EAP-Message = 0x027b00061900
Fri Feb 27 11:48:44 2015 : Debug: (5)   State = 0x43bc3b6947c722ae11358de93389f275
Fri Feb 27 11:48:44 2015 : Debug: (5)   Message-Authenticator = 0x26fbcdf393cfc34938f4cb49fc549a34
Fri Feb 27 11:48:44 2015 : Debug: (5) session-state: No cached attributes
Fri Feb 27 11:48:44 2015 : Debug: (5) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (5)   authorize {
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     [preprocess] = ok
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: calling chap (rlm_chap) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: returned from chap (rlm_chap) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     [chap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: calling mschap (rlm_mschap) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     [mschap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: calling digest (rlm_digest) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: returned from digest (rlm_digest) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     [digest] = noop
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: calling suffix (rlm_realm) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:44 2015 : Debug: (5) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:44 2015 : Debug: (5) suffix: No such realm "NULL"
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: returned from suffix (rlm_realm) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     [suffix] = noop
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: calling eap (rlm_eap) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5) eap: Peer sent code Response (2) ID 123 length 6
Fri Feb 27 11:48:44 2015 : Debug: (5) eap: Continuing tunnel setup
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authorize]: returned from eap (rlm_eap) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     [eap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (5)   } # authorize = ok
Fri Feb 27 11:48:44 2015 : Debug: (5) Found Auth-Type = EAP
Fri Feb 27 11:48:44 2015 : Debug: (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (5)   authenticate {
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authenticate]: calling eap (rlm_eap) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5) eap: Expiring EAP session with state 0x43bc3b6947c722ae
Fri Feb 27 11:48:44 2015 : Debug: (5) eap: Finished EAP session with state 0x43bc3b6947c722ae
Fri Feb 27 11:48:44 2015 : Debug: (5) eap: Previous EAP request found for state 0x43bc3b6947c722ae, released from the list
Fri Feb 27 11:48:44 2015 : Debug: (5) eap: Peer sent method PEAP (25)
Fri Feb 27 11:48:44 2015 : Debug: (5) eap: EAP PEAP (25)
Fri Feb 27 11:48:44 2015 : Debug: (5) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:48:44 2015 : Debug: (5) eap_peap: processing EAP-TLS
Fri Feb 27 11:48:44 2015 : Debug: (5) eap_peap: Received TLS ACK
Fri Feb 27 11:48:44 2015 : Debug: (5) eap_peap: Received TLS ACK
Fri Feb 27 11:48:44 2015 : Debug: (5) eap_peap: ACK handshake is finished
Fri Feb 27 11:48:44 2015 : Debug: (5) eap_peap: eaptls_verify returned 3
Fri Feb 27 11:48:44 2015 : Debug: (5) eap_peap: eaptls_process returned 3
Fri Feb 27 11:48:44 2015 : Debug: (5) eap_peap: FR_TLS_SUCCESS
Fri Feb 27 11:48:44 2015 : Debug: (5) eap_peap: Session established.  Decoding tunneled attributes
Fri Feb 27 11:48:44 2015 : Debug: (5) eap_peap: PEAP state TUNNEL ESTABLISHED
Fri Feb 27 11:48:44 2015 : Debug: (5) eap: EAP session adding &reply:State = 0x43bc3b6946c022ae
Fri Feb 27 11:48:44 2015 : Debug: (5)     modsingle[authenticate]: returned from eap (rlm_eap) for request 5
Fri Feb 27 11:48:44 2015 : Debug: (5)     [eap] = handled
Fri Feb 27 11:48:44 2015 : Debug: (5)   } # authenticate = handled
Fri Feb 27 11:48:44 2015 : Debug: (5) session-state: Nothing to cache
Fri Feb 27 11:48:44 2015 : Debug: (5) Sent Access-Challenge Id 229 from 71.46.62.133:1812 to 24.94.145.173:50155 length 101
Fri Feb 27 11:48:44 2015 : Debug: (5)   EAP-Message = 0x017c002b1900170301002007afa2959ac5a35ab7be1c21e6e25a0d6413eaf0677db7d0fe19697e5f250723
Fri Feb 27 11:48:44 2015 : Debug: (5)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (5)   State = 0x43bc3b6946c022ae11358de93389f275
Fri Feb 27 11:48:44 2015 : Debug: (5) Finished request
Fri Feb 27 11:48:44 2015 : Debug: (6) Received Access-Request Id 230 from 24.94.145.173:50155 to 71.46.62.133:1812 length 265
Fri Feb 27 11:48:44 2015 : Debug: (6)   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (6)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:48:44 2015 : Debug: (6)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:48:44 2015 : Debug: (6)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:48:44 2015 : Debug: (6)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:48:44 2015 : Debug: (6)   NAS-Port = 0
Fri Feb 27 11:48:44 2015 : Debug: (6)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:48:44 2015 : Debug: (6)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:48:44 2015 : Debug: (6)   Acct-Session-Id = '54ECEF48-00000185'
Fri Feb 27 11:48:44 2015 : Debug: (6)   Framed-MTU = 1400
Fri Feb 27 11:48:44 2015 : Debug: (6)   EAP-Message = 0x027c0050190017030100204c14e44d14e786f23214914585acb1ff7210b2b406f0494d90b6bcb8bf089b6c17030100204d7cb98434e7e3b344376e1f72e94ba3feaff899d19fb679385e7b238feeaaed
Fri Feb 27 11:48:44 2015 : Debug: (6)   State = 0x43bc3b6946c022ae11358de93389f275
Fri Feb 27 11:48:44 2015 : Debug: (6)   Message-Authenticator = 0xc8f4975baf27b73352f6bd5e238706b5
Fri Feb 27 11:48:44 2015 : Debug: (6) session-state: No cached attributes
Fri Feb 27 11:48:44 2015 : Debug: (6) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (6)   authorize {
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     [preprocess] = ok
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: calling chap (rlm_chap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: returned from chap (rlm_chap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     [chap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: calling mschap (rlm_mschap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     [mschap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: calling digest (rlm_digest) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: returned from digest (rlm_digest) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     [digest] = noop
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: calling suffix (rlm_realm) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:44 2015 : Debug: (6) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:44 2015 : Debug: (6) suffix: No such realm "NULL"
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: returned from suffix (rlm_realm) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     [suffix] = noop
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: calling eap (rlm_eap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: Peer sent code Response (2) ID 124 length 80
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: Continuing tunnel setup
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authorize]: returned from eap (rlm_eap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     [eap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (6)   } # authorize = ok
Fri Feb 27 11:48:44 2015 : Debug: (6) Found Auth-Type = EAP
Fri Feb 27 11:48:44 2015 : Debug: (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (6)   authenticate {
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authenticate]: calling eap (rlm_eap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: Expiring EAP session with state 0x43bc3b6946c022ae
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: Finished EAP session with state 0x43bc3b6946c022ae
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: Previous EAP request found for state 0x43bc3b6946c022ae, released from the list
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: Peer sent method PEAP (25)
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: EAP PEAP (25)
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: processing EAP-TLS
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: eaptls_verify returned 7
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Done initial handshake
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: eaptls_process returned 7
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: FR_TLS_OK
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Session established.  Decoding tunneled attributes
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: PEAP state WAITING FOR INNER IDENTITY
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Identity - qaresdon
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Got inner identity 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Setting default EAP type for tunneled EAP session
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Got tunneled request
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap:   EAP-Message = 0x027c000d017161726573646f6e
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Setting User-Name to qaresdon
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Sending tunneled request to inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap:   EAP-Message = 0x027c000d017161726573646f6e
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap:   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap:   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (6) Virtual server received request
Fri Feb 27 11:48:44 2015 : Debug: (6)   EAP-Message = 0x027c000d017161726573646f6e
Fri Feb 27 11:48:44 2015 : Debug: (6)   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Feb 27 11:48:44 2015 : Debug: (6)   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (6) server inner-tunnel {
Fri Feb 27 11:48:44 2015 : Debug: (6)   session-state: No State attribute
Fri Feb 27 11:48:44 2015 : Debug: (6)   # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (6)     authorize {
Fri Feb 27 11:48:44 2015 : Debug: (6)       modsingle[authorize]: calling suffix (rlm_realm) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:44 2015 : Debug: (6) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:44 2015 : Debug: (6) suffix: No such realm "NULL"
Fri Feb 27 11:48:44 2015 : Debug: (6)       modsingle[authorize]: returned from suffix (rlm_realm) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)       [suffix] = noop
Fri Feb 27 11:48:44 2015 : Debug: (6)       update control {
Fri Feb 27 11:48:44 2015 : Debug: (6)         &Proxy-To-Realm := 'LOCAL'
Fri Feb 27 11:48:44 2015 : Debug: (6)       } # update control = noop
Fri Feb 27 11:48:44 2015 : Debug: (6)       modsingle[authorize]: calling files (rlm_files) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)       modsingle[authorize]: returned from files (rlm_files) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)       [files] = noop
Fri Feb 27 11:48:44 2015 : Debug: (6)       update control {
Fri Feb 27 11:48:44 2015 : Debug: (6)         Cache-Status-Only = yes
Fri Feb 27 11:48:44 2015 : Debug: (6)       } # update control = noop
Fri Feb 27 11:48:44 2015 : Debug: (6)       modsingle[authorize]: calling cache (rlm_cache) for request 6
Fri Feb 27 11:48:44 2015 : Debug: %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: attribute --> User-Name
Fri Feb 27 11:48:44 2015 : Debug: attribute --> Calling-Station-Id
Fri Feb 27 11:48:44 2015 : Debug: (6) cache: EXPAND %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:48:44 2015 : Debug: (6) cache:    --> qaresdone899c47233d8
Fri Feb 27 11:48:44 2015 : Debug: (6) cache: Mutex acquired
Fri Feb 27 11:48:44 2015 : Debug: (6) cache: No cache entry found for "qaresdone899c47233d8"
Fri Feb 27 11:48:44 2015 : Debug: (6) cache: Mutex released
Fri Feb 27 11:48:44 2015 : Debug: (6)       modsingle[authorize]: returned from cache (rlm_cache) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)       [cache] = notfound
Fri Feb 27 11:48:44 2015 : Debug: (6)       if (notfound) {
Fri Feb 27 11:48:44 2015 : Debug: (6)       if (notfound)  -> TRUE
Fri Feb 27 11:48:44 2015 : Debug: (6)       if (notfound)  {
Fri Feb 27 11:48:44 2015 : Debug: (6)         modsingle[authorize]: calling ldap (rlm_ldap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: rlm_ldap (ldap): Reserved connection (4)
Fri Feb 27 11:48:44 2015 : Debug: (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: literal --> (uid=
Fri Feb 27 11:48:44 2015 : Debug: if {
Fri Feb 27 11:48:44 2015 : Debug:       attribute --> Stripped-User-Name
Fri Feb 27 11:48:44 2015 : Debug: }
Fri Feb 27 11:48:44 2015 : Debug: else {
Fri Feb 27 11:48:44 2015 : Debug:       attribute --> User-Name
Fri Feb 27 11:48:44 2015 : Debug: }
Fri Feb 27 11:48:44 2015 : Debug: literal --> )
Fri Feb 27 11:48:44 2015 : Debug: (6) ldap: EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri Feb 27 11:48:44 2015 : Debug: (6) ldap:    --> (uid=qaresdon)
Fri Feb 27 11:48:44 2015 : Debug: ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: literal --> ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: (6) ldap: EXPAND ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: (6) ldap:    --> ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: (6) ldap: Performing search in 'ou=Customers,dc=brighthouse,dc=com' with filter '(uid=qaresdon)', scope 'sub'
Fri Feb 27 11:48:44 2015 : Debug: (6) ldap: Waiting for search result...
Fri Feb 27 11:48:44 2015 : Debug: (6) ldap: User object found at DN "rrCustomerID=A6398B1D-9057-4873-B13F-E41B1808B52A,ou=18,ou=Customers,dc=brighthouse,dc=com"
Fri Feb 27 11:48:44 2015 : Debug: (6) ldap: Added eDirectory password.  control:Cleartext-Password += 'xxxxxxxxx'
Fri Feb 27 11:48:44 2015 : Debug: rlm_ldap (ldap): Released connection (4)
Fri Feb 27 11:48:44 2015 : Debug: (6)         modsingle[authorize]: returned from ldap (rlm_ldap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)         [ldap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (6)       } # if (notfound)  = ok
Fri Feb 27 11:48:44 2015 : Debug: (6)       ... skipping else for request 6: Preceding "if" was taken
Fri Feb 27 11:48:44 2015 : Debug: (6)       modsingle[authorize]: calling eap (rlm_eap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: Peer sent code Response (2) ID 124 length 13
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Fri Feb 27 11:48:44 2015 : Debug: (6)       modsingle[authorize]: returned from eap (rlm_eap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)       [eap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (6)     } # authorize = ok
Fri Feb 27 11:48:44 2015 : Debug: (6)   Found Auth-Type = EAP
Fri Feb 27 11:48:44 2015 : Debug: (6)   # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (6)     authenticate {
Fri Feb 27 11:48:44 2015 : Debug: (6)       modsingle[authenticate]: calling eap (rlm_eap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: Peer sent method Identity (1)
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: Calling eap_mschapv2 to process EAP data
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_mschapv2: Issuing Challenge
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: EAP session adding &reply:State = 0x6b88392f6bf52321
Fri Feb 27 11:48:44 2015 : Debug: (6)       modsingle[authenticate]: returned from eap (rlm_eap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)       [eap] = handled
Fri Feb 27 11:48:44 2015 : Debug: (6)     } # authenticate = handled
Fri Feb 27 11:48:44 2015 : Debug: (6)   session-state: Nothing to cache
Fri Feb 27 11:48:44 2015 : Debug: (6) } # server inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (6) Virtual server sending reply
Fri Feb 27 11:48:44 2015 : Debug: (6)   EAP-Message = 0x017d00221a017d001d10fbfbbf8ba4b1db205dcc5219e907e91f7161726573646f6e
Fri Feb 27 11:48:44 2015 : Debug: (6)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (6)   State = 0x6b88392f6bf5232156f28677d6cf42f4
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Got tunneled reply code 11
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap:   EAP-Message = 0x017d00221a017d001d10fbfbbf8ba4b1db205dcc5219e907e91f7161726573646f6e
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap:   State = 0x6b88392f6bf5232156f28677d6cf42f4
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Got tunneled reply RADIUS code 11
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap:   EAP-Message = 0x017d00221a017d001d10fbfbbf8ba4b1db205dcc5219e907e91f7161726573646f6e
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap:   State = 0x6b88392f6bf5232156f28677d6cf42f4
Fri Feb 27 11:48:44 2015 : Debug: (6) eap_peap: Got tunneled Access-Challenge
Fri Feb 27 11:48:44 2015 : Debug: (6) eap: EAP session adding &reply:State = 0x43bc3b6945c122ae
Fri Feb 27 11:48:44 2015 : Debug: (6)     modsingle[authenticate]: returned from eap (rlm_eap) for request 6
Fri Feb 27 11:48:44 2015 : Debug: (6)     [eap] = handled
Fri Feb 27 11:48:44 2015 : Debug: (6)   } # authenticate = handled
Fri Feb 27 11:48:44 2015 : Debug: (6) session-state: Nothing to cache
Fri Feb 27 11:48:44 2015 : Debug: (6) Sent Access-Challenge Id 230 from 71.46.62.133:1812 to 24.94.145.173:50155 length 133
Fri Feb 27 11:48:44 2015 : Debug: (6)   EAP-Message = 0x017d004b190017030100403dcc9aa3a1008804f371755d196e3ee3506abdd0a53d8ba83fb250e40f9cfde61b5591c899ff06286cc78c1be57fb3e0fded46cb3dc961d2ab1fe7466a171b46
Fri Feb 27 11:48:44 2015 : Debug: (6)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (6)   State = 0x43bc3b6945c122ae11358de93389f275
Fri Feb 27 11:48:44 2015 : Debug: (6) Finished request
Fri Feb 27 11:48:44 2015 : Debug: Waking up in 0.1 seconds.
Fri Feb 27 11:48:44 2015 : Debug: (7) Received Access-Request Id 231 from 24.94.145.173:50155 to 71.46.62.133:1812 length 329
Fri Feb 27 11:48:44 2015 : Debug: (7)   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (7)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:48:44 2015 : Debug: (7)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:48:44 2015 : Debug: (7)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:48:44 2015 : Debug: (7)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:48:44 2015 : Debug: (7)   NAS-Port = 0
Fri Feb 27 11:48:44 2015 : Debug: (7)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:48:44 2015 : Debug: (7)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:48:44 2015 : Debug: (7)   Acct-Session-Id = '54ECEF48-00000185'
Fri Feb 27 11:48:44 2015 : Debug: (7)   Framed-MTU = 1400
Fri Feb 27 11:48:44 2015 : Debug: (7)   EAP-Message = 0x027d00901900170301002028b62386607152c2ee4e621bbbe67318a10319d55f50790b823ade126586647317030100606c0b54a6dbec65d6f822482e20fa62f3a00532a86daa88d7c607fbfb16b7337d01b2277c026dda0cdcd1898e0dd01fc6df09786f9daff0d5f6945feb2252b0968995a8d7d21f95
Fri Feb 27 11:48:44 2015 : Debug: (7)   State = 0x43bc3b6945c122ae11358de93389f275
Fri Feb 27 11:48:44 2015 : Debug: (7)   Message-Authenticator = 0x7545a7d9ea81e6116bbbbd401a5b6537
Fri Feb 27 11:48:44 2015 : Debug: (7) session-state: No cached attributes
Fri Feb 27 11:48:44 2015 : Debug: (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (7)   authorize {
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     [preprocess] = ok
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: calling chap (rlm_chap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: returned from chap (rlm_chap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     [chap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: calling mschap (rlm_mschap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     [mschap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: calling digest (rlm_digest) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: returned from digest (rlm_digest) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     [digest] = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: calling suffix (rlm_realm) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:44 2015 : Debug: (7) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:44 2015 : Debug: (7) suffix: No such realm "NULL"
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: returned from suffix (rlm_realm) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     [suffix] = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: calling eap (rlm_eap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Peer sent code Response (2) ID 125 length 144
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Continuing tunnel setup
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authorize]: returned from eap (rlm_eap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     [eap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (7)   } # authorize = ok
Fri Feb 27 11:48:44 2015 : Debug: (7) Found Auth-Type = EAP
Fri Feb 27 11:48:44 2015 : Debug: (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (7)   authenticate {
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authenticate]: calling eap (rlm_eap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Expiring EAP session with state 0x6b88392f6bf52321
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Finished EAP session with state 0x43bc3b6945c122ae
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Previous EAP request found for state 0x43bc3b6945c122ae, released from the list
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Peer sent method PEAP (25)
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: EAP PEAP (25)
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: processing EAP-TLS
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: eaptls_verify returned 7
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: Done initial handshake
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: eaptls_process returned 7
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: FR_TLS_OK
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: Session established.  Decoding tunneled attributes
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: PEAP state phase2
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: EAP type MSCHAPv2 (26)
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: Got tunneled request
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   EAP-Message = 0x027d00431a027d003e31e9285a78d42e3a93726ee1bbf6e3535f00000000000000001bc3e5cd456bb9130ca8c059f9b20edc266084fd17d2fc35007161726573646f6e
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: Setting User-Name to qaresdon
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: Sending tunneled request to inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   EAP-Message = 0x027d00431a027d003e31e9285a78d42e3a93726ee1bbf6e3535f00000000000000001bc3e5cd456bb9130ca8c059f9b20edc266084fd17d2fc35007161726573646f6e
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   State = 0x6b88392f6bf5232156f28677d6cf42f4
Fri Feb 27 11:48:44 2015 : Debug: (7) Virtual server received request
Fri Feb 27 11:48:44 2015 : Debug: (7)   EAP-Message = 0x027d00431a027d003e31e9285a78d42e3a93726ee1bbf6e3535f00000000000000001bc3e5cd456bb9130ca8c059f9b20edc266084fd17d2fc35007161726573646f6e
Fri Feb 27 11:48:44 2015 : Debug: (7)   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Feb 27 11:48:44 2015 : Debug: (7)   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (7)   State = 0x6b88392f6bf5232156f28677d6cf42f4
Fri Feb 27 11:48:44 2015 : Debug: (7) server inner-tunnel {
Fri Feb 27 11:48:44 2015 : Debug: (7)   session-state: No cached attributes
Fri Feb 27 11:48:44 2015 : Debug: (7)   # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (7)     authorize {
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: calling suffix (rlm_realm) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:44 2015 : Debug: (7) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:44 2015 : Debug: (7) suffix: No such realm "NULL"
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: returned from suffix (rlm_realm) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       [suffix] = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)       update control {
Fri Feb 27 11:48:44 2015 : Debug: (7)         &Proxy-To-Realm := 'LOCAL'
Fri Feb 27 11:48:44 2015 : Debug: (7)       } # update control = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: calling files (rlm_files) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: returned from files (rlm_files) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       [files] = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)       update control {
Fri Feb 27 11:48:44 2015 : Debug: (7)         Cache-Status-Only = yes
Fri Feb 27 11:48:44 2015 : Debug: (7)       } # update control = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: calling cache (rlm_cache) for request 7
Fri Feb 27 11:48:44 2015 : Debug: %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: attribute --> User-Name
Fri Feb 27 11:48:44 2015 : Debug: attribute --> Calling-Station-Id
Fri Feb 27 11:48:44 2015 : Debug: (7) cache: EXPAND %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:48:44 2015 : Debug: (7) cache:    --> qaresdone899c47233d8
Fri Feb 27 11:48:44 2015 : Debug: (7) cache: Mutex acquired
Fri Feb 27 11:48:44 2015 : Debug: (7) cache: No cache entry found for "qaresdone899c47233d8"
Fri Feb 27 11:48:44 2015 : Debug: (7) cache: Mutex released
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: returned from cache (rlm_cache) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       [cache] = notfound
Fri Feb 27 11:48:44 2015 : Debug: (7)       if (notfound) {
Fri Feb 27 11:48:44 2015 : Debug: (7)       if (notfound)  -> TRUE
Fri Feb 27 11:48:44 2015 : Debug: (7)       if (notfound)  {
Fri Feb 27 11:48:44 2015 : Debug: (7)         modsingle[authorize]: calling ldap (rlm_ldap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: rlm_ldap (ldap): Reserved connection (4)
Fri Feb 27 11:48:44 2015 : Debug: (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: literal --> (uid=
Fri Feb 27 11:48:44 2015 : Debug: if {
Fri Feb 27 11:48:44 2015 : Debug:       attribute --> Stripped-User-Name
Fri Feb 27 11:48:44 2015 : Debug: }
Fri Feb 27 11:48:44 2015 : Debug: else {
Fri Feb 27 11:48:44 2015 : Debug:       attribute --> User-Name
Fri Feb 27 11:48:44 2015 : Debug: }
Fri Feb 27 11:48:44 2015 : Debug: literal --> )
Fri Feb 27 11:48:44 2015 : Debug: (7) ldap: EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri Feb 27 11:48:44 2015 : Debug: (7) ldap:    --> (uid=qaresdon)
Fri Feb 27 11:48:44 2015 : Debug: ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: literal --> ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: (7) ldap: EXPAND ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: (7) ldap:    --> ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: (7) ldap: Performing search in 'ou=Customers,dc=brighthouse,dc=com' with filter '(uid=qaresdon)', scope 'sub'
Fri Feb 27 11:48:44 2015 : Debug: (7) ldap: Waiting for search result...
Fri Feb 27 11:48:44 2015 : Debug: (7) ldap: User object found at DN "rrCustomerID=A6398B1D-9057-4873-B13F-E41B1808B52A,ou=18,ou=Customers,dc=brighthouse,dc=com"
Fri Feb 27 11:48:44 2015 : Debug: (7) ldap: Added eDirectory password.  control:Cleartext-Password += xxxxxxxxx'
Fri Feb 27 11:48:44 2015 : Debug: rlm_ldap (ldap): Released connection (4)
Fri Feb 27 11:48:44 2015 : Debug: (7)         modsingle[authorize]: returned from ldap (rlm_ldap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)         [ldap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (7)       } # if (notfound)  = ok
Fri Feb 27 11:48:44 2015 : Debug: (7)       ... skipping else for request 7: Preceding "if" was taken
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: calling eap (rlm_eap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Peer sent code Response (2) ID 125 length 67
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: No EAP Start, assuming it's an on-going EAP conversation
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: returned from eap (rlm_eap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       [eap] = updated
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: calling mschap (rlm_mschap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: returned from mschap (rlm_mschap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       [mschap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: calling expiration (rlm_expiration) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: returned from expiration (rlm_expiration) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       [expiration] = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: calling logintime (rlm_logintime) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authorize]: returned from logintime (rlm_logintime) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       [logintime] = noop
Fri Feb 27 11:48:44 2015 : Debug: (7)     } # authorize = updated
Fri Feb 27 11:48:44 2015 : Debug: (7)   Found Auth-Type = EAP
Fri Feb 27 11:48:44 2015 : Debug: (7)   # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (7)     authenticate {
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authenticate]: calling eap (rlm_eap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Expiring EAP session with state 0x6b88392f6bf52321
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Finished EAP session with state 0x6b88392f6bf52321
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Previous EAP request found for state 0x6b88392f6bf52321, released from the list
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Peer sent method MSCHAPv2 (26)
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: EAP MSCHAPv2 (26)
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: Calling eap_mschapv2 to process EAP data
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_mschapv2: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_mschapv2:   Auth-Type MS-CHAP {
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_mschapv2:     modsingle[authenticate]: calling mschap (rlm_mschap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7) mschap: Found Cleartext-Password, hashing to create NT-Password
Fri Feb 27 11:48:44 2015 : Debug: (7) mschap: Found Cleartext-Password, hashing to create LM-Password
Fri Feb 27 11:48:44 2015 : Debug: (7) mschap: Creating challenge hash with username: qaresdon
Fri Feb 27 11:48:44 2015 : Debug: (7) mschap: Client is using MS-CHAPv2
Fri Feb 27 11:48:44 2015 : Debug: (7) mschap: Adding MS-CHAPv2 MPPE keys
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authenticate]: returned from mschap (rlm_mschap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     [mschap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (7)   } # Auth-Type MS-CHAP = ok
Fri Feb 27 11:48:44 2015 : Debug: MSCHAP Success
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: EAP session adding &reply:State = 0x6b88392f6af62321
Fri Feb 27 11:48:44 2015 : Debug: (7)       modsingle[authenticate]: returned from eap (rlm_eap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)       [eap] = handled
Fri Feb 27 11:48:44 2015 : Debug: (7)     } # authenticate = handled
Fri Feb 27 11:48:44 2015 : Debug: (7)   session-state: Nothing to cache
Fri Feb 27 11:48:44 2015 : Debug: (7) } # server inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (7) Virtual server sending reply
Fri Feb 27 11:48:44 2015 : Debug: (7)   EAP-Message = 0x017e00331a037d002e533d35414646464342363839433035393834453941344330454241343939354442343842303746423330
Fri Feb 27 11:48:44 2015 : Debug: (7)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (7)   State = 0x6b88392f6af6232156f28677d6cf42f4
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: Got tunneled reply code 11
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   EAP-Message = 0x017e00331a037d002e533d35414646464342363839433035393834453941344330454241343939354442343842303746423330
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   State = 0x6b88392f6af6232156f28677d6cf42f4
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: Got tunneled reply RADIUS code 11
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   EAP-Message = 0x017e00331a037d002e533d35414646464342363839433035393834453941344330454241343939354442343842303746423330
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap:   State = 0x6b88392f6af6232156f28677d6cf42f4
Fri Feb 27 11:48:44 2015 : Debug: (7) eap_peap: Got tunneled Access-Challenge
Fri Feb 27 11:48:44 2015 : Debug: (7) eap: EAP session adding &reply:State = 0x43bc3b6944c222ae
Fri Feb 27 11:48:44 2015 : Debug: (7)     modsingle[authenticate]: returned from eap (rlm_eap) for request 7
Fri Feb 27 11:48:44 2015 : Debug: (7)     [eap] = handled
Fri Feb 27 11:48:44 2015 : Debug: (7)   } # authenticate = handled
Fri Feb 27 11:48:44 2015 : Debug: (7) session-state: Nothing to cache
Fri Feb 27 11:48:44 2015 : Debug: (7) Sent Access-Challenge Id 231 from 71.46.62.133:1812 to 24.94.145.173:50155 length 149
Fri Feb 27 11:48:44 2015 : Debug: (7)   EAP-Message = 0x017e005b190017030100506f8c0fad2c150493f6f8f759190e77949efcaf4d1eb9491b591127034df269b255fb7607e16850bb9aea522c4c27833281217b4d32d2b3adf6f93b0be1da43add5ee8762da31eaa872c6dc0f32282b8a
Fri Feb 27 11:48:44 2015 : Debug: (7)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (7)   State = 0x43bc3b6944c222ae11358de93389f275
Fri Feb 27 11:48:44 2015 : Debug: (7) Finished request
Fri Feb 27 11:48:44 2015 : Debug: (8) Received Access-Request Id 232 from 24.94.145.173:50155 to 71.46.62.133:1812 length 265
Fri Feb 27 11:48:44 2015 : Debug: (8)   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (8)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:48:44 2015 : Debug: (8)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:48:44 2015 : Debug: (8)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:48:44 2015 : Debug: (8)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:48:44 2015 : Debug: (8)   NAS-Port = 0
Fri Feb 27 11:48:44 2015 : Debug: (8)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:48:44 2015 : Debug: (8)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:48:44 2015 : Debug: (8)   Acct-Session-Id = '54ECEF48-00000185'
Fri Feb 27 11:48:44 2015 : Debug: (8)   Framed-MTU = 1400
Fri Feb 27 11:48:44 2015 : Debug: (8)   EAP-Message = 0x027e005019001703010020a950bd75dc6307af1141c1662042728c039dbdb7a3f447e708efdaf6a9d4e27a1703010020d2a93caa71b032db036e214d9e1bb7cbd0f0ea7a13d755f73534e81ca4895dd5
Fri Feb 27 11:48:44 2015 : Debug: (8)   State = 0x43bc3b6944c222ae11358de93389f275
Fri Feb 27 11:48:44 2015 : Debug: (8)   Message-Authenticator = 0x338b376fcc47f2c2c65739ee6043e0f3
Fri Feb 27 11:48:44 2015 : Debug: (8) session-state: No cached attributes
Fri Feb 27 11:48:44 2015 : Debug: (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (8)   authorize {
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     [preprocess] = ok
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: calling chap (rlm_chap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: returned from chap (rlm_chap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     [chap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: calling mschap (rlm_mschap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     [mschap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: calling digest (rlm_digest) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: returned from digest (rlm_digest) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     [digest] = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: calling suffix (rlm_realm) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:44 2015 : Debug: (8) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:44 2015 : Debug: (8) suffix: No such realm "NULL"
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: returned from suffix (rlm_realm) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     [suffix] = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: calling eap (rlm_eap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Peer sent code Response (2) ID 126 length 80
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Continuing tunnel setup
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authorize]: returned from eap (rlm_eap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     [eap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (8)   } # authorize = ok
Fri Feb 27 11:48:44 2015 : Debug: (8) Found Auth-Type = EAP
Fri Feb 27 11:48:44 2015 : Debug: (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (8)   authenticate {
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authenticate]: calling eap (rlm_eap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Expiring EAP session with state 0x6b88392f6af62321
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Finished EAP session with state 0x43bc3b6944c222ae
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Previous EAP request found for state 0x43bc3b6944c222ae, released from the list
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Peer sent method PEAP (25)
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: EAP PEAP (25)
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: processing EAP-TLS
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: eaptls_verify returned 7
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: Done initial handshake
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: eaptls_process returned 7
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: FR_TLS_OK
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: Session established.  Decoding tunneled attributes
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: PEAP state phase2
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: EAP type MSCHAPv2 (26)
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: Got tunneled request
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   EAP-Message = 0x027e00061a03
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: Setting User-Name to qaresdon
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: Sending tunneled request to inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   EAP-Message = 0x027e00061a03
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   State = 0x6b88392f6af6232156f28677d6cf42f4
Fri Feb 27 11:48:44 2015 : Debug: (8) Virtual server received request
Fri Feb 27 11:48:44 2015 : Debug: (8)   EAP-Message = 0x027e00061a03
Fri Feb 27 11:48:44 2015 : Debug: (8)   FreeRADIUS-Proxied-To = 127.0.0.1
Fri Feb 27 11:48:44 2015 : Debug: (8)   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (8)   State = 0x6b88392f6af6232156f28677d6cf42f4
Fri Feb 27 11:48:44 2015 : Debug: (8) server inner-tunnel {
Fri Feb 27 11:48:44 2015 : Debug: (8)   session-state: No cached attributes
Fri Feb 27 11:48:44 2015 : Debug: (8)   # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (8)     authorize {
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: calling suffix (rlm_realm) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:44 2015 : Debug: (8) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:44 2015 : Debug: (8) suffix: No such realm "NULL"
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: returned from suffix (rlm_realm) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       [suffix] = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)       update control {
Fri Feb 27 11:48:44 2015 : Debug: (8)         &Proxy-To-Realm := 'LOCAL'
Fri Feb 27 11:48:44 2015 : Debug: (8)       } # update control = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: calling files (rlm_files) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: returned from files (rlm_files) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       [files] = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)       update control {
Fri Feb 27 11:48:44 2015 : Debug: (8)         Cache-Status-Only = yes
Fri Feb 27 11:48:44 2015 : Debug: (8)       } # update control = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: calling cache (rlm_cache) for request 8
Fri Feb 27 11:48:44 2015 : Debug: %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: attribute --> User-Name
Fri Feb 27 11:48:44 2015 : Debug: attribute --> Calling-Station-Id
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: EXPAND %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:48:44 2015 : Debug: (8) cache:    --> qaresdone899c47233d8
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: Mutex acquired
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: No cache entry found for "qaresdone899c47233d8"
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: Mutex released
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: returned from cache (rlm_cache) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       [cache] = notfound
Fri Feb 27 11:48:44 2015 : Debug: (8)       if (notfound) {
Fri Feb 27 11:48:44 2015 : Debug: (8)       if (notfound)  -> TRUE
Fri Feb 27 11:48:44 2015 : Debug: (8)       if (notfound)  {
Fri Feb 27 11:48:44 2015 : Debug: (8)         modsingle[authorize]: calling ldap (rlm_ldap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: rlm_ldap (ldap): Reserved connection (4)
Fri Feb 27 11:48:44 2015 : Debug: (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: literal --> (uid=
Fri Feb 27 11:48:44 2015 : Debug: if {
Fri Feb 27 11:48:44 2015 : Debug:       attribute --> Stripped-User-Name
Fri Feb 27 11:48:44 2015 : Debug: }
Fri Feb 27 11:48:44 2015 : Debug: else {
Fri Feb 27 11:48:44 2015 : Debug:       attribute --> User-Name
Fri Feb 27 11:48:44 2015 : Debug: }
Fri Feb 27 11:48:44 2015 : Debug: literal --> )
Fri Feb 27 11:48:44 2015 : Debug: (8) ldap: EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri Feb 27 11:48:44 2015 : Debug: (8) ldap:    --> (uid=qaresdon)
Fri Feb 27 11:48:44 2015 : Debug: ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: literal --> ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: (8) ldap: EXPAND ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: (8) ldap:    --> ou=Customers,dc=brighthouse,dc=com
Fri Feb 27 11:48:44 2015 : Debug: (8) ldap: Performing search in 'ou=Customers,dc=brighthouse,dc=com' with filter '(uid=qaresdon)', scope 'sub'
Fri Feb 27 11:48:44 2015 : Debug: (8) ldap: Waiting for search result...
Fri Feb 27 11:48:44 2015 : Debug: (8) ldap: User object found at DN "rrCustomerID=A6398B1D-9057-4873-B13F-E41B1808B52A,ou=18,ou=Customers,dc=brighthouse,dc=com"
Fri Feb 27 11:48:44 2015 : Debug: (8) ldap: Added eDirectory password.  control:Cleartext-Password += 'xxxxxxxxx'
Fri Feb 27 11:48:44 2015 : Debug: rlm_ldap (ldap): Released connection (4)
Fri Feb 27 11:48:44 2015 : Debug: (8)         modsingle[authorize]: returned from ldap (rlm_ldap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)         [ldap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (8)       } # if (notfound)  = ok
Fri Feb 27 11:48:44 2015 : Debug: (8)       ... skipping else for request 8: Preceding "if" was taken
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: calling eap (rlm_eap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Peer sent code Response (2) ID 126 length 6
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: No EAP Start, assuming it's an on-going EAP conversation
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: returned from eap (rlm_eap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       [eap] = updated
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: calling mschap (rlm_mschap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: returned from mschap (rlm_mschap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       [mschap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: calling expiration (rlm_expiration) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: returned from expiration (rlm_expiration) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       [expiration] = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: calling logintime (rlm_logintime) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authorize]: returned from logintime (rlm_logintime) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       [logintime] = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)     } # authorize = updated
Fri Feb 27 11:48:44 2015 : Debug: (8)   Found Auth-Type = EAP
Fri Feb 27 11:48:44 2015 : Debug: (8)   # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (8)     authenticate {
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authenticate]: calling eap (rlm_eap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Expiring EAP session with state 0x6b88392f6af62321
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Finished EAP session with state 0x6b88392f6af62321
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Previous EAP request found for state 0x6b88392f6af62321, released from the list
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Peer sent method MSCHAPv2 (26)
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: EAP MSCHAPv2 (26)
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Calling eap_mschapv2 to process EAP data
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: Freeing handler
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[authenticate]: returned from eap (rlm_eap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       [eap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (8)     } # authenticate = ok
Fri Feb 27 11:48:44 2015 : Debug: (8)   # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (8)     post-auth {
Fri Feb 27 11:48:44 2015 : Debug: (8)       policy cui-inner.post-auth {
Fri Feb 27 11:48:44 2015 : Debug: (8)         if (&outer.request:Chargeable-User-Identity &&        (&outer.request:Operator-Name || ('no' != 'yes'))) {
Fri Feb 27 11:48:44 2015 : Debug: (8)         if (&outer.request:Chargeable-User-Identity &&        (&outer.request:Operator-Name || ('no' != 'yes')))  -> FALSE
Fri Feb 27 11:48:44 2015 : Debug: (8)       } # policy cui-inner.post-auth = noop
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[post-auth]: calling cache (rlm_cache) for request 8
Fri Feb 27 11:48:44 2015 : Debug: %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: attribute --> User-Name
Fri Feb 27 11:48:44 2015 : Debug: attribute --> Calling-Station-Id
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: EXPAND %{User-Name}%{outer.request:Calling-Station-Id}
Fri Feb 27 11:48:44 2015 : Debug: (8) cache:    --> qaresdone899c47233d8
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: Mutex acquired
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: No cache entry found for "qaresdone899c47233d8"
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: Creating new cache entry
Fri Feb 27 11:48:44 2015 : Debug: %{control:NT-Password}
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: attribute --> NT-Password
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: EXPAND %{control:NT-Password}
Fri Feb 27 11:48:44 2015 : Debug: (8) cache:    -->
Fri Feb 27 11:48:44 2015 : Debug: (8) cache:   control:NT-Password := 0x
Fri Feb 27 11:48:44 2015 : Debug: %{control:LM-Password}
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: attribute --> LM-Password
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: EXPAND %{control:LM-Password}
Fri Feb 27 11:48:44 2015 : Debug: (8) cache:    -->
Fri Feb 27 11:48:44 2015 : Debug: (8) cache:   control:LM-Password := 0x
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: Merging cache entry into request
Fri Feb 27 11:48:44 2015 : Debug: (8) cache:   &control:NT-Password := 0x
Fri Feb 27 11:48:44 2015 : Debug: (8) cache:   &control:LM-Password := 0x
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: FROM 2 TO 4 MAX 6
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: Examining NT-Password
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: APPENDING NT-Password FROM 0 TO 4
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: Examining LM-Password
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: APPENDING LM-Password FROM 1 TO 5
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: TO in 4 out 6
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: to[0] = Proxy-To-Realm
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: to[1] = Ldap-UserDn
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: to[2] = Cleartext-Password
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: to[3] = Auth-Type
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: to[4] = NT-Password
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: ::: to[5] = LM-Password
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: Commited entry, TTL 86400 seconds
Fri Feb 27 11:48:44 2015 : Debug: (8) cache: Mutex released
Fri Feb 27 11:48:44 2015 : Debug: (8)       modsingle[post-auth]: returned from cache (rlm_cache) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)       [cache] = updated
Fri Feb 27 11:48:44 2015 : Debug: (8)     } # post-auth = updated
Fri Feb 27 11:48:44 2015 : Debug: (8) } # server inner-tunnel
Fri Feb 27 11:48:44 2015 : Debug: (8) Virtual server sending reply
Fri Feb 27 11:48:44 2015 : Debug: (8)   MS-MPPE-Encryption-Policy = Encryption-Required
Fri Feb 27 11:48:44 2015 : Debug: (8)   MS-MPPE-Encryption-Types = 4
Fri Feb 27 11:48:44 2015 : Debug: (8)   MS-MPPE-Send-Key = 0x82aec3d769a163ccc766fb41c013b37a
Fri Feb 27 11:48:44 2015 : Debug: (8)   MS-MPPE-Recv-Key = 0xdfe3b05c037d0adfaa6fce66ada59d8e
Fri Feb 27 11:48:44 2015 : Debug: (8)   EAP-Message = 0x037e0004
Fri Feb 27 11:48:44 2015 : Debug: (8)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (8)   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: Got tunneled reply code 2
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   MS-MPPE-Encryption-Policy = Encryption-Required
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   MS-MPPE-Encryption-Types = 4
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   MS-MPPE-Send-Key = 0x82aec3d769a163ccc766fb41c013b37a
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   MS-MPPE-Recv-Key = 0xdfe3b05c037d0adfaa6fce66ada59d8e
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   EAP-Message = 0x037e0004
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: Got tunneled reply RADIUS code 2
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   MS-MPPE-Encryption-Policy = Encryption-Required
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   MS-MPPE-Encryption-Types = 4
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   MS-MPPE-Send-Key = 0x82aec3d769a163ccc766fb41c013b37a
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   MS-MPPE-Recv-Key = 0xdfe3b05c037d0adfaa6fce66ada59d8e
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   EAP-Message = 0x037e0004
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap:   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: Tunneled authentication was successful
Fri Feb 27 11:48:44 2015 : Debug: (8) eap_peap: SUCCESS
Fri Feb 27 11:48:44 2015 : Debug: (8) eap: EAP session adding &reply:State = 0x43bc3b694bc322ae
Fri Feb 27 11:48:44 2015 : Debug: (8)     modsingle[authenticate]: returned from eap (rlm_eap) for request 8
Fri Feb 27 11:48:44 2015 : Debug: (8)     [eap] = handled
Fri Feb 27 11:48:44 2015 : Debug: (8)   } # authenticate = handled
Fri Feb 27 11:48:44 2015 : Debug: (8) session-state: Nothing to cache
Fri Feb 27 11:48:44 2015 : Debug: (8) Sent Access-Challenge Id 232 from 71.46.62.133:1812 to 24.94.145.173:50155 length 101
Fri Feb 27 11:48:44 2015 : Debug: (8)   EAP-Message = 0x017f002b1900170301002039ba24b117670330f3fa6c9fd5a5dca913596bb6c42c15d56031c60ca5f94490
Fri Feb 27 11:48:44 2015 : Debug: (8)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (8)   State = 0x43bc3b694bc322ae11358de93389f275
Fri Feb 27 11:48:44 2015 : Debug: (8) Finished request
Fri Feb 27 11:48:44 2015 : Debug: (9) Received Access-Request Id 233 from 24.94.145.173:50155 to 71.46.62.133:1812 length 265
Fri Feb 27 11:48:44 2015 : Debug: (9)   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (9)   NAS-IP-Address = 24.94.145.173
Fri Feb 27 11:48:44 2015 : Debug: (9)   NAS-Identifier = 'Ericsson'
Fri Feb 27 11:48:44 2015 : Debug: (9)   Called-Station-Id = '000d67218560:BHN_E_Secure'
Fri Feb 27 11:48:44 2015 : Debug: (9)   NAS-Port-Type = Wireless-802.11
Fri Feb 27 11:48:44 2015 : Debug: (9)   NAS-Port = 0
Fri Feb 27 11:48:44 2015 : Debug: (9)   Calling-Station-Id = 'e899c47233d8'
Fri Feb 27 11:48:44 2015 : Debug: (9)   Connect-Info = 'CONNECT 0Mbps 802.11b'
Fri Feb 27 11:48:44 2015 : Debug: (9)   Acct-Session-Id = '54ECEF48-00000185'
Fri Feb 27 11:48:44 2015 : Debug: (9)   Framed-MTU = 1400
Fri Feb 27 11:48:44 2015 : Debug: (9)   EAP-Message = 0x027f0050190017030100204a3f77e84975f8dc7a043f03dc642b872e979c5b5350f2a2d58242d5f3c474c917030100201909ec387bf04a8b2bfa1855721ba76f65efb7067508cd872b92761f51396f21
Fri Feb 27 11:48:44 2015 : Debug: (9)   State = 0x43bc3b694bc322ae11358de93389f275
Fri Feb 27 11:48:44 2015 : Debug: (9)   Message-Authenticator = 0x63dfb473113d4bc7adb4acb7e848bd2d
Fri Feb 27 11:48:44 2015 : Debug: (9) session-state: No cached attributes
Fri Feb 27 11:48:44 2015 : Debug: (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (9)   authorize {
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: calling preprocess (rlm_preprocess) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     [preprocess] = ok
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: calling chap (rlm_chap) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: returned from chap (rlm_chap) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     [chap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: calling mschap (rlm_mschap) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: returned from mschap (rlm_mschap) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     [mschap] = noop
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: calling digest (rlm_digest) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: returned from digest (rlm_digest) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     [digest] = noop
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: calling suffix (rlm_realm) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9) suffix: Checking for suffix after "@"
Fri Feb 27 11:48:44 2015 : Debug: (9) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL
Fri Feb 27 11:48:44 2015 : Debug: (9) suffix: No such realm "NULL"
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: returned from suffix (rlm_realm) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     [suffix] = noop
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: calling eap (rlm_eap) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9) eap: Peer sent code Response (2) ID 127 length 80
Fri Feb 27 11:48:44 2015 : Debug: (9) eap: Continuing tunnel setup
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authorize]: returned from eap (rlm_eap) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     [eap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (9)   } # authorize = ok
Fri Feb 27 11:48:44 2015 : Debug: (9) Found Auth-Type = EAP
Fri Feb 27 11:48:44 2015 : Debug: (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (9)   authenticate {
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authenticate]: calling eap (rlm_eap) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9) eap: Expiring EAP session with state 0x43bc3b694bc322ae
Fri Feb 27 11:48:44 2015 : Debug: (9) eap: Finished EAP session with state 0x43bc3b694bc322ae
Fri Feb 27 11:48:44 2015 : Debug: (9) eap: Previous EAP request found for state 0x43bc3b694bc322ae, released from the list
Fri Feb 27 11:48:44 2015 : Debug: (9) eap: Peer sent method PEAP (25)
Fri Feb 27 11:48:44 2015 : Debug: (9) eap: EAP PEAP (25)
Fri Feb 27 11:48:44 2015 : Debug: (9) eap: Calling eap_peap to process EAP data
Fri Feb 27 11:48:44 2015 : Debug: (9) eap_peap: processing EAP-TLS
Fri Feb 27 11:48:44 2015 : Debug: (9) eap_peap: eaptls_verify returned 7
Fri Feb 27 11:48:44 2015 : Debug: (9) eap_peap: Done initial handshake
Fri Feb 27 11:48:44 2015 : Debug: (9) eap_peap: eaptls_process returned 7
Fri Feb 27 11:48:44 2015 : Debug: (9) eap_peap: FR_TLS_OK
Fri Feb 27 11:48:44 2015 : Debug: (9) eap_peap: Session established.  Decoding tunneled attributes
Fri Feb 27 11:48:44 2015 : Debug: (9) eap_peap: PEAP state send tlv success
Fri Feb 27 11:48:44 2015 : Debug: (9) eap_peap: Received EAP-TLV response
Fri Feb 27 11:48:44 2015 : Debug: (9) eap_peap: Success
Fri Feb 27 11:48:44 2015 : Debug: (9) eap: Freeing handler
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[authenticate]: returned from eap (rlm_eap) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     [eap] = ok
Fri Feb 27 11:48:44 2015 : Debug: (9)   } # authenticate = ok
Fri Feb 27 11:48:44 2015 : Debug: (9) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default
Fri Feb 27 11:48:44 2015 : Debug: (9)   post-auth {
Fri Feb 27 11:48:44 2015 : Debug: (9)     update {
Fri Feb 27 11:48:44 2015 : Debug: (9)       No attributes updated
Fri Feb 27 11:48:44 2015 : Debug: (9)     } # update = noop
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[post-auth]: calling linelog (rlm_linelog) for request 9
Fri Feb 27 11:48:44 2015 : Debug: Accounting-Request.%{%{Acct-Status-Type}:-unknown}
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: literal --> Accounting-Request.
Fri Feb 27 11:48:44 2015 : Debug: if {
Fri Feb 27 11:48:44 2015 : Debug:       attribute --> Acct-Status-Type
Fri Feb 27 11:48:44 2015 : Debug: }
Fri Feb 27 11:48:44 2015 : Debug: else {
Fri Feb 27 11:48:44 2015 : Debug:       literal --> unknown
Fri Feb 27 11:48:44 2015 : Debug: }
Fri Feb 27 11:48:44 2015 : Debug: (9) linelog: EXPAND Accounting-Request.%{%{Acct-Status-Type}:-unknown}
Fri Feb 27 11:48:44 2015 : Debug: (9) linelog:    --> Accounting-Request.unknown
Fri Feb 27 11:48:44 2015 : Debug: /var/log/radius/linelog
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: literal --> /var/log/radius/linelog
Fri Feb 27 11:48:44 2015 : Debug: (9) linelog: EXPAND /var/log/radius/linelog
Fri Feb 27 11:48:44 2015 : Debug: (9) linelog:    --> /var/log/radius/linelog
Fri Feb 27 11:48:44 2015 : Debug: NAS %{Packet-Src-IP-Address} (%{NAS-IP-Address}) sent unknown Acct-Status-Type %{Acct-Status-Type}
Fri Feb 27 11:48:44 2015 : Debug: Parsed xlat tree:
Fri Feb 27 11:48:44 2015 : Debug: literal --> NAS
Fri Feb 27 11:48:44 2015 : Debug: attribute --> Packet-Src-IP-Address
Fri Feb 27 11:48:44 2015 : Debug: literal -->  (
Fri Feb 27 11:48:44 2015 : Debug: attribute --> NAS-IP-Address
Fri Feb 27 11:48:44 2015 : Debug: literal --> ) sent unknown Acct-Status-Type
Fri Feb 27 11:48:44 2015 : Debug: attribute --> Acct-Status-Type
Fri Feb 27 11:48:44 2015 : Debug: (9) linelog: EXPAND NAS %{Packet-Src-IP-Address} (%{NAS-IP-Address}) sent unknown Acct-Status-Type %{Acct-Status-Type}
Fri Feb 27 11:48:44 2015 : Debug: (9) linelog:    --> NAS 24.94.145.173 (24.94.145.173) sent unknown Acct-Status-Type
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[post-auth]: returned from linelog (rlm_linelog) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     [linelog] = ok
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[post-auth]: calling exec (rlm_exec) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     modsingle[post-auth]: returned from exec (rlm_exec) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)     [exec] = noop
Fri Feb 27 11:48:44 2015 : Debug: (9)     policy remove_reply_message_if_eap {
Fri Feb 27 11:48:44 2015 : Debug: (9)       if (&reply:EAP-Message && &reply:Reply-Message) {
Fri Feb 27 11:48:44 2015 : Debug: (9)       if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
Fri Feb 27 11:48:44 2015 : Debug: (9)       else {
Fri Feb 27 11:48:44 2015 : Debug: (9)         modsingle[post-auth]: calling noop (rlm_always) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)         modsingle[post-auth]: returned from noop (rlm_always) for request 9
Fri Feb 27 11:48:44 2015 : Debug: (9)         [noop] = noop
Fri Feb 27 11:48:44 2015 : Debug: (9)       } # else = noop
Fri Feb 27 11:48:44 2015 : Debug: (9)     } # policy remove_reply_message_if_eap = noop
Fri Feb 27 11:48:44 2015 : Debug: (9)   } # post-auth = ok
Fri Feb 27 11:48:44 2015 : Debug: (9) Sent Access-Accept Id 233 from 71.46.62.133:1812 to 24.94.145.173:50155 length 170
Fri Feb 27 11:48:44 2015 : Debug: (9)   MS-MPPE-Recv-Key = 0xf9f233b4f415e166139f17345897d51ef8f739bd9a7674da6f424300c3ab08d7
Fri Feb 27 11:48:44 2015 : Debug: (9)   MS-MPPE-Send-Key = 0x4a577470348ad1582a59e092c346c9ff53f0a07da642ee33a54039fb9e03e35c
Fri Feb 27 11:48:44 2015 : Debug: (9)   EAP-Message = 0x037f0004
Fri Feb 27 11:48:44 2015 : Debug: (9)   Message-Authenticator = 0x00000000000000000000000000000000
Fri Feb 27 11:48:44 2015 : Debug: (9)   User-Name = 'qaresdon'
Fri Feb 27 11:48:44 2015 : Debug: (9) Finished request

________________________________

CONFIDENTIALITY NOTICE: This e-mail may contain information that is privileged, confidential or otherwise protected from disclosure. **If you are not the intended recipient of this e-mail, please notify the sender immediately by return e-mail, purge it and do not disseminate or copy it.



More information about the Freeradius-Users mailing list