Authentication freeze after Policy Server start

book

Article ID: 197975

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

 

We're running a Policy Server and 5 minutes after it starts, the
Policy Server becomes unresponsive randomly. When it happens, after
5 minutes, then the Policy Server resume to process request
normally.

How can we fix that ?

 

Cause

 

Analysing the Policy Server traces, we can see that the Normal queue
piles up at 12:49:39 to come down to normal 2 minutes later at
12:51:33 :

  |     Time | Amount Req. in Normal Queue |
  |----------+-----------------------------|
  | 12:49:39 |                           0 |
  | 12:49:39 |                           1 |
  | 12:49:39 |                           1 |
  | 12:49:39 |                           2 |
  | 12:49:39 |                           3 |
  |      ... |                             |
  | 12:51:31 |                         245 |
  | 12:51:32 |                         167 |
  |      ... |                             |
  | 12:51:33 |                          20 |
  | 12:51:33 |                           1 |
  | 12:51:33 |                           0 |

At 12:49:39, all threads are busy, and the thread 140471720466176
started 80 seconds before (12:48:19) as not finished yet, because
handling a Custom Authentication Scheme which seems running under
RedHat JVM, making several connections to LDAP, and following
referrals.

  |       Thread Nb | First Ldap call time |
  |-----------------+----------------------|
  | 140471720466176 |             12:48:19 |
  | 140471686895360 |             12:48:44 |
  | 140471586248448 |             12:48:55 |
  | 140471695288064 |             12:49:01 |
  | 140471603033856 |             12:49:02 |
  | 140471594641152 |             12:49:12 |
  | 140471703680768 |             12:49:17 |
  | 140471712073472 |             12:49:17 |
  | 140469813987072 |             12:49:20 |
  | 140469805594368 |             12:49:22 |
  | 140469797201664 |             12:49:24 |
  | 140469788808960 |             12:49:39 |

