Strukturiertes Logging mit Serilog

Im ersten Teil haben wir schon gesehen, wie man mit Serilog Logging in eine Anwendung bekommen kann.

Bisher haben wir lediglich einfache Meldungen in Log geschrieben. Das ist zwar schon nett, aber typischerweise will man in einem technischen Log auch ein paar Details zu der aktuell ausgeführten Operation sehen. Sprich: es sollten auch Variablen-Inhalte in das Log geschrieben werden.

Ein naiver Ansatz wäre nun folgender:

var foo = "meinWert";
Log.Logger.Debug("Wert von foo: " + foo);

Das erfüllt zwar auf den ersten Blick die Anforderung, aber das geht auch besser.

Holen wir einmal ein wenig aus …

Wenn man sich einmal das EventLog von Windows ansieht, dann sehen Logmeldungen typischer so aus

Man kann sich die gleiche Meldung aber auch mit Details ansehen.

Dort erkennt man, dass die Meldung detaillierter dargestellt wird. Neben der reinen textuellen Darstellung kann man den Wert jeder einzelnen Variable auch einzeln sehen. Das ist interessant, würde es doch möglich sein, dass man sich alle Meldungen anzeigen lässt, in der das Feld updateGuid den Wert {D7F12BD4-EE54-4993-909A-D1893145D8FB} hat.

Nun wieder zurück zu Serilog. Diese Art von Logging nennt man „structured logging“. Das kann man mit Serilog ebenfalls erreichen. In unserem Beispiel von oben müssten wir dazu unser Logging ein wenig anpassen:

var foo = "meinWert"; 
Log.Logger.Debug("Wert von foo: {foo} ", foo); 

Beim Logging in eine Textdatei oder auf die Konsole ändert sich ersteinmal nichts. Diese Sinks können nur die reine Text-Darstellung logging. Die Meldung im Log sieht als so aus

[DBG] Wert von foo: "meinWert"

Interessant ist vielleicht noch, wie die Logmeldung aussieht wenn foo ein leerer String ist

[DBG] Wert von foo: ""

Serilog hat hier also um den Wert von foo Anführungszeichen gesetzt. Das macht es (in meinen Augen) leichter zu erkennen ob eine Zeichenfolge einfach nur leer ist oder zB aus Leerzeichen besteht.

Anmerkung: mit einem der letzten Updates des File-Sinks hat sich das Default-Verhalten geändert, so dass dieses Sink keine Anführungszeichen um die Werte setzt. Um dieses Verhalten wieder zu erhalten muss man das Template für das Logging anpassen.

.WriteTo.File("MyApplication.log", outputTemplate:"[{Level:u3}] {Message:j}{NewLine}{Exception}")

Entscheidend ist hierbei {Message:j}. Default wäre {Message:lj}, wobei das :l anzeigt, dass keine Anführungszeichen eingefügt werden sollen. (Mehr zun den Output-Templates findet man im Wiki)

Mit einem geeigneten Sink kann man nun (wie Application-Insights) auch den Wert von foo getrennt erkennen.

Und man kann nun auch alle Logmeldungen suchen, in denen foo den Wert “Mein Wert” hat.

Das eröffnet ungeahnte Möglichkeiten …

Aber vielleicht noch mal zurück zu dem Logging von Werten. In dem Beispiel haben wir ja einfach nur einen String gelogged. Aber häufig hat man vielleicht auch komplexere Objekte (zB DTOs) deren Zustand man Loggen will. Der naheliegenste Weg ist hier wiederum

var newUser = new User(){FirstName = "Henning", LastName = "Eiben"};
Log.Logger.Debug("Neuer Benutzer erstellte: Vorname: {Firstname}, Nachname: {Lastname}", newUser.FirstName, newUser.LastName);

Aber bei vielen Eigenschaften ist das irgendwie lästig. Einfacher ist da diese Schreibweise:

Log.Logger.Debug("Neuer Benutzer erstellte: {@newUser}", newUser);

Das dazugehörige Logfile sieht dann wie folgt aus:

[DBG] Neuer Benutzer erstellte: {"FirstName":"Henning","LastName":"Eiben","$type":"User"}

Das ist deutlich kürzer und zudem – wenn neue Eigenschaften zu dem User-Objekt dazukommen, werden die automatisch auch mit gelogged werden!

Etwas besonders ist die Behandlung von Arrays, Listen und Dictionaries. So erzeugt dieser Code

var plattforms = new[] { "SharePoint", "Office365", "Azure" };
Log.Information("Meine Plattformen: {plattforms}", plattforms);

folgenden Logeintrag

[INF] Meine Plattformen: ["SharePoint","Office365","Azure"]

Das soll für den zweiten Teil zu Serilog erst einmal genügen, mehr zum strukturieren Logging findet man im Wiki.