Welcome to dumpsville. Population: your files!
You might have had this happen to you – an application is accessed via UAG, but the parsing doesn’t work as expected. Maybe some links are not signed, or perhaps the process fails and puts out a 500 error. Luckily, there are some tools at our disposal to handle a 500 error.
A 500 error is a server error, and could happen either on the backend server, or on UAG itself. When UAG requests a page from a backend server, and gets a 500 error, it will deliver it as-is to the user, but it may look no different than an error generated by UAG itself. The best way to know this is to get a UAG Server trace, which I discussed several times in the past (1, 2 and 3). In this situation, the keyword to look for is “transmit500”, which is the function that UAG executes when it is the one generating the error. In a trace, this would look like this:
[c]424.22e8 01/31/2012-10:26:27.849 [whlfilter WhlExt2IWS.cpp@1655] Entering CExtECB::Transmit500 called, (ExtECB=0000000009AD1270), (PFC=000000001336D248)
Once you see something like this, you would typically see the cause shortly before that line. It will often be hard to understand, as you can’t read the source code and may not know what it does, but it may give you some clue. For example, here’s a classic 500 error that comes up often:
[0]32b8.c94 05/26/2011-18:54:50.109 [whlhttpparser whlHttpParser::CHttpBaseParser::ParseChunkBody HttpBaseParser.cpp@1010] ERROR:Concat failed.
[0]32b8.c94 05/26/2011-18:54:50.109 [whlhttpparser whlHttpParser::CHttpBaseParser::ParseHttpBuffer HttpBaseParser.cpp@379] ERROR:<parser id: 455851> Caught CHttpMemException in ParseHttpBuffer
[0]32b8.c94 05/26/2011-18:54:50.109 [whlfilter CExtECB::OnRead WhlExt2IWS.cpp@5868] ERROR:OnRead(10.210.90.28:80, 00000000036629B0): out-of-memory exception from HttpParser (Error: CHttpBaseParser::ParseChunkBody - Concat failed.) (ExtECB=000000002061BD20), (PFC=000000000EB177B8)
[0]32b8.c94 05/26/2011-18:54:50.109 [whlfilter CExtECB::OnRead WhlExt2IWS.cpp@5897] ERROR:OnRead(00000000036629B0): dwStatus <[!0x1F9!]>. (ExtECB=000000002061BD20), (PFC=000000000EB177B8)
[0]32b8.c94 05/26/2011-18:54:50.109 [whlfilter WhlExt2IWS.cpp@1437] Entering CExtECB::EndISAPIRequest called, (ExtECB=000000002061BD20), (PFC=000000000EB177B8)
[0]32b8.c94 05/26/2011-18:54:50.109 [whlfilter CExtECB::EndISAPIRequest WhlExt2IWS.cpp@1443] Info:closing with status <505>. (ECB=0000000014481BF8), (ExtECB=000000002061BD20), (PFC=000000000EB177B8)
[0]32b8.c94 05/26/2011-18:54:50.109 [whlfilter WhlExt2IWS.cpp@1631] Entering CExtECB::Transmit500 called, (ExtECB=000000002061BD20), (PFC=000000000EB177B8)
The above happens because UAG’s file parsing buffer is set to 10 MB by default, so if it tries to parse a file that’s larger, it will cause an exception (this is common with SharePoint servers hosting large documents). The solution is discussed here.
When analyzing such a trace, keep in mind that the PFC code listed in the error (000000001336D248 above) can help you find out which URL was the trigger, if you are not sure. All you have to do is search the content of the trace for the string “request from client to filter (PFC=000000001336D248)”, adjusting the PFC number according to what you saw in the error. This line is where the request process starts, and will reveal the URL and more details. For example:
[c]424.26c 01/31/2012-10:26:27.307 [whlfilter TraceAllHeaders FilterLog.cpp@547] Info:------- request from client to filter (PFC=000000001336D248)------
[c]424.26c 01/31/2012-10:26:27.307 [whlfilter TraceAllHeaders FilterLog.cpp@549] Info:Protocol : HTTPS
[c]424.26c 01/31/2012-10:26:27.307 [whlfilter TraceAllHeaders FilterLog.cpp@553] Info:URL : /uniquesig64be21cd0900ce816deb731ea4e8e2cd23c028aabc68e88da 93a5df01779e70c/uniquesig1/exchange/
[c]424.26c 01/31/2012-10:26:27.307 [whlfilter TraceAllHeaders FilterLog.cpp@554] Info:Method : GET
[c]424.26c 01/31/2012-10:26:27.307 [whlfilter TraceAllHeaders FilterLog.cpp@555] Info:Version : HTTP/1.1
[c]424.26c 01/31/2012-10:26:27.307 [whlfilter TraceAllHeaders FilterLog.cpp@571] Info:Connection: Keep-Alive
Accept: */*
Accept-Encoding: gzip, deflate
Accept-Language: en-US
Cookie: uniquesigC5D96768A45A2ACD24BAE292A00BFC8DA9DC41 E83EF7D099C02BCB5E630A0D8AC99799AF D3608641DC207E0A396AB7A7=MPGLHDEPDPAAHACKAMHDMGDC; OutlookSession=31a37744c2254b72808759baaca74e7b; HATServerCookie=uniquesig6816deb88da13a5dcd0ea4e8e2cd23c0738aabc68e 29900cf017794be21e e70c/uniquesig1; uniquesigE633B201E0B8F5B1E7626A160F1532D762E68 AF7597799FBB348AE35612572B78E6714AE737555A994F802744B207B0B=-49a4-9697-a0eee3f059c9a4c-39835155f:0x409; dwLastDetectionTimestamp=2012,0,31,10,21,49,0; WhlWinTitle=Microsoft%20Outlook%20Web%20Access; NLSessionSmail=L/lZ7Cu1VJ/9x45Wwurh/W5RVhvsrnVDyCwU8Cfz/eA+THWJ2ED0hq/IHW6Y3mVHtaOdbHluWUCLN+0IYBjSIuL2/ueoTCPyaTTvfutJ0JudE2P44Qu+KjcvkHO7jsJB; WhlPII=2
Host: owa.createhive.com
Referer: https:// owa.createhive.com/uniquesig6cfe229473b55191fbfd6d69a3 d399c 6/uniquesig0/InternalSite/Validate.asp
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; Trident/5.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; MS-RTC EA 2; .NET4.0C; .NET4.0E; MS-RTC LM 8)
(The signatures and data are scrambled, so don’t look for too much logic in the example above beyond the general structure)
Keep in mind, though, that the PFC codes are recycled once a request is completed, so if you find multiple client requests with the same PFC, this is normal. Simply look for the last request with that PFC before the error is generated.
If your trace doesn’t contain the keyword transmit500, then it typically means the backend server is the party that generated it, and in the trace, it will usually look like this:
[0]179c.1748 05/11/2011-13:10:27.030 [whlfilter CExtECB::OnRecvSrvrDataCompleted WhlExt2IWS.cpp@3227] Info:Response from RWS to filter (ExtECB=0000000005370020), (PFC=00000000064108C8) ---[HTTP/1.1 500 Internal Server Error
Here you can see the RWS (remote web server) response is the 500 error. The next step will be to figure out why, by inspecting the logs on the remote server. Hopefully, it will provide as much information as UAG does.
Another tool at our disposal in case of errors like these is the SRA Dump. This is a built in function of UAG, which saves a copy of every file parsed by UAG to the local hard drive, both before parsing, and after it. This can be very useful, as it shows you the data received by UAG in its entirety, so if there’s anything wrong with it (malformatted data, for example), you would be able to see it.
Before using the SRA Dump, please keep in mind that it generates a huge amount of data, which can fill up your hard drive rapidly. This also puts a lot of strain on your hard drive and CPU. If you need to do this, make sure you do so sparingly and carefully, and never leave an in-production server with this on without a babysitter.
To enable the SRA dump:
1. On the UAG Server, create folder for the dumps (anywhere is fine, provided ample disk space is available)
2. open registry editor and go to HKLM\SOFTWARE\WhaleCom\e-Gap\von\UrlFilter\WhlFiltSecureRemote
3. Create a new string value called "DumpFilePath" with a value of the location you created in step 1. For example:
4. Exit the registry editor
5. Reset IIS by typing IISRESET in a CMD prompt
6. The dump folder will start filling up with files:
7. Once all is done, remove the value in the Registry editor, and do another IISRESET to stop the dump.
As you can see above, each file name starts with BeforeParsing or AfterParsing. The string Whl1 is a replacement for the / in the path, which can’t be part of a file name (similarly, Whl5 replaces the question mark char) and the rest of the text in the name represents the path.
Good luck with your analysis!