nexarch/mail/internal/pop3/protolog_test.go

package pop3

import (
	"bufio"
	"bytes"
	"context"
	"encoding/json"
	"log/slog"
	"net"
	"strings"
	"testing"
	"time"

	"gitea.perlbach24.de/scripte/nexarch/mail/internal/protoguard"
	"gitea.perlbach24.de/scripte/nexarch/mail/internal/protolog"
)

func startLoggedTestServer(t *testing.T, logger *slog.Logger) (addr string, stop func()) {
	t.Helper()
	auth := fakeAuthenticator{users: map[string]string{"alice": "geheim123"}}
	store := newFakeMailboxStore()
	srv := NewServerWithGuardTLSAndLogger(auth, store, protoguard.DefaultConfig(), nil, logger)

	listener, err := net.Listen("tcp", "127.0.0.1:0")
	if err != nil {
		t.Fatalf("listener: %v", err)
	}
	ctx, cancel := context.WithCancel(context.Background())
	done := make(chan struct{})
	go func() {
		_ = srv.Serve(ctx, listener)
		close(done)
	}()
	return listener.Addr().String(), func() {
		cancel()
		<-done
	}
}

func runFullSession(t *testing.T, addr string) {
	t.Helper()
	conn, err := net.DialTimeout("tcp", addr, 2*time.Second)
	if err != nil {
		t.Fatalf("dial: %v", err)
	}
	defer func() { _ = conn.Close() }()
	reader := bufio.NewReader(conn)
	_, _ = reader.ReadString('\n')
	_, _ = conn.Write([]byte("USER alice\r\n"))
	_, _ = reader.ReadString('\n')
	_, _ = conn.Write([]byte("PASS geheim123\r\n"))
	_, _ = reader.ReadString('\n')
	_, _ = conn.Write([]byte("STAT\r\n"))
	_, _ = reader.ReadString('\n')
	_, _ = conn.Write([]byte("QUIT\r\n"))
	_, _ = reader.ReadString('\n')
}

// TestProtolog_RedactsCredentialsInRealSessionLog ist die geforderte
// Pflichtprüfung 1 (ING-08): Redaktion sensibler Felder in ALLEN
// Log-Pfaden — hier gegen den echten, laufenden POP3-Server geprüft,
// nicht nur gegen die protolog-Bausteine isoliert.
func TestProtolog_RedactsCredentialsInRealSessionLog(t *testing.T) {
	var buf bytes.Buffer
	logger := slog.New(slog.NewJSONHandler(&buf, nil))
	addr, stop := startLoggedTestServer(t, logger)
	defer stop()

	runFullSession(t, addr)

	logged := buf.String()
	if strings.Contains(logged, "geheim123") {
		t.Fatalf("passwort im klartext im log gefunden:\n%s", logged)
	}
	if !strings.Contains(logged, "PASS [REDACTED]") {
		t.Fatalf("erwartete redigierten PASS-eintrag im log, habe:\n%s", logged)
	}
}

// TestProtolog_SessionFullyReconstructableByCorrelationID ist die
// geforderte Pflichtprüfung 2 (ING-08): eine komplette Session ist über
// die Korrelations-ID lückenlos rekonstruierbar — Stichprobe aus
// mehreren gleichzeitig geloggten Sessions.
func TestProtolog_SessionFullyReconstructableByCorrelationID(t *testing.T) {
	var buf bytes.Buffer
	logger := slog.New(slog.NewJSONHandler(&buf, nil))
	addr, stop := startLoggedTestServer(t, logger)
	defer stop()

	// Zwei Sessions nacheinander, damit sich die Logs im gemeinsamen
	// Puffer mischen — realistischer als eine einzelne isolierte Session.
	runFullSession(t, addr)
	runFullSession(t, addr)

	all, err := protolog.Reconstruct(bytes.NewReader(buf.Bytes()), "does-not-exist")
	if err != nil {
		t.Fatalf("Reconstruct (kontrollaufruf): %v", err)
	}
	if len(all) != 0 {
		t.Fatalf("unerwartete treffer für nicht existierende id: %d", len(all))
	}

	// Erste correlation_id aus dem rohen Log extrahieren (erste Zeile =
	// session_start der ersten Session).
	firstLine := strings.SplitN(buf.String(), "\n", 2)[0]
	var raw map[string]any
	if err := json.Unmarshal([]byte(firstLine), &raw); err != nil {
		t.Fatalf("erste logzeile parsen: %v", err)
	}
	firstID, _ := raw["correlation_id"].(string)
	if firstID == "" {
		t.Fatalf("keine correlation_id in erster logzeile: %s", firstLine)
	}

	entries, err := protolog.Reconstruct(bytes.NewReader(buf.Bytes()), firstID)
	if err != nil {
		t.Fatalf("Reconstruct: %v", err)
	}
	// session_start, 4 kommandos (USER/PASS/STAT/QUIT), session_end.
	if len(entries) != 6 {
		t.Fatalf("erwartete 6 lückenlose einträge für die session, habe %d: %+v", len(entries), entries)
	}
	if entries[0].Msg != "session_start" || entries[len(entries)-1].Msg != "session_end" {
		t.Fatalf("session nicht lückenlos rekonstruierbar (start/ende falsch): %+v", entries)
	}
	for _, e := range entries {
		if e.CorrelationID != firstID {
			t.Fatalf("eintrag mit falscher correlation_id in rekonstruktion: %+v", e)
		}
	}
}

// TestProtolog_LoggingDoesNotRelevantlyImpactThroughput ist die
// geforderte Pflichtprüfung 3 (ING-08): Lasttest bestätigt, dass
// Logging die Durchsatzrate nicht relevant beeinträchtigt.
func TestProtolog_LoggingDoesNotRelevantlyImpactThroughput(t *testing.T) {
	const sessions = 100

	// Ohne Logging (logger nil -> protolog.Event ist no-op).
	addrOff, stopOff := startLoggedTestServer(t, nil)
	startOff := time.Now()
	for i := 0; i < sessions; i++ {
		runFullSession(t, addrOff)
	}
	durationOff := time.Since(startOff)
	stopOff()

	// Mit Logging in einen echten (verworfenen) Puffer.
	var buf bytes.Buffer
	logger := slog.New(slog.NewJSONHandler(&buf, nil))
	addrOn, stopOn := startLoggedTestServer(t, logger)
	startOn := time.Now()
	for i := 0; i < sessions; i++ {
		runFullSession(t, addrOn)
	}
	durationOn := time.Since(startOn)
	stopOn()

	// Großzügige Toleranz (Faktor 3): Ziel ist der Ausschluss eines
	// GROBEN Regressionsfaktors (z. B. synchrones Schreiben pro
	// Byte, blockierendes I/O ohne Puffer), nicht eine exakte
	// Performance-Zusicherung — Testläufe auf geteilten CI-Hosts
	// schwanken.
	if durationOn > 3*durationOff+5*time.Millisecond {
		t.Fatalf("logging verlangsamt durchsatz relevant: ohne=%v, mit=%v", durationOff, durationOn)
	}
}