Error: Execution time exceeded threshold with ODBC User Store in PS
Article ID: 224566
Updated On:
Products
CA Single Sign On Agents (SiteMinder)
SITEMINDER
Issue/Introduction
When running Policy Server, this one reports info:
"Execution time exceeded threshold"
when the user accesses application /myApp/:
smps.log :
[26166/139944748095232][Tue Sep 07 2021 06:21:20][Sm_Auth_Message.cpp:1968][INFO][sm-log-00000] Execution time exceeded threshold. (CSm_Auth_Message::AuthenticateUser, 127041, 5000, agent=myAgent client= server= resource=/myApp/ action=get user=myUser) host = _host source = /opt/CA/siteminder/log/smps.log sourcetype = smps
Environment
Policy Server 12.8 on OEL 6;
ODBC User Store on Oracle 12R2;
Cause
The Policy Server reports the error in smps.log:
[26166/139944748095232][Tue Sep 07 2021 06:21:20][Sm_Auth_Message.cpp:1968][INFO][sm-log-00000] Execution time exceeded threshold. (CSm_Auth_Message::AuthenticateUser, 127041, 5000, agent=myAgent client= server= resource=/myApp/ action=get user=myUser) host = _host source = /opt/CA/siteminder/log/smps.log sourcetype = smps
smtracedefault.log :
Policy Server receives the request at 06:19:13.080:
[][26166][139944748095232][09/07/2021][06:19:13][06:19:13.080][][][][Enter function CServer::ProcessRequest][][][][CServer::ProcessRequest][CServer.cpp:6186][][][][][][][]
Policy Server loads the My Custom Authentication Scheme:
[][26166][139944748095232][09/07/2021][06:19:13][06:19:13.081][][][][myConnector: * My Custom Authentication Scheme Parameters *][][* My Custom Authentication Scheme Parameters *][][ServerTrace][SmAuthUser.cpp:782][][][][][][][]
[][26166][139944748095232][09/07/2021][06:19:13][06:19:13.081][][][][myConnector: Auth scheme has disambiguated user to DN 'myuser@example._com'][][Auth scheme has disambiguated user to DN 'myuser@example._com'][][ServerTrace][SmAuthUser.cpp:782][][][][][][][]
At 06:19:13.105, the Policy Server sends an update SQL request through the Data Source "myDataSource" to update the user's Password Data field:
[][26166][139944748095232][09/07/2021][06:19:13][06:19:13.105][][][][Connection myDataSource: Changing object state 'Available' to state 'Active'.][][][][CSmDbMonitoredClass::SetState][CSmDbUtilities.cpp:806][][][][][][][]
[][26166][139944748095232][09/07/2021][06:19:13][06:19:13.105][][][][Report connections status for data source 'myDataSource' and user 'mySmUser'][][4 connections, 1 active with 1 sessions, 3 available, 0 hung, 0 starting.][][CSmDbServerSession::GetConnection][CSmDbServerSession.cpp:629][][][][][][][]
[][26166][139944748095232][09/07/2021][06:19:13][06:19:13.105][][][][Leave function CSmDbServerSession::GetConnection][][][0][CSmDbServerSession::GetConnection][CSmDbServerSession.cpp:632][][][][][][][]
[][26166][139944748095232][09/07/2021][06:19:13][06:19:13.105][][][][Start processing SQL statement.][][][][CSmRecordset::Execute][CDb.cpp:312][][][][update SM_USERS_VIEW set SM_PASSWORD_DATA = 'dasdwwsdfasvghsdfasf/rV0XjtVO257/6[...omitted for brevity...]bfCZ24m6sBpY3uhcBK6ksA2Ko8Vk2I1cj7fXcJ6qQ=' where EMAIL_ADDRESS = 'myuser@example._com'][][][]
The Policy Server reports a time-out around 30 seconds later:
[][26166][139944748095232][09/07/2021][06:19:45][06:19:45.a075][][][][SQL Error.][][][-1][CSmDbConnectionODBC::CheckForError][CSmDbODBC.cpp:1468][[CA SSO][ODBC Oracle Wire Protocol driver]Timeout expired.][HYT00][][][][][]
[][26166][139944748095232][09/07/2021][06:19:45][06:19:45.075][][][][SQL Server BUSY or State with Error, so Retrying][][][-1][CSmDbConnectionODBC::CheckForError][CSmDbODBC.cpp:1513][[CA SSO][ODBC Oracle Wire Protocol driver]Timeout expired.][HYT00][][][][][]
[][26166][139944748095232][09/07/2021][06:19:45][06:19:45.076][][][][SQL Still Executing (Not expected if using syncronous connections.][][][][CSmDbConnectionODBC::CheckForError][CSmDbODBC.cpp:1547][][][][][][][]
[][26166][139944748095232][09/07/2021][06:19:45][06:19:45.076][][][][We had to retry and the retry count is 0][][][][InvokeSQLExecute][CSmDbODBC.cpp:1781][][][][][][][]
The Policy Server tries again the same request which ends with time out another 30 seconds later:
[][26166][139944748095232][09/07/2021][06:20:16][06:20:16.078][][][][SQL Error.][][][-1][CSmDbConnectionODBC::CheckForError][CSmDbODBC.cpp:1468][[CA SSO][ODBC Oracle Wire Protocol driver]Timeout expired.][HYT00][][][][][]
[][26166][139944748095232][09/07/2021][06:20:16][06:20:16.078][][][][SQL Server BUSY or State with Error, so Retrying][][][-1][CSmDbConnectionODBC::CheckForError][CSmDbODBC.cpp:1513][[CA SSO][ODBC Oracle Wire Protocol driver]Timeout expired.][HYT00][][][][][]
[][26166][139944748095232][09/07/2021][06:20:16][06:20:16.078][][][][SQL Still Executing (Not expected if using syncronous connections.][][][][CSmDbConnectionODBC::CheckForError][CSmDbODBC.cpp:1547][][][][][][][]
[][26166][139944748095232][09/07/2021][06:20:16][06:20:16.078][][][][We had to retry and the retry count is 1][][][][InvokeSQLExecute][CSmDbODBC.cpp:1781][][][][][][][]
The Policy Server tries again the same request which ends with time out another 30 seconds later:
[][26166][139944748095232][09/07/2021][06:20:48][06:20:48.073][][][][SQL Error.][][][-1][CSmDbConnectionODBC::CheckForError][CSmDbODBC.cpp:1468][[CA SSO][ODBC Oracle Wire Protocol driver]Timeout expired.][HYT00][][][][][]
[][26166][139944748095232][09/07/2021][06:20:48][06:20:48.073][][][][SQL Server BUSY or State with Error, so Retrying][][][-1][CSmDbConnectionODBC::CheckForError][CSmDbODBC.cpp:1513][[CA SSO][ODBC Oracle Wire Protocol driver]Timeout expired.][HYT00][][][][][]
[][26166][139944748095232][09/07/2021][06:20:48][06:20:48.073][][][][SQL Still Executing (Not expected if using syncronous connections.][][][][CSmDbConnectionODBC::CheckForError][CSmDbODBC.cpp:1547][][][][][][][]
The Policy Server first reports the transaction taking time:
[][26166][139944748095232][09/07/2021][06:21:20][06:21:20.085][][][][LogMessage:INFO:[sm-log-00000] Execution time exceeded threshold.(CSmDbConnectionODBC::DoExecute, 126979, 5000, agent=myAgent client= server= resource=/myApp/ action=get user=myUser)][][][][][CSmDbODBC.cpp:1965][][][][][][][]
And finally, the Policy Server ends the ODBC request with an error:
[][26166][139944748095232][09/07/2021][06:21:20][06:21:20.098][][][][Caught an exception 'Internal Error: Database error. Code is -4007 (DBMSG: <<<State = HYT00 Internal Code = 0 - s>>>)'][][][][CSmRecordset::Update] [CDb.cpp:729][Internal Error: Database error. Code is -4007 (DBMSG: <<<State = HYT00 Internal Code = 0 - s>>>)][][][][][][]
[][26166][139944748095232][09/07/2021][06:21:20][06:21:20.111][][][][LogMessage:ERROR:[sm-Odbc-00170] Database Error executing query ( 'update SM_USERS_VIEW set SM_PASSWORD_DATA = 'dasdwwsdfasvghsdfasf/rV0XjtVO257 [...omitted for brevity...] ubbfCZ24m6sBpY3uhcBK6ksA2Ko8Vk2I1cj7fXcJ6qQ='where EMAIL_ADDRESS = 'myuser@example._com''). Error: Internal Error: Database error. Code is -4007 (DBMSG: <<<State = HYT00 Internal Code = 0 - s>>>) .][][][][][SmDsOdbcProvider.cpp:3250][][][][][][][]
[][26166][139944748095232][09/07/2021][06:21:20][06:21:20.121][][][][Inactivate connection.][][][][CSmDbConnection::MakeInactive][CSmDbConnection.cpp:200][][][][][][][]
[][26166][139944748095232][09/07/2021][06:21:20][06:21:20.121][][][][Connection myDataSource: Changing object state 'Active' to state 'Available'.][][][][CSmDbMonitoredClass::SetState][CSmDbUtilities.cpp:806][][][][][][][]
[][26166][139944748095232][09/07/2021][06:21:20][06:21:20.121][][][][Release connection reference. ReferenceCount = '2'][][][][CSmDbConnection::ReleaseReference][CSmDbConnection.cpp:241][][][][][][][]
The user cannot get fully authenticated.
[s442/r2][26166][139944748095232][09/07/2021][06:21:20][06:21:20.122][myAgent][][myUser][** Status: Not Authenticated. ][][][][CSm_Auth_Message::SendReply][Sm_Auth_Message.cpp:4902][][][][][][][]
Policy Server is "_host":
smtracedefault.log :
[][3051][140010335278880][09/07/2021][06:35:37][06:35:37.560][][][][LogMessage:INFO:[sm-Server-02080] SiteMinder Policy Server is ready on _host][][][][][CServer.cpp:6100][][][][][][][]
The above transactions are reflected in the network traces. The network traces show that the request goes out of the Policy Server box, and the ODBC User Store doesn't reply promptly.
myTcpdump.pcap
Arrival Time: Sep 7, 2021 07:19:13.106011000 Romance Daylight Time
19039 383.879017 10.0.0.10 10.0.0.20 TCP 936 49395 -> 1521
[PSH, ACK] Seq=13848 Ack=18559 Win=1452 Len=882
update SM_USERS_VIEW set SM_PASSWORD_DATA =
'dasdwwsdfasvghsdfasf/rV0XjtVO257/6F020xpyDcgRZPoY0myZuG++ObEoCR0QFi+Un6u7tm1P [...omitted for brevity...] k2I1cj7fXcJ6qQ='
where EMAIL_ADDRESS = 'myuser@example._com'
Arrival Time: Sep 7, 2021 07:19:13.146309000 Romance Daylight Time
19042 383.919315 10.0.0.20 10.0.0.10 TCP 60 1521 -> 49395
[ACK] Seq=18559 Ack=14730 Win=1452 Len=0
Arrival Time: Sep 7, 2021 07:19:43.130323000 Romance Daylight Time
20416 413.903329 10.0.0.10 10.0.0.20 TCP 55 49395 -> 1521
[PSH, ACK, URG] Seq=14730 Ack=18559 Win=1452 Urg=1 Len=1
Arrival Time: Sep 7, 2021 07:19:43.130887000 Romance Daylight Time
20417 413.903893 10.0.0.20 10.0.0.10 TCP 60 1521 -> 49395
[ACK] Seq=18559 Ack=14731 Win=1452 Len=0
Arrival Time: Sep 7, 2021 07:19:45.074950000 Romance Daylight Time
20490 415.847956 10.0.0.10 10.0.0.20 TCP 65 49395 -> 1521
[PSH, ACK] Seq=14731 Ack=18570 Win=1452 Len=11
Arrival Time: Sep 7, 2021 07:19:45.075515000 Romance Daylight Time
20491 415.848521 10.0.0.20 10.0.0.10 TCP 60 1521 -> 49395
[ACK] Seq=18570 Ack=14742 Win=1452 Len=0
Arrival Time: Sep 7, 2021 07:19:45.075642000 Romance Daylight Time
20492 415.848648 10.0.0.20 10.0.0.10 TCP 158 1521 -> 49395
[PSH, ACK] Seq=18570 Ack=14742 Win=1452 Len=104
ORA-01013: user requested cancel of current operation
Arrival Time: Sep 7, 2021 07:19:45.076071000 Romance Daylight Time
20493 415.849077 10.0.0.10 10.0.0.20 TCP 936 49395 -> 1521
[PSH, ACK] Seq=14742 Ack=18674 Win=1452 Len=882
update SM_USERS_VIEW set SM_PASSWORD_DATA =
'dasdwwsdfasvghsdfasf/rV0XjtVO257/6F020xpyDcgRZPoY0myZuG++ObEoCR0QFi+Un6u7tm1P
[...omitted for brevity...]
k2I1cj7fXcJ6qQ='
where EMAIL_ADDRESS = 'myuser@example._com'
Arrival Time: Sep 7, 2021 07:20:16.078203000 Romance Daylight Time
21770 446.851209 10.0.0.20 10.0.0.10 TCP 158 1521 -> 49395
[PSH, ACK] Seq=18685 Ack=15636 Win=1452 Len=104
ORA-01013: user requested cancel of current operation
Arrival Time: Sep 7, 2021 07:20:16.078592000 Romance Daylight Time
21773 446.851598 10.0.0.10 10.0.0.20 TCP 936 49395 -> 1521
[PSH, ACK] Seq=15636 Ack=18789 Win=1452 Len=882
update SM_USERS_VIEW set SM_PASSWORD_DATA =
'dasdwwsdfasvghsdfasf/rV0XjtVO257/6F020xpyDcgRZPoY0myZuG++ObEoCR0QFi+Un6u7tm1P
[...omitted for brevity...]
k2I1cj7fXcJ6qQ='
where EMAIL_ADDRESS = 'myuser@example._com'
Arrival Time: Sep 7, 2021 07:20:48.072619000 Romance Daylight Time
23257 478.845625 10.0.0.20 10.0.0.10 TCP 158 1521 -> 49395
[PSH, ACK] Seq=18800 Ack=16530 Win=1452 Len=104
Arrival Time: Sep 7, 2021 07:20:48.088429000 Romance Daylight Time
23258 478.861435 10.0.0.10 10.0.0.20 TCP 936 49395 -> 1521
[PSH, ACK] Seq=16530 Ack=18904 Win=1452 Len=882
update SM_USERS_VIEW set SM_PASSWORD_DATA =
'dasdwwsdfasvghsdfasf/rV0XjtVO257/6F020xpyDcgRZPoY0myZuG++ObEoCR0QFi+Un6u7tm1P
[...omitted for brevity...]
k2I1cj7fXcJ6qQ='
where EMAIL_ADDRESS = 'myuser@example._com'
Per this page, the ORA-01013 means the client (Policy Server) ends the request because of a timeout (1).
Resolution
Investigate with the DB team why the database referenced in "myDataSource" doesn't reply in a timely manner;
Additional Information
Feedback
Yes
No
Powered by
