Error : Policy Server Execution time exceeded threshold with Oracle ODBC User Store

book

Article ID: 224566

calendar_today

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