Troubleshooting HttpWebRequest connection timeout. (Part 2)

05. March 2010 Uncategorized 0

Check out Part One.

Unfortunately, sometime Monday a user called up with the same problem.  Prices were STILL coming back $0.  So back to the drawing board.

One thing that bugged me in this process was trying to line up my normal log file with the trace file, especially since the trace file did not come with timestamps.  I went over to my favorite development site, Stack Overflow, and dug around hoping someone had done this, sure enough, they had.

So now I’ve got my network log and my normal log side by side.  It makes for a rather larger log file (order of MB instead of KB) but if it helps me chase down the issue I’ll be happy.

Going through the log file I noticed the time stamp between when I logged that we were making the call, and when the call timed out 1:40, which is exactly 100s.  That’s a nice, round number.  The type of number that would be a good default.  So I hit up the webservice team and asked them to log anytime a request took more than 60s (just to be safe.)

Without fail, that day a salesman lets me know he had pricing come back all 0’s.  I pulled up my log and saw the timeout occurred at 14:48:39  so I went to the web service log files looking around for a similar time stamp.  Much to my disappointment, there was nothing there.  Or rather, there was nothing related to the functions I was calling.  That sent me back to the System.Net trace lines.  I pulled up a log that I knew succeeded and traced out the steps.  Here’s what they are:

  1. HttpWebRequest::GetRequestStream
  2. Associating HttpWebRequest#17689868 with ServicePoint#6385742
  3. Associating Connection#24991086 with HttpWebRequest#17689868
  4. Associating HttpWebRequest#17689868 with ConnectStream#23593186
  5. HttpWebRequest#17689868 – Request: POST <webservice address> HTTP/1.1
  6. ConnectStream#23593186 – Sending Headers
  7. Connection#24991086 – Received Status
  8. Connection#24991086 – Received Headers
  9. Exiting HttpWebReqeust#17689868
  10. ConnectStream#23593186::Write()

At this point, it actually writes the data to the web service.  I stopped here because the web service didn’t even show me connecting to it.

By contrast, here are the steps that happened when the timeout occurred:

  1. HttpWebRequest#23927005::GetRequestStream()
  2. Associating HttpWebReqeust#23927005 with ServicePoint#9008175
  3. Associating Connection#12988329 with HttpWebRequest#23927005
  4. HttpWebRequest#23927005::Abort (The operation timed out)

So here we see that the request timed out before it got a chance to even POST to the service.

Now we have new information. To be honest, I didn’t know what ServicePoints, ConnectionStreams etc were.  I so Google took me to at least one helpful document.  From reading this article and others I noticed that .Net tries to get into the whole “green” way of doing things by recycling connections.  So I went back to my log file.  Sure enough, Connection#12988329 showed up about 1 hour earlier, with a pricing request done at 13:48:00.  So it appears that there is a timeout occurring on this connection, and once it times out, it can’t recover.

The solution, at least at this point, appears to be to set the ConnectionLeaseTimeout to 0 (it’s default is -1, which means it never times out, but apparently the connections can.)

The process I was using to fetch pricing went like this:

  1. Create WebRequestor
  2. Set up the string of data I want to pass
  3. Call the web service
  4. Get back by data.
  5. Repeat as necessary

To get this to work, I simply added this line of code while creating my web requestor:

myRequestor.ServicePoint.ConnectionLeaseTimeout = 0;

From my log file, I can now see that every request creates, and associates, a new Connection, thereby bypassing the timeout.