Configuring the SiteMinder Policy Server Trace (Profiler) to help find the cause of Bad S/R Requests

Products

• CA Single Sign On Secure Proxy Server (SiteMinder)
• CA Single Sign On SOA Security Manager (SiteMinder)
• CA Single Sign-On

Issue/Introduction

Description:

Sometimes the Policy Server Error Log (default name: smps.log) will have an error such as;

 	[1234/5678][Sun Nov 11 2012 10:30:00][Sm_Az_Message.cpp:210][ERROR] Bad s147/r258 request detected 

In order to find the cause of the error, you will need to cross reference the SMPS Error Log with the SMPS Trace (Profiler) Log, which contains the detailed information on the offending transaction.

Solution:

In order to solve why the bad S/R requests are happening and identify the root cause, we have to capture the information in two places.

The first place is the Error Log and the second is a properly configured Profiler Log.

Part A: Identifying what is in the SMPS Error Log

using the example line:

 	[1234/5678][Sun Nov 11 2012 10:30:00][Sm_Az_Message.cpp:210][ERROR] Bad s147/r258 request detected 

The first field of the line above, [1234/5678] is the Process and Thread IDs (Pid and Tid in the profiler)

The second field, [Sun Nov 11 2012 10:30:00] is the Date and Time (Date and Time in the profiler)

The third field, [Sm_Az_Message.cpp:210], is a notation of where this occurs in SiteMinder code

The fourth field, [ERROR] Bad s147/r258 request detected, is the error message which contains a Transaction ID (s147/r258)

Part B: How to properly configure your Policy Server Trace (Profiler)

1. Open your SMConsole AKA Policy Server Management Console. (Often referred to as the "stop light console")
   
   

   <Please see attached file for image>

   
   
   
2. Go to the Profiler Tab
   
   

   <Please see attached file for image>

   
   
   
3. Ensure the Profiler is Enabled
   
   It is enabled if a check mark appear next to "Enable Profiling"
   
   
4. Configure the Profiler as shown below:
   
   

   <Please see attached file for image>

   
   
   

   <Please see attached file for image>

   
   
   Please note the order.
   
   Date, PreciseTime, and Pid should always be the same size, and Tid should be relatively minor in changes. Same with TransactionID. thus this order helps make it much easier for a human to read and analyze.
   
   Please note, the above configuration is the absolute minimum necessary. It is better to use the following Data Field Selection as it includes data that is necessary should you need to attain support's assistance.
   
   

   <Please see attached file for image>

   
   
   
5. Save the configuration
   
   
6. Reproduce the issue
   
   
7. Check your profiler log

Part C: Profiler Example and Information

Here is an example of a good output from a Profiler logging transactions coming in from a Web Agent

In order, we have: IsProtected, IsAuthenticated and IsAuthoroized

[Date][PreciseTime][Pid][Tid][TransactionID][Message][Data]
...
[11/12/2012][11:13:06.604][2524][1676][s1/r3][Receive request attribute 208, data size is 9][127.0.0.1]
[11/12/2012][11:13:06.604][2524][1676][s1/r3][Receive request attribute 200, data size is 0][internal]
[11/12/2012][11:13:06.604][2524][1676][s1/r3][Receive request attribute 217, data size is 9][127.0.0.1]
[11/12/2012][11:13:06.604][2524][1676][s1/r3][Receive request attribute 201, data size is 25][/transpolar/employee/blah]
[11/12/2012][11:13:06.604][2524][1676][s1/r3][Receive request attribute 202, data size is 3][get]
[11/12/2012][11:13:06.604][2524][1676][s1/r3][** Received agent request.][internal]
...
[11/12/2012][11:13:08.524][2524][1676][s1/r4][Receive request attribute 208, data size is 9][127.0.0.1]
[11/12/2012][11:13:08.524][2524][1676][s1/r4][Receive request attribute 200, data size is 0][internal]
[11/12/2012][11:13:08.524][2524][1676][s1/r4][Receive request attribute 217, data size is 9][127.0.0.1]
[11/12/2012][11:13:08.524][2524][1676][s1/r4][Receive request attribute 201, data size is 25][/transpolar/employee/blah]
[11/12/2012][11:13:08.524][2524][1676][s1/r4][Receive request attribute 202, data size is 3][get]
[11/12/2012][11:13:08.524][2524][1676][s1/r4][Receive request attribute 204, data size is 39][06-c5c24f6a-50b9-4f7d-8b5f-b66d6fd0d38a]
[11/12/2012][11:13:08.524][2524][1676][s1/r4][Receive request attribute 210, data size is 5][user1]
[11/12/2012][11:13:08.524][2524][1676][s1/r4][Receive request attribute 211, data size is 8][** Not Shown **]
[11/12/2012][11:13:08.524][2524][1676][s1/r4][** Received request from agent][]
...
[11/12/2012][11:13:10.098][2524][1676][s1/r5][Receive request attribute 208, data size is 9][127.0.0.1]
[11/12/2012][11:13:10.098][2524][1676][s1/r5][Receive request attribute 200, data size is 0][internal]
[11/12/2012][11:13:10.098][2524][1676][s1/r5][Receive request attribute 217, data size is 9][127.0.0.1]
[11/12/2012][11:13:10.098][2524][1676][s1/r5][Receive request attribute 201, data size is 25][/transpolar/employee/blah]
[11/12/2012][11:13:10.098][2524][1676][s1/r5][Receive request attribute 202, data size is 3][get]
[11/12/2012][11:13:10.098][2524][1676][s1/r5][Receive request attribute 204, data size is 39][06-c5c24f6a-50b9-4f7d-8b5f-b66d6fd0d38a]
[11/12/2012][11:13:10.098][2524][1676][s1/r5][Receive request attribute 205, data size is 28][eTyKOZg+vBCYxr7zJiF8xsNDQYM=]
[11/12/2012][11:13:10.098][2524][1676][s1/r5][Receive request attribute 209, data size is 416]
[cJ0IZuRLGnsRmAY/TXRhjz3XHtcvyeh4UJQ4jRK6FV031ayFoIVVQURzo/vqKmijHRlUS3OXUWCjqj3mE1/O0vnnLWPASax1tSjx3yOaDaHZvs12ZUMU8+
4WvxrgxRCRYiil7k9GO1eopl6I2B1Yl9qwR4m6C3gxIsnJm418NSPQ64bl2EFt7MW2OBvQK8N12nX0UXdXj3K+HdXFfyGvWx0xS9530wtunfTHd+
WiaI7eJaPVNh/25dsbMqtHfO47uqo2/EyM1sO2wNAWq5eWPiExk2lkG6cPOPX1FZwLHr+YzMUv9QiOfUPEtzJG6T5G4E2YbMKyLPJiEYyrTZg4T5iSCm3fRe81I+
oCzVLBN9ZBZS9nrz1Gvv+f12taaZVrsNM+QRDUz0cht9Fr8gjXTXg4V1D+GWlV]
[11/12/2012][11:13:10.098][2524][1676][s1/r5][** Received agent request.][internal]

To help you understand the data passed to the Policy Server in the Message field ("Receive request attribute ...") of the request, please refer to this chart:

Request Attribute Number	Number Meaning
200	Agent Name
201	Resource
202	Action
204	Realm OID
205	Session ID
208	Client IP Address
209	Session Spec
210	User Name
211	User Password
212	Reason
217	Server

If any of the data in the received request attributes is corrupt or missing, the "Bad S/R" error message will be logged.

Part D: Common Causes

Common Cause 1:

Non-uniform use of "EncryptAgentName"

If "EncryptAgentName" is set to "no" in any one agent, then when you move to an agent with "EncryptAgentName" set to "yes", you will end up with Agent Name Corruption. The opposite is also true.

Thus all agents in a SSO environment must have "EncryptAgentName" set to the same value.

Common Cause 2:

Miscoded Custom Login Page

A Web Agent issues a 302 redirect for HTML Forms Based Authentication and includes in the query string, information necessary for processing the request.

The "out of the box" login.fcc uses special directive noted by $$ to grab the information passed in the query string making the values available in the subsequent post to the FCC.

        <input type=hidden name=target value="$$target$$">
        <input type=hidden name=smquerydata value="$$smquerydata$$">
        <input type=hidden name=smauthreason value="$$smauthreason$$">
        <input type=hidden name=smagentname value="$$smagentname$$">
        <input type=hidden name=postpreservationdata value="$$postpreservationdata$$">

If you are using a custom FCC, or other language page posting to an FCC, your Custom FCC form will need to use the above format, and if you are using an ASP, JSP, or other language, please ensure the above name-value pairs are obtained and passed to the SiteMinder FCC when posting the credentials.

Failure to include these will likely cause the bad S/R requests.

Environment

Release: SOASMU99000-12.5-SOA Security Manager-Upgrade
Component: