ClawdDotNet/tests/ClawdDotNet.App.Tests/Services/LogTailTests.cs

using ClawdDotNet.App.Services;
using Shouldly;

namespace ClawdDotNet.App.Tests.Services;

/// <summary>
/// #376: Every module writes into its own file, and collection happened file by
/// file — i.e. alphabetically by module name. In the log view the lines thus stood
/// in blocks per module instead of in the order in which they came into being.
/// Observed was a line from 14:34:40 above four lines from 14:34:39.
///
/// The file system is not abstracted here: <see cref="LogTail"/> is exactly the
/// handling of real files that grow alongside — an abstraction would hide the
/// behavior this is about.
/// </summary>
public sealed class LogTailTests : IDisposable
{
    private readonly string _logDirectory;
    private readonly string _today;

    public LogTailTests()
    {
        _logDirectory = Path.Combine(
            Path.GetTempPath(), "clawd-tests", Guid.NewGuid().ToString("N"), "Logs");

        // LogTail reads exclusively the directory of today, by
        // local time — the writing side creates it the same way.
        _today = Path.Combine(_logDirectory, DateTime.Now.ToString("yyyy-MM-dd"));
        Directory.CreateDirectory(_today);
    }

    public void Dispose()
    {
        try { Directory.Delete(Path.GetDirectoryName(_logDirectory)!, recursive: true); }
        catch { /* Cleaning up is secondary */ }
    }

    private void Write(string module, params string[] lines)
        => File.AppendAllLines(Path.Combine(_today, $"{module}.log"), lines);

    private LogTail Tail() => new(_logDirectory);

    // ═══════════════════════════════════════════════════════════
    //  Order across module files
    // ═══════════════════════════════════════════════════════════

    [Fact]
    public void Zeilen_aus_mehreren_Modulen_stehen_in_zeitlicher_Reihenfolge()
    {
        // Exactly the observed case: "Deploymentcenter" comes alphabetically before
        // "Startup", but its line is the most recent of all.
        Write("Deploymentcenter", "[14:34:40.246] [INF] kein Token hinterlegt");
        Write("Startup",
            "[14:34:39.840] [INF] ClawdDotNet startet",
            "[14:34:39.871] [INF] Instanz-Verzeichnis",
            "[14:34:40.238] [WRN] Kein OpenRouter API-Key konfiguriert");

        var lines = Tail().ReadNew();

        lines.Select(l => l.Text).ShouldBe([
            "[14:34:39.840] [INF] ClawdDotNet startet",
            "[14:34:39.871] [INF] Instanz-Verzeichnis",
            "[14:34:40.238] [WRN] Kein OpenRouter API-Key konfiguriert",
            "[14:34:40.246] [INF] kein Token hinterlegt"
        ]);
    }

    [Fact]
    public void Bei_gleichem_Zeitstempel_bleibt_die_bisherige_Ordnung()
    {
        // Sorted stably: two lines of the same millisecond must not swap
        // places, otherwise a coherent sequence within a module falls apart.
        //
        // Across module files the module name then decides — "Alpha" before "Beta".
        // Directory.GetFiles returns the directory order under Linux; without the
        // sorting in ReadNew something different would stand here from run to run.
        Write("Alpha", "[10:00:00.000] [INF] alpha eins", "[10:00:00.000] [INF] alpha zwei");
        Write("Beta", "[10:00:00.000] [INF] beta eins");

        var lines = Tail().ReadNew();

        lines.Select(l => l.Text).ShouldBe([
            "[10:00:00.000] [INF] alpha eins",
            "[10:00:00.000] [INF] alpha zwei",
            "[10:00:00.000] [INF] beta eins"
        ]);
    }

