April 2016

Band 31, Nummer 4

.NET-Grundlagen: Protokollieren mit .NET Core

Von Mark Michaelis

In der Ausgabe vom Februar habe ich mich ausgiebig mit der neuen Konfigurations-API befasst, die zur neu benannten .NET Core 1.0-Plattform gehört (siehe bit.ly/1OoqmkJ). (Ich gehe davon aus, dass die meisten von Ihnen von der vor Kurzem erfolgten Umbenennung von NET Core 5, das Teil der ASP.NET 5-Plattform war [siehe bit.ly/1Ooq7WI], in .NET Core 1.0 gehört haben.) In jenem Artikel habe ich Komponententests verwendet, um die „Microsoft.Extensions.Configuration“-API zu untersuchen. In diesem Artikel wähle ich einen ähnlichen Ansatz, doch dieses Mal mit der „Microsoft.Extensions.Logging“-API. Der Hauptunterschied besteht darin, dass der Test basierend auf einer CSPROJ-Datei von .NET 4.6 anstatt auf einem ASP.NET Core-Projekt erfolgt. Dies unterstreicht die Tatsache, dass .NET Core Ihnen sofort zur Verfügung steht, auch wenn Sie noch nicht zu ASP.NET Core-Projekten migriert sind.

Protokollierung? Warum brauchen wir unbedingt ein neues Protokollierungsframework? Es gibt doch schon NLog, Log4Net, Loggr, Serilog und das integrierte „Microsoft.Diagnostics.Trace/Debug/TraceSource“-Framework, um nur einige zu nennen. Die Tatsache, dass es bereits so viele Protokollierungsframeworks gibt, ist sogar einer der wesentlichen Faktoren für die Relevanz von„Microsoft.Extensions.Logging“. Als Entwickler mit einer Vielzahl von Auswahlmöglichkeiten wählen Sie zunächst eines aus und wissen, dass Sie später ggf. zu einem anderen wechseln müssen. Deshalb sind Sie wahrscheinlich versucht, einen eigenen Wrapper für die Protokollierungs-API zu schreiben, der das bestimmte Protokollierungsframework aufruft, das von Ihnen oder Ihrem Unternehmen in dieser Woche gewählt wurde. Möglich ist auch, dass Sie ein bestimmtes Protokollierungsframework in Ihrer Anwendung verwenden, um dann festzustellen, dass eine der Bibliotheken, die Sie nutzen, ein anderes verwendet. Deshalb müssen Sie einen Listener schreiben, der die Meldungen von einem zum anderen überträgt.

Mit „Microsoft.Extensions.Logging“ bietet Microsoft genau diesen Wrapper, damit Entwickler keinen eigenen schreiben müssen. Dieser Wrapper bietet eine Gruppe von APIs, die an den Anbieter Ihrer Wahl weitergeleitet werden. Microsoft hat bereits Anbieter für die Konsole (Microsoft.Extensions.Logging.Console), das Debugging (Microsoft.Extensions.Logging.Debug), das Ereignisprotokoll (Microsoft.Extensions.Logging.EventLog) und TraceSource (Microsoft.Estensions.Logging.TraceSource) im Angebot. Nach einer Zusammenarbeit mit verschiedenen Entwicklungsteams von Protokollierungsframework (einschließlich Drittanbietern wie u. a. NLog, Serilog, Loggr und Log4Net) werden jetzt auch mit „Microsoft.Extensions.Logging“ kompatible Anbieter zur Verfügung gestellt.

Erste Schritte

Der Ausgangspunkt der Protokollierungsaktivität ist eine Protokollierungsfactory (siehe Abbildung 1).

Abbildung 1: Verwendung von „Microsoft.Extensions.Logging“

public static void Main(string[] args = null)
{
  ILoggerFactory loggerFactory = new LoggerFactory()
    .AddConsole()
    .AddDebug();
  ILogger logger = loggerFactory.CreateLogger<Program>();
  logger.LogInformation(
    "This is a test of the emergency broadcast system.");
}

Wie der Code zeigt, beginnen Sie mit der Instanziierung einer „Microsoft.Extensions.Logging.LoggerFactory“, die „ILoggerFactory“ im selben Namespace implementiert. Als Nächstes geben Sie an, welche Anbieter Sie verwenden möchten, indem Sie die Erweiterungsmethode von „ILoggerFactory“ nutzen. In Abbildung 1 verwende ich insbesondere „Microsoft.Extensions.Logging.ConsoleLoggerExtensions.AddConsole“ und „Microsoft.Extensions.Log­ging.DebugLoggerFactoryExtensions.AddDebug“. (Wenngleich beide Klassen im „Microsoft.Extensions.Logging“-Namespace enthalten sind, befinden sie sich tatsächlich in den NuGet-Paketen „Microsoft.Extensions.Log­ging.Console“ und „Microsoft.Extensions.Logging.Debug“.)

