Сбор контекстной информации для логирования +10

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


Постановка задачи


Пусть у нас есть ASP.NET MVC We-сервис. Он принимает POST-запросы, содержащие описание того, что нужно сделать, в JSON-формате. После анализа такого описания, сервис создает и выполняет несколько SQL-запросов к базе данных. Затем он объединяет результаты и отсылает их клиенту.


Необходимо сказать, что этот сервис широко использует асинхронность и многопоточность через async/await и Task.


Теперь, когда мы понимаем, с чем имеем дело, перейдем к проблемам.


Сбор контекстной информации об ошибках


Иногда наш сервис выдает ошибки. Причины могут быть разными: неправильный JSON на входе, баги в коде, проблемы с базой данных,… В этом случае мы должны записать в лог информацию об ошибке.


Нет никаких проблем с логированием самого исключения. Мы можем отловить его в action-методе нашего контроллера:


public class ServiceController : ApiController
{
    [Route("api/service")]
    [HttpPost]
    public async Task<HttpResponseMessage> ServiceAction(
        [FromBody] RequestModel requestModel
    )
    {
        try
        {
            ...
        }
        catch (Exception ex)
        {
            Logger.LogError(ex);
            throw;
        }
    }
}

Или же мы можем создать для этого специализированный атрибут:


public class LogErrorAttribute : ActionFilterAttribute
{
    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);

        if (actionExecutedContext.Exception != null)
        {
            Logger.LogError(actionExecutedContext.Exception);
        }
    }
}

и использовать его на action-методе:


[Route("api/service")]
[HttpPost]
[LogError]
public async Task<HttpResponseMessage> ServiceAction(
    [FromBody] RequestModel requestModel
)
{
    ...
}

Но нам требуется большее. Для каждой ошибки мы хотим сохранять дополнительную информацию:


  • Текст JSON-тела запроса.
  • Текст всех сгенерированных SQL-запросов.

Есть и еще одно требование. Эта дополнительная информация должна записываться в лог только с случае возникновения ошибки. В противном случае в логах она нам не нужна.


Выполнить это для тела запроса не сложно:


public class ServiceController : ApiController
{
    [Route("api/service")]
    [HttpPost]
    public async Task<HttpResponseMessage> ServiceAction(
        [FromBody] RequestModel requestModel
    )
    {
        var requestText = await Request.Content.ReadAsStringAsync();

        try
        {
            ...
        }
        catch (Exception ex)
        {
            Logger.LogError(ex);
            Logger.LogError($"Request test is {requestText}");
            throw;
        }
    }
}

Но для SQL-запросов все не так просто. Дело в том, что эти запросы генерируются не action-методом. Они даже генерируются не в контроллере. Между action-методом и методом, генерирующим SQL, множество вызовов других методов других классов. Как же нам извлечь тексты этих запросов, когда они будут нам нужны?


Одним из вариантов является использование списка сообщений (например, List<string>). Мы создаем его в нашем action-методе (ServiceAction) и передаем его в метод, занимающийся генерацией SQL. Там мы добавим тексты SQL-запросов в этот список. В случае, если произошла ошибка, action-метод будет иметь у себя список сообщений, которые нужно поместить в лог.


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


Если вы используете DI контейнер и можете создавать ваши классы из него, то можно попробовать поместить список сообщений в контейнер с временем жизни “per request”. Класс, занимающийся генерацией SQL, будет принимать этот список сообщений в качестве параметра конструктора. Тогда и экземпляр данного класса и экземпляр контроллера смогут получить доступ к одному и тому же экземпляру списка сообщений.


Но существует более удобный способ сбора контекстной информации даже в том случае, если вы не используете DI контейнер. Было бы хорошо, если бы мы могли получать доступ к списку сообщений через статическое свойство:


public static async Task<SqlDataReader> RunReaderAsync(this SqlCommand cmd)
{
        var message = $"SQL Server query is: {cmd.CommandText}";
        ErrorContext.Current.AttachMessage(message);

        ...
}

Здесь есть серьезная проблема. Наш сервис может одновременно обслуживать несколько запросов. И каждый такой запрос должен иметь свой собственный список сообщений. Более того, при обработке одного запроса наш код может порождать несколько потоков (например, с помощью async/await). И все эти потоки должны иметь доступ к одному и тому же списку сообщений. Как это можно реализовать?


Нам на помощь приходит класс AsyncLocal<T>. Он гарантирует, что если вы положите некоторое значение в экземпляр этого класса в одном потоке, то вы сможете получить это значение в данном потоке, а также во всех потоках, запущенных из данного начиная с этого момента. В то же время все другие потоки не будут иметь доступа к этому значению.


Давайте посмотрим на реализацию класса ErrorContext:


public class ErrorContext
{
    private static readonly object Lock = new object();
    private static readonly AsyncLocal<ErrorContext> CurrentErrorContext = new AsyncLocal<ErrorContext>();

    private readonly Lazy<ConcurrentBag<string>> _attachedMessages = new Lazy<ConcurrentBag<string>>(() => new ConcurrentBag<string>());

    private ErrorContext()
    {}

    public static ErrorContext Current
    {
        get
        {
            lock (Lock)
            {
                var errorContext = CurrentErrorContext.Value;
                if (errorContext == null)
                {
                    CurrentErrorContext.Value = errorContext = new ErrorContext();
                }
                return errorContext;
            }
        }
    }

    public static ErrorContext CreateNewErrorContext()
    {
        lock (Lock)
        {
            var errorContext = new ErrorContext();
            CurrentErrorContext.Value = errorContext;
            return errorContext;
        }
    }

    public void AttachMessage(string message)
    {
        if (!string.IsNullOrWhiteSpace(message))
        {
            _attachedMessages.Value.Add(message);
        }
    }

    public IReadOnlyList<string> GetMessages()
    {
        return _attachedMessages.Value.ToArray();
    }

}

Метод CreateNewErrorContext немедленно создает новый список сообщений и сохраняет его в поле CurrentErrorContext, имеющем тип AsyncLocal. Вы можете получить доступ к текущему списку в любом месте кода с помощью статического свойства Current. Метод AttachMessage добавляет новое сообщение в список. Он сохраняет сообщения в экземпляре ConcurrentBag, поскольку этот метод может одновременно вызываться из нескольких потоков. Метод GetMessages возвращает все сохраненные сообщений, так что их можно записать в лог.


Теперь можно легко инициализировать и использовать ErrorContext внутри LogErrorAttribute:


public class LogErrorAttribute : ActionFilterAttribute
{
    public override void OnActionExecuting(HttpActionContext actionContext)
    {
        ErrorContext.CreateNewErrorContext();

        base.OnActionExecuting(actionContext);
    }

    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);

        if (actionExecutedContext.Exception != null)
        {
            foreach(var message in ErrorContext.Current.GetMessages())
            {
                  Logger.LogError(message);
            }
            Logger.LogError(actionExecutedContext.Exception);
        }
    }
}

В любом месте вашего кода можно добавить свое сообщение в текущие контекст ошибки следующим образом:


ErrorContext.Current.AttachMessage(message);

Логирование проблем с производительностью


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


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


Какая информация мне нужна? Определенно нужно знать, сколько времени заняла обработка запроса. Но этого не достаточно. Мой сервис делает множество вещей: проверку параметров запроса, получение данных из других сервисов, построение SQL-запросов и их выполнение, … Мне нужно знать, сколько времени заняла каждая такая часть, чтобы понять, где скрыта проблема.


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


Как этого можно добиться? Опять же, с помощью класса AsyncLocal:


public class Timer : IDisposable
{
    private static readonly object Lock = new object();
    private static readonly AsyncLocal<Timer> CurrentTimer = new AsyncLocal<Timer>();

    private readonly Stopwatch _stopwatch = new Stopwatch();
    private readonly Lazy<ConcurrentQueue<Timer>> _attachedTimers = new Lazy<ConcurrentQueue<Timer>>(() => new ConcurrentQueue<Timer>());
    private readonly Lazy<ConcurrentQueue<string>> _attachedMessages = new Lazy<ConcurrentQueue<string>>(() => new ConcurrentQueue<string>());
    private readonly string _description;
    private readonly TimeSpan? _threshold;
    private readonly Timer _previousCurrent;

    private bool _isDisposed;
    private bool _suspendLogging;

    private Timer(Timer previousCurrent, string description = null, TimeSpan? threshold = null)
    {
        _previousCurrent = previousCurrent;
        _description = description;
        _threshold = threshold;
        _stopwatch.Start();
    }

    public static Timer Current
    {
        get
        {
            lock (Lock)
            {
                var timer = CurrentTimer.Value;
                if (timer == null)
                {
                    CurrentTimer.Value = timer = new Timer(null);
                }
                return timer;
            }
        }
    }

    public static Timer SetCurrentTimer(string description, TimeSpan? threshold = null)
    {
        lock (Lock)
        {
            var currentTimer = CurrentTimer.Value;

            var timer = new Timer(currentTimer, description, threshold);

            CurrentTimer.Value = timer;

            currentTimer?._attachedTimers.Value.Enqueue(timer);

            return timer;
        }
    }

    public void AttachMessage(string message)
    {
        if (!string.IsNullOrWhiteSpace(message))
        {
            _attachedMessages.Value.Enqueue(message);
        }
    }

    public void Dispose()
    {
        if (!_isDisposed)
        {
            _isDisposed = true;

            _stopwatch.Stop();

            if (_attachedTimers.IsValueCreated)
            {
                foreach (var attachedTimer in _attachedTimers.Value)
                {
                    attachedTimer.Dispose();
                }
            }

            if (!_suspendLogging && _threshold.HasValue && _stopwatch.Elapsed > _threshold.Value)
            {
                Log();
            }

            if (_previousCurrent != null)
            {
                CurrentTimer.Value = _previousCurrent;
            }
        }
    }

    private JObject Message
    {
        get
        {
            Dispose();

            var message = new StringBuilder($"It took {_stopwatch.ElapsedMilliseconds} ms to execute {_description}.");

            if (_threshold.HasValue)
            {
                message.Append($" Duration threshold is {_threshold.Value.TotalMilliseconds} ms.");
            }

            var messageObj = new JObject
            {
                ["message"] = message.ToString(),
            };

            if (_attachedTimers.IsValueCreated && _attachedTimers.Value.Any())
            {
                messageObj["attachedTimers"] = new JArray(_attachedTimers.Value.Select(t => t.Message));
            }

            if (_attachedMessages.IsValueCreated && _attachedMessages.Value.Any())
            {
                messageObj["attachedMessages"] = new JArray(_attachedMessages.Value);
            }

            return messageObj;
        }
    }

    public void Log()
    {
        try
        {
            _suspendLogging = true;

            Dispose();

            if (_stopwatch.Elapsed < _threshold)
            {
                Logger.LogDebug(Message.ToString());
            }
            else
            {
                Logger.LogWarning(Message.ToString());
            }
        }
        finally
        {
            _suspendLogging = false;
        }
    }
}

Давайте посмотрим, как это работает. Метод SetCurrentTimer создает новый таймер. Здесь можно задать его описание и необязательный порог времени выполнения.


Почему этот порог не обязателен? Иногда мне требуется, чтобы часть моего кода выполнялась не дольше определенного времени. Так я могу желать, чтобы весь запрос к сервису обрабатывался за 3 секунды. В других случаях я не хочу накладывать ограничения на время выполнения. Например, мне не важно сколько занимает выполнение моих SQL-запросов до тех пор, пока весь запрос к сервису обрабатывается менее чем за 3 секунды. По этой причине для некоторых таймеров нужно устанавливать порог времени выполнения, тогда как для других — нет.