    [Fact]
    public void Ein_Stacktrace_bleibt_bei_seiner_Meldung()
    {
        // An exception hangs its lines without their own timestamp below the message.
        // Without special handling they would have slipped to the very front without a key.
        Write("Alpha", "[10:00:00.500] [INF] danach");
        Write("Engine",
            "[10:00:00.100] [ERR] Aufruf fehlgeschlagen",
            "System.InvalidOperationException: kaputt",
            "   bei ClawdDotNet.Engine.Run()");

        var lines = Tail().ReadNew();

        lines.Select(l => l.Text).ShouldBe([
            "[10:00:00.100] [ERR] Aufruf fehlgeschlagen",
            "System.InvalidOperationException: kaputt",
            "   bei ClawdDotNet.Engine.Run()",
            "[10:00:00.500] [INF] danach"
        ]);
    }

    [Fact]
    public void Ein_Stacktrace_bleibt_auch_ueber_die_Taktgrenze_bei_seiner_Meldung()
    {
        // The tick can end in the middle of an entry: the message has been read, the
        // continuation only comes with the next call. The timestamp must then be carried over from
        // the previous tick.
        var tail = Tail();

        Write("Engine", "[10:00:00.100] [ERR] Aufruf fehlgeschlagen");
        tail.ReadNew();

        Write("Alpha", "[10:00:00.500] [INF] danach");
        Write("Engine", "   bei ClawdDotNet.Engine.Run()");

        var lines = tail.ReadNew();

        lines.Select(l => l.Text).ShouldBe([
            "   bei ClawdDotNet.Engine.Run()",
            "[10:00:00.500] [INF] danach"
        ]);
    }

    [Fact]
    public void Eine_Uhrzeit_mitten_in_der_Meldung_ist_kein_Sortierschluessel()
    {
        // What is looked for is the timestamp at the start of the line, not any time in the text.
        Write("Alpha", "[10:00:00.100] [INF] naechster Lauf um [23:59:59.999]");
        Write("Beta", "[10:00:00.200] [INF] danach");

        var lines = Tail().ReadNew();

        lines.Select(l => l.Text).ShouldBe([
            "[10:00:00.100] [INF] naechster Lauf um [23:59:59.999]",
            "[10:00:00.200] [INF] danach"
        ]);
    }

    // ═══════════════════════════════════════════════════════════
    //  What the sorting must not break
    // ═══════════════════════════════════════════════════════════

    [Fact]
    public void Nur_das_Neue_kommt_zurueck()
    {
        var tail = Tail();

        Write("Alpha", "[10:00:00.100] [INF] erste");
        tail.ReadNew().Count.ShouldBe(1);

        Write("Alpha", "[10:00:00.200] [INF] zweite");
        tail.ReadNew().Select(l => l.Text).ShouldBe(["[10:00:00.200] [INF] zweite"]);
    }

    [Fact]
    public void Der_Modulfilter_laesst_nur_sein_Modul_durch()
    {
        Write("Alpha", "[10:00:00.100] [INF] alpha");
        Write("Beta", "[10:00:00.200] [INF] beta");

        var lines = Tail().ReadNew(module: "Beta");

        lines.Select(l => l.Text).ShouldBe(["[10:00:00.200] [INF] beta"]);
    }

    [Fact]
    public void Eine_weggefilterte_Zeile_traegt_ihren_Zeitstempel_trotzdem_weiter()
    {
        // The level filter must not lose the assignment of the continuation lines:
        // the message drops out, its stack trace does not — it has no level of its own and
        // is deliberately let through. It must then stand in the message's place.
        Write("Alpha", "[10:00:00.500] [ERR] spaeter Fehler");
        Write("Engine",
            "[10:00:00.100] [INF] harmlos",
            "   Fortsetzung ohne Stufe");

        var lines = Tail().ReadNew(level: LogLevelFilter.Error);

        lines.Select(l => l.Text).ShouldBe([
            "   Fortsetzung ohne Stufe",
            "[10:00:00.500] [ERR] spaeter Fehler"
        ]);
    }

    [Fact]
    public void Ohne_Tagesverzeichnis_kommt_eine_leere_Liste()
    {
        Directory.Delete(_today, recursive: true);

        Tail().ReadNew().ShouldBeEmpty();
    }
}