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<\/p>\n
\r\npublic class HomeController : Controller\r\n{\r\n private static readonly Logger Logger = LogManager.GetCurrentClassLogger();\r\n \r\n public async Task Index()\r\n {\r\n await PreprocessRequest(nameof(Index));\r\n return View();\r\n }\r\n \r\n private static async Task PreprocessRequest(string actionName)\r\n {\r\n Logger.Info($\"Log from {actionName} action, from thread={Thread.CurrentThread.ManagedThreadId}\");\r\n \r\n await Task.Run(() => Logger.Info($\"Log from {actionName}, from thread {Thread.CurrentThread.ManagedThreadId} assigned by scheduler\"))\r\n .ConfigureAwait(continueOnCapturedContext: false);\r\n Logger.Info($\"Log from {actionName} action, from async continuation, from thread {Thread.CurrentThread.ManagedThreadId}\");\r\n \r\n var thread =\r\n new Thread(() => Logger.Info($\"Log from {actionName} action, from explicitly created thread {Thread.CurrentThread.ManagedThreadId}\"));\r\n thread.Start();\r\n thread.Join();\r\n }\r\n}\r\n<\/pre>\nDefault log file usually looks like that<\/p>\n
\r\nTimeStamp=2016-07-03 11:56:02.2327 ThreadId=5 Level=INFO Message=About to start GET \/ request\r\nTimeStamp=2016-07-03 11:56:02.3797 ThreadId=5 Level=INFO Message=Log from Index action, from thread=5\r\nTimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index, from thread 6 assigned by scheduler\r\nTimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index action, from async continuation, from thread 6\r\nTimeStamp=2016-07-03 11:56:02.3917 ThreadId=14 Level=INFO Message=Log from Index action, from explicitly created thread 14\r\nTimeStamp=2016-07-03 11:56:04.8250 ThreadId=8 Level=INFO Message=Request completed with status code: 200 \r\n<\/pre>\nHaving multiple simultaneous Index<\/i> requests, makes it almost impossible to figure out which log entry is part of which call. Fortunately with NLog<\/i> it is possible to solve this problem without too much of a hassle. <\/p>\n2. Proposed solution <\/h3>\n
The whole idea is to leverage MappedDiagnosticsLogicalContext<\/i> “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<\/i>. The very first implementation looks like that<\/p>\n\r\npublic class LoggingHttpModule : IHttpModule\r\n{\r\n private const string CorrelationIdKey = \"correlationid\";\r\n\r\n private static readonly Logger Logger = LogManager.GetCurrentClassLogger();\r\n\r\n public void Init(HttpApplication context)\r\n {\r\n context.BeginRequest += HandleBeginRequest;\r\n context.EndRequest += HandleEndRequest;\r\n }\r\n\r\n public void Dispose()\r\n {\r\n }\r\n\r\n private void HandleBeginRequest(object sender, EventArgs e)\r\n {\r\n var value = Guid.NewGuid().ToString();\r\n var httpApplication = (HttpApplication) sender;\r\n var httpContext = httpApplication.Context;\r\n MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, value);\r\n Logger.Info($\"About to start {httpContext.Request.HttpMethod} {httpContext.Request.RawUrl} request\");\r\n }\r\n\r\n private void HandleEndRequest(object sender, EventArgs e)\r\n {\r\n var httpApplication = (HttpApplication) sender;\r\n var httpContext = httpApplication.Context;\r\n Logger.Info($\"Request completed with status code: {httpContext.Response.StatusCode} \");\r\n }\r\n}\r\n<\/pre>\nOnce the HttpModule<\/i> is ready it is necessary to register it in web.config<\/i>.<\/p>\n\r\n\r\n\r\n \r\n \r\n \r\n <\/modules>\r\n<\/system.webServer>\r\n\r\n\r\n\r\n \r\n \r\n \r\n <\/httpModules>\r\n<\/system.web>\r\n<\/pre>\nFrom now on, every request goes through LogginHttpModule<\/i> and proper correlationId<\/i> is set in MappedDiagnosticsLogicalContext<\/i>.
\nAs we want to have correlationId<\/i> included in log files it is necessary to modify Nlog.config<\/i>. In my case it looks like that<\/p>\n\r\n\r\n\r\n\r\n \r\n \r\n \r\n Note that we can access our correlationId<\/i> variable via ${mdlc:item=correlationid}<\/i>
\nLog file after the changes looks like that<\/p>\n\r\nTimeStamp=2016-07-03 12:41:35.7292 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=About to start GET \/ request\r\nTimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from thread=6\r\nTimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index, from thread 7 assigned by scheduler\r\nTimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from async continuation, from thread 7\r\nTimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from explicitly created thread 9\r\nTimeStamp=2016-07-03 12:41:38.4454 CorrelationId= Level=INFO Message=Request completed with status code: 200\r\n<\/pre>\nThis is almost perfect, however for some reasons correlationId<\/i> is lost in EndRequest<\/i> event handler. I am not sure if this is bug in NLog<\/i> (I’ve posted question in Nlog’s<\/i> github) or it is by design, however there is easy workaround for that. We can store our correlationId<\/i> in HttpContext.Items<\/i> collection and reassign it to MappedDiagnosticsLogicalContext<\/i> in EndRequest<\/i> event handler.<\/p>\n\r\nprivate void HandleBeginRequest(object sender, EventArgs e)\r\n{\r\n var value = Guid.NewGuid().ToString();\r\n var httpApplication = (HttpApplication) sender;\r\n var httpContext = httpApplication.Context;\r\n MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, value);\r\n\r\n httpContext.Items[CorrelationIdKey] = value;\r\n Logger.Info($\"About to start {httpContext.Request.HttpMethod} {httpContext.Request.RawUrl} request\");\r\n}\r\n\r\nprivate void HandleEndRequest(object sender, EventArgs e)\r\n{\r\n var httpApplication = (HttpApplication) sender;\r\n var httpContext = httpApplication.Context;\r\n\r\n var correlationId = httpContext.Items[CorrelationIdKey].ToString();\r\n MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, correlationId);\r\n\r\n Logger.Info($\"Request completed with status code: {httpContext.Response.StatusCode} \");\r\n}\r\n<\/pre>\nAfter these changes our log file finally looks OK<\/p>\n
\r\nTimeStamp=2016-07-03 12:41:35.7292 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=About to start GET \/ request\r\nTimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from thread=6\r\nTimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index, from thread 7 assigned by scheduler\r\nTimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from async continuation, from thread 7\r\nTimeStamp=2016-07-03 12:41:35.8752 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Log from Index action, from explicitly created thread 9\r\nTimeStamp=2016-07-03 12:41:38.4454 CorrelationId=b322d1fa-47b2-4582-b7a9-c9463b7c0a47 Level=INFO Message=Request completed with status code: 200 \r\n<\/pre>\n