Когда на нашей рабочей системе происходит какая-либо ошибка, нам хочется, чтобы логи содержали всю необходимую информацию о том, из-за чего она произошла. На достаточно сложных системах это приводит к сбору большого количества данных: какие этапы обработки были выполнены, с какими аргументами вызывались те или иные методы, что вернули запросы к внешним системам и т. д. Проблема заключается в том, что эту информацию нам приходится собирать даже в случае, если никакой ошибки не произошло. А это приводит к росту объёма наших логов, за который нам приходится платить деньги.

Уровни логирования (error, warning, information, ...) здесь помогают мало. Обычно для приложения выставляется некий целевой уровень (например, information). Это означает, что все записи с уровнем выше или равным данному попадают в логи, а менее значимые выбрасываются. Но в тот момент, когда происходит ошибка, для нас наибольший интерес представляют именно записи debug-уровня, которые обычно и выбрасываются. Хорошо, если ошибка встречается довольно часто. В это случае можно временно опустить целевой уровень логирования системы, собрать информацию об ошибке, а потом вернуть уровень назад. Таким образом объём собираемых логов возрастёт только временно. Если же ошибка встречается достаточно редко, такой подход хоть и возможен, но не очень удобен, поскольку приводит к значительному росту объёма логов.

Можно ли как-то улучшить сложившуюся ситуацию? Я думаю, что можно. Сразу оговорюсь, что в этой статье я предлагаю не готовое решение, а скорее пожелание к существующим системам логирования, поскольку реализация этого подхода по-видимому потребует внесения изменений в их исходный код.

А теперь приступим.

Основная идея

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

using(_logBlockFactory.CreateLogBlock())
{
    ...

    SomeOperations();

    ...
}

Все записи в лог, которые произошли внутри такого блока, не отправляются в хранилища логов немедленно, а ожидают вызова метода Dispose блока. Внутри вызова этого метода Dispose производится анализ этих записей. Если среди них есть записи уровня error или выше, то блок отправляет все записи в хранилища логов. Если же оказывается, что никаких сообщений об ошибках там нет, то блок просто выбрасывает все собранные записи.

Естественно, отметка времени каждой записи берётся в тот момент, когда она была сформирована, а не тогда, когда был вызван Dispose блока.

Возможные усовершенствования

Эту базовую идею можно усовершенствовать.

Во-первых, вам может требоваться, чтобы некоторые записи попадали в лог обязательно, вне зависимости от того, произошла ли ошибка или нет. Например, вы можете вести аудит по таким записям, или сохранять информацию о быстродействии операций для дальнейшего анализа (хотя, для этой цели лучше использовать метрики). Тем не менее, такую возможность следует предусмотреть:

_logger.Mandatory.WriteInformation("Something");

Во-вторых, вам может потребоваться самостоятельно решать, стоит ли сбрасывать записи в хранилища логов или нет. Для этого можно использовать как простое свойство:

_logBlockFactory.CurrentBlock.WriteBlock = true;

так и придумать что-нибудь более сложное типа функции, которая будет просматривать записи внутри блока и на их основе принимать решение.

Можно даже поиграть уровнями логирования. Например, при наличии ошибки блок записывает в хранилища все записи любых уровней, а при отсутствии - только information и выше. Не знаю, насколько реально (и нужно) реализовать такой подход. Сегодня можно выставлять целевые уровни логирования для каждого хранилища отдельно. Так что, думаю, такой новый подход потребует слишком больших изменений в самой существующей концепции логирования.

Проблемы

Естественно, данная идея имеет и свои отрицательные стороны.

Если вам требуется, чтобы записи поступали в хранилища практически в реальном времени, то данный подход вам не подойдёт. Реальная запись в хранилища происходит только в момент вызова метода Dispose блока.

Поскольку записи теперь пишутся в хранилища пакетами, может оказаться, что они размещаются там не по порядку времени. Например, первый блок записал записи за 11:31:01, 11:31:02, 11:31:03. После этого завершился второй блок и так же записал записи за 11:31:01, 11:31:02, 11:31:03. Т. е. записи оказываются перемешанными по времени. Если ваше хранилище не поддерживает сортировку по времени (console, file, ...), это может быть проблемой. С другой стороны, думаю, что все промышленные хранилища (типа Azure Application Insights) поддерживают такую сортировку. Кроме того, записи из разных блоков наверняка будут иметь разный correlation id, что облегчит их отделение друг от друга.

Далее, поскольку записи заносятся в хранилища не сразу, в случае серьёзного сбоя приложения мы можем потерять часть записей (если метод Dispose блока вообще не будет вызван).

Определённую проблему представляет также семантика вложенных блоков. Если ошибка произошла во внутреннем блоке, как должен вести себя внешний блок? Что если ошибка произошла во внешнем блоке? Нужно куда-то писать записи из внутренних блоков? Всё это нужно детально продумать.

Заключение

Вот и вся идея, которая пришла мне в голову для решения проблемы распухания логов. Надеюсь, она будет полезна, и кто-нибудь попробует её реализовать. Удачи!