Eigenes Logging-System: Sinks, Logger und MemorySink (Teil 10)

Warum einen eigenen Logger bauen, wenn es fertige Lösungen wie Microsoft.Extensions.Logging, Serilog oder NLog gibt? In EchoPlay hat das konkrete Gründe: Volle Kontrolle über das Format, keine Drittanbieter-Abhängigkeiten in der Kerninfrastruktur, und ein spezielles Feature — der MemorySink, der Log-Einträge im RAM hält und in der Settings-UI anzeigt.

Die Architektur: Sinks, Logger, Manager

Der EchoPlay-Logger ist in drei Schichten aufgeteilt. Sinks nehmen Log-Einträge entgegen und schreiben sie irgendwo hin: in eine Datei, in die Debug-Konsole, oder in einen Ring-Buffer im Speicher. Logger koordinieren das Schreiben — ein Logger-Objekt hat eine Kategorie (z.B. "SeriesDataService") und eine Liste von Sinks. Wenn man _logger.Info("...") aufruft, erstellt der Logger einen LogEntry und sendet ihn an alle Sinks. Der LoggerManager hält alles zusammen: Er erzeugt Logger, verwaltet die Sinks und ist für das Cleanup (z.B. Datei schließen) zuständig.

ILogger: Die Schnittstelle

public interface ILogger
{
    void Trace(string message);
    void Debug(string message);
    void Info(string message);
    void Warning(string message);
    void Error(string message, Exception? exception = null);
    void Fatal(string message, Exception? exception = null);
    LogScope BeginScope(string name);
}

Alle Services in EchoPlay arbeiten nur mit ILogger — einem Interface. Die konkrete Logger-Klasse kennen sie nicht. Das erlaubt es, in Tests eine eigene ILogger-Implementierung zu injizieren — zum Beispiel einen Fake, der alle Einträge in einer Liste sammelt und am Ende des Unit-Tests prüfbar macht.

Logger: Verteilung an Sinks

private async Task LogAsync(LogLevel level, string message, Exception? exception = null)
{
    if (level < _minimumLevel)
    {
        return;
    }

    LogEntry entry = new(
        Timestamp: DateTime.Now,
        Level: level,
        Message: message,
        Category: _category,
        Scopes: LogScopeManager.CurrentScopes,
        Exception: exception
    );

    foreach (ILogSink sink in _sinks)
    {
        try
        {
            await sink.WriteAsync(entry).ConfigureAwait(false);
        }
        catch (Exception ex)
        {
            // Sink-Fehler dürfen nie die Anwendung crashen
            System.Diagnostics.Debug.WriteLine($"Logger: Sink-Fehler: {ex.Message}");
        }
    }
}

Der frühzeitige Abbruch ist entscheidend: Wenn das Log-Level unter dem konfigurierten Minimum liegt, wird sofort zurückgekehrt. Ein Debug-Statement, das in Production auf Information-Level konfiguriert ist, kostet fast nichts. Die Fehlerresilienz bei Sinks ist genauso wichtig — wenn ein Sink fehlschlägt, zum Beispiel die Datei-Ausgabe wegen eines vollen Speichers, darf das die Anwendung nicht zum Absturz bringen. Der Fehler wird in die Debug-Konsole geschrieben (die kein Sink ist), und die anderen Sinks erhalten den Eintrag trotzdem.

LogScope: Kontext für zusammengehörige Operationen

Manchmal will man nicht nur eine Nachricht loggen, sondern einen Kontext mitgeben — einen LogScope: Diese 5 Logzeilen gehören zur Datenbankoperation DB:Series:Delete:123. Das macht Log-Auswertungen deutlich einfacher.

public sealed class LogScope : IDisposable
{
    private readonly string _name;

    public LogScope(string name)
    {
        _name = name;
        LogScopeManager.PushScope(name);
    }

    public void Dispose()
    {
        LogScopeManager.PopScope(_name);
    }
}

Die Verwendung ist denkbar einfach:

using (EchoPlay.Logger.Scoping.LogScope scope = _logger.BeginScope("DB:Series:Delete"))
{
    _logger.Debug("Lade Serie...");
    _logger.Info("Serie gelöscht.");
} // Scope wird automatisch beendet

LogScopeManager verwaltet einen threadlokalen Stack von Scope-Namen. Jeder LogEntry enthält eine Momentaufnahme des aktuellen Stacks. So sieht man in den Logs, in welchem Kontext eine Nachricht entstanden ist.

MemorySink: Log-Einträge in der UI anzeigen

Ein besonderes Feature von EchoPlay: Die letzten 100 Log-Einträge sind in der Settings-UI unter „Protokoll“ sichtbar. Das ermöglicht es Nutzern, selbst nachzusehen, was die Anwendung zuletzt gemacht hat — ohne in Logdateien zu suchen. Der MemorySink ist ein Ring-Buffer: Er hält die letzten N Einträge im Arbeitsspeicher. Wenn er voll ist, fällt der älteste Eintrag raus.

public sealed class MemorySink : ILogSink
{
    private readonly Queue<LogEntry> _entries;
    private readonly int _capacity;
    private readonly object _lock = new();

    public MemorySink(int capacity)
    {
        _capacity = capacity;
        _entries = new Queue<LogEntry>(capacity);
    }

    public Task WriteAsync(LogEntry entry)
    {
        lock (_lock)
        {
            if (_entries.Count >= _capacity)
            {
                _entries.Dequeue(); // Ältesten Eintrag entfernen
            }
            _entries.Enqueue(entry);
        }
        return Task.CompletedTask;
    }

    public IReadOnlyList<LogEntry> GetEntries()
    {
        lock (_lock)
        {
            return _entries.ToList();
        }
    }
}

Der lock ist notwendig, weil Logger aus verschiedenen Threads aufgerufen werden können — der MemorySink muss threadsicher sein.

Konfiguration via DI

builder.Services.AddEchoPlayLogger(options =>
{
    options.LogDirectory = "logs";
    options.MaxFileSizeMb = 10;
    options.RetentionDays = 30;
    options.MinimumLevel = EchoPlay.Logger.Models.LogLevel.Debug;
    options.EnableMemorySink = true;
    options.MemorySinkCapacity = 100;
});

AddEchoPlayLogger registriert alle nötigen Sinks, die LoggerFactory und den LoggerManager im DI-Container. Jeder Service, der ILoggerFactory injiziert bekommt, kann damit Logger erstellen:

private readonly ILogger _logger = loggerFactory.CreateLogger("SeriesDataService");

Die Kategorie ("SeriesDataService") erscheint in jedem Log-Eintrag und hilft, Einträge verschiedener Services zu unterscheiden.

Live-Protokoll: Events statt Polling

Die Protokoll-Seite in EchoPlay zeigt neue Log-Einträge in Echtzeit — ohne Polling, ohne Timer. Das Schlüsselkonzept ist ein Event auf dem MemorySink. Neben ILogSink (Schreiben) gibt es ILiveLogSink (Benachrichtigen). MemorySink implementiert beide. Das Event wird nach dem Schreiben, aber außerhalb des Locks gefeuert:

public Task WriteAsync(LogEntry entry)
{
    lock (_lock)
    {
        if (_entries.Count >= _capacity)
            _entries.Dequeue();
        _entries.Enqueue(entry);
    }

    // Außerhalb des Locks – Subscriber dürfen GetEntries() aufrufen
    LogEntryAdded?.Invoke(entry);
    return Task.CompletedTask;
}

Warum außerhalb des Locks? Weil ein Subscriber im Event-Handler GetEntries() aufrufen könnte, das selbst den Lock braucht. Würde das Event innerhalb des Locks gefeuert, wäre das ein klassischer Deadlock.

ViewModel abonniert das Event

Das ProtokollViewModel abonniert das Event beim Betreten der Seite und kündigt beim Verlassen:

// OnNavigatedTo in der Page
ViewModel.Activate(DispatcherQueue);

// OnNavigatedFrom in der Page
ViewModel.Deactivate();

Im ViewModel selbst sieht das so aus:

public void Activate(DispatcherQueue queue)
{
    _dispatcherQueue = queue;
    _memorySink.LogEntryAdded += OnNewEntry;
    LoadCurrentEntries();
}

private void OnNewEntry(LogEntry entry)
{
    _dispatcherQueue.TryEnqueue(() =>
    {
        LogEntries.Insert(0, Map(entry));

        // Ältesten Eintrag entfernen sobald das Limit überschritten wird
        if (LogEntries.Count > 500)
            LogEntries.RemoveAt(LogEntries.Count - 1);
    });
}

Das Event wird asynchron auf einem Hintergrund-Thread gefeuert — dem Thread, der WriteAsync aufgerufen hat. DispatcherQueue.TryEnqueue wechselt sicher auf den UI-Thread, bevor die ObservableCollection geändert wird. Das ist der korrekte Weg in WinUI 3. In WPF gibt es Dispatcher.RunAsync, in WinUI 3 heißt das Äquivalent DispatcherQueue.TryEnqueue. Der Unterschied: TryEnqueue kann scheitern, wenn die DispatcherQueue bereits abgebaut wurde (z.B. nach dem Schließen des Fensters). Ein gescheitertes TryEnqueue ist kein Fehler — es ist die sichere Reaktion auf einen bereits abgebauten UI-Thread.

Live-Toggle

Ein ToggleSwitch in der UI steuert, ob neue Einträge automatisch erscheinen. Wird Live reaktiviert, werden zunächst alle gepufferten Einträge aus dem MemorySink geladen, dann das Event-Abonnement gestartet. So gibt es keine Lücke zwischen dem letzten gepufferten Eintrag und dem ersten Live-Eintrag:

// Erst abonnieren, dann laden – kein Eintrag kann verloren gehen
_memorySink.LogEntryAdded += OnNewEntry;
LoadCurrentEntries();

Was nicht gemacht werden sollte

// FALSCH: Console.WriteLine ist in produktivem Code verboten
Console.WriteLine($"Serie geladen: {series.Title}");

// RICHTIG
_logger.Info($"Serie '{series.Title}' geladen.");

Console.WriteLine erscheint weder in der Log-Datei noch im MemorySink. Es verschwindet in der MSIX-gepackten App sowieso, weil es kein Konsolenfenster gibt. Alles, was protokolliert werden soll, muss durch den Logger laufen.

// FALSCH: Exception-Details verschlucken
_logger.Error("Fehler.");

// RICHTIG: Exception mitloggen
_logger.Error("Soft-Delete fehlgeschlagen.", ex);

Ohne die Exception gibt es keine Stack Trace, keine Zeilennummer, keine Information darüber, was schiefgelaufen ist. Die Error– und Fatal-Methoden nehmen eine optionale Exception entgegen — sie sollte immer mitgegeben werden.