Die Erweiterungsmethoden sind schlicht bequeme Abkürzungen zum Hinzufügen eines Anbieters – „ILoggerFactory.AddProvider“ ­- („ILoggerProvider“-Anbieter). Die Abkürzung besteht darin, dass die „AddProvider“-Methode eine Instanz des Protokollanbieters benötigt (wahrscheinlich eine, deren Konstruktor einen Filterausdruck für den Protokolliergrad verlangt), während die Erweiterungsmethoden Standardwerte für solche Ausdrücke liefern. Die Konstruktorsignatur für „ConsoleLoggerProvider“ ist z. B.:

public ConsoleLoggerProvider(Func<string, LogLevel, bool> filter,
  bool includeScopes);

Der erste Parameter ist ein Prädikatsausdruck, mit dem Sie basierend auf dem Wert des protokollierten Texts und des Protokolliergrads festlegen können, ob eine Meldung in der Ausgabe aufgeführt wird.

Sie können beispielsweise „AddProvider“ mit einer besonderen „Console­LoggerProvider“-Instanz aufrufen, die anhand eines Filters aller Meldungen mit einer höheren Bedeutung als „LogLevel.Information“ erstellt wurde:

loggerFactory.AddProvider(
  new ConsoleLoggerProvider(
    (text, logLevel) => logLevel >= LogLevel.Verbose , true));

(Interessanterweise gibt „AddProvider“ im Gegensatz zu den Erweiterungsmethoden, die „ILoggerFactory“ zurückgeben, „void“ zurück, was die in Abbildung 1 gezeigte flüssige Typsyntax verhindert.)

Sehr wichtig ist der Hinweis, dass es leider eine gewisse Inkonsistenz bei Protokollanbietern dahingehend gibt, ob ein hoher Protokolliergradwert mehr oder weniger aussagekräftig ist. Sagt der Protokolliergrad 6 aus, dass ein kritischer Fehler aufgetreten ist, oder handelt es sich bloß um eine ausführliche Diagnosemeldung? „Microsoft.Extensions.Logging.LogLevel“ verwendet hohe Werte zum Angeben einer höheren Priorität mithilfe der folgenden „enum“-Deklaration für „LogLevel“:

public enum LogLevel
{
  Debug = 1,
  Verbose = 2,
  Information = 3,
  Warning = 4,
  Error = 5,
  Critical = 6,
  None = int.MaxValue
}

Durch Instanziieren eines „ConsoleLoggerProvider“, der Meldungen nur ausgibt, wenn „logLevel >= LogLevel.Verbose“, schließen Sie deshalb nur Meldungen auf der Debugstufe vom Schreiben in die Ausgabe aus.

Sie können der Protokollfactory mehrere Anbieter und sogar mehrere Anbieter desselben Typs hinzufügen. Wenn ich z. B. einen Aufruf von „ILoggerFactory.AddProvider“ zu Abbildung 1 hinzufüge, wird durch einen Aufruf von „ILogger.LogInformation“ eine Meldung zweimal in der Konsole angezeigt. Der erste Konsolenanbieter (der von „AddConsole“ hinzugefügt wurde) zeigt standardmäßig „LogLevel.Information“ oder höher an. Ein Aufruf von „ILogger.LogVerbose“ wird hingegen nur einmal angezeigt, da nur der zweite (über die „AddProvider“-Methode hinzugefügte) Anbieter erfolgreich vermeidet, herausgefiltert zu werden.

Protokollierungsmuster

Wie Abbildung 1 zeigt, ist der Ausgangspunkt der gesamten Protokollierung eine Protokollfactory, aus der Sie über die „ILoggerFactory.CreateLogger<T>“-Methode einen „ILogger“ anfordern können. Der allgemeine Typ „T“ in dieser Methode dient zum Bestimmen der Klasse, in der der Code ausgeführt wird. Deshalb ist es möglich, den Namen der Klasse auszugeben, in den die Protokollierung Meldungen schreibt. Durch Aufrufen von „loggerFactory.CreateLogger<Program>“ lösen Sie also eine Protokollierung spezifisch für die „Program“-Klasse aus, sodass jedes Mal, wenn eine Meldung geschrieben wird, es auch möglich ist, den Ausführungskontext so wie innerhalb der „Program“-Klasse zu schreiben. Demnach lautet die Konsolenausgabe von Abbildung 1 wie folgt:

