Ein tieferer Einblick in die Protokollanreicherung

In diesem Artikel werden wir abschließend untersuchen, wie Protokollierungsprobleme und Code von Infrastruktur und Geschäftscode getrennt und entkoppelt werden können. Im vorherigen Artikel haben wir untersucht, wie Sie DiagnosticSource und DiagnosticListener verwenden, um dies für Infrastrukturvorgänge zu erreichen.

Jetzt sehen wir uns an, wie die protokollierten Daten mit zusätzlichem Kontext angereichert werden können.

Im Wesentlichen geht es beim Konzept der Anreicherung protokollierter Daten um die Registrierung zusätzlicher Kontexte oder Daten, die mit den Protokollnachrichten einhergehen sollen. Dieser Kontext kann alles sein – von einer einfachen Zeichenfolge bis hin zu einem komplexen Objekt, und er wird zu einem bestimmten Zeitpunkt innerhalb der Infrastruktur oder des Geschäftscodes erzeugt oder bekannt, nicht zu dem Zeitpunkt, zu dem die Protokollnachrichten geschrieben werden.

Daher können wir Protokollnachrichten nicht einfach eine weitere Eigenschaft hinzufügen, da dieser Code keine Protokollierungsausgabe erzeugt, oder wir möchten, dass der Kontext an mehrere Protokollnachrichten angehängt wird, die möglicherweise in der Ausführungskette erzeugt werden oder nicht.

Dieser Kontext kann sogar bedingt sein – etwa das Hinzufügen bestimmter Daten nur zu Fehlerprotokollmeldungen, während alle anderen Meldungen diese nicht benötigen.

Wir werden Serilog und seine Anreicherungsfunktion verwenden, da Serilog es sehr flexibel und leistungsstark gemacht hat. Auch andere Lösungen verfügen über ähnliche Funktionen auf unterschiedlichen Reifegraden, und wir werden die Erweiterung von Serilog mit dem vergleichen, was Microsoft.Extensions.Logging standardmäßig bereitstellt.

Ein Überblick über die vorhandenen Log Enricher für Serilog

Serilog ist vollgepackt mit vielen nützlichen Anreicherern, die in manchen Szenarien sehr praktisch sein können. Sie können diese Seite besuchen – https://github.com/serilog/serilog/wiki/Enrichment – um die vollständige Liste der Enricher und ihre Beschreibungen anzuzeigen.

Beispielsweise gibt es die LogContext- und GlobalLogContext-Enricher, die es ermöglichen, zusätzliche Daten zu übertragen, um sie mit den Protokollnachrichten zu protokollieren, wenn sie in einem übereinstimmenden Bereich geschrieben werden.

Der LogContext-Enricher ist dem Konzept der Protokollierungsbereiche in Microsoft.Extensions.Logging sehr ähnlich. Im Wesentlichen übertragen sie einige benutzerdefinierte Daten und stellen ein IDisposable-Objekt bereit, das entsorgt werden sollte, um die Daten aus dem Protokollkontext zu entfernen.

Das heißt, solange sich das IDisposable-Objekt im Gültigkeitsbereich befindet, werden die Daten an alle Protokollnachrichten angehängt, die in diesem Bereich geschrieben werden. Wenn es entsorgt wird, werden die Daten nicht mehr angehängt.

Die Serilog- und Microsoft-Dokumentation enthält die folgenden Beispiele:

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

Obwohl sie für einige Szenarien nützlich sind, sind sie recht begrenzt. Die beste Verwendung für diese Art der Protokollanreicherung sind Implementierungen vom Typ Middleware oder Dekorator, bei denen der Bereich genau definiert ist und die Daten zum Zeitpunkt der Bereichserstellung bekannt sind und wir sicher sind, dass die Daten außerhalb des Bereichs keinen Wert haben Umfang.

Beispielsweise können wir damit eine Korrelations-ID an alle Protokollnachrichten innerhalb eines einzelnen HTTP-Anforderungsverarbeitungsbereichs anhängen.

Der GlobalLogContext-Anreicherer ähnelt LogContext, ist jedoch global – er überträgt die Daten an alle in einer Anwendung geschriebenen Protokollnachrichten. Allerdings sind die tatsächlichen Anwendungsfälle für diese Art der Anreicherung sehr begrenzt.

Benutzerdefiniertes Log Enricher-Beispiel für Serilog

Tatsächlich ist die Implementierung benutzerdefinierter Protokollanreicherer für Serilog sehr einfach: Implementieren Sie einfach die ILogEventEnricher Schnittstelle und registrieren Sie den Anreicherer bei der Logger-Konfiguration. Die Schnittstelle muss nur eine Methode implementieren – Enrich – die das Protokollereignis akzeptiert und es mit den gewünschten Daten anreichert.

Sehen wir uns eine Beispielimplementierung für einen benutzerdefinierten Protokollanreicherer an.

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

