Request log details for session: R0000008c-01-583df7c7

Time	Message
2016-11-29 13:48:55,600	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf
2016-11-29 13:48:55,600	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcall: entering group authorize for request 301
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcallauthorize]: module "dacl" returns noop for request 301
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_service: The request does not have Service-State attribute
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 58:185:68-f7-28-8d-60-39
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_service: service_get_polsvr_conn: Checking Id: 0
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_service: service_get_polsvr_conn: Got Id: 0, handle: 0xb35360
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_service: add req-packet attributes
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - User-Name = "host/Mike Smith"
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - NAS-Port = 72
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - EAP-Message = 0x0200001701686f73742f4a6f6e617468616e2048756e74
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Message-Authenticator = 0x7c9afc0465577c5f71bb6fddae4d0f3a
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Acct-Session-Id = "8O2.1x81a10ace000eee6d"
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - NAS-Port-Id = "ge-0/0/5.0"
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Calling-Station-Id = "68-f7-28-8d-60-39"
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Called-Station-Id = "64-87-88-a4-60-80"
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - NAS-IP-Address = 10.128.16.37
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - NAS-Identifier = "Test-Duo"
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - NAS-Port-Type = Ethernet
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_service: add config attributes
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Session-Id = "R0000008c-01-583df7c7"
2016-11-29 13:48:55,601	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_service: add connection attributes
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG StatsDClient.StatsClient - Formatted StatsD data=default.cp1-laxa.radius.serviceeval.time:3|ms
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG StatsDClient.StatsClient - Sending StatsD request=default.cp1-laxa.radius.serviceeval.time:3|ms
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] INFO RadiusServer.Radius - Service Categorization time = 3 ms
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_service: Policy Server reply does not contain Requested-Posture-Credentials
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_service: service_release_polsvr_conn: Release Id: 0, handle: 0xb35360
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "contoso NAC Test"
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_service: svcreq_list_add Service-State = 0x0047009a0047002c2d010000732ae9451b0e07885105fcbb971be6d2, Session-Id = "R0000008c-01-583df7c7"
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcallauthorize]: module "service" returns ok for request 301
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcall: leaving group authorize (returns ok) for request 301
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Found Autz-Type svc_contoso NAC Test_3002
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Processing the authorize section of radiusd.conf
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcall: entering group svc_contoso NAC Test_3002 for request 301
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcall: entering group for request 301
2016-11-29 13:48:55,604	[Th 4 Req 301 SessId R0000008c-01-583df7c7] INFO RadiusServer.Radius - rlm_ldap: searching for user host/Mike Smith in AD:dc1-snaa.ad.contoso.biz
2016-11-29 13:48:55,604	[RequestHandler-1-0x7ff61373e700 r=psauto-1479775612-294 h=55 r=R0000008c-01-583df7c7] INFO Core.ServiceReqHandler - Service classification result = contoso NAC Test
2016-11-29 13:48:55,605	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - radius_xlat: Running registered xlat function of module authsrc_3002 for string 'Username'
2016-11-29 13:48:55,605	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_ldap: - ldap_xlat
2016-11-29 13:48:55,605	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_ldap: found machine name host/Mike Smith
2016-11-29 13:48:55,605	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - radius_xlat: '(&(sAMAccountName=Mike Smith$)(objectClass=user))'
2016-11-29 13:48:55,605	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - radius_xlat: 'ou=us,dc=ad,dc=contoso,dc=biz'
2016-11-29 13:48:55,605	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_ldap: ldap_get_conn: Checking Id: 0
2016-11-29 13:48:55,605	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_ldap: ldap_get_conn: Got Id: 0
2016-11-29 13:48:55,605	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_ldap: Allocated referral parameters dn = clearpass@ad.contoso.biz & password
2016-11-29 13:48:55,605	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_ldap: performing search in ou=us,dc=ad,dc=contoso,dc=biz, with filter (&(sAMAccountName=Mike Smith$)(objectClass=user))
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_ldap: object not found or got ambiguous search result
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_ldap: search failed
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_ldap: ldap_release_conn: Release Id: 0
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcallauthorize]: module "authsrc_3002" returns notfound for request 301
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcall: leaving group (returns notfound) for request 301
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_eap: Deleting Proxy-To-Realm and Post-Proxy-Type attributes
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_eap: EAP packet type response id 0 length 23
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3002_eap" returns updated for request 301
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_auth_check: Allowed authentication methods: svc_3002_eap
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - radius: No MS Identity VP
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_auth_check: allowed Authentication method svc_3002_eap set.
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcallauthorize]: module "svc_3002_auth_check" returns ok for request 301
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcall: leaving group svc_contoso NAC Test_3002 (returns updated) for request 301
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rad_check_password: Found Auth-Type svc_3002_eap
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - auth: type "svc_3002_eap"
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Processing the authenticate section of radiusd.conf
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcall: entering group svc_3002_eap for request 301
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_eap: EAP Identity
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_eap: processing type tls instance contoso EAP-TLS
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] INFO RadiusServer.Radius - rlm_eap_tls: Initiate
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_eap_tls: Requiring client certificate
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_eap_tls: Start returned 1
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_eap: eap_compose returned 3
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_eap: eap_list_add EAP-State = 0x009500fe004e00942d01000094f759bbf6473b31
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcallauthenticate]: module "svc_3002_eap" returns handled for request 301
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcall: leaving group svc_3002_eap (returns handled) for request 301
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - The request contains following state_items
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Service-State = 0x0047009a0047002c2d010000732ae9451b0e07885105fcbb971be6d2
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - EAP-State = 0x009500fe004e00942d01000094f759bbf6473b31
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - The request contains following session_id
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Session-Id = "R0000008c-01-583df7c7"
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - The request contains following session messages
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - The request contains following persistent config items
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Policy Evaluation Status: 0, Request Status: 0, Error Code: 201
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - reqst_node_alloc: allocating pkt info - 0x4401ae00, pkt info size 16
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - reqst_node_alloc: updated pkt info - pkt # 0
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Sending Access-Challenge of id 58 to 10.128.16.37 port 62498
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - EAP-Message = 0x010100060d20
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Message-Authenticator = 0x00000000000000000000000000000000
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - State = APcAmwAQAEQtAQAAsP2RR0Y10lunn+rXV9KEJQ==
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - reqst_update_state node pkt info ptr 0x4401ae00, req cur pkt # 0, node cur pkt # 0
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 58:88:68-f7-28-8d-60-39:APcAmwAQAEQtAQAAsP2RR0Y10lunn+rXV9KEJQ==
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Finished request 301
2016-11-29 13:48:55,606	[Th 4 Req 301 SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Going to the next request
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] ERROR RadiusServer.Radius - reqst_clean_list: Deleting request sessid - R0000008c-01-583df7c7, state - APcAmwAQAEQtAQAAsP2RR0Y10lunn+rXV9KEJQ=
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] ERROR RadiusServer.Radius - reqst_clean_list: Packet 58:185:88:68-f7-28-8d-60-39 recv 1480456135.600703 - resp 1480456135.606855
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG StatsDClient.StatsClient - Formatted StatsD data=default.cp1-laxa.radius.timedoutpkt.count:1|c
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG StatsDClient.StatsClient - Sending StatsD request=default.cp1-laxa.radius.timedoutpkt.count:1|c
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Found Post-Auth-Type
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Processing the post-auth section of radiusd.conf
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcall: entering group REJECT for request 0
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation.
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_get_polsvr_conn: Checking Id: 0
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_get_polsvr_conn: Got Id: 0, handle: 0x9e1790
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_add_request_vps
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - User-Name = "host/Mike Smith"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - NAS-Port = 72
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Acct-Session-Id = "8O2.1x81a10ace000eee6d"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - NAS-Port-Id = "ge-0/0/5.0"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Calling-Station-Id = "68-f7-28-8d-60-39"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Called-Station-Id = "64-87-88-a4-60-80"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - NAS-IP-Address = 10.128.16.37
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - NAS-Identifier = "Test-Duo"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - NAS-Port-Type = Ethernet
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Stripped-User-Name = "Mike Smith$"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_add_config_vps - Request has the following config items
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Session-Id = "R0000008c-01-583df7c7"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Service-Name = "contoso NAC Test"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Service-Id = 3002
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Autz-Type = svc_contoso NAC Test_3002
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Auth-Type = svc_3002_eap
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Authentication-Method = "EAP"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Post-Auth-Type = REJECT
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Service-Name = "contoso NAC Test"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Session-Id = "R0000008c-01-583df7c7"
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_add_reply_vps
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_add_conn_info
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_add_authentication_attributes
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_add_authorization_attributes
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_add_certificate_attributes
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG StatsDClient.StatsClient - Formatted StatsD data=default.cp1-laxa.radius.auth.failure:1|c
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG StatsDClient.StatsClient - Sending StatsD request=default.cp1-laxa.radius.auth.failure:1|c
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG StatsDClient.StatsClient - Formatted StatsD data=default.cp1-laxa.radius.auth.count:1|c
2016-11-29 13:49:53,688	[main SessId R0000008c-01-583df7c7] DEBUG StatsDClient.StatsClient - Sending StatsD request=default.cp1-laxa.radius.auth.count:1|c
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 r=psauto-1479775612-298 h=58 r=R0000008c-01-583df7c7] INFO Common.EndpointTable - Returning NULL (EndpointPtr) for macAddr 68f7288d6039
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 r=psauto-1479775612-298 h=58 r=R0000008c-01-583df7c7] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3003 entity id = 29
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 r=psauto-1479775612-298 h=58 r=R0000008c-01-583df7c7] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3003
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 r=psauto-1479775612-298 h=58 r=R0000008c-01-583df7c7] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3003|entityId=29
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 r=psauto-1479775612-298 h=58 r=R0000008c-01-583df7c7] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3003|entity=Device
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 r=psauto-1479775612-298 h=58 r=R0000008c-01-583df7c7] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser)
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 r=psauto-1479775612-298 h=58 r=R0000008c-01-583df7c7] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser)
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 r=psauto-1479775612-298 h=58 r=R0000008c-01-583df7c7] INFO TAT.EndpointTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Endpoint)
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 r=psauto-1479775612-298 h=58 r=R0000008c-01-583df7c7] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User)
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started ***
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction **
2016-11-29 13:49:53,690	[RequestHandler-2-0x7ff61353d700 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping **
2016-11-29 13:49:53,691	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction **
2016-11-29 13:49:53,691	[RequestHandler-2-0x7ff61353d700 h=2606 c=R0000008c-01-583df7c7] INFO Core.PETaskRoleMapping - Roles: Other]
2016-11-29 13:49:53,691	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping **
2016-11-29 13:49:53,691	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult **
2016-11-29 13:49:53,692	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult **
2016-11-29 13:49:53,692	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement **
2016-11-29 13:49:53,693	[RequestHandler-2-0x7ff61353d700 h=2609 c=R0000008c-01-583df7c7] INFO Core.PETaskEnforcement - EnfProfiles: Allow Access Profile]
2016-11-29 13:49:53,693	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement **
2016-11-29 13:49:53,693	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder **
2016-11-29 13:49:53,693	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskRadiusCoAEnfProfileBuilder **
2016-11-29 13:49:53,693	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder **
2016-11-29 13:49:53,693	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskAgentEnfProfileBuilder **
2016-11-29 13:49:53,693	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskPostAuthEnfProfileBuilder **
2016-11-29 13:49:53,693	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskGenericEnfProfileBuilder **
2016-11-29 13:49:53,693	[RequestHandler-2-0x7ff61353d700 h=2615 c=R0000008c-01-583df7c7] INFO Core.PETaskGenericEnfProfileBuilder - getApplicableProfiles: No App enforcement (Generic) profiles applicable for this device
2016-11-29 13:49:53,696	[RequestHandler-2-0x7ff61353d700 h=2610 c=R0000008c-01-583df7c7] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT
2016-11-29 13:49:53,696	[RequestHandler-2-0x7ff61353d700 h=2610 c=R0000008c-01-583df7c7] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: Allow Access Profile]
2016-11-29 13:49:53,696	[RequestHandler-2-0x7ff61353d700 h=2610 c=R0000008c-01-583df7c7] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 0
2016-11-29 13:49:53,696	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskGenericEnfProfileBuilder **
2016-11-29 13:49:53,696	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2614 c=R0000008c-01-583df7c7] WARN Core.PETaskPostAuthEnfProfileBuilder - handleHttpResponseEv: Fetching Radius attributes from battery failed, errMsg=
2016-11-29 13:49:53,696	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2614 c=R0000008c-01-583df7c7] INFO Core.PETaskPostAuthEnfProfileBuilder - getApplicableProfiles: No Post auth enforcement profiles applicable for this device
2016-11-29 13:49:53,696	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskAgentEnfProfileBuilder **
2016-11-29 13:49:53,696	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder **
2016-11-29 13:49:53,697	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskCliEnforcement **
2016-11-29 13:49:53,697	[RequestHandler-2-0x7ff61353d700 h=2616 c=R0000008c-01-583df7c7] INFO Core.PETaskCliEnforcement - startHandler: No commands for CLI enforcement
2016-11-29 13:49:53,697	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2611 c=R0000008c-01-583df7c7] WARN Core.PETaskRadiusCoAEnfProfileBuilder - handleHttpResponseEv: Fetching Radius attributes from battery failed, errMsg=
2016-11-29 13:49:53,697	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder **
2016-11-29 13:49:53,697	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskPostAuthEnfProfileBuilder **
2016-11-29 13:49:53,697	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskCliEnforcement **
2016-11-29 13:49:53,697	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskRadiusCoAEnfProfileBuilder **
2016-11-29 13:49:53,697	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo **
2016-11-29 13:49:53,697	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes **
2016-11-29 13:49:53,697	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog **
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] DEBUG StatsDClient.StatsClient - Formatted StatsD data=default.cp1-laxa.radius.policyeval.time:11|ms
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] DEBUG StatsDClient.StatsClient - Sending StatsD request=default.cp1-laxa.radius.policyeval.time:11|ms
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] INFO RadiusServer.Radius - Policy Evaluation time = 11 ms
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_add_resp_attrs
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] INFO RadiusServer.Radius - rlm_policy: Received Accept Enforcement Profile
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: Request rejected. Not adding Class attribute.
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - Request Policy Evaluation Status: 1, Request Status: 3
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - rlm_policy: policy_release_polsvr_conn: Release Id: 0, handle: 0x9e1790
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcallpost-auth]: module "policy" returns reject for request 0
2016-11-29 13:49:53,699	[main SessId R0000008c-01-583df7c7] DEBUG RadiusServer.Radius - modcall: leaving group REJECT (returns reject) for request 0
2016-11-29 13:49:53,699	[RequestHandler-2-0x7ff61353d700 h=2618 c=R0000008c-01-583df7c7] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs
2016-11-29 13:49:53,699	[RequestHandler-2-0x7ff61353d700 h=2618 c=R0000008c-01-583df7c7] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2016-11-29 13:49:53,699	[RequestHandler-2-0x7ff61353d700 h=2617 c=R0000008c-01-583df7c7] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2016-11-29 13:49:53,700	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog **
2016-11-29 13:49:53,700	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes **
2016-11-29 13:49:53,700	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo **
2016-11-29 13:49:53,700	[RequestHandler-2-0x7ff61353d700 r=R0000008c-01-583df7c7 h=2604 c=R0000008c-01-583df7c7] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed ***