Una inmersión más profunda en el enriquecimiento de registros

En este artículo, concluiremos revisando cómo las preocupaciones y el código de registro se pueden separar y desacoplar de la infraestructura y el código comercial. En el artículo anterior , revisamos cómo usar DiagnosticSource y DiagnosticListener para lograrlo en operaciones de infraestructura.

Ahora, revisaremos cómo enriquecer los datos registrados con contexto adicional.

Básicamente, el concepto de enriquecer los datos registrados gira en torno al registro de contexto o datos adicionales que deben ir junto con los mensajes de registro. Este contexto puede ser cualquier cosa, desde una simple cadena hasta un objeto complejo, y se produce o se conoce en algún momento dentro de la infraestructura o el código comercial, no en el momento en que se escriben los mensajes de registro.

Por lo tanto, no podemos simplemente agregar otra propiedad para registrar mensajes, ya que este código no produce ningún resultado de registro, o queremos que el contexto se adjunte a múltiples mensajes de registro que pueden producirse o no en la cadena de ejecución.

Este contexto puede ser incluso condicional, como agregar datos específicos solo a los mensajes de registro de errores mientras que el resto de mensajes no los necesitan.

Usaremos Serilog y su función de enriquecimiento, ya que Serilog lo hizo muy flexible y poderoso. Otras soluciones también tienen características similares en diferentes niveles de madurez, y compararemos el enriquecimiento de Serilog con lo que Microsoft.Extensions.Logging proporciona de fábrica.

Una descripción general de los enriquecedores de registros existentes para Serilog

Serilog viene con muchos enriquecedores útiles que pueden resultar muy útiles para algunos escenarios. Puede visitar esta página, https://github.com/serilog/serilog/wiki/Enrichment , para ver la lista completa de enriquecedores y sus descripciones.

Por ejemplo, existen enriquecedores LogContext y GlobalLogContext que permiten enviar datos adicionales para que se registren con los mensajes de registro si se escriben dentro de un alcance coincidente.

El enriquecimiento de LogContext es muy similar al concepto de ámbitos de registro en Microsoft.Extensions.Logging. Esencialmente, ambos envían algunos datos personalizados y proporcionan un objeto IDisposable que debe eliminarse para eliminar los datos del contexto de registro.

Es decir, siempre que el objeto IDisposable esté dentro del alcance, los datos se adjuntarán a todos los mensajes de registro escritos dentro de ese alcance. Cuando se elimine, los datos ya no se adjuntarán.

La documentación de Serilog y Microsoft proporciona estos ejemplos:

 // For Serilog log.Information("No contextual properties"); using (LogContext.PushProperty("A", 1)) { log.Information("Carries property A = 1"); using (LogContext.PushProperty("A", 2)) using (LogContext.PushProperty("B", 1)) { log.Information("Carries A = 2 and B = 1"); } log.Information("Carries property A = 1, again"); } // For Microsoft.Extensions.Logging scopes using (logger.BeginScope(new List<KeyValuePair<string, object>> { new KeyValuePair<string, object>("TransactionId", transactionId), })) { _logger.LogInformation(MyLogEvents.GetItem, "Getting item {Id}", id); todoItem = await _context.TodoItems.FindAsync(id); if (todoItem == null) { _logger.LogWarning(MyLogEvents.GetItemNotFound, "Get({Id}) NOT FOUND", id); return NotFound(); } }

Si bien son útiles para algunos escenarios, son bastante limitados. El mejor uso para este tipo de enriquecimiento de registros es en implementaciones de tipo middleware o decorador, donde el alcance está bien definido y los datos se conocen en el momento de la creación del alcance, y estamos seguros de que los datos no tienen valor fuera del alcance.

Por ejemplo, podemos usarlo para adjuntar un ID de correlación a todos los mensajes de registro dentro de un único alcance de procesamiento de solicitudes HTTP.

El enriquecido GlobalLogContext es similar a LogContext, pero es global: envía los datos a todos los mensajes de registro escritos dentro de una aplicación. Sin embargo, los casos de uso reales de este tipo de enriquecimiento son muy limitados.

Muestra de enriquecedor de registros personalizado para Serilog

De hecho, implementar enriquecedores de registros personalizados para Serilog es muy fácil: simplemente implemente la interfaz ILogEventEnricher y registre el enriquecedor con la configuración del registrador. La interfaz solo tiene un método para implementar, Enrich , que acepta el evento de registro y lo enriquece con los datos que desea.

Revisemos una implementación de muestra para un enriquecedor de registros personalizado.

 public sealed class CustomLogEnricher : ILogEventEnricher { private readonly IHttpContextAccessor contextAccessor; public CustomLogEnricher(IHttpContextAccessor contextAccessor) { this.contextAccessor = contextAccessor; } public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) { var source = contextAccessor.HttpContext?.RequestServices.GetService<ICustomLogEnricherSource>(); if (source is null) { return; } var loggedProperties = source.GetCustomProperties(logEvent.Level); foreach (var item in loggedProperties) { var property = item.ProduceProperty(propertyFactory); logEvent.AddOrUpdateProperty(property); } } }

Como vemos, este enriquecedor se basa en ICustomLogEnricherSource para obtener las propiedades personalizadas con las que enriquecer el evento de registro. Normalmente, los enriquecedores de registros son instancias de larga duración e incluso siguen el patrón Singleton: se registran una vez al iniciar la aplicación y viven durante toda la vida útil de la aplicación.

Por lo tanto, necesitamos desacoplar el enriquecedor del origen de las propiedades personalizadas, y el origen puede ser una instancia con alcance y una vida útil limitada.

 public sealed class CustomLogEnricherSource : ICustomLogEnricherSource { private readonly Dictionary<string, CustomLogEventProperty> properties = new(); public ICustomLogEnricherSource With<T>(string property, T? value, LogEventLevel logLevel) where T : class { if (value is null) { return this; } properties[property] = new CustomLogEventProperty(property, value, logLevel); return this; } public void Remove(string property) { properties.Remove(property); } public IEnumerable<CustomLogEventProperty> GetCustomProperties(LogEventLevel logLevel) { foreach (var item in properties.Values) { if (item.Level <= logLevel) { yield return item; } } } } // And CustomLogEventProperty is a simple struct (you can make it a class, too): public struct CustomLogEventProperty { private LogEventProperty? propertyValue; public CustomLogEventProperty(string property, object value, LogEventLevel level) { Name = property; Value = value; Level = level; } public string Name { get; } public object Value { get; } public LogEventLevel Level { get; } public LogEventProperty ProduceProperty(ILogEventPropertyFactory propertyFactory) { propertyValue ??= propertyFactory.CreateProperty(Name, Value, destructureObjects: true); return propertyValue; } }

Esta implementación tiene algunos detalles simples:

• El enriquecido está desacoplado del origen de las propiedades personalizadas de los mensajes de registro para tener en cuenta diferentes vidas útiles de estos componentes y diferentes responsabilidades. Si es necesario, el enriquecimiento se puede realizar consumiendo una lista de instancias ICustomLogEnricherSource , ya que diferentes componentes de la aplicación pueden producir diferentes propiedades personalizadas.

• La fuente ( ICustomLogEnricherSource ) se puede inyectar en cualquier componente que necesite enriquecer los mensajes de registro con propiedades personalizadas. Idealmente, debería ser una instancia con ámbito, ya que no proporciona una manera conveniente de hacer caducar las propiedades personalizadas.

• El enriquecedor y la fuente implementan una lógica de filtrado simple basada en el nivel de registro de un mensaje de registro. Sin embargo, la lógica puede ser mucho más compleja y depender de otras propiedades LogEvent o incluso del estado de la aplicación.

• CustomLogEventProperty almacena en caché una instancia LogEventProperty producida para evitar crearla varias veces para la misma propiedad personalizada, ya que puede adjuntarse a varios mensajes de registro.

Otro detalle importante está en esta línea de código, el parámetro destructureObjects :

 propertyFactory.CreateProperty(Name, Value, destructureObjects: true);

Cuando adjuntamos objetos complejos (clases, registros, estructuras, colecciones, etc.) y este parámetro no está configurado en true , Serilog llamará a ToString en el objeto y adjuntará el resultado al mensaje de registro. Si bien los registros tienen una implementación ToString que generará todas las propiedades públicas y podemos anular ToString para nuestras clases y estructuras, este no siempre es el caso.

Además, dicha salida no funciona bien para el registro estructurado, ya que será una cadena simple y no podremos buscar ni filtrar mensajes de registro según las propiedades del objeto adjunto. Entonces, aquí configuramos este parámetro en true . Los tipos simples (tipos de valor y cadenas) funcionarán bien con cualquier valor de este parámetro.

Otro beneficio de esta implementación es que una vez que una propiedad personalizada se registra en la fuente, permanece allí para todos los mensajes de registro hasta que se elimina o se elimina la fuente (recuerde, debe ser una instancia con alcance). Es posible que algunas implementaciones necesiten un mejor control sobre la vida útil de las propiedades personalizadas, y esto se puede lograr de diferentes maneras.

Por ejemplo, proporcionando implementaciones específicas CustomLogEventProperty o proporcionando una devolución de llamada para comprobar si la propiedad personalizada debe eliminarse.

Esta lógica de vencimiento se puede usar en el método GetCustomProperties para verificar previamente una propiedad personalizada y eliminarla del origen si ha caducado.

Cómo ayuda esto a desacoplar las preocupaciones sobre el registro del código empresarial y de infraestructura

Bueno, idealmente no querríamos mezclar las preocupaciones de registro con el código comercial y de infraestructura. Esto se puede lograr con varios decoradores, middleware y otros patrones que permitan "envolver" el código comercial y de infraestructura con código específico de registro.

Sin embargo, es posible que esto no siempre sea posible y, a veces, puede ser más conveniente inyectar una abstracción intermedia como ICustomLogEnricherSource en el código comercial y de infraestructura y dejar que registre los datos personalizados para el registro.

De esta manera, el código comercial y de infraestructura no necesita saber nada sobre el registro real, y al mismo tiempo lo mezcla con algunas piezas de código que tienen en cuenta el registro.

De todos modos, este código estará mucho menos acoplado y será mucho más comprobable. Incluso podemos introducir algo como NullLogEnricherSource para una implementación no operativa que no consumirá rendimiento ni memoria en algunos escenarios de rutas muy activas.

Consideraciones de rendimiento

Como afirma Microsoft,

El registro debe ser tan rápido que no valga la pena el costo de rendimiento del código asincrónico.

Por lo tanto, siempre que enriquezcamos nuestros mensajes de registro con contexto adicional, debemos ser conscientes de las implicaciones en el rendimiento. En términos generales, la implementación del enriquecimiento de registros de Serilog es muy rápida, al menos está a la par con los alcances de registro de Microsoft, pero producir mensajes de registro llevará más tiempo si les adjuntamos más datos.

Cuantas más propiedades personalizadas adjuntemos, más objetos complejos habrá entre ellos y más tiempo y memoria se necesitará para generar un mensaje de registro. Por lo tanto, un desarrollador debe pensar mucho sobre qué datos adjuntar a los mensajes de registro, cuándo adjuntarlos y cuál debe ser su vida útil.

A continuación se muestra una pequeña tabla de resultados de pruebas comparativas que muestra el rendimiento y el consumo de memoria tanto para el enriquecimiento de registros de Serilog como para los alcances de registro de Microsoft. Cada método de referencia produciría 20 mensajes de registro con diferentes formas de enriquecerlos con propiedades personalizadas.

