DB Transport Error - Policy Server ODBC Session Store failover

Products

SITEMINDER

Issue/Introduction

When 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 is getting higher, the Policy Server starts to answer to Web Agent requests slowly.

Policy Server reports this error checking availability of the Session Store:

LogMessage:ERROR:[sm-Server-07011] failed.Exception : Internal Error: DB Transport Error. Code is -4017 (DBMSG: <<<State = 08S01 Internal Code = -3114 - s>>>)

Environment

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

Cause

The fix mentioned in 12.8SP4 fits the Policy Server traces (1).

The failover on the secondary ODBC Store doesn't happen until the load ends around 13:07.

This is very similar to the same use case as per the DE433079:

smps.log

The <second> 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 '<second>'.
[17548/139795292153600][Tue Jul 14 2020 11:55:48][CSmDbSessionManager.cpp:550][INFO][sm-Server-04350] Using ODBC 'Session Data' data source '<primary>'.

At 13:04:32, the Policy Server reports the first error about ODBC connectivity:

[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 wait until 13:06:58 to see 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 '<second>'.
[17548/139794743031552][Tue Jul 14 2020 13:07:54][CSmDbSessionManager.cpp:148][INFO][sm-Server-04330]Failing over to 'Session Data' data source '<second>'.

Before 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][Enter function CServer::ProcessRequest][13:04:32][CServer.cpp:6186][CServer::ProcessRequest]
[07/14/2020][13:04:32.164][Connection <primary>: Changing object state 'Available' to state 'Active'.][13:04:32][CSmDbUtilities.cpp:806][CSmDbMonitoredClass::SetState]
[07/14/2020][13:04:32.164][Report connections status for data source '<primary>' and user '<admin>'][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][SQL Still Executing (Not expected if using syncronous connections.][13:04:32][CSmDbODBC.cpp:1535][CSmDbConnectionODBC::CheckForError]
[07/14/2020][13:04:32.439][We had to retry and the retry count is 0][13:04:32][CSmDbODBC.cpp:1769][InvokeSQLExecute]
[07/14/2020][13:04:32.455][Connection <primary>: Cancelling SQL call for SQLExecute on connection.][13:04:32][CSmDbODBC.cpp:541][CSmDbConnectionODBC::CancelSQLCall]
[07/14/2020][13:04:32.455][Connection <primary>: Changing object state 'Active' to state 'Hung'.][13:04:32][CSmDbUtilities.cpp:806][CSmDbMonitoredClass::SetState]
[07/14/2020][13:04:32.455][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][Connection <primary>: Changing object state 'Available' to state 'Active'.][13:04:32][CSmDbUtilities.cpp:806][CSmDbMonitoredClass::SetState]
[07/14/2020][13:04:32.455][Report connections status for data source '<primary>' and user '<admin>'][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][SQL Still Executing (Not expected if using syncronous connections.][13:04:32][CSmDbODBC.cpp:1535][CSmDbConnectionODBC::CheckForError]
[07/14/2020][13:04:32.456][We had to retry and the retry count is 1][13:04:32][CSmDbODBC.cpp:1769][InvokeSQLExecute]
[07/14/2020][13:04:32.471][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][** Status: Not Ok. Invalid session token][13:04:32][Sm_Az_Message.cpp:598][CSm_Az_Message::SendReply][s94/r2155][68I [...omitted for brevity...] A==]
[07/14/2020][13:04:32.907][Enter function CServer::ProcessRequest][13:04:32][CServer.cpp:6186][CServer::ProcessRequest]
[07/14/2020][13:04:32.908][Report connections status for data source '<primary>' and user '<admin>'][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][Report connections status for data source '<second>' and user '<admin>'][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][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][LogMessage:ERROR:[sm-Server-06007] failed. Error code : 3][13:04:32][SmSessionServer.cpp:571]
[07/14/2020][13:04:32.908][Report connections status for data source '<primary>' and user '<admin>'][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][** 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 '<primary>' and user '<admin>' [12 connections, 0 active with 0 sessions, 0 available, 12 hung, 0 starting.
[13:05:43.960 [Report connections status for data source '<second>' and user '<admin>' [1 connections, 0 active with 0 sessions, 0 available, 1 hung, 0 starting.
[07/14/2020][13:06:58.751][Connection <second>: Changing object state 'Available' to state 'Active'.][13:06:58][CSmDbUtilities.cpp:806][CSmDbMonitoredClass::SetState]
[07/14/2020][13:06:58.751][Report connections status for data source '<second>' and user '<admin>'][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 '<primary>' and user '<admin>' [12 connections, 0 active with 0 sessions, 0 available, 12 hung, 0 starting.
[13:06:58.751 [ Report connections status for data source '<second>' and user '<admin>' [1 connections, 0 active with 0 sessions, 1 available, 0 hung, 0 starting.

system_odbc.ini :

[<primary>]
Driver=/{home_policy_server}/odbc/lib/NSora28.so
Description=DataDirect 8.0 Oracle Driver
Logon=<admin>
Password=*******
HostName=<primary>.example.com
PortNumber=1111
ServiceName=<service>
CatalogOptions=0
ProcedureRetResults=0
EnableDescribeParam=0
EnableStaticCursorsForLongData=0
ApplicationUsingThreads=1
LoadBalancing=1
KeepAlive=1
LoadBalanceTimeout=300

[<second>]
Driver=/{home_policy_server}/odbc/lib/NSora28.so
Description=DataDirect 8.0 Oracle Driver
Logon=<admin>
Password=******
HostName=<second>.example.com
PortNumber=1111
ServiceName=<service>
CatalogOptions=0
ProcedureRetResults=0
EnableDescribeParam=0
EnableStaticCursorsForLongData=0
ApplicationUsingThreads=1
LoadBalancing=1
KeepAlive=1
LoadBalanceTimeout=300

Resolution

To fix the issue, upgrade the Policy Server to 12.8SP4 (1).

Additional Information

Defects Fixed in 12.8.04