ASP.NET Core – default API version with url path versioning

2017-05-032017-05-08 TPodolakASP.NET Core, versioning

1. Introduction.

When you start versioning your API sometimes you want to have access to your endpoints without specifying version explicitly. Thanks to Microsoft.AspNetCore.Mvc.Versioning library this can be easily achieved with proper setup of configuration action. However, it turns out that in order to enable default API version for url path versioning, there are a couple additional steps to do.

2. Default API version without url path versioning

Let’s start with the initial setup of API versioning which will work for every type of versioning apart from url path versioning. All you have to do is to assign an ApiVersionSelector and set the AssumeDefaultVersionWhenUnspecified property to true.

public void ConfigureServices(IServiceCollection services)
{
    // Add framework services.
    services.AddApiVersioning(options =>
    {
        options.ApiVersionReader = new QueryStringApiVersionReader();
        options.AssumeDefaultVersionWhenUnspecified = true;
        options.ApiVersionSelector = new CurrentImplementationApiVersionSelector(options);
    });
}

public void ConfigureServices(IServiceCollection services)

{

// Add framework services.

services.AddApiVersioning(options =>

{

options.ApiVersionReader = new QueryStringApiVersionReader();

options.AssumeDefaultVersionWhenUnspecified = true;

options.ApiVersionSelector = new CurrentImplementationApiVersionSelector(options);

});

}

Now when the user will try to access the endpoint without specifying version explicitly the ApiVersionSelector will select proper version – in this case highest available version.

3. Default Api version with URL path versioning

Running the same configuration against controllers which are versioned via url path (not query string)

namespace AspNetCoreDefaultApiVersionAndRoutePrefix.Controllers.V1
{
    [Route("v{version:apiVersion}/[controller]")]
    [ApiVersion("1")]
    public class ValuesController : Controller
    {
        // GET api/values
        [HttpGet]
        public IEnumerable<string> Get()
        {
            return new string[] {"V1"};
        }
    }
}

namespace AspNetCoreDefaultApiVersionAndRoutePrefix.Controllers.V2
{
    [Route("v{version:apiVersion}/[controller]")]
    [ApiVersion("2")]
    public class ValuesController : Controller
    {
        // GET api/values
        [HttpGet]
        public IEnumerable<string> Get()
        {
            return new string[] {"V2"};
        }
    }
}

namespace AspNetCoreDefaultApiVersionAndRoutePrefix.Controllers.V1