Wie wir sehen, ist dieser Anreicherer auf eine ICustomLogEnricherSource angewiesen, um die benutzerdefinierten Eigenschaften abzurufen, mit denen das Protokollereignis angereichert werden soll. Normalerweise sind die Protokollanreicherer langlebige Instanzen und folgen sogar dem Singleton-Muster – sie werden einmal beim Anwendungsstart registriert und sind für die gesamte Anwendungslebensdauer aktiv.

Daher müssen wir den Enricher von der Quelle der benutzerdefinierten Eigenschaften entkoppeln, und die Quelle kann eine bereichsbezogene Instanz mit begrenzter Lebensdauer sein.

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

Diese Implementierung weist einige einfache Details auf:

• Der Enricher ist von der Quelle der benutzerdefinierten Eigenschaften für Protokollnachrichten entkoppelt, um unterschiedliche Lebensdauern dieser Komponenten und unterschiedliche Verantwortlichkeiten zu berücksichtigen. Bei Bedarf kann der Anreicherer durch Nutzung einer Liste von ICustomLogEnricherSource Instanzen erstellt werden, da unterschiedliche Anwendungskomponenten möglicherweise unterschiedliche benutzerdefinierte Eigenschaften erzeugen.

• Die Quelle ( ICustomLogEnricherSource ) kann in jede Komponente eingefügt werden, die Protokollnachrichten mit benutzerdefinierten Eigenschaften anreichern muss. Idealerweise sollte es sich um eine bereichsbezogene Instanz handeln, da sie keine bequeme Möglichkeit bietet, die benutzerdefinierten Eigenschaften ablaufen zu lassen.

• Der Anreicherer und die Quelle implementieren eine einfache Filterlogik basierend auf der Protokollebene einer Protokollnachricht. Allerdings kann die Logik viel komplexer sein und auf anderen LogEvent Eigenschaften oder sogar auf dem Anwendungsstatus basieren.

• CustomLogEventProperty speichert eine erstellte LogEventProperty Instanz zwischen, um zu vermeiden, dass sie mehrmals für dieselbe benutzerdefinierte Eigenschaft erstellt wird, da sie möglicherweise an mehrere Protokollnachrichten angehängt wird.

Ein weiteres wichtiges Detail in dieser Codezeile ist der destructureObjects Parameter:

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

Wenn wir komplexe Objekte anhängen – Klassen, Datensätze, Strukturen, Sammlungen usw. – und dieser Parameter nicht auf true gesetzt ist, ruft Serilog ToString für das Objekt auf und hängt das Ergebnis an die Protokollnachricht an. Während Datensätze über eine ToString Implementierung verfügen, die alle öffentlichen Eigenschaften ausgibt, und wir ToString für unsere Klassen und Strukturen überschreiben können, ist dies nicht immer der Fall.

Außerdem eignet sich eine solche Ausgabe nicht gut für die strukturierte Protokollierung, da es sich um eine einfache Zeichenfolge handelt und wir nicht in der Lage sind, Protokollnachrichten basierend auf den Eigenschaften des angehängten Objekts zu suchen und zu filtern. Deshalb setzen wir diesen Parameter hier auf true . Die einfachen Typen (Werttypen und Zeichenfolgen) funktionieren problemlos mit beiden Werten dieses Parameters.

Ein weiterer Vorteil dieser Implementierung besteht darin, dass eine einmal in der Quelle registrierte benutzerdefinierte Eigenschaft für alle Protokollmeldungen dort verbleibt, bis sie entfernt oder die Quelle verworfen wird (denken Sie daran, dass es sich um eine bereichsbezogene Instanz handeln sollte). Bei einigen Implementierungen ist möglicherweise eine bessere Kontrolle über die Lebensdauer der benutzerdefinierten Eigenschaften erforderlich. Dies kann auf unterschiedliche Weise erreicht werden.

Beispielsweise durch die Bereitstellung spezifischer CustomLogEventProperty Implementierungen oder durch die Bereitstellung eines Rückrufs, um zu prüfen, ob die benutzerdefinierte Eigenschaft entfernt werden sollte.

Diese Ablauflogik kann in der GetCustomProperties Methode verwendet werden, um eine benutzerdefinierte Eigenschaft vorab zu prüfen und sie aus der Quelle zu entfernen, wenn sie abgelaufen ist.

Wie dies dabei hilft, Protokollierungsprobleme vom Geschäfts- und Infrastrukturcode zu entkoppeln

Nun, im Idealfall möchten wir Protokollierungsbelange nicht mit Geschäfts- und Infrastrukturcode vermischen. Dies kann mit verschiedenen Dekoratoren, Middlewares und anderen Mustern erreicht werden, die es ermöglichen, den Geschäfts- und Infrastrukturcode mit protokollierungsspezifischem Code zu „umschließen“.

Dies ist jedoch möglicherweise nicht immer möglich, und manchmal kann es bequemer sein, eine solche Zwischenabstraktion wie ICustomLogEnricherSource in den Geschäfts- und Infrastrukturcode einzufügen und die benutzerdefinierten Daten für die Protokollierung registrieren zu lassen.

Auf diese Weise muss der Geschäfts- und Infrastrukturcode nichts über die eigentliche Protokollierung wissen, während er sie dennoch mit einigen protokollierungsfähigen Codeteilen vermischt.

