Loggen–aber bitte mit Kontext

Weiter geht es in meiner kleinen Serie “Sommer-Logging mit Serilog”.

Wir haben bei dem Strukturierten Logging ja schon gesehen, dass man mit einem geeigneten Sink die Parameter einer Logmeldung getrennt einsehen und auch abfragen kann. Aber das erfordert natürlich, dass ich ein entsprechendes Sink habe, welches die Daten auch so aufbereiten kann.

Typischerweise hat man aber nun mal Text-Dateien als Logfiles. Dort geht das nicht, und die Suche nach einem bestimmten Parameter gestaltet sich mit unter schwierig. Wäre es da nicht schön, wenn man bestimmte Informationen in einer Spalte im Logfile erfassen könnte, so wie das mit den Informationen aus dem Logging-Context ja auch geht?

Das geht!

Man kann bei jeder Logmeldung einen Context definieren, der zusammen mit der eigentlichen Meldung und den Parametern an das jeweilige Sink übergeben wird.

Log.Logger.ForContext("MeinProperty", "MeinWert").Information("Meine Meldung");

Das haben wir bei dem fachlichen Logging ja schon mal gesehen!

Wenn ich nun die Formatierung der Logmeldungen anpasse, so kann ich nun diese Eigenschaft „MeinProperty“ aus dem Kontext als Platzhalter in meinem Template mit angeben.

.WriteTo.Console(outputTemplate:"[{Timestamp:HH:mm:ss} {Level:u3}] {MeinProperty:u} {Message}")

Damit wird also nun MeinProperty als Upper-Case in einer eigenen Spalte mit ausgegeben.

Das ganze kann praktisch sein, um z.B. bestimmte Informationen in jeder Zeile eines Logfiles mit anzugeben. Das könnte die ID eines verarbeiteten Jobs sein oder was anderes.

Gibt es da nicht schon was fertiges?

Solche erweiterten Kontext-Informationen gibt es auch schon als Nuget Packages. Da ganze nennt sich „Enricher“, weil es den Kontext um zusätzliche Informationen anreichert.

Typische Enricher sind Process und Threads. Diese stellen die aktuelle Prozess- bzw. Thread-ID im Context zur Verfügung, so dass diese mit {ProcessId} bzw {ThreadId} in das Log mit aufgenommen werden können. Eingebunden wird das Ganze dann so:

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .WriteTo.Console(outputTemplate:"[{Timestamp:HH:mm:ss} {Level:u3}] {ProcessId} {Message}")
    .Enrich.WithProcessId()
    .CreateLogger();

Voila! Natürlich kann man hier auch mehrere Enricher angeben.

Interessant für Web-Entwickler ist vielleicht noch der Enricher Serilog.Web.Classic (gibt es auch für Dotnet Core!). Dieser erzeugt für jeden Web-Request eine GUID und fügt die in den Kontext mit ein. Somit bekommen alle Log-Meldungen, die zu eine Web-Request gehören eine eindeutige ID. Damit kann man später alle Meldungen anhand dieser Request-ID filtern und somit genau die Meldungen erhalten, die zu einem einzelnen Http-Request gehört haben.