WinHttpSendRequest() stopped working

[t***@hotmail.com]

Hi All,

Some background info:

Win2000 server SP4
c:\winnt\system32\winhttp.dll version is 5.1
We're using the C interfaces asynchronously,
the DLL is dynamically loaded.
There are multiple threads trying to fetch stuff,
all threads are using the same handle returned by WinHttpOpen.
But, each thread is calling WinHttpConnect(),
WinHttpOpenRequest() separately.
In other words, the threads do not share the handles,
except the WinHttpOpen() handle.
We're fetching from 2 servers, Windows 2000 IIS and Apache Tomcat.


The problem is, sometimes WinHttpSendRequest() would stop sending HTTP
requests.
WinHttpSendRequest() returns no error and there is no error code in the
trace log.
Then, the requests would timed out after a while(via
WINHTTP_OPTION_CONNECT_TIMEOUT),
and we have to close the handles.

This is extremely difficult to reproduced.
It only happens on a system that has been load tested for hours.

By the way, it fails gradually. At first only some of the fetches would
fail.
It would run like that for hours, and then finally all fetches would
fail.
After it failed, we tried to fetch from the same web servers using
Internet Explorer, and IE and the webservers work just fine.

We've load tested the winhttp.dll in a unit test environment,
and we just can't reproduce the problem after tons of HTTP fetches.


Please help!


Some additional observation:

Typically, when everything works correctly, most WinHttpConnect() in
the logs do not associate with a session:
02:52:47.953 ::*Session* :: WinHttpConnect(0x4f45000, "appserver", 80,
0x0)

When it stops fetching, we notice that all WinHttpConnect() are
associated with a session:
16:17:44.906 ::*015347d* :: WinHttpConnect(0x51c5000, "appserver", 80,
0x0)
16:17:44.906 ::*015347d* :: WinHttpConnect() returning handle
0x50de1c00
16:17:52.796 ::*015347e* :: WinHttpConnect(0x51c5000, "appserver", 80,
0x0)
16:17:52.796 ::*015347e* :: WinHttpConnect() returning handle
0x5043b100



Thanks,
Adrian


