Execution time exceeded threshold in Policy Server with Active Directory User Directory

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.

Environment

User Directory on Active Directory;

Cause

The "Execution time exceeded Threshold" is an indication of slower running transactions on the Policy Server side.

The Policy Server is configured to report these warnings by default every 5 seconds (this can be changed in the registry, please see link for more details (1).

To find out the reason behind a transaction taking time to complete, 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 a culprit.

In the sample below, it looks like the backend Active Directory User Store took time to reply back to the Policy Server which is what caused the transaction delay and resulted of the Execution time threshold messages to be printed.

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:<sp> 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: <ldap_user_store>.example.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: <ldap_user_store>.example.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: <ldap_user_store>.example.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 <ldap_user_store>][][][][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 <ldap_user_store>][][][][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=<user>,OU=Users,DC=example,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:<sp> client= server= resource=/ action=visit user=)][][][][][SmAzMapping.cpp:2617]

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

Running the Policy Server Trace Analyzer, the report shows other transaction taking time (2).

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: <ldap_user_store>: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][ <Custom> 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: <ldap_user_store>: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][ <Custom> 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: <ldap_user_store>: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: <ldap_user_store>.example.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: <ldap_user_store>.example.com:636
  Called 2 Times av time: 2501,000 ms (min: 1001 ms, max: 4001 ms),

Resolution

Investigate the Active Directory performances to solve this issue.