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
{
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;
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
{
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();
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();
}
}
}
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)
{
if (comboOperation.SelectedIndex < 0)
{
MessageBox.Show("Select an operation.");
return;
}
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);
}
...
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);
}
}
...
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!
