A menudo necesita escribir información adicional en los registros, lo que puede aclarar la situación y simplificar aún más la depuración de la aplicación. Por ejemplo, si se registra información de error, sería bueno guardar también los datos de entrada de alguna forma, para que sea más fácil reproducir el problema. Aquí quiero describir un enfoque que le permite recopilar esta información adicional.
Declaración del problema.
Supongamos que tenemos un ASP.NET MVC We service. Acepta solicitudes POST que contienen una descripción de lo que debe hacerse en formato JSON. Después de analizar dicha descripción, el servicio crea y ejecuta varias consultas SQL a la base de datos. Luego combina los resultados y los envía al cliente.
Hay que decir que este servicio hace un uso extensivo de asincronía y subprocesamiento múltiple a través de async / await y Task .
Ahora que entendemos a qué nos enfrentamos, pasemos a los problemas.
A veces nuestro servicio da errores. Los motivos pueden ser diferentes: entrada JSON incorrecta, errores en el código, problemas con la base de datos ... En este caso, deberíamos escribir información de error en el registro.
No hay problema para registrar la excepción en sí. Podemos atraparlo en el método de acción de nuestro 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; } } }
O podemos crear un atributo especializado para esto:
public class LogErrorAttribute : ActionFilterAttribute { public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext) { base.OnActionExecuted(actionExecutedContext); if (actionExecutedContext.Exception != null) { Logger.LogError(actionExecutedContext.Exception); } } }
y úsalo en el método de acción:
[Route("api/service")] [HttpPost] [LogError] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
Pero necesitamos más. Para cada error, queremos almacenar información adicional:
- El texto del cuerpo JSON de la solicitud.
- El texto de todas las consultas SQL generadas.
Hay un requisito más. Esta información adicional debe registrarse en el registro solo si se produce un error. De lo contrario, no lo necesitamos en los registros.
Hacer esto para el cuerpo de la solicitud no es 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; } } }
Pero para las consultas SQL, no todo es tan simple. El hecho es que estas solicitudes no son generadas por el método de acción. Ni siquiera se generan en el controlador. Entre el método de acción y el método de generación de SQL, hay muchas llamadas a otros métodos de otras clases. ¿Cómo extraemos los textos de estas solicitudes cuando las necesitamos?
Una opción es usar una lista de mensajes (por ejemplo, List<string> ). Lo creamos en nuestro método de acción ( ServiceAction ) y lo pasamos al método que genera SQL. Allí agregaremos los textos de consulta SQL a esta lista. En caso de que ocurra un error, el método de acción tendrá una lista de mensajes que deben colocarse en el registro.
Este método tiene un inconveniente muy significativo, en mi opinión. Tendremos que pasar nuestra lista de mensajes a lo largo de toda la cadena de llamadas a métodos hasta llegar al método que genera SQL. Esto significa que en muchos lugares esta lista de mensajes será necesaria solo para transmitirla. Esto complica el código, y trataría de evitarlo.
Si utiliza un contenedor DI y puede crear sus clases a partir de él, puede intentar colocar la lista de mensajes en el contenedor con una vida útil "por solicitud". La clase de generación SQL aceptará esta lista de mensajes como un parámetro constructor. Entonces, tanto una instancia de esta clase como una instancia del controlador podrán acceder a la misma instancia de la lista de mensajes.
Pero hay una forma más conveniente de recopilar información contextual, incluso si no está utilizando un contenedor DI. Sería bueno si pudiéramos acceder a la lista de mensajes a través de una propiedad estática:
public static async Task<SqlDataReader> RunReaderAsync(this SqlCommand cmd) { var message = $"SQL Server query is: {cmd.CommandText}"; ErrorContext.Current.AttachMessage(message); ... }
Hay un problema serio aquí. Nuestro servicio puede atender simultáneamente varias solicitudes. Y cada solicitud debe tener su propia lista de mensajes. Además, al procesar una sola solicitud, nuestro código puede generar varios hilos (por ejemplo, usando async / wait ). Y todos estos hilos deben tener acceso a la misma lista de mensajes. ¿Cómo se puede implementar esto?
La AsyncLocal<T> viene en nuestra ayuda. Garantiza que si coloca algún valor en una instancia de esta clase en un hilo, puede obtener este valor en este hilo, así como en todos los hilos lanzados desde este en adelante. Al mismo tiempo, todos los otros hilos no tendrán acceso a este valor.
Veamos la implementación de la clase 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(); } }
El método CreateNewErrorContext crea inmediatamente una nueva lista de mensajes y la guarda en el campo CurrentErrorContext , que es del tipo AsyncLocal . Puede acceder a la lista actual en cualquier parte del código utilizando la propiedad estática Current . El método AttachMessage agrega un nuevo mensaje a la lista. Almacena mensajes en una instancia de ConcurrentBag , porque este método se puede llamar desde varios subprocesos al mismo tiempo. El método GetMessages devuelve todos los mensajes guardados, para que puedan escribirse en el registro.
Ahora puede inicializar y usar ErrorContext dentro de 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); } } }
En cualquier parte de su código, puede agregar su mensaje al contexto de error actual de la siguiente manera:
ErrorContext.Current.AttachMessage(message);
Registro de rendimiento
A veces mi servicio es lento. No para todas las consultas, pero para algunas lleva demasiado tiempo completarlas. Me gustaría conservar información sobre tales solicitudes para analizarla más adelante. ¿Cómo se puede implementar esto y qué información necesitamos?
En primer lugar, necesito un umbral de tiempo de ejecución. Si procesar la solicitud lleva menos tiempo, entonces todo está en orden. No escribiré nada en el registro en este caso. Pero si lleva más tiempo, tengo que agregar información al registro.
¿Qué información necesito? Definitivamente necesita saber cuánto tiempo llevó el procesamiento de la solicitud. Pero eso no es suficiente. Mi servicio hace muchas cosas: verificar parámetros de consulta, obtener datos de otros servicios, crear consultas SQL y ejecutarlas ... Necesito saber cuánto tiempo tomó cada parte para comprender dónde está oculto el problema.
Además, necesito la misma información que para los errores. Necesito un cuerpo de solicitud para poder reproducir el problema. Necesito los textos de las consultas SQL en caso de que tarden más tiempo.
¿Cómo se puede lograr esto? Nuevamente, usando la clase 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; } } }
Veamos como funciona. El método SetCurrentTimer crea un nuevo temporizador. Aquí puede especificar su descripción y un umbral de tiempo de ejecución opcional.
¿Por qué es opcional este umbral? A veces necesito parte de mi código para ejecutar no más de una cierta cantidad de tiempo. Por lo tanto, puedo desear que toda la solicitud de servicio se procese en 3 segundos. En otros casos, no quiero imponer restricciones al tiempo de ejecución. Por ejemplo, no me importa cuánto tiempo lleve ejecutar mis consultas SQL hasta que toda la solicitud de servicio se procese en menos de 3 segundos. Por esta razón, para algunos temporizadores, debe establecer un umbral de tiempo de ejecución, mientras que para otros, no.
Dentro del método SetCurrentTimer , se crea un nuevo temporizador y se coloca en la variable CurrentTimer del tipo AsyncLocal . Pero eso no es todo. En este punto, puede existir otro temporizador activo. En este caso, el nuevo temporizador que acaba de crear se une al existente. Esto le permite crear temporizadores anidados para medir el tiempo de ejecución de todo el bloque de código y sus partes:
using (Timer.SetCurrentTimer("The whole block")) { ... using (Timer.SetCurrentTimer("Part 1")) { ... } ... using (Timer.SetCurrentTimer("Part 2")) { ... } ... }
La propiedad Current da acceso al temporizador actual. Esto es útil si desea agregarle algunos mensajes:
var message = $"SQL Server query is: {cmd.CommandText}"; Timer.Current.AttachMessage(message);
Aquí, los mensajes adjuntos y los temporizadores anidados se almacenan en instancias de ConcurrentQueue , ya que su orden puede ser importante.
La propiedad Message devuelve mensajes recopilados en una sola unidad del actual y todos los temporizadores apilados en él. Aquí uso las clases JSON de la biblioteca JSON.NET para estructurar todos los mensajes. Pero en realidad no es tan importante. Puedes usar cualquier formato.
El método de Log escribe información almacenada en el temporizador en el registro, independientemente de si el umbral de tiempo de ejecución se ha establecido o no. Al mismo tiempo, el método Dispose escribe información en el registro solo si se ha excedido el umbral de tiempo de ejecución establecido.
Ahora podemos crear otro atributo para los métodos de nuestros 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(); } }
y úsalo en métodos de acción como este:
[Route("api/service")] [HttpPost] [TimerContext("For ServiceAction method", 3000)] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
Conclusión
En este artículo, describí lo simple que es recopilar información de muchos lugares en el código y acceder a ella más tarde. Dicha funcionalidad se puede implementar utilizando propiedades estáticas y métodos que manipulan instancias de la clase AsyncLocal .
Espero que el artículo sea útil para mejorar el sistema de registro en sus aplicaciones.