July 2016 – .NET BLOG

We’ve been using Cake in our project for quite some time and it has been working great. However for time to time lack of debugging support was really annoying for me. Fortunately it seems that these times are gone now. During NDC Oslo 2016 Gary Ewan Park showed that it is possible to attach debugger to the build process. Here are the steps to achieve that. Let’s assume that we have following simple cake script.

var target = Argument("target", "Default");
Task("Default")
    .Does(() =>
{
    MSBuild(Directory("../") + File("DebuggingCakeScript.sln"));
});

RunTarget(target);

var target = Argument("target", "Default");

Task("Default")

.Does(() =>

{

MSBuild(Directory("../") + File("DebuggingCakeScript.sln"));

});

RunTarget(target);

In order to make the debugging possible it is necessary to add

#break

#break

preprocessor directive to the task we want the debugger to stop.

var target = Argument("target", "Default");
Task("Default")
    .Does(() =>
{
    #break
    MSBuild(Directory("../") + File("DebuggingCakeScript.sln"));
});

RunTarget(target);

var target = Argument("target", "Default");

Task("Default")

.Does(() =>

{

#break

MSBuild(Directory("../") + File("DebuggingCakeScript.sln"));

});

RunTarget(target);

This operation doesn’t affect the default build process, so if you run in console

.\build.ps1 -target Default

1	.\build.ps1 -target Default

the build will run as usual. In order to be able to attach the debugger we have to call Cake with

 --debug

--debug

flag. You can’t do it directly via

\build.ps1

1	\build.ps1

script so assuming that you didn’t change directory structure created by bootstrapper, go to Tools/Cake folder and run from PowerShell

.\Cake.exe ..\..\build.cake -target=Default --debug

1	.\Cake.exe ..\..\build.cake -target=Default --debug

where

..\..\build.cake

1	..\..\build.cake

is path to your cake script and

Default

Default

is task you want to start. Once you run the command, cake will wait for attaching the debugger

Now launch Visual Studio, go to Debug-> Attach to Process…, find process id listed in console

and click Attach. After couple of seconds Visual Studio will load your cake script and you will be able to debug it like normal application.

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

public class HomeController : Controller
{
    private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
    
    public async Task<ActionResult> Index()
    {
        await PreprocessRequest(nameof(Index));
        return View();
    }
    
    private static async Task PreprocessRequest(string actionName)
    {
        Logger.Info($"Log from {actionName} action, from thread={Thread.CurrentThread.ManagedThreadId}");
        
        await Task.Run(() => Logger.Info($"Log from {actionName}, from thread {Thread.CurrentThread.ManagedThreadId} assigned by scheduler"))
                  .ConfigureAwait(continueOnCapturedContext: false);
        Logger.Info($"Log from {actionName} action, from async continuation, from thread {Thread.CurrentThread.ManagedThreadId}");
               
        var thread =
            new Thread(() => Logger.Info($"Log from {actionName} action, from explicitly created thread {Thread.CurrentThread.ManagedThreadId}"));
        thread.Start();
        thread.Join();
    }
}

public class HomeController : Controller

{

private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

public async Task<ActionResult> Index()

{

await PreprocessRequest(nameof(Index));

return View();

}

private static async Task PreprocessRequest(string actionName)

{

Logger.Info($"Log from {actionName} action, from thread={Thread.CurrentThread.ManagedThreadId}");

await Task.Run(() => Logger.Info($"Log from {actionName}, from thread {Thread.CurrentThread.ManagedThreadId} assigned by scheduler"))

.ConfigureAwait(continueOnCapturedContext: false);

Logger.Info($"Log from {actionName} action, from async continuation, from thread {Thread.CurrentThread.ManagedThreadId}");

var thread =

new Thread(() => Logger.Info($"Log from {actionName} action, from explicitly created thread {Thread.CurrentThread.ManagedThreadId}"));

thread.Start();

thread.Join();

}

Default log file usually looks like that

TimeStamp=2016-07-03 11:56:02.2327 ThreadId=5 Level=INFO Message=About to start GET / request
TimeStamp=2016-07-03 11:56:02.3797 ThreadId=5 Level=INFO Message=Log from Index action, from thread=5
TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index, from thread 6 assigned by scheduler
TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index action, from async continuation, from thread 6
TimeStamp=2016-07-03 11:56:02.3917 ThreadId=14 Level=INFO Message=Log from Index action, from explicitly created thread 14
TimeStamp=2016-07-03 11:56:04.8250 ThreadId=8 Level=INFO Message=Request completed with status code: 200

TimeStamp=2016-07-03 11:56:02.2327 ThreadId=5 Level=INFO Message=About to start GET / request

TimeStamp=2016-07-03 11:56:02.3797 ThreadId=5 Level=INFO Message=Log from Index action, from thread=5

TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index, from thread 6 assigned by scheduler

TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index action, from async continuation, from thread 6

TimeStamp=2016-07-03 11:56:02.3917 ThreadId=14 Level=INFO Message=Log from Index action, from explicitly created thread 14

TimeStamp=2016-07-03 11:56:04.8250 ThreadId=8 Level=INFO Message=Request completed with status code: 200

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

public class LoggingHttpModule : IHttpModule
{
    private const string CorrelationIdKey = "correlationid";

    private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

    public void Init(HttpApplication context)
    {
        context.BeginRequest += HandleBeginRequest;
        context.EndRequest += HandleEndRequest;
    }

    public void Dispose()
    {
    }

    private void HandleBeginRequest(object sender, EventArgs e)
    {
        var value = Guid.NewGuid().ToString();
        var httpApplication = (HttpApplication) sender;
        var httpContext = httpApplication.Context;
        MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, value);
        Logger.Info($"About to start {httpContext.Request.HttpMethod} {httpContext.Request.RawUrl} request");
    }

    private void HandleEndRequest(object sender, EventArgs e)
    {
        var httpApplication = (HttpApplication) sender;
        var httpContext = httpApplication.Context;
        Logger.Info($"Request completed with status code: {httpContext.Response.StatusCode} ");
    }
}

public class LoggingHttpModule : IHttpModule

{

private const string CorrelationIdKey = "correlationid";

private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

public void Init(HttpApplication context)

{

context.BeginRequest += HandleBeginRequest;

context.EndRequest += HandleEndRequest;

}

public void Dispose()

{

}

private void HandleBeginRequest(object sender, EventArgs e)

{

var value = Guid.NewGuid().ToString();

var httpApplication = (HttpApplication) sender;

var httpContext = httpApplication.Context;

MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, value);

Logger.Info($"About to start {httpContext.Request.HttpMethod} {httpContext.Request.RawUrl} request");

}

private void HandleEndRequest(object sender, EventArgs e)

{

var httpApplication = (HttpApplication) sender;

var httpContext = httpApplication.Context;

Logger.Info($"Request completed with status code: {httpContext.Response.StatusCode} ");

}

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

<!--rest of the code omitted -->
<system.webServer>
  <modules>
  <!--rest of the code omitted -->
    <add name="LoggingHttpModule" type="AspNetMvcLoggingWithCorrelationId.HttpModules.LoggingHttpModule"/>
  </modules>
</system.webServer>
<!--rest of the code omitted -->
<system.web>
<!--rest of the code omitted -->
  <httpModules>
  <!--rest of the code omitted -->
    <add name="ApplicationInsightsWebTracking" type="Microsoft.ApplicationInsights.Web.ApplicationInsightsHttpModule,Microsoft.AI.Web"/>
  </httpModules>
</system.web>