Tracing System.Net to debug HTTP Clients

If you are writing software that leverages the System.Net.WebRequest class, you’re probably familiar with tools like Fiddler or Wireshark. You can use these tools to see the actual HTTP requests and responses going back and forth between your client and the server. A nice alternative to these tools, that I only recently discovered, is the System.Net trace source. The System.Net source emits logging messages from the HttpWebRequest and HttpWebResponse classes that give a very similar experience to using Fiddler.

Here’s an example App.config file that configures the System.Net listener to output both to the console and a log file:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>

    <system.diagnostics>

        <trace autoflush="true" />
        
        <sources>
            <source name="System.Net" maxdatasize="1024">
                <listeners>
                    <add name="MyTraceFile"/>
                    <add name="MyConsole"/>
                </listeners>
            </source>
        </sources>

        <sharedListeners>
            <add
              name="MyTraceFile"
              type="System.Diagnostics.TextWriterTraceListener"
              initializeData="System.Net.trace.log"
                />
            <add name="MyConsole" type="System.Diagnostics.ConsoleTraceListener" />
        </sharedListeners>

        <switches>
            <add name="System.Net" value="Information" />
<!--            <add name="System.Net" value="Verbose" />-->
        </switches>

    </system.diagnostics>

</configuration>

Here I’ve set up two listeners; ‘MyTraceFile’, that outputs the trace information to a log file; and ‘MyConsole’, that outputs to the console.

My favourite test tool is TestDriven.NET which allows you to run arbitrary methods and sends the output to the Visual Studio output console. Being able to run a test method (I’ve got F8 mapped to run tests, so it’s a single keystroke) and see the System.Net trace output immediately in Visual Studio is very cool.

Here’s some code which makes a GET request to www.google.com …

var request = WebRequest.CreateDefault(new Uri("http://www.google.com/"));

request.Method = "GET";

var response = (HttpWebResponse)request.GetResponse();

using (var responseStream = response.GetResponseStream())
{
    if (responseStream == null)
    {
        Console.Out.WriteLine("response stream is null");
        return;
    }

    using (var reader = new StreamReader(responseStream))
    {
        // do something with the response body
        var responseBody = reader.ReadToEnd();
    }
    
}

When I run this code, I get the following trace output …

System.Net Information: 0 : [5752] Current OS installation type is 'Client'.
System.Net Information: 0 : [5752] RAS supported: True
System.Net Error: 0 : [5752] Can't retrieve proxy settings for Uri 'http://www.google.com/'. Error code: 12180.
System.Net Information: 0 : [5752] Associating HttpWebRequest#49685557 with ServicePoint#53977989
System.Net Information: 0 : [5752] Associating Connection#56846532 with HttpWebRequest#49685557
System.Net Information: 0 : [5752] Connection#56846532 - Created connection from 192.168.1.146:53202 to 173.194.67.99:80.
System.Net Information: 0 : [5752] Associating HttpWebRequest#49685557 with ConnectStream#19026863
System.Net Information: 0 : [5752] HttpWebRequest#49685557 - Request: GET / HTTP/1.1

