WCF Debugging

jscreationzs / FreeDigitalPhotos.net

I must say that setting up WCF and making it running with the simplest “Hello WCF” functionality is pretty simple. But when your architecture gets more complicated, the object graph gets more complicated, it quickly becomes a nightmare to find bugs without knowing about what tools there are to help you.

In my current project at Avanade we are building a WPF application that is executed through Citrix. Each client application in fetching data from a database and SAP using WCF services hosted by a Windows Service. This has worked pretty good for a while but suddenly started to act really weird. No obvious exceptions or nothing, just that from time to time the WCF services returned NULL. Time to debug! :)

I would say that the most important part in WCF development (well basically all application development) is actually that you have a proper knowledge of how to do debugging. When talking about WCF debugging there are several “places” where you would like to debug but you usually start by enabling tracing to log all operations made on the service(s).

WCF Tracing
The easiest way of enabling tracing is by using the SvcConfigEditor.exe tool (unless you really like coding directly in the .config files). Start by right-clicking on the App.Config file for the WCF service host and select the option “Edit WCF Configuration”. On the left hand side under “Configuration”, navigate to the Diagnostics node and click the “Enable Tracing link”. This will enable tracing of your WCF service and add all needed configurations in the App.Config file.

Here you can change some settings like, trace level, change trace file location and so on. You can read more about that at MSDN, http://msdn.microsoft.com/en-us/library/ms733025.aspx

One important part here is where the traces will be written. The default location is in the folder where WCF service is hosted and in a file called app_tracelog.svclog. You can easily change that under node Listeners/ServiceModelTraceListener by changing the initData attribute value.

If we close the SvcConfigEditor tool, we can see that all needed configurations are added to the App.Config file. If we take a look in the configuration file you should have something similar to this:

  <system.diagnostics>
    <sources>
      <source name="System.ServiceModel" switchValue="Warning, ActivityTracing"
        propagateActivity="true">
        <listeners>
          <add type="System.Diagnostics.DefaultTraceListener" name="Default">
            <filter type="" />
          </add>
          <add name="ServiceModelTraceListener">
            <filter type="" />
          </add>
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add initializeData="c:\log\app_tracelog.svclog"
        type="System.Diagnostics.XmlWriterTraceListener, System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
        name="ServiceModelTraceListener" traceOutputOptions="Timestamp">
        <filter type="" />
      </add>
    </sharedListeners>
  </system.diagnostics>

Examine the Trace file
Now it’s time to do some debugging. Start your application and run the services that are failing or acting weird. In my case I had to start and restart the application several times since my problem just showed itself now and then. But after I have successfully replicated the problem I closed my application and browsed to my log folder and double-clicked the .svclog file. This will now open the SvcTraceViewer.exe tool so that you can view what has actually happened and analyze all the diagnostic traces that are generated by WCF. In this tool you can easily filter trace messages, view, diagnose and verify WCF service issues. There is a lot of information here related to the traces, information that shows what is actually happening, and hopefully I will find my issue here. Through the diagnostic traces you can follow all the operations from source to destination so I bet I will find my source of problem here.

This tool also gives you some visual helpers, items/operations in yellow are warnings and items in red are exceptions, but I had a little surprise waiting, not a single yellow or red item. I went through them all to see if I could find anything that could hint me with what is going on here. Remember my issue is that from time to time the WCF service operations returns NULL, but not always, it also works now and then…

To be able to debug the diagnostic traces even deeper you have to enable Message Logging. This will make our debugging process even more effective since we also get details about the actual message itself. Perhaps there is something wrong with the message, are we actually sending a message or what?

