How to enable trace for WCF service
One thing I like the most about WCF is the extensibility it offers to developers. Without making any code changes we can enable many things using configurations. Tracing is not enabled by default. In order to enable trace we need to add the following code to WCF Web.config file<configuration>
<system.diagnostics>
<sources>
<source name="System.ServiceModel"
switchValue="Information, ActivityTracing"
propagateActivity="true">
<listeners>
<add name="traceListener"
type="System.Diagnostics.XmlWriterTraceListener"
initializeData= "c:\log\Traces.svclog" />
</listeners>
</source>
</sources>
</system.diagnostics>
</configuration>
The level details that gets logged in the output file (C:\log\Traces.svclog) depends on the value of switchValue. The permissible values are
- Warning
- ActivityTracing
- Information
- Verbose
- TextWriterTraceListener
- ConsoleTraceListener
- EventLogTraceListener
- DelimitedListTraceListener
There is another great article on this:
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>
10: <source name="System.ServiceModel.MessageLogging"
11: switchValue="All">
12: <listeners>
13: <add name="xmlTraceListener" />
14: </listeners>
15: </source>
16: </sources>
17: <sharedListeners>
18: <add name="xmlTraceListener"
19: type="System.Diagnostics.XmlWriterTraceListener"
20: initializeData="ClientLogBasic.svclog" />
21: </sharedListeners>
22: <trace autoflush="true" />
23: </system.diagnostics>
24:
25: <!-- child of the <system.serviceModel> element -->
26: <diagnostics>
27: <messageLogging maxMessagesToLog="10000"
28: logEntireMessage="true"
29: logMessagesAtServiceLevel="true"
30: logMalformedMessages="true"
31: logMessagesAtTransportLevel="true">
32: <filters>
33: <clear/>
34: </filters>
35: </messageLogging>
36: </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}" />
10: <Execution ProcessName="ClientApplication" ProcessID="4144" ThreadID="1" />
11: <Channel />
12: <Computer>MyComputer</Computer>
13: </System>
14: <ApplicationData>
15: <TraceData>
16: <DataItem>
17: <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">
18: <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
19: <s:Header>
20: <Action s:mustUnderstand="1" xmlns="http://schemas.microsoft.com/ws/2005/05/addressing/none">http://tempuri.org/ILearnWcfService/AddInt</Action>
21: </s:Header>
22: <s:Body>
23: <AddInt xmlns="http://tempuri.org/">
24: <arg1>1</arg1>
25: <arg2>2</arg2>
26: </AddInt>
27: </s:Body>
28: </s:Envelope>
29: </MessageLogTraceRecord>
30: </DataItem>
31: </TraceData>
32: </ApplicationData>
33: </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" />
10: <Correlation ActivityID="{9fab5e4d-4608-490e-bbf0-4b1ba0393227}" />
11: <Execution ProcessName="ClientApplication" ProcessID="4144" ThreadID="1" />
12: <Channel />
13: <Computer>MyComputer</Computer>
14: </System>
15: <ApplicationData>
16: <TraceData>
17: <DataItem>
18: <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">
19: <HttpResponse>
20: <StatusCode>OK</StatusCode>
21: <StatusDescription>OK</StatusDescription>
22: <WebHeaders>
23: <Connection>Close</Connection>
24: <Content-Length>185</Content-Length>
25: <Cache-Control>private</Cache-Control>
26: <Content-Type>text/xml; charset=utf-8</Content-Type>
27: <Date>Tue, 12 Apr 2011 05:05:36 GMT</Date>
28: <Server>ASP.NET Development Server/10.0.0.0</Server>
29: <X-AspNet-Version>4.0.30319</X-AspNet-Version>
30: </WebHeaders>
31: </HttpResponse>
32: <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
33: <s:Header></s:Header>
34: <s:Body>
35: <AddIntResponse xmlns="http://tempuri.org/">
36: <AddIntResult>3</AddIntResult>
37: </AddIntResponse>
38: </s:Body>
39: </s:Envelope>
40: </MessageLogTraceRecord>
41: </DataItem>
42: </TraceData>
43: </ApplicationData>
44: </E2ETraceEvent>
The same process repeats itself for the AddDouble method.
There’s more in the next part.
Reference:
No comments:
Post a Comment