Skip to content

Serilog

Jump to bottom
Stefan Vogelsang edited this page Feb 22, 2022 · 4 revisions

Logging ist ein Schlüsselelement in der Systemüberwachung, insbesondere wenn es um die Diagnose von Fehlern geht. Deswegen ist es auch ein wichtiger Bestandteil des Workshops. Ein gutes Logging gibt einen tieferen Einblick in die innere Arbeitsweise eines Systems, was ohne ein entsprechendes Logging schwer zu verstehen wäre.

Wir schauen uns ein paar Beispiele für das Logging direkt in unserer Anwendung an. Hierüber bekommen wir einen besseren Überblick über die Funktionsweise der Anwendung, den wir nur durch die Benutzung der Anwendung nicht bekommen würden. Dazu starten wir mit einer kurzen Einführung in unser zentralisiertes und strukturiertes Logging System, insbesondere dem Einsatz von Serilog zum Schreiben von Log-Einträgen und das Auswerten und Betrachten dieser mit Kibana.

Serilog ist ein Open Source Project auf GitHub und hervorragend geeignet für die Verwendung von strukturierten Logging.

Im Folgenden beschäftigen wir uns grob mit dem Thema Structured Logging und wir gehen auf einige wichtige Tipps und Tricks bei der Verwendung mit C# ein. Zudem beschäftigen wir uns mit dem Setup und der Konfiguration.

INHALT

Logging Beispiele aus der Anwendung

Im Folgenden schauen wir uns ein paar Beispiele an, wie wir entsprechende Log-Einträge für verschiedene Anwendungsfälle abrufen können.

Start der Anwendung

Betrachten der Log-Nachrichten zum Start einer Anwendung:

Ein Filter über den ApplicationContext zeigt alle Einträge zur entsprechenden Anwendung.

Das "Log-Level" der Einträge, wie z.B. Debug, Information, Warning, kann wie im Abschnitt: Setup und Konfiguration beschrieben konfiguriert werden.

Einschränkung auf einen spezifischen Ereignistyp

Die Fokussierung kann auch auf einen speziellen Ereignistypen (MessageTemplate) gelegt werden (hier für einen einzelnen ApplicationContext):

Oder alle Einträge für einen Ereignistypen über alle Anwendungen:

Betrachtung der Details eines Logeintrags

Wenn man keine Felder für die Anzeige auswählt, werden die Log-Einträge komprimiert mit ihren Eigenschaften dargestellt:

Zu jedem Eintrag können auch die Details in einer Art Tabellenansicht mit allen Eigenschaften angezeigt werden:

Oder aber auch als Rohansicht in JSON:

Konfiguration zur Laufzeit

Was in den Anwendungen an Ereignissen geschrieben werden soll kann durch das Hinzufügen von weiteren Umgebungsvariablen nach dem Muster Serilog__MinimumLevel__Override__* in der docker-compose.override.yml gesteuert werden. Siehe dazu folgendes Beispiel:

ordering.api:
  environment:
    - Serilog__MinimumLevel__Override__Store.Sales=Verbose

Das Hinzufügen der o.a. Umgebungsvariablen hat die gleichen Auswirkungen wie das Hinzufügen der u.a. Werte zur Serilog Konfiguration in der appsettings.json:

"Serilog": {
  "MinimumLevel": {
    "Override": {
      "Store.Sales": "Verbose",
    }
  }
},

Diese Konfiguration legt fest, das alle Ereignisse vom Level "Trace" oder höher für alle Klassen im Namensraum Store.Sales.* protokolliert werden sollen.

Verwendung von strukturiertem Logging

Widmen wir uns jetzt den Quellcode relevanten Aspekten des Loggings und beginnen mit den grundlegenden Konzepten des structured logging die uns die erwähnten Beispiele erst ermöglichen.

Im Gegensatz zum konventionellem Logging, wo jeder Eintrag nur durch einen einfachen Text repräsentiert wird, kann man structured logging als ein Stream von Schlüsselwerten (key-value pairs) für jedes protokollierte Ereignis ansehen.

Diese Schlüsselwertpaare bilden die Grundlage, die es uns ermöglicht, die vorhanden Einträge wie gezeigt entsprechend abzurufen und zu filtern.

Zugriff auf den Logger