13:03:32.640 ::*0152dfe* :: WinHttpConnect(0x51c5000, "webserver1",
8080, 0x0)
13:03:32.640 ::*0152dfe* :: WinHttpConnect() returning handle
0x5b5f9f00
13:03:32.640 ::*Session* :: WinHttpOpenRequest(0x5b5f9f00, "POST",
"/Exec/MySubroutine", "", "", 0x0, 0x00000100)
13:03:32.640 ::*Session* :: WinHttpCreateUrlA(0x6eef20c, 0x0,
0x262c0000, 0x6eef248)
13:03:32.640 ::*Session* :: WinHttpCreateUrlA() returning TRUE
13:03:32.640 ::*0152e03* :: WinHttpOpenRequest() returning handle
0x5b5ebc00
13:03:32.640 ::*Session* :: WinHttpQueryOption(0x5b5ebc00, (12),
0x6eef498, 0x6eef474 [4])
13:03:32.640 ::*Session* :: WinHttpQueryOption() returning TRUE
13:03:32.640 ::*Session* :: WinHttpAddRequestHeaders(0x5b5ebc00,
"Content-Type: application/x-www-form-urlencoded\r\nReferer:
http://appserver/vappl", -1, 0x1)
13:03:32.640 ::*Session* :: WinHttpAddRequestHeaders() returning TRUE
13:03:32.640 ::*0152e03* :: WinHttpSetOption(0x5b5ebc00, (63),
0x6eef4a8 [0x1], 4)
13:03:32.640 ::*0152e03* :: WinHttpSetOption() returning TRUE
13:03:32.640 ::*0152e03* :: WinHttpSendRequest(0x5b5ebc00, "", 0,
0x26a7c780, 494, 494, 154c5d)
13:03:32.640 ::*0152e03* :: WinHttpSendRequest() returning TRUE
13:03:32.640 ::*0152e03* :: WinHttpSetOption(0x5b5ebc00, (3),
0x2388f254 [0xdac], 4)
13:03:32.640 ::*0152e03* :: WinHttpSetOption() returning TRUE

It does not send the requests??

13:03:34.109 ::*0152e03* ::
WinHttpCrackUrl("http://webserver1:8080/Exec/MySubroutine", 0x0, 0x0,
0x6eef598)
13:03:34.109 ::*0152e03* ::
WinHttpCrackUrlA("http://webserver1:8080/Exec/MySubroutine", 0x31, 0x0,
0x6eef274)
13:03:34.109 ::*0152e03* :: WinHttpCrackUrlA() returning TRUE
13:03:34.109 ::*0152e03* :: WinHttpCrackUrl() returning TRUE
13:03:34.109 ::*0152e03* :: WinHttpConnect(0x51c5000, "eis2server",
8080, 0x0)
13:03:34.109 ::*0152e03* :: WinHttpConnect() returning handle
0x4e961000

timed out because WINHTTP_OPTION_CONNECT_TIMEOUT is set to [0xdac],
3500ms

13:03:36.140 ::*Session* :: WinHttpCloseHandle(0x5b5ebc00)
13:03:36.140 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:36.140 ::*Session* :: WinHttpCloseHandle(0x5b5f9f00)
13:03:36.140 ::*Session* :: WinHttpCloseHandle() returning TRUE

[Stephen Sulzer]

You might need to contact Microsoft PSS/Developer Support about this.

It is too hard to tell with the information you provided whether the problem
is with winhttp or with the web servers that process the HTTP requests.

Can you give more details:

- What is the exact nature of the error that occurs? You state that
WinHttpSendRequest does nothing and returns no error, but then you get a
timeout error from some other API call? Can you be more specific please. Do
you get a timeout error reported to your async callback function?

- Typically, how many asynchronous HTTP requests does your application have
alive/outstanding at any given one time?

- Do requests to both servers experience timeout errors, or is it with just
one server that the timeout occurs? Do the timeout errors begin to happen
with both servers at approximately the same time?

- Do the servers support persistent connections (keep-alive)? If the
responses from the server include a "Connection: Close" response header, for
example, then the answer is no.

- On average, how frequently does the application send requests to each
server? For example, 10 requests every minute? Does the app send a new
request to a server before the previous request finishes?

- Can you show some of your code? Does the app open a new request handle
(created by WinHttpOpenRequest) for each HTTP request? (It should do so--the
app should not be reusing a WinHttp request handle for more than one HTTP
request.)

- Can you show a more complete trace, especially when the problem occurs? It
would help to see some of the HTTP traffic in the trace too. In the trace
output you give, I don't actually see a timeout error occurring.

- It is possible that the 3.5 second connect timeout setting may be too
aggressive: if the target servers become heavily loaded, then perhaps the
timeout errors are caused by problems on the servers, not in the WinHttp
client. Have you tried a larger connect timeout setting (say 15 seconds)?

- Are the target servers on the same local network as the client? Or out on
the Internet? Do the requests go through a proxy server?


It is Ok for two threads to share the session handle from WinHttpOpen. It
also does not matter if different threads create their own connect handle
from WinHttpConnect or share a connect handle.

Post by t***@hotmail.com
Typically, when everything works correctly, most WinHttpConnect() in
02:52:47.953 ::*Session* :: WinHttpConnect(0x4f45000, "appserver", 80,
0x0)
When it stops fetching, we notice that all WinHttpConnect() are
16:17:44.906 ::*015347d* :: WinHttpConnect(0x51c5000, "appserver", 80,
0x0)
16:17:44.906 ::*015347d* :: WinHttpConnect() returning handle
0x50de1c00
16:17:52.796 ::*015347e* :: WinHttpConnect(0x51c5000, "appserver", 80,
0x0)
16:17:52.796 ::*015347e* :: WinHttpConnect() returning handle
0x5043b100

This observation is not correct. The *015347e* does not represent a
session--it is a unique number that identifies a request. Each request
handle gets a unique ID number--this helps someone reading the trace output
to identify what request is currently being processed even if WinHttp reuses
the values of the HTTP request handles. Often, WinHttp will "remember" what
request handle was last being processed on the thread, and will report that
request handle's ID in the trace. If the trace output shows *Session*
instead, it means that WinHttp does not remember what the previous request
handle was. So, I would not read too much significance into this part of the
trace output.


- Stephen

[t***@hotmail.com]

Hi Stephen,

Thanks for your reply.

Here are somemore details:

- The problem is Winhttp just stopped sending the GET/POST
requests to the servers. There's no "sending data:" logs after
WinHttpSendRequest() is called.

- Typically, we have 20-30 HTTP transactions/s. But, we may have as
many as 200 simultaneous HTTP transactions under load.

- Strangely, the requests to the Apache Tomcat server stopped first.
It could still fetch from IIS when it stopped fetching from Tomcat.
After a few hours, the requests to IIS failed too.

- The problem does not occur after a fixed period of time.
We've seen it happened after 14hours, 20 hours, 3 days..
And sometimes it runs fine for 4 days.

- It also does not occur on the same systems consistently.
We have 6 systems, it happened 3 times on system 1, twice on
system 3. The rest are error free.
We've compared the OS and software on the the systems and they
are identical.

- I'm not sure about the keep-alive. I know that there is no
"connection:" field in the responses.
So it defaults to keep-alive probably?

- There are 100 unique "users" trying to fetch from the servers, and
each user may have 2 simultaneous fetches. So, worst case scenario,
we'll have 200 simultaneous fetches. Typically,we have 20-30
fetches per second(according to the logs)

- yes you're right. There is no timeout errors in the logs.
After winhttpsendrequest() call, we got as far as
WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER. I don't know if
WINHTTP_CALLBACK_STATUS_CONNECTED_TO_SERVER is received or not.

- We have a thread that will remove timed-out requests,
and the thread will send a timeout error to the upper layers.
That's where the timeouts came from.
When the thread removes the requests, it will close the winhttp
handles.

- Yes each "user" calls WinHttpConnect and WinHttpOpenRequest
seperately for each HTTP request. If you really want to see
the code I can email it to you.
The app initialize the dll by calling winhttpopen once.
Then, each "user" starts the request by creating an request
object and put it in a queue. The "user" would return
and wait for the fetch completion.

- There is a threadpool with 5 threads that picks up the HTTP
requests from the queue, and then initiates the asyn HTTP
transactions by calling winhttpconnect, winhttpOpenRequest
and winhttpSendRequest. Then the threads returns to the pool.
When the callbacks came in, we are using the callback
threads to start the next async operations: winhttpQueryHeaders,
winhttpreaddata etc. until there is an error returned by the
callback,
or the HTTP transaction ended
(WINHTTP_CALLBACK_STATUS_READ_COMPLETE).

- We have a mixture of timeout values, 3.5s to 8s. All HTTP
request would be stuck regardless of the timeout values.
And the web server logs indicate that the web server did not
receive any HTTP request from the winhttp client at all.
IE is able to fetch from the same servers while the
app is in the failed state.

- Also, after system 3 failed, the rest of the systems are
running fine using the same web servers. So the problem is
unlikely to be the web servers or the network. All the
systems are connected to the same gigabit switch. There is no
proxy servers.

Thanks,
Adrian

Here are somemore logs. Sorry about the huge post and linewraps.
0152dd0 failed. 0152dd1 works.


13:03:08.796 ::*0152dcb* :: WinHttpConnect(0x51c5000, "tomcatserver",
8080, 0x0)
13:03:08.796 ::*0152dcb* :: WinHttpConnect() returning handle
0x5b6e2900
13:03:08.796 ::*Session* :: WinHttpOpenRequest(0x5b6e2900, "POST",
"/App1/ExecuteSubroutine", "", "", 0x0, 0x00000100)
13:03:08.796 ::*Session* :: WinHttpCreateUrlA(0x6bef20c, 0x0,
0x25e40000, 0x6bef248)
13:03:08.796 ::*Session* :: WinHttpCreateUrlA() returning TRUE
13:03:08.796 ::*0152dd0* :: WinHttpOpenRequest() returning handle
0x5b56e400
13:03:08.796 ::*Session* :: WinHttpQueryOption(0x5b56e400, (12),
0x6bef498, 0x6bef474 [4])
13:03:08.796 ::*Session* :: WinHttpQueryOption() returning TRUE
13:03:08.796 ::*Session* :: WinHttpAddRequestHeaders(0x5b56e400,
"Content-Type: application/x-www-form-urlencoded\r\nReferer:
http://iisserver/vappl", -1, 0x1)
13:03:08.796 ::*Session* :: WinHttpAddRequestHeaders() returning TRUE
13:03:08.796 ::*0152dd0* :: WinHttpSetOption(0x5b56e400, (63),
0x6bef4a8 [0x1], 4)
13:03:08.796 ::*0152dd0* :: WinHttpSetOption() returning TRUE
13:03:08.796 ::*0152dd0* :: WinHttpSendRequest(0x5b56e400, "", 0,
0x26a93b18, 1553, 1553, 154c2a)
13:03:08.796 ::*0152dd0* :: WinHttpSendRequest() returning TRUE
13:03:08.796 ::*0152dd0* :: WinHttpSetOption(0x5b56e400, (3),
0x23a4f254 [0x1f40], 4)
13:03:08.796 ::*0152dd0* :: WinHttpSetOption() returning TRUE
13:03:09.453 ::*0152dcc* ::
WinHttpCrackUrl("http://iisserver/vappl/ASPs/xlate.asp?FileName=areastat&Key=234",
0x0, 0x0, 0x6eef598)
13:03:09.453 ::*0152dcc* ::
WinHttpCrackUrlA("http://iisserver/vappl/ASPs/xlate.asp?FileName=areastat&Key=234",
0x3f, 0x0, 0x6eef274)
13:03:09.453 ::*0152dcc* :: WinHttpCrackUrlA() returning TRUE
13:03:09.453 ::*0152dcc* :: WinHttpCrackUrl() returning TRUE
13:03:09.453 ::*0152dcc* :: WinHttpConnect(0x51c5000, "iisserver", 80,
0x0)
13:03:09.453 ::*0152dcc* :: WinHttpConnect() returning handle
0x5b5f9600
13:03:09.453 ::*Session* :: WinHttpOpenRequest(0x5b5f9600, "GET",
"/vappl/ASPs/xlate.asp?FileName=areastat&Key=234", "", "", 0x0,
0x00000100)
13:03:09.453 ::*Session* :: WinHttpCreateUrlA(0x6eef210, 0x0,
0x262c0000, 0x6eef24c)
13:03:09.453 ::*Session* :: WinHttpCreateUrlA() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpOpenRequest() returning handle
0x5b5e9800
13:03:09.453 ::*Session* :: WinHttpQueryOption(0x5b5e9800, (12),
0x6eef498, 0x6eef474 [4])
13:03:09.453 ::*Session* :: WinHttpQueryOption() returning TRUE
13:03:09.453 ::*Session* :: WinHttpAddRequestHeaders(0x5b5e9800,
"Content-Type: application/x-www-form-urlencoded\r\nReferer:
http://iisserver/vappl", -1, 0x1)
13:03:09.453 ::*Session* :: WinHttpAddRequestHeaders() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpSetOption(0x5b5e9800, (63),
0x6eef4a8 [0x1], 4)
13:03:09.453 ::*0152dd1* :: WinHttpSetOption() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpSendRequest(0x5b5e9800, "", 0, 0x0,
0, 0, 154c2b)
13:03:09.453 ::*0152dd1* :: WinHttpSendRequest() returning TRUE
13:03:09.453 ::*0152dd1* :: sending data:
13:03:09.453 ::*0152dd1* :: 402 (0x192) bytes
13:03:09.453 ::*0152dd1* :: <<<<-------- HTTP headers follow below
----------------------------------------------->>>>
13:03:09.453 ::*0152dd1* :: GET
/vappl/ASPs/xlate.asp?FileName=areastat&Key=234 HTTP/1.1
13:03:09.453 ::*0152dd1* :: Content-Type:
application/x-www-form-urlencoded
13:03:09.453 ::*0152dd1* :: Referer:
http://iisserver/vappl/BAC004/Utility_Lib_Get_Translate_Table.vxml
13:03:09.453 ::*0152dd1* :: Cookie:
ASPSESSIONIDAQBTACSS=MNCJBDEDIFAAGHEDLMPCLLFO
13:03:09.453 ::*0152dd1* :: User-Agent: Mozilla/4.0 (compatible;
Windows 2000)
13:03:09.453 ::*0152dd1* :: Host: iisserver
13:03:09.453 ::*0152dd1* :: Connection: Keep-Alive
13:03:09.453 ::*0152dd1* :: Cache-Control: no-cache
13:03:09.453 ::*0152dd1* :: Pragma: no-cache
13:03:09.453 ::*0152dd1* :: <<<<-------- End
----------------------------------------------->>>>
13:03:09.453 ::*0152dd1* :: WinHttpSetOption(0x5b5e9800, (5),
0x23a4f8f4 [0x1388], 4)
13:03:09.453 ::*0152dd1* :: WinHttpSetOption() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpSetOption(0x5b5e9800, (6),
0x23a4fa24 [0xffffffff], 4)
13:03:09.453 ::*0152dd1* :: WinHttpSetOption() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpReceiveResponse(0x5b5e9800, 0x0)
13:03:09.453 ::*0152dd1* :: WinHttpReceiveResponse() returning TRUE
13:03:09.453 ::*0152dd1* :: received data:
13:03:09.453 ::*0152dd1* :: 379 (0x17b) bytes
13:03:09.453 ::*0152dd1* :: <<<<-------- HTTP headers follow below
----------------------------------------------->>>>
13:03:09.453 ::*0152dd1* :: HTTP/1.1 200 OK
13:03:09.453 ::*0152dd1* :: Server: Microsoft-IIS/5.0
13:03:09.453 ::*0152dd1* :: Date: Tue, 24 May 2005 18:06:37 GMT
13:03:09.453 ::*0152dd1* :: Content-Length: 226
13:03:09.453 ::*0152dd1* :: Content-Type: text/html
13:03:09.453 ::*0152dd1* :: Cache-control: private
13:03:09.453 ::*0152dd1* :: <<<<-------- End
----------------------------------------------->>>>
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders(0x5b5e9800, (0x13),
"<null>", 0x2388c0f0, 0x2388c0ec [31], 0x0 [0])
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders(0x5b5e9800, (0x16),
"<null>", 0x0, 0x2388f408 [0], 0x0 [0])
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders() returning FALSE
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders(0x5b5e9800, (0x16),
"<null>", 0x503cc00, 0x2388f408 [308], 0x0 [0])
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders(0x5b5e9800, (0x1),
"<null>", 0x2388f274, 0x2388f404 [399], 0x0 [0])
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders(0x5b5e9800, (0x31),
"<null>", 0x2388c980, 0x2388c97c [199], 0x2388f248 [0])
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders(0x5b5e9800, (0x31),
"<null>", 0x2388c980, 0x2388c97c [199], 0x2388f248 [1])
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders() returning FALSE
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders(0x5b5e9800, (0xa),
"<null>", 0x2388c764, 0x2388c760 [499], 0x0 [0])
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders() returning FALSE
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders(0x5b5e9800, (0x9),
"<null>", 0x2388c560, 0x2388c55c [499], 0x0 [0])
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders(0x5b5e9800, (0x11),
"<null>", 0x2388c3b8, 0x2388c548 [199], 0x2388f248 [0])
13:03:09.453 ::*0152dd1* :: WinHttpQueryHeaders() returning FALSE
13:03:09.453 ::*0152dd1* :: WinHttpReadData(0x5b5e9800, 0x410d7e63,
10240, 0x410da664)
13:03:09.453 ::*0152dd1* :: WinHttpReadData(0x5b5e9800, 0x410d7e63,
10240, 0x410da664)
13:03:09.453 ::*0152dd1* :: WinHttpReadData() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpReadData() returning TRUE
13:03:09.453 ::*0152dd1* :: WinHttpCloseHandle(0x5b5e9800)
13:03:09.453 ::*0152dd1* :: WinHttpCloseHandle() returning TRUE
13:03:09.453 ::*Session* :: WinHttpCloseHandle(0x5b5f9600)
13:03:09.453 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:09.468 ::*0152dcd* ::
WinHttpCrackUrl("http://iisserver/vappl/ASPs/xlate.asp?FileName=sysid&Key=10.1.80.13",
0x0, 0x0, 0x6aef598)
13:03:09.468 ::*0152dcd* ::
WinHttpCrackUrlA("http://iisserver/vappl/ASPs/xlate.asp?FileName=sysid&Key=10.1.80.13",
0x43, 0x0, 0x6aef274)
13:03:09.468 ::*0152dcd* :: WinHttpCrackUrlA() returning TRUE
13:03:09.468 ::*0152dcd* :: WinHttpCrackUrl() returning TRUE
13:03:09.468 ::*0152dcd* :: WinHttpConnect(0x51c5000, "iisserver", 80,
0x0)
13:03:09.468 ::*0152dcd* :: WinHttpConnect() returning handle
0x5b60c400
13:03:09.468 ::*Session* :: WinHttpOpenRequest(0x5b60c400, "GET",
"/vappl/ASPs/xlate.asp?FileName=sysid&Key=10.1.80.13", "", "", 0x0,
0x00000100)
13:03:09.468 ::*Session* :: WinHttpCreateUrlA(0x6aef210, 0x0,
0x19d10000, 0x6aef24c)
13:03:09.468 ::*Session* :: WinHttpCreateUrlA() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpOpenRequest() returning handle
0x5b5bcc00
13:03:09.468 ::*Session* :: WinHttpQueryOption(0x5b5bcc00, (12),
0x6aef498, 0x6aef474 [4])
13:03:09.468 ::*Session* :: WinHttpQueryOption() returning TRUE
13:03:09.468 ::*Session* :: WinHttpAddRequestHeaders(0x5b5bcc00,
"Content-Type: application/x-www-form-urlencoded\r\nReferer:
http://iisserver/vappl", -1, 0x1)
13:03:09.468 ::*Session* :: WinHttpAddRequestHeaders() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpSetOption(0x5b5bcc00, (63),
0x6aef4a8 [0x1], 4)
13:03:09.468 ::*0152dd2* :: WinHttpSetOption() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpSendRequest(0x5b5bcc00, "", 0, 0x0,
0, 0, 154c2c)
13:03:09.468 ::*0152dd2* :: WinHttpSendRequest() returning TRUE
13:03:09.468 ::*0152dd2* :: sending data:
13:03:09.468 ::*0152dd2* :: 406 (0x196) bytes
13:03:09.468 ::*0152dd2* :: <<<<-------- HTTP headers follow below
----------------------------------------------->>>>
13:03:09.468 ::*0152dd2* :: GET
/vappl/ASPs/xlate.asp?FileName=sysid&Key=10.1.80.13 HTTP/1.1
13:03:09.468 ::*0152dd2* :: Content-Type:
application/x-www-form-urlencoded
13:03:09.468 ::*0152dd2* :: Referer:
http://iisserver/vappl/BAC004/Utility_Lib_Get_Translate_Table.vxml
13:03:09.468 ::*0152dd2* :: Cookie:
ASPSESSIONIDAQBTACSS=MNCJBDEDIFAAGHEDLMPCLLFO
13:03:09.468 ::*0152dd2* :: User-Agent: Mozilla/4.0 (compatible;
Windows 2000)
13:03:09.468 ::*0152dd2* :: Host: iisserver
13:03:09.468 ::*0152dd2* :: Connection: Keep-Alive
13:03:09.468 ::*0152dd2* :: Cache-Control: no-cache
13:03:09.468 ::*0152dd2* :: Pragma: no-cache
13:03:09.468 ::*0152dd2* :: <<<<-------- End
----------------------------------------------->>>>
13:03:09.468 ::*0152dd2* :: WinHttpSetOption(0x5b5bcc00, (5),
0x2388f8f4 [0x1388], 4)
13:03:09.468 ::*0152dd2* :: WinHttpSetOption() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpSetOption(0x5b5bcc00, (6),
0x2388fa24 [0xffffffff], 4)
13:03:09.468 ::*0152dd2* :: WinHttpSetOption() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpReceiveResponse(0x5b5bcc00, 0x0)
13:03:09.468 ::*0152dd2* :: WinHttpReceiveResponse() returning TRUE
13:03:09.468 ::*0152dd2* :: received data:
13:03:09.468 ::*0152dd2* :: 392 (0x188) bytes
13:03:09.468 ::*0152dd2* :: <<<<-------- HTTP headers follow below
----------------------------------------------->>>>
13:03:09.468 ::*0152dd2* :: HTTP/1.1 200 OK
13:03:09.468 ::*0152dd2* :: Server: Microsoft-IIS/5.0
13:03:09.468 ::*0152dd2* :: Date: Tue, 24 May 2005 18:06:37 GMT
13:03:09.468 ::*0152dd2* :: Content-Length: 239
13:03:09.468 ::*0152dd2* :: Content-Type: text/html
13:03:09.468 ::*0152dd2* :: Cache-control: private
13:03:09.468 ::*0152dd2* :: <<<<-------- End
----------------------------------------------->>>>
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders(0x5b5bcc00, (0x13),
"<null>", 0x23a4c0f0, 0x23a4c0ec [31], 0x0 [0])
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders(0x5b5bcc00, (0x16),
"<null>", 0x0, 0x23a4f408 [0], 0x0 [0])
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders() returning FALSE
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders(0x5b5bcc00, (0x16),
"<null>", 0x503cc00, 0x23a4f408 [308], 0x0 [0])
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders(0x5b5bcc00, (0x1),
"<null>", 0x23a4f274, 0x23a4f404 [399], 0x0 [0])
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders(0x5b5bcc00, (0x31),
"<null>", 0x23a4c980, 0x23a4c97c [199], 0x23a4f248 [0])
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders(0x5b5bcc00, (0x31),
"<null>", 0x23a4c980, 0x23a4c97c [199], 0x23a4f248 [1])
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders() returning FALSE
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders(0x5b5bcc00, (0xa),
"<null>", 0x23a4c764, 0x23a4c760 [499], 0x0 [0])
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders() returning FALSE
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders(0x5b5bcc00, (0x9),
"<null>", 0x23a4c560, 0x23a4c55c [499], 0x0 [0])
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders(0x5b5bcc00, (0x11),
"<null>", 0x23a4c3b8, 0x23a4c548 [199], 0x23a4f248 [0])
13:03:09.468 ::*0152dd2* :: WinHttpQueryHeaders() returning FALSE
13:03:09.468 ::*0152dd2* :: WinHttpReadData(0x5b5bcc00, 0x410d7e63,
10240, 0x410da664)
13:03:09.468 ::*0152dd2* :: WinHttpReadData(0x5b5bcc00, 0x410d7e63,
10240, 0x410da664)
13:03:09.468 ::*0152dd2* :: WinHttpReadData() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpReadData() returning TRUE
13:03:09.468 ::*0152dd2* :: WinHttpCloseHandle(0x5b5bcc00)
13:03:09.468 ::*0152dd2* :: WinHttpCloseHandle() returning TRUE
13:03:09.468 ::*Session* :: WinHttpCloseHandle(0x5b60c400)
13:03:09.468 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:09.484 ::*Session* ::
WinHttpCrackUrl("http://tomcatserver:8080/App1/ExecuteSubroutine", 0x0,
0x0, 0x6cef598)
13:03:09.484 ::*Session* ::
WinHttpCrackUrlA("http://tomcatserver:8080/App1/ExecuteSubroutine",
0x31, 0x0, 0x6cef274)
13:03:09.484 ::*Session* :: WinHttpCrackUrlA() returning TRUE
13:03:09.484 ::*Session* :: WinHttpCrackUrl() returning TRUE
13:03:09.484 ::*Session* :: WinHttpConnect(0x51c5000, "tomcatserver",
8080, 0x0)
13:03:09.484 ::*Session* :: WinHttpConnect() returning handle
0x5b614f00
13:03:09.484 ::*Session* :: WinHttpOpenRequest(0x5b614f00, "POST",
"/App1/ExecuteSubroutine", "", "", 0x0, 0x00000100)
13:03:09.484 ::*Session* :: WinHttpCreateUrlA(0x6cef20c, 0x0,
0x26120000, 0x6cef248)
13:03:09.484 ::*Session* :: WinHttpCreateUrlA() returning TRUE
13:03:09.484 ::*0152dd3* :: WinHttpOpenRequest() returning handle
0x5b913800
13:03:09.484 ::*Session* :: WinHttpQueryOption(0x5b913800, (12),
0x6cef498, 0x6cef474 [4])
13:03:09.484 ::*Session* :: WinHttpQueryOption() returning TRUE
13:03:09.484 ::*Session* :: WinHttpAddRequestHeaders(0x5b913800,
"Content-Type: application/x-www-form-urlencoded\r\nReferer:
http://iisserver/vappl", -1, 0x1)
13:03:09.484 ::*Session* :: WinHttpAddRequestHeaders() returning TRUE
13:03:09.484 ::*0152dd3* :: WinHttpSetOption(0x5b913800, (63),
0x6cef4a8 [0x1], 4)
13:03:09.484 ::*0152dd3* :: WinHttpSetOption() returning TRUE
13:03:09.484 ::*0152dd3* :: WinHttpSendRequest(0x5b913800, "", 0,
0x26ad9db0, 1553, 1553, 154c2d)
13:03:09.484 ::*0152dd3* :: WinHttpSendRequest() returning TRUE
13:03:09.484 ::*0152dd3* :: WinHttpSetOption(0x5b913800, (3),
0x23a4f254 [0x1f40], 4)
13:03:09.484 ::*0152dd3* :: WinHttpSetOption() returning TRUE
13:03:16.796 ::*Session* :: WinHttpCloseHandle(0x5b56e400)
13:03:16.796 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:16.796 ::*Session* :: WinHttpCloseHandle(0x5b6e2900)
13:03:16.796 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:17.484 ::*Session* :: WinHttpCloseHandle(0x5b913800)
13:03:17.484 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:17.484 ::*Session* :: WinHttpCloseHandle(0x5b614f00)
13:03:17.484 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:24.265 ::*Session* :: WinHttpCloseHandle(0x5b5e2000)
13:03:24.265 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:24.265 ::*Session* :: WinHttpCloseHandle(0x5b53a800)
13:03:24.265 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:24.281 ::*Session* ::
WinHttpCrackUrl("http://tomcatserver:8080/App1/ExecuteSubroutine", 0x0,
0x0, 0x6def598)
13:03:24.281 ::*Session* ::
WinHttpCrackUrlA("http://tomcatserver:8080/App1/ExecuteSubroutine",
0x31, 0x0, 0x6def274)
13:03:24.281 ::*Session* :: WinHttpCrackUrlA() returning TRUE
13:03:24.281 ::*Session* :: WinHttpCrackUrl() returning TRUE
13:03:24.281 ::*Session* :: WinHttpConnect(0x51c5000, "tomcatserver",
8080, 0x0)
13:03:24.281 ::*Session* :: WinHttpConnect() returning handle
0x470d0700
13:03:24.281 ::*Session* :: WinHttpOpenRequest(0x470d0700, "POST",
"/App1/ExecuteSubroutine", "", "", 0x0, 0x00000100)
13:03:24.281 ::*Session* :: WinHttpCreateUrlA(0x6def20c, 0x0,
0x261f0000, 0x6def248)
13:03:24.281 ::*Session* :: WinHttpCreateUrlA() returning TRUE
13:03:24.281 ::*0152dd4* :: WinHttpOpenRequest() returning handle
0x5b5c9800
13:03:24.281 ::*Session* :: WinHttpQueryOption(0x5b5c9800, (12),
0x6def498, 0x6def474 [4])
13:03:24.281 ::*Session* :: WinHttpQueryOption() returning TRUE
13:03:24.281 ::*Session* :: WinHttpAddRequestHeaders(0x5b5c9800,
"Content-Type: application/x-www-form-urlencoded\r\nReferer:
http://iisserver/vappl", -1, 0x1)
13:03:24.281 ::*Session* :: WinHttpAddRequestHeaders() returning TRUE
13:03:24.281 ::*0152dd4* :: WinHttpSetOption(0x5b5c9800, (63),
0x6def4a8 [0x1], 4)
13:03:24.281 ::*0152dd4* :: WinHttpSetOption() returning TRUE
13:03:24.281 ::*0152dd4* :: WinHttpSendRequest(0x5b5c9800, "", 0,
0x503b1f0, 494, 494, 154c2e)
13:03:24.281 ::*0152dd4* :: WinHttpSendRequest() returning TRUE
13:03:24.281 ::*0152dd4* :: WinHttpSetOption(0x5b5c9800, (3),
0x23a4f254 [0xdac], 4)
13:03:24.281 ::*0152dd4* :: WinHttpSetOption() returning TRUE
13:03:24.437 ::*Session* :: WinHttpCloseHandle(0x5b5c3400)
13:03:24.437 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:24.437 ::*Session* :: WinHttpCloseHandle(0x5b5a3d00)
13:03:24.437 ::*Session* :: WinHttpCloseHandle() returning TRUE
13:03:24.453 ::*0152dd0* ::
WinHttpCrackUrl("http://tomcatserver:8080/App1/ExecuteSubroutine", 0x0,
0x0, 0x6bef598)
13:03:24.453 ::*0152dd0* ::
WinHttpCrackUrlA("http://tomcatserver:8080/App1/ExecuteSubroutine",
0x31, 0x0, 0x6bef274)
13:03:24.453 ::*0152dd0* :: WinHttpCrackUrlA() returning TRUE
13:03:24.453 ::*0152dd0* :: WinHttpCrackUrl() returning TRUE
13:03:24.453 ::*0152dd0* :: WinHttpConnect(0x51c5000, "tomcatserver",
8080, 0x0)
13:03:24.453 ::*0152dd0* :: WinHttpConnect() returning handle
0x5b6e2a00
13:03:24.453 ::*Session* :: WinHttpOpenRequest(0x5b6e2a00, "POST",
"/App1/ExecuteSubroutine", "", "", 0x0, 0x00000100)
13:03:24.453 ::*Session* :: WinHttpCreateUrlA(0x6bef20c, 0x0,
0x25e40000, 0x6bef248)
13:03:24.453 ::*Session* :: WinHttpCreateUrlA() returning TRUE
13:03:24.453 ::*0152dd5* :: WinHttpOpenRequest() returning handle
0x5b56e800
13:03:24.453 ::*Session* :: WinHttpQueryOption(0x5b56e800, (12),
0x6bef498, 0x6bef474 [4])
13:03:24.453 ::*Session* :: WinHttpQueryOption() returning TRUE
13:03:24.453 ::*Session* :: WinHttpAddRequestHeaders(0x5b56e800,
"Content-Type: application/x-www-form-urlencoded\r\nReferer:
http://iisserver/vappl", -1, 0x1)
13:03:24.453 ::*Session* :: WinHttpAddRequestHeaders() returning TRUE
13:03:24.453 ::*0152dd5* :: WinHttpSetOption(0x5b56e800, (63),
0x6bef4a8 [0x1], 4)
13:03:24.453 ::*0152dd5* :: WinHttpSetOption() returning TRUE
13:03:24.453 ::*0152dd5* :: WinHttpSendRequest(0x5b56e800, "", 0,
0x26a7c978, 494, 494, 154c2f)
13:03:24.453 ::*0152dd5* :: WinHttpSendRequest() returning TRUE
13:03:24.453 ::*0152dd5* :: WinHttpSetOption(0x5b56e800, (3),
0x23a4f254 [0xdac], 4)
13:03:24.453 ::*0152dd5* :: WinHttpSetOption() returning TRUE

[Stephen Sulzer]

Hi Adrian,

Thanks for your follow-up information. This is starting to sound like a
WinHttp bug.

What is the exact file version of winhttp.dll on your Windows 2000 SP4
machines? If it is less than 5.1.2600.1557, then you should contact
Microsoft PSS and request the winhttp hotfix from KB article 872766. Version
5.1.2600.1577 fixes a bug which can cause WinHttp to hang.
http://support.microsoft.com/default.aspx?scid=kb;en-us;872766

This may not be the same issue that is affecting you, but it would be good
to ensure that your winhttp.dll on Windows 2000 SP4 is up-to-date. I believe
the most recent winhttp.dll for Win2000 SP4 is version 5.1.2600.2504, per KB
article 873420, so you probably want to ask Microsoft PSS for that one
instead (or whatever is the most recent post-SP4 hotfix build of
winhttp.dll).

In addition, can you check that when WinHttpSendRequest fails to send the
request, your callback function receives the CONNECTING_TO_SERVER
notification but _not_ CONNECTED_TO_SERVER? Do you receive any other
callback notifications for that particular request handle after calling
WinHttpSendRequest?

Also:

- Do you set any of the following options on the WinHttpOpen session handle?
WINHTTP_OPTION_MAX_CONNS_PER_SERVER
WINHTTP_OPTION_MAX_CONNS_PER_1_0_SERVER

- In your call to WinHttpSetStatusCallback, what is given for the
dwNotificationFlags parameter? (Is it
WINHTTP_CALLBACK_FLAG_ALL_COMPLETIONS?) I just want to confirm that your
callback function is registered to receive the
WINHTTP_CALLBACK_STATUS_REQUEST_ERROR notification.


It sounds like WinHttpSendRequest is somehow losing or "forgetting" the
request altogether while setting up the asynchronous socket connect
operation. (WinHttpSendRequest is responsible for establishing the socket
connection.) This would fit with the observations that:

1) WinHttpSendRequest returns TRUE indicating success, indicating at the
very least that WinHttp (in async mode) believes it has successfully
initiated (but not necessarily completed) the socket connect operation;

2) your status callback function receives the CONNECTING_TO_SERVER
notification but not CONNECTED_TO_SERVER, and

3) the callback function does not receive a REQUEST_ERROR notification
indicating a timeout error, even with a small (less than 10s) connect
timeout setting.

I have seen a similar bug in WinHttp before, involving asynchronous HTTP
requests, in which WinHttp "lost" the request during a very low memory
situation.


- Stephen

[t***@hotmail.com]

Stephen,


All the critical hotfixes were installed via windowsupdate. So we've
got the latest winhttp from 842773.
The exact version is 5.1.2600.1557, Oct-11-2004

5.1.2600.2504 From 873420 has a higher build version. However, it's
dated earlier(Aug-13-2004). I'll contact Microsoft PSS to figure
this out.

We've experimented with WINHTTP_OPTION_MAX_CONNS_PER_SERVER before.
It didn't fix the problem. Currently it's not being set.

WINHTTP_CALLBACK_FLAG_ALL_NOTIFICATIONS is used in
WinHttpSetStatusCallback. After WinHttpSendRequest is called
successfully, we are relying on winhttp to send back one
of the following callbacks:

WINHTTP_CALLBACK_STATUS_SENDREQUEST_COMPLETE
WINHTTP_CALLBACK_STATUS_REQUEST_ERROR

The app didn't receive any of these when the problem occurs.
I'm not sure exactly where it stopped. I'll add some code to log
the exact callbacks received after WinHttpSendRequest call.

We had a memory fragmentation problem. So we've set the
HeapDeCommitFreeBlockThreshold flag to 0x40000 according
to KB315407. Since the flag is set, the virtual bytes and private
bytes just flatlined during the load tests.
So there are quite a lot of memory available(several hundred MB)

By the way, the WINHTTP_OPTION_CONNECT_TIMEOUT is set _in_
the WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER callback. Is it
going to cause problems?

case WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER:
{ // Setting timeout for connecting to server
unsigned data = timeRemain.getMsLong();
unsigned dwSize = sizeof(unsigned);

WinHttpSetOption(
m_hResource,
WINHTTP_OPTION_CONNECT_TIMEOUT,
&data,
dwSize);
}
break;


Thanks for your help Stephen, I'll follow your recommendations and
see how it goes. If all else fails, I'll add some logic that
detects this condition and reloads winhttp.dll. That should
probably fix it.


Thanks,
Adrian

[Stephen Sulzer]

Setting the connect timeout during the CONNECTING_TO_SERVER callback
notification is cutting it pretty close, although for asynchronous requests
I think doing that is Ok. (The risk is that WinHttpSendRequest has already
"picked up" the connect timeout value from the request handle.) To be sure
they take effect, the timeouts should be set before calling
WinHttpSendRequest.

- Stephen

[t***@hotmail.com]

Stephen,

You're right. For the failed requests,
we received WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER
notifications and WINHTTP_CALLBACK_STATUS_CONNECTED_TO_SERVER
never happened.

Anyway, most of the successful requests never receive a
WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER notification.
This is probably due to the "connection reuse" feature?


Here's a snapshot of the logs. We logged the raw callback hex value.
WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER == 4h
WINHTTP_CALLBACK_STATUS_SENDING_REQUEST == 10h etc..

06-05-2005,02:58:27:890,url:'http://tomcatserver:8080/App1/SessionClose'
callbacks='10|20|400000|40|80|20000|40|80|80000|80000|'
06-05-2005,02:58:27:968,url:'http://tomcatserver:8080/App1/ExecuteSubroutine'
callbacks='10|20|400000|40|80|20000|40|80|80000|80000|'
06-05-2005,02:58:27:984,url:'http://tomcatserver:8080/App1/SessionClose'
callbacks='10|20|400000|40|80|20000|40|80|80000|80000|'
06-05-2005,02:58:28:593,url:'http://iisserver/vappl/ASPs/getText.asp?FileName=test03'
callbacks='4|'
06-05-2005,02:58:28:703,url:'http://iisserver/vappl/App/m1533.txt'
callbacks='4|'
06-05-2005,02:58:28:718,url:'http://tomcatserver:8080/App1/ExecuteSubroutine'
callbacks='10|20|400000|40|80|20000|40|80|80000|80000|'
06-05-2005,02:58:28:875,url:'http://tomcatserver:8080/App1/ExecuteSubroutine'
callbacks='10|20|10|20|400000|40|80|20000|40|80|80000|80000|'
06-05-2005,02:58:30:093,url:'http://iisserver/vappl/App/m1715.txt'
callbacks='4|'
06-05-2005,02:58:30:187,url:'http://tomcatserver:8080/App1/ExecuteSubroutine'
callbacks='10|20|400000|40|80|20000|40|80|80000|80000|'
06-05-2005,02:58:30:203,url:'http://iisserver/vappl/App/m1715.txt'
callbacks='4|'
06-05-2005,02:58:30:312,url:'http://iisserver/vappl/ASPs/getText.asp?FileName=test02'
callbacks='4|'


Adrian