Just when you thought you knew HTML, they've gone and announced HTML 5.

It looks like they're running with some of the Semantic Web ideas, and have added elements specifically designed to give semantic meaning to parts of a web page. My particular favourite is the <time> element. I've wanted something like this for ages. Currently, when you put a time on a web page, the reader generally has no idea when it is. E.g. what time is 9.50? Is that AM? What time zone? Similarly, is 01/02/2007 February 1st (of course it is) or the 2nd of January? And look at all those blog posts, every one of them with a date and time on them.

Anyway, the <time> element wraps around a bit of text (such as "Sunday") and in the attributes can provide an exact date, time and time zone. The only downside is that there isn't a recommended rendering for the element. Indeed, the browser should probably just render the content of the element, so perhaps the actual date and time (preferably translated to local time) would be available as a tooltip? But that's not very discoverable, is it?

Interestingly, this won't break compatibility with existing browsers because a downlevel browser will ignore the element and just render the content.

But the real question is, why do we need this? The microformats movement have been embedding semantic meaning into web pages via the use of CSS class attributes for ages. Take a look at this example:

Does exactly the same as the <time> element. There's a good comment further down that page that claims this is bad for accessibility reasons - screen readers will read out the title attribute of the abbreviation element for clarity. But then it's easily fixed by simply using a <span> element.

So, HTML5 and Microformats. Which is Betamax, and which is VHS?

I've been scratching my head on this one for several days.

After spending a number of posts looking at System.Diagnostics for tracing, and especially at the concept of activity IDs, I decided to put into a project I'm working on. And it all went wrong.

Here's the scenario. I have a WPF application. At start up, it goes straight into a business process that is neatly encapsulated in a model-view-presenter style, written using the Supervising Controller pattern (well, WPF's databinding is so powerful and so pervasive, it'd be rude not to). When I spin up my controller, I create and transfer to a new activity. Events logged at this point correctly live in the new activity.

When I click a button to make something happen, a (custom) event is raised from the view, and handled by the controller. Events logged here are suddenly not part of the activity. The activity Id has been reset to a zero guid.

From the msdn docs on CorrelationManager:

The CorrelationManager class provides methods used to store a logical operation identity in a thread-bound context and automatically tag each trace event generated by the thread with the stored identity.

So obviously my first thought was that this is a threading issue. Turns out it is, but not how you'd expect.

I verified that the thread I started the activity on and the thread used to execute the event handlers were the same, so they should really have the same activity Id.

A serious session of spelunking with Reflector later (and I do mean serious), I had my answer. The CorrelationManager uses Remoting's CallContext to store the activity Id (which has the nice side effect of being transferred across AppDomain boundaries, propagating the activity Id). Cutting a long story short, the data set via the CallContext ends up (indirectly) in an instance of a class called ExecutionContext.

And it's ExecutionContext that causes all the trouble. Again, from the msdn docs:

The ExecutionContext class provides a single container for all information relevant to a logical thread of execution.

The key word there is "logical".

Ever wondered how your security impersonation data is transferred between threads? What about your call stack for Code Access Security? Yep. ExecutionContext.

Every time you start a thread or queue an operation on the thread pool, the current ExecutionContext is carried with it. This is really rather cool when you think about it.

How does that cause problems for me? Well, WPF, like Windows Forms, needs to marshal calls onto the correct thread to prevent deadlocks. That needs an ExecutionContext. If the ExecutionContext is grabbed before I make my change to the activity Id, it won't get propagated. The existing ExecutionContext, which contains the previous, empty activity Id will be used. Practically, this means that all event handlers run under an ExecutionContext created by WPF, and it's this ExecutionContext I am seeing as having no activity Id. And the ExecutionContext is used even if you're already on the correct thread - presumably for CAS and impersonation reasons.

I can see two ways to fix this problem. If you noticed in the description of my problem - I was starting the activity in code that got evaluated from Main, not from the message pump. If I set it from the message pump, I think I'd be using the same ExecutionContext that WPF uses for the event handlers. I suspect that would look something like:

Dispatcher.Invoke(DispatcherPriority.Normal, delegate {
  _previousActivityId = Trace.CorrelationManager.ActivityId;
  Guid newActivityId = Guid.NewGuid();
  _traceSource.TraceTransfer(0, null, newActivityId);
  Trace.CorrelationManager.ActivityId = newActivityId;
  _traceSource.TraceEvent(TraceEventType.Start, 0, "New activity");
});

