Click here to Skip to main content
Click here to Skip to main content

Debugging WCF Apps

, 20 Jan 2007
Rate this:
Please Sign up or sign in to vote.
Exploring diagnostic utilities for WCF

Introduction

I've been meaning to write this for a while now but the day job keeps getting in the way. After having given WCF such accolades in the previous article I knew that sooner or later reality would settle in and things would take on a more down to earth perspective. I am still pretty positive with regards to WCF, I think it's the most complete solution that's come out of Redmond. Is it the last framework we'll see? No, I'm sure the successor is probably in the works already. But it's certainly a very good foundation for the future, at least much better than COM turned out to be. Anyway, in this article I thought I'd share some of my experiences in working with WCF. Specifically some of the tools that I've found useful in debugging WCF applications. In a subsequent article perhaps Ill have the time to present some of the pitfalls that I have experienced.

Paying the Piper

No matter how good we think we are, at some point we all have to resort to some down and dirty debugging. There seems to always be something. Sometimes it's simple to find and fix other times not so easy. But always something. Fortunately Visual Studio does provide us with a very rich debugging environment. However, debugging a distributed application does pose some new challenges. If the bug happens to be within your code then your lucky. If on the other hand it's something that happens after you invoke the call to the service, good luck! There is a big mountain of code that sits between your client code and the other end. If you also control the service side code things are also a little better. But if the problem appears to be somewhere in between, what do you do? ; How do we know that WCF is interpreting our calls correctly or that we are using the myriad of classes that make up WCF in the right way?

I suppose different people have different strategies or approaches to debugging. I try to find clues that make sense to me as to why the system is behaving the way it is. Although I've caught myself saying more than once "That doesn't make sense!" Once you've found it, however, it almost inevitably does make sense. Another technique is the divide and conquer approach where we try to weed out the least likely suspects and concentrate on proving or disproving each one. Debugging, in the end, is a problem solving process. And the more tools we have at our disposal the easier and perhaps the faster a solution will be found.

Since I'm a hands on kind of person, I write the text as if you were firing up the compiler and following along. That's not completely necessary and you should benefit from just the article text since the code is pretty straight forward. However, I would suggest spending some time with the utilities describe in the text since there is a lot to be learned there and only experimentation will do.

Building A Test Service

So let's get started. Create a console app and have it host a service as indicated in the code below. The service has one method and performs the operation specified by the client. Very simple, same as most of the sample code supplied with the SDK. I've just made some modifications (using enums, returning an object, etc.) simply to make it a little more interesting.

namespace CheckPointe
{
   [ServiceBehavior(InstanceContextMode = 
      InstanceContextMode.Single, ConcurrencyMode = 
      ConcurrencyMode.Multiple)]
   public class WCFService : IWCFService
   {
      // Returns the result of the requested operation
      public OperationResult DoOperation(OperationType op, 
                              int value1, int value2)
      {
         OperationResult or = new OperationResult();
         try
         {
             switch (op)
             {
                 case OperationType.Add:
                      or.Value = value1 + value2;
                      break;
                 case OperationType.Sub:
                      or.Value = value1 - value2;
                      break;
                 case OperationType.Mul:
                      or.Value = value1 * value2;
                      break;
                 
                 //exception will catch div by zero
                 case OperationType.Div: 
                      or.Value = value1 / value2;
                      break;
             }
             or.Result = ResultCode.Success;
         }
         catch (System.Exception ex)
         {
             Trace.WriteLine(ex.Message);
             or.Result = ResultCode.Fail;
         }
         return or;
     }
     static void Main(string[] args)
     {
         NetTcpBinding tcpBinding = new NetTcpBinding();
         NetNamedPipeBinding pipeBinding = 
            new NetNamedPipeBinding();

         Uri tcpBaseAddress;
         Uri pipeBaseAddress;
         ServiceHost host = null;

         try
         {
             //We'll support two transports, one local 
             //and one remote
             tcpBaseAddress = new Uri(
                ConfigurationManager.AppSettings[
                "baseTcpWCFService"]);
             pipeBaseAddress = new Uri(
                ConfigurationManager.AppSettings[
                "basePipeWCFService"]);
             host = new ServiceHost(typeof(CheckPointe
                .WCFService), tcpBaseAddress, 
                pipeBaseAddress);

             host.AddServiceEndpoint(typeof(CheckPointe
                .IWCFService), tcpBinding, tcpBaseAddress);
             host.AddServiceEndpoint(typeof(CheckPointe
                .IWCFService), pipeBinding, 
                pipeBaseAddress);

             host.Open();

             // The service can now be accessed.
             Console.WriteLine("The service is ready.");
             Console.WriteLine("Press <ENTER> to terminate 
                                service.");
             Console.WriteLine();
             Console.ReadLine();
         }
         catch (System.Exception ex)
         {
             Trace.WriteLine(ex.Message);
         }

         if (host != null)
             host.Close();   //Release host
      }
   }
}

The config file for the service is indicated below. I'm initializing the endpoints a little differently than in the previous article but the net results are the same. The service supports two transports, named pipes and Tcp, one for local and one for remote clients. And the interface definition is kept as a separate file so that it can be made accessible to the client. You can see the directory structure in the download source.

<configuration>
  <appSettings>
    <add key="basePipeWCFService" value=
       "net.pipe://localhost/WCFService" />
    <add key="baseTcpWCFService" value=
       "net.tcp://localhost:9000/WCFService" />
  </appSettings>
</configuration>

Building A Test Client

The following is the test client that we'll use to consume the service described above. It's built as a Form so that we can have a more interactive test and we can perform several operations during the test.

The only code of interest in the client is the handler for the Send button. And that code is shown below. We just make sure that we've got a valid inputs and then format the appropriate method call to the service.

...
private void buttonSend_Click(object sender, EventArgs e)
{
    //Make sure we got an operation selected
    if (comboOperation.SelectedIndex < 0)
    {
        MessageBox.Show("Select an operation.");
        return;
    }
    //And we need some values...
    if (textVal1.Text.Length == 0 || 
        textVal2.Text.Length == 0)
    {
        MessageBox.Show("Need two numbers...");
        return;
    }
    OperationType opType = (OperationType)Enum.Parse(
       typeof(OperationType), comboOperation.Text);

    WCFServiceClient client = new WCFServiceClient();

    OperationResult or = client.DoOperation(opType, 
       System.Convert.ToInt32(textVal1.Text),System.Convert
       .ToInt32(textVal2.Text) );
    if (or.Result == ResultCode.Success)
        textResult.Text = or.Value.ToString();
    else
        MessageBox.Show("Couldn't do it!");
}
...

And we know the client needs a proxy in order to make a call to the service so here's the code for that. I hand edit the proxies since it's easier than using the svcutil but that's just personal preference.

using CheckPointe;
   public interface IWCFServiceChannel : IWCFService, 
      System.ServiceModel.IClientChannel
   {
   }

