Symantec Access Management

Tuesday Tip by David Macedo, Senior Support Engineer, for 9-4-12


In the context of this note, SPS was used simply as a reverse proxy with no protection. Users were getting 500 errors on POSTs intermittently.

Product Name=CA SiteMinder Secure Proxy Server
FullVersion=12.00.0301.189

There were 2 environments setup with the SPS that had the 500 problem. Using a standard Apache Reverse Proxy in a 3rd environment did not have the 500 error. Also, it was interesting that, after the user received a 500, if they merely refreshed, the request would be successful.

In the access log, we could see identical working and non-working POST requests.

WORKING
[24/Aug/2012:00:12:33 -0400] "POST /Vital/Prostrakan/Lynx/Default.aspx?tabid=124 HTTP/1.1" 302 98478 https://securestg.xyz.com/Vital/Prostrakan/Lynx/Default.aspx?tabid=124 "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; InfoPath.2; .NET4.0C; .NET4.0E; MS-RTC LM8)"

NON-WORKING
[24/Aug/2012:00:15:23 -0400] "POST /Vital/Prostrakan/Lynx/Default.aspx?tabid=124 HTTP/1.1" 500 1057 https://securestg.xyz.com/Vital/Prostrakan/Lynx/Default.aspx?tabid=124 "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; InfoPath.2; .NET4.0C; .NET4.0E; MS-RTC LM8)"

Further digging led us to the match the timestamp with these errors in the web agent trace log. We can see the POST being made, then a message that the socket has been closed, so it retries. Then retries again noting that the “Unbuffered entity enclosing request can not be repeated.” On the 3rd and final attempt, we see that it throws an exception with the same error message.

[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][SmProxyRules.processRules][Dispatching to service FORWARD with url https://securestg.abc.dmz/Vital/Prostrakan/Lynx/Default.aspx?tabid=124]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][Noodle::service][Method is: POST Content length is: 2676]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][Noodle::doGet][Using responseblocksize = 500 KB]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][getInputRequestEntity][Sending Request Data using HttpPost]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][getInputRequestEntity][Using requestblocksize(in KBs) = 500]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][getInputRequestEntity][Content-Length header is present in Request]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][getConnectionWithTimeout][HttpConnection is created from pool]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][releaseConnection][Returning HTTPConnection back to Pool]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][doIt][Socket is closed]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][doIt][Retrying to send the request to backend web server.Retry count: 1]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][getConnectionWithTimeout][HttpConnection is created from pool]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][setRequestHeader][Need to preseve Proxy HOST Header.Sending Proxy Host to the backend web server]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][releaseConnection][Returning HTTPConnection back to Pool]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][doIt][Stream closed]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][doIt][Retrying to send the request to backend web server.Retry count: 2]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][releaseConnection][Backend has closed the connection.Closing stale connection]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][getConnectionWithTimeout][HttpConnection is created from pool]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][setRequestHeader][Need to preseve Proxy HOST Header.Sending Proxy Host to the backend web server]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][releaseConnection][Returning HTTPConnection back to Pool]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][doIt][Unbuffered entity enclosing request can not be repeated.]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][doIt][Retrying to send the request to backend web server.Retry count: 3]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][doIt][Tried to send the request to backend web server three times.Throwing the exception to client. ]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][releaseConnection][Backend has closed the connection.Closing stale connection]
[08/24/2012][00:15:23][3120][5844][43bdb1f0-010045b1-3f8a1ce0-a1dd70ac-811f191f-7][Noodle::doGet][proxy: org.apache.commons.httpclient.ProtocolException Unbuffered entity enclosing request can not be repeated.]

What was happening was that the backend connection had been closed. The SPS was then attempting to resend the POST to the backend, however the POST data itself was no longer available. The reason the refresh worked was that the POST data was resent from the browser, not the SPS.

Solution:

The solution was to enable this setting in the server.conf, ‘enablecachepostdata=yes’. With this, the POST data is cached and is available for resubmission to the backend.

References from the SPS Guide:

Caching POST Data
The following two parameters are included in the server.conf to enable POST
data caching and to set the size of cached data:

enablecachepostdata
Description: Specifies whether the SPS caches POST data.
Limits: Yes, No
Default: No

maxcachedpostdata
Description: Specifies the size (in KB) of the POST data to cache.
Limits: None
Default: 1024 KB

Hi,

Thanks for the useful info.

What are the disadvantages of enabling this value? Any performance drawbacks or other considerations?

Thanks in advance.

Geeshan

One of the key things is "Too Large of MaxCacheData" VS Java Memory Size. How much can be the value of MaxCacheData Size be defined in conjuction to JVM and / or anyother memory factors. I don't have an answer to this. However would like to seek thoughts from peers here.

Is there a defined formula that'd used to set this value, after computing what existing resource limits are available / set?

Regards

Hubert

Hi Hurbert,

Thanks for the reply.

Actually my scenario is different. It is not a java app. We have a SharePoint 2010 application protected by site minder and the ca agent for SharePoint works as the reverse proxy. We have a custom claims provider attached to the application which adds more claims to the SAML token.  When we enable this configuration we do not see 500 issue popping up. But when it is disabled it is intermittent and when started to popup, it happens for every user. Even SharePoint backend pages are not accessible. On HTTP error log on WFE we see 400 bad request and in IIS logs, there is nothing. it is not even hitting the IIS as per our understanding as failed request tracing gave us nothing. no log file at all.

Our infrastructure team is not keen on enabling this configuration based on the fact that it reduces the overall system performance. Further it causes another SharePoint file upload functionality to fail. They are in favor of resolving this from the SharePoint application level. Is there any possibility that this can be rwsolved at the application level?

Thanks.