{

[Route("v{version:apiVersion}/[controller]")]

[ApiVersion("1")]

public class ValuesController : Controller

{

// GET api/values

[HttpGet]

public IEnumerable<string> Get()

{

return new string[] {"V1"};

}

namespace AspNetCoreDefaultApiVersionAndRoutePrefix.Controllers.V2

{

[Route("v{version:apiVersion}/[controller]")]

[ApiVersion("2")]

public class ValuesController : Controller

{

// GET api/values

[HttpGet]

public IEnumerable<string> Get()

{

return new string[] {"V2"};

}

will result with 404 status code, as routing is not able to match the url.

Fortunately, unlike the ASP.NET Web API, ASP.NET Core allows us to have multiple route attributes applied to given controller, so in order to fix the issue we just have to add

[Route("[controller]")]

1	[Route("[controller]")]

attribute to versioned controllers. From now on we can access our API without specifying version as well as with version specified.

4. Adding default route with convention

If you don’t want to specify default route manually for every controller, you can do it via application model convention. The interesting thing about it is the fact that apart from changing existing values of application model we can also add new items to it. This means that we can add additional SelectorModel with our default route to Selectors’ collection

public class DefaultRoutePrefixConvention : IApplicationModelConvention
{
    public void Apply(ApplicationModel application)
    {
        foreach (var applicationController in application.Controllers)
        {
            applicationController.Selectors.Add(new SelectorModel
            {
                AttributeRouteModel = new AttributeRouteModel
                {
                    Template = "[controller]"
                }
            });
        }
    }
}

public class DefaultRoutePrefixConvention : IApplicationModelConvention

{

public void Apply(ApplicationModel application)

{

foreach (var applicationController in application.Controllers)

{

applicationController.Selectors.Add(new SelectorModel

{

AttributeRouteModel = new AttributeRouteModel

{

Template = "[controller]"

}

});

}

Now we can get rid of [Route(“[controller]”)] attribute from our versioned controllers and just rely on convention which can be added as follows

public void ConfigureServices(IServiceCollection services)
{
    // rest of the code omitted for brevity 
    services.AddMvc(mvc =>
    {
        mvc.Conventions.Add(new DefaultRoutePrefixConvention());
    });
}

public void ConfigureServices(IServiceCollection services)

{

// rest of the code omitted for brevity

services.AddMvc(mvc =>

{

mvc.Conventions.Add(new DefaultRoutePrefixConvention());

});

}

Source code for this post can be found here

Asp.NET Core – populating IOptions<T> from external data source

2017-02-26 TPodolakASP.NET Core1 Comment

1. Introduction

In ASP.NET Core web.config is no longer a proper place for storing application settings. New framework introduces the concept of a json based configuration and the default file which stores the settings now is appsettings.json. Here is a quick tutorial how to use new features.

2. Reading configuration

Let’s assume that our appsettings.json file looks as follows.

{
    "Logging": {
        "IncludeScopes": false,
        "LogLevel": {
            "Default": "Debug",
            "System": "Information",
            "Microsoft": "Information"
        }
    },
    "AvailabilitySearchOptions": {
        "FlexDaysIn": 2,
        "FlexDaysOut": 3
    }
}

{

"Logging": {

"IncludeScopes": false,

"LogLevel": {

"Default": "Debug",

"System": "Information",

"Microsoft": "Information"

}

"AvailabilitySearchOptions": {

"FlexDaysIn": 2,

"FlexDaysOut": 3

}

Thanks to ConfigurationBuilder we can parse this config and later on materialize sections or entire file into strongly typed configuration classes. Let’s say we want to parse AvailabilitySearchOptions node to following class

public class AvailabilitySearchOptions
{
    public int FlexDaysIn { get; set; }

    public int FlexDaysOut { get; set; }

    public TimeSpan MinimumConnectionTime { get; set; }

    public TimeSpan MinimumDepartureTime { get; set; }
}

public class AvailabilitySearchOptions

{

public int FlexDaysIn { get; set; }

public int FlexDaysOut { get; set; }

public TimeSpan MinimumConnectionTime { get; set; }

public TimeSpan MinimumDepartureTime { get; set; }

}

We can achieve that with following steps. First of all, we need to read entire configuration

public IConfigurationRoot Configuration { get; }

public Startup(IHostingEnvironment env)
{
    var builder = new ConfigurationBuilder()
                        .SetBasePath(env.ContentRootPath)
                        .AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)
                        .AddJsonFile($"appsettings.{env.EnvironmentName}.json", optional: true)
                        .AddEnvironmentVariables();
    Configuration = builder.Build();
}

public IConfigurationRoot Configuration { get; }

public Startup(IHostingEnvironment env)

{

var builder = new ConfigurationBuilder()

.SetBasePath(env.ContentRootPath)

.AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)

.AddJsonFile($"appsettings.{env.EnvironmentName}.json", optional: true)

.AddEnvironmentVariables();

Configuration = builder.Build();

}

And in the next step we have to register IOptions<AvailabilitySearchOptions> in the container using services.Configure<TOptions>(IConfiguration section) method

// This method gets called by the runtime. Use this method to add services to the container.
public void ConfigureServices(IServiceCollection services)
{
    // Add framework services.
    services.AddMvc();
    services.Configure<AvailabilitySearchOptions>(Configuration.GetSection("AvailabilitySearchOptions"));  
}

// This method gets called by the runtime. Use this method to add services to the container.

public void ConfigureServices(IServiceCollection services)

{

// Add framework services.

services.AddMvc();

services.Configure<AvailabilitySearchOptions>(Configuration.GetSection("AvailabilitySearchOptions"));

}

Note Configuration.GetSection(“AvailabilitySearchOptions”) passed as argument to services.Configure method.
From now on we can access AvailabilitySearchOptions settings via IOptions<AvailabilitySearchOptions> interface, which you can easily inject into your classes.

[Route("api/[controller]")]
public class OptionsController : Controller
{
    private readonly IOptions<AvailabilitySearchOptions> availabilitySearchOptions;

    public OptionsController(IOptions<AvailabilitySearchOptions> availabilitySearchOptions)
    {
        this.availabilitySearchOptions = availabilitySearchOptions;
    }

    public AvailabilitySearchOptions Get()
    {
        return availabilitySearchOptions.Value;
    }
}

[Route("api/[controller]")]

public class OptionsController : Controller

{

private readonly IOptions<AvailabilitySearchOptions> availabilitySearchOptions;

public OptionsController(IOptions<AvailabilitySearchOptions> availabilitySearchOptions)

{

this.availabilitySearchOptions = availabilitySearchOptions;

}

public AvailabilitySearchOptions Get()

{

return availabilitySearchOptions.Value;

}

3. Populating IOptions<T> from external data source

From time to time, reading configuration just from JSON file might not be enough and for instance you would like to add additional configuration read from some external data source. Fortunately you don’t have to resign from the IOptions<T> class as it is possible to read additional data for literally any other source thanks to IConfigureOptions<T> class. All we have to do is to create a setup class which implements IConfigureOptions<T> interface

public class AvailabilitySearchOptionsSetupService : IConfigureOptions<AvailabilitySearchOptions>
{
    private readonly ILogger<AvailabilitySearchOptionsSetupService> logger;
    private readonly IReservationSettingsService reservationSettingsService;
	
    public AvailabilitySearchOptionsSetupService(ILogger<AvailabilitySearchOptionsSetupService> logger ,IReservationSettingsService reservationSettingsService)
    {
        this.logger = logger;
        this.reservationSettingsService = reservationSettingsService;
    }
	
    public void Configure(AvailabilitySearchOptions options)
    {
        this.logger.LogInformation($"Calling first {typeof(IConfigureOptions<AvailabilitySearchOptions>)} service");
        options.MinimumConnectionTime = reservationSettingsService.GetMinimumConnectionTime();
    }
}

public class AvailabilitySearchOptionsSetupService : IConfigureOptions<AvailabilitySearchOptions>

{

private readonly ILogger<AvailabilitySearchOptionsSetupService> logger;

private readonly IReservationSettingsService reservationSettingsService;

public AvailabilitySearchOptionsSetupService(ILogger<AvailabilitySearchOptionsSetupService> logger ,IReservationSettingsService reservationSettingsService)

{

this.logger = logger;

this.reservationSettingsService = reservationSettingsService;

}

public void Configure(AvailabilitySearchOptions options)

{

this.logger.LogInformation($"Calling first {typeof(IConfigureOptions<AvailabilitySearchOptions>)} service");

options.MinimumConnectionTime = reservationSettingsService.GetMinimumConnectionTime();

}

And then registering this class in our container

// This method gets called by the runtime. Use this method to add services to the container.
public void ConfigureServices(IServiceCollection services)
{
    // Add framework services.
    services.AddMvc();
    services.Configure<AvailabilitySearchOptions>(Configuration.GetSection("AvailabilitySearchOptions"));
    services.AddSingleton<IConfigureOptions<AvailabilitySearchOptions>, AvailabilitySearchOptionsSetupService>();
}

// This method gets called by the runtime. Use this method to add services to the container.

public void ConfigureServices(IServiceCollection services)

{

// Add framework services.

services.AddMvc();

services.Configure<AvailabilitySearchOptions>(Configuration.GetSection("AvailabilitySearchOptions"));

services.AddSingleton<IConfigureOptions<AvailabilitySearchOptions>, AvailabilitySearchOptionsSetupService>();

}

From now on, when value of IOptions<AvailabilitySearchOptions> is accessed for very first time, Configure method from AvailabilitySearchOptionsSetupService will be called and you will be able to set additional values for your settings. Note that values from appsettings.json will already be there.
In addition, it is possible to have multiple implementations of IConfigureOptions<T> so if you want your setup to be split into multiple classes you are good to go.

Source code for this post can be found here

ASP.NET Core – tracking flow of requests with NLog

2017-02-18 TPodolakASP.NET Core, NLog3 Comments

1. Introduction

A while ago I wrote an article about using MappedDiagnosticsLogicalContext for tracking request flow in your application. As we are moving our project to ASP.NET Core, I wanted to keep that functionality in place. Unfortunately, MDLC layout renderer is not available in that framework anymore(when targeting .NET Core). Luckily, there are two other renderers which can be used as a replacement:

aspnet-traceidentifier
aspnet-item

2. Configuring NLog

Before I dig into details of layout renderers mentioned above, we have to configure ASP.NET Core to use NLog as a logger. First of all, we need to grab NLog.Web.AspNetCore NuGet package. Once the package is installed we have to manually add NLog.config to the project (the file won’t be added automatically by NuGet installer). The next step is to configure NLog with our config, then configure NLogWeb and finally register NLog in LoggingFactory. All of these steps should be done in Startup class.

public class Startup
{
    public Startup(IHostingEnvironment env)
    {
        // rest of the code omitted for brevity
        env.ConfigureNLog("NLog.config");
        // rest of the code omitted for brevity
    }
	
    // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
    public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
    {
        // rest of the code omitted for brevity
        loggerFactory.AddNLog();
        app.AddNLogWeb();
        // rest of the code omitted for brevity
    }
}

public class Startup

{

public Startup(IHostingEnvironment env)

{

// rest of the code omitted for brevity

env.ConfigureNLog("NLog.config");

// rest of the code omitted for brevity

}

// This method gets called by the runtime. Use this method to configure the HTTP request pipeline.

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)

{

// rest of the code omitted for brevity

loggerFactory.AddNLog();

app.AddNLogWeb();

// rest of the code omitted for brevity

}

The final step required for NLog to work is to register HttpContextAccessor in IoC container of your choice. If you use the build one, you can do it like that

public class Startup
{
    // rest of the code omitted for brevity
    public void ConfigureServices(IServiceCollection services)
    {
        services.AddSingleton<IHttpContextAccessor, HttpContextAccessor>();
    }
    // rest of the code omitted for brevity
}

public class Startup

{

// rest of the code omitted for brevity

public void ConfigureServices(IServiceCollection services)

{

services.AddSingleton<IHttpContextAccessor, HttpContextAccessor>();

}

// rest of the code omitted for brevity

}

3. Using aspnet-traceidentifier renderer

Aspnet-traceidentifier layout renderer allows you to obtain value of TraceIdentifier property from current HttpContext. TraceIdentifier is basically unique id which identifies the request. The renderer can be used as follows

	<?xml version="1.0" encoding="utf-8" ?>
	<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
	      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	      autoReload="true">
	
	  <extensions>
	    <add assembly="NLog.Web.AspNetCore"/>
	  </extensions>
	  
	  <targets>
	    <target xsi:type="File" name="File" fileName="${basedir}/logs/${shortdate}.log"
	            layout="TimeStamp=${longdate} Level=${uppercase:${level}} TraceId=${aspnet-traceidentifier} Message=${message}" />
	  </targets>
	   
	  <rules>
	    <logger name="*" minlevel="Debug" writeTo="File" />
	  </rules>

</nlog>

<?xml version="1.0" encoding="utf-8" ?>

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"

xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

autoReload="true">

</extensions>

<target xsi:type="File" name="File" fileName="${basedir}/logs/${shortdate}.log"

layout="TimeStamp=${longdate} Level=${uppercase:${level}} TraceId=${aspnet-traceidentifier} Message=${message}" />

</targets>

<rules>

</rules>

</nlog>

From now on (without any additional configuration) every log entry logged (once HttpContext is created), will contain TraceIdentifier.

	TimeStamp=2017-02-15 23:10:52.1901 Level=INFO TraceId=0HL2LTTU3JVBI Message=Request starting HTTP/1.1 GET http://localhost:50334/api/values  
	TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Request successfully matched the route with name '' and template 'api/Values'.
	TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Action 'AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Post (AspNetCoreLoggingWithCorrelationId)' with id 'a133346a-a8f9-4182-ac10-efa1afb18c4d' did not match the constraint 'Microsoft.AspNetCore.Mvc.Internal.HttpMethodActionConstraint'
	TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Executing action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId)
	TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executing action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) with arguments () - ModelState is Valid
	TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Get method requested
	TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from thread=4
	TimeStamp=2017-02-15 23:10:52.2271 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get, from thread 3 assigned by scheduler
	TimeStamp=2017-02-15 23:10:52.2271 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from async continuation, from thread 3
	TimeStamp=2017-02-15 23:10:52.2422 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from explicitly created thread 15
	TimeStamp=2017-02-15 23:10:52.3212 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Executed action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId), returned result Microsoft.AspNetCore.Mvc.ObjectResult.
	TimeStamp=2017-02-15 23:10:52.3212 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=No information found on request to perform content negotiation.
	TimeStamp=2017-02-15 23:10:52.3322 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.JsonOutputFormatter' and content type 'application/json' to write the response.
	TimeStamp=2017-02-15 23:10:52.3322 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
	TimeStamp=2017-02-15 23:10:52.3492 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executed action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) in 140.4884ms
	TimeStamp=2017-02-15 23:10:52.3492 Level=INFO TraceId=0HL2LTTU3JVBI Message=Request finished in 170.7178ms 200 application/json; charset=utf-8
	TimeStamp=2017-02-15 23:10:52.3672 Level=DEBUG TraceId= Message=Connection id "0HL2LTTU1ONI7" completed keep alive response.

TimeStamp=2017-02-15 23:10:52.1901 Level=INFO TraceId=0HL2LTTU3JVBI Message=Request starting HTTP/1.1 GET http://localhost:50334/api/values

TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Request successfully matched the route with name '' and template 'api/Values'.

TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Action 'AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Post (AspNetCoreLoggingWithCorrelationId)' with id 'a133346a-a8f9-4182-ac10-efa1afb18c4d' did not match the constraint 'Microsoft.AspNetCore.Mvc.Internal.HttpMethodActionConstraint'

TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Executing action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId)

TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executing action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) with arguments () - ModelState is Valid

TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Get method requested

TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from thread=4

TimeStamp=2017-02-15 23:10:52.2271 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get, from thread 3 assigned by scheduler

TimeStamp=2017-02-15 23:10:52.2271 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from async continuation, from thread 3

TimeStamp=2017-02-15 23:10:52.2422 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from explicitly created thread 15

TimeStamp=2017-02-15 23:10:52.3212 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Executed action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId), returned result Microsoft.AspNetCore.Mvc.ObjectResult.

TimeStamp=2017-02-15 23:10:52.3212 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=No information found on request to perform content negotiation.

TimeStamp=2017-02-15 23:10:52.3322 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.JsonOutputFormatter' and content type 'application/json' to write the response.

TimeStamp=2017-02-15 23:10:52.3322 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.

TimeStamp=2017-02-15 23:10:52.3492 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executed action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) in 140.4884ms