Внутри метода SetCurrentTimer создается новый таймер и кладется в переменную CurrentTimer типа AsyncLocal. Но это еще не все. В этот момент может уже существовать другой активный таймер. В этом случае новый только что созданный таймер присоединяется к уже существующему. Это позволяет создавать вложенные таймеры, чтобы измерять время выполнения как всего блока кода, так и его частей:


using (Timer.SetCurrentTimer("The whole block"))
{
    ...

    using (Timer.SetCurrentTimer("Part 1"))
    {
        ... 
    }

    ...

    using (Timer.SetCurrentTimer("Part 2"))
    {
        ... 
    }

    ...
}

Свойство Current дает доступ к текущему таймеру. Это полезно, если вы хотите добавить к нему некоторые сообщения:


var message = $"SQL Server query is: {cmd.CommandText}";
Timer.Current.AttachMessage(message);

Здесь присоединенные сообщения и вложенные таймеры хранятся в экземплярах ConcurrentQueue, поскольку порядок их следования может быть важен.


Свойство Message возвращает собранные в единое целое сообщения от текущего и всех сложенных в него таймеров. Здесь я использую JSON-классы из библиотеки JSON.NET для структурирования всех сообщений. Но на самом деле это не так важно. Можно использовать любой формат.


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


Теперь можно создать еще один атрибут для методов наших контроллеров:


public class TimerContextAttribute : ActionFilterAttribute
{
    private readonly string _timerDescription;
    private readonly int _durationThresholdMs;
    private readonly AsyncLocal<Timer> _timer = new AsyncLocal<Timer>();

    public TimerContextAttribute(string timerDescription, int durationThresholdMs)
    {
        if (string.IsNullOrWhiteSpace(timerDescription)) throw new ArgumentNullException(nameof(timerDescription));
        _timerDescription = timerDescription;
        _durationThresholdMs = durationThresholdMs;
    }

    public override void OnActionExecuting(HttpActionContext actionContext)
    {
        _timer.Value = Timer.SetCurrentTimer(_timerDescription,
            TimeSpan.FromMilliseconds(_durationThresholdMs));

        base.OnActionExecuting(actionContext);
    }

    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);

        _timer.Value?.Dispose();

    }
}

и использовать его на action-методах так:


[Route("api/service")]
[HttpPost]
[TimerContext("For ServiceAction method", 3000)]
public async Task<HttpResponseMessage> ServiceAction(
    [FromBody] RequestModel requestModel
)
{
    ...
}

Заключение


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


Надеюсь, материал статьи будет полезен для улучшения системы логирования в ваших приложениях.

Вы можете помочь и перевести немного средств на развитие сайта



Комментарии (9):

  1. naa
    /#18870983

    А какой смысл там в lock'ах и ConcurrentBag'е? Если используется только async/await и потоки не создаются «руками», то как раз AsyncLocal.Value исключает конкурентный доступ в рамках одной цепочки задач (Task'ов).

    • iakimov
      /#18871013

      На самом деле сервис может одновременно запустить несколько потоков и ожидать их завершения с помощью Task.WhenAll. В этом случае несколько потоков могут обращаться к одному и тому же экземпляру таймера или ErrorContext. Поэтому необходимость в ConcurrentBag есть.

      Действительно ли так нужен lock — вопрос. На всякий случай я добавил его.

      • naa
        /#18871073

        Если речь про одновременные запросы в разных потоках, то они будут запущены все равно в рамках разных задач (Task) и контекст синхронизации будет разный и у каждой задачи опять будет свой AsyncLocal.Value.
        Инстанст ConcurrentBag он свой на каждый запрос, а внутри async/await не может быть одновременно несколько рабочих потоков, которые будут конкурировать за ConcurrentBag. Даже если после await продолжение задачи (Task) попадет на другой поток из пула, она будет выполнена последовательно относительно других задач.

        • iakimov
          /#18875251

          Речь идет о создании разных потоков в рамках одного запроса к сервису. Что-то типа:

          ErrorContext.CreateNewErrorContext();
          
          Task[] tasks = Enumerable.Range(1, 10).Select(i => Task.Factory.StartNew(() =>
          {
              // do something
          
              ErrorContext.Current.AttachMessage("message");
          
              // do another thing
          })).ToArray();
          
          await Task.WhenAll(tasks);
          


          В этом случае все запущенные задачи будут одновременно обращаться к одному и тому же экземпляру ErrorContext.

          Если же все такие задачи последовательно ждутся с помощью await, то доступ к экземпляру ErrorContext будет действительно последовательный, а не одновременный:

          ErrorContext.CreateNewErrorContext();
          
          await Task.Factory.StartNew(() =>
          {
              // do something
          
              ErrorContext.Current.AttachMessage("message");
          
              // do another thing
          });
          
          await Task.Factory.StartNew(() =>
          {
              // do something
          
              ErrorContext.Current.AttachMessage("message");
          
              // do another thing
          });
          
          // waiting for other tasks
          

          • naa
            /#18875541

            А в пером примере не будет разве для каждой созданной задачи свой AsyncLocal.Value? Вот такой пример

            static AsyncLocal<long> asyncCounter = new AsyncLocal<long>();
            
            static void Main(string[] args)
            {
                Task[] tasks = Enumerable.Range(1, 10).Select(i => Task.Factory.StartNew(() =>
                {
                    asyncCounter.Value++;
                })).ToArray();
            
                Task.WhenAll(tasks).GetAwaiter().GetResult();
            
                Console.WriteLine(asyncCounter.Value);
            }
            


            ожидаем выведет на консоль 0

            • AlexZyl
              /#18877033

              It depends.

              AsyncLocal-данные хранятся в словаре _localValues ExecutionContext-а. Т.к. при создании таски через StartNew происходит захват контекста, то «дочерний» контекст получает все данные «родительского». А так как автор использует обертку для данных в виде ErrorContext, то два ExecutionContext-а шарят референс на инстанс ErrorContext-а. Так что ConcurrentBag вполне уместен.

              В вашем примере, значение остается нулевым, т.к. референс на parentEc._localValues != childEc._localValues, а значит, что при инкременте замена объекта в _localValues внутри созданной таски происходит только для childEc._localValues.

              А вот почему ссылки словарей различаются я пока не понял. Словно производится копирование содержимого родительского _localValues в дочерний, хотя по коду ExecutionContext.Capture копирует лишь ссылку на словарь.

            • AlexZyl
              /#18877133

              Пример кода:

              public class CounterContext
              {
                  public long AsyncCounter;
              }
              
              static AsyncLocal<CounterContext> CounterContext = new AsyncLocal<CounterContext>();
              
              static void Main(string[] args)
              {
                  CounterContext.Value = new CounterContext();
                  Task[] tasks = Enumerable.Range(1, 1000).Select(i => Task.Factory.StartNew(() =>
                  {
                      CounterContext.Value.AsyncCounter++;
                  })).ToArray();
              
                  Task.WhenAll(tasks).GetAwaiter().GetResult();
              
                  Console.WriteLine(CounterContext.Value.AsyncCounter);
              }
              


              Выведет 997-1000 из-за конкурентного доступа

  2. AlexZyl
    /#18871023

    Что-то подсказывает, что такая инициализация контекста в фильтре может ударить по перфомансу при нагрузке.
    Не лучше ли вынести этот код в какой-нибудь ErrorContextInitializationMiddleware и зарегистрировать на PreHandlerExecute стэйдж? Тогда синхронизации доступа к Current контексту не понадобится, а логирование вынести в кастомный IExceptionLogger (раз уж речь в статье идет о ASP.NET WebAPI)

    • iakimov
      /#18871031

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