paint-brush
Fixing Logging Issues In ASP.NET: TelemetryClient Vs. ILoggerby@vitaliihoncharuk
6,808 reads
6,808 reads

Fixing Logging Issues In ASP.NET: TelemetryClient Vs. ILogger

by Vitalii HoncharukApril 16th, 2021
Read on Terminal Reader
Read this story w/o Javascript
tldt arrow

Too Long; Didn't Read

In ASP.NET: TelemetryClient Vs. ILogger vs. Ilogger is a way to log important data (like ids and exception types) to separate columns to make a comfortable logs querying experience using Microsoft.ApplicationInsights.Logging.NET. In this article, we try to answer the next questions: find the best way to. log data corresponding to the action across all call stack tree tree. Use Microsoft.Extensions to log data in custom dimensions without using regular expressions.

Company Mentioned

Mention Thumbnail
featured image - Fixing Logging Issues In ASP.NET: TelemetryClient Vs. ILogger
Vitalii Honcharuk HackerNoon profile picture

Plan:

  1. Intro
  2. TelemetryClient logs in App Insights
  3. ILogger logs in App Insights
  4. ILogger improvements
  5. Benchmark

Intro:

When your start building a system that consists of more than one application you can get such problems with logging:

  • not structuring logging (logging as a string, no data to query through)
  • in different classes and apps you have different names for values you are logging
  • difficulties to see all logs from one request through all classes and services in one query to logging provider
  • no way to create robust analytical diagrams, charts and alerts

To solve the issues above let's try to answer the next questions:

  • find the best way to log data corresponding to the action across all call stack tree
  • provide a way to log important data (like ids and exception types) to separate columns to make a comfortable logs querying experience

Logs using Microsoft.ApplicationInsights.TelemetryClient

Let's check this code example below:

var a = new TelemetryClient(new TelemetryConfiguration("the key"));
a.TrackTrace("TelemetryClient test 1",
  new Dictionary<string, string>() { { "someKey", "some value" } });

Code above will create a log entry that will be displayed as following:

This data in custom dimensions will allow you to make queries without using regular expressions.

TelemetryClient doing pretty well its job but let's see pros and cons:

pros:

  • name of the key appears in the app insights without any changes
  • custom dimensions contain only wanted data

cons:

  • usage of TelemetryClient requires to stay with the Microsoft App Insights

Logs with Microsoft.Extensions.Logging.ILogger

Let's check a code example

