SiteMinder Policy Server fails back to the Primary Policy Store at startup time.

Document ID : KB000052889
Last Modified Date : 14/02/2018
Show Technical Document Details

Description:

On restart the smps logs showed the following statements:

<- Begin

[23355/1][SmObjStore.cpp:1072] BulkFetch policy store
[23355/1][CSmDbSessionManager.cpp:157] Failing back to 
'Policy Store' data source 'SiteMinder Policy Data Source'.
[23355/1][SmObjCache.cpp:288]Preloading policy store cache
-> End

Review of the logs shows; Policy Server contacting to the Secondary Policy Store first, it then issues the Initialization and Bulk Fetch command. Just after that Policy Server Fails back to the primary Policy Store.

Questions: Why the policy Server is using the Second Datasource and then failing over to the Primary Policy Store?

Solution:

Profiler shows that the policy server activated the connection for the DataSource 'SiteMinder Policy Data Source2' first:

SiteMinder Policy Data Source:

<- Begin

[23355][10][20:23:20.607][Report connections status for data source 
'SiteMinder Policy Data Source' and user 'smeuser'][][1 connections,
 0 active with 0 sessions, 0 available, 0 hung, 1 starting.]
[23355][10][20:23:20.607][Leave function CSmDbServerSession::GetConnection][][][-1024]
-> End

SiteMinder Policy Data Source2:

<- Begin

[23355][10][20:23:20.607][Report connections status for data source
 'SiteMinder Policy Data Source2' and user 'smeuser'][][1 connections,
 1 active with 1 sessions, 0 available, 0 hung, 0 starting.]
[23355][10][20:23:20.607][Leave function CSmDbServerSession::GetConnection]
[23355][10][20:23:20.607][Queued Request has completed without timing out.]

-> End

In the first snippet, error 1024 means connection not available (SMDB_ERROR_CONNECTIONNOTAVAILABLE), since the connection was not available the Policy Server will use the connection from the second DataSource. The second snippet shows that the connection to the DataSource 'SiteMinder Policy Data Source2' was established.

Eventually the policy server established the connection to the first DataSource:

<- Begin

[23355][16][20:23:21.896][Result from driver connect is 1]
[23355][16][20:23:21.896][Result from unlocking the branded drivers is 0]
[23355][16][20:23:21.896][Result from get DBMS name('Oracle') is 0]
[23355][16][20:23:21][Connection SiteMinder Policy Data Source: Changing object state
 'Initialized' to state 'Available'.]
[23355][16][20:23:21][Established a connection to 'ODBC'server 'SiteMinder Policy Data Source'.]

-> End

Once the connection was established, the policy server failed back to the primary DataSource 'SiteMinder Policy Data Source':

<- Begin

[23355][1][20:23:22.303][Failing back to 'Policy Store' data source
 'SiteMinder Policy Data Source'.]
[23355][1][20:23:22.303][Starting clean up thread to clean connections
 to data source 'SiteMinder Policy Data Source2'.]
-> End

This is the expected behavior since the connection is still in process, until it changes to 'Available' state, we get the error -1024. Also the requests that need the connection will get queued and will be picked up later when the connection gets established.

The theory is that the primary policy store would be more utilized than secondary policy store, so it might take slightly longer time in responding back as compared to Secondary store.