In my current project, we use Microsoft.Extensions.Logging.ILogger<T><\/i> default implementation as our logging mechanism. This basically comes with the ASP.NET Core 2.0<\/i> package and it was working fine so far. However recently we decided to switch the default implementation with a custom one, due to the fact that we wanted to have some additional logic applied for all of the logging providers. <\/p>\n2. Implementation<\/h3>\n
The custom implementation itself is very similar to the original one, we came up with something like that<\/p>\n
\r\npublic class Logger : ILogger\r\n{\r\n private readonly ILogger _logger;\r\n\r\n public Logger(ILoggerFactory loggerFactory)\r\n {\r\n _logger = loggerFactory.CreateLogger();\r\n }\r\n\r\n public void Log(LogLevel, EventId, TState state, Exception, Func formatter)\r\n {\r\n string Formatter(TState innserState, Exception innerException)\r\n {\r\n \/\/ additional logic goes here, in my case that was extracting additional information from custom exceptions\r\n var message = formatter(innserState, innerException) ?? string.Empty;\r\n return message + \" additional stuff in here\";\r\n }\r\n\r\n _logger.Log(logLevel, eventId, state, exception, Formatter);\r\n }\r\n\r\n public bool IsEnabled(LogLevel logLevel)\r\n {\r\n return _logger.IsEnabled(logLevel);\r\n }\r\n\r\n public IDisposable BeginScope(TState state)\r\n {\r\n return _logger.BeginScope(state);\r\n }\r\n}\r\n<\/pre>\nand we replaced the default logger with this code<\/p>\n
\r\nservices.Replace(new ServiceDescriptor(typeof(ILogger<>), typeof(Logger.Logger<>), ServiceLifetime.Singleton));\r\n<\/pre>\nAs you can see we basically wanted to add information from custom exceptions to the message. Due to the fact that this is added in here, we don\u2019t have to modify all of our existing logging providers. <\/p>\n
3. NLog<\/i> call site renderer issue<\/h3>\n
Once we run the application all of the providers were working fine and were producing expected output apart from NLog<\/i> provider. Originally NLog<\/i> provider for the following code<\/p>\n\r\n[Route(\"api\/[controller]\")]\r\npublic class ValuesController : Controller\r\n{\r\n private readonly ILogger _logger;\r\n\r\n public ValuesController(ILogger logger)\r\n {\r\n _logger = logger;\r\n }\r\n\r\n [HttpGet]\r\n public IEnumerable Get()\r\n {\r\n _logger.LogTrace(\"Get method called trace\");\r\n _logger.LogWarning(\"Get method called warning\");\r\n _logger.LogError(\"Get method called error\");\r\n _logger.LogInformation(\"Get method called information\");\r\n\r\n return new string[] {\"value1\", \"value2\"};\r\n }\r\n}\r\n<\/pre>\nwas producing this output<\/p>\n
\r\nTimeStamp=2018-02-28 20:14:37.2711 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=TRACE Message=Get method called trace \r\nTimeStamp=2018-02-28 20:14:37.3261 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=WARN Message=Get method called warning \r\nTimeStamp=2018-02-28 20:14:37.3261 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=ERROR Message=Get method called error \r\nTimeStamp=2018-02-28 20:14:37.3261 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=INFO Message=Get method called information \r\n<\/pre>\nHowever, after introducing new implementation of ILogger<T><\/i>, it started appending wrong caller member name<\/p>\n\r\nTimeStamp=2018-02-28 20:17:27.4044 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=TRACE Message=Get method called trace additional stuff in here \r\nTimeStamp=2018-02-28 20:17:27.5117 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=WARN Message=Get method called warning additional stuff in here \r\nTimeStamp=2018-02-28 20:17:27.5117 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=ERROR Message=Get method called error additional stuff in here \r\nTimeStamp=2018-02-28 20:17:27.5202 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=INFO Message=Get method called information additional stuff in here \r\n<\/pre>\nAfter some digging, it turned out that the issue lies in the (indirect)configuration of NLog’s<\/i> callsite layout renderer<\/a>. Long story short, when you add NLog<\/i> provider to your logger providers, under the hood it adds Microsoft.Extensions.Logging.Abstractions<\/i> assembly(among others) to something called hidden assembly collection. Once the NLog<\/i> tries to figure out what is the caller member name, it crawls the stack trace to find a method name. If the method in current frame comes from a hidden assembly, logger skips it and continues iteration. As we changed the Logger<T><\/i> to our custom one, it is no longer part of Microsoft.Extensions.Logging.Abstractions<\/i> assembly, so the NLog<\/i> reports Log<\/i> method from our custom logger as a caller member name. <\/p>\n4. The fix <\/h3>\n
In order to restore previous behavior you have to add custom logger assembly to the hidden assembly collection. You can do it via<\/p>\n
\r\nLogManager.AddHiddenAssembly(typeof(Logger.Logger<>).Assembly);\r\n<\/pre>\nOf course, if the logger is located in the same assembly as rest of your code, this might not be the perfect solution – as this will impact the way the callsite is rendered for other parts of your code in this assembly. In that case, you might consider moving the logging piece to separate assembly or resign from using callsite layout renderer at all. We decided to replace it with logger layout renderer<\/a> as callsite layout renderer, either way, wouldn\u2019t be used in production environments. <\/p>\n