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) } }