Апрель 2016

Том 31 номер 4

Главное в .NET - Протоколирование в .NET Core

Марк Михейлис | Апрель 2016

Исходный код можно скачать по ссылке

В номере за февраль я углубился в новый API конфигурации, включенный в новую платформу .NET Core 1.0 (bit.ly/1OoqmkJ). (Полагаю, что большинство читателей слышало о недавно переименованной .NET Core 1.0, которая ранее обозначалась как .NET Core 5 и являлась частью платформы ASP.NET 5 [bit.ly/1Ooq7WI].) В той статье я использовал модульное тестирование, чтобы исследовать Microsoft.Extensions.Configuration API. В этой статье я предприму похожий подход, но в отношении Microsoft.Extensions.Logging. Ключевое отличие в моем подходе в том, что сейчас я буду тестировать API из .NET 4.6 CSPROJ-файла, а не из проекта ASP.NET Core. Это подчеркивает тот факт, что .NET Core уже доступна вам для немедленного применения, даже если вы не перешли на проекты ASP.NET Core.

Протоколирование? С какой стати нам понадобилась новая инфраструктура протоколирования? У нас уже есть NLog, Log4Net, Loggr, Serilog и встроенная Microsoft.Diagnostics.Trace/Debug/TraceSource, не говоря уже о других. Оказывается, тот факт, что на рынке так много инфраструктур протоколирования, и послужил одним из стимулов к созданию Microsoft.Extensions.Logging. Как разработчик, столкнувшийся с широчайшим выбором, вы скорее всего выберете что-то одно, понимая, что позднее вам, возможно, придется переключиться на другое. Поэтому у вас может возникнуть соблазн написать собственную оболочку API протоколирования, которая обращается к любой конкретной инфраструктуре протоколирования, выбранной вами или вашей компанией на этой неделе. Аналогично вы можете использовать некую конкретную инфраструктуру протоколирования в своем приложении и обнаружить только то, что одна из библиотек, применяемых вами, использует другую библиотеку, вынуждая вас писать слушатель, принимающий сообщения от одной библиотеки к другой.

Microsoft предоставляет с Microsoft.Extensions.Logging оболочку, поэтому никому больше не понадобится писать собственную. Эта оболочка содержит один набор API, которые затем пересылают вызовы выбранному вами провайдеру. Хотя Microsoft включает провайдеры для консоли (Microsoft.Extensions.Logging.Console), отладки (Microsoft.Extensions.Logging.Debug), журнала событий (Microsoft.Extensions.Logging.EventLog) и TraceSource (Microsoft.Estensions.Logging.TraceSource), она также сотрудничает с различными группами, создающими другие инфраструктуры протоколирования (включая сторонние вроде NLog, Serilog, Loggr, Log4Net и др.), так что в Microsoft.Extensions.Logging есть совместимые провайдеры и от них.

Приступаем к работе

Операции протоколирования начинаются с фабрики журналов (log factory), как показано на рис. 1.

Рис. 1. Как использовать Microsoft.Extensions.Logging

public static void Main(string[] args = null)
{
  ILoggerFactory loggerFactory = new LoggerFactory()
    .AddConsole()
    .AddDebug();

  ILogger logger = loggerFactory.CreateLogger<Program>();

  logger.LogInformation(
    "This is a test of the emergency broadcast system.");
}

Как демонстрирует этот код, вы начинаете с создания экземпляра Microsoft.Extensions.Logging.LoggerFactory, который реализует ILoggerFactory в том же пространстве имен. Затем вы указываете, какие провайдеры вы хотите задействовать, вызывая метод расширения ILoggerFactory. На рис. 1 я намеренно использую Microsoft.Extensions.Logging.ConsoleLoggerExtensions.AddConsole и Microsoft.Extensions.Logging.DebugLoggerFactoryExtensions.AddDebug. (Хотя оба эти класса находятся в пространстве имен Microsoft.Extensions.Logging, они на самом деле содержатся в NuGet-пакетах Microsoft.Extensions.Logging.Console и Microsoft.Extensions.Logging.Debug соответственно.)

Методы расширения являются просто удобными сокращениями для более универсального способа добавления провайдера: ILoggerFactory.AddProvider(ILoggerProvider provider). Сокращение в том, что метод AddProvider принимает экземпляр провайдера журнала (возможно, того, конструктор которого требует передачи выражения фильтра уровня ведения журнала), а методы расширения предоставляют умолчания для таких выражений. Например, сигнатура конструктора для ConsoleLoggerProvider выглядит так:

public ConsoleLoggerProvider(Func<string, LogLevel, bool>
  filter, bool includeScopes);

Первый параметр является предикативным выражением, которое позволяет вам определять, появится ли сообщение в выводе, на основе значения протоколируемого текста и уровня ведения журнала.

Например, вы могли бы вызвать AddProvider с конкретным экземпляром ConsoleLoggerProvider, который был сконструирован из фильтра, пропускающего все сообщения с более высоким значением (более значимые), чем LogLevel.Information:

loggerFactory.AddProvider(new ConsoleLoggerProvider(
  (text, logLevel) => logLevel >= LogLevel.Verbose , true));

(Любопытно, что в отличие от методов расширения, возвращающих ILoggerFactory, AddProvider возвращает void, что предотвращает использование текучего синтаксиса типов, показанного на рис. 1.)

Важно понимать, что, к сожалению, между провайдерами журналов существует некоторая несогласованность в отношении того, как рассматривать высокое значение уровня ведения журнала (log-level value) — как более или менее значимое? Указывает ли уровень 6 на критическую ошибку или это просто степень детализации диагностического сообщения? Microsoft.Extensions.Logging.LogLevel использует высокие значения для указания на более высокий приоритет с помощью следующего объявления перечисления LogLevel:

public enum LogLevel
{
  Debug = 1,
  Verbose = 2,
  Information = 3,
  Warning = 4,
  Error = 5,
  Critical = 6,
  None = int.MaxValue
}

Поэтому, создавая экземпляр ConsoleLoggerProvider, который записывает сообщения, только когда logLevel >= LogLevel.Verbose, вы исключаете из вывода лишь сообщения уровня Debug.

Заметьте, что можно добавить несколько провайдеров к фабрике журналов, даже несколько провайдеров одного и того же типа. Следовательно, если я добавлю вызов ILoggerFactory.AddProvider в код на рис. 1, вызов ILogger.LogInformation выведет сообщение в консоль дважды. Первый провайдер консоли (добавленный AddConsole) по умолчанию отображает все, что находится на уровне LogLevel.Information или выше. Однако вызов ILogger.LogVerbose проявится лишь раз, когда единственный дополнительный провайдер (добавленный методом AddProvider) успешно пройдет фильтрацию.

Шаблоны протоколирования

Как демонстрирует рис. 1, любое протоколирование начинается с фабрики журналов, из которой можно запрашивать ILogger методом ILoggerFactory.CreateLogger<T>. Обобщенный тип T в этом методе идентифицирует класс, в котором выполняется код, поэтому можно выводить имя класса, куда средство ведения журнала пишет сообщения. Иначе говоря, вызвав loggerFactory.CreateLogger<Program>, вы, по сути, инициируете средство ведения журнала, специфичное для класса Program, так чтобы при каждой записи сообщения, можно было записывать и контекст выполнения как находящийся в классе Program. Таким образом, консольный вывод кода с рис. 1 выглядит так:

info: SampleWebConsoleApp.Program[0]
      This is a test of the emergency broadcast system.

Этот вывод основан на следующем:

• info вытекает из того факта, что это вызов метода LogInformation;
• SampleWebConsoleApp.Program определяется по T;
• [0] является eventId — значением, которое я не указывал, поэтому по умолчанию оно равно 0;
• текст «This is a test of the emergency broadcast system.» — это аргумент messages, переданный в LogInformation.

Поскольку значение Program указывает контекст уровня класса, вы скорее всего захотите создавать другой экземпляр средства ведения журналов для каждого класса, из которого вам нужно протоколировать сообщения. Например, если Program создает и вызывает экземпляр класса Controller, вы предпочтете новый экземпляр средства ведения журналов в классе Controller, созданный другим вызовом метода, где T теперь является Controller:

loggerFactory.CreateLogger<Controller>()

Как вы, вероятно, заметили, это требует доступа к тому же экземпляру фабрики средств ведения журналов, под который ранее были сконфигурированы провайдеры. И хотя вполне допустимо передавать экземпляр фабрики средства ведения журналов в каждый класс, в котором вам нужно протоколировать сообщения, соответствующий код быстро станет громоздким, что потребует рефакторинга.

Решение — сохранить единственный статический ILoggerFactory в качестве статического свойства, доступного всем классам при создании специфичного для их объекта экземпляра ILoggger. Рассмотрим, к примеру, добавление статического класса ApplicationLogging, включающего статический экземпляр ILoggerFactory:

public static class ApplicationLogging
{
  public static ILoggerFactory LoggerFactory {get;} =
    new LoggerFactory();
  public static ILogger CreateLogger<T>() =>
    LoggerFactory.CreateLogger<T>();
}

Очевидная озабоченность в таком классе — является ли LoggerFactory безопасным в многопоточной среде. И, к счастью, как демонстрирует метод AddProvider на рис. 2, он безопасен.

Рис. 2. Реализация Microsoft.Extensions.Logging.LoggerFactory AddProvider

public void AddProvider(ILoggerProvider provider)
{
  lock (_sync)
  {
    _providers = _providers.Concat(
      new[] { provider }).ToArray();
    foreach (var logger in _loggers)
    {
      logger.Value.AddProvider(provider);
    }
  }
}

Поскольку единственные данные в экземпляре ILogger определяются обобщенным типом T, вы могли бы возразить, что каждый класс мог бы иметь статический ILogger, используемый объектом каждого класса. Однако, согласно стандарту программирования, гарантирующего безопасность в многопоточной среде для всех статических членов, такой подход потребовал бы контроля параллельной обработки в реализации ILogger (чего по умолчанию в ней нет) и скорее всего вызвал бы появление значимого узкого места из-за необходимости захватывать и освобождать блокировки. По этой причине и рекомендуется иметь индивидуальный экземпляр ILogger для каждого экземпляра какого-либо класса. Поэтому в итоге вы видите свойство ILogger в каждом классе, который должен поддерживать протоколирование (рис. 3).

Рис. 3. Добавление экземпляра ILogger в каждый объект, подлежащий протоколированию

public class Controller
{
  ILogger Logger { get; } =
    ApplicationLogging.CreateLogger<Controller>();

  // ...
  public void Initialize()
  {
    using (Logger.BeginScopeImpl(
      $"=>{ nameof(Initialize) }"))
    {
      Logger.LogInformation("Initialize the data");
      //...
      Logger.LogInformation("Initialize the UI");
      //...
    }
  }
}

Понимание областей

Зачастую провайдеры поддерживают концепцию области (scope), так чтобы вы могли (к примеру) протоколировать, как ваш ход проходит по цепочке вызовов. Продолжая этот пример, если Program вызывает какой-то метод в классе Controller, тот класс в свою очередь создает экземпляр собственного средства ведения журналов со своим контекстом типа T. Однако вместо того, чтобы просто отображать контекст сообщения в виде info: SampleWebConsoleApp.Program[0], за которым следует info: SampleWebConsoleApp.Controller[0], возможно, вы захотите протоколировать сообщения от Controller, вызванного Program, и даже включать имена самих методов. Для этого вы активируете концепцию областей в провайдере. На рис. 3 приведен пример этого в методе Initialize через вызов Logger.BeginScopeImpl.

Использование шаблона протоколирования и одновременное применение активации областей приведет к тому, что класс Program, возможно, будет выглядеть наподобие того, что показано на рис. 4.

Рис. 4. Обновленная реализация класса Program

public class Program
{
  static ILogger Logger { get; } =
    ApplicationLogging.CreateLogger<Program>();
public static void Main(string[] args = null)
  {
    ApplicationLogging.LoggerFactory.AddConsole(true);
    Logger.LogInformation(
      "This is a test of the emergency broadcast system.");
    using (Logger.BeginScopeImpl(nameof(Main)))
    {
      Logger.LogInformation("Begin using controller");
      Controller controller = new Controller();
      controller.Initialize();
      Logger.LogInformation("End using controller");
    }
    Logger.Log(LogLevel.Information, 0,
      "Shutting Down...", null, null);
  }
}

Вывод кода с рис. 3 в сочетании с кодом с рис. 4 показан на рис. 5.

Рис. 5. Консольный вывод протоколирования с включением областей

info: SampleWebConsoleApp.Program[0]
      This is a test of the emergency broadcast system.
info: SampleWebConsoleApp.Program[0]
      => Main
      Begin using controller
info: SampleWebConsoleApp.Controller[0]
      => Main => Initialize
      Initialize the data
info: SampleWebConsoleApp.Controller[0]
      => Main => Initialize
      Initialize the UI
info: SampleWebConsoleApp.Program[0]
      => Main
      End using controller
info: SampleWebConsoleApp.Program[0]
      Shutting down...

Заметьте, как области автоматически раскручиваются, чтобы больше не включать Initialize или Main. Эта функциональность предоставляется благодаря тому, что BeginScopeImpl возвращает экземпляр IDisposable, который автоматически раскручивает область, когда выражение using вызывает Dispose.

Применение стороннего провайдера

Чтобы сделать доступными некоторые из наиболее известных сторонних инфраструктур протоколирования, Microsoft сотрудничала с их разработчиками и предусмотрела провайдеры для каждой из таких инфраструктур. Рассмотрим, как подключить инфраструктуру NLog (рис. 6).

Рис. 6. Конфигурирование NLog в качестве провайдера Microsoft.Extensions.Logging

[TestClass]
public class NLogLoggingTests
{
  ILogger Logger {get;}
    = ApplicationLogging.CreateLogger<NLogLoggingTests>();

  [TestMethod]
  public void LogInformation_UsingMemoryTarget_
    LogMessageAppears()
  {
    // Добавляем провайдер NLog
    ApplicationLogging.LoggerFactory.AddNLog(
      new global::NLog.LogFactory(
        global::NLog.LogManager.Configuration));

    // Конфигурируем target
    MemoryTarget target = new MemoryTarget();
    target.Layout = "${message}";
    global::NLog.Config.SimpleConfigurator.
      ConfigureForTargetLogging(
      target, global::NLog.LogLevel.Info);

    Logger.LogInformation(Message);
      Assert.AreEqual<string>(
      Message, target.Logs.FirstOrDefault<string>());
  }
}

Большая часть кода хорошо известна тем, кто знаком с NLog. Сначала я создаю экземпляр мишени NLog типа NLog.Targets.MemoryTarget и конфигурирую его. (Существуют многочисленные мишени [targets] NLog, и каждую из них можно идентифицировать и настроить в конфигурационном файле NLog — в дополнение к использованию конфигурационного кода, приведенного на рис. 6.) Заметьте, что при всей схожести Layout присваивается литеральное значение ${message}, а не строковое интерполированное значение.

После добавления к LoggerFactory и настройки код идентичен коду для любого другого провайдера.

Обработка исключений

Конечно, одна из самых распространенных причин протоколирования — регистрация того, где произошло исключение, а точнее, когда исключение обрабатывается, а не повторно генерируется или когда оно никак не обрабатывается (bit.ly/1LYGBVS). Как и следовало бы ожидать, Microsoft.Extensions.Logging имеет специфические методы для обработки исключений. Большинство таких методов реализовано в Microsoft.Extensions.Logging.LoggerExtensions как методы расширения ILogger. И именно в этом классе реализуется каждый метод, специфичный для конкретного уровня ведения журнала (ILogger.LogInformation, ILogger.LogDebug, ILogger.LogCritical и т. д.). Например, если вы хотите записывать в журнал сообщение LogLevel.Critical, относящееся к исключению (возможно, перед корректным закрытием приложения), то должны вызвать:

Logger.LogCritical(message,
  new InvalidOperationException("Yikes..."));

Другой важный аспект протоколирования и обработки исключений заключается в том, что ведение журнала, особенно при обработке исключений, не должно приводить к генерации какого-либо исключения. Если исключение генерируется при ведении журнала, очевидно, что сообщение или исключение никогда не будет зарегистрировано в журнале и потенциально может ускользнуть от внимания независимо от того, насколько оно критичное. К сожалению, готовая реализация ILogger — Microsoft.Extensions.Logging.Logger — не имеет такой обработки исключений, поэтому, если произойдет исключение, вызывающему коду понадобится обработать его — и делать так при каждом вызове Logger.LogX. Универсальный подход к решению этой задачи — возможное обертывание Logger для перехвата исключения. Но не исключено, что вы предпочтете реализовать свои версии ILogger и ILoggerFactory (пример см. по ссылке bit.ly/1LYHq0Q). Учитывая, что .NET Core имеет открытый исходный код, вы могли бы даже клонировать класс и сознательно реализовать обработку исключений в собственных реализациях LoggerFactory и ILogger.

Заключение

Я начал с вопроса: «С какой стати нам понадобилась новая инфраструктура протоколирования?». Надеюсь, теперь это понятно. Новая инфраструктура создает уровень абстракции или оболочку, которая позволяет вам использовать любую инфраструктуру протоколирования в качестве провайдера. Это обеспечивает вам максимальную гибкость в вашей работе. Более того, хотя это доступно только в .NET Core, ссылки на NuGet-пакеты .NET Core вроде Microsoft.Extensions.Logging в стандартном проекте Visual Studio для .NET 4.6 не являются проблемой.

Марк Михейлис (Mark Michaelis) — учредитель IntelliTect, где является главным техническим архитектором и тренером. Почти два десятилетия был Microsoft MVP и региональным директором Microsoft с 2007 года. Работал в нескольких группах рецензирования проектов программного обеспечения Microsoft, в том числе C#, Microsoft Azure, SharePoint и Visual Studio ALM. Выступает на конференциях разработчиков, автор множества книг, последняя из которых — «Essential C# 6.0 (5th Edition)» (itl.tc/EssentialCSharp). С ним можно связаться в Facebook (facebook.com/Mark.Michaelis), через его блог (IntelliTect.com/Mark), в Twitter (@markmichaelis) или по электронной почте mark@IntelliTect.com.

Выражаю благодарность за рецензирование статьи экспертам IntelliTect Кевину Босту (Kevin Bost), Крису Финлейсону (Chris Finlayson) и Майклу Стоуксбери (Michael Stokesbary).

Discuss this article in the MSDN Magazine forum