Zeitstempel in (ASP) .NET Core Anwendungen auf der Konsole anzeigen

Die ILogger Schnittstelle ermöglicht das einfache Injizieren eines Loggers in jegliche Klasse. Durch das Protokollieren des Namespace ist stets klar, von welcher Komponente die Informationen stammen. In der appsettings.json können wir für jeden Namespace den Detailgrad einstellen. Dies geht bis hin zu Debug- und Tracelogs, die uns z.B. beim EntityFramework die SQL-Abfragen protokollieren.

Das standardmäßig verfügbare Logging-Komponente ist also recht mächtig. Drittanbieter-Alternativen wie Log4j (die auch nach .NET portiert wurden) müssen daher nicht zwingend eingebunden werden. Doch leider fehlt zumindest bisher noch eine entscheidende Funktion: Zeitstempel. Sämtliche Logeinträge erhalten keinerlei Datums- oder Zeitangaben. Gerade bei längeren Protokollen ist daher nicht mehr nachvollziehbar, wann ein bestimmtes Ereignis geschehen ist. Zur Lösung dieses Problemes gibt es leider auch noch keine Konfigurationseinstellung

Auf den ersten Blick bleibt daher nur der manuelle Weg: Den aktuellen Zeitstempel händisch in den zu protokollierenden Text einfügen

logger.LogInformation($"{DateTime.Now.ToString()} Index-Action aufgerufen");

Automatisierte Zeistempel durch Vererbung

Der händische Weg ist aber umständlich, wenig flexibel und fehleranfällig. Außerdem verschlechtert sich die Lesbarkeit des Codes. Das Problem lässt sich recht einfach, aber nachhaltig durch Vererbung lösen. Wir erstellen eine Klasse TimedLogger<T>, die von ILogger<T> erbt. Hier fügen wir in der generischsten Log-Methode den Zeitstempel ein. Alles andere wird an eine Instanz der Basisklasse weitergegeben.

using System;
using Microsoft.Extensions.Logging;

public class TimedLogger<T> : ILogger<T> {
    private readonly ILogger logger;

    public TimedLogger(ILogger logger) => this.logger = logger;

    public TimedLogger(ILoggerFactory loggerFactory) : this(new Logger<T>(loggerFactory)) { }

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter) =>
        logger.Log(logLevel, eventId, state, exception, (s, ex) => $"[{DateTime.UtcNow:HH:mm:ss.fff}] {formatter(s, ex)}");

    public bool IsEnabled(LogLevel logLevel) => logger.IsEnabled(logLevel);

    public IDisposable BeginScope<TState>(TState state) => logger.BeginScope(state);
}

Das Format kann man natürlich frei anpassen und auf Wunsch auch die Zeitzone des Zielsystemes statt UTC verwenden. Möchte man beispielsweise das Datum im Format 16.05.20 vor der Uhrzeit sehen und die lokale Zeitzone nutzen, kann folgende Formatierung genutzt werden:

DateTime.Now:dd.MM.y, HH:mm:ss.fff

Unsere modifizierte TimedLogger<T> ist nun Einsatzbereit. Allerdings wird sie noch nicht geladen. Wie injizieren wir TimedLogger<T> per Dependency Injection, statt des standardmäßigen Logger<T>? Hierfür gibt es die praktische IServiceCollection Erweiterungsmethode Replace: Sie ersetzt eine bereits registrierte Dienstklasse anhand des Types und erlaubt diese zu Ersetzen.

In Startup.ConfigureServices führen wir damit die Ersetzung durch:

services.Replace(ServiceDescriptor.Singleton(typeof(ILogger<>), typeof(TimedLogger<>)));

Die Erweiterungsmethode befindet sich im Namensraum Microsoft.Extensions.DependencyInjection.Extensions. Nun erhalten alle Klassen, die ILogger<T> referenzieren, unsere eigene Klasse mit den Zeitangaben. Ein weiterer Vorteil dieser Lösung gegenüber anderen Frameworks wie Log4 ist: Bestehender Code muss nicht geändert werden. Haben wir den integrierten Ilogger<T> zuvor bereits genutzt, beispielsweise in einem Controller

public class HomeController : Controller {
    readonly ILogger<HomeController> logger;
    public HomeController(ILogger<HomeController> logger) {
        this.logger = logger;
    }
	
    public IActionResult Index() {
        logger.LogInformation("Index-Action aufgerufen");
        return View();
    }
}

Funktioniert dies aufgrund der Vererbung weiterhin. Nun allerdings mit Zeitstempel.