Une plongée plus approfondie dans l'enrichissement des journaux

Dans cet article, nous conclurons en examinant comment les problèmes de journalisation et le code peuvent être séparés et découplés de l'infrastructure et du code métier. Dans l' article précédent , nous avons expliqué comment utiliser DiagnosticSource et DiagnosticListener pour y parvenir pour les opérations d'infrastructure.

Nous allons maintenant voir comment enrichir les données enregistrées avec un contexte supplémentaire.

Essentiellement, le concept d’enrichissement des données enregistrées consiste à enregistrer un contexte ou des données supplémentaires qui doivent accompagner les messages du journal. Ce contexte peut être n'importe quoi - d'une simple chaîne à un objet complexe, et il est produit ou connu à un moment donné dans l'infrastructure ou le code métier, et non au moment où les messages du journal sont écrits.

Ainsi, nous ne pouvons pas simplement ajouter une autre propriété aux messages de journalisation, car ce code ne produit aucune sortie de journalisation, ou nous voulons que le contexte soit attaché à plusieurs messages de journal qui peuvent être ou non produits tout au long de la chaîne d'exécution.

Ce contexte peut même être conditionnel, comme l'ajout de données spécifiques uniquement aux messages du journal d'erreurs alors que tous les autres messages n'en ont pas besoin.

Nous utiliserons Serilog et sa fonction d'enrichissement, car Serilog l'a rendu très flexible et puissant. D'autres solutions ont également des fonctionnalités similaires à différents niveaux de maturité, et nous comparerons l'enrichissement de Serilog avec ce que Microsoft.Extensions.Logging fournit immédiatement.

Un aperçu des enrichisseurs de journaux existants pour Serilog

Serilog est livré avec de nombreux enrichisseurs utiles qui peuvent être très utiles dans certains scénarios. Vous pouvez visiter cette page - https://github.com/serilog/serilog/wiki/Enrichment - pour voir la liste complète des enrichisseurs et leurs descriptions.

Par exemple, il existe des enrichisseurs LogContext et GlobalLogContext qui permettent de transmettre des données supplémentaires pour les enregistrer avec les messages du journal si elles sont écrites dans une portée correspondante.

L'enrichisseur LogContext est très similaire au concept d'étendues de journalisation dans Microsoft.Extensions.Logging. Essentiellement, ils transmettent tous deux des données personnalisées et fournissent un objet IDisposable qui doit être supprimé pour supprimer les données du contexte du journal.

Autrement dit, tant que l'objet IDisposable est dans la portée, les données seront jointes à tous les messages de journal écrits dans cette portée. Une fois supprimées, les données ne seront plus jointes.

La documentation Serilog et Microsoft fournit ces exemples :

 // 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(); } }

Bien qu'utiles dans certains scénarios, ils sont assez limités. La meilleure utilisation de ce type d'enrichissement des journaux est dans les implémentations de type middleware ou décorateur, où la portée est bien définie et les données sont connues au moment de la création de la portée, et nous sommes certains que les données n'ont aucune valeur en dehors du portée.

Par exemple, nous pouvons l'utiliser pour attacher un ID de corrélation à tous les messages de journal dans une seule étendue de traitement de requête HTTP.

L'enrichisseur GlobalLogContext est similaire à LogContext, mais il est global : il transmet les données à tous les messages de journal écrits dans une application. Cependant, les cas d’usage réels de ce type d’enrichissement sont très limités.

Exemple d'enrichisseur de journaux personnalisé pour Serilog

En fait, l'implémentation d'enrichisseurs de journaux personnalisés pour Serilog est très simple : il suffit d'implémenter l'interface ILogEventEnricher et d'enregistrer l'enrichisseur avec la configuration de l'enregistreur. L'interface n'a qu'une seule méthode à implémenter - Enrich - qui accepte l'événement de journal et l'enrichit avec les données souhaitées.

Examinons un exemple d'implémentation pour un enrichisseur de journaux personnalisé.

 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); } } }

