Error : Policy Server Execution time exceeded threshold with Oracle ODBC User Store
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 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 =
myHost source = /opt/CA/siteminder/log/smps.log
sourcetype = smps
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 =
myHost 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
'[email protected]'][][Auth scheme has disambiguated user to DN
'[email protected]'][][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
CXH9M5Glc3Lt9iRfgMvAbAkpLbQTu/+db11VTcA0+jZic4WEpP8bS1cqLt4gztkZ2sBUCIHdX7srL67I
oBRWXVQPnF+B11uv6gBuDx1gpk5JHtxJ+D0QGGr/AhQbRZ9421djLIri/9xvn4aCMAsYeeFZqo4VBQdX
Lfoeid3GGQJxG3VkaoZqf9IhFQe+S5O/+klVn6Me+++bGuwk1u2sFifeSUyielvgFUMldwTsoq7aT9oN
gDadGkNQg7xrco6wPiLNJig7yDd/1tGfAyxg+CEvfa74VU83HiNYa+CoqGHZ04aEJ4hWOrvheCde8oz6
TVhnQRb3hMjlrMPUndn4+iWhgWPehYJEjZKSSsl8t6WcB5rJG0OU9Kv08K2Dhxs9Wt3m+S/ehEVELd8D
Lbh9HkxPIasXL7RsclbHDLbEWjAJSOQaIhXXS0j36kIM1h1rkX0GMlKE5svQiboxfGHF9EdiYetRrBaY
C6lIiu6q4BcpY8p9Fe9MC0pau8B9ygpsv5NEf+3g2ajW7FOfXzokSvy0wfZ3BXfXUH5x4DWYMesJ80ub
bfCZ24m6sBpY3uhcBK6ksA2Ko8Vk2I1cj7fXcJ6qQ=' where EMAIL_ADDRESS = '[email protected]']
[][][]
The Policy Server reports a time out around 30 seconds later :
[][26166][139944748095232][09/07/2021][06:19:45][06:19:45.075][][][][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][][][][][][][]
And 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][][][][][][][]
And 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][][][][][][][]
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 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
twCXH9M5Glc3Lt9iRfgMvAbAkpLbQTu/+db11VTcA0+jZic4WEpP8bS1cqLt4gztkZ2sBUCIHdX7srL6
7IoBRWXVQPnF+B11uv6gBuDx1gpk5JHtxJ+D0QGGr/AhQbRZ9421djLIri/9xvn4aCMAsYeeFZqo4VBQ
dXLfoeid3GGQJxG3VkaoZqf9IhFQe+S5O/+klVn6Me+++bGuwk1u2sFifeSUyielvgFUMldwTsoq7aT9
oNgDadGkNQg7xrco6wPiLNJig7yDd/1tGfAyxg+CEvfa74VU83HiNYa+CoqGHZ04aEJ4hWOrvheCde8o
z6TVhnQRb3hMjlrMPUndn4+iWhgWPehYJEjZKSSsl8t6WcB5rJG0OU9Kv08K2Dhxs9Wt3m+S/ehEVELd
8DLbh9HkxPIasXL7RsclbHDLbEWjAJSOQaIhXXS0j36kIM1h1rkX0GMlKE5svQiboxfGHF9EdiYetRrB
aYC6lIiu6q4BcpY8p9Fe9MC0pau8B9ygpsv5NEf+3g2ajW7FOfXzokSvy0wfZ3BXfXUH5x4DWYMesJ80
ubbfCZ24m6sBpY3uhcBK6ksA2Ko8Vk2I1cj7fXcJ6qQ='
where EMAIL_ADDRESS = '[email protected]''). 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][][][][][][][]
And 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 "myHost" :
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 myHost]
[][][][][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 in timely manner.
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
jZic4WEpP8bS1cqLt4gztkZ2sBUCIHdX7srL67IoBRWXVQPnF+B11uv6gBuDx1gpk5JHtxJ+D0QGGr
/AhQbRZ9421djLIri/9xvn4aCMAsYeeFZqo4VBQdXLfoeid3GGQJxG3VkaoZqf9IhFQe+S5O/+klVn
6Me+++bGuwk1u2sFifeSUyielvgFUMldwTsoq7aT9oNgDadGkNQg7xrco6wPiLNJig7yDd/1tGfAyx
g+CEvfa74VU83HiNYa+CoqGHZ04aEJ4hWOrvheCde8oz6TVhnQRb3hMjlrMPUndn4+iWhgWPehYJEj
ZKSSsl8t6WcB5rJG0OU9Kv08K2Dhxs9Wt3m+S/ehEVELd8DLbh9HkxPIasXL7RsclbHDLbEWjAJSOQ
aIhXXS0j36kIM1h1rkX0GMlKE5svQiboxfGHF9EdiYetRrBaYC6lIiu6q4BcpY8p9Fe9MC0pau8B9y
gpsv5NEf+3g2ajW7FOfXzokSvy0wfZ3BXfXUH5x4DWYMesJ80ubbfCZ24m6sBpY3uhcBK6ksA2Ko8V
k2I1cj7fXcJ6qQ='
where EMAIL_ADDRESS = '[email protected]'
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
jZic4WEpP8bS1cqLt4gztkZ2sBUCIHdX7srL67IoBRWXVQPnF+B11uv6gBuDx1gpk5JHtxJ+D0QGGr
/AhQbRZ9421djLIri/9xvn4aCMAsYeeFZqo4VBQdXLfoeid3GGQJxG3VkaoZqf9IhFQe+S5O/+klVn
6Me+++bGuwk1u2sFifeSUyielvgFUMldwTsoq7aT9oNgDadGkNQg7xrco6wPiLNJig7yDd/1tGfAyx
g+CEvfa74VU83HiNYa+CoqGHZ04aEJ4hWOrvheCde8oz6TVhnQRb3hMjlrMPUndn4+iWhgWPehYJEj
ZKSSsl8t6WcB5rJG0OU9Kv08K2Dhxs9Wt3m+S/ehEVELd8DLbh9HkxPIasXL7RsclbHDLbEWjAJSOQ
aIhXXS0j36kIM1h1rkX0GMlKE5svQiboxfGHF9EdiYetRrBaYC6lIiu6q4BcpY8p9Fe9MC0pau8B9y
gpsv5NEf+3g2ajW7FOfXzokSvy0wfZ3BXfXUH5x4DWYMesJ80ubbfCZ24m6sBpY3uhcBK6ksA2Ko8V
k2I1cj7fXcJ6qQ='
where EMAIL_ADDRESS = '[email protected]'
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
jZic4WEpP8bS1cqLt4gztkZ2sBUCIHdX7srL67IoBRWXVQPnF+B11uv6gBuDx1gpk5JHtxJ+D0QGGr
/AhQbRZ9421djLIri/9xvn4aCMAsYeeFZqo4VBQdXLfoeid3GGQJxG3VkaoZqf9IhFQe+S5O/+klVn
6Me+++bGuwk1u2sFifeSUyielvgFUMldwTsoq7aT9oNgDadGkNQg7xrco6wPiLNJig7yDd/1tGfAyx
g+CEvfa74VU83HiNYa+CoqGHZ04aEJ4hWOrvheCde8oz6TVhnQRb3hMjlrMPUndn4+iWhgWPehYJEj
ZKSSsl8t6WcB5rJG0OU9Kv08K2Dhxs9Wt3m+S/ehEVELd8DLbh9HkxPIasXL7RsclbHDLbEWjAJSOQ
aIhXXS0j36kIM1h1rkX0GMlKE5svQiboxfGHF9EdiYetRrBaYC6lIiu6q4BcpY8p9Fe9MC0pau8B9y
gpsv5NEf+3g2ajW7FOfXzokSvy0wfZ3BXfXUH5x4DWYMesJ80ubbfCZ24m6sBpY3uhcBK6ksA2Ko8V
k2I1cj7fXcJ6qQ='
where EMAIL_ADDRESS = '[email protected]'
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
jZic4WEpP8bS1cqLt4gztkZ2sBUCIHdX7srL67IoBRWXVQPnF+B11uv6gBuDx1gpk5JHtxJ+D0QGGr
/AhQbRZ9421djLIri/9xvn4aCMAsYeeFZqo4VBQdXLfoeid3GGQJxG3VkaoZqf9IhFQe+S5O/+klVn
6Me+++bGuwk1u2sFifeSUyielvgFUMldwTsoq7aT9oNgDadGkNQg7xrco6wPiLNJig7yDd/1tGfAyx
g+CEvfa74VU83HiNYa+CoqGHZ04aEJ4hWOrvheCde8oz6TVhnQRb3hMjlrMPUndn4+iWhgWPehYJEj
ZKSSsl8t6WcB5rJG0OU9Kv08K2Dhxs9Wt3m+S/ehEVELd8DLbh9HkxPIasXL7RsclbHDLbEWjAJSOQ
aIhXXS0j36kIM1h1rkX0GMlKE5svQiboxfGHF9EdiYetRrBaYC6lIiu6q4BcpY8p9Fe9MC0pau8B9y
gpsv5NEf+3g2ajW7FOfXzokSvy0wfZ3BXfXUH5x4DWYMesJ80ubbfCZ24m6sBpY3uhcBK6ksA2Ko8V
k2I1cj7fXcJ6qQ='
where EMAIL_ADDRESS = '[email protected]'
As per this page, the ORA-01013 means the client (Policy Server) ends
the request because of a timeout (1).
Environment
Policy Server 12.8 on OEL 6;
ODBC User Store on Oracle 12R2;
Resolution
- Investigate with the DB team why the database referenced in
"myDataSource" doesn't reply in timely manner;
Additional Information
(1)
ORA-01013: user requested cancel of current operation tips
The most common cause of ORA-01013 is timeouts.
http://www.dba-oracle.com/t_ora_01013_user_requested_cancel_of_current_operation.htm
Feedback
Yes
No
Powered by