   [System.Diagnostics.DebuggerStepThroughAttribute()]
   public partial class WCFServiceClient : System
      .ServiceModel.ClientBase<IWCFService>, IWCFService
   {
      public WCFServiceClient() { }
      public WCFServiceClient(string 
         endpointConfigurationName): base(
         endpointConfigurationName)
      {
      }
      public OperationResult DoOperation(OperationType op, 
         int value1, int value2)
      {
         return base.Channel.DoOperation(op,value1,value2);
      }
   }

And finally here's the config file data that defines the service endpoint.

<configuration>
  <system.serviceModel>
    <client>
      <endpoint address="net.tcp://localhost:9000/WCFService" binding="netTcpBinding"
        contract="IWCFService" name="WCFService" />
    </client>
  </system.serviceModel>
</configuration>

So, there's nothing special about the client or the service. Very simple, the client simply sends two values to the service along with an operation type. The service performs the specified operation on the two values and returns the result of the operation.

Let 'er Rip!

Go ahead and build the service and start it up. Then build the client and execute it. Enter two values in the entry fields on the client and press the Send button. You should see the results of the operation. Everything worked, right? Try a couple of different operations to prove that everything is working correctly. Well everything might seem to be working but in actuality there is a bug. Yessiree Bob, there is one. Let's see if we can bring it up to the surface so we can see that there actually is one. Modify the code for the client as shown below and recompile and run the test.

...
OperationType opType = (OperationType)Enum.Parse(typeof(
                        OperationType), comboOperation
                        .Text);

for (int n = 0; n < 50; n++)
{
   WCFServiceClient client = new WCFServiceClient();
   OperationResult or = client.DoOperation(opType, System
      .Convert.ToInt32(textVal1.Text), System.Convert
      .ToInt32(textVal2.Text));
   if (or.Result == ResultCode.Success)
      textResult.Text = or.Value.ToString();
   else
      MessageBox.Show("Couldn't do it!");
   Thread.Sleep(100);  //A short breather
}
...

This time you should see the hour glass appear on the client and shortly afterwards you'll get an exception. The exception will be that a timeout was not handled and that's true because there is no try catch block in the code. But what caused the timeout? When I first encountered this, the application I was working on had about a dozen services which were all interconnected in different ways. Finding a repeatable sequence and following the calls was a little bit of a challenge.

For now, we'll get rid of the bug so we can verify that we can fix it. Later we'll put it back in so we can explore the debugging tools and see how they can be used to help us in testing and debugging. But before we do that go ahead and do one more thing. Remove the loop in the code above so that the code reverts back to the original code. Compile and run the application. Performs as many operations as you care to do from the UI and see if you get an error. You can do 50 operations without any signs of an error. How come the error is generated when it's in the loop and not from the UI? Revise the code again as shown below and re-run the test.

...
OperationType opType = (OperationType)Enum.Parse(typeof(
   OperationType), comboOperation.Text);

for (int n = 0; n < 50; n++)
{
   using (WCFServiceClient client = new WCFServiceClient())
   {
      OperationResult or = client.DoOperation(opType, 
         System.Convert.ToInt32(textVal1.Text), System
         .Convert.ToInt32(textVal2.Text));
   if (or.Result == ResultCode.Success)
       textResult.Text=or.Value.ToString();
   else
       MessageBox.Show("Couldn't do it!");
       Thread.Sleep(100);  //A short breather
   }
}
...

You should see the result of the operation displayed almost immediately. So what was the bug? Well, using the using construct automatically releases resources that may have been used by the object. In this case I'm guessing it's the underlying socket that was not being released. When the calls were being made from the UI (without the loop), maybe there was enough time for the garbage collector to kick in and release the resource. That's my guess, and sometimes we just have to guess as to what may be happening in external code. Other times you just don't care because you found a work around and you move on to other problems. But there are times when you just want to make some sense of it. Who would've thunk?! There's other .Net classes where Close is called automatically in the destructor. What's the rule?. Oh well, jot this one down in the frontal lobe.

Telling WCF to Talk to You

OK, so now to the point of this article. How can we check to see if there are errors happening that may cause headaches under some instances? What can we use to give us a clue as to where to look? And in fact, tell us when there are errors when we have no visible indication. Let's start by taking a look at the SvcConfigEditor. You should find it along with a bunch of other utilities in the Bin directory where the SDK was installed. Go ahead and start up the utility. ;

In the menu select File...Open and then select the config file for our test client.

;

You can use SvcConfigEditor to add your endpoints, binding, services, and anything else that can be defined, to your App.config file. Since we added the service endpoint by hand above you should see that information if you click on the WCFService node. What we're interested in right now is the folder labeled Diagnostics. We'll use that to configure our application so that WCF outputs trace information to a file and we can see what it's doing. We are going to use the default XML trace viewer available in the SDK. Go ahead and click on the Diagnostics node so we can specify the options.

There are two things we want to specify, a listener and a source. We first need to specify the source since the listener will need a source specified. Start by selecting the Sources node. The right hand pane will display the options that are available. In the Name field select System.ServiceModel. Now select the Trace Level that we want to see. If you select Verbose you will get everything. By the way, remember that once you configure tracing for WCF there will be a lot of data being generated. So expect everything to slow down accordingly. For our test, select Information.

Now that we've specified a source we can go ahead and specify a listener. Select Listeners and then click on Create Listener. The right pane will display an edit window where you can specify the options. There is a name already specified so leave that as is. We'll also accept the default for the TraceOutputOptions and TypeName. The TraceOutputOptions let you specify what information you'd like to see in the trace statements. And the TypeName is where we can specify the listener that we want to use. If you click on the entry field you'll be able to see the other options that are available. And as with a lot of .Net, you can also create your own listener. The only thing that we need to specify here is where we want the output stored. Enter a path for the file and change the default name to 'WCFClient.svclog'. The only thing that's left is to select a source for the listener. Depress the 'Add...' button and select System.ServiceModel. Close the editor to save the changes.

Go ahead and make similar changes to our test service config file. Use 'WCFService.svclog' as the file name, or whatever you like as long as the name for the client and service are different unless you are specifying different folders. Side note: the reason why you don't see the service endpoint specified in the SvcConfigEditor is that I am initializing the ServiceHost programmatically. Just a preference on my part. You can see the differences by looking at the previous article.

If you go back and take a look at the config file for the client and service you'll see that there a couple of new entries. This is how we'll tell WCF to tell us what it's doing, and of course any errors it may encounter.

Let the Talking Begin

OK, we are ready. You can go ahead and start the service, but on the client we want to change the code back to what we had originally as shown below.

...
OperationType opType = (OperationType)Enum.Parse(typeof(
   OperationType), comboOperation.Text);

WCFServiceClient client = new WCFServiceClient();
OperationResult or = client.DoOperation(opType, System
   .Convert.ToInt32(textVal1.Text), System.Convert.ToInt32(
   textVal2.Text));
if (or.Result == ResultCode.Success)
   textResult.Text = or.Value.ToString();
else
   MessageBox.Show("Couldn't do it!");
...

Compile and start up the client. Go ahead an perform one operation on the client and when the result is displayed shut down the app, and shut down the service as well. Here's where the fun begins. In the Bin directory where you found the SvcConfigEditor there is another utility named SvcTraceViewer. Guess what it's for? Go ahead and start it up. From the File...Open menu select the log file that was created for the client, 'WCFClient.svclog'.

Wow! A mother lode of information! Let's take a look at some of the information that we've captured. The left pane shows a list activities with descriptive names like 'Construct ChannelFactory', 'Open ClientBase', and 'Process action'. All are activities that we would expect to have happened on the client. If you select any of the activity items, the right hand panes will be updated with detail information. Look at the left pane 'Open ClientBase' item, it indicates that there are four traces for that activity. When you select it, the right hand pane displays the four traces that were emitted. Select any of the trace items, the bottom right pane will display details for that trace. You can see that the proxy (ClientBase) was initialized with contract IWCFService. You can also see that we sent the message DoOperation.

So we have a lot of information but everything looks like it should. There's no indication of any error anywhere. Let's look at the service side. Open the service log file using the trace viewer. ; Similar information is presented, but look!, half-way down in the activity list there is an entry that is highlighted in red. That can't be good.

Go ahead and select the activity that's highlighted in red. The right hand pane will display the detail trace information. Well, there's a trace indicating that an exception was thrown. Select the trace to see the details in the bottom pane. The Message field indicates that the socket connection was aborted and that it was a timeout. Unfortunately we won't find a trace statement that says 'You forgot to call Close, you dummy.' The best we can hope for is enough clues to help us in narrowing down the causes or maybe even just identifying a point in time. There is also another clue here. If you double click the activity that's highlighted in red or select the Graph tab you'll see a graphical time sequence of the operation. Pretty cool if you ask me. If you select any of the nodes on the graph you'll see the details for it. The clue that I see here is that the exception actually occurred after the response was sent back to the client. And in fact if you look at the timestamp it occurred much later. Yeah, I know, it's a lot easier once you know what the bug was.

But Wait There's More!

Yes, there is more! From the File menu on the SvcTraceViewer select 'Add...' and enter the name of the client log file. Now we've got both trace files to look at the same time. But the cool part is in the Graph view. Go ahead and select that view now.

As you can see the graph displays the complete communication cycle between the client and the service! And if you had multiple intermediate services you could follow the path through each one. If you click on any item in the graph the right hand side is updated with the details. Remember also that we did not select the 'Verbose' level for the tracing. Verbose provides much more detail.

In Summary

No, we don't have a debugging utility yet that will analyze our code and pinpoint where we've goofed. If there was I think we'd all be out of a job. WCF is an excellent framework for developing distributed applications but distributed apps are still challenging. The good news is that WCF's trace capabilities provides us with information that can be invaluable when we are trying to track down a bug. And SvcTraceViewer is an excellent utility that should become part of your debugging arsenal. Have fun!

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)

Share

About the Author

Al Alberto
Software Developer (Senior)
United States United States
No Biography provided

Comments and Discussions

 
GeneralWindows Communication Foundation Tools PinmemberMarc Livin24-Jul-07 1:43 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.

| Advertise | Privacy | Mobile
Web02 | 2.8.140821.2 | Last Updated 20 Jan 2007
Article Copyright 2007 by Al Alberto
Everything else Copyright © CodeProject, 1999-2014
Terms of Service
Layout: fixed | fluid