Wie auch immer, dieser Code wird viel weniger gekoppelt und viel besser testbar sein. Möglicherweise führen wir sogar so etwas wie NullLogEnricherSource für eine No-Op-Implementierung ein, die für einige Szenarien mit sehr heißem Pfad keine Leistung und keinen Speicher beansprucht.

Leistungsüberlegungen

Wie Microsoft angibt,

Die Protokollierung sollte so schnell sein, dass sie die Leistungseinbußen von asynchronem Code nicht wert ist.

Wenn wir also unsere Protokollnachrichten mit zusätzlichem Kontext anreichern, sollten wir uns der Auswirkungen auf die Leistung bewusst sein. Im Allgemeinen ist die Implementierung der Serilog-Protokollanreicherung sehr schnell und entspricht zumindest den Protokollierungsbereichen von Microsoft. Die Erstellung von Protokollnachrichten dauert jedoch länger, wenn wir ihnen mehr Daten hinzufügen.

Je mehr benutzerdefinierte Eigenschaften wir anhängen, desto komplexere Objekte sind darunter und desto mehr Zeit und Speicher wird benötigt, um eine Protokollmeldung zu erstellen. Daher sollte ein Entwickler sehr sorgfältig darüber nachdenken, welche Daten an Protokollnachrichten angehängt werden, wann diese angehängt werden und wie lange sie gültig sein sollen.

Nachfolgend finden Sie eine kleine Benchmark-Ergebnistabelle, die die Leistung und den Speicherverbrauch sowohl für die Serilog-Protokollanreicherung als auch für die Microsoft-Protokollierungsbereiche zeigt. Jede Benchmark-Methode würde 20 Protokollmeldungen mit unterschiedlichen Möglichkeiten zur Anreicherung mit benutzerdefinierten Eigenschaften erzeugen.

Keine benutzerdefinierten Eigenschaften angehängt:

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

An jede Protokollnachricht sind drei Zeichenfolgen angehängt:

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

An jede Protokollnachricht sind drei komplexe Objekte (Datensätze) angehängt:

 | 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

Die Serilog*Context Methoden verwenden LogContext.PushProperty , die Serilog*Enrichment -Methoden verwenden den im Artikel angegebenen benutzerdefinierten Enricher und die Quellimplementierung, während Microsoft* -Methoden Protokollierungsbereiche verwenden.

Wir können sehen, dass Leistung und Speicherverbrauch in den meisten Fällen sehr ähnlich sind und die Anreicherung mit komplexen Objekten teurer ist als die Anreicherung mit einfachen Typen. Die einzige Ausnahme ist die Protokollierung mit Microsoft-Implementierung, wenn wir Datensätze an Protokollnachrichten anhängen.

Dies liegt daran, dass Protokollierungsbereiche keine komplexen Objekte zerstören und ToString Methode zur Serialisierung verwenden, wenn sie an Protokollnachrichten angehängt werden. Dies beschleunigt die Microsoft-Implementierung etwas, verbraucht aber mehr Speicher.

Wenn wir Klassen mit der standardmäßigen ToString Implementierung verwenden würden, wäre der Speicherverbrauch viel geringer, aber diese benutzerdefinierten Objekte würden als vollständig qualifizierte Typnamen protokolliert – völlig nutzlos.

Und auf jeden Fall wären wir mit der Microsoft-Implementierung nicht in der Lage, Protokollnachrichten basierend auf den Eigenschaften dieser Objekte zu suchen und zu filtern, da sie nicht zerstört werden.

Dies ist also die Einschränkung der Microsoft-Protokollierungsbereiche, die wir beachten sollten: Keine Destrukturierung komplexer Objekte, während einfache Typen problemlos protokolliert werden und durchsuchbar und filterbar sind.

Hinweis: Der Benchmark-Quellcode und die Codebeispiele für diesen Artikel finden Sie im GitHub-Repository

Abschluss

Eine ordnungsgemäße Protokollanreicherung ist eine „Verbesserung der Lebensqualität“ für die Entwicklung und Wartung des Codes. Es ermöglicht die Möglichkeit, zusätzlichen Kontext zu Protokollnachrichten hinzuzufügen, der zum Zeitpunkt der Erstellung der Protokollnachricht noch nicht bekannt ist.

Dieser Kontext kann alles sein – von einer einfachen Zeichenfolge bis hin zu einem komplexen Objekt, und er wird irgendwann innerhalb der Infrastruktur oder des Geschäftscodes erzeugt oder bekannt.

Dies ist eine Möglichkeit, Protokollierungs- und Observability-Code von Infrastruktur- und Geschäftscode zu trennen und den Code wartbarer, testbarer und lesbarer zu machen.

Verweise

• Zur Serilog-Protokollanreicherung – https://github.com/serilog/serilog/wiki/Enrichment
• Auf Microsoft-Protokollierungsbereichen – https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-8.0#log-scopes
• Codebeispiele für diesen Artikel – https://github.com/dmitry-slabko/log-enrichment-pub