System.Net Information: 0 : [5752] ConnectStream#19026863 - Sending headers
{
Host: www.google.com
Connection: Keep-Alive
}.
System.Net Information: 0 : [5752] Connection#56846532 - Received status line: Version=1.1, StatusCode=302, StatusDescription=Found.
System.Net Information: 0 : [5752] Connection#56846532 - Received headers
{
Cache-Control: private
Content-Type: text/html; charset=UTF-8
Location: http://www.google.co.uk/
Set-Cookie: expires=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=www.google.com,path=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=www.google.com,domain=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=www.google.com,expires=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=.www.google.com,path=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=.www.google.com,domain=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=.www.google.com,expires=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=google.com,path=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=google.com,domain=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=google.com,expires=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=.google.com,path=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=.google.com,domain=; expires=Mon, 01-Jan-1990 00:00:00 GMT; path=/; domain=.google...}.
System.Net Information: 0 : [5752] ConnectStream#10789400::ConnectStream(Buffered 221 bytes.)
System.Net Information: 0 : [5752] Associating HttpWebRequest#49685557 with ConnectStream#10789400
System.Net Information: 0 : [5752] Associating HttpWebRequest#49685557 with HttpWebResponse#11016073
System.Net Warning: 0 : [5752] HttpWebRequest#49685557::() - Error code 302 was received from server response.
System.Net Warning: 0 : [5752] HttpWebRequest#49685557::() - Resubmitting request.
System.Net Information: 0 : [5752] Associating HttpWebRequest#49685557 with ServicePoint#23936385
System.Net Information: 0 : [5752] Associating Connection#22196665 with HttpWebRequest#49685557
System.Net Information: 0 : [5752] Connection#22196665 - Created connection from 192.168.1.146:53203 to 173.194.67.94:80.
System.Net Information: 0 : [5752] Associating HttpWebRequest#49685557 with ConnectStream#57250404
System.Net Information: 0 : [5752] HttpWebRequest#49685557 - Request: GET / HTTP/1.1

System.Net Information: 0 : [5752] ConnectStream#57250404 - Sending headers
{
Host: www.google.co.uk
Connection: Keep-Alive
}.
System.Net Information: 0 : [5752] Connection#22196665 - Received status line: Version=1.1, StatusCode=200, StatusDescription=OK.
System.Net Information: 0 : [5752] Connection#22196665 - Received headers
{
Cache-Control: private, max-age=0
Content-Type: text/html; charset=ISO-8859-1
Date: Thu, 12 Jul 2012 13:39:26 GMT
Expires: -1
Set-Cookie: NID=61=CTUlcAyhXQp63NVCOkXYWVgi2nMQiOUpyG-x1yRlw-Unhq3OyQ5zXCIxIJ9ctSN_qg6Lni90142sYKQzDZ7oZXBZxnWQbzhcjqVcKQEgCfBgMAjxhDgVLOfgXBR6IzTm; expires=Fri, 11-Jan-2013 13:39:26 GMT; path=/; domain=.google.co.uk; HttpOnly,PREF=ID=b7c02536ab59a395:FF=0:TM=1342100366:LM=1342100366:S=gqGT-3tWl96NIpdz; expires=Sat, 12-Jul-2014 13:39:26 GMT; path=/; domain=.google.co.uk,NID=61=CTUlcAyhXQp63NVCOkXYWVgi2nMQiOUpyG-x1yRlw-Unhq3OyQ5zXCIxIJ9ctSN_qg6Lni90142sYKQzDZ7oZXBZxnWQbzhcjqVcKQEgCfBgMAjxhDgVLOfgXBR6IzTm; expires=Fri, 11-Jan-2013 13:39:26 GMT; path=/; domain=.google.co.uk; HttpOnly
P3P: CP="This is not a P3P policy! See http://www.google.com/support/accounts/bin/answer.py?hl=en&answer=151657 for more info."
Server: gws
X-XSS-Protection: 1; mode=block
X-Frame-Options: SAMEORIGIN
Transfer-Encoding: chunked
}.
System.Net Information: 0 : [5752] ConnectStream#42047594::ConnectStream(Buffered -1 bytes.)
System.Net Information: 0 : [5752] Associating HttpWebRequest#49685557 with ConnectStream#42047594
System.Net Information: 0 : [5752] Associating HttpWebRequest#49685557 with HttpWebResponse#47902635
System.Net Information: 0 : [5752] ContentLength=-1

You can see that Google users in the UK get a 302 redirect to www.google.co.uk. This is a special Google that refuses to say anything bad about Her Majesty and stops working to drink tea at exactly 11 am.

With the reporting level set at ‘Information’, you can see all the header HTTP information and some of the work that the underlying sockets are doing. Setting the level to ‘Verbose’ will give you the HTTP bodies as well.

For more information see the MSDN documentation here.

Happy HTTPing!