Debug Web or Cloud Applications Using Internet Explorer

Developers and IT pros are increasingly faced with the daunting task of troubleshooting network issues with cloud- or web-based applications. Developers design a web application to work one way, while IT pros discover that users can find creative ways in which to use these application outside their intended design. Toss in potential issues with the web server or applications running on the clients, and you could find yourself facing a complicated troubleshooting problem. Here I will cover one approach to troubleshooting web or cloud application problems web that should help you answer some important questions in identifying the source of a problem.

Starting way back in Windows 98 and Internet Explorer 4.x, you could download and install an SDK version of wininet.dll that contained a logging feature. When interpreted by a knowledgeable IT pro, this log output would provide API-level detail about system processes and, further, was the only way you could debug SSL issues. This method of logging was not without its idiosyncrasies. Sometimes simply swapping in the debug wininet.dll would change the timing, and the problem you were troubleshooting would no longer be reproducible. Although this process lasted all the way though Windows XP, it is no longer necessary in Windows 7.

Beginning with Windows Vista and continuing in Windows 7, wininet.dll can be debugged using Event Tracing for Windows (ETW) tracing. Let's explore how easy it is in Windows 7 and Internet Explorer (IE) 8 or 9 to collect an ETL trace that contains wininet.dll API-level detail. Note that everything we will use to collect the tracing data (ETL files) is built into Windows. This same approach will work for any application that consumes wininet.dll directly.

Collecting Data Using Netsh

Let's start the process of our collecting ETL data into a log on a Windows 7 machine. First, to avoid contaminating the ETL file with unnecessary information, be sure to close any Internet Explorer processes that are running. Create a folder in which you would like to store the ETL output. Next open an elevated command prompt and CD (change directory) over to the folder where you plan to store the ETL file then execute the following command:

netsh trace start scenario=InternetClient level=5 tracefile=wininet.etl report=yes

Note: Level=5 sets the output detail to maximum. When you enable report=yes, a handy HTML report will be generated for you that contains details about the physical machine from which the data was collected. This report is very useful if you are working on an issue where the problem appears to be machine specific.

If tracing starts correctly you should have output similar to that shown in Figure 1.

Figure 1: Netsh trace output

Now you can launch IE and connect to your web application. When you have reproduced the network issue, stop tracing using the following command:

netsh trace stop

It can take a few minutes for the trace correlation, data collection, and report generation processes to finish. You will see a message indicating that the tracing was successfully stopped. What you are left with is an .etl file and a .cab file. Remember that "report=yes" argument we supplied? If you decompress the .cab file, you'll find the report.htm file. View this report for more information about the network hardware and configuration, running processes, and other various system-related information.

Viewing the Wininet.etl File

To view the output from this ETL, file you will need to download and install Microsoft Network Monitor 3.4. To open the ETL log file, simply launch Microsoft Network Monitor and drag and drop the ETL log file into the open Network Monitor window, as Figure 2 shows.

Figure 2: Viewing the ETL log file in Network Monitor

At first glance Network Monitor has parsed the output and labeled all Network Conversations as "NetEvent Activity ID x", and only a couple of protocols are labeled.
 
In order for us to properly decode the ETL into meaningful data, we need to configure the Network Monitor parser profile. To access the parser profile options, click on the Parser Profiles button located on the Network Monitor toolbar. Set the active parser to Windows, as shown in Figure 3, and click OK.

Figure 3: Setting the active parser to Windows

Now you can set the display filter to protocol.WinINet_MicrosoftWindowsWinInet, and Network Monitor will display WinInet detail only. (This is the same detail that was previously reserved for only those with the checked-build SDK version of Wininet.dll.) As an example of how this works, I collected an ETL log while accessing https://www.microsoft.com—an SSL-protected web page. Prior to using ETW tracing as explained in this article, I would have been left with a Network Monitor capture of encrypted content. This data would not be very useful for digging into most issues.
 
Let's look at some of the detail we can extract from the ETL log and how this information might be useful to you when debugging your web application.

First, let's examine the information we can extract about cookies. Here is a typical enumeration of the cookie jar, as seen in the ETL output:

MicrosoftWindowsWinINet: Client has stored a cookie in the cookie jar: Domain=live.com, Path=/, Name=ANON, Value=A=FFFFFFFFFFFFFFFFFFFFFFFFF&E=FFF&W=0

Something as simple as seeing the cookies that are stored or sent becomes complicated when the request is sent over SSL. You would have to revert to running additional tools such as Fiddler or decrypting the network trace to get this information. Using ETL tracing and Network Monitor makes it very easy to view this information.