Die Infrastruktur für Loggings aus dem .NET Framework unterstützt das strukturierte Logging bei Verwendung einer LoggerFactory, wie z.B. Serilog, die selbst das strukturierte Logging unterstützen. Der einfachste Weg dazu ist mittels Dependency Injection (DI) eine Abhängigkeit vom Typ ILogger<T> im Klassenkontruktor wie im folgendem Beispiel zu definieren:

public class WorkerClass
{
    private readonly ILogger<WorkerClass> _logger;

    public WorkerClass(ILogger<WorkerClass> logger) => _logger = logger;

    // If you have to use ILoggerFactory, change the constructor like this:
    public WorkerClass(ILoggerFactory loggerFactory) => _logger = loggerFactory.CreateLogger<WorkerClass>();
}

Bei der Nutzung von ILogger<T> ist bereits die Eigenschaft SourceContext entsprechend mit dem Klassennamen der verwendeten Klasse belegt.

Schreiben von Log-Einträgen

Das Schreiben von Log-Einträgen ist ziemlich einfach, wie das folgende Beispiel verdeutlicht:

_logger.LogInformation("----- Publishing integration event: {IntegrationEventId} from {AppName} - ({@IntegrationEvent})", pubEvent.EventId, Program.AppName, pubEvent.IntegrationEvent);

Der oben gezeigte Code arbeitet ähnlich wie die Methode string.format(), abgesehen von drei wichtigen Unterschieden:

  1. Der erste Parameter definiert den Eventtypen oder auch Template welches über seine Eigenschaften abgefragt werden kann.

  2. Jeder Name in geschweiften Klammern innerhalb eines Template definiert eine Eigenschaft dessen Wert von einer Parameterangabe nach dem Template entnommen wird, ähnlich wie bei string.Format().

  3. Wenn ein Eigenschaftsname mit einem @ beginnt wird der gesamte Objektgraph als Wert im Log gespeichert.

Logging-Kontexte und Correlation Ids

Ein Logging-Kontext erlaubt uns einen Bereich zu definieren innerhalb dessen alle dazugehörigen Ereignisse erfasst werden können. Hierüber und über so genannte Correlation Ids lassen sich eine Sammlung von Events verfolgen, auch über den Kontext einer Anwendung hinaus.

Correlation Ids dienen dazu eine Verknüpfung zwischen zwei oder mehreren Ereignissen zu erstellen und sind eine Möglichkeit Ereignisse zwischen mehreren Kontexten oder Anwendungen zu verknüpfen. Je nach Umfang kann es jedoch recht mühselig werden, die hierüber verknüpften Links zu verfolgen. Eine einfachere und eine bessere Möglichkeit kann dann die Gruppierung der Einträge über die erwähnten Kontexte sein, die Geschäftskonzepte oder Entitäten wiederspiegeln. Über einen solchen Kontext wie z.B. OrderContext können alle Einträge dann einfach identifiziert werden. Dies ist auch über Anwendungsgrenzen und sogar unter Verwendung verschiedener Technologien möglich.

Die folgenden Eigenschaften für solche Kontexte werden in der Beispielanwendung verwendet:

  • ApplicationContext wird bei Programmstart definiert und allen Ereignissen wird der entsprechende ApplicationContext hinzugefügt.

  • SourceContext identifiziert den Namen der Klasse in der das Ereignis erfasst wird und wird gewöhnlicherweise beim Erstellen der Klasse erzeugt, wenn die Logger-Instanz mittels Dependency Inhection aufgelöst wird.

  • MessageId fasst alle Ereignisse zuzammen, die während der Verarbeitung einer Nachricht auftreten und wird manuell in den behandelten Klassen gesetzt.

Wichtige Regeln

Beim Einsatz von strukturiertem Logging sollten folgende wenige und einfache Regeln eingehalten werden:

  1. KEINE Verwendung von String Interpolation mit Variablen im Template.

    Die Verwendung der String Interpolation führt dazu, dass das Template seine Bedeutung verliert und daraus resultiert dass der Eintrag seine Schlüsselwerte verliert und somit wie beim konventiuellen Logging zu einem einfachen Text verkommt.

  2. Das Loggen von Ausnahmen sollte mit den entsprechenden überladenen Methoden erfolgen. Dies zeigen die folgenden Code-Zeilen:

    catch (Exception ex)
{
    _logger.LogWarning(ex, "Could not publish event: {EventId} after {Timeout}s ({ExceptionMessage})", @event.Id, $"{time.TotalSeconds:n1}", ex.Message);
}