TimeStamp=2017-02-15 23:10:52.3492 Level=INFO TraceId=0HL2LTTU3JVBI Message=Request finished in 170.7178ms 200 application/json; charset=utf-8

TimeStamp=2017-02-15 23:10:52.3672 Level=DEBUG TraceId= Message=Connection id "0HL2LTTU1ONI7" completed keep alive response.

4. Using aspnet-item renderer

If for some reasons we don’t like to use TraceIdentifier as our CorrelationId, we can leverage aspnet-item renderer, which basically allows you to read data from HttpContext.Items collection. However in that case, we are responsible for providing and storing unique identifier of request in HttpContext.Items. Fortunately it is pretty straightforward to do with custom middleware.

public class LoggingMiddleware
{
    private readonly ILogger<LoggingMiddleware> logger;
    private readonly RequestDelegate next;
	
    public LoggingMiddleware(ILogger<LoggingMiddleware> logger, RequestDelegate next)
    {
        this.logger = logger;
        this.next = next;
    }
	
    public async Task Invoke(HttpContext context)
    {
        context.Items["CorrelationId"] = Guid.NewGuid().ToString();
        logger.LogInformation($"About to start {context.Request.Method} {context.Request.GetDisplayUrl()} request");
	
        await next(context);

        logger.LogInformation($"Request completed with status code: {context.Response.StatusCode} ");
    }
}