info: SampleWebConsoleApp.Program[0]
      This is a test of the emergency broadcast system.

Diese Ausgabe basiert auf Folgendem:

• „info“ resultiert aus der Tatsache, dass dies der Aufruf einer „LogInformation“-Methode ist.
• „SampleWebConsoleApp.Program“ wird von „T“ bestimmt.
• „[0]“ ist die Ereignis-ID (ein Wert, den ich nicht angegeben habe, der deshalb standardmäßig 0 ist).
• „This is a test of the emergency broadcast system.“ ist das an „LogInformation“ übergebene „messages“-Argument .

Da der Wert „Program“ einen Kontext auf Klassenebene angibt, instanziieren Sie wahrscheinlich eine andere Protokollierungsinstanz für jede Klasse, mit deren Hilfe Sie protokollieren möchten. Wenn z. B. „Program“ eine „Controller“-Klasseninstanz erstellt und aufruft, benötigen Sie eine neue Protokollierungsinstanz innerhalb der „Controller“-Klasse, die über einen anderen Methodenaufruf erstellt wurde, bei dem „T“ nun „Controller“ ist:

loggerFactory.CreateLogger<Controller>()

Wie Sie ggf. bemerken, erfordert dies Zugriff auf dieselbe Protokollierungsfactoryinstanz, für die die Anbieter zuvor konfiguriert waren. Während es vorstellbar ist, dass Sie die Protokollierungsfactoryinstanz an jede Klasse übergeben, über die Sie eine Protokollierung durchführen möchten, würden Sie rasch in Schwierigkeiten geraten und ein Refactoring erwägen.

Die Lösung ist das Speichern einer einzelnen statischen „ILoggerFactory“ als statische Eigenschaft, die für alle Klassen verfügbar ist, wenn die spezifische „ILogger“-Instanz ihres Objekts instanziiert wird. Ziehen Sie beispielsweise das Hinzufügen einer statischen „ApplicationLogging“-Klasse in Betracht, die eine statische „ILoggerFactory“-Instanz enthält:

public static class ApplicationLogging
{
  public static ILoggerFactory LoggerFactory {get;} = new LoggerFactory();
  public static ILogger CreateLogger<T>() =>
    LoggerFactory.CreateLogger<T>();
}

Ein evidenter Aspekt bei einer solchen Klasse ist, ob die „LoggerFactory“ threadsicher ist. Wie die „AddProvider“-Methode in Abbildung 2 zeigt, ist dies glücklicherweise der Fall.

Abbildung 2: Die Implementierung von „Microsoft.Extensions.Logging.LoggerFactory AddProvider“

public void AddProvider(ILoggerProvider provider)
{
  lock (_sync)
  {
    _providers = _providers.Concat(new[] { provider }).ToArray();
    foreach (var logger in _loggers)
    {
      logger.Value.AddProvider(provider);
    }
  }
}

Da die einzigen Daten in der „ILogger“-Instanz vom allgemeinen Typ „T“ bestimmt werden, könnten Sie die Ansicht vertreten, dass jede Klasse einen statischen „ILogger“ haben könnte, den das Objekt jeder Klasse nutzen könnte. Doch vor dem Hintergrund des Programmierungsstandards, der die Threadsicherheit aller statischen Member sicherstellt, würde ein solcher Ansatz eine Steuerung der Nebenläufigkeit in der „ILogger“-Implementierung erfordern (die es standardmäßig nicht gibt) und zu einem erheblichen Engpass führen, während Sperren aktiviert und freigegeben werden. Aus diesem Grund ist die Empfehlung, eine einzelne „ILogger“-Instanz für jede Instanz einer Klasse vorzusehen. Das Ergebnis ist eine „ILogger“-Eigenschaft für jede Klasse, für die die Protokollierung unterstützt werden soll (siehe Abbildung 3).

Abbildung 3: Hinzufügen einer „ILogger“-Instanz zu jedem Objekt, das eine Protokollierung erfordert

public class Controller
{
  ILogger Logger { get; } =
    ApplicationLogging.CreateLogger<Controller>();
  // ...
  public void Initialize()
  {
    using (Logger.BeginScopeImpl(
      $"=>{ nameof(Initialize) }"))
    {
      Logger.LogInformation("Initialize the data");
      //...
      Logger.LogInformation("Initialize the UI");
      //...
    }
  }
}

Grundlegendes zum „Scope“-Konzept

Häufig unterstützen Anbieter das „Scope“-Konzept insofern, dass Sie beispielsweise protokollieren können, wie Ihr Code eine Aufrufkette durchläuft. Wenn zur Fortsetzung dieses Beispiels „Program“ eine Methode für eine „Controller“-Klasse aufruft, instanziiert diese Klasse wiederum ihre eigene Protokollierungsinstanz mit ihrem eigenen Kontext des Typs „T“. Doch anstatt einfach einen Meldungskontext des Typs „info: SampleWebConsoleApp.Program[0]“ gefolgt von „info: SampleWebConsoleApp.Controller[0]“ anzuzeigen, möchten Sie ggf. den von „Program“ aufgerufenen Controller protokollieren und möglicherweise sogar die Methodennamen selbst einbeziehen. Um dies zu erreichen, aktivieren Sie das „Scope“-Konzept innerhalb des Anbieters. Abbildung 3 zeigt ein Beispiel in der „Initialize“-Methode über den Aufruf von „Logger.BeginScopeImpl“.

Das Verwenden des Protokollierungsmusters bei gleichzeitiger Aktivierung von „Scope“ führt zu einer „Program“-Klasse, die ungefähr so wie in Abbildung 4 aussieht.

Abbildung 4: Aktualisierte Implementierung von „Program“

public class Program
{
  static ILogger Logger { get; } =
    ApplicationLogging.CreateLogger<Program>();
  public static void Main(string[] args = null)
  {
    ApplicationLogging.LoggerFactory.AddConsole(true);
    Logger.LogInformation(
      "This is a test of the emergency broadcast system.");
    using (Logger.BeginScopeImpl(nameof(Main)))
    {
      Logger.LogInformation("Begin using controller");
      Controller controller = new Controller();
      controller.Initialize();
      Logger.LogInformation("End using controller");
    }
    Logger.Log(LogLevel.Information, 0, "Shutting Down...", null, null);
  }
}

Die Ausgabe von Abbildung 3 kombiniert mit Abbildung 4 wird in Abbildung 5 gezeigt.

Abbildung 5: Ausgabe der Konsolenprotokollierung mit einbezogenen „Scopes“

info: SampleWebConsoleApp.Program[0]
      This is a test of the emergency broadcast system.
info: SampleWebConsoleApp.Program[0]
      => Main
      Begin using controller
info: SampleWebConsoleApp.Controller[0]
      => Main => Initialize
      Initialize the data
info: SampleWebConsoleApp.Controller[0]
      => Main => Initialize
      Initialize the UI
info: SampleWebConsoleApp.Program[0]
      => Main
      End using controller
info: SampleWebConsoleApp.Program[0]
      Shutting down...

Beachten Sie, dass „Scope“ automatisch so entladen wird, dass „Initialize“ oder „Main“ nicht mehr enthalten sind. Diese Funktionalität beruht darauf, dass „BeginScopeImpl“ eine „IDisposable“-Instanz zurückgibt, die „Scope“ automatisch entlädt, sobald die „using“-Anweisung „Dispose“ aufruft.

Verwenden eines Anbieters eines Drittanbieters

Um einige der beliebtesten Protokollierungsframeworks von Drittanbietern verfügbar zu machen, hat Microsoft mit deren Entwicklern zusammengearbeitet und dafür gesorgt, dass es für jedes davon Anbieter gibt. Ohne eine Präferenz vorzugeben, prüfen Sie, wie eine Verbindung mit dem Framework NLog hergestellt wird (siehe Abbildung 6).

Abbildung 6: Konfigurieren von NLog als „Microsoft.Extensions.Logging Provider“

[TestClass]
public class NLogLoggingTests
{
  ILogger Logger {get;}
    = ApplicationLogging.CreateLogger<NLogLoggingTests>();
  [TestMethod]
  public void LogInformation_UsingMemoryTarget_LogMessageAppears()
  {
    // Add NLog provider
    ApplicationLogging.LoggerFactory.AddNLog(
      new global::NLog.LogFactory(
        global::NLog.LogManager.Configuration));
    // Configure target
    MemoryTarget target = new MemoryTarget();
    target.Layout = "${message}";
    global::NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(
      target, global::NLog.LogLevel.Info);
    Logger.LogInformation(Message);
     Assert.AreEqual<string>(
      Message, target.Logs.FirstOrDefault<string>());
  }
}

Wenn Sie mit NLog vertraut sind, ist Ihnen der Großteil des Codes bekannt. Zuerst instanziiere und konfiguriere ich ein NLog-Ziel des Typs „NLog.Targets.MemoryTarget“. (Es gibt zahlreiche NLog-Ziele, die alle in der NLog-Konfigurationsdatei bestimmt und konfiguriert werden können, und zwar zusätzlich zum Verwenden des Konfigurationscodes in Abbildung 6.) Wenngleich ähnlich im Aussehen, wird „Layout“ der Literalwert „${message}“ und kein Wert mit Zeichenfolgeninterpolation zugewiesen.

