WCF Trace Tool

2

February 16, 2009 by Alistair Deneys

I’ve been doing a fair bit of WCF lately. And an absolute nightmare of an error to try to debug is the “Channel was in a faulted state” error. This is a very generic error and doesn’t really say much at all about the cause of the error.

The way WCF communicates is through channels. When a channel is in the faulted state, it means the construction and opening of a channel failed for some reason, and the channel faulted. Once in the faulted state a channel cannot be used. It must be constructed again.

So how do I debug this issue and resolve the cause of the error? If only there were some way of getting more information out of the channel creation process. Enter the WCF Trace Tool. WCF traces a fair bit of information when it’s doing it’s thing. There’s a lot going on under the hood, and Microsoft realise that we need to know what exactly is going on. So now all we have to do, is catch that trace.

Open up web.config and add the following configuration to /configuration/system.serviceModel:

<diagnostics performanceCounters="All" wmiProviderEnabled="true">
  <messageLogging logEntireMessage="true" logMalformedMessages="true"
    logMessagesAtServiceLevel="true" logMessagesAtTransportLevel="true"
    maxMessagesToLog="100000"/>
</diagnostics>

Then add the following to /configuration/system.diagnostics:

<sharedListeners>
  <add name="sharedListener"
    type="System.Diagnostics.XmlWriterTraceListener"
    initializeData="c:\logs\servicetrace.svclog" />
</sharedListeners>
<sources>
  <source name="System.ServiceModel" switchValue="Verbose,
ActivityTracing" >
    <listeners>
      <add name="sharedListener" />
    </listeners>
  </source>
  <source name="System.ServiceModel.MessageLogging"
    switchValue="Verbose">
    <listeners>
      <add name="sharedListener" />
    </listeners>
  </source>
</sources>

Thank Michele Leroux Bustamante for this info from her blog entry SvcTraceViewer.exe – Learn it, Know it, Love it.

Now when WCF is invoked, an XML trace file is written to the location above in the initializeData attribute. You could try inspecting this file in a text or XML editor, but the easiest way to inspect it is to use the WCF Trace Viewer which ships with the .net 3.0 SDK. This can be found at c:\Program Files\Microsoft Visual Studio 9.0\SvcTraceViewer.exe (that might only be the location if you have VS installed).

Just execute this program and load the XML trace file into it using the file menu. Now I can inspect the process of channel creation, servicing requests, and channel destruction. If I get an error it will be highlighted red.

Now let me tell you about what I was doing when I found this tool, as I reckon this is a pretty cool feature of WCF. Being that I’m building web sites, I of course usually host my WCF services in IIS. IIS only supports the HTTP protocols. As we all know HTTP only supports request / response calls. A server cannot send data to a client unless it is a response to a request. But WCF allows us to get around this limitation of HTTP, by using the duplex channel.

A duplex channel facilitates two way communication between a client and the server. How is this done? When the client sets up it’s channel, it communicates with the server and registers itself. To allow the server to call back into the client, the client sets up it’s own WCF service and tells the server about it, so the server can just call the service hosted by the client. So to facilitate two way communication, each machine hosts it’s own service which the other machine makes calls to. And the client side service is completely transparent to the developer.

So what did I need the trace tool for? Initially I was hosting the service I had issues with on the same machine as I was calling it from. Whilst both the server and the client were the same machine, I didn’t have any issues. I then moved the service onto another machine that was only connected to the first through a VPN. All of a sudden I started getting the faulted channel error. After enabling the trace and reading it in the trace viewer I could see the call where the client registers it’s callback service with the server. And I could see that the host name the client was sending to the server was the internal machine name which wouldn’t resolve through the VPN. After I changed this by setting the clientBaseAddress attribute on the binding, and applying the appropriate security, all worked fine.

I never would have worked this out had it not been for the trace viewer. I could have ripped out wireshark (you know it’s a bad day when you have to rip out wireshark 🙂 ), but this was a production server where the error was occurring, and I wouldn’t have liked to deploy such a heavy tool to work it out. I hope this save you some sanity.

Advertisements

2 thoughts on “WCF Trace Tool

  1. Hey,
    Just so you know be very carefull with WCF and website, the reason for this is that you start to run into weird behaviour and performancing issues. The reason for this is that the WCF is mainly a generic library and has lots of added features your not really using, this can cause timeouts, delays etc when the WCF channels are either maxed out or returning large data sets.

    Here are a few things:
    – Creating a channel is the most taxing thing on the system, so try and reuse and keep open the channels.
    – Instead of directly calling the Method to return the data, call the .Open() first, this will give minor performance increases.
    – Always check to see if the channel is in the correct state and don’t call Close() unless it’s needed.

    Here is a very very basic example (Please note it doesn’t resuse the channel):

    try
    {
    // do we have to create a new reference
    if (client.State == System.ServiceModel.CommunicationState.Closed)
    {
    client = new MediaServiceClient();
    }

    // make sure the client is set to created and not already opened or closed
    if (client.State == System.ServiceModel.CommunicationState.Created)
    {
    // open the model
    client.Open();

    // fetch the information
    item = client.GetMethodData(_methodId);
    }
    }
    catch (System.Exception ex)
    {
    // there was an error so log the bug
    Diagnostics.Log.Error(“Method Details”, ex, this);
    }
    finally
    {
    // make sure we can actually close the client
    if (client != null &&
    (!(client.State == System.ServiceModel.CommunicationState.Closed) ||
    !(client.State == System.ServiceModel.CommunicationState.Closing)))
    {
    // kill the client
    // is the current state faulted
    if (client.State == System.ServiceModel.CommunicationState.Faulted)
    {
    client.Abort();
    }
    else
    {
    // kill the client
    client.Close();
    }
    }
    }

    For more info on WCF info check out this blog:
    http://blogs.msdn.com/wenlong/default.aspx

  2. Bruce says:

    I have a strange problem with trying to get tracing to work. I have one example where I used WCF under IIS and I did get a log file created (but not immediately sometimes and it didn’t always get written to until much later…very strange). I still haven’t figured out what’s going on there.

    However, I have a new WCF example (fairly simplistic) with Basic HTTP binding, running under the WCF Test Client and no log file is created. All of the sections noted in this blog above are present in the config, but I still don’t have a trace. Any ideas as to what I should look for? Should it work under the WCF Test Client?

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Categories

The views expressed on this blog are solely my own and do not necessarily reflect the views of my employer.
%d bloggers like this: