Читая Technology Radar от ThoughtWorks, я наткнулся на технику "Отдельный уровень логирования на каждый запрос (Log level per request)". Мы в Confirmit широко используем логирование, и мне стало интересно, как можно реализовать эту функциональность.

Описание проблемы

Давайте разберемся, о чем идет речь. Пусть у нас есть Web-сервис. В какой-то момент он начинает сбоить на рабочих серверах, но только для некоторых запросов. Например, сбои происходят только для определенного пользователя. Или только на отдельной точке доступа… Нам необходимо найти причину. В этом случае нам на помощь приходит логирование.

Мы можем вставить в наш код достаточно инструкций логирования, чтобы понять причину проблемы. Эти инструкции обычно ставят в соответствие вашему сообщению некоторый уровень логирования (log level) (Debug, Info, Warning, ...). Кроме того, сам лог также имеет свой уровень. Все сообщения с уровнями выше уровня лога будут записаны в хранилища лога (log sink) (файл, базу данных, ...). Если же уровень сообщения ниже уровня лога, то сообщение будет просто отброшено.

Когда наше приложение работает нормально, мы хотим видеть как можно меньше записей в логе, чтобы его размер оставался маленьким. В то же время, если в приложении происходит сбой, мы хотим, чтобы в логе было достаточно записей, чтобы мы могли понять причину проблемы. Сложность здесь в том, что обычно мы устанавливаем один уровень логирования для всех логгеров в нашем приложении. Если все в порядке, мы держим этот уровень высоким (например, Warning). Если же нам нужно искать причину сбоя, мы устанавливаем его ниже (например, Debug).

Один уровень логирования на все приложение

Когда мы устанавливаем уровень логирования в приложении низким, наши хранилища логов заполняются массой сообщений. Эти сообщения приходят от разных запросов и перемешаны между собой, поскольку запросы могут обслуживаться одновременно. Это ведет к ряду потенциальных проблем:

• Как отделить сообщения проблемных запросов от сообщений других запросов?
• Запросы, не приводящие к сбоям, все равно тратят свое время на запись в хранилища логов, хотя эти сообщения никогда не будут использованы.
• Сообщения из успешных запросов будут занимать место в хранилищах логов, хотя эти сообщения никогда не будут использованы.

Честно говоря, эти трудности не являются непреодолимыми. Чтобы отделить сообщения “хороших” запросов от сообщений “плохих” запросов, можно использовать correlation id. Все современные системы обработки логов позволяют производить фильтрацию записей по различным критериям, в том числе и по этому.

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

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

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

Отдельный уровень логирования для каждого запроса

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

Итак, задача поставлена. Давайте начнем.

Я создам простой Web-сервис на основе .NET Core. У него будет единственный контроллер:

[Route("api/[controller]")]
[ApiController]
public class ValuesController : ControllerBase
{
    ...

    // GET api/values
    [HttpGet]
    public ActionResult<IEnumerable<string>> Get()
    {
        Logger.Info("Executing Get all");

        return new[] { "value1", "value2" };
    }

    // GET api/values/5
    [HttpGet("{id}")]
    public ActionResult<string> Get(int id)
    {
        Logger.Info($"Executing Get {id}");

        return "value";
    }
}

Реализацию свойства Logger обсудим позже. Для этого приложения я буду использовать библиотеку log4net для логирования. Данная библиотека предоставляет интересную возможность. Я говорю о наследовании уровня логирования (level inheritance). Кратко говоря, если в конфигурации этой библиотеки вы говорите, что лог с именем X должен иметь уровень логирования Info, это означает, что все логи с именами, начинающимися с X. (например, X.Y, X.Z, X.A.B) будут наследовать этот самый уровень.

Отсюда проистекает изначальная идея. Для каждого запроса я каким-то образом определю требуемый уровень логирования. Затем я создам новый именованный лог в конфигурации log4net. Этот лог будет иметь требуемый уровень логирования. После этого, все объекты логгеров, созданные в рамках текущего запроса, должны иметь имена начинающиеся с имени этого нового созданного мной лога. Единственной проблемой здесь является то, что log4net никогда не удаляет логи. Будучи однажды созданными, они существуют все время жизни приложения. По этой причине я изначально создаю по одному логу на каждый возможный уровень логирования:

<?xml version="1.0" encoding="utf-8" ?>
<log4net>
  <appender name="Console" type="log4net.Appender.ConsoleAppender">
    <layout type="log4net.Layout.PatternLayout">
      <!-- Pattern to output the caller's file name and line number -->
      <conversionPattern value="%5level [%thread] (%file:%line) - %message%newline" />
    </layout>
  </appender>

  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
    <file value="RequestLoggingLog.log" />
    <appendToFile value="true" />
    <maximumFileSize value="100KB" />
    <maxSizeRollBackups value="2" />

    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%level %thread %logger - %message%newline" />
    </layout>
  </appender>

  <root>
    <level value="WARN" />
    <appender-ref ref="Console" />
    <appender-ref ref="RollingFile" />
  </root>

  <logger name="EdlinSoftware.Log.Error">
    <level value="ERROR" />
  </logger>

  <logger name="EdlinSoftware.Log.Warning">
    <level value="WARN" />
  </logger>

  <logger name="EdlinSoftware.Log.Info">
    <level value="INFO" />
  </logger>

  <logger name="EdlinSoftware.Log.Debug">
    <level value="DEBUG" />
  </logger>
</log4net>

Теперь у меня есть несколько логов с именами EdlinSoftware.Log.XXXX. Эти имена будут служить префиксами имен логов, используемых в запросах. Чтобы избежать коллизий между запросами, я буду хранить вычисленный префикс для данного запроса в экземпляре AsyncLocal. Значение этого объекта будет устанавливаться в новом OWIN middleware:

app.Use(async (context, next) =>
{
    try
    {
        LogSupport.LogNamePrefix.Value = await LogSupport.GetLogNamePrefix(context);

        await next();
    }
    finally
    {
        LogSupport.LogNamePrefix.Value = null;
    }
});

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

public static class LogSupport
{
    public static readonly AsyncLocal<string> LogNamePrefix = new AsyncLocal<string>();

    public static ILog GetLogger(string name)
    {
        return GetLoggerWithPrefixedName(name);
    }

    public static ILog GetLogger(Type type)
    {
        return GetLoggerWithPrefixedName(type.FullName);
    }

    private static ILog GetLoggerWithPrefixedName(string name)
    {
        if (!string.IsNullOrWhiteSpace(LogNamePrefix.Value))
        { name = $"{LogNamePrefix.Value}.{name}"; }

        return LogManager.GetLogger(typeof(LogSupport).Assembly, name);
    }

    ....

}

Теперь понятно, как получить экземпляр логгера в нашем контроллере:

[Route("api/[controller]")]
[ApiController]
public class ValuesController : ControllerBase
{
    private ILog _logger;

    private ILog Logger
    {
        get => _logger ?? (_logger = LogSupport.GetLogger(typeof(ValuesController)));
    }

    ....
}

Осталось сделать только одну вещь: как-то задать правила, по которым мы выбираем уровень логирования для каждого запроса. Это должен быть достаточно гибкий механизм. Основная идея заключается в использовании скриптинга C#. Я создам файл LogLevelRules.json, где определю набор пар “правило — уровень логирования”:

[
  {
    "logLevel": "Debug",
    "ruleCode": "context.Request.Path.Value == \"/api/values/1\""
  },
  {
    "logLevel": "Debug",
    "ruleCode": "context.Request.Path.Value == \"/api/values/3\""
  }
]

Здесь logLevel — желаемый уровень логирования, а ruleCode — код на C#, который возвращает булевское значение для заданного запроса. Приложение будет запускать коды правил один за другим. Первое правило, чей код вернет true, будет использовано для установки соответствующего уровня логирования. Если все правила вернули false, будет использован уровень по умолчанию.

Для создания делегатов из строкового представления правил, используется класс CSharpScript:

public class Globals
{
    public HttpContext context;
}

internal class LogLevelRulesCompiler
{
    public IReadOnlyList<LogLevelRule> Compile(IReadOnlyList<LogLevelRuleDescription> levelRuleDescriptions)
    {
        var result = new List<LogLevelRule>();

        foreach (var levelRuleDescription in levelRuleDescriptions ?? new LogLevelRuleDescription[0])
        {
            var script = CSharpScript.Create<bool>(levelRuleDescription.RuleCode, globalsType: typeof(Globals));
            ScriptRunner<bool> runner = script.CreateDelegate();

            result.Add(new LogLevelRule(levelRuleDescription.LogLevel, runner));
        }

        return result;
    }
}

internal sealed class LogLevelRule
{
    public string LogLevel { get; }

    public ScriptRunner<bool> Rule { get; }