..., ILogger log)
{
  var calloutId = 1234;
  var testData = "test data";
  var data = new WeatherForecast{ Date = DateTimeOffset.Now, Summary = "test", TemperatureCelsius = 15};
  var jsonString = JsonConvert.SerializeObject(data);
  
  log.LogInformation("ILogger log22 {calloutId}, {testData}, {data}, {jsonString}",
      calloutId, testData, data, jsonString);
....

This code will be displayed in the Application Insights as following:

ILogger also doing pretty well bat also has some disadvantages:

pros:

  • it is possible to log data as a separate column
  • ILogger is a generic logger that may be used for any output destination

cons:

  • name of the property appears in the app insights with the prefix “prop__“
  • custom dimensions contain other data that was not manually provided
  • .ToString()
    is used for each param passed to the ILogger, so for objects passed will be displayed only their fully qualified name (requires to use
    .ToJson()
    before passing objects, except anonymous ones)

Intermediate result 1:

TelemetryClient
is a good choice for those who going to stay with AppInsights forever, on the other hand going with the default
ILogger
will add prefixes to your logged data but provide flexibility for the destination of the logs.

Improving developer experience for logging with
ILogger
to Application insights:

To encapsulate that weird way to provide additional properties to logging templates you can create a set of extension methods. Also, you can include there additional useful data like row number, file path and method name.

So usage of prepared extensions may look like this:

..., ILogger log)
{
    var calloutId = 1234;
    var companyId = 1234;
    log.LogInfo("Something happened", calloutId, companyId);
    log.LogWarn("Something happened", calloutId, companyId);
    
    try
    {
      throw new ArgumentOutOfRangeException("Test exception");
    }
    catch (Exception ex)
    {
      log.LogErr(ex, "Something happened", calloutId, companyId);
    }
....

Here is a code example for extension methods used above:

    public static class LoggerExtensions
    {
        public static void LogInfo(this ILogger logger, string reason, int calloutId, int? companyId = null, int? customerId = null,
            [CallerMemberName] string method = "",
            [CallerFilePath] string srcFilePath = "",
            [CallerLineNumber] int srcLineNumber = 0)
        {
            logger.LogInformation("{reason}, {calloutId}, {companyId}, {customerId}, {method}, {srcFilePath}, {srcLineNumber}",
                reason, calloutId, companyId, customerId, method, srcFilePath, srcLineNumber);
        }

        public static void LogWarn(this ILogger logger, string reason, int calloutId, int? companyId = null, int? customerId = null,
            [CallerMemberName] string method = "",
            [CallerFilePath] string srcFilePath = "",
            [CallerLineNumber] int srcLineNumber = 0)
        {
            logger.LogWarning("{reason}, {calloutId}, {companyId}, {customerId}, {method}, {srcFilePath}, {srcLineNumber}",
                reason, calloutId, companyId, customerId, method, srcFilePath, srcLineNumber);
        }

        public static void LogErr(this ILogger logger, Exception ex, string reason, int calloutId, int? companyId = null, int? customerId = null,
            [CallerMemberName] string method = "",
            [CallerFilePath] string srcFilePath = "",
            [CallerLineNumber] int srcLineNumber = 0)
        {
            logger.LogError("{exType}, {reason}, {calloutId}, {companyId}, {customerId}, {method}, {srcFilePath}, {srcLineNumber}, {exDetails}",
                ex.GetType().Name, reason, calloutId, companyId, customerId, method, srcFilePath, srcLineNumber, ex.ToString());
        }
    }

Intermediate result 2: With such a logging approach you can group all your logs by method name or source file as well as by any data you provide as an additional column.

Benchmark for
custom extensions for ILogger
vs
ILogger
vs
LoggerMessage

Results for 1000 logs per logger candidate running on Azure Function.
iLoggerTimer: 00:00:05.0994452
enhancedLoggerTimer: 00:00:05.4228425
loggerMsgTimer: 00:00:05.1233116

I see good results for

custom extensions for ILogger
including the fact it is also logging line number, file path and method name and have the ability to log even more useful data.

private readonly SpecificLogger _log;
private static Func<ILogger, int, int, IDisposable> scope = LoggerMessage.DefineScope<int, int>("Scope calloutId: {calloutId}, companyId: {companyId}");
private static readonly Action<ILogger, int, Exception> testLog = LoggerMessage.Define<int>(LogLevel.Information, new EventId(4, "TestEventName"), "loggerMsg: Something happened {customerId}");

public Function2(SpecificLogger log)
{
  _log = log;
}

[FunctionName("Function2")]
public async Task<IActionResult> Run(
  [HttpTrigger(AuthorizationLevel.Function, "get", "post", Route = null)]
  HttpRequest req,
  ILogger log)
{
  var calloutId = 1234;
  var companyId = 2345;
  var customerId = 3456;
  var times = 1000;

  var iLoggerTimer = Stopwatch.StartNew();
  using (log.BeginScope("Scope calloutId: {calloutId}, companyId: {companyId}", calloutId, companyId))
  {
      for (int i = 0; i < times; i++)
      {
          log.LogInformation("iLogger: Something happened {customerId}", customerId);
      }
  }

  iLoggerTimer.Stop();

  var enhancedLoggerTimer = Stopwatch.StartNew();
  _log.SetCalloutId(calloutId);
  _log.SetCompanyId(companyId);
  for (int i = 0; i < times; i++)
  {
      _log.LogWarn("enhancedLogger: Something happened 4", customerId: customerId);
  }

  enhancedLoggerTimer.Stop();

  var loggerMsgTimer = Stopwatch.StartNew();
  using (scope(log, calloutId, companyId))
  {
      for (int i = 0; i < times; i++)
      {
          testLog(log, customerId, null);
      }
  }

  loggerMsgTimer.Stop();

  var result =
      $"iLoggerTimer: {iLoggerTimer.Elapsed}; enhancedLoggerTimer: {enhancedLoggerTimer.Elapsed}, loggerMsgTimer: {loggerMsgTimer.Elapsed}";

  return new OkObjectResult(result);
}

Thanks for reading this article, hope it helps you!