Comme nous le voyons, cet enrichisseur s'appuie sur un ICustomLogEnricherSource pour obtenir les propriétés personnalisées avec lesquelles enrichir l'événement de journal. Normalement, les enrichisseurs de journaux sont des instances de longue durée et suivent même le modèle Singleton : ils sont enregistrés une fois au démarrage de l'application et restent actifs pendant toute la durée de vie de l'application.

Nous devons donc dissocier l'enrichisseur de la source des propriétés personnalisées, et la source peut être une instance limitée avec une durée de vie limitée.

 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; } }

Cette implémentation comporte quelques détails simples :

• L'enrichisseur est découplé de la source des propriétés personnalisées pour les messages de journal afin de tenir compte des différentes durées de vie de ces composants et des différentes responsabilités. Si nécessaire, l'enrichisseur peut être réalisé en consommant une liste d'instances ICustomLogEnricherSource , car différents composants d'application peuvent produire différentes propriétés personnalisées.

• La source ( ICustomLogEnricherSource ) peut être injectée dans n'importe quel composant devant enrichir les messages de journal avec des propriétés personnalisées. Idéalement, il devrait s’agir d’une instance limitée, car elle ne fournit pas un moyen pratique d’expirer les propriétés personnalisées.

• L'enrichisseur et la source implémentent une logique de filtrage simple basée sur le niveau de journalisation d'un message de journal. Cependant, la logique peut être beaucoup plus complexe et s'appuyer sur d'autres propriétés LogEvent , voire sur l'état de l'application.

• CustomLogEventProperty met en cache une instance LogEventProperty produite pour éviter de la créer plusieurs fois pour la même propriété personnalisée, car elle peut être attachée à plusieurs messages de journal.

Un autre détail important se trouve dans cette ligne de code, le paramètre destructureObjects :

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

Lorsque nous attachons des objets complexes - classes, enregistrements, structures, collections, etc. - et que ce paramètre n'est pas défini sur true , Serilog appellera ToString sur l'objet et joindra le résultat au message de journal. Bien que les enregistrements aient une implémentation ToString qui affichera toutes les propriétés publiques et que nous puissions remplacer ToString pour nos classes et structures, ce n'est pas toujours le cas.

De plus, une telle sortie ne convient pas à la journalisation structurée, car il s'agira d'une simple chaîne et nous ne pourrons pas rechercher et filtrer les messages de journal en fonction des propriétés de l'objet joint. Nous définissons donc ce paramètre sur true ici. Les types simples (types valeur et chaînes) feront très bien l’affaire avec l’une ou l’autre valeur de ce paramètre.

