DB session store slow failover

book

Article ID: 197129

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 when Primary Session Store goes
down, then the Policy Server fails over the Second one and the
transaction response time are getting higher, the Policy Server starts
to answer to Web Agent request slowly.

We would like to understand why during failback SM is slowing down ?

 

Cause

 

The fix mentioned in 12.8SP4 fits the Policy Server traces. The
failover on the secondary ODBC Store doesn't happens until the load
ends around 13:07. This is very similar to the same use case as per
the DE433079 :

Defects Fixed in 12.8.04

  20067088, 31782950 DE433079 Policy Server fails to verify dead
  connections from SQL database. Policy Server failover fails due to
  this issue.

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_04.html

smps.log

The SecondarySessionStoreDB ODBC Session Store is down when the Policy
Server starts :

  [17548/139794843481856][Tue Jul 14 2020
  11:55:48][CSmDbUtilities.cpp:465][ERROR][sm-Odbc-00060] Failed to
  connect to datasource 'SecondarySessionStoreDB'.

  [17548/139795292153600][Tue Jul 14 2020
  11:55:48][CSmDbSessionManager.cpp:550][INFO][sm-Server-04350] Using
  ODBC 'Session Data' data source 'PrimarySessionStoreDB'.

At 13:04:32, the first error about ODBC connectivity is reported :

  [17548/139788357199616][Tue Jul 14 2020
  13:04:32][SmSSProvider.cpp:628][ERROR][sm-Server-07011]
  failed.Exception : Internal Error: DB Transport Error.  Code is
  -4017 (DBMSG: <<<State = 08S01 Internal Code = -3114 - s>>>)

and we have to wait until 13:06:58 to seem the Policy Server failing
over to the secondary database :

  [17548/139788940199680][Tue Jul 14 2020
  13:06:58][CSmDbSessionManager.cpp:148][INFO][sm-Server-04330]
  Failing over to 'Session Data' data source 'SecondarySessionStoreDB'.

  [17548/139794743031552][Tue Jul 14 2020
  13:07:54][CSmDbSessionManager.cpp:148][INFO][sm-Server-04330]
  Failing over to 'Session Data' data source 'SecondarySessionStoreDB'.

Before that, we see that once the Policy Server looses the connection
to the primary ODBC Session Store, it doesn't seem to check the
connectivity to the Second ODBC Session Store :