Nach seiner Hinzufügung zu „LoggerFactory“ und Konfiguration ist der Code identisch mit dem gesamten anderen Anbietercode.

Ausnahmebehandlung

Einer der gängigsten Gründe für die Protokollierung ist das Aufzeichnen, wann eine Ausnahme ausgelöst wird, d. h. wann die Ausnahme behandelt anstatt erneut ausgelöst wird oder wann die Ausnahme gänzlich unbehandelt bleibt (siehe bit.ly/1LYGBVS). Wie erwartet, bietet „Microsoft.Extensions.Logging“ besondere Methoden zum Behandeln einer Ausnahme. Die meisten dieser Methoden sind in „Microsoft.Extensions.Logging.LoggerExtensions“ als Erweiterungsmethoden für „ILogger“ implementiert. Ausgehend von dieser Klasse wird jede Methode implementiert, die für einen bestimmten Protokollierungsgrad (ILogger.LogInformation, ILogger.LogDebug, ILogger.LogCritical usw.) spezifisch ist. Wenn Sie z. B. eine „LogLevel.Critical“-Meldung zu einer Ausnahme protokollieren möchten (ehe Sie die Anwendung ordnungsgemäß herunterfahren), rufen Sie Folgendes auf:

Logger.LogCritical(message,
  new InvalidOperationException("Yikes..."));

Ein weiterer wichtiger Aspekt der Protokollierung und Ausnahmebehandlung ist, dass die Protokollierung, insbesondere bei der Behandlung von Ausnahmen, keine Ausnahme auslösen darf. Wenn bei der Protokollierung eine Ausnahme ausgelöst wird, wird die Meldung oder Ausnahme vermutlich nicht ausgegeben und ungeachtet ihres Schweregrads möglicherweise unbeachtet bleiben. Leider bietet die standardmäßige „ILogger“-Implementierung (Microsoft.Extensions.Logging.Logger) keine solche Ausnahmebehandlung. Wenn also eine Ausnahme auftritt, muss sie vom aufrufenden Code behandelt werden, und zwar immer wenn „Logger.LogX“ aufgerufen wird. Eine Lösungsmöglichkeit ist ggf. das Umschließen von „Logger“, um die Ausnahme abzufangen. Sie können jedoch auch eigene Versionen von „ILogger“ und „ILoggerFactory“ implementieren (ein Beispiel finden Sie unter bit.ly/1LYHq0Q). Da .NET Core eine Open-Source-Lösung ist, können sie sogar die Klasse klonen und die Ausnahmebehandlung mit Absicht in Ihre eigenen „LoggerFactory“- und „ILogger“-Implementierungen integrieren.

Zusammenfassung

Am Anfang habe ich die Frage gestellt, warum wir unbedingt noch ein Protokollierungsframework in .NET benötigen. Ich hoffe, die Antwort gegeben zu haben. Das neue Framework erstellt eine Abstraktionsebene bzw. einen Wrapper, die/der Ihnen ermöglicht, das Protokollierungsframework zu nutzen, das Sie sich als Anbieter wünschen. Dies stellt Ihre maximale Flexibilität bei der Arbeit als Entwickler sicher. Auch wenn es darüber hinaus nur mit .NET Core verfügbar ist, ist das Verweisen auf NuGet-Pakete für .NET Core wie „Microsoft.Extensions.Logging“ für ein Visual Studio .NET 4.6-Standardprojekt kein Problem.

Mark Michaelis ist der Gründer von IntelliTect und arbeitet als leitender technischer Architekt und Trainer. Seit fast zwei Jahrzehnten ist er ein Microsoft MVP und Microsoft-Regionalleiter seit 2007. Michaelis arbeitet in verschiedenen Microsoft-Softwareentwicklungs-Reviewteams mit, einschließlich C#, Microsoft Azure, SharePoint und Visual Studio ALM. Er hält häufig Vorträge bei Entwicklerkonferenzen und hat viele Bücher geschrieben, einschließlich seines letzten „Essential C# 6.0 (5th Edition)“ (itl.tc/­EssentialCSharp). Sie können ihn auf Facebook unter facebook.com/Mark.Michaelis, über seinen Blog unter IntelliTect.com/Mark, auf Twitter: @markmichaelis oder per E-Mail unter mark@IntelliTect.com erreichen.

Unser Dank gilt den folgenden technischen Experten von IntelliTect für die Durchsicht dieses Artikels: Kevin Bost, Chris Finlayson und Michael Stokesbary