Message Logging
To get information about the actual message that is sent, we need to enable Message logging in the WCF Configuration Editor. In the same way as we did for tracing, using the tool, we can easily enable Message logging by clicking the “Enable message logging” link. This creates all the necessary configurations for you. Again, make sure the message log file is located where you want it to be, if not change it :). If we close the configuration editor and examine the .config file once more we see that is has added listeners in same way as for Tracing. But there is one new part that needs a little bit more attention.

  <system.serviceModel>
    <diagnostics>
      <messageLogging logMalformedMessages="true" logMessagesAtServiceLevel="false"
        logMessagesAtTransportLevel="true" />
    </diagnostics>

The above configuration is the default, but I usually change this to make sure I get all possible information. Since if I have turned Message logging on then I want as much information as possible about my traces. After some new changes using the WCF configuration editor, I end up with the following config:

  <system.serviceModel>
    <diagnostics>
      <messageLogging logEntireMessage="true" logMalformedMessages="true"
        logMessagesAtServiceLevel="true" logMessagesAtTransportLevel="true"
        maxMessagesToLog="10000" maxSizeOfMessageToLog="10485760" />
    </diagnostics>

You can read more about these settings at MSDN, http://msdn.microsoft.com/en-us/library/ms730064.aspx

But I would like to highlight two of them, maxMessagesToLog and MaxSizeOfMessageToLog.

  • maxMessagesToLog gives you the opportunity to limit the total number of message in the log and thus limiting the size of the log file.
  • maxSizeOfMessageToLog allows you to set a restriction on how large messages will be logged, thus also limiting the size of the log file.

I hade to turn up the MaxSizeOfMessageToLog value to 10MB since we are sending very large objects over the channel.

Examine Message Logs
Now how do you examine these message logs? Well in SvcTraceTool there is a tab called Messages, if we look in that now it is empty even if you have opened your app_tracelog.svclog trace file. To show the message logging you navigate to the project tab, and while the app_tracelog.svclog is loaded, right-click the Project node and select Add File. Browse to the app_messages.svclog file and add it. The message logging is now merged with the traces and this information can be very useful for debugging purposes.

But was I lucky? Did I find my root cause of the problem. Nooo!! Everything looks good, not a single strange thing going on.

So by examining the traces and message logs we now know that WCF is most likely not the evil general in this bug. Through the traces and message loggings I could see that the messages was as expected, we are not sending NULL to the client. This gives me the conclusion that there has to be something wrong on the client side when the message is received.

SBS (Skit Bakom Spakarna) or more known to you all by PEBKAC
Then it hit me, I have done a custom DataContractSerializer since we have cyclic object graphs in our data, this is where it has to go wrong. Since this part is called by WCF during deserialization of the message we do not get any exception or faults, the result was just NULL. Taking a deeper look at the code I have written showed that I had done something wrong :)

Creating a XmlObjectSerializer is resource heavy, and a while ago when profiling the application we found out that all these xml serializers were kept in memory, they never got garbage collected. So my implementation to this was to use a SerializationFactory to only create a new serializer if it has not yet been created, basically keeping the object count as low as possible. There was a tiny bug in there that returned the wrong xml serializer depending on if the DataContractSerializer used regular “string” or “XmlString” for name, namespaces etc. So all in all, changing one tiny line of code fixed this truly awkward bug we had.

Conclusion
Below is the debugging options to find issue with WCF services i usually use.

  • Debug server side code using Visual Studio to make sure you do not get an exception there, are you sending the correct information that you expect to send.
  • Debug on the client side using Visual Studio to make sure you get the expected values from the service, perhaps there is some exception or error in your code that fiddles with the data after it is received from the service call.
  • Enable tracing and you can easily inspect visually all the messages and make sure that things are going as expected
  • Enable Message logging if traces does not give you the answer. Using message logging you get even more information about the actual messages itself. This really makes the picture complete in the WCF debugging process.

So make sure that you are aware of this tool and how to use it!! It’s truly an excellent way of inspecting messages when things start to go wrong. Debugging WCF services without this is super hard. And a last suggestion, Don’t write bugs! :)

Advertisements
  1. January 3rd, 2012

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

%d bloggers like this: