NLog – tracking flow of requests using MappedDiagnosticsLogicalContext

1. Problem

Everyone who has ever had to analyze logs from production environment knows, that quite often it is not an easy task. Usually application flow is deduced by log entries matched by thread id, which is problematic when you deal with multithreading scenarios. Say for example we have following piece of code

Default log file usually looks like that

Having multiple simultaneous Index requests, makes it almost impossible to figure out which log entry is part of which call. Fortunately with NLog it is possible to solve this problem without too much of a hassle.

2. Proposed solution

The whole idea is to leverage MappedDiagnosticsLogicalContext “storage” to keep some unique identifier of request for entire call. Note, that this identifier will be accessible also from other threads created from within given call. In order to set unique request id (also known as correlation id) I will use custom HttpModule. The very first implementation looks like that

Once the HttpModule is ready it is necessary to register it in web.config.

From now on, every request goes through LogginHttpModule and proper correlationId is set in MappedDiagnosticsLogicalContext.
As we want to have correlationId included in log files it is necessary to modify Nlog.config. In my case it looks like that

Note that we can access our correlationId variable via ${mdlc:item=correlationid}
Log file after the changes looks like that

This is almost perfect, however for some reasons correlationId is lost in EndRequest event handler. I am not sure if this is bug in NLog (I’ve posted question in Nlog’s github) or it is by design, however there is easy workaround for that. We can store our correlationId in HttpContext.Items collection and reassign it to MappedDiagnosticsLogicalContext in EndRequest event handler.

After these changes our log file finally looks OK

Source code for this post can be found here

NLog – tracking flow of requests using MappedDiagnosticsLogicalContext

TPL – exception handling and UnobservedTaskException issue

1. Introduction

Working with Tasks is a modern way of writing asynchronous code in an easy and flexible manner. It is quite straightforward to start using them, so usually developers do not investigate thoroughly the topic. Unfortunately this often leads to unpleasant surprises – especially when it comes to exception handling. Having this in mind let’s take a look how to handle exceptions in Task and what can happen if we do it wrong.

2. Exception handling

Because of the fact that Tasks are run asynchronously we can’t just use a standard try catch block surrounding Task

In that case catch block is unreachable (I will describe later what happens with that exception), of course we could use try catch inside Task.Factory.StartNew lambda expression but this is not always the case. Usually we want to handle exception in the caller of the Task, not inside the Task itself. There are couple of ways of achieving that – depending on the situation you can use one of the following ways. Exception are propagated to caller once you start waiting for the result of Task. So basically you can use try catch block if you wait for a Task to finish – either by accessing Result property or using Wait method

However accessing Result or calling Wait method are blocking calls, so this might not be a perfect solution for every scenario. Fortunately we can also leverage ContinueWith method which gives you an ability to specify what should be done once Task finishes processing the operation. What is more important you can configure this method to only be called if exception occurs. Nonetheless there is one crucial thing you have to remember – in order to make exception handled or observed you have to access Exception property of Task

or call Handle method from AggregateException object

Otherwise exception will not be handled which may cause a lot of troubles described in section 3 of this post. Lastly if you use .NET 4.5 you can also just use async await and try catch block

3. Handling UnobservedTaskException

If it happens that exception thrown by Task is not handled, once the Task is garbage-collected, finalizer thread will throw UnobservedTaskException.

The implication of this depends on framework we are running our application on. If you run your app on .NET 4.5 or later version, with default escalation policy, TaskScheduler.UnobservedTaskException event will be raised and basically that is all. No more further problems, so basically you may not even realize that there is something like UnobservedTaskException. However if we add this entry

to app.configour process will be killed once UnobservedTaskExceptionis is thrown.
The problem arises in .NET 4.0 (if you run your app on .NET 4.0 not only compile it against this framework version), in this version of framework default escalation policy is very strict and will kill our process once the UnobservedTaskException is thrown by finalizer thread. Furthermore you cannot change this policy using app.config. Fortunately there is a one last chance to handle UnobservedExceptions and prevent our process from being killed. All you have to do is to wire up TaskScheduler.UnobservedTaskException static event handler and then set exception to observed state

There is one more thing to clarify. You can compile your library against .NET 4.0 but if you have .NET 4.5 installed on your machine, your application is launched and run on .NET 4.5. This means that escalation policy from .NET 4.5 will be used – so by default process will not be killed. In order to simulate pure .NET 4.0 behavior while having .NET 4.5 installed you have to add

in your app.config as it was mentioned before. Otherwise you would have to uninstall .NET 4.5 in order to, for example reproduce production issue. Source code for this post can be found here

TPL – exception handling and UnobservedTaskException issue

Implementing INotifyPropertyChanged without lambda expressions and “magic” strings

I think almost every .NET developer is familiar with INotifyPropertyChanged interface. Typical implementation of this interface looks more or less like that:

Thanks to lambda expressions we can get rid of so called “magic” strings when rising PorpertyChange event.

However, with .NET 4.5 we can even get rid of lambda expressions itself. Everything thanks to CallerMemberNameAttribute, which provides us information about caller of given method. Now we can rewrite NotifyPropertyBase class as follows

From this moment we can call OnPropertyChanged method without any arguments

and thanks to CallerMemberName attribute, argument propertyName will be filled with appropriate value.
Source code for this post can be found here

Implementing INotifyPropertyChanged without lambda expressions and “magic” strings