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 Lines_from_several_modules_are_in_time_order()
    {
        // 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 With_equal_timestamps_the_previous_order_stays()
    {
        // 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 A_stack_trace_stays_with_its_message()
    {
        // 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 A_stack_trace_stays_with_its_message_even_across_the_tick_boundary()
    {
        // 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 A_time_in_the_middle_of_the_message_is_not_a_sort_key()
    {
        // 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 Only_the_new_comes_back()
    {
        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 The_module_filter_only_lets_its_module_through()
    {
        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 A_filtered_out_line_still_passes_on_its_timestamp()
    {
        // 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 Without_day_directory_an_empty_list_comes_back()
    {
        Directory.Delete(_today, recursive: true);

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