WCF Service Trace Viewer Part 1

Thursday, June 9, 2011

I hit upon this tool SvcTraceViewer.exe and found it quite interesting. Usually located at <drive>:\Program Files\Microsoft SDKs\Windows\v7.0A\bin\NETFX 4.0 Tools (for version .net 4.0), this tool helps you to locate an error that’s happening behind the scenes. It also gives you a better understanding of how things flow with a service.

I have this service that exposes two operation contracts – AddInt and AddDouble. On the client-side (a console app), all I do is to call these two operations. That’s it – a very simplistic application. The only variation I’m going to do is to make the first call through Basic Http Binding and the second one using WSHttp Binding. Let’s see the differences.

I have the following settings in my app.config file.

        1: <!-- child of the <configuration> element -->

       2: <system.diagnostics>

       3:     <sources>

       4:         <source name="System.ServiceModel" 

       5:                 switchValue="All">

       6:             <listeners>

       7:                 <add name="xmlTraceListener" />

       8:             </listeners>

       9:         </source>

        <source name="System.ServiceModel.MessageLogging" 

                switchValue="All">

            <listeners>

                <add name="xmlTraceListener" />

            </listeners>

        </source>

    </sources>

    <sharedListeners>

        <add name="xmlTraceListener" 

             type="System.Diagnostics.XmlWriterTraceListener" 

             initializeData="ClientLogBasic.svclog" />

    </sharedListeners>

    <trace autoflush="true" />

</system.diagnostics>

  

<!-- child of the <system.serviceModel> element -->

<diagnostics>

    <messageLogging maxMessagesToLog="10000"

    logEntireMessage="true"

    logMessagesAtServiceLevel="true"

    logMalformedMessages="true"

    logMessagesAtTransportLevel="true">

        <filters>

            <clear/>

        </filters>

    </messageLogging>

</diagnostics>

A couple of things to note here. I’m using the XmlWriterTraceListener to log all the messages. All these messages will be written to ClientLogBasic.svclog file, set through the initializeData attribute. A switch value of ‘All’ means I’ll be logging a LOT of information. You can have a comma-separated list of the following trace levels – Critical, Error, Warning, Information, Verbose, ActivityTracing. You can also set the trace level to Off to turn off all tracing. See details on configuration settings here. You can have these settings on either the client- or the server-side config file.

I’ll begin by making a call to the WCF service using the basic Http binding.

       1: private static void CallWcfService()

       2: {

       3:     LearnWcfServiceClient learnWcfServiceClient = new LearnWcfServiceClient(BasicEndPointName);

       4:     //LearnWcfServiceClient learnWcfServiceClient = new LearnWcfServiceClient(WsHttpEndPointName);

       5:     int sumInt = learnWcfServiceClient.AddInt(1, 2);

       6:     double sumDouble = learnWcfServiceClient.AddDouble(1.1, 3.3);

       7:     Console.WriteLine("{0} - {1}", sumInt, sumDouble);

       8:     learnWcfServiceClient.Close();

       9: }

As expected the ClientLogBasic.svclog file gets created:

I open the file only to be a little overwhelmed! I have uploaded the .svclog files here so you can see what I’m talking here as you read through.

So you see Activity tab on the left, a list of traces on the right top and the actual XML for these traces just below. An activity is nothing but a grouping of related traces. You can also view the message in a formatted way, but I prefer XML. I click on the second activity Construct ChannelFactory on the activity tab and GetChannelEndpointElement trace.

We see in the xml that it’s reading some of the elements of the config file - BasicHttpBinding_ILearnWcfService as the endpoint, ServiceProxy.ILearnWcfService as the contract, basicHttpBinding as the binding and the url of the endpoint along with a bunch of other information.

There another cool thing about this tool – it displays the flow graphically as well. Just double click on any activity and it’ll switch to the Graph tab and show a hierarchy of the trace flow.

Clicking on one of the messages, shows the details of the call to the AddInt operation. Let’s get to the Message tab.