thread_000000-140471720466176.log :

  [07/08/2020][12:48:18][140471720466176][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:18][140471720466176][        Authenticating user.][Login][][][5][0][myCustomAuthenticationScheme][mytestuser][][/myapp/mypage.html][][][][myWebAgent][][]
  [07/08/2020][12:48:18][140471720466176][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:19][140471720466176][            Binding 'dir' connection to LDAP server bank #1: myldap.mydomain.com:636][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:19][140471720466176][            Binding 'user' connection to LDAP server bank #1: myldap.mydomain.com:636][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:19][140471720466176][          Return from call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:19][140471720466176][          LogMessage:INFO:[sm-JavaApi-01030] SmJVMSupport: Using the following JRE: /usr/java/default/jre/][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:19][140471720466176][            Unable to retrieve a UserObjectFilter attribute for UserDirectory myUserDirectory][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:19][140471720466176][            search filter is : (sAMAccountName=mytestuser)][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:19][140471720466176][            LDAP search of (sAMAccountName=mytestuser) took 0 seconds and 1547 microseconds][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:29][140471720466176][            Successful V3 Bind server][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:39][140471720466176][            Successful V3 Bind server][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:39][140471720466176][            Binding referred 'dir' connection to ForestDnsZones.mydomain.com:636][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:40][140471720466176][            Binding 'dir' connection to LDAP server bank #1: myotherldap.mydomain.com:636][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:41][140471720466176][            Binding 'user' connection to LDAP server bank #1: ldap3.mydomain.com:636][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:41][140471720466176][            Binding 'dir' connection to LDAP server bank #2: ldap4.mydomain.com:636][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:41][140471720466176][            Binding 'user' connection to LDAP server bank #2: ldap4.mydomain.com:636][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:41][140471720466176][            LDAP search of (sAMAccountName=mytestuser) took 0 seconds and 2013 microseconds][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:41][140471720466176][            Successful V3 Bind server][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:41][140471720466176][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:41][140471720466176][            Starting DsServerCheckerThread][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:41][140471720466176][            Starting DsServerCheckerThread][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:41][140471720466176][            Starting DsServerCheckerThread][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:52][140471720466176][          Return from call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:52][140471720466176][          Directory can not be contacted][][][][][][][][][][Active Directory 2008 SAIPEM][][][][][]
  [07/08/2020][12:48:53][140471720466176][            Binding 'user' connection to LDAP server bank #1: ldap-gc.mydomain.com:636][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:55][140471720466176][            LogMessage:ERROR:[sm-Ldap-01370] SmDsLdapConnMgr Bind. Server DomainDnsZones.mydomain.com : 636. Error 81-Can't contact LDAP server][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:56][140471720466176][          Directory can not be contacted][][][][][][][][][][Active Directory General Controler][][][][][]
  [07/08/2020][12:48:56][140471720466176][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:56][140471720466176][            Starting DsServerCheckerThread][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:56][140471720466176][            Starting DsServerCheckerThread][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:31][140471720466176][          Return from call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:36][140471720466176][              LogMessage:INFO:[sm-Server-03580] [CustomAuthenticationEni][][][][][][][][][][][][][][INFO ] SmAuthenticationResult instance in response from authentication => reason 0, Sm_AuthApi_NoUserContext (6)][]
  [07/08/2020][12:51:36][140471720466176][              Enter function CSmAuthUser::SavePasswordState][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:36][140471720466176][              Leave function CSmAuthUser::SavePasswordState][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:36][140471720466176][            Leave function CSmAuthUser::Authenticate][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:36][140471720466176][        Leave function CSm_Auth_Message::AuthenticateUser][][][][][][][][][][][][][][][]

thread_000000-140469788808960.log

  [07/08/2020][12:49:39][140469788808960][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:49:39][140469788808960][      Validate session and session type for the user.][][][][][][][myuid][][][Active Directory][][][][2][]
  [07/08/2020][12:49:39][140469788808960][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140469788808960][            Using LDAP server bank #2][][][][][][][][][][][][][][][]

thread_000000-140469797201664.log

  [07/08/2020][12:49:24][140469797201664][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:49:24][140469797201664][      Validate session and session type for the user.][][][][][][][myuid2][][][Active Directory][][][][2][]
  [07/08/2020][12:49:24][140469797201664][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140469797201664][            Using LDAP server bank #1][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140469797201664][          Return from call InitDir.][][][][][][][][][][][][][][][]

thread_000000-140469805594368.log

  [07/08/2020][12:49:22][140469805594368][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:49:22][140469805594368][      Validate session and session type for the user.][][][][][][][myuid3][][][myUserStore][][][][2][]
  [07/08/2020][12:49:22][140469805594368][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140469805594368][            Using LDAP server bank #2][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140469805594368][          Return from call InitDir.][][][][][][][][][][][][][][][]

thread_000000-140469813987072.log

  [07/08/2020][12:49:20][140469813987072][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:49:20][140469813987072][        Validate session and session type for the user.][Login][][][][][myCustomAuthenticationScheme][][][/myapp/myspecialpage.html][][][][myWebAgent][2][]
  [07/08/2020][12:49:20][140469813987072][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140469813987072][            Using LDAP server bank #1][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140469813987072][          Return from call InitDir.][][][][][][][][][][][][][][][]

thread_000000-140471586248448.log

  [07/08/2020][12:48:55][140471586248448][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:55][140471586248448][        Authenticating user.][myRealm][][][5][0][myAuthScheme][myUser4][][/webapp/myhome.html][][][][myotherwebagent][][]
  [07/08/2020][12:48:55][140471586248448][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:31][140471586248448][            Using LDAP server bank #1][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:31][140471586248448][          Return from call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:31][140471586248448][          LogMessage:INFO:[sm-Server-02750] Loaded authentication scheme myAuthScheme. Version 768 . SiteMinder(tm) myAuthScheme][][][][][][][][][][][][][][][]

thread_000000-140471594641152.log

  [07/08/2020][12:49:12][140471594641152][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:49:12][140471594641152][        Authenticating user.][Login][][][5][0][myCustomAuthenticationScheme][mytestuser][][/myapp/mypage.html][][][][myWebAgent][][]
  [07/08/2020][12:49:12][140471594641152][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471594641152][            Using LDAP server bank #1][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471594641152][          Return from call InitDir.][][][][][][][][][][][][][][][]

thread_000000-140471603033856.log

  [07/08/2020][12:49:02][140471603033856][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:49:02][140471603033856][      Validate session and session type for the user.][][][][][][][myuid2][][][Active Directory][][][][2][]
  [07/08/2020][12:49:02][140471603033856][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:32][140471603033856][            Using LDAP server bank #1][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:32][140471603033856][          Return from call InitDir.][][][][][][][][][][][][][][][]

thread_000000-140471686895360.log

  [07/08/2020][12:48:44][140471686895360][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:44][140471686895360][        Authenticating user.][Login][][][5][0][myCustomAuthenticationScheme][myuser5][][/myapp/myspecialpage.html][][][][myWebAgent][][]
  [07/08/2020][12:48:44][140471686895360][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:52][140471686895360][            Using LDAP server bank #1][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:52][140471686895360][          Return from call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:48:56][140471686895360][            LDAP search of (&(sAMAccountName=myuser5)(objectclass=*)) took 0 seconds and 1686 microseconds][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471686895360][            LDAP search of (&(sAMAccountName=myuser5)(objectclass=*)) took 0 seconds and 6460 microseconds][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:36][140471686895360][            LDAP search of (&(sAMAccountName=myuser5)(objectclass=*)) took 0 seconds and 22446 microseconds][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:36][140471686895360][  Leave function CServer::ProcessRequest][][][][][][][][][][][][][][][]

thread_000000-140471695288064.log

  [07/08/2020][12:49:01][140471695288064][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:49:01][140471695288064][      Validate session and session type for the user.][][][][][][][myuid][][][Active Directory][][][][2][]
  [07/08/2020][12:49:01][140471695288064][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:32][140471695288064][            Using LDAP server bank #2][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:32][140471695288064][          Return from call InitDir.][][][][][][][][][][][][][][][]

thread_000000-140471703680768.log

  [07/08/2020][12:49:17][140471703680768][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:49:17][140471703680768][        Authenticating user.][Login][][][5][0][myCustomAuthenticationScheme][myuser5][][/myapp/myspecialpage.html][][][][02srv001b3-auth-micrositi-www2-st][][]
  [07/08/2020][12:49:17][140471703680768][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471703680768][            Using LDAP server bank #1][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471703680768][          Return from call InitDir.][][][][][][][][][][][][][][][]
thread_000000-140471712073472.log
 
  [07/08/2020][12:49:17][140471712073472][Enter function CServer::ProcessRequest][][][][][][][][][][][][][][][]
  [07/08/2020][12:49:17][140471712073472][        Validate session and session type for the user.][Login][][][][][myCustomAuthenticationScheme][][][/myapp/myspecialpage.html][][][][myWebAgent][2][]
  [07/08/2020][12:49:17][140471712073472][          Start of call InitDir.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            Binding 'dir' connection to LDAP server bank #4: ldap4.mydomain.com:636][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            LogMessage:WARN:[sm-Ldap-02910] SSLv3 client protocol is disabled. If connection fails configure LDAP server to support TLS protocols.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            PRLDAP_OPT_IO_MAX_TIMEOUT set to 10000 milliseconds][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            PRLDAP_OPT_IO_MAX_TIMEOUT set to 22000 milliseconds][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            PRLDAP_OPT_IO_MAX_TIMEOUT set to 10000 milliseconds][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            Using Active Directory type][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            Retrieve an object from the object cache.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            Global Preferences:][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            Binding 'user' connection to LDAP server bank #4: ldap4.mydomain.com:636][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            LogMessage:WARN:[sm-Ldap-02910] SSLv3 client protocol is disabled. If connection fails configure LDAP server to support TLS protocols.][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            PRLDAP_OPT_IO_MAX_TIMEOUT set to 10000 milliseconds][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            PRLDAP_OPT_IO_MAX_TIMEOUT set to 10000 milliseconds][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][            Using LDAP server bank #4][][][][][][][][][][][][][][][]
  [07/08/2020][12:51:33][140471712073472][          Return from call InitDir.][][][][][][][][][][][][][][][]

smps.log

  [1221/140472182208320][Wed Jul 08 2020
  12:42:51][CServer.cpp:4072][INFO][sm-Server-03550] Version: 12.8;
  Update: 02.00; Build: 1992; CR: 00;

  [1221/140472182208320][Wed Jul 08 2020
  12:42:51][CServer.cpp:4858][INFO][sm-Server-02020] Thread pool
  limit: 12

  [1221/140470384858880][Wed Jul 08 2020
  12:43:39][SmPolicyServer.cpp:1879][INFO][sm-Server-00870] Journaling
  thread started, will delete commands older than 60 minutes

 

Environment

 

  Policy Server 12.8SP2 on RedHat 7;
  Policy Store on CA Directory 14.1;
  User Store on Active Directory;

 

Resolution

 

Upgrade the environment to the latest version to benefit the fix :

Defects Fixed in 12.8.03

  1241631 DE398424 "When Active Directory is configured with LDAP
  namespace, the LDAP searches intermittently receive referrals and
  thus there is an impact on processing time"

https://techdocs.broadcom.com/content/broadcom/techdocs/us/en/ca-enterprise-software/layer7-identity-and-access-management/single-sign-on/12-8/release-notes/service-packs/defects-fixed-in-12-8-03.html