WinInet ETW Logs: Part 1 - Reading Logs

  • [アーティクル]

Hello, my name is Marcus Frazier. I am a developer on the WinInet team and I am here to talk about reading and understanding WinInet ETW logs. If you need to know how to capture these logs, check out Jonathan’s post. Keep in mind that WinInet ETW tracing is only available on Vista.

Events

ETW logs are event based. When an event occurs an entry is placed in the log. These events are based on protocol behavior and decision points.

WinInet currently has seven event categories:

1) Handle Events – Events dealing with the creation and destruction of HINTERNET handles.

2) HTTP Events – Events dealing with the processing of HTTP requests and responses.

3) Connection Events – Events dealing with underlying network operations (TCP, DNS).

4) Authentication Events – Events dealing with authentication.

5) HTTPS Events – Events dealing with the HTTPS protocol.

6) Autoproxy Events – Events dealing with Autoproxy.

7) Cookie Events – Events dealing with cookies.

WinInet currently uses three event levels. Each event can be one of these levels:

1) Error – These events are raised when an error condition is reached.

2) Information – These events provide additional information regarding protocol handling.

3) Verbose – These events provide extra information that can help in diagnosing certain situations but are not required for all cases.


XML Logs

Let’s look at a single event entry in a log highlighting relevant information. This log was converted from ETL to XML format using the tracerpt as described in Jonathan’s post.

<Event xmlns="https://schemas.microsoft.com/win/2004/08/events/event">

<System>

<EventID>103</EventID>

<Level>4</Level>

<TimeCreated SystemTime="2006-08-21T13:00:35.614957600Z" />

<Execution ProcessID="2480" ThreadID="3396" ProcessorID="1” KernelTime="30" UserTime="0" />

</System>

<RenderingInfo Culture="en-US">

<Level>Information</Level>

<Keywords>

<Keyword>Flagged on all WinINet events dealing with creation or destruction of INTERNET handles</Keyword>

</Keywords>

<Message>Handle 0xCC0010 created by InternetConnect: SessionHandle=0xCC0004, Server=www.live.com:80, HTTP, Flags=0x0

</Message>

<Channel>Microsoft-Windows-WinINet/Analytic</Channel>

</RenderingInfo>

</Event>

When reading a log in XML format, there is a lot of information about every event. The first thing to look for is the open <event> tag. All the information from this tag to the </event> tag is about a single event. When quickly scanning through these logs I find the easiest thing to look for is the <message> tag within each event block. This is the English version of what has actually happened. Some other useful information is the SystemTime in the <TimeCreated> tag, which tells you when this event happened, and the <Execution> tag which shows the ProcessID and ThreadID.


Text Logs

In addition to XML format, ETW logs can also be converted to an easier-to-read text format using the following command (Vista only):

wevtutil qe <etl file path> /lf:True /f:Text > <output path>

An example of the full sequence of commands would look like this:

logman start "test1" -p "Microsoft-Windows-WinInet" -o "test1.etl" -ets

<Run scenario>

logman stop "test1" -ets

wevtutil qe c:\logs\test1.etl /lf:True /f:Text > c:\logs\test1.txt

notepad test1.txt

Entries in the text formatted log appear in a concise format:

Event[21]:

Log Name: N/A

Source: Microsoft-Windows-WinINet

Date: 2007-01-22T12:43:55.735

Event ID: 301

Task: N/A

Level: Information

Opcode: Info

Keyword: Flagged on all WinINet events dealing with network operations (TCP, DNS)

User: N/A

User Name: N/A

Computer: mfrazier2-test

Description:

TCP connection to server www.live.com established: ConnectionHandle=0xcc0014, SocketHandle=0x944, LocalPort=49779

These text files can be read with notepad. The “Description” is the same text as contained in the <message> tag from the XML log and describes what has happened.

Diagnosing problems with an ETW log can prove to be difficult at times. ETW logs will not always produce an error level event when a problem occurs. It takes some practice to recognize an “incorrect” sequence of events when there is no explicit error level event in the log. It is helpful to understand the normal flow of the protocol, and to understand what a “correct” series of events looks like. We suggest capturing the log of a working scenario and keeping it for reference.

The best way to get better at reading these logs is to see the difference between good and bad logs. Subsequent blog entries will give examples of diagnosing common problems using ETW logs. These examples will help you diagnose real ETW logs. The next post will deal with a simple case: No Internet Connectivity.

- Marcus

Comments