No se adjuntan propiedades personalizadas:

 | Method | Mean | Error | StdDev | Gen0 | Allocated | | SerilogLoggingNoEnrichment | 74.22 us | 1.194 us | 1.116 us | 1.2207 | 21.25 KB | | MicrosoftLoggingNoEnrichment | 72.58 us | 0.733 us | 0.685 us | 1.2207 | 21.25 KB |

Cada mensaje de registro tiene tres cadenas adjuntas:

 | Method | Mean | Error | StdDev | Gen0 | Allocated | | SerilogLoggingWithContext | 77.47 us | 0.551 us | 0.516 us | 1.7090 | 28.6 KB | | SerilogLoggingWithEnrichment | 79.89 us | 1.482 us | 2.028 us | 1.7090 | 29.75 KB | | MicrosoftLoggingWithEnrichment | 81.86 us | 1.209 us | 1.131 us | 1.8311 | 31.22 KB |

Cada mensaje de registro tiene tres objetos complejos (registros) adjuntos:

 | Method | Mean | Error | StdDev | Gen0 | Allocated | | SerilogLoggingWithObjectContext | 108.49 us | 1.193 us | 1.058 us | 5.3711 | 88.18 KB | | SerilogLoggingWithObjectEnrichment | 106.07 us | 0.489 us | 0.409 us | 5.3711 | 89.33 KB | | MicrosoftLoggingWithObjectEnrichment | 99.63 us | 1.655 us | 1.468 us | 6.1035 | 100.28 KB |The

Los métodos Serilog*Context usan LogContext.PushProperty , los métodos Serilog*Enrichment usan el enriquecimiento personalizado y la implementación de fuente proporcionada en el artículo, mientras que los métodos Microsoft* usan alcances de registro.

Podemos ver que el rendimiento y el consumo de memoria son muy similares en la mayoría de los casos, y enriquecer con objetos complejos es más costoso que enriquecer con tipos simples. La única excepción es el registro con la implementación de Microsoft cuando adjuntamos registros para registrar mensajes.

Esto se debe a que los ámbitos de registro no desestructuran objetos complejos y utilizan el método ToString para la serialización al adjuntarlos a mensajes de registro. Esto hace que la implementación de Microsoft sea un poco más rápida pero consume más memoria.

Si usáramos clases con la implementación ToString predeterminada, el consumo de memoria sería mucho menor, pero estos objetos personalizados se registrarían como nombres de tipo completos, totalmente inútiles.

Y en cualquier caso, no podríamos buscar y filtrar mensajes de registro en función de las propiedades de estos objetos con la implementación de Microsoft debido a que no los desestructuramos.

Entonces, esta es la limitación de los alcances de registro de Microsoft que debemos tener en cuenta: no se desestructuran objetos complejos, mientras que los tipos simples se registran bien y se pueden buscar y filtrar.

Nota: el código fuente de referencia y los ejemplos de código para este artículo se pueden encontrar en el repositorio de GitHub.

Conclusión

El enriquecimiento adecuado del registro es una "mejora de la calidad de vida" para el desarrollo y mantenimiento del código. Permite la posibilidad de adjuntar contexto adicional para registrar mensajes que no se conocen en el momento de la creación del mensaje de registro.

Este contexto puede ser cualquier cosa, desde una simple cadena hasta un objeto complejo, y se produce o se conoce en algún momento dentro de la infraestructura o el código comercial.

Es una forma de separar el código de registro y observabilidad del código de infraestructura y comercial y hacer que el código sea más mantenible, comprobable y legible.

Referencias

• Sobre el enriquecimiento de registros de Serilog: https://github.com/serilog/serilog/wiki/Enrichment
• Sobre los ámbitos de registro de Microsoft: https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-8.0#log-scopes
• Ejemplos de código para este artículo: https://github.com/dmitry-slabko/log-enrichment-pub