Service Trace Viewer
Categories
Audience participation time! Download this file, it contains a copy of the Service Trace Viewer program and some demo files (as far as I can see the viewer is only available as part of the Windows SDK, which makes it a little hard to get a hold of).
The demo files are a set of verbose logs from a simple WCF client calling an equally simple WCF service to add 2 numbers and return the result.
Two important links for this one - again, MSDN has the docs in two different places. Here's the doc for the .exe, which provides a metric truckload of information on how to use the viewer. Then this page is a bit more of a tutorial style page, with lots of pictures. I'd strongly suggest reading them both.
Not that you will, so let's crack on. Fire up the viewer and load the service.stvproj file to load all the service .svclog files. You'll see something like this:
The left hand pane is a flattened list of all the activities in all the trace files. Select an item here, and on the top right, you see all the events in that activity, including transfers to and from other activities. Bottom right is the details of a given event, including details such as timestamp, callstack, process details and even the actual WCF message.
If you double click an activity on the left pane ("Listen at http://localhost:8000/CalculateService" is a good candidate for exploring), you'll get taken to the graph view.
Here it is, all things collapsed. It starts on the left with the root activity, and then transfers through all activities (without showing details) until it reaches the Listen activity. The two yellow boxes are events, one of which is the activity boundary, the other is that the client is now actually starting to listen for messages. Select any of these events, and the associated event is highlighted in the two window panes on the right, showing more details.
You can see that this "listen" activity transfers back to the calling (and eventually root) activity, but still continues. When a message does arrive, it is logged in the "listen" activity. We can switch the display mode to Thread (top of the graph view) to see this a bit more explicitly.
Each of the collapsed boxes in the new thread are activities that represent messages arriving. Expanding this first gives us a "receive bytes" activity, with another nested activity - "Processing message 1". One of the events in this nested activity is a "received message" event. Select this and on the bottom right we see a new tab called "Message" which displays the actual SOAP message received (minus any private information - WCF automatically strips known personal information). And we see that this is a request for a security token (WCF is secure out of the box - I would have to create more config to disable security).
Expanding the next activity event gives a whole heap of events and we now start to wish we hadn't enabled verbose logging.
Now what we have here is 4 activities - listen, receive bytes, process message, and the huge process action "http://schemas.xmlsoap.org/ws/2005/02/trust/RST/Issue", which is the SOAP action for issuing a security token via WS-Trust. We can see that processing the Issue action is continuing while several other activities are occurring (the listen activity in the first column has several other activities that are timestamped during the lifetime of the Issue activity). That's because there are several messages exchanged to bootstrap the secure conversation. If you're feeling brave, open up all the activities (leave the fourth one for the minute) and look at the messages. You'll soon find you're looking at encrypted data.
This is a complex example to show as a demo, but it's worth seeing what a real-world trace would look like, how much data is in the verbose traces and especially important to see that activities are not stacks and can happen in parallel.
Incidentally, if there's too much of the verbose logging, you can filter it out, either with the options at the top of the graph view, or by changing the level in the search filter at the top of the main window - this gets rid of a lot of noise.
It's probably worth collapsing all the Listen sub-activities and just look at the fourth one. This is finally the call to the Add service method. Expand its sub-activities, and you'll end up with 5 activities in all - listen, process message 4, receive bytes, process action "http://tempuri.org/ICalculator/Add" and execute service "WcfService.ICalculator.Add". This very last activity is the actual code for the service method. And in it, you should see a simple trace output I added with the following code:
TraceSource ts = new TraceSource("WcfService.TraceSource", SourceLevels.Information);
ts.TraceInformation("Adding {0} and {1} = {2}", a, b, a + b);
(No reference to activities here - the trace automatically picks up the current activity.)
So that's activities and correlation. Let's have a quick look at propagation. Close that project and open all.stvproj. This contains both the service and the client logs, again at full logging levels.
In the Activity list on the left, find the activity called Process action 'http://tempuri.org/ICalculator/Add'. This is the client calling the Add web service operation. Double click the activity, and you'll see a graph of what the client goes through before calling into the server. And it all nicely joins up to the server trace logs, so you now see a full end to end call.
And that's a quick run around with Service Trace Viewer. It's certainly powerful, but I don't think it's the most intuitive program - there's a lot of data, and lot of axes to be looking along, which can be a bit overwhelming. The best thing to do is just play around - select things, double click things, filter things and see what happens.
I think its biggest failing is the difficulty of finding that one trace you're looking for. It's awkward not being able to select the root activity - you have to jump in at the right start activity (clearly displaying the root activity as a graph is just asking for trouble - everything starts off in the root activity, so you're going to get a huge graph). I think searching is going to work best here - but again, you need to know what you're searching for. If you're just looking at errors, then the tool helps; any activity that contains an exception gets highlighted.
But hey - nice graphs!