    public LogLevelRule(string logLevel, ScriptRunner<bool> rule)
    {
        LogLevel = logLevel ?? throw new ArgumentNullException(nameof(logLevel));
        Rule = rule ?? throw new ArgumentNullException(nameof(rule));
    }
}

Здесь метод Compile получает список объектов, прочитанных из файла LogLevelRules.json. Он создает делегат runner для каждого правила.

Этот список делегатов может быть сохранен:

LogSupport.LogLevelSetters = new LogLevelRulesCompiler().Compile(
    new LogLevelRulesFileReader().ReadFile("LogLevelRules.json")
);

и использован в дальнейшем:

public static class LogSupport
{
    internal static IReadOnlyList<LogLevelRule> LogLevelSetters = new LogLevelRule[0];

    ...

    public static async Task<string> GetLogNamePrefix(HttpContext context)
    {
        var globals = new Globals
        {
            context = context
        };

        string result = null;

        foreach (var logLevelSetter in LogLevelSetters)
        {
            if (await logLevelSetter.Rule(globals))
            {
                result = $"EdlinSoftware.Log.{logLevelSetter.LogLevel}";
                break;
            }
        }

        return result;
    }
}

Таким образом, при запуске приложения мы читаем LogLevelRules.json, преобразуем его содержимое в список делегатов, используя класс CSharpScript, и сохраняем этот список в поле LogSupport.LogLevelSetters. Затем на каждый запрос мы выполняем делегаты из этого списка, чтобы получить уровень логирования.

Единственной вещью, которую осталось сделать, является отслеживание изменений в файле LogLevelRules.json. Если мы хотим установить уровень логирования для каких-то запросов, мы добавляем новое правило в этот файл. Чтобы заставить наше приложение применить эти изменения без перезапуска, необходимо следить за файлом:

var watcher = new FileSystemWatcher
{
    Path = Directory.GetCurrentDirectory(),
    Filter = "*.json",
    NotifyFilter = NotifyFilters.LastWrite
};
watcher.Changed += (sender, eventArgs) =>
{
    // Подождать, пока приложение, изменяющие файл, не освободит его.
    Thread.Sleep(1000);

    LogSupport.LogLevelSetters = new LogLevelRulesCompiler().Compile(
        new LogLevelRulesFileReader().ReadFile("LogLevelRules.json")
    );
};
watcher.EnableRaisingEvents = true;

Следует отметить, что ради краткости я опустил код потоковой синхронизации при работе с полем LogSupport.LogLevelSetters. Но на практике такая синхронизация обязательна.

Полный код приложения можно найти на GitHub.

Недостатки

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

1. Этот подход меняет имена логов. Так в хранилище логов вместо "MyClassLogger" будет храниться что-то типа "Edlinsoft.Log.Debug.MyClassLogger". С этим можно жить, но это не очень удобно. Возможно, проблему можно преодолеть, изменяя раскладку лога (log layout).

2. Теперь невозможно использовать статические экземпляры классов логгера, поскольку они должны создаваться отдельно для каждого запроса. Наиболее серьезной проблемой здесь, на мой взгляд, является то, что разработчики должны всегда об этом помнить. Кто-нибудь может случайно создать статическое поле с логгером и получить странные результаты. Преодолеть эту ситуацию можно созданием класса-обертки для логгеров вместо прямого использования классов log4net. Такая обертка может всегда создавать новые экземпляры логгеров log4net для каждой операции. В этом случае ее можно свободно использовать и в статических полях.

3. Описанный подход создает много экземпляров логгеров. На это тратится память и такты процессора как во время создания, так и во время сборки мусора. В зависимости от вашего приложения это может являться или не являться существенной проблемой.

4. Когда мы изменяем JSON-файл с правилами, код правил может содержать ошибки. Очень просто использовать блоки try-catch для того, чтобы эти ошибки не разрушили наше основное приложение. Тем не менее, мы как-то должны узнать, что что-то пошло не так. Есть два типа ошибок:

• Ошибки времени компиляции кода правил в делегаты.
• Ошибки времени выполнения этих делегатов.

Каким-то образом мы должны узнавать об этих ошибках, иначе наше логирование просто не будет работать, и мы даже не будем знать об этом.

5. Код правил в JSON-файле может в принципе содержать любые инструкции. Это потенциально может вести к проблемам с безопасностью. Нужно как-то ограничивать возможности этого кода. С другой стороны, если уж злоумышленник получил возможность прямой записи в файлы вашего приложения, то проблема с безопасностью и так налицо.

Заключение

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