There are a total of 8 messages here. Expand the left column in the log files and you’ll see that the first 4 belong to AddInt and the rest belong to AddDouble. You can see the full xml of the first message.

       1: <E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">

       2:     <System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">

       3:         <EventID>0</EventID>

       4:         <Type>3</Type>

       5:         <SubType Name="Information">0</SubType>

       6:         <Level>8</Level>

       7:         <TimeCreated SystemTime="2011-04-12T05:05:35.8170630Z" />

       8:         <Source Name="System.ServiceModel.MessageLogging" />

       9:         <Correlation ActivityID="{9fab5e4d-4608-490e-bbf0-4b1ba0393227}" />

        <Execution ProcessName="ClientApplication" ProcessID="4144" ThreadID="1" />

        <Channel />

        <Computer>MyComputer</Computer>

    </System>

    <ApplicationData>

        <TraceData>

            <DataItem>

                <MessageLogTraceRecord Time="2011-04-12T10:35:35.8110624+05:30" Source="ServiceLevelSendRequest" Type="System.ServiceModel.Channels.BodyWriterMessage" xmlns="http://schemas.microsoft.com/2004/06/ServiceModel/Management/MessageTrace">

                    <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">

                        <s:Header>

                            <Action s:mustUnderstand="1" xmlns="http://schemas.microsoft.com/ws/2005/05/addressing/none">http://tempuri.org/ILearnWcfService/AddInt</Action>

                        </s:Header>

                        <s:Body>

                            <AddInt xmlns="http://tempuri.org/">

                                <arg1>1</arg1>

                                <arg2>2</arg2>

                            </AddInt>

                        </s:Body>

                    </s:Envelope>

                </MessageLogTraceRecord>

            </DataItem>

        </TraceData>

    </ApplicationData>

</E2ETraceEvent>

See that the Source attribute of the MessageLogTraceRecord element says ServiceLevelSendRequest (above). The Action element points to the operation contract and the AddInt element shows the two arguments that were passed to the method.

Coming to the second trace (left image), we see traces like ‘Sent a message over a channel’, ‘Received a message over a channel’ and ‘Received reply over the request channel’, giving us a visual of everything that’s going on to call the service and receive response from it. The Source attribute for this one says TransportSend.

The third trace shows the Source as TransportReceive and the fourth one show it as ServiceLevelReceiveReply. You see the full xml of the fourth trace below with the sum value of 3 as a return from the AddInt operation method.

       1: <!-- full xml of the fourth trace -->

       2: <E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">

       3:         <System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">

       4:             <EventID>0</EventID>

       5:             <Type>3</Type>

       6:             <SubType Name="Information">0</SubType>

       7:             <Level>8</Level>

       8:             <TimeCreated SystemTime="2011-04-12T05:05:36.6061419Z" />

       9:             <Source Name="System.ServiceModel.MessageLogging" />

            <Correlation ActivityID="{9fab5e4d-4608-490e-bbf0-4b1ba0393227}" />

            <Execution ProcessName="ClientApplication" ProcessID="4144" ThreadID="1" />

            <Channel />

            <Computer>MyComputer</Computer>

        </System>

        <ApplicationData>

            <TraceData>

                <DataItem>

                    <MessageLogTraceRecord Time="2011-04-12T10:35:36.6061419+05:30" Source="ServiceLevelReceiveReply" Type="System.ServiceModel.Channels.BufferedMessage" xmlns="http://schemas.microsoft.com/2004/06/ServiceModel/Management/MessageTrace">

                        <HttpResponse>

                            <StatusCode>OK</StatusCode>

                            <StatusDescription>OK</StatusDescription>

                            <WebHeaders>

                                <Connection>Close</Connection>

                                <Content-Length>185</Content-Length>

                                <Cache-Control>private</Cache-Control>

                                <Content-Type>text/xml; charset=utf-8</Content-Type>

                                <Date>Tue, 12 Apr 2011 05:05:36 GMT</Date>

                                <Server>ASP.NET Development Server/10.0.0.0</Server>

                                <X-AspNet-Version>4.0.30319</X-AspNet-Version>

                            </WebHeaders>

                        </HttpResponse>

                        <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">

                            <s:Header></s:Header>

                            <s:Body>

                                <AddIntResponse xmlns="http://tempuri.org/">

                                    <AddIntResult>3</AddIntResult>

                                </AddIntResponse>

                            </s:Body>

                        </s:Envelope>

                    </MessageLogTraceRecord>

                </DataItem>

            </TraceData>

        </ApplicationData>

    </E2ETraceEvent>

The same process repeats itself for the AddDouble method.

There’s more in the next part.

2 Comments