Error : Policy Server Execution time exceeded threshold Error with Active Directory

book

Article ID: 194940

calendar_today

Updated On:

Products

CA Single Sign On Secure Proxy Server (SiteMinder) CA Single Sign On Agents (SiteMinder) CA Single Sign On Federation (SiteMinder) CA Single Sign On SOA Security Manager (SiteMinder) SITEMINDER

Issue/Introduction

 

When running a Policy Server this one reports the following message :

   Execution time exceeded threshold.

Cause

 

Enable the full log and traces (Profiler) on the Policy Server to get
the details of the slow transactions and to see what operation is
culprit.

After doing so, it looks like the backend Active Directory User Store
takes time to answer to the Policy Server and this is what delays the
transactions.

smps.log :

  [25818/139869457184512][Mon Jun 22 2020 04:47:02][SmAzMapping.cpp:2617]
  [INFO][sm-log-00000] Execution time exceeded threshold.
  (CSmAzMapping::SmValLocateUserEntry, 5072, 5000, agent=samlsp:mysp
  client= server= resource=/ action=visit user=)
  
smtracedefault.log :

  [][25818][139869457184512][06/22/2020][04:46:57][04:46:57.892][][][]
  [Dequeuing a Normal Priority message, from IP 10.0.0.1 with Port
  No 54540. Current count is 0][][][][ThreadPool::Run][CServer.cpp:1514]
  [][][][][][][]

  [][25818][139869457184512][06/22/2020][04:46:57][04:46:57.898][][][]
  [Starting DsServerCheckerThread][][][][CSmDsLdapConnMgr::StartCheck]
  [SmDsLdapConnMgr.cpp:1099][][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:01][04:47:01.899][][][]
  [Binding 'dir' connection to LDAP server bank #1: myuserstore.mydomain.com:636]
  [][][][CSmDsLdapProvider::InitDir][SmDsLdapProvider.cpp:1326]
  [][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.933][][][]
  [Binding 'dir' connection to LDAP server bank #1: myuserstore.mydomain.com:636]
  [][][][CSmDsLdapProvider::InitDir][SmDsLdapProvider.cpp:1326]
  [][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.948][][][]
  [Using Active Directory type][][][][SmldapPs_GetDirVersionPrivate]
  [SmLdapPs.cpp:1660][][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.948][][][]
  [Binding 'user' connection to LDAP server bank #1: myuserstore.mydomain.com:636]
  [][][][CSmDsLdapProvider::InitDir][SmDsLdapProvider.cpp:1456][][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.962][][][]
  [Unable to retrieve a UserObjectFilter attribute for UserDirectory myuserstore]
  [][][][CSmAzUserDirAttributesCache::Add][SmAzUserDirAttributesCache.cpp:568]
  [][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.962][][][]
  [Unable to retrieve a UserObjectClass attribute for UserDirectory myuserstore]
  [][][][CSmAzUserDirAttributesCache::Add][SmAzUserDirAttributesCache.cpp:580]
  [][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.963][][][]
  [Searching for 'Property' object with a search key in one domain][]
  [][][CSmObjProvider::Search][SmObjProvider.cpp:676][][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
  [Search failed][][][][CSmObjProvider::Search][SmObjProvider.cpp:717]
  [Object Not Found][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
  [attr pwdLastSet][][][][AddAttrValue][SmDsLdapProvider.cpp:1758][][]
  [][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
  [attr lockoutTime][][][][AddAttrValue][SmDsLdapProvider.cpp:1758][][
  ][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
  [attr accountExpires][][][][AddAttrValue][SmDsLdapProvider.cpp:1758]
  [][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
  [attr userAccountControl][][][][AddAttrValue]
  [SmDsLdapProvider.cpp:1758][][][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
  [attr objectclass][][][][AddAttrValue][SmDsLdapProvider.cpp:1758][]
  [][][][][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.964][][][]
  [Ldap Search callout succeeds.][][][][CSmDsLdapProvider::Search]
  [SmDsLdapProvider.cpp:2365][][][][][(Search) Retrieving attributes for:
  'CN=jsmith,OU=Users,DC=mydomain,DC=com, DC=com',
  Filter: 'objectclass=*'. Status: 1 matching objects.][][]

  [][25818][139869457184512][06/22/2020][04:47:02][04:47:02.967][][][]
  [LogMessage:INFO:[sm-log-00000] Execution time exceeded threshold.
  (CSmAzMapping::SmValLocateUserEntry, 5072, 5000, agent=samlsp:mysp
  client= server= resource=/ action=visit user=)]
  [][][][][SmAzMapping.cpp:2617][][][][][][][]

  [s1/r2][25818][139869457184512][06/22/2020][04:47:02][04:47:02.970][
  samlsp:mysp][][SiteMinder|Policy Server|myhost 55441|]
  [** Status: Validated. ][][][][CSm_Auth_Message::SendReply][
  Sm_Auth_Message.cpp:4902][][][][][][][]

Running the Policy Server Trace Analyser, the reports shows other
transaction taking time (1).

2020-06-29-smtracedefault.log-TransReport.pdf

11.1. Trans : Time Taken :6 sec

  __[06/22/2020][04:46:57.920][25818][139868898326272]
  [ Look up a cached object.][][04:46:57][][][][][][][CSmObjCache::Lookup]
  [SmObjCache.cpp:779][][][][][][][]

  __[06/22/2020][04:47:01.930][25818][139868898326272][ Binding 'dir' 
  connection to LDAP server bank #2: myuserstore:636][][04:47:01][][][]
  [][][][CSmDsLdapProvider::InitDir][SmDsLdapProvider.cpp:1326][][][][]
  [][][]

  __[06/22/2020][04:47:02.310][25818][139868898326272]
  [ Processing Attribute [Property = SM_AUTHENTICATIONLEVEL]
  [Trim Property = SM_AUTHENTICATIONLEVEL] [Separator =^]][][04:47:02]
  [][][][][][][GetPropIndex][SmAuthUser.cpp:2295][][][][][][][]
  
  __[06/22/2020][04:47:03.316][25818][139868898326272]
  [ Processing Attribute [Property = UUID] [Trim Property = UUID]
  [Separator = ^]][][04:47:03][][][][][][][GetPropIndex]
  [SmAuthUser.cpp:2295][][][][][][][]

  __[06/22/2020][04:47:03.374][25818][139868898326272]
  [ MyCustom SAML 2.0 Assertion Plugin: Done customizeAssertion][]
  [04:47:03][][][][][Done customizeAssertion][][ServerTrace]
  [SmAuthUser.cpp:782][][][][][][][]
  
  __[06/22/2020][04:47:04.349][25818][139868898326272]
  [ IsOk? Yes, Return 0 responses with 1 attributes added.][]
  [04:47:04][][][][][][][CSmAz::IsOk][SmAuthorization.cpp:1912]
  [][][][][][][]

11.2. Trans : Time Taken :6 sec

  __[06/22/2020][04:46:57.921][25818][139869446686464]
  [ Look up a cached object.][][04:46:57][][][][][][]
  [CSmObjCache::Lookup][SmObjCache.cpp:779][][][][][][][]

  __[06/22/2020][04:47:01.966][25818][139869446686464]
  [ Binding 'dir' connection to LDAP server bank #3: myuserstore:636]
  [][04:47:01][][][][][][][CSmDsLdapProvider::InitDir][SmDsLdapProvider.cpp:1326]
  [][][][][][][]

  __[06/22/2020][04:47:02.310][25818][139869446686464]
  [ Processing Attribute [Property = SM_AUTHENTICATIONLEVEL]
  [Trim Property = SM_AUTHENTICATIONLEVEL] [Separator =^]]
  [][04:47:02][][][][][][][GetPropIndex][SmAuthUser.cpp:2295][][][]
  [][][][]

  __[06/22/2020][04:47:03.317][25818][139869446686464]
  [ Processing Attribute [Property = UUID] [Trim Property = UUID]
  [Separator = ^]][][04:47:03][][][][][][][GetPropIndex]
  [SmAuthUser.cpp:2295][][][][][][][]

  __[06/22/2020][04:47:03.376][25818][139869446686464]
  [ MyCustom SAML 2.0 Assertion Plugin: Done customizeAssertion][]
  [04:47:03][][][][][Done customizeAssertion][][ServerTrace]
  [SmAuthUser.cpp:782][][][][][][][]

  __[06/22/2020][04:47:04.338][25818][139869446686464]
  [ IsOk? Yes, Return 0 responses with 1 attributes added.][]
  [04:47:04][][][][][][][CSmAz::IsOk][SmAuthorization.cpp:1912]
  [][][][][][][]

11.3. Trans : Time Taken :5 sec

  __[06/22/2020][04:46:57.937][25818][139869465577216]
  [ Look up a cached object.][][04:46:57][][][][][][][CSmObjCache::Lookup]
  [SmObjCache.cpp:779][][][][][][][]

  __[06/22/2020][04:47:02.044][25818][139869465577216]
  [ Using LDAP server bank #2][][04:47:02][][][][][][][CSmDsLdapProvider::InitDir]
  [SmDsLdapProvider.cpp:1523][][][][][][][]

  __[06/22/2020][04:47:02.044][25818][139869465577216][ Look up a cached object.][]
  [04:47:02][][][][][][][CSmObjCache::Lookup][SmObjCache.cpp:779][][][][][][][]

  __[06/22/2020][04:47:03.020][25818][139869465577216]
  [ Binding 'dir' connection to LDAP server bank #4: myuserstore:636][]
  [04:47:03][][][][][][][CSmDsLdapProvider::InitDir][SmDsLdapProvider.cpp:1326]
  [][][][][][][]

1.5. SrcLine Table ProcessRequest

  From SmObjCache.cpp:779 - Look up a cached object.
  To SmDsLdapProvider.cpp:1523 - Using LDAP server bank #1
  av time: 50,493 ms (min: 0 ms, max: 4118 ms),

  From SmObjCache.cpp:779 - Look up a cached object.
  To SmDsLdapProvider.cpp:1326 - Binding 'dir' connection to LDAP server bank #2: myuserstore.mydomain.com:636
  Called 6 Times av time: 2496,167 ms (min: 918 ms, max: 4081 ms),

  From SmDsLdapConnMgr.cpp:1099 - Starting DsServerCheckerThread
  To SmDsLdapProvider.cpp:1326 - Binding 'dir' connection to LDAP server bank #1: myuserstore.mydomain.com:636
  Called 2 Times av time: 2501,000 ms (min: 1001 ms, max: 4001 ms),


Environment

 

  Policy Server 12.8SP3 on RedHat 6;
  User Directory on Active Directory;

 

Resolution

 

Investigate the Active Directory performances to solve this issue.

 

Additional Information

 

(1)

   Siteminder Policy Trace Analysis

     Siteminder Policy Trace Analysis Tool
 
     Attached is a java Policy Log analysis tool that we have been using
     in CA Support for a while now for analysis of various SiteMinder
     logs.Siteminder Policy Trace Analysis Tool

     Attached is a java Policy Log analysis tool that we have been using
     in CA Support for a while now for analysis of various SiteMinder
     logs.
   
   https://community.broadcom.com/communities/community-home/digestviewer/viewthread?MID=824043#bm08008f22-0cbb-433d-916a-2dc4b1048062