Request log details for session: R0000002a-03-50dc5a62 Time Message 2012-12-27 15:25:38,127 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf 2012-12-27 15:25:38,127 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group authorize for request 219 2012-12-27 15:25:38,127 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "dacl" returns noop for request 219 2012-12-27 15:25:38,127 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: The request does not have Service-State attribute 2012-12-27 15:25:38,127 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization 2012-12-27 15:25:38,127 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: service_get_polsvr_conn: Checking Id: 0 2012-12-27 15:25:38,127 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: service_get_polsvr_conn: Got Id: 0, handle: 0x12e65310 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: add req-packet attributes 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Name = "aruba" 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NAS-IP-Address = 192.168.20.130 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NAS-Port = 1 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NAS-Identifier = "192.168.20.130" 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NAS-Port-Type = Wireless-802.11 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Calling-Station-Id = "0019D2AF162C" 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Called-Station-Id = "D8C7C8C74A21" 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Service-Type = Login-User 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Framed-MTU = 1100 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-Message = 0x0201000a016172756261 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Aruba-Essid-Name = "hh-hnk-dot1x" 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Message-Authenticator = 0xc29727c400219d4dd8dbf84537784abf 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: add config attributes 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,128 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: add connection attributes 2012-12-27 15:25:38,132 [RequestHandler-1-0x40db8940 r=auto-97 h=47 r=R0000002a-03-50dc5a62] INFO Core.ServiceReqHandler - Service classification result = aruba wireless 802.1x client cert against AD 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: Policy Server reply does not contain Requested-Posture-Credentials 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: service_release_polsvr_conn: Release Id: 0, handle: 0x12e65310 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "aruba wireless 802.1x client cert against AD" 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_add Service-State = 0x00a8005900b800b6db00000098df642a3fbc3f1a4263fe93156aa72f, Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "service" returns ok for request 219 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group authorize (returns ok) for request 219 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Found Autz-Type svc_aruba wireless 802.1x client cert against AD_3011 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group svc_aruba wireless 802.1x client cert against AD_3011 for request 219 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group for request 219 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_ldap: searching for user aruba in AD:192.168.20.193 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - radius_xlat: Running registered xlat function of module authsrc_3002 for string 'Username' 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: - ldap_xlat 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - radius_xlat: '(&(sAMAccountName=aruba)(objectClass=user))' 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - radius_xlat: 'dc=hnk,dc=loc' 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: ldap_get_conn: Checking Id: 0 2012-12-27 15:25:38,133 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: ldap_get_conn: Got Id: 0 2012-12-27 15:25:38,134 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Allocated referral parameters dn = cn=administrator,cn=users,dc=hnk,dc=loc & password 2012-12-27 15:25:38,134 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: performing search in dc=hnk,dc=loc, with filter (&(sAMAccountName=aruba)(objectClass=user)) 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Setting Ldap-UserDn = CN=aruba networks,CN=Users,DC=hnk,DC=loc 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: user aruba has 1 certificates 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: length of certificate of user aruba: 1434 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Certificate = 0x308205963082047ea003020102020a19285807000000000010300d06092a864886f70d0101050500304631133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274311a3018060355040313116272742d5444432d4252542d30312d4341301e170d3132313232373134303132305a170d3133313232373134303132305a305331133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274310e300c060355040313055573657273311730150603550403130e6172756261206e6574776f726b7330819f300d06092a864886f70d010101050003818d0030818902818100d43093c78a64e9fa7b5d736c2b90acedd946d7762a6485a9b334e84b98e39edba3bec4a36c841227096a291485d7e46ec28ccca2db49aaebce807e6f5a8e07f4f0a6fcfea9d69a3d91c33bfb158304eb3eba9cd0f21d76ff96d9d519c265667cf5bd6c84264da097ad798526d935b1ec7188d0d16d39fba3746dafd694c776050203010001a38202fb308202f7300e0603551d0f0101ff0404030205a0304406092a864886f70d01090f04373035300e06082a864886f70d030202020080300e06082a864886f70d030402020080300706052b0e030207300a06082a864886f70d0307301d0603551d0e0416041437f65761e3 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: user aruba has attribute sAMAccountName 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Account-Name = "aruba" 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_ldap: found user aruba in AD:192.168.20.193 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Setting Alternate-Auth-Type = authsrc_3002 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Setting Authentication-Source = AD:192.168.20.193 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Setting Authentication-Source-Name = hnk-dc-01 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Setting MS-CHAP-Use-NTLM-Auth = Yes 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Setting NetBIOS-Name = hnk 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: ldap_release_conn: Release Id: 0 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "authsrc_3002" returns ok for request 219 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group (returns ok) for request 219 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Deleting Proxy-To-Realm and Post-Proxy-Type attributes 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: EAP packet type response id 1 length 10 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: No EAP Start, assuming it's an on-going EAP conversation 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3011_eap" returns updated for request 219 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_auth_check: Allowed authentication methods: svc_3011_eap 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - radius: No MS Identity VP 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_auth_check: allowed Authentication method svc_3011_eap set. 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3011_auth_check" returns ok for request 219 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group svc_aruba wireless 802.1x client cert against AD_3011 (returns updated) for request 219 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rad_check_password: Found Auth-Type svc_3011_eap 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - auth: type "svc_3011_eap" 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authenticate section of radiusd.conf 2012-12-27 15:25:38,135 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group svc_3011_eap for request 219 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: EAP Identity 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: processing type tls instance EAP TLS] test 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_eap_tls: Initiate 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Requiring client certificate 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Start returned 1 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eap_compose returned 3 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eap_list_add EAP-State = 0x00df00b500ee00c2db000000aea9fdee3182df04 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthenticate]: module "svc_3011_eap" returns handled for request 219 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group svc_3011_eap (returns handled) for request 219 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following state_items 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Service-State = 0x00a8005900b800b6db00000098df642a3fbc3f1a4263fe93156aa72f 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-State = 0x00df00b500ee00c2db000000aea9fdee3182df04 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following session_id 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following session messages 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request error code 0 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following persistent config items 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Ldap-UserDn = "CN=aruba networks,CN=Users,DC=hnk,DC=loc" 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Certificate = 0x308205963082047ea003020102020a19285807000000000010300d06092a864886f70d0101050500304631133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274311a3018060355040313116272742d5444432d4252542d30312d4341301e170d3132313232373134303132305a170d3133313232373134303132305a305331133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274310e300c060355040313055573657273311730150603550403130e6172756261206e6574776f726b7330819f300d06092a864886f70d010101050003818d0030818902818100d43093c78a64e9fa7b5d736c2b90acedd946d7762a6485a9b334e84b98e39edba3bec4a36c841227096a291485d7e46ec28ccca2db49aaebce807e6f5a8e07f4f0a6fcfea9d69a3d91c33bfb158304eb3eba9cd0f21d76ff96d9d519c265667cf5bd6c84264da097ad798526d935b1ec7188d0d16d39fba3746dafd694c776050203010001a38202fb308202f7300e0603551d0f0101ff0404030205a0304406092a864886f70d01090f04373035300e06082a864886f70d030202020080300e06082a864886f70d030402020080300706052b0e030207300a06082a864886f70d0307301d0603551d0e0416041437f65761e3 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Account-Name = "aruba" 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Alternate-Auth-Type = "authsrc_3002" 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Source = "AD:192.168.20.193" 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Source-Name = "hnk-dc-01" 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - MS-CHAP-Use-NTLM-Auth = Yes 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NetBIOS-Name = "hnk" 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Policy Evaluation Status of the request: 0 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Sending Access-Challenge of id 220 to 192.168.20.130 port 49153 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-Message = 0x010200060d20 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Message-Authenticator = 0x00000000000000000000000000000000 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - State = 0x001e009000e6002edb000000b8465cc9f2ce3752b1c8826bdeb344c9 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Finished request 219 2012-12-27 15:25:38,136 [Th 5 Req 219 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Going to the next request 2012-12-27 15:25:38,139 [Th 1 Req 220] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group authorize for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "dacl" returns noop for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: The request has Service-State attribute 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_find Service-State = 0x00a8005900b800b6db00000098df642a3fbc3f1a4263fe93156aa72f, Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: Request found, released from the list 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "aruba wireless 802.1x client cert against AD" 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_add Service-State = 0x006b003500d2004ddc0000006def32704da2a1fd5a2504bb518f457f, Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "service" returns ok for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group authorize (returns ok) for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Found Autz-Type svc_aruba wireless 802.1x client cert against AD_3011 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group svc_aruba wireless 802.1x client cert against AD_3011 for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Request contains authsrc items, returning 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "authsrc_3002" returns ok for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group (returns ok) for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Deleting Proxy-To-Realm and Post-Proxy-Type attributes 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: EAP packet type response id 2 length 87 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: No EAP Start, assuming it's an on-going EAP conversation 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3011_eap" returns updated for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_auth_check: Allowed authentication methods: svc_3011_eap 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - radius: No MS Identity VP 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_auth_check: allowed Authentication method svc_3011_eap set. 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3011_auth_check" returns ok for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group svc_aruba wireless 802.1x client cert against AD_3011 (returns updated) for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rad_check_password: Found Auth-Type svc_3011_eap 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - auth: type "svc_3011_eap" 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authenticate section of radiusd.conf 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group svc_3011_eap for request 220 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eaplist_find EAP-State = 0x00df00b500ee00c2db000000aea9fdee3182df04 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Request found, released from the list 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: processing type tls instance EAP TLS] test 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Authenticate 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Authorization is not mandatory 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: processing TLS 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Server version 0 Peer Version 0 Choosing 0 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Length Included 2012-12-27 15:25:38,140 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - eaptls_verify returned 11 2012-12-27 15:25:38,141 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: TLS packet length 86 flags 80 2012-12-27 15:25:38,141 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - (other): before/accept initialization 2012-12-27 15:25:38,141 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - TLS_accept: before/accept initialization 2012-12-27 15:25:38,141 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: <<< TLS 1.0 Handshake length 0048], ClientHello 2012-12-27 15:25:38,141 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - TLS_accept: SSLv3 read client hello A 2012-12-27 15:25:38,141 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: >>> TLS 1.0 Handshake length 004a], ServerHello 2012-12-27 15:25:38,141 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - TLS_accept: SSLv3 write server hello A 2012-12-27 15:25:38,141 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: >>> TLS 1.0 Handshake length 0230], Certificate 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - TLS_accept: SSLv3 write certificate A 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: >>> TLS 1.0 Handshake length 01a8], CertificateRequest 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - TLS_accept: SSLv3 write certificate request A 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - TLS_accept: SSLv3 flush data 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client certificate A 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - In SSL Handshake Phase 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - In SSL Accept mode 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - eaptls_process returned 13 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eap_compose returned 3 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eap_list_add EAP-State = 0x002e007c006300bfdc0000001661140d42ba77c8 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthenticate]: module "svc_3011_eap" returns handled for request 220 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group svc_3011_eap (returns handled) for request 220 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following state_items 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Service-State = 0x006b003500d2004ddc0000006def32704da2a1fd5a2504bb518f457f 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-State = 0x002e007c006300bfdc0000001661140d42ba77c8 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following session_id 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following session messages 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request error code 0 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following persistent config items 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Ldap-UserDn = "CN=aruba networks,CN=Users,DC=hnk,DC=loc" 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Certificate = 0x308205963082047ea003020102020a19285807000000000010300d06092a864886f70d0101050500304631133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274311a3018060355040313116272742d5444432d4252542d30312d4341301e170d3132313232373134303132305a170d3133313232373134303132305a305331133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274310e300c060355040313055573657273311730150603550403130e6172756261206e6574776f726b7330819f300d06092a864886f70d010101050003818d0030818902818100d43093c78a64e9fa7b5d736c2b90acedd946d7762a6485a9b334e84b98e39edba3bec4a36c841227096a291485d7e46ec28ccca2db49aaebce807e6f5a8e07f4f0a6fcfea9d69a3d91c33bfb158304eb3eba9cd0f21d76ff96d9d519c265667cf5bd6c84264da097ad798526d935b1ec7188d0d16d39fba3746dafd694c776050203010001a38202fb308202f7300e0603551d0f0101ff0404030205a0304406092a864886f70d01090f04373035300e06082a864886f70d030202020080300e06082a864886f70d030402020080300706052b0e030207300a06082a864886f70d0307301d0603551d0e0416041437f65761e3 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Account-Name = "aruba" 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Alternate-Auth-Type = "authsrc_3002" 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Source = "AD:192.168.20.193" 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Source-Name = "hnk-dc-01" 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - MS-CHAP-Use-NTLM-Auth = Yes 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NetBIOS-Name = "hnk" 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Policy Evaluation Status of the request: 0 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Sending Access-Challenge of id 221 to 192.168.20.130 port 49153 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-Message = 0x0103040a0dc000000431160301004a02000046030150dc5a6288fd688f33739e86d4aa1a42b02c9671fbda7b797f6e1f865bfe4ae42002d63861d347b223a9a59602756141e161f346d93a23ed283912271ea1008b81000a0016030102300b00022c000229000226308202223082018ba003020102020900c690ac17946d9b07300d06092a864886f70d01010505003039311f301d06035504031316636c65617270617373746573742e746573742e6c6f6331163014060355040a130d506f6c6963794d616e61676572301e170d3132303630333137323835385a170d3133303630333137323835385a3039311f301d06035504031316636c65617270 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-Message = 0x617373746573742e746573742e6c6f6331163014060355040a130d506f6c6963794d616e6167657230819f300d06092a864886f70d010101050003818d0030818902818100f88c82eb5452ff56377b9af324d037b5c3cd3ac9653d32a1744f7034eaaac7d36a4838ecbb38ff278cf165e4f0da7034d5c683e802d74ed7da3c963d92ccb68881793baa187755967ba3f32c6e99f2ee134c622918924c10765f39f79b0880e02f2252ddf027bce4c69f3f0f2c774ecd4668fc5d7e0b363518d7a0317b163e410203010001a3323030300f0603551d11040830068704c0a814c0301d0603551d250416301406082b0601050507030106082b060105050703 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-Message = 0x03300d06092a864886f70d01010505000381810018fd5c181ce9acb7c60f7d4423d037d85b4b22fdbfa59c06c9d3a00f7cffbe011ff8ed0c446a4aed6b81776ef0f6e770f6eb2fbf9a01adbaa5eea1953280d9d712864ece7aa04b263b2ef59f58ee091ff2f29f9ccd93fcc57af5f8580b2e83e23e1c49215b36c90dc63efa549771b6c9685170fc1ed1b248ced1ff6eb337035916030101a80d0001a0020102019b00c43081c1310b300906035504061302555331173015060355040a130e566572695369676e2c20496e632e313c303a060355040b1333436c6173732031205075626c6963205072696d6172792043657274696669636174696f6e20 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-Message = 0x417574686f72697479202d204732313a3038060355040b1331286329203139393820566572695369676e2c20496e632e202d20466f7220617574686f72697a656420757365206f6e6c79311f301d060355040b1316566572695369676e205472757374204e6574776f726b00443042310b3009060355040613024e4c310b3009060355040813025a483111300f060355040a13086261727420696e63311330110603550403130a43412d626172742d303100433041310b3009060355040613024e4c310b3009060355040813025a483110300e060355040a130768656e6b206276311330110603550403130a43412d68656e6b2d303100483046311330 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-Message = 0x11060a0992268993f22c64011916036c6f6331133011 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Message-Authenticator = 0x00000000000000000000000000000000 2012-12-27 15:25:38,142 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - State = 0x0052005800c100fcdc0000004192e70cf3f369accb7b8dac8acda0fd 2012-12-27 15:25:38,143 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Finished request 220 2012-12-27 15:25:38,143 [Th 1 Req 220 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Going to the next request 2012-12-27 15:25:38,152 [Th 2 Req 221] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group authorize for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "dacl" returns noop for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: The request has Service-State attribute 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_find Service-State = 0x006b003500d2004ddc0000006def32704da2a1fd5a2504bb518f457f, Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: Request found, released from the list 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "aruba wireless 802.1x client cert against AD" 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_add Service-State = 0x007200670069008edd00000011d23500148f730a4e3e0ff49bde98b1, Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "service" returns ok for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group authorize (returns ok) for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Found Autz-Type svc_aruba wireless 802.1x client cert against AD_3011 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group svc_aruba wireless 802.1x client cert against AD_3011 for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Request contains authsrc items, returning 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "authsrc_3002" returns ok for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group (returns ok) for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Deleting Proxy-To-Realm and Post-Proxy-Type attributes 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: EAP packet type response id 3 length 6 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: No EAP Start, assuming it's an on-going EAP conversation 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3011_eap" returns updated for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_auth_check: Allowed authentication methods: svc_3011_eap 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - radius: No MS Identity VP 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_auth_check: allowed Authentication method svc_3011_eap set. 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3011_auth_check" returns ok for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group svc_aruba wireless 802.1x client cert against AD_3011 (returns updated) for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rad_check_password: Found Auth-Type svc_3011_eap 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - auth: type "svc_3011_eap" 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authenticate section of radiusd.conf 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group svc_3011_eap for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eaplist_find EAP-State = 0x002e007c006300bfdc0000001661140d42ba77c8 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Request found, released from the list 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: processing type tls instance EAP TLS] test 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Authenticate 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Authorization is not mandatory 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: processing TLS 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Received EAP-TLS ACK message 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: ack handshake fragment handler 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - eaptls_verify returned 1 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - eaptls_process returned 13 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eap_compose returned 3 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eap_list_add EAP-State = 0x007d0002007a00bfdd0000000ee43d4057f412f8 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthenticate]: module "svc_3011_eap" returns handled for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group svc_3011_eap (returns handled) for request 221 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following state_items 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Service-State = 0x007200670069008edd00000011d23500148f730a4e3e0ff49bde98b1 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-State = 0x007d0002007a00bfdd0000000ee43d4057f412f8 2012-12-27 15:25:38,153 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following session_id 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following session messages 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request error code 0 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following persistent config items 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Ldap-UserDn = "CN=aruba networks,CN=Users,DC=hnk,DC=loc" 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Certificate = 0x308205963082047ea003020102020a19285807000000000010300d06092a864886f70d0101050500304631133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274311a3018060355040313116272742d5444432d4252542d30312d4341301e170d3132313232373134303132305a170d3133313232373134303132305a305331133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274310e300c060355040313055573657273311730150603550403130e6172756261206e6574776f726b7330819f300d06092a864886f70d010101050003818d0030818902818100d43093c78a64e9fa7b5d736c2b90acedd946d7762a6485a9b334e84b98e39edba3bec4a36c841227096a291485d7e46ec28ccca2db49aaebce807e6f5a8e07f4f0a6fcfea9d69a3d91c33bfb158304eb3eba9cd0f21d76ff96d9d519c265667cf5bd6c84264da097ad798526d935b1ec7188d0d16d39fba3746dafd694c776050203010001a38202fb308202f7300e0603551d0f0101ff0404030205a0304406092a864886f70d01090f04373035300e06082a864886f70d030202020080300e06082a864886f70d030402020080300706052b0e030207300a06082a864886f70d0307301d0603551d0e0416041437f65761e3 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Account-Name = "aruba" 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Alternate-Auth-Type = "authsrc_3002" 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Source = "AD:192.168.20.193" 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Source-Name = "hnk-dc-01" 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - MS-CHAP-Use-NTLM-Auth = Yes 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NetBIOS-Name = "hnk" 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Policy Evaluation Status of the request: 0 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Sending Access-Challenge of id 222 to 192.168.20.130 port 49153 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-Message = 0x010400370d00060a0992268993f22c6401191603627274311a3018060355040313116272742d5444432d4252542d30312d43410e000000 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Message-Authenticator = 0x00000000000000000000000000000000 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - State = 0x00af00be00d00004dd0000006f47819869d5dc2189b665af4006191b 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Finished request 221 2012-12-27 15:25:38,154 [Th 2 Req 221 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Going to the next request 2012-12-27 15:25:38,162 [Th 3 Req 222] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group authorize for request 222 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "dacl" returns noop for request 222 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: The request has Service-State attribute 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_find Service-State = 0x007200670069008edd00000011d23500148f730a4e3e0ff49bde98b1, Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: Request found, released from the list 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "aruba wireless 802.1x client cert against AD" 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_add Service-State = 0x009b008a00130045de000000767d897f03a87121d3fbe4bec9b34f3c, Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "service" returns ok for request 222 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group authorize (returns ok) for request 222 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Found Autz-Type svc_aruba wireless 802.1x client cert against AD_3011 2012-12-27 15:25:38,162 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group svc_aruba wireless 802.1x client cert against AD_3011 for request 222 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group for request 222 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Request contains authsrc items, returning 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "authsrc_3002" returns ok for request 222 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group (returns ok) for request 222 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Deleting Proxy-To-Realm and Post-Proxy-Type attributes 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: EAP packet type response id 4 length 253 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: No EAP Start, assuming it's an on-going EAP conversation 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3011_eap" returns updated for request 222 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_auth_check: Allowed authentication methods: svc_3011_eap 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - radius: No MS Identity VP 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_auth_check: allowed Authentication method svc_3011_eap set. 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3011_auth_check" returns ok for request 222 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group svc_aruba wireless 802.1x client cert against AD_3011 (returns updated) for request 222 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rad_check_password: Found Auth-Type svc_3011_eap 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - auth: type "svc_3011_eap" 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authenticate section of radiusd.conf 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group svc_3011_eap for request 222 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eaplist_find EAP-State = 0x007d0002007a00bfdd0000000ee43d4057f412f8 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Request found, released from the list 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: processing type tls instance EAP TLS] test 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Authenticate 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Authorization is not mandatory 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: processing TLS 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Received EAP-TLS First Fragment of the message 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - eaptls_verify returned 9 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: TLS packet length 1489 flags c0 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - eaptls_process returned 13 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eap_compose returned 3 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eap_list_add EAP-State = 0x00f100ae00600028de000000eb6f937ec3d6e9db 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthenticate]: module "svc_3011_eap" returns handled for request 222 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group svc_3011_eap (returns handled) for request 222 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following state_items 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Service-State = 0x009b008a00130045de000000767d897f03a87121d3fbe4bec9b34f3c 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-State = 0x00f100ae00600028de000000eb6f937ec3d6e9db 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following session_id 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following session messages 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request error code 0 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - The request contains following persistent config items 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Ldap-UserDn = "CN=aruba networks,CN=Users,DC=hnk,DC=loc" 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Certificate = 0x308205963082047ea003020102020a19285807000000000010300d06092a864886f70d0101050500304631133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274311a3018060355040313116272742d5444432d4252542d30312d4341301e170d3132313232373134303132305a170d3133313232373134303132305a305331133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274310e300c060355040313055573657273311730150603550403130e6172756261206e6574776f726b7330819f300d06092a864886f70d010101050003818d0030818902818100d43093c78a64e9fa7b5d736c2b90acedd946d7762a6485a9b334e84b98e39edba3bec4a36c841227096a291485d7e46ec28ccca2db49aaebce807e6f5a8e07f4f0a6fcfea9d69a3d91c33bfb158304eb3eba9cd0f21d76ff96d9d519c265667cf5bd6c84264da097ad798526d935b1ec7188d0d16d39fba3746dafd694c776050203010001a38202fb308202f7300e0603551d0f0101ff0404030205a0304406092a864886f70d01090f04373035300e06082a864886f70d030202020080300e06082a864886f70d030402020080300706052b0e030207300a06082a864886f70d0307301d0603551d0e0416041437f65761e3 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Account-Name = "aruba" 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Alternate-Auth-Type = "authsrc_3002" 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Source = "AD:192.168.20.193" 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Source-Name = "hnk-dc-01" 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - MS-CHAP-Use-NTLM-Auth = Yes 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NetBIOS-Name = "hnk" 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Policy Evaluation Status of the request: 0 2012-12-27 15:25:38,163 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Sending Access-Challenge of id 223 to 192.168.20.130 port 49153 2012-12-27 15:25:38,164 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-Message = 0x010500060d00 2012-12-27 15:25:38,164 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Message-Authenticator = 0x00000000000000000000000000000000 2012-12-27 15:25:38,164 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - State = 0x00aa009f007f001ede000000f5f9612cf36cdbf339c4bbc89ebe1840 2012-12-27 15:25:38,164 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Finished request 222 2012-12-27 15:25:38,164 [Th 3 Req 222 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Going to the next request 2012-12-27 15:25:38,167 [Th 4 Req 223] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group authorize for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "dacl" returns noop for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: The request has Service-State attribute 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_find Service-State = 0x009b008a00130045de000000767d897f03a87121d3fbe4bec9b34f3c, Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: Request found, released from the list 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "aruba wireless 802.1x client cert against AD" 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_add Service-State = 0x000100bb0055008cdf00000017c59652df23385adafa7e3ff8b82965, Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "service" returns ok for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group authorize (returns ok) for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Found Autz-Type svc_aruba wireless 802.1x client cert against AD_3011 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group svc_aruba wireless 802.1x client cert against AD_3011 for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_ldap: Request contains authsrc items, returning 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "authsrc_3002" returns ok for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group (returns ok) for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Deleting Proxy-To-Realm and Post-Proxy-Type attributes 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: EAP packet type response id 5 length 253 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: No EAP Start, assuming it's an on-going EAP conversation 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3011_eap" returns updated for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_auth_check: Allowed authentication methods: svc_3011_eap 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - radius: No MS Identity VP 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_auth_check: allowed Authentication method svc_3011_eap set. 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3011_auth_check" returns ok for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group svc_aruba wireless 802.1x client cert against AD_3011 (returns updated) for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rad_check_password: Found Auth-Type svc_3011_eap 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - auth: type "svc_3011_eap" 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the authenticate section of radiusd.conf 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group svc_3011_eap for request 223 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: eaplist_find EAP-State = 0x00f100ae00600028de000000eb6f937ec3d6e9db 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Request found, released from the list 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: processing type tls instance EAP TLS] test 2012-12-27 15:25:38,167 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Authenticate 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Authorization is not mandatory 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: processing TLS 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - eaptls_verify returned 7 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Done initial handshake 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: TLS packet length 293 flags 00 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - EAP-TLS: Client certificate received msg_len 1440 encd_len 1437 cert_len 1434 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - eap: Certificate: hexdump: 30 82 05 96 30 82 04 7e a0 03 02 01 02 02 0a 19 28 58 07 00 00 00 00 00 10 30 0d 06 09 2a 86 48 86 f7 0d 01 01 05 05 00 30 46 31 13 30 11 06 0a 09 92 26 89 93 f2 2c 64 01 19 16 03 6c 6f 63 31 13 30 11 06 0a 09 92 26 89 93 f2 2c 64 01 19 16 03 62 72 74 31 1a 30 18 06 03 55 04 03 13 11 62 72 74 2d 54 44 43 2d 42 52 54 2d 30 31 2d 43 41 30 1e 17 0d 31 32 31 32 32 37 31 34 30 31 32 30 5a 17 0d 31 33 31 32 32 37 31 34 30 31 32 30 5a 30 53 31 13 30 11 06 0a 09 92 26 89 93 f2 2c 64 01 19 16 03 6c 6f 63 31 13 30 11 06 0a 09 92 26 89 93 f2 2c 64 01 19 16 03 62 72 74 31 0e 30 0c 06 03 55 04 03 13 05 55 73 65 72 73 31 17 30 15 06 03 55 04 03 13 0e 61 72 75 62 61 20 6e 65 74 77 6f 72 6b 73 30 81 9f 30 0d 06 09 2a 86 48 86 f7 0d 01 01 01 05 00 03 81 8d 00 30 81 89 02 81 81 00 d4 30 93 c7 8a 64 e9 fa 7b 5d 73 6c 2b 90 ac ed d9 46 d7 76 2a 64 85 a9 b3 34 e8 4b 98 e3 9e db a3 be c4 a3 6c 84 12 27 09 6a 29 14 85 d7 e4 6e c2 8c cc a2 db 49 aa eb ce 80 7e 6f 5a 8e 07 f4 f0 a6 fc fe a9 d6 9a 3d 91 c3 3b fb 15 83 04 eb 3e ba 9c d0 f2 1d 76 ff 96 d9 d5 19 c2 65 66 7c f5 bd 6c 84 26 4d a0 97 ad 79 85 26 d9 35 b1 ec 71 88 d0 d1 6d 39 fb a3 74 6d af d6 94 c7 76 05 02 03 01 00 01 a3 82 02 fb 30 82 02 f7 30 0e 06 03 55 1d 0f 01 01 ff 04 04 03 02 05 a0 30 44 06 09 2a 86 48 86 f7 0d 01 09 0f 04 37 30 35 30 0e 06 08 2a 86 48 86 f7 0d 03 02 02 02 00 80 30 0e 06 08 2a 86 48 86 f7 0d 03 04 02 02 00 80 30 07 06 05 2b 0e 03 02 07 30 0a 06 08 2a 86 48 86 f7 0d 03 07 30 1d 06 03 55 1d 0e 04 16 04 14 37 f6 57 61 e3 f9 7a 0a 1e d3 9a 29 f9 51 68 fa 83 1e dd eb 30 17 06 09 2b 06 01 04 01 82 37 14 02 04 0a 1e 08 00 55 00 73 00 65 00 72 30 1f 06 03 55 1d 23 04 18 30 16 80 14 f2 e3 aa b9 a7 cb 79 9f 9c ed 95 39 f0 72 1d c0 70 28 07 41 30 81 ce 06 03 55 1d 1f 04 81 c6 30 81 c3 30 81 c0 a0 81 bd a0 81 ba 86 81 b7 6c 64 61 70 3a 2f 2f 2f 43 4e 3d 62 72 74 2d 54 44 43 2d 42 52 54 2d 30 31 2d 43 41 2c 43 4e 3d 54 44 43 2d 42 52 54 2d 30 31 2c 43 4e 3d 43 44 50 2c 43 4e 3d 50 75 62 6c 69 63 25 32 30 4b 65 79 25 32 30 53 65 72 76 69 63 65 73 2c 43 4e 3d 53 65 72 76 69 63 65 73 2c 43 4e 3d 43 6f 6e 66 69 67 75 72 61 74 69 6f 6e 2c 44 43 3d 62 72 74 2c 44 43 3d 6c 6f 63 3f 63 65 72 74 69 66 69 63 61 74 65 52 65 76 6f 63 61 74 69 6f 6e 4c 69 73 74 3f 62 61 73 65 3f 6f 62 6a 65 63 74 43 6c 61 73 73 3d 63 52 4c 44 69 73 74 72 69 62 75 74 69 6f 6e 50 6f 69 6e 74 30 82 01 1e 06 08 2b 06 01 05 05 07 01 01 04 82 01 10 30 82 01 0c 30 81 ac 06 08 2b 06 01 05 05 07 30 02 86 81 9f 6c 64 61 70 3a 2f 2f 2f 43 4e 3d 62 72 74 2d 54 44 43 2d 42 52 54 2d 30 31 2d 43 41 2c 43 4e 3d 41 49 41 2c 43 4e 3d 50 75 62 6c 69 63 25 32 30 4b 65 79 25 32 30 53 65 72 76 69 63 65 73 2c 43 4e 3d 53 65 72 76 69 63 65 73 2c 43 4e 3d 43 6f 6e 66 69 67 75 72 61 74 69 6f 6e 2c 44 43 3d 62 72 74 2c 44 43 3d 6c 6f 63 3f 63 41 43 65 72 74 69 66 69 63 61 74 65 3f 62 61 73 65 3f 6f 62 6a 65 63 74 43 6c 61 73 73 3d 63 65 72 74 69 66 69 63 61 74 69 6f 6e 41 75 74 68 6f 72 69 74 79 30 2a 06 08 2b 06 01 05 05 07 30 01 86 1e 68 74 74 70 3a 2f 2f 74 64 63 2d 62 72 74 2d 30 31 2e 62 72 74 2e 6c 6f 63 2f 6f 63 73 70 30 2f 06 08 2b 06 01 05 05 07 30 01 86 23 68 74 74 70 3a 2f 2f 74 64 63 2d 62 72 74 2d 30 31 2e 62 72 74 2e 6c 6f 63 2f 6f 63 73 70 2d 62 61 72 74 30 29 06 03 55 1d 25 04 22 30 20 06 0a 2b 06 01 04 01 82 37 0a 03 04 06 08 2b 06 01 05 05 07 03 04 06 08 2b 06 01 05 05 07 03 02 30 28 06 03 55 1d 11 04 21 30 1f a0 1d 06 0a 2b 06 01 04 01 82 37 14 02 03 a0 0f 0c 0d 61 72 75 62 61 40 62 72 74 2e 6c 6f 63 30 0d 06 09 2a 86 48 86 f7 0d 01 01 05 05 00 03 82 01 01 00 5a c4 37 b2 42 19 74 2d f0 11 f6 d1 46 f4 2d 8c 44 4e 02 83 b5 30 20 a2 78 ac ee e1 34 99 be 32 94 41 0b 45 79 18 e1 07 ac 59 4c a0 0c d1 95 24 df cc d5 29 45 14 a2 a7 24 3e c4 6f f6 07 73 a3 0c 66 04 24 87 26 e1 9c c1 76 a5 fe ed ed 33 3c 82 8c 66 b7 c7 9e ff 89 03 30 cb ae f3 90 c5 d7 32 71 50 d3 d6 81 20 4f ce f2 c8 dc bc 34 35 ca a5 10 3a 50 55 11 fd 75 4f 2b fb 24 8b 0a 47 32 ec 0b 3f 44 ba ab d6 cd 43 96 33 2f 1d e0 fe eb fb bd 65 d5 cc 0c ed b5 fe 19 b4 69 0e 86 c8 84 eb 95 71 3a 50 9f 3c 1b 05 43 85 68 b2 1e 2a 9e 08 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: <<< TLS 1.0 Handshake length 05a4], Certificate 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - chain-depth=1, 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - error=0 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - --> User-Name = aruba 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - --> subject = /DC=loc/DC=hnk/CN=hnk-TDC-hnk-01-CA 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - --> issuer = /DC=loc/DC=hnk/CN=hnk-TDC-hnk-01-CA 2012-12-27 15:25:38,168 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - --> verify return:1 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Version value 3 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Serial-Number value 19:28:58:07:00:00:00:00:00:10 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Subject-DN value CN=aruba networks,CN=Users,DC=hnk,DC=loc 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Subject-DC value loc 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Subject-DC value hnk 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Subject-CN value Users 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Subject-CN value aruba networks 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Issuer-DN value CN=hnk-TDC-hnk-01-CA,DC=hnk,DC=loc 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Issuer-DC value loc 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Issuer-DC value hnk 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Issuer-CN value hnk-TDC-hnk-01-CA 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: Adding certificate attribute Subject-AltName-msUPN value aruba@hnk.loc 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - --> Starting OCSP Request 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Parsing the OCSP URLs in the certificate 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] ERROR RadiusServer.Radius - Certificate does not contain OCSP URL. OCSP check required. 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] ERROR RadiusServer.Radius - ocsp] --> Certificate has expired/been revoked! 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] ERROR RadiusServer.Radius - OCSP checks have failed 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - chain-depth=0, 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - error=0 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - --> User-Name = aruba 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - --> subject = /DC=loc/DC=hnk/CN=Users/CN=aruba networks 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - --> issuer = /DC=loc/DC=hnk/CN=hnk-TDC-hnk-01-CA 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - --> verify return:0 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: >>> TLS 1.0 Alert length 0002], fatal certificate_unknown 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] ERROR RadiusServer.Radius - TLS Alert write:fatal:certificate unknown 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client certificate B 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] ERROR RadiusServer.Radius - rlm_eap_tls: SSL_read failed in a system call (-1), TLS session fails. error:140890B2:SSL routines:SSL3_GET_CLIENT_CERTIFICATE:no certificate returned 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: tls_handshake_recv failed 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - eaptls_process returned 4 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Handler failed in EAP/tls 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap_tls: SSL ex data at index 0 - (nil) 2012-12-27 15:25:38,169 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_eap: Failed in EAP select 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallauthenticate]: module "svc_3011_eap" returns invalid for request 223 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group svc_3011_eap (returns invalid) for request 223 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - auth: Failed to validate the user. 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Found Post-Auth-Type 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Processing the post-auth section of radiusd.conf 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: entering group REJECT for request 223 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation. 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_get_polsvr_conn: Checking Id: 0 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_get_polsvr_conn: Got Id: 0, handle: 0x12fe01b0 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_add_request_vps 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Name = "aruba" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NAS-IP-Address = 192.168.20.130 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NAS-Port = 1 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NAS-Identifier = "192.168.20.130" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NAS-Port-Type = Wireless-802.11 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Calling-Station-Id = "0019D2AF162C" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Called-Station-Id = "D8C7C8C74A21" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Service-Type = Login-User 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Framed-MTU = 1100 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Aruba-Essid-Name = "hh-hnk-dot1x" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Stripped-User-Name = "aruba" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_add_config_vps - Request has the following config items 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Ldap-UserDn = "CN=aruba networks,CN=Users,DC=hnk,DC=loc" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Certificate = 0x308205963082047ea003020102020a19285807000000000010300d06092a864886f70d0101050500304631133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274311a3018060355040313116272742d5444432d4252542d30312d4341301e170d3132313232373134303132305a170d3133313232373134303132305a305331133011060a0992268993f22c64011916036c6f6331133011060a0992268993f22c6401191603627274310e300c060355040313055573657273311730150603550403130e6172756261206e6574776f726b7330819f300d06092a864886f70d010101050003818d0030818902818100d43093c78a64e9fa7b5d736c2b90acedd946d7762a6485a9b334e84b98e39edba3bec4a36c841227096a291485d7e46ec28ccca2db49aaebce807e6f5a8e07f4f0a6fcfea9d69a3d91c33bfb158304eb3eba9cd0f21d76ff96d9d519c265667cf5bd6c84264da097ad798526d935b1ec7188d0d16d39fba3746dafd694c776050203010001a38202fb308202f7300e0603551d0f0101ff0404030205a0304406092a864886f70d01090f04373035300e06082a864886f70d030202020080300e06082a864886f70d030402020080300706052b0e030207300a06082a864886f70d0307301d0603551d0e0416041437f65761e3 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - User-Account-Name = "aruba" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Alternate-Auth-Type = "authsrc_3002" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Source = "AD:192.168.20.193" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Source-Name = "hnk-dc-01" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - MS-CHAP-Use-NTLM-Auth = Yes 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - NetBIOS-Name = "hnk" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Service-Name = "aruba wireless 802.1x client cert against AD" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Service-Id = 3011 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Autz-Type = svc_aruba wireless 802.1x client cert against AD_3011 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Auth-Type = svc_3011_eap 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-EAP-Method = "tls" 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a56657273696f6e3d33 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a53657269616c2d4e756d6265723d31393a32383a35383a30373a30303a30303a30303a30303a30303a313020 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d444e3d434e3d6172756261206e6574776f726b732c434e3d55736572732c44433d6272742c44433d6c6f63 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d44433d6c6f63 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d44433d627274 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d434e3d5573657273 2012-12-27 15:25:38,170 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d434e3d6172756261206e6574776f726b73 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a4973737565722d444e3d434e3d6272742d5444432d4252542d30312d43412c44433d6272742c44433d6c6f63 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a4973737565722d44433d6c6f63 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a4973737565722d44433d627274 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a4973737565722d434e3d6272742d5444432d4252542d30312d4341 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d416c744e616d652d6d7355504e3d6172756261406272742e6c6f63 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Authentication-Method = "EAP" 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Post-Auth-Type = REJECT 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Service-Name = "aruba wireless 802.1x client cert against AD" 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Session-Id = "R0000002a-03-50dc5a62" 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Ldap-UserDn = "CN=aruba networks,CN=Users,DC=hnk,DC=loc" 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_add_reply_vps 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_add_conn_info 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_add_authentication_attributes 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_add_authorization_attributes 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_add_certificate_attributes 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a56657273696f6e3d33 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a53657269616c2d4e756d6265723d31393a32383a35383a30373a30303a30303a30303a30303a30303a313020 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d444e3d434e3d6172756261206e6574776f726b732c434e3d55736572732c44433d6272742c44433d6c6f63 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d44433d6c6f63 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d44433d627274 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d434e3d5573657273 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d434e3d6172756261206e6574776f726b73 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a4973737565722d444e3d434e3d6272742d5444432d4252542d30312d43412c44433d6272742c44433d6c6f63 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a4973737565722d44433d6c6f63 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a4973737565722d44433d627274 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a4973737565722d434e3d6272742d5444432d4252542d30312d4341 2012-12-27 15:25:38,171 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Added certificate attribute Certificate-Attributes = 0x43657274696669636174653a5375626a6563742d416c744e616d652d6d7355504e3d6172756261406272742e6c6f63 2012-12-27 15:25:38,174 [RequestHandler-1-0x40db8940 r=auto-98 h=48 r=R0000002a-03-50dc5a62] INFO Common.EndpointTable - Returning NULL (EndpointPtr) for macAddr 0019d2af162c 2012-12-27 15:25:38,174 [RequestHandler-1-0x40db8940 r=auto-98 h=48 r=R0000002a-03-50dc5a62] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3008 entity id = 29 2012-12-27 15:25:38,174 [RequestHandler-1-0x40db8940 r=auto-98 h=48 r=R0000002a-03-50dc5a62] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3008 2012-12-27 15:25:38,175 [RequestHandler-1-0x40db8940 r=auto-98 h=48 r=R0000002a-03-50dc5a62] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3008|entityId=29 2012-12-27 15:25:38,175 [RequestHandler-1-0x40db8940 r=auto-98 h=48 r=R0000002a-03-50dc5a62] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3008|entity=Device 2012-12-27 15:25:38,175 [RequestHandler-1-0x40db8940 r=auto-98 h=48 r=R0000002a-03-50dc5a62] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser) 2012-12-27 15:25:38,175 [RequestHandler-1-0x40db8940 r=auto-98 h=48 r=R0000002a-03-50dc5a62] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser) 2012-12-27 15:25:38,175 [RequestHandler-1-0x40db8940 r=auto-98 h=48 r=R0000002a-03-50dc5a62] INFO TAT.EndpointTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Endpoint) 2012-12-27 15:25:38,175 [RequestHandler-1-0x40db8940 r=auto-98 h=48 r=R0000002a-03-50dc5a62] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User) 2012-12-27 15:25:38,175 [RequestHandler-1-0x40db8940 h=788 c=R0000002a-03-50dc5a62] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started *** 2012-12-27 15:25:38,176 [RequestHandler-1-0x40db8940 h=790 c=R0000002a-03-50dc5a62] INFO Core.PETaskRoleMapping - Roles: 2012-12-27 15:25:38,177 [RequestHandler-1-0x40db8940 h=793 c=R0000002a-03-50dc5a62] INFO Core.PETaskEnforcement - EnfProfiles: Allow Access Profile] 2012-12-27 15:25:38,177 [RequestHandler-1-0x40db8940 h=794 c=R0000002a-03-50dc5a62] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT 2012-12-27 15:25:38,177 [RequestHandler-1-0x40db8940 h=794 c=R0000002a-03-50dc5a62] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: Allow Access Profile] 2012-12-27 15:25:38,177 [RequestHandler-1-0x40db8940 h=794 c=R0000002a-03-50dc5a62] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 0 2012-12-27 15:25:38,178 [RequestHandler-1-0x40db8940 h=797 c=R0000002a-03-50dc5a62] INFO Core.PETaskCliEnforcement - startHandler: No commands for CLI enforcement 2012-12-27 15:25:38,181 [RequestHandler-1-0x40db8940 r=R0000002a-03-50dc5a62 h=795 c=R0000002a-03-50dc5a62] INFO Core.PETaskRadiusCoAEnfProfileBuilder - getApplicableProfiles: No radius_coa enforcement profiles applicable for this device 2012-12-27 15:25:38,184 [RequestHandler-1-0x40db8940 h=799 c=R0000002a-03-50dc5a62] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs 2012-12-27 15:25:38,184 [RequestHandler-1-0x40db8940 h=799 c=R0000002a-03-50dc5a62] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr 2012-12-27 15:25:38,185 [RequestHandler-1-0x40db8940 h=798 c=R0000002a-03-50dc5a62] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr 2012-12-27 15:25:38,185 [RequestHandler-1-0x40db8940 r=R0000002a-03-50dc5a62 h=788 c=R0000002a-03-50dc5a62] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed *** 2012-12-27 15:25:38,186 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_add_resp_attrs 2012-12-27 15:25:38,186 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_policy: Received Accept Enforcement Profile 2012-12-27 15:25:38,186 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: Request rejected. Not adding Class attribute. 2012-12-27 15:25:38,186 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response 2012-12-27 15:25:38,186 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - rlm_policy: policy_release_polsvr_conn: Release Id: 0, handle: 0x12fe01b0 2012-12-27 15:25:38,186 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcallpost-auth]: module "policy" returns reject for request 223 2012-12-27 15:25:38,186 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - modcall: leaving group REJECT (returns reject) for request 223 2012-12-27 15:25:38,186 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Delaying request 223 for 1 seconds 2012-12-27 15:25:38,186 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Finished request 223 2012-12-27 15:25:38,186 [Th 4 Req 223 SessId R0000002a-03-50dc5a62] DEBUG RadiusServer.Radius - Going to the next request