Identify log entries across a series of async operations

Question

I have seen in the past people associating log entries on thread ID; an imperfect solution, but one that worked in many cases. Having started doing async programming in c#, I am curious what is the best way to handle logging across multiple async operations. So an example:

async Task<string> GetSongNameAsync(byte [] songBytes, AuthInfo auth)
{    
    Log("Received request from user " + auth.User);
    if (!await Authentication.HasPremiumAccountAsync(auth)) // More logging in here
    {
        return "Error: Your subscription does not support this feature";
    }

    Song song = await SongIdentifier.IdentifyAsync(songBytes); // Even more logging here
    if (song != null)
    {
        return song.ToString()
    }

    return new Song() {Name = "Never Gonna Give You Up", Artist = "Rick Astley", Notes = "You just got rick-rolled!"};
}

If there is an error in the auth logic or the song ID logic, I'd like to associate the error with the particular request, so that I can query my logging database and see somewhat-sequentially how the request was handled, and maybe why it failed. I could start passing around a Guid or something like that, and include that in the message, but it seems somewhat cumbersome to make every constructor and object expose this value, when I really want it at the async equivalent of 'thread local storage'.

Answer 1

You can use Task.Id ,and the static Task.CurrentId in a somewhat similar way to Thread.Id, but it doesn't really play along with async\await as you can see here. I think the best approach is to identify each request you receive in a unique way, either by attaching a requestId to it (or to the base class), using something provided by the infrastucture (in WCF this would be OperationContext.Current.IncomingMessageHeaders.MessageId), or by using the exact tick (maybe with thread id) when the request was received as the ID.

---

BTW this is also a nice solution if your request is handled across a distributed system

---

Regarding your comment..

You can:

public static class MagicalHelpper
{
private static ConditionalWeakTable<object, int> _registry = new ConditionalWeakTable<object, int>();

public void GetId(object obj)
{
 int result = _registry.GetValue(obj, ((object key)=> DateTime.Now.Ticks +   
                                                  Thread.CurrentThread.ManagedThreadId));
  return result;

}
}

this was written without a compiler...

Now whenever you want, you can just go MagicalHelpper.GetId(something) just remember to stick to the same request object...

This should be compleatly thread safe, and not cause any memory leak. ConditionalWeakTable documentation: http://msdn.microsoft.com/en-us/library/dd287757.aspx

Answer 2

There's a large MSDN article on this subject here. There's no simple solution, but it describes one method of doing this using ExecutionContext and thread local storage. There's some example code of this. Caveats apply though.

There's also an alternative answer for this question if you're running .Net 4.5