But I haven't tried it, so can't be sure - I don't actually know where the WPF ExecutionContext gets created, or even how often it gets created. Relying on this is too flaky for my liking. (But I do like how elegant it is to be able to execute an arbitrary anonymous delegate on the UI thread. Just try doing that in Win32.)

As usual, we can solve this by adding an extra level of abstraction. I think I'm going to add a new class that will encapsulate starting and transferring an activity. All logging will go through this, too, and before each log it will check that the current activity is the correct one. If not, it will set it, log the event and reset it back to what it was. Simple, and effective.

Just to be clear, this won't be a problem for most uses of activities. If you have a bounded activity - i.e. if you both start and stop the activity in a single method, then you'll always be on a single thread of execution, always using the same ExecutionContext and all will be good. If you start an activity and then queue up an operation on the thread pool, the current ExecutionContext (with the current activity Id) will go with it, and again, all will be good. You're only going to have a problem when you have pieces of your activity executing in different contexts, such as with Windows Forms or WPF event handlers.

As can be seen from the last few posts (if you ignore the monsters one), I've been having a bit of a deep dive into the System.Diagnostics tracing classes, and especially the concept of activities (as glorified by WCF's Service Trace Viewer).

I needed a logging solution for a project at work. This was all about seeing if System.Diagnostics was up to the job. Here are the key points I see from this.

Boring Logging Solved

If your requirements are just for simple but flexible logging, then you're sorted. Knock yourself out.

Reducing Dependencies

I don't want my project to have to take on dependencies it doesn't need. It has to be downloaded to a client's desktop. I'd rather not have to download log4net, or Enterprise Library.

Asynchronous Logging

Unfortunately, logging is synchronous, which would mean a performance hit. You'll need to weigh up if this matters to you. Logging in a client application will likely not have as much of an impact as logging on a high volume server side app.

We can mitigate this by writing an asynchronous TraceListener. Or just use Enterprise Library's MSMQ trace listener. There goes point #2 above.

Logging Arbitrary/Ambient Data

You can enable the logging of certain types of standard data, such as process id, thread id and callstack, which is very useful. You can also use TraceSource.TraceData to output custom data, such as a customer identifier. If you always wanted to output the customer identifier (what I'm calling ambient data), you'll need to write a wrapper API.

The nice thing is that once the extra data has been serialised, Service Trace Viewer can search and filter on it, thanks to custom xpath expressions.

End to End Tracing

The value in being able to join up logging at the client side with logging at the server side and view them in a nice tool like Service Trace Viewer shouldn't be underestimated.

But sometimes end to end tracing isn't enough. If you're interested in knowing the steps a customer took to get to a certain point, you need to group all customer interactions into a form of session.

A simple solution would be to have a session identifier as the form of ambient data that always gets output. Then Service Trace Viewer could filter on this.

Another solution would be to write a particular event that ties the session identifier to a specific activity id, then correlate all the activity ids from that.

End to End Tracing Analysis

Which nicely brings me to the analysis of the end to end tracing.

Service Trace Viewer is a nice tool, but I think it's more of a visualisation/inspection tool than an analysis tool.

End to end tracing is a graph. To get all of the records in a single end to end call, I need to walk that graph and follow the transfer of activities. This is fairly straightforward when we're in an xml file that I'll need to process linearly anyway, but if we stored the data in a database? That'd make an interesting query...

But we can still mitigate this. There's nothing stopping storing a session identifier in each record, either at runtime or post processing.

File Formats

Hang on. Databases? Oh.

Service Trace Viewer only supports flat files.

And you can only use STV if you use the XmlWriterTraceListener.

Propogation of Activities/Context

This Just Works when you're using WCF, and is easy to implement if your not, and the gains in end to end tracing are very cool.

Custom Logging in Service Trace Viewer

It appears that WCF interacts so nicely with Service Trace Viewer by chucking out more information. WCF has built a whole load of plumbing on top of System.Diagnostics, all of which is internal, but it helps dump full exception details, give friendly names to activities and so on. I need to investigate this a bit more.

Finished...

It's clear that System.Diagnostics isn't the final word on tracing and logging, but it's certainly Good Enough, and given its extensibility, it's definitely a Good Start.

I wanted to be able to tick enough boxes that I could just use the logging out of the box, without having to go and evaluate any other frameworks. I think I've done that, but only just. Simple logging is handled, but I really like the activities idea. Yet to make it easy to use that, I think I'm going to have to write some wrappers. And if there's extra stuff to output to make Service Trace Viewer play nicer, then maybe that'll be a few more wrappers. That's a little disappointing.