6,909 reads

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

by Vitalii HoncharukApril 16th, 2021

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

featured image - Fixing Logging Issues In ASP.NET: TelemetryClient Vs. ILogger

Plan:

Intro
TelemetryClient logs in App Insights
ILogger logs in App Insights
ILogger improvements
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

ILogger

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);
}