public class LoggingMiddleware

{

private readonly ILogger<LoggingMiddleware> logger;

private readonly RequestDelegate next;

public LoggingMiddleware(ILogger<LoggingMiddleware> logger, RequestDelegate next)

{

this.logger = logger;

this.next = next;

}

public async Task Invoke(HttpContext context)

{

context.Items["CorrelationId"] = Guid.NewGuid().ToString();

logger.LogInformation($"About to start {context.Request.Method} {context.Request.GetDisplayUrl()} request");

await next(context);

logger.LogInformation($"Request completed with status code: {context.Response.StatusCode} ");

}

Of course we have to also use this middleware in our application so we have to add following line

app.UseMiddleware<LoggingMiddleware>();

1	app.UseMiddleware<LoggingMiddleware>();

in configure method of our Startup class. Having all the pieces in place, now we can append CorrelationId read from HttpContext.Items to our log entries with following configuration

	<?xml version="1.0" encoding="utf-8" ?>
	<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
	      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	      autoReload="true">
	
	  <extensions>
	    <add assembly="NLog.Web.AspNetCore"/>
	  </extensions>
	  
	  <targets>
	    <target xsi:type="File" name="File" fileName="${basedir}/logs/${shortdate}.log"
	            layout="TimeStamp=${longdate} Level=${uppercase:${level}} CorrelationId=${aspnet-item:variable=CorrelationId} Message=${message}" />
	  </targets>
	   
