Frequentemente, você precisa escrever informações adicionais nos logs, o que pode esclarecer a situação e simplificar ainda mais a depuração do aplicativo. Por exemplo, se as informações de erro forem registradas, seria bom também salvar os dados de entrada de alguma forma, para que seja mais fácil reproduzir o problema. Aqui, quero descrever uma abordagem que permita coletar essas informações adicionais.
Declaração do problema
Suponha que tenhamos um serviço ASP.NET MVC We. Ele aceita solicitações POST contendo uma descrição do que precisa ser feito no formato JSON. Após analisar essa descrição, o serviço cria e executa várias consultas SQL no banco de dados. Ele então combina os resultados e os envia para o cliente.
Deve-se dizer que esse serviço faz uso extensivo de assincronia e multithreading por meio de async / waitit e Task .
Agora que entendemos com o que estamos lidando, vamos aos problemas.
Às vezes, nosso serviço apresenta erros. Os motivos podem ser diferentes: entrada incorreta de JSON, erros no código, problemas com o banco de dados ... Nesse caso, devemos escrever informações de erro no log.
Não há nenhum problema ao registrar a exceção em si. Podemos pegá-lo no método de ação do nosso controlador:
public class ServiceController : ApiController { [Route("api/service")] [HttpPost] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { try { ... } catch (Exception ex) { Logger.LogError(ex); throw; } } }
Ou podemos criar um atributo especializado para isso:
public class LogErrorAttribute : ActionFilterAttribute { public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext) { base.OnActionExecuted(actionExecutedContext); if (actionExecutedContext.Exception != null) { Logger.LogError(actionExecutedContext.Exception); } } }
e use-o no método de ação:
[Route("api/service")] [HttpPost] [LogError] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
Mas precisamos de mais. Para cada erro, queremos armazenar informações adicionais:
- O texto do corpo JSON da solicitação.
- O texto de todas as consultas SQL geradas.
Há mais um requisito. Essas informações adicionais devem ser registradas no log somente se ocorrer um erro. Caso contrário, não precisamos dele nos logs.
Fazer isso para o corpo da solicitação não é difícil:
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; } } }
Mas para consultas SQL, nem tudo é tão simples. O fato é que essas solicitações não são geradas pelo método de ação. Eles nem são gerados no controlador. Entre o método de ação e o método que gera SQL, há muitas chamadas para outros métodos de outras classes. Como extraímos os textos dessas solicitações quando precisamos delas?
Uma opção é usar uma lista de mensagens (por exemplo, List<string> ). Nós o criamos em nosso método de ação ( ServiceAction ) e o passamos para o método que gera SQL. Lá, adicionaremos os textos de consulta SQL a esta lista. Caso ocorra um erro, o método de ação terá uma lista de mensagens que precisam ser colocadas no log.
Este método tem uma desvantagem muito significativa, na minha opinião,. Teremos que passar nossa lista de mensagens por toda a cadeia de chamadas de métodos até alcançarmos o método que gera SQL. Isso significa que em muitos lugares essa lista de mensagens será necessária apenas para transmiti-la. Isso complica o código e eu tentaria evitá-lo.
Se você usa um contêiner de DI e pode criar suas classes a partir dele, pode tentar colocar a lista de mensagens no contêiner com uma vida útil "por solicitação". A classe de geração SQL aceitará essa lista de mensagens como um parâmetro construtor. Então, uma instância dessa classe e uma instância do controlador poderão acessar a mesma instância da lista de mensagens.
Mas existe uma maneira mais conveniente de coletar informações contextuais, mesmo se você não estiver usando um contêiner de DI. Seria bom se pudéssemos acessar a lista de mensagens através de uma propriedade estática:
public static async Task<SqlDataReader> RunReaderAsync(this SqlCommand cmd) { var message = $"SQL Server query is: {cmd.CommandText}"; ErrorContext.Current.AttachMessage(message); ... }
Há um problema sério aqui. Nosso serviço pode atender simultaneamente a vários pedidos. E cada solicitação desse tipo deve ter sua própria lista de mensagens. Além disso, ao processar uma única solicitação, nosso código pode gerar vários threads (por exemplo, usando async / waitit ). E todos esses threads devem ter acesso à mesma lista de mensagens. Como isso pode ser implementado?
A AsyncLocal<T> vem em nosso auxílio. Ele garante que, se você colocar algum valor em uma instância dessa classe em um thread, poderá obter esse valor nesse thread, bem como em todos os threads lançados a partir daqui. Ao mesmo tempo, todos os outros threads não terão acesso a esse valor.
Vejamos a implementação da classe 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(); } }
O método CreateNewErrorContext cria imediatamente uma nova lista de mensagens e a salva no campo CurrentErrorContext , que é do tipo AsyncLocal . Você pode acessar a lista atual em qualquer lugar do código usando a propriedade estática Current . O método AttachMessage adiciona uma nova mensagem à lista. Ele armazena mensagens em uma instância do ConcurrentBag , porque esse método pode ser chamado de vários threads ao mesmo tempo. O método GetMessages retorna todas as mensagens salvas, para que possam ser gravadas no log.
Agora você pode facilmente inicializar e usar o LogErrorAttribute dentro do 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); } } }
Em qualquer lugar do seu código, você pode adicionar sua mensagem ao contexto de erro atual da seguinte maneira:
ErrorContext.Current.AttachMessage(message);
Registro de desempenho
Às vezes, meu serviço é lento. Não é para todas as consultas, mas para algumas leva muito tempo para ser concluído. Gostaria de manter informações sobre essas solicitações para analisá-las posteriormente. Como isso pode ser implementado e quais informações precisamos?
Primeiro de tudo, preciso de um limite de tempo de execução. Se o processamento da solicitação demorar menos, tudo estará em ordem. Não gravarei nada no log nesse caso. Mas, se levar mais tempo, tenho que adicionar algumas informações ao log.
Quais informações eu preciso? Você definitivamente precisa saber quanto tempo levou o processamento da solicitação. Mas isso não basta. Meu serviço faz muitas coisas: verificar parâmetros de consulta, obter dados de outros serviços, criar consultas SQL e executá-las ... Preciso saber quanto tempo cada uma dessas partes levou para entender onde o problema está oculto.
Além disso, preciso das mesmas informações dos erros. Preciso de um corpo de solicitação para poder reproduzir o problema. Preciso dos textos das consultas SQL, caso demorem mais tempo.
Como isso pode ser alcançado? Novamente, usando a classe 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; } } }
Vamos ver como isso funciona. O método SetCurrentTimer cria um novo cronômetro. Aqui você pode especificar sua descrição e um limite de tempo de execução opcional.
Por que esse limite é opcional? Às vezes, preciso que parte do meu código seja executada não mais que uma certa quantidade de tempo. Assim, desejo que toda a solicitação de serviço seja processada em 3 segundos. Em outros casos, não quero impor restrições ao tempo de execução. Por exemplo, não me importa quanto tempo leva para executar minhas consultas SQL até que toda a solicitação de serviço seja processada em menos de 3 segundos. Por esse motivo, para alguns timers, é necessário definir um limite de tempo de execução, enquanto para outros não.
Dentro do método SetCurrentTimer , um novo timer é criado e colocado na variável CurrentTimer do tipo AsyncLocal . Mas isso não é tudo. Neste ponto, outro temporizador ativo já pode existir. Nesse caso, o novo timer que você acabou de criar se une ao existente. Isso permite criar temporizadores aninhados para medir o tempo de execução de todo o bloco de código e de suas partes:
using (Timer.SetCurrentTimer("The whole block")) { ... using (Timer.SetCurrentTimer("Part 1")) { ... } ... using (Timer.SetCurrentTimer("Part 2")) { ... } ... }
A propriedade Current fornece acesso ao cronômetro atual. Isso é útil se você quiser adicionar algumas mensagens:
var message = $"SQL Server query is: {cmd.CommandText}"; Timer.Current.AttachMessage(message);
Aqui, as mensagens anexadas e os cronômetros aninhados são armazenados nas instâncias do ConcurrentQueue , pois sua ordem pode ser importante.
A propriedade Message retorna as mensagens coletadas em uma única unidade da atual e de todos os cronômetros empilhados nela. Aqui eu uso as classes JSON da biblioteca JSON.NET para estruturar todas as mensagens. Mas, na verdade, não é tão importante. Você pode usar qualquer formato.
O método Log grava as informações armazenadas no timer no log, independentemente de o limite de tempo de execução ter sido definido ou não. Ao mesmo tempo, o método Dispose grava informações no log apenas se o limite de tempo de execução definido tiver sido excedido.
Agora podemos criar outro atributo para os métodos de nossos controladores:
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(); } }
e use-o em métodos de ação como este:
[Route("api/service")] [HttpPost] [TimerContext("For ServiceAction method", 3000)] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
Conclusão
Neste artigo, descrevi como é simples coletar informações de vários lugares no código e acessá-las posteriormente. Essa funcionalidade pode ser implementada usando propriedades e métodos estáticos que manipulam instâncias da classe AsyncLocal .
Espero que o artigo seja útil para melhorar o sistema de registro em seus aplicativos.