Un autre avantage de cette implémentation est qu'une fois qu'une propriété personnalisée est enregistrée dans la source, elle y reste pour tous les messages de journal jusqu'à ce qu'elle soit supprimée ou que la source soit supprimée (rappelez-vous qu'il doit s'agir d'une instance limitée). Certaines implémentations peuvent nécessiter un meilleur contrôle sur la durée de vie des propriétés personnalisées, et cela peut être réalisé de différentes manières.

Par exemple, en fournissant des implémentations CustomLogEventProperty spécifiques ou en fournissant un rappel pour vérifier si la propriété personnalisée doit être supprimée.

Cette logique d'expiration peut être utilisée dans la méthode GetCustomProperties pour pré-vérifier une propriété personnalisée et la supprimer de la source si elle a expiré.

Comment cela aide à dissocier les préoccupations liées à l’exploitation forestière du code des entreprises et des infrastructures

Eh bien, idéalement, nous ne voudrions pas mélanger les problèmes de journalisation avec le code commercial et d'infrastructure. Ceci peut être réalisé avec divers décorateurs, middlewares et autres modèles qui permettent « d'envelopper » le code métier et d'infrastructure avec du code spécifique à la journalisation.

Cependant, cela n'est pas toujours possible et parfois, il peut être plus pratique d'injecter une abstraction intermédiaire telle que ICustomLogEnricherSource dans le code métier et d'infrastructure et de la laisser enregistrer les données personnalisées pour la journalisation.

De cette façon, le code métier et d'infrastructure n'a pas besoin de connaître quoi que ce soit sur la journalisation réelle, tout en le mélangeant avec certains morceaux de code prenant en charge la journalisation.

Quoi qu’il en soit, ce code sera beaucoup moins couplé et beaucoup plus testable. Nous pouvons même introduire quelque chose comme NullLogEnricherSource pour une implémentation sans opération qui ne consommera aucune performance ni mémoire pour certains scénarios très chauds.

Considérations relatives aux performances

Comme le déclare Microsoft,

La journalisation doit être si rapide qu'elle ne vaut pas le coût en performances du code asynchrone.

Ainsi, chaque fois que nous enrichissons nos messages de journal avec un contexte supplémentaire, nous devons être conscients des implications en termes de performances. D'une manière générale, la mise en œuvre de l'enrichissement des journaux Serilog est très rapide, au moins à égalité avec les étendues de journalisation de Microsoft, mais la production de messages de journal prendra plus de temps si nous y attachons plus de données.

Plus nous attachons de propriétés personnalisées, plus les objets sont complexes et plus il faudra de temps et de mémoire pour produire un message de journal. Ainsi, un développeur doit réfléchir très attentivement aux données à joindre aux messages de journal, au moment de les joindre et à leur durée de vie.

Vous trouverez ci-dessous un petit tableau de résultats de référence montrant les performances et la consommation de mémoire pour l'enrichissement des journaux Serilog et les étendues de journalisation Microsoft. Chaque méthode de référence produirait 20 messages de journal avec différentes manières de les enrichir avec des propriétés personnalisées.

Aucune propriété personnalisée attachée :

 | 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 |

Chaque message de journal est associé à trois chaînes :

 | 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 |

Chaque message de journal est associé à trois objets complexes (enregistrements) :

 | 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

Les méthodes Serilog*Context utilisent LogContext.PushProperty , les méthodes Serilog*Enrichment utilisent l'enrichisseur personnalisé et l'implémentation source indiqués dans l'article, tandis que les méthodes Microsoft* utilisent des étendues de journalisation.

Nous pouvons constater que les performances et la consommation de mémoire sont très similaires dans la plupart des cas, et que l’enrichissement avec des objets complexes est plus coûteux que l’enrichissement avec des types simples. La seule exception concerne la journalisation avec l'implémentation Microsoft lorsque nous joignons des enregistrements aux messages du journal.

En effet, les étendues de journalisation ne déstructurent pas les objets complexes et utilisent la méthode ToString pour la sérialisation lors de leur attachement aux messages de journal. Cela rend la mise en œuvre de Microsoft légèrement plus rapide mais consomme plus de mémoire.

Si nous utilisions des classes avec l'implémentation ToString par défaut, la consommation de mémoire serait beaucoup plus petite, mais ces objets personnalisés seraient enregistrés en tant que noms de types complets - totalement inutiles.

Et dans tous les cas, nous ne serions pas en mesure de rechercher et de filtrer les messages du journal en fonction des propriétés de ces objets avec l'implémentation Microsoft car ils ne sont pas déstructurés.

C'est donc la limitation des étendues de journalisation Microsoft dont nous devons être conscients : pas de déstructuration des objets complexes alors que les types simples sont correctement enregistrés et peuvent être recherchés et filtrables.

Remarque : le code source de référence et les exemples de code de cet article sont disponibles dans le référentiel GitHub.

Conclusion

Un enrichissement approprié des journaux est une « amélioration de la qualité de vie » pour le développement et la maintenance du code. Il permet d'attacher un contexte supplémentaire aux messages de journal qui ne sont pas connus au moment de la création du message de journal.

Ce contexte peut être n'importe quoi - d'une simple chaîne à un objet complexe, et il est produit ou connu à un moment donné dans l'infrastructure ou le code métier.

C'est un moyen de séparer le code de journalisation et d'observabilité du code d'infrastructure et métier et de rendre le code plus maintenable, testable et lisible.

Les références

• Sur l'enrichissement des journaux Serilog - https://github.com/serilog/serilog/wiki/Enrichment
• Sur les étendues de journalisation Microsoft - https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-8.0#log-scopes
• Exemples de code pour cet article - https://github.com/dmitry-slabko/log-enrichment-pub