	  <rules>
	    <logger name="*" minlevel="Debug" writeTo="File" />
	  </rules>
	</nlog>

<?xml version="1.0" encoding="utf-8" ?>

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"

xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

autoReload="true">

</extensions>

<target xsi:type="File" name="File" fileName="${basedir}/logs/${shortdate}.log"

layout="TimeStamp=${longdate} Level=${uppercase:${level}} CorrelationId=${aspnet-item:variable=CorrelationId} Message=${message}" />

</targets>

<rules>

</rules>

</nlog>

From now on, CorrelationId will be automatically added to our log entries

TimeStamp=2017-02-15 23:35:56.8333 Level=INFO CorrelationId= Message=Request starting HTTP/1.1 GET http://localhost:50334/api/values  
TimeStamp=2017-02-15 23:35:56.8333 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=About to start GET http://localhost:50334/api/values request
TimeStamp=2017-02-15 23:35:56.8333 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request successfully matched the route with name '' and template 'api/Values'.
TimeStamp=2017-02-15 23:35:56.8513 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Action 'AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Post (AspNetCoreLoggingWithCorrelationId)' with id '5d60d23c-ddef-4d20-98eb-a0c03885bea5' did not match the constraint 'Microsoft.AspNetCore.Mvc.Internal.HttpMethodActionConstraint'
TimeStamp=2017-02-15 23:35:56.8513 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId)
TimeStamp=2017-02-15 23:35:56.8513 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) with arguments () - ModelState is Valid
TimeStamp=2017-02-15 23:35:56.8673 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Get method requested
TimeStamp=2017-02-15 23:35:56.8673 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from thread=3
TimeStamp=2017-02-15 23:35:56.8923 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get, from thread 4 assigned by scheduler
TimeStamp=2017-02-15 23:35:56.8993 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from async continuation, from thread 4
TimeStamp=2017-02-15 23:35:56.8993 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from explicitly created thread 16
TimeStamp=2017-02-15 23:35:56.9163 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executed action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId), returned result Microsoft.AspNetCore.Mvc.ObjectResult.
TimeStamp=2017-02-15 23:35:56.9163 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=No information found on request to perform content negotiation.
TimeStamp=2017-02-15 23:35:56.9274 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.JsonOutputFormatter' and content type 'application/json' to write the response.
TimeStamp=2017-02-15 23:35:56.9274 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
TimeStamp=2017-02-15 23:35:56.9444 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executed action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) in 83.2831ms
TimeStamp=2017-02-15 23:35:56.9444 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request completed with status code: 200 
TimeStamp=2017-02-15 23:35:56.9674 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request finished in 134.3253ms 200 application/json; charset=utf-8
TimeStamp=2017-02-15 23:35:56.9764 Level=DEBUG CorrelationId= Message=Connection id "0HL2LUBSKVM2T" completed keep alive response.

TimeStamp=2017-02-15 23:35:56.8333 Level=INFO CorrelationId= Message=Request starting HTTP/1.1 GET http://localhost:50334/api/values

TimeStamp=2017-02-15 23:35:56.8333 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=About to start GET http://localhost:50334/api/values request

TimeStamp=2017-02-15 23:35:56.8333 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request successfully matched the route with name '' and template 'api/Values'.

TimeStamp=2017-02-15 23:35:56.8513 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Action 'AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Post (AspNetCoreLoggingWithCorrelationId)' with id '5d60d23c-ddef-4d20-98eb-a0c03885bea5' did not match the constraint 'Microsoft.AspNetCore.Mvc.Internal.HttpMethodActionConstraint'

TimeStamp=2017-02-15 23:35:56.8513 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId)

TimeStamp=2017-02-15 23:35:56.8513 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) with arguments () - ModelState is Valid

TimeStamp=2017-02-15 23:35:56.8673 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Get method requested

TimeStamp=2017-02-15 23:35:56.8673 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from thread=3

TimeStamp=2017-02-15 23:35:56.8923 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get, from thread 4 assigned by scheduler

TimeStamp=2017-02-15 23:35:56.8993 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from async continuation, from thread 4

TimeStamp=2017-02-15 23:35:56.8993 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from explicitly created thread 16

TimeStamp=2017-02-15 23:35:56.9163 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executed action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId), returned result Microsoft.AspNetCore.Mvc.ObjectResult.

TimeStamp=2017-02-15 23:35:56.9163 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=No information found on request to perform content negotiation.

TimeStamp=2017-02-15 23:35:56.9274 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.JsonOutputFormatter' and content type 'application/json' to write the response.

TimeStamp=2017-02-15 23:35:56.9274 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.

TimeStamp=2017-02-15 23:35:56.9444 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executed action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) in 83.2831ms

TimeStamp=2017-02-15 23:35:56.9444 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request completed with status code: 200

TimeStamp=2017-02-15 23:35:56.9674 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request finished in 134.3253ms 200 application/json; charset=utf-8

TimeStamp=2017-02-15 23:35:56.9764 Level=DEBUG CorrelationId= Message=Connection id "0HL2LUBSKVM2T" completed keep alive response.

6. It works in multithreading scenarios

If you take a closer look at logs presented above, you will see that both of the renderers can log proper CorrelationId/TraceId regardless of the thread from which the logger was called. This is possible thanks to implementation of HttpContextAccessor which uses AsyncLocal under the hood, which allows you to persist data across threads.

// decompiled code
namespace Microsoft.AspNetCore.Http
{
    public class HttpContextAccessor : IHttpContextAccessor
    {
        private AsyncLocal<HttpContext> _httpContextCurrent = new AsyncLocal<HttpContext>();
	
        public HttpContext HttpContext
        {
            get
            {
                return this._httpContextCurrent.Value;
            }
            set
            {
                this._httpContextCurrent.Value = value;
            }
        }
    }
}

// decompiled code

namespace Microsoft.AspNetCore.Http

{

public class HttpContextAccessor : IHttpContextAccessor

{

private AsyncLocal<HttpContext> _httpContextCurrent = new AsyncLocal<HttpContext>();

public HttpContext HttpContext

{

get

{

return this._httpContextCurrent.Value;

}

set

{

this._httpContextCurrent.Value = value;

}

Source code for this post can be found here

.NET BLOG

.NET, C# blog

ASP.NET Core

ASP.NET Core – default API version with url path versioning

1. Introduction.

2. Default API version without url path versioning

3. Default Api version with URL path versioning

4. Adding default route with convention

Asp.NET Core – populating IOptions<T> from external data source

1. Introduction

2. Reading configuration

3. Populating IOptions<T> from external data source

ASP.NET Core – tracking flow of requests with NLog

1. Introduction

2. Configuring NLog

3. Using aspnet-traceidentifier renderer

4. Using aspnet-item renderer

6. It works in multithreading scenarios