[Перевод] Сбор контекстной информации для логирования
Зачастую требуется записывать в логи дополнительную информацию, которая может прояснить ситуацию и в дальнейшем упростить отладку приложения. Например, если логируется информация об ошибке, неплохо было бы также сохранить в некоторой форме и входные данные, чтобы было проще воспроизвести проблему. Здесь я хочу описать подход, позволяющий собрать эту дополнительную информацию.
Постановка задачи
Пусть у нас есть ASP.NET MVC We-сервис. Он принимает POST-запросы, содержащие описание того, что нужно сделать, в JSON-формате. После анализа такого описания, сервис создает и выполняет несколько SQL-запросов к базе данных. Затем он объединяет результаты и отсылает их клиенту.
Необходимо сказать, что этот сервис широко использует асинхронность и многопоточность через async/await и Task.
Теперь, когда мы понимаем, с чем имеем дело, перейдем к проблемам.
Сбор контекстной информации об ошибках
Иногда наш сервис выдает ошибки. Причины могут быть разными: неправильный JSON на входе, баги в коде, проблемы с базой данных, … В этом случае мы должны записать в лог информацию об ошибке.
Нет никаких проблем с логированием самого исключения. Мы можем отловить его в action-методе нашего контроллера:
public class ServiceController : ApiController
{
[Route("api/service")]
[HttpPost]
public async Task 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 ServiceAction(
[FromBody] RequestModel requestModel
)
{
...
}
Но нам требуется большее. Для каждой ошибки мы хотим сохранять дополнительную информацию:
- Текст JSON-тела запроса.
- Текст всех сгенерированных SQL-запросов.
Есть и еще одно требование. Эта дополнительная информация должна записываться в лог только с случае возникновения ошибки. В противном случае в логах она нам не нужна.
Выполнить это для тела запроса не сложно:
public class ServiceController : ApiController
{
[Route("api/service")]
[HttpPost]
public async Task 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). Мы создаем его в нашем action-методе (ServiceAction) и передаем его в метод, занимающийся генерацией SQL. Там мы добавим тексты SQL-запросов в этот список. В случае, если произошла ошибка, action-метод будет иметь у себя список сообщений, которые нужно поместить в лог.
У этого метода есть очень существенный, на мой взгляд, недостаток. Нам придется передавать наш список сообщений по всей цепочке вызовов методов до тех пор, пока мы не достигнем метода, генерирующего SQL. Это означает, что во многих местах этот список сообщений будет нужен только для того, чтобы передать его дальше. Это усложняет код, и я постарался бы избежать этого.
Если вы используете DI контейнер и можете создавать ваши классы из него, то можно попробовать поместить список сообщений в контейнер с временем жизни «per request». Класс, занимающийся генерацией SQL, будет принимать этот список сообщений в качестве параметра конструктора. Тогда и экземпляр данного класса и экземпляр контроллера смогут получить доступ к одному и тому же экземпляру списка сообщений.
Но существует более удобный способ сбора контекстной информации даже в том случае, если вы не используете DI контейнер. Было бы хорошо, если бы мы могли получать доступ к списку сообщений через статическое свойство:
public static async Task RunReaderAsync(this SqlCommand cmd)
{
var message = $"SQL Server query is: {cmd.CommandText}";
ErrorContext.Current.AttachMessage(message);
...
}
Здесь есть серьезная проблема. Наш сервис может одновременно обслуживать несколько запросов. И каждый такой запрос должен иметь свой собственный список сообщений. Более того, при обработке одного запроса наш код может порождать несколько потоков (например, с помощью async/await). И все эти потоки должны иметь доступ к одному и тому же списку сообщений. Как это можно реализовать?
Нам на помощь приходит класс AsyncLocal. Он гарантирует, что если вы положите некоторое значение в экземпляр этого класса в одном потоке, то вы сможете получить это значение в данном потоке, а также во всех потоках, запущенных из данного начиная с этого момента. В то же время все другие потоки не будут иметь доступа к этому значению.
Давайте посмотрим на реализацию класса ErrorContext:
public class ErrorContext
{
private static readonly object Lock = new object();
private static readonly AsyncLocal CurrentErrorContext = new AsyncLocal();
private readonly Lazy> _attachedMessages = new Lazy>(() => new ConcurrentBag());
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 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 CurrentTimer = new AsyncLocal();
private readonly Stopwatch _stopwatch = new Stopwatch();
private readonly Lazy> _attachedTimers = new Lazy>(() => new ConcurrentQueue());
private readonly Lazy> _attachedMessages = new Lazy>(() => new ConcurrentQueue());
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 = new AsyncLocal();
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 ServiceAction(
[FromBody] RequestModel requestModel
)
{
...
}
Заключение
В этой статье я описал, как достаточно просто собирать информацию из многих мест в коде и получить к ней доступ позже. Такая функциональность может быть реализована с помощью статических свойств и методов, которые манипулируют экземплярами класса AsyncLocal.
Надеюсь, материал статьи будет полезен для улучшения системы логирования в ваших приложениях.