smtracedefault.log :

  [07/14/2020][13:04:32.163][17548][139788357199616]
  [Enter function CServer::ProcessRequest][13:04:32][][][][][][][][][][][][][][][]
  [CServer.cpp:6186][CServer::ProcessRequest][][][][][][][][][][][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.164][17548][139788357199616]
  [          Connection PrimarySessionStoreDB: Changing object state 'Available' to state 'Active'.]
  [13:04:32][][][][][][][][][][][][][][][][CSmDbUtilities.cpp:806]
  [CSmDbMonitoredClass::SetState][][][][][][][][][][][][][][][][][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.164][17548][139788357199616]
  [          Report connections status for data source 'PrimarySessionStoreDB' and user 'SMUSER']
  [13:04:32][][][][][][][][][][][][][][12 connections, 0 active with 0 sessions, 12 available, 0 hung, 0 starting.]
  [][CSmDbServerSession.cpp:629][CSmDbServerSession::GetConnection][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.439][17548][139788357199616]
  [          SQL Still Executing (Not expected if using syncronous connections.]
  [13:04:32][][][][][][][][][][][][][][][][CSmDbODBC.cpp:1535][CSmDbConnectionODBC::CheckForError]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.439][17548][139788357199616]
  [          We had to retry and the retry count is 0][13:04:32][][][][][][][][][]
  [][][][][][][CSmDbODBC.cpp:1769][InvokeSQLExecute][][][][][][][][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.455][17548][139788357199616]
  [        Connection PrimarySessionStoreDB: Cancelling SQL call for SQLExecute on connection.]
  [13:04:32][][][][][][][][][][][][][][][][CSmDbODBC.cpp:541][CSmDbConnectionODBC::CancelSQLCall]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.455][17548][139788357199616]
  [        Connection PrimarySessionStoreDB: Changing object state 'Active' to state 'Hung'.]
  [13:04:32][][][][][][][][][][][][][][][][CSmDbUtilities.cpp:806]
  [CSmDbMonitoredClass::SetState][][][][][][][][][][][][][][][][][][][][][][][][][]
  [][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.455][17548][139788357199616]
  [        LogMessage:ERROR:[sm-Server-07011] failed.Exception : Internal Error: DB Transport Error.  
  Code is -4017 (DBMSG: <<<State = 08S01 Internal Code = -3114 - s>>>)][13:04:32][]
  [][][][][][][][][][][][][][][SmSSProvider.cpp:628][][][][][][][][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.455][17548][139788357199616]
  [          Connection PrimarySessionStoreDB: Changing object state 'Available' to state 'Active'.]
  [13:04:32][][][][][][][][][][][][][][][][CSmDbUtilities.cpp:806][CSmDbMonitoredClass::SetState]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.455][17548][139788357199616]
  [          Report connections status for data source 'PrimarySessionStoreDB' and user 'SMUSER']
  [13:04:32][][][][][][][][][][][][][][12 connections, 5 active with 5 sessions, 5 available, 2 hung, 0 starting.]
  [][CSmDbServerSession.cpp:629][CSmDbServerSession::GetConnection][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.456][17548][139788357199616]
  [          SQL Still Executing (Not expected if using syncronous connections.]
  [13:04:32][][][][][][][][][][][][][][][][CSmDbODBC.cpp:1535][CSmDbConnectionODBC::CheckForError]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.456][17548][139788357199616]
  [          We had to retry and the retry count is 1][13:04:32][][][][][][][][][]
  [][][][][][][CSmDbODBC.cpp:1769][InvokeSQLExecute][][][][][][][][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.471][17548][139788357199616]
  [        LogMessage:ERROR:[sm-Server-07011] failed.Exception : State = 08S01 Internal Code = -3114 - s. 
  Error code -4017 Native code -3114][13:04:32][][][][][][][][][][][][][][][]
  [SmSSProvider.cpp:847][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]
  [][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.472][17548][139788357199616]
  [        ** Status: Not Ok. Invalid session token][13:04:32][][][][][][]
  [][][][][][][][][][Sm_Az_Message.cpp:598][CSm_Az_Message::SendReply][][]
  [][][s94/r2155][][][][][][][][][][][68IwDhrYOKTxtOpw4zH5di9Tfovf7rJ6o
  ohmuwON7lSldOwxatISUl1kVSTSGra7Z7osLZUgucupOQ30A1/i3wN/BkNDxLPPeh29V02ecyFsdMLyM
  dX+YRGiZ49efGwDEWwP5keCxEgcT4BxnQ1dOpZSCyFP1FJmhgBBUhQW4zR7+ag5lng9l1R+bltOZoID6
  15C5A==][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.907][17548][139788357199616]
  [Enter function CServer::ProcessRequest][13:04:32][][][][][][][][][][][][][][][]
  [CServer.cpp:6186][CServer::ProcessRequest][][][][][][][][][][][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.908][17548][139788357199616]
  [            Report connections status for data source 'PrimarySessionStoreDB' and user 'SMUSER']
  [13:04:32][][][][][][][][][][][][][][12 connections, 6 active with 6 sessions, 0 available, 6 hung, 0 starting.]
  [][CSmDbServerSession.cpp:629][CSmDbServerSession::GetConnection][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.908][17548][139788357199616]
  [            Report connections status for data source 'SecondarySessionStoreDB' and user 'SMUSER']
  [13:04:32][][][][][][][][][][][][][][1 connections, 0 active with 0 sessions, 0 available, 1 hung, 0 starting.]
  [][CSmDbServerSession.cpp:629][CSmDbServerSession::GetConnection][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.908][17548][139788357199616]
  [          LogMessage:ERROR:[sm-Server-07011] failed.Exception : 
  Unexpected error in database interface. Error code -1063][13:04:32][][][][][][]
  [][][][][][][][][][SmSSProvider.cpp:628][][][][][][][][][][][][][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.908][17548][139788357199616]
  [        LogMessage:ERROR:[sm-Server-06007] failed. Error code : 3][13:04:32][][]
  [][][][][][][][][][][][][][SmSessionServer.cpp:571][][][][][][][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.908][17548][139788357199616]
  [            Report connections status for data source 'PrimarySessionStoreDB' and user 'SMUSER']
  [13:04:32][][][][][][][][][][][][][][12 connections, 6 active with 6 sessions, 0 available, 6 hung, 0 starting.]
  [][CSmDbServerSession.cpp:629][CSmDbServerSession::GetConnection][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:04:32.909][17548][139788357199616]
  [          ** Status: Not Validated. Invalid session token][13:04:32][]
  [][][Invalid session token][][][][][][][][][][][][Sm_Auth_Message.cpp:4902]
  [CSm_Auth_Message::SendReply][][][][][s58/r1915][][][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [13:05:43.960 [            
  Report connections status for data source 'PrimarySessionStoreDB' and user 'SMUSER' 
  [12 connections, 0 active with 0 sessions, 0 available, 12 hung, 0 starting.

  [13:05:43.960 
  [            Report connections status for data source 'SecondarySessionStoreDB' and user 'SMUSER' 
  [1 connections, 0 active with 0 sessions, 0 available, 1 hung, 0 starting.

  [07/14/2020][13:06:58.751][17548][139788357199616]
  [                  Connection SecondarySessionStoreDB: Changing object state 'Available' to state 'Active'.]
  [13:06:58][][][][][][][][][][][][][][][][CSmDbUtilities.cpp:806][CSmDbMonitoredClass::SetState]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [07/14/2020][13:06:58.751][17548][139788357199616]
  [                  Report connections status for data source 'SecondarySessionStoreDB' and user 'SMUSER']
  [13:06:58][][][][][][][][][][][][][][1 connections, 0 active with 0 sessions, 1 available, 0 hung, 0 starting.]
  [][CSmDbServerSession.cpp:629][CSmDbServerSession::GetConnection][][][][][][][][]
  [][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][][]

  [13:06:58.751 
  [                  Report connections status for data source 'PrimarySessionStoreDB' and user 'SMUSER' 
  [12 connections, 0 active with 0 sessions, 0 available, 12 hung, 0 starting.
  [13:06:58.751 
  [                  Report connections status for data source 'SecondarySessionStoreDB' and user 'SMUSER' 
  [1 connections, 0 active with 0 sessions, 1 available, 0 hung, 0 starting.

system_odbc.ini :

  [PrimarySessionStoreDB]
  Driver=/opt/CA/siteminder/odbc/lib/NSora28.so
  Description=DataDirect 8.0 Oracle Driver
  Logon=SMUSER
  Password=*******
  HostName=myprimarydb.mydomain.com
  PortNumber=1111
  ServiceName=MYSERVICENAME
  CatalogOptions=0
  ProcedureRetResults=0
  EnableDescribeParam=0
  EnableStaticCursorsForLongData=0
  ApplicationUsingThreads=1
  LoadBalancing=1
  KeepAlive=1
  LoadBalanceTimeout=300

  [SecondarySessionStoreDB]
  Driver=/opt/CA/siteminder/odbc/lib/NSora28.so
  Description=DataDirect 8.0 Oracle Driver
  Logon=SMUSER
  Password=******
  HostName=mysecondarydb.mydomain.com
  PortNumber=1111
  ServiceName=MYSERVICENAME
  CatalogOptions=0
  ProcedureRetResults=0
  EnableDescribeParam=0
  EnableStaticCursorsForLongData=0
  ApplicationUsingThreads=1
  LoadBalancing=1
  KeepAlive=1
  LoadBalanceTimeout=300

 

Environment

 

  2 Policy Servers 12.8SP2 on RedHat 6;
  Session Store on ODBC Oracle 12c;

Resolution

 

To fix the issue, upgrade the Policy Server to 12.8SP4 in order to
benifit from fix :

Defects Fixed in 12.8.04

  20067088, 31782950 DE433079 Policy Server fails to verify dead
  connections from SQL database. Policy Server failover fails due to
  this issue.

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_04.html