.../...

catch (Exception ex)
{
    _logger.LogError(ex, "Program terminated unexpectedly ({AppName})!", AppName);
    return 1;
}

    Es ist wichtig nicht nur die Textnachricht der Ausnahme zu protokollieren, dies wäre wie ein Verstoß gegen die Regel #1 - mit den selben Folgen.

Setup und Konfiguration

Serilog

Das Setup für das Logging in unserer Lösung weicht etwas von den gewöhnlichen Beispielen in ASP.NET Core ab und orientiert sich an https://github.com/serilog/serilog-aspnetcore. Der Grund hierfür ist, dass wir den Zugriff auf eine Logger-Instanz so früh wie möglich beim Anwendnungsstart erhalten.

Folgende Pakete werden typischerweise für die Verwenung von Serilog in Anwendungen eingesetzt:

  • Serilog.AspNetCore
  • Serilog.Enrichers.Environment
  • Serilog.Settings.Configuration
  • Serilog.Sinks.Console
  • Serilog.Sinks.Http

Die Konfiguration für das Logging erfolgt über die Verwendung einer Erweiterungsmethode in CommonConfiguration.cs des Projektes Store.Shared wie hier gezeigt:

public static Serilog.ILogger CreateSerilogLogger(this IConfiguration configuration, string applicationContext)
{
  string logstashUrl = configuration["Serilog:LogstashUrl"];
  
  return new LoggerConfiguration()
      .MinimumLevel.Verbose()
      .Enrich.WithProperty("ApplicationContext", applicationContext)
      .Enrich.FromLogContext()
      .WriteTo.Console()
      .WriteTo.Http(string.IsNullOrWhiteSpace(logstashUrl) ? "http://logstash:8080" : logstashUrl)
      .ReadFrom.Configuration(configuration)
      .CreateLogger();
}

Folgende Punkte sind dabei erwähnenswert:

  • .Enrich.WithProperty("ApplicationContext", applicationContext) definiert die Eigenschaft ApplicationContext die for alle Einträge entsprechend belegt wird.
  • .Enrich.FromLogContext() ermöglicht uns, überall dort wo benötigt, einen eigenen Log-Kontext zu definieren.
  • .ReadFrom.Configuration(configuration) ermöglicht das Überschreiben der Standardkonfiguration aus der appsettings.json, z.B. mittels Umgebungsvariablen, was uns gerade beim Einsatz von Containern entgegenkommt.

Der folgende JSON Auszug zeigt die in der Beispielanwendung typische Standardardkonfiguration für das Logging in der appsettings.json:

{
  "Serilog": {
    "LogstashUrl": null,
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning",
        "Microsoft.Hosting.Lifetime": "Information",
        "System": "Warning"
      }
    }
  }
}

Der vorherige JSON Auzug zeigt wie das MinimumLevel für Log-Einträge, entsprechend den Namensräume anhand der Eigenschaft SourceContext, gesetzt wird. So werden standardmässig alle Einträge vom Level Information oder höher, mit Ausnahme für die Namensräume Microsoft.* and System.* protokolliert. Dabei wird für den Namensraum Microsoft.Hosting.Lifetime erneut eine Ausnahme definiert, die wieder Information als Level angibt.

Kibana

Wir verwenden Kibana als weiterern Container über folgende docker-compose Konfiguration:

# In docker-compose.yml
services:
  kibana:
    build:
      context: elk/kibana/
    depends_on:
      - elasticsearch

# in docker-compose.override.yml
  kibana:
    ports:
      - "5601:5601"
    volumes:
      - ./elk/kibana/config/:/usr/share/kibana/config:ro

Mit der o.a. Konfiguration ist Kibana an der Adresse http://localhost:5601 verfügbar.

Wichtiger Hinweis zur Konfiguration

In Produktionsumgebungen sollte das Logging dahingehend konfiguriert werden, dass die Einträge in der Anzahl und Zeit der Aufbewahrung beschränkt werden.

Zusätzliche Quellen

Workshop

Einführung

Anleitung

Übungen

Clone this wiki locally