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

https://ivanyakimov.blogspot.com/2019/01/log-level-per-request.html
  • Перевод
Читая 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-файле может в принципе содержать любые инструкции. Это потенциально может вести к проблемам с безопасностью. Нужно как-то ограничивать возможности этого кода. С другой стороны, если уж злоумышленник получил возможность прямой записи в файлы вашего приложения, то проблема с безопасностью и так налицо.

Заключение


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

Комментарии 7

    0
    фильтр логов?
      +1

      Возможно, вам было бы проще с NLog. В нем есть опция асинхронных контекстов — см. тут.


      Алгоритм действий:


      1. В начале обработки запроса необходимо инициализировать контекст.
      2. В конце — вызвать Dispose (то есть по сути — обычный using).
      3. В конфигурации — пропускать только те logging event, которые содержат свойство из контекста (у вас такое и сделано).

      Плюс моего подхода в том, что он позволяет фильтровать события даже из 3rd party библиотек.

        +1
        Да, согласен. Вместо изменения уровня логирования всего лога, можно прописывать специальные значения для некоторого свойства в асинхроном контексте, а в конфигурационном файле прописать несколько вариантов logger с разными фильтрами для разных значений этого свойства. Вы правы, это решит ряд проблем.
        0
        Вы не правильно понимаете, что такое уровни логирования. Так Logger.Trace() и Logger.Debug() пишут информацию для разработчиков; Logger.Info() — разовые операции, которые влияют на поведение системы (например: обновление конфига или загрузка плагина); Logger. Warning() – сигнализирует о потенциальных проблемах; Logger. Error () и Logger. Fatal() – детали ошибки.

        Обычно, в DEV-конфигурации для записи логов используется минимальный уровень события Trace, а для PROD – минимальным уровнем выставляется Info.

        Я бы переформулировал вашу задачу с «Должен существовать способ установить отдельный уровень логирования для каждого запроса.» на «Требуется логировать событий по переделённым критериям (в том числе, параметрам запроса)».

        Я не работал с log4net, но, например, в NLog или Serilog эти критерии и таргеты вывода можно декларативно прописать в конфигурационном файле.

        Для .Net Core, если логгер используется под оберткой ILogger из Microsoft.Extensions.Logging, то контекст логгера для можно создать методом Logger.BeginScope(…). В частности, реализовав middleware, в котором вызывается Logger.BeginScope(…) можно добавить нестандартные параметры во все события запроса и потом делать по ним фильтрацию.
          0
          Если на production установить причину проблемы можно только по записям с уровнем Info и серьезнее, то никакой надобности в изменении конфигурации логгеров нет. Но если этого не достаточно, и мы считаем, что записи уровней Trace и Debug могут нам помочь, то здесь нужно что-то делать.

          Да, вы правы, можно для этой цели использовать фильтрацию NLog, как предложили выше.
            0
            А что мешает в production написать что-то вроде такого:

            <nlog>
             <rules>
              <!-- Логируем события любого уровня от ValuesController -->
              <logger name="ValuesController" writeTo="traceFile" minlevel="Trace" />
              <!-- Детальные логи по ошибкам -->
              <logger name="*" writeTo="email,errorFile" minlevel="Warn" />
              <!-- Общие логи по работе системы -->
              <logger name="*" writeTo="commonFile" minlevel="Info" />
             </rules>
            </nlog>


            Для более сложных критериев можно воспользоваться фильтрами.

            Отмечу, что nlog не поддерживает декларативную конфигурацию в appsettings.json, только XML. Если все же хочется работать с конфигами в json, то рекомендую Serilog. Но суть будет примерно та же…
              0
              Ничего не мешает, если вы хотите видеть в логах записи и от «хороших», и от «плохих» запросов. Если же вам нужны только записи из «плохих» запросов, то их нужно как-то пометить. Тогда эти «метки» можно будет использовать в фильтрах логов.

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

        Самое читаемое