await Task.Run altering trace ActivityId on exit

Question

I am trying to use the Trace.CorrelationManager.ActivityId to correlate log entries. However, I'm finding when this code finishes:

var result = await Task.Run(() => LongRunningMethod());

The ActivityId has changed from what it was when it was entered. While in LongRunningMethod() it is correct (i've got various trace events in the method), it only seems to change when the await completes.

My question is why has ActivityId changed?

This line of code is in a function declared with async, which is in turn called by an async controller action in an MVC project:

async public Task<ActionResult> Index()
{
...
var tasks = {list of Download<T> delegates}

var result = await Task.WhenAll(tasks)
}


async public Task<OperationResult> Download<T>(IEnumerable<T> data, Device device)
{
...
var result = await Task.Run(() => LongRunningMethod());

return result
}

Perhaps I am using the async/await or Task methods incorrectly? I basically want all the 'LongRunningMethod' to be started at the same time asynchronously and then wait till all finish.

Answer 1

It is not clear why you are using the await keyword. If you do not need a 'continuation' of the required task, start it using

var result = Task.Factory.StartNew(() => LongRunningMethod());

It is likely (but not guaranteed due to the small amount of code you have given) that you have code after the call to await. await is causing a continuation to be setup which will run using a different synchronisation context that that used to run your LongRunningMethod() which will run on a background thread-pool thread.

I hope this helps.

Answer 2

You're not doing it wrong, but it won't work.

Under WCF and ASP.NET (including MVC), before the framework executes a request, it captures the current context, so it can restore it to make sure that the completion runs on the original thread.

Unfortunately, this happens BEFORE your controller gets called. The system's snapshot occurs before you have a chance to update the ActivityID. In the continuation, the context is reset to the value before you set it.

I've found that if you add .ConfigureAwait(false) to your task, the continuation doesn't have to run on the original context, so your activity ID will be restored.

I don't have a better solution for this at the moment, other than to use CallContext.LogicalGetData/LogicalSetData to manage your own ActivityID. For the way I handled it in EventSourceProxy, see https://github.com/jonwagner/EventSourceProxy/commit/fa43c6acd07690dcd276346e3fcf25028f796b8c

Here's a great writeup of a deeper explanation.

http://sticklebackplastic.com/post/2007/08/14/One-mighty-gotcha-for-SystemDiagnostic-activity-Ids.aspx