Now we will look at the connection request to the server. Because of the level of detail provided by the ETL trace log, I will highlight only some of the more interesting frames. The two frames shown in Figure 4 clearly display the server, port and target for this request. You would use this information to locate the request in which you are debugging.

Figure 4: ETL output showing server, port, and target for a request

WININET_CONNECT_HANDLE_CREATED: Handle 0x00CC0008 created by InternetConnect: SessionHandle=0x00CC0004, Server=www.microsoft.com:443 (0x1BB), HTTP, Flags=8388608 (0x800000)
WININET_HTTP_REQUEST_HANDLE_CREATED: Request handle 0x00CC000C created by HttpOpenRequest: ConnectionHandle=0x00CC0008, GET, Target=/en-us/default.aspx, Ver=HTTP/1.1, Referrer=, Media types=, Flags=12583936 (0xC00400)

Next, in Figure 5, we see the start of the Send request, which also includes the full URL. But before the request hits the wire, WinINet will check the local temporary Internet file cache. In the third frame you see a CACHEMISS, which as you might expect tells us this content is not stored in our local temporary Internet file cache from a previous visit.

Figure 5: ETL output showing send request and cache information

WININET_SENDREQUEST_START: WININET_SENDREQUEST_START - Request : 0x0A4A6C98, AddressName : https://www.microsoft.com/en-us/default.aspx
WININET_PRENET_CACHELOOKUP_INFO: WININET_PRENET_CACHELOOKUP_INFO - Request : 0x0A4A6C98
WININET_PRENET_CACHEMISS_INFO: WININET_PRENET_CACHEMISS_INFO - Request : 0x0A4A6C98

Because the cache is empty, WinINet must now build up an actual request and put it on the wire. The next three frames, in Figure 6, show this process of building the request. If you track the Request pointer, it will ensure that you are looking at the correct request.

Figure 6: ETL output showing the process of building a request

WININET_CONNECT_START: WININET_CONNECT_START - Request : 0x0A4A6C98
WININET_LOOKUPCONNECTION_START: WININET_LOOKUPCONNECTION_START - Request : 0x0A4A6C98
WININET_LOOKUPCONNECTION_STOP: WININET_LOOKUPCONNECTION_STOP - Request : 0x0A4A6C98, Socket : 4294967295 (0xFFFFFFFF)

We need to resolve the domain name to an actual IP address before the request can be sent. In the frames shown in Figure 7, we will see WinINet make a request to DNS for the IP address of www.microsoft.com.

Figure 7: ETL output showing WinINet making a DNS request for an IP address

WININET_RESOLVEHOST_START: WININET_RESOLVEHOST_START - Request : 0x0A4A6C98, HostName : www.microsoft.com
WININET_DNS_QUERY_SENT: DNS query for www.microsoft.com hostname is sent: Handle=0x00CC000C
WININET_GETADDRINFO_START: WININET_GETADDRINFO_START - Flags : 3 (0x3), AddressName : www.microsoft.com
WININET_GETADDRINFO_STOP: WININET_GETADDRINFO_STOP - error : 0 (0x0), Flags : 3 (0x3), AddressName : www.microsoft.com
WININET_DNS_QUERY_COMPLETE: DNS query for www.microsoft.com hostname is complete: Handle=0x00CC000C, Addresses=207.46.170.123;207.46.170.10;

Great! Now we have the IP address, so that WinINet can finally get this request on the wire. We see in the next few frames, shown in Figure 8, where the connection is established and SSL negotiated. I have simplified the SSL negotiation to one frame, but when you run this yourself you will see that the actual SSL negotiation is very verbose and covers many calls down to schannel.dll from wininet.dll.

Figure 8: ETL output showing establishment of connection and SSL negotiation


WININET_TCP_CONNECTION_ESTABLISHED: TCP connection to server www.microsoft.com established: ConnectionHandle=0x00000000, SocketHandle=0x000005CC, LocalPort=52915 (0xCEB3)
WININET_HTTPS_NEGOTIATION_STARTED: Client begins SSL negotiation: RequestHandle=0x00CC000C
WININET_HTTP_REQUEST_SENT: HTTP request was sent successfully: RequestHandle=0x00000000, SocketHandle=0x000005CC, ???, CookieSent= FALSE

The Solution Is in the Details

You've had a glimpse here of how WinINet ETL tracing can provide developers a deeper look inside how the client builds up and makes request to the web server. This level of detail is very helpful when debugging issues related to SSL or whenever you need to take a deeper look at how the client is communicating with a web server.

Louis Shanks ([email protected]) is a senior escalation engineer for Microsoft's Developer Support Internet Services team. He specializes in advanced Internet Explorer debugging and online web diagnostic issues.