На главную

Логирование

28-09-2017

Конспект доклада, прочитанного на заседании Клуба программистов 27 сентября 2017 года.

Логирование

Проблематика

  1. Грязный код. Классы и методы выполняют не одну работу, а две.
  2. Лишняя зависимость. Вы не можете просто вырезать из проекта класс и перенести в другой проект.
  3. Мало логов. Когда это так надо, оказывается, что нужной информации как раз и нет.
  4. Много логов. Ненужной информации оказывается слишком много, и она затрудняет поиск важных записей.
  5. Логи нужны ограниченное время при создании системы. Когда программисты отладили работу системы, логи можно отключать.

Решения

Инверсия зависимости и декорация интерфейсов

Используем мощь объектно-ориентированного и аспектно-ориентированного программирования.

В качестве примера у нас традиционный блогерский движок. Для работы с постами используем паттерн Хранилище (Repository). Чтобы иметь возможность изменить способ хранения, инвертируем зависимости в проекте: явно опишем интерфейс Хранилища на уровне предметной области, а реализацию вынесем на уровень доступа к данным.

public interface IPostRepository
{
   Post Create(string title, string content);

   Post ReadById(Guid id);

   IReadOnlyCollection<Post> ReadAll(int offset, int count);

   void Update(Post post);

   void DeleteById(Guid id);
}

Реализация метода Create для Entity Framework:

private readonly DbContext dbContext;
private readonly Func<DateTimeOffset> now;
private readonly ILogger logger;

…

public Post Create(string title, string content)
{
    logger.Trace("Start IPostRepository.Create with parameters: {0}, {1}", title, content);

    var dto = new PostDto
    {
        Created = now(),
        Title = title,
        Content = content
    };
    
    dbContext.Posts.Add(dto);

    dbContext.SaveChanges();

    var result = new Post(dto);

    logger.Trace("End IPostRepository.Create with result: {0}", result);

    return result;
}

Код простой, но его усложняет логирование и зависимость от логгера. Вынесем всё это в отдельный класс с тем же интерфейсом:

public class PostRepositoryLogger : IPostRepository
{
    private readonly IPostRepository decorating;
    private readonly ILogger logger;
…
    public Post Create(string title, string content)
    {
        logger.Trace(“Start IPostRepository.Create with parameters {0}, {1}”, title, content);

        var result = decorating.Create(title, content);

        logger.Trace(“End IPostRepository.Create with result {0}”, post);
    }
}

Это паттерн Декоратор. Класс PostRepositoryLogger логирует начало и конец каждого метода, а в середине вызывает сам метод. Теперь у нас есть два простых класса, и нет зависимости от логера. Из-за того, что классы реализуют один интерфейс, клиентский код не меняется.

Однако при таком подходе у нас получается слишком много классов-декораторов для логирования, которые мы пишем вручную. Чтобы избавиться от них, применим аспектный подход. В C# некоторые IoC-библиотеки, в частности, Autofac, позволяют генерировать байт-код для классов наподобие PostRepositoryLogger:

public class LogInterceptor : IInterceptor
{
    private readonly ILogger logger;
…
    public void Intercept(IInvocation invocation)
    {
        var parameters = string.Join(“, ”, invocation.Arguments.Select(x => (x ?? “”).ToString()));
        logger.Trace(“Start {0} with parameters {1}”, invocation.Method.Name, parameters);

        invocation.Proceed();

        logger.Trace(“End {0} with result {1}”, invocation.Method.Name, invocation.ReturnValue);
    }
}

При подключении этого обработчика Autofac самостоятельно сгенерирует байт-код, аналогичный коду метода PostRepositoryLogger.Create для тех интерфейсов, которые мы укажем.

Глобальный обработчик исключений

Обычно мы хотим логировать условия возникновения ошибок. В этом случае нам достаточно выбрасывать исключение и обрабатывать его в самом корне программы, в глобальном обработчике. В ASP.NET Core мы создаём глобальный обработчик с помощью такого кода:

public class ExceptionLoggingMiddleware
{
    private readonly RequestDelegate next;
    private readonly ILogger logger;

    public ExceptionLoggingMiddleware(RequestDelegate next, ILogger logger)
    {
        this.next = next;
        this.logger = logger;
    }

    public async Task Invoke(HttpContext context)
    {
        try
        {
            await next(context);
        }
        catch (Exception exception)
        {
            logger.Trace(“The following error happened: {0}”, exception);
        }
    }
}

Теперь вместо логирования выбрасываем исключение:

public int Avg(int[] array)
{
   if (array.Length == 0)
       throw new ArgumentException(“Zero count of elements”);

   int sum = array[0];
   for (int i = 1; i < array.Length; i++)
       sum += array[i];

   return sum / array.Length;
}

Или используем утверждения/контракты

public int Avg(int[] array)
{
   Debug.Assert(array.Length > 0, “array.Length > 0”);
   int sum = array[0];
   for (int i = 1; i < array.Length; i++)
       sum += array[i];

   return sum / array.Length;
}

Этот код многословнее, чем код без проверок, но он остаётся читаемым, и не вызывает проблем с пониманием.

Системные средства логирования

Зависимости страшны, если это не зависимости от стандартной библиотеки. Используйте для логирования стандартные средства. В C# это System.Diagnostics.TraceSource, в Java — java.util.logging. Не стесняйтесь пользоваться Debug.Assert или создавайте исключения непосредственно в коде.

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

using System.Diagnostics;

public class ExceptionLoggingMiddleware
{
    private static readonly TraceSource traceSource = new TraceSource(Assembly.GetExecutingAssembly().GetName().Name);

    private readonly RequestDelegate next;

    public ExceptionLoggingMiddleware(RequestDelegate next, ILogger logger)
    {
        this.next = next;
        this.logger = logger;
    }

    public async Task Invoke(HttpContext context)
    {
        try
        {
            await next(context);
        }
        catch (Exception exception)
        {
            traceSource.TraceEvent(TraceEventType.Error, 0, “The following error happened: {0}”, exception);
        }
    }
}
Модульные тесты

Иногда разбор логов постфактум занятие неблагодарное. Правильнее провести анализ кода и подготовить тестовые наборы данных.

Типичный пример ужасного решения:

static void BubbleSort(int[] array)
{
    for (int i = 0; i < array.Length; i++)
    {
        for (int j = i + 1; j < array.Length; j++)
        {
            if (array[i] > array[j])
            {
                traceSource.TraceEvent(TraceEventType.Trace, 0, "swap [{0}] = {1} with [{2}] = {3}", i, a[i], j, a[j]);

                int temporary = array[i];
                array[i] = array[j];
                array[j] = temporary;
            }
        }
    }
}

Видим, что логов окажется слишком много и разобраться в них будет непросто. Кроме того, видимо, что проиводительность одной из базовых операций очень сильно снизится. Чтобы протестировать цикл, мы должны предусмотреть, что при нуле и при одной итерации ничего страшного не случится. Полезно проверить сортировку массива, уже упорядоченного в прямом и обратном порядках. Полезно также проверить сортировку случайного массива.

[TestMethod]
public void BubbleSort_WithEmptyArray_ReturnsEmptyArray
{
    var actual = new int[0];

    BubbleSort(actual);

    CollectionAssert.AreEqual(new int[0], actual);
}

[TestMethod]
public void BubbleSort_WithSingleElement_ReturnsSingleElement
{
    var actual = new[] { 1 };

    BubbleSort(actual);

    CollectionAssert.AreEqual(new[] { 1 }, actual);
}

[TestMethod]
public void BubbleSort_WithSortedArray_ReturnsSortedArray
{
    var actual = new[] { 1, 2, 3, 4, 5 };

    BubbleSort(actual);

    CollectionAssert.AreEqual(new[] { 1, 2, 3, 4, 5 }, actual);
}

[TestMethod]
public void BubbleSort_WithReverseArray_ReturnsSortedArray
{
    var actual = new[] { 5, 4, 3, 2, 1 };

    BubbleSort(actual);

    CollectionAssert.AreEqual(new[] { 1, 2, 3, 4, 5 }, actual);
}

[TestMethod]
public void BubbleSort_WithRandomArray_ReturnsSortedArray
{
    var actual = new[] { 2, 3, 5, 1, 4 };

    BubbleSort(actual);

    CollectionAssert.AreEqual(new[] { 1, 2, 3, 4, 5 }, actual);
}

Логирование надо заменять на анализ и тесты именно там, где вы знаете, что лог получится огромным. Красный флаг: трейс внутри цикла, особенно внутри вложенного цикла.

Паттерн Издатель-Подписчик

Как быть, когда логирование требуется в середине метода?

Пример из практики: банковский шлюз, который получает данные из одной системы и складывает их в другую. Что делать, если полученные данные не удалось обработать и сохранить? Решение, изложенное выше — бросить исключение и обработать его в глобальном обработчике — в данном случае не очень подходит. Если одну из записей не удалось обработать, мы хотели бы записать это событие в лог и продолжить, не прервыя работу в середине.

К нам на помощь приходит паттерн Издатель-Подписчик (Publisher-Subscriber), он же Наблюдтель (Observer).

public event EventHandler<Exception> ExceptionOccured;

protected virtual void OnExceptionOccured(Exception exception)
{
    ExceptionOccured?.Invoke(this, exception);
}
…
foreach (var row in importedRows)
{
    try
    {
        // Обрабатываем и сохраняем row
        …
    }
    catch (Exception exception)
    {
        OnExceptionOccured(exception);
    }
}
…
// Где-то снаружи класса Importer, где есть зависимость от логера
importer.ExceptionOccured += (sender, exception) =>
{
    traceSource.TraceEvent(TraceEventType.Error, 0, exception.ToString());
};

Что видим? Ситуации, которые происходят при импорте, мы выносим наружу как события. Теперь код, который импортирует данные, не зависит от логера и чист. При всём при этом этот код можно переносить из консольного приложения в оконное, или в веб-сервис — и использовать их средства для отображения ошибок импорта. Для этого нам не нужно будет вносить изменения — в полном соответствии с принципом код открыт для расширения, но закрыт для изменения.

Фильтрация

Когда лог слишком большой, его нужно фильтровать. Важные принципы:

  1. Знать, что не нужно логировать. Часть сценариев, которые реализованы через исключения, на самом деле ожидаемы, и не требуют специального разбора. Например, в базе данных нет сущности с заданным идентификатором: генерируем исключение, которое приведёт к возврату статуса HTTP 404 (ресурс не найден). Обрабатывать надо, логировать нет.
  2. Два раза думать при определении уровня сообщения. Напомню: Trace, Debug, Information, Warning, Error, Fatal. При уровне Information мусора в логе быть не должно. На практике: есть веб-сервис. При старте мы логируем окружение. Это Information, один раз на каждый рестарт сервиса, обычно несколько раз в день. Если то же самое делаем при каждом запросе, это не Information, и даже не Debug, а Trace. Если ваша программа умеет восстанавливать сетевые подключения, то потеря подключения это не Error, а тоже Trace. Вот если она пыталась 3 раза и не смогла, тогда это Error.
  3. Следить за пространствами имён. Обычно у каждого класса свой логер, привязанный к полному имени класса. Можно отключать целые куски иерархий, с учётом вложенности. Для этого надо, чтобы пространства имён соответствовали правилу: если А зависит от Б, то А находится во вложенном пространстве имён по отношению к Б. При гексагональной архитектуре это позволяет отключить весь ограниченный контекст целиком, или отдельные уровни этого контекста.
Двенадцатифакторные приложения

https://12factor.net/ru/logs

Консольное приложение, которое само для себя сервер. Надо не использовать вообще никакую систему логирования, а писать всё в stdout. Тем не менее, следуем зависимостям. Не протягиваем зависимость от уровня представления (HTTP) в уровень предметной области. Используем TraceSource и по-умолчанию настраиваем трассировку в стандартный поток вывода (см. ConsoleTraceListener).