{"id":1001,"date":"2017-02-18T14:11:18","date_gmt":"2017-02-18T14:11:18","guid":{"rendered":"http:\/\/tpodolak.com\/blog\/?p=1001"},"modified":"2017-02-18T14:11:18","modified_gmt":"2017-02-18T14:11:18","slug":"asp-net-core-tracking-flow-requests-nlog","status":"publish","type":"post","link":"https:\/\/tpodolak.com\/blog\/2017\/02\/18\/asp-net-core-tracking-flow-requests-nlog\/","title":{"rendered":"ASP.NET Core &#8211; tracking flow of requests with NLog"},"content":{"rendered":"<h3>1. Introduction<\/h3>\n<p>A while ago I wrote an <a href=\"\/\/tpodolak.com\/blog\/2016\/07\/05\/nlog-tracking-flow-of-requests-using-mappeddiagnosticslogicalcontext\/\">article<\/a> about using <i>MappedDiagnosticsLogicalContext<\/i> for tracking request flow in your application. As we are moving our project to <i>ASP.NET Core<\/i>, I wanted to keep that functionality in place. Unfortunately, <i>MDLC<\/i> layout renderer is not available in that framework anymore(when targeting <i>.NET Core<\/i>). Luckily, there are two other renderers which can be used as a replacement:<\/p>\n<ul>\n<li>aspnet-traceidentifier<\/li>\n<li>aspnet-item<\/li>\n<\/ul>\n<h3>2. Configuring NLog<\/h3>\n<p>Before I dig into details of layout renderers mentioned above, we have to configure <i>ASP.NET Core<\/i> to use <i>NLog<\/i> as a logger. First of all, we need to grab <i>NLog.Web.AspNetCore<\/i> <i>NuGet<\/i> package. Once the package is installed we have to manually add <i>NLog.config<\/i> to the project (the file won&#8217;t be added automatically by <i>NuGet<\/i> installer). The next step is to configure <i>NLog<\/i> with our config, then configure <i>NLogWeb<\/i> and finally register <i>NLog<\/i> in <i>LoggingFactory<\/i>. All of these steps should be done in <i>Startup<\/i> class. <\/p>\n<pre lang=\"csharp\">\r\npublic class Startup\r\n{\r\n    public Startup(IHostingEnvironment env)\r\n    {\r\n        \/\/ rest of the code omitted for brevity\r\n        env.ConfigureNLog(\"NLog.config\");\r\n        \/\/ rest of the code omitted for brevity\r\n    }\r\n\t\r\n    \/\/ This method gets called by the runtime. Use this method to configure the HTTP request pipeline.\r\n    public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)\r\n    {\r\n        \/\/ rest of the code omitted for brevity\r\n        loggerFactory.AddNLog();\r\n        app.AddNLogWeb();\r\n        \/\/ rest of the code omitted for brevity\r\n    }\r\n}\t\r\n<\/pre>\n<p>The final step required for <i>NLog<\/i> to work is to register <i>HttpContextAccessor<\/i> in <i>IoC<\/i> container of your choice. If you use the build one, you can do it like that<\/p>\n<pre lang=\"csharp\">\r\npublic class Startup\r\n{\r\n    \/\/ rest of the code omitted for brevity\r\n    public void ConfigureServices(IServiceCollection services)\r\n    {\r\n        services.AddSingleton<IHttpContextAccessor, HttpContextAccessor>();\r\n    }\r\n    \/\/ rest of the code omitted for brevity\r\n}\r\n<\/pre>\n<h3>3. Using aspnet-traceidentifier renderer<\/h3>\n<p><i>Aspnet-traceidentifier<\/i> layout renderer allows you to obtain value of <i>TraceIdentifier<\/i> property from current <i>HttpContext<\/i>. <i>TraceIdentifier<\/i> is basically unique id which identifies the request. The renderer can be used as follows<\/p>\n<pre lang=\"xml\">\r\n\t<?xml version=\"1.0\" encoding=\"utf-8\" ?>\r\n\t<nlog xmlns=\"http:\/\/www.nlog-project.org\/schemas\/NLog.xsd\"\r\n\t      xmlns:xsi=\"http:\/\/www.w3.org\/2001\/XMLSchema-instance\"\r\n\t      autoReload=\"true\">\r\n\t\r\n\t  <extensions>\r\n\t    <add assembly=\"NLog.Web.AspNetCore\"\/>\r\n\t  <\/extensions>\r\n\t  \r\n\t  <targets>\r\n\t    <target xsi:type=\"File\" name=\"File\" fileName=\"${basedir}\/logs\/${shortdate}.log\"\r\n\t            layout=\"TimeStamp=${longdate} Level=${uppercase:${level}} TraceId=${aspnet-traceidentifier} Message=${message}\" \/>\r\n\t  <\/targets>\r\n\t   \r\n\t  <rules>\r\n\t    <logger name=\"*\" minlevel=\"Debug\" writeTo=\"File\" \/>\r\n\t  <\/rules>\r\n\r\n<\/nlog>\r\n<\/pre>\n<p>From now on (without any additional configuration) every log entry logged (once <i>HttpContext<\/i> is created), will contain <i>TraceIdentifier<\/i>.<\/p>\n<pre lang=\"bash\">\r\n\tTimeStamp=2017-02-15 23:10:52.1901 Level=INFO TraceId=0HL2LTTU3JVBI Message=Request starting HTTP\/1.1 GET http:\/\/localhost:50334\/api\/values  \r\n\tTimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Request successfully matched the route with name '' and template 'api\/Values'.\r\n\tTimeStamp=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'\r\n\tTimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Executing action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId)\r\n\tTimeStamp=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\r\n\tTimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Get method requested\r\n\tTimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from thread=4\r\n\tTimeStamp=2017-02-15 23:10:52.2271 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get, from thread 3 assigned by scheduler\r\n\tTimeStamp=2017-02-15 23:10:52.2271 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from async continuation, from thread 3\r\n\tTimeStamp=2017-02-15 23:10:52.2422 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from explicitly created thread 15\r\n\tTimeStamp=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.\r\n\tTimeStamp=2017-02-15 23:10:52.3212 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=No information found on request to perform content negotiation.\r\n\tTimeStamp=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.\r\n\tTimeStamp=2017-02-15 23:10:52.3322 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.\r\n\tTimeStamp=2017-02-15 23:10:52.3492 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executed action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) in 140.4884ms\r\n\tTimeStamp=2017-02-15 23:10:52.3492 Level=INFO TraceId=0HL2LTTU3JVBI Message=Request finished in 170.7178ms 200 application\/json; charset=utf-8\r\n\tTimeStamp=2017-02-15 23:10:52.3672 Level=DEBUG TraceId= Message=Connection id \"0HL2LTTU1ONI7\" completed keep alive response.\r\n<\/pre>\n<h3>4. Using aspnet-item renderer<\/h3>\n<p>If for some reasons we don\u2019t like to use <i>TraceIdentifier<\/i> as our CorrelationId, we can leverage <i>aspnet-item<\/i> renderer, which basically allows you to read data from <i>HttpContext.Items<\/i> 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.<\/p>\n<pre lang=\"csharp\">\r\npublic class LoggingMiddleware\r\n{\r\n    private readonly ILogger<LoggingMiddleware> logger;\r\n    private readonly RequestDelegate next;\r\n\t\r\n    public LoggingMiddleware(ILogger<LoggingMiddleware> logger, RequestDelegate next)\r\n    {\r\n        this.logger = logger;\r\n        this.next = next;\r\n    }\r\n\t\r\n    public async Task Invoke(HttpContext context)\r\n    {\r\n        context.Items[\"CorrelationId\"] = Guid.NewGuid().ToString();\r\n        logger.LogInformation($\"About to start {context.Request.Method} {context.Request.GetDisplayUrl()} request\");\r\n\t\r\n        await next(context);\r\n\r\n        logger.LogInformation($\"Request completed with status code: {context.Response.StatusCode} \");\r\n    }\r\n}\r\n<\/pre>\n<p>Of course we have to also use this middleware in our application so we have to add following line<\/p>\n<pre lang=\"csharp\">\r\napp.UseMiddleware<LoggingMiddleware>();\r\n<\/pre>\n<p>in configure method of our <i>Startup<\/i> class. Having all the pieces in place, now we can append <i>CorrelationId <\/i> read from <i>HttpContext.Items<\/i> to our log entries with following configuration<\/p>\n<pre lang=\"xml\">\r\n\t<?xml version=\"1.0\" encoding=\"utf-8\" ?>\r\n\t<nlog xmlns=\"http:\/\/www.nlog-project.org\/schemas\/NLog.xsd\"\r\n\t      xmlns:xsi=\"http:\/\/www.w3.org\/2001\/XMLSchema-instance\"\r\n\t      autoReload=\"true\">\r\n\t\r\n\t  <extensions>\r\n\t    <add assembly=\"NLog.Web.AspNetCore\"\/>\r\n\t  <\/extensions>\r\n\t  \r\n\t  <targets>\r\n\t    <target xsi:type=\"File\" name=\"File\" fileName=\"${basedir}\/logs\/${shortdate}.log\"\r\n\t            layout=\"TimeStamp=${longdate} Level=${uppercase:${level}} CorrelationId=${aspnet-item:variable=CorrelationId} Message=${message}\" \/>\r\n\t  <\/targets>\r\n\t   \r\n\t  <rules>\r\n\t    <logger name=\"*\" minlevel=\"Debug\" writeTo=\"File\" \/>\r\n\t  <\/rules>\r\n\t<\/nlog>\r\n<\/pre>\n<p>From now on, <i>CorrelationId<\/i> will be automatically added to our log entries<\/p>\n<pre lang=\"bash\">\r\nTimeStamp=2017-02-15 23:35:56.8333 Level=INFO CorrelationId= Message=Request starting HTTP\/1.1 GET http:\/\/localhost:50334\/api\/values  \r\nTimeStamp=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\r\nTimeStamp=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'.\r\nTimeStamp=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'\r\nTimeStamp=2017-02-15 23:35:56.8513 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId)\r\nTimeStamp=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\r\nTimeStamp=2017-02-15 23:35:56.8673 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Get method requested\r\nTimeStamp=2017-02-15 23:35:56.8673 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from thread=3\r\nTimeStamp=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\r\nTimeStamp=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\r\nTimeStamp=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\r\nTimeStamp=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.\r\nTimeStamp=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.\r\nTimeStamp=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.\r\nTimeStamp=2017-02-15 23:35:56.9274 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.\r\nTimeStamp=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\r\nTimeStamp=2017-02-15 23:35:56.9444 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request completed with status code: 200 \r\nTimeStamp=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\r\nTimeStamp=2017-02-15 23:35:56.9764 Level=DEBUG CorrelationId= Message=Connection id \"0HL2LUBSKVM2T\" completed keep alive response.\r\n<\/pre>\n<h3>6. It works in multithreading scenarios<\/h3>\n<p>If you take a closer look at logs presented above, you will see that both of the renderers can log proper <i>CorrelationId<\/i>\/<i>TraceId<\/i> regardless of the thread from which the logger was called. This is possible thanks to implementation of <i>HttpContextAccessor<\/i> which uses <i>AsyncLocal<\/i> under the hood, which allows you to persist data across threads.<\/p>\n<pre class=\"csharp\">\r\n\/\/ decompiled code\r\nnamespace Microsoft.AspNetCore.Http\r\n{\r\n    public class HttpContextAccessor : IHttpContextAccessor\r\n    {\r\n        private AsyncLocal<HttpContext> _httpContextCurrent = new AsyncLocal<HttpContext>();\r\n\t\r\n        public HttpContext HttpContext\r\n        {\r\n            get\r\n            {\r\n                return this._httpContextCurrent.Value;\r\n            }\r\n            set\r\n            {\r\n                this._httpContextCurrent.Value = value;\r\n            }\r\n        }\r\n    }\r\n}    \r\n<\/pre>\n<p>Source code for this post can be found <a href=\"https:\/\/github.com\/tpodolak\/Blog\/tree\/master\/AspNetCoreLoggingWithCorrelationId\">here<\/a><\/p>\n","protected":false},"excerpt":{"rendered":"<p>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 [&hellip;]<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[317,300],"tags":[318,297],"class_list":["post-1001","post","type-post","status-publish","format-standard","hentry","category-asp-net-core","category-nlog","tag-asp-net-core","tag-nlog"],"_links":{"self":[{"href":"https:\/\/tpodolak.com\/blog\/wp-json\/wp\/v2\/posts\/1001","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/tpodolak.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/tpodolak.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/tpodolak.com\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/tpodolak.com\/blog\/wp-json\/wp\/v2\/comments?post=1001"}],"version-history":[{"count":9,"href":"https:\/\/tpodolak.com\/blog\/wp-json\/wp\/v2\/posts\/1001\/revisions"}],"predecessor-version":[{"id":1010,"href":"https:\/\/tpodolak.com\/blog\/wp-json\/wp\/v2\/posts\/1001\/revisions\/1010"}],"wp:attachment":[{"href":"https:\/\/tpodolak.com\/blog\/wp-json\/wp\/v2\/media?parent=1001"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/tpodolak.com\/blog\/wp-json\/wp\/v2\/categories?post=1001"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/tpodolak.com\/blog\/wp-json\/wp\/v2\/tags?post=1001"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}