felhom-agent/internal/log/log_test.go

package log

import (
	"bytes"
	"fmt"
	"strings"
	"testing"
)

// S1 capture-at-info (the observability pass's load-bearing property): at emit level
// "info" a DEBUG line reaches the ring AND is absent from the stderr stream. Companion
// red-proof: revert the fan-out (New returning a single stderr handler) → the ring
// misses the DEBUG entry → the first assertion fails.
func TestCaptureAtInfo_RingHoldsDebugStderrDoesNot(t *testing.T) {
	var stderr bytes.Buffer
	logger, ring := NewWithWriter(&stderr, "info", 50)

	logger.Debug("netverify: /proc/mounts verdict", "mounted", false)
	logger.Info("netmount: ensured network mount", "name", "nas-media")

	entries, total := ring.Entries(0)
	if total != 2 {
		t.Fatalf("ring holds %d entries, want 2 (DEBUG must be captured at emit level info)", total)
	}
	if entries[0].Level != "DEBUG" || !strings.Contains(entries[0].Message, "proc/mounts verdict") {
		t.Errorf("ring entry 0 = %+v, want the DEBUG verdict line", entries[0])
	}
	if entries[1].Level != "INFO" {
		t.Errorf("ring entry 1 level = %q, want INFO", entries[1].Level)
	}
	if strings.Contains(stderr.String(), "proc/mounts verdict") {
		t.Errorf("stderr contains the DEBUG line at emit level info:\n%s", stderr.String())
	}
	if !strings.Contains(stderr.String(), "ensured network mount") {
		t.Errorf("stderr missing the INFO line:\n%s", stderr.String())
	}
}

// At emit level "debug" both sinks carry the line (journald behavior unchanged).
func TestCaptureAtDebug_BothSinks(t *testing.T) {
	var stderr bytes.Buffer
	logger, ring := NewWithWriter(&stderr, "debug", 50)
	logger.Debug("flow detail", "k", "v")
	if _, total := ring.Entries(0); total != 1 {
		t.Fatalf("ring total = %d, want 1", total)
	}
	if !strings.Contains(stderr.String(), "flow detail") {
		t.Errorf("stderr missing the DEBUG line at emit level debug:\n%s", stderr.String())
	}
}

// The ring wraps: with capacity 5 and 8 writes, the NEWEST 5 survive in order.
func TestRing_WrapKeepsNewest(t *testing.T) {
	var stderr bytes.Buffer
	logger, ring := NewWithWriter(&stderr, "error", 5)
	for i := 0; i < 8; i++ {
		logger.Info(fmt.Sprintf("line-%d", i))
	}
	entries, total := ring.Entries(0)
	if total != 5 || len(entries) != 5 {
		t.Fatalf("total=%d len=%d, want 5", total, len(entries))
	}
	for i, e := range entries {
		want := fmt.Sprintf("line-%d", i+3)
		if !strings.Contains(e.Message, want) {
			t.Errorf("entry %d = %q, want it to contain %q (chronological, newest kept)", i, e.Message, want)
		}
	}
}

// Entries(limit) keeps the most recent `limit` entries.
func TestRing_LimitKeepsNewest(t *testing.T) {
	logger, ring := NewWithWriter(&bytes.Buffer{}, "error", 10)
	for i := 0; i < 6; i++ {
		logger.Info(fmt.Sprintf("line-%d", i))
	}
	entries, _ := ring.Entries(2)
	if len(entries) != 2 || !strings.Contains(entries[1].Message, "line-5") || !strings.Contains(entries[0].Message, "line-4") {
		t.Errorf("Entries(2) = %+v, want the two newest lines", entries)
	}
}

// Lines honors the byte budget by dropping the OLDEST lines (the heartbeat 128 KB cap).
func TestRing_LinesByteBudgetKeepsNewest(t *testing.T) {
	logger, ring := NewWithWriter(&bytes.Buffer{}, "error", 10)
	for i := 0; i < 5; i++ {
		logger.Info(fmt.Sprintf("line-%d %s", i, strings.Repeat("x", 100)))
	}
	all := ring.Lines(0)
	if len(all) != 5 {
		t.Fatalf("uncapped lines = %d, want 5", len(all))
	}
	// Budget for roughly two lines.
	budget := len(all[3]) + len(all[4]) + 2
	capped := ring.Lines(budget)
	if len(capped) >= 5 {
		t.Fatalf("byte budget did not truncate: %d lines", len(capped))
	}
	if !strings.Contains(capped[len(capped)-1], "line-4") {
		t.Errorf("newest line missing after byte cap: %q", capped[len(capped)-1])
	}
}

// The slog text line parser extracts time + level and preserves the remainder verbatim.
func TestParseSlogLine(t *testing.T) {
	e := parseSlogLine(`time=2026-07-11T10:30:00.123+02:00 level=WARN msg="verify failed" code=auth_failed`)
	if e.Level != "WARN" {
		t.Errorf("level = %q, want WARN", e.Level)
	}
	if e.Time.Year() != 2026 || e.Time.Minute() != 30 {
		t.Errorf("time not parsed: %v", e.Time)
	}
	if !strings.Contains(e.Message, `msg="verify failed"`) || !strings.Contains(e.Message, "code=auth_failed") {
		t.Errorf("message lost content: %q", e.Message)
	}
	// A non-slog line degrades to INFO with the line verbatim (never dropped).
	raw := parseSlogLine("plain text line")
	if raw.Level != "INFO" || raw.Message != "plain text line" {
		t.Errorf("raw line entry = %+v", raw)
	}
}