From 7c892ed10abd226a836cab9a9e3094e67a68d963 Mon Sep 17 00:00:00 2001 From: sysops Date: Tue, 1 Sep 2026 09:07:35 +0200 Subject: [PATCH] =?UTF-8?q?feat(mail):=20ING-08=20strukturiertes=20Protoko?= =?UTF-8?q?ll-Logging=20&=20Diagnose=20f=C3=BCr=20IMAP/POP3/SMTP?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Neues Paket mail/internal/protolog (log/slog): SessionLogger loggt strukturierte Ereignisse einer Verbindung mit fester correlation_id und protocol über die gesamte Verbindungsdauer (Akzeptanzkriterium 1) — ein Logger mit logger==nil ist sicher benutzbar und loggt nichts (Rückwärtskompatibilität zu ING-01..ING-07, Logging ist opt-in wie TLS und Guard-Konfiguration). RedactCommandLine ersetzt bei sensiblen Kommandos (PASS, LOGIN, AUTH) alle Argumente vollständig durch [REDACTED] statt einzeln zu parsen (Akzeptanzkriterium 2). Reconstruct liest zeilenweise JSON-Logs und liefert ausschließlich die Einträge einer Korrelations-ID in Reihenfolge — das geforderte Diagnosewerkzeug (Akzeptanzkriterium 3). Alle drei Sessions loggen jetzt session_start/command (je empfangener Zeile, redigiert)/session_end. Nachrichteninhalte werden strukturell nie geloggt: SMTP-DATA-Body-Zeilen laufen durch eine eigene Leseschleife, die nicht durch den Kommando-Logpfad der Hauptschleife kommt: nur das Kommando DATA selbst erscheint im Log. Alle drei Pflichtprüfungen mit echten Nachweisen durchgeführt, jeweils in IMAP, POP3 und SMTP einzeln: Redaktion gegen den echten laufenden Server bestätigt (Klartextpasswort bzw. absichtlich eingebettetes Geheimnis im SMTP-Body erscheint nie im Log), zwei gemischte reale Sessions über dieselbe Korrelations-ID lückenlos rekonstruiert, Lasttest mit 100 Sessions mit/ohne Logging ohne relevante Durchsatzeinbuße. go build/go vet/golangci-lint clean, gesamtes Mail-Modul (~29 Pakete) regressionsfrei getestet. --- mail/docs/ING-08-PRUEFPROTOKOLL.md | 130 ++++++++++++++++++ mail/internal/imap/protolog_test.go | 135 +++++++++++++++++++ mail/internal/imap/server.go | 11 +- mail/internal/imap/session.go | 15 ++- mail/internal/pop3/protolog_test.go | 167 ++++++++++++++++++++++++ mail/internal/pop3/server.go | 11 +- mail/internal/pop3/session.go | 18 ++- mail/internal/protolog/diagnose.go | 68 ++++++++++ mail/internal/protolog/protolog.go | 63 +++++++++ mail/internal/protolog/protolog_test.go | 91 +++++++++++++ mail/internal/protolog/redact.go | 35 +++++ mail/internal/smtp/protolog_test.go | 157 ++++++++++++++++++++++ mail/internal/smtp/server.go | 11 +- mail/internal/smtp/session.go | 24 +++- 14 files changed, 930 insertions(+), 6 deletions(-) create mode 100644 mail/docs/ING-08-PRUEFPROTOKOLL.md create mode 100644 mail/internal/imap/protolog_test.go create mode 100644 mail/internal/pop3/protolog_test.go create mode 100644 mail/internal/protolog/diagnose.go create mode 100644 mail/internal/protolog/protolog.go create mode 100644 mail/internal/protolog/protolog_test.go create mode 100644 mail/internal/protolog/redact.go create mode 100644 mail/internal/smtp/protolog_test.go diff --git a/mail/docs/ING-08-PRUEFPROTOKOLL.md b/mail/docs/ING-08-PRUEFPROTOKOLL.md new file mode 100644 index 0000000..86fefbc --- /dev/null +++ b/mail/docs/ING-08-PRUEFPROTOKOLL.md @@ -0,0 +1,130 @@ +# ING-08 — Mailserver-Protokoll-Logging & Diagnose: Prüfprotokoll + +Datum: 2026-09-01 +Host: 192.168.1.131 (Build/Test/Lint), rsync + ssh +Pakete: `mail/internal/protolog` (neu, gemeinsam genutzt), `mail/internal/imap`, `mail/internal/pop3`, `mail/internal/smtp` + +## Umsetzung + +Neues Paket `protolog` (`log/slog`, wie im Ticket vorgegeben) bündelt +die für alle drei Protokollserver gemeinsame Logging-Grundlage: + +- `NewCorrelationID()` erzeugt eine zufällige, session-eindeutige ID. +- `SessionLogger` loggt strukturierte Ereignisse EINER Verbindung, mit + `correlation_id` und `protocol` als festen Feldern auf jedem Eintrag + (Akzeptanzkriterium 1). Ein `SessionLogger` mit `logger == nil` ist + sicher benutzbar und loggt nichts — Server ohne konfigurierten Logger + verhalten sich unverändert wie vor ING-08 (Rückwärtskompatibilität zu + ING-01..ING-07). +- `RedactCommandLine(verb, args)` liefert eine loggbare + Kommandodarstellung: bei sensiblen Verben (`PASS`, `LOGIN`, `AUTH`) + werden ALLE Argumente vollständig durch `[REDACTED]` ersetzt statt + einzeln geparst — verhindert, dass unerwartet platzierte + Zugangsdaten durchrutschen (Akzeptanzkriterium 2). +- `Reconstruct(r, correlationID)` (`diagnose.go`) ist das geforderte + Diagnosewerkzeug: liest zeilenweise JSON-Logs und liefert, in + Log-Reihenfolge, ausschließlich die Einträge einer Korrelations-ID + (Akzeptanzkriterium 3). + +**Alle drei Sessions** (IMAP, POP3, SMTP) loggen jetzt: +`session_start` (mit `remote_addr`) beim Verbindungsaufbau, EIN +`command`-Ereignis pro empfangener Kommandozeile (Kommandoname + +via `RedactCommandLine` redigierte Argumente) und `session_end` per +`defer` — deckt die gesamte Verbindungsdauer ab (Akzeptanzkriterium 1). +Reader/Writer-Aufsetzung nach STARTTLS/STLS bleibt unverändert (ING-06); +der Logger wird unabhängig von TLS-Zustand weitergereicht. + +**Nachrichteninhalte werden strukturell nie geloggt**: POP3 `RETR` +liefert Nachrichteninhalt nur in der SMTP-/POP3-Antwort, nicht als +Log-Attribut; SMTP-`DATA`-Body-Zeilen werden von einer eigenen +Leseschleife (`handleData`) konsumiert, die NICHT durch den +Kommando-Logpfad der `Serve`-Hauptschleife läuft — nur das Kommando +`DATA` selbst erscheint im Log, nie der Body (Akzeptanzkriterium 2). + +Neue Konstruktoren `NewServerWithGuardTLSAndLogger` (IMAP/POP3) und +`NewServerWithMaxMessageBytesTLSAndLogger` (SMTP) — `logger` optional, +bestehende Konstruktoren (`NewServer`, `NewServerWithGuardConfig`, +`NewServerWithGuardAndTLSConfig` usw.) unverändert. + +## Pflichtprüfung 1: Redaktion sensibler Felder in allen Log-Pfaden + +Isoliert: `TestRedactCommandLine_HidesCredentials` und +`TestSessionLogger_EventNeverContainsRawMessage` +(`protolog/protolog_test.go`). + +Gegen den ECHTEN, laufenden Server (nicht nur die protolog-Bausteine): +`TestProtolog_RedactsCredentialsInRealSessionLog` in `imap` (LOGIN mit +Klartextpasswort) und `pop3` (USER/PASS) — vollständige reale Session +über TCP, Logausgabe geprüft: kein Klartextpasswort, redigierter +Eintrag vorhanden. `TestProtolog_NeverLogsMessageBodyOrRedactsCredentials` +in `smtp`: reale Nachricht mit absichtlich eingebettetem +`Passwort=geheim123` im Betreff/Body per DATA übertragen — weder das +eingebettete Geheimnis noch der Nachrichtentext erscheinen im Log. + +Ergebnis: **BESTANDEN** in allen drei Protokollen. + +## Pflichtprüfung 2: Stichprobe — eine komplette Session ist über die Korrelations-ID lückenlos rekonstruierbar + +`TestProtolog_SessionFullyReconstructableByCorrelationID` in allen drei +Protokollpaketen: ZWEI vollständige, nacheinander über denselben Server +laufende Sessions werden in denselben Logstream geschrieben (Logs +mischen sich, wie im Betrieb). `protolog.Reconstruct` mit der +Korrelations-ID der ersten Session liefert exakt deren Einträge, in +korrekter Reihenfolge, beginnend mit `session_start` und endend mit +`session_end`, jeder Zwischeneintrag mit passender `correlation_id` — +keine Vermischung mit der zweiten Session. Zusätzlich +`TestReconstruct_ReturnsOnlyMatchingSessionInOrder` +(`protolog/protolog_test.go`) als isolierter Baustein-Test. + +Ergebnis: **BESTANDEN** in allen drei Protokollen — Stichprobe +tatsächlich gezogen und lückenlos rekonstruiert. + +## Pflichtprüfung 3: Lasttest bestätigt, dass Logging die Durchsatzrate nicht relevant beeinträchtigt + +`TestProtolog_LoggingDoesNotRelevantlyImpactThroughput` in allen drei +Protokollpaketen: 100 vollständige reale Sessions ohne Logger +(`logger == nil`, no-op) gegen 100 identische Sessions mit aktivem +JSON-Logger gemessen, jeweils über echte TCP-Verbindungen gegen den +laufenden Server. Ergebnis auf 192.168.1.131: + +``` +pop3: PASS (0.11s für 100 Sessions mit Logging, im Toleranzfaktor) +imap: PASS (0.10s für 100 Sessions mit Logging, im Toleranzfaktor) +smtp: PASS (0.11s für 100 Sessions mit Logging, im Toleranzfaktor) +``` + +Toleranzfaktor 3× + 5ms Grundrauschen, um Messschwankungen auf einem +geteilten Testhost abzufangen — Ziel ist der Ausschluss eines groben +Regressionsfaktors (z. B. unbuffered/synchrones I/O pro Byte), nicht +eine exakte Performance-Zusicherung. + +Ergebnis: **BESTANDEN** in allen drei Protokollen. + +## Akzeptanzkriterien + +1. **Jede Session erzeugt strukturierte Logs mit Korrelations-ID über + die gesamte Verbindungsdauer**: `session_start`/`command` + (mehrfach)/`session_end`, alle mit derselben `correlation_id` — + durch Pflichtprüfung 2 belegt. +2. **Zugangsdaten und Nachrichteninhalte erscheinen nie im Klartext im + Log**: durch Pflichtprüfung 1 belegt. +3. **Diagnosewerkzeug kann eine einzelne Session anhand der + Korrelations-ID vollständig nachvollziehen**: `protolog.Reconstruct`, + durch Pflichtprüfung 2 belegt. + +## Build/Vet/Lint/Test — Gesamtmodul + +``` +go build ./... → OK +go vet ./... → OK +golangci-lint run ./... → 0 issues +go test ./... -p 1 (TEST_TENANT_DSN, TEST_MANTICORE_URL gesetzt) → alle Pakete ok, inkl. neuem internal/protolog +``` + +Keine Regression in den bestehenden ~29 Paketen. + +## Ergebnis + +ING-08 erfüllt alle Akzeptanzkriterien mit echten, ausgeführten +Nachweisen — in allen drei Protokollen (IMAP, POP3, SMTP) einzeln +geprüft. Freigeschaltet: QA-02. diff --git a/mail/internal/imap/protolog_test.go b/mail/internal/imap/protolog_test.go new file mode 100644 index 0000000..df00fa4 --- /dev/null +++ b/mail/internal/imap/protolog_test.go @@ -0,0 +1,135 @@ +package imap + +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 := fakeMailboxStore{mailboxes: map[string][]Message{ + "INBOX": {{SequenceNumber: 1, UID: 101, Flags: []string{}}}, + }} + 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') + sendTaggedOn(t, conn, reader, "A1", "LOGIN alice geheim123") + sendTaggedOn(t, conn, reader, "A2", "SELECT INBOX") + sendTaggedOn(t, conn, reader, "A3", "LOGOUT") +} + +// TestProtolog_RedactsCredentialsInRealSessionLog ist die geforderte +// Pflichtprüfung 1 (ING-08) gegen den echten, laufenden IMAP-Server. +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, "LOGIN [REDACTED]") { + t.Fatalf("erwartete redigierten LOGIN-eintrag im log, habe:\n%s", logged) + } +} + +// TestProtolog_SessionFullyReconstructableByCorrelationID ist die +// geforderte Pflichtprüfung 2 (ING-08). +func TestProtolog_SessionFullyReconstructableByCorrelationID(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, nil)) + addr, stop := startLoggedTestServer(t, logger) + defer stop() + + runFullSession(t, addr) + runFullSession(t, addr) + + 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, 3 kommandos (LOGIN/SELECT/LOGOUT), session_end. + if len(entries) != 5 { + t.Fatalf("erwartete 5 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: %+v", entries) + } +} + +// TestProtolog_LoggingDoesNotRelevantlyImpactThroughput ist die +// geforderte Pflichtprüfung 3 (ING-08). +func TestProtolog_LoggingDoesNotRelevantlyImpactThroughput(t *testing.T) { + const sessions = 100 + + addrOff, stopOff := startLoggedTestServer(t, nil) + startOff := time.Now() + for i := 0; i < sessions; i++ { + runFullSession(t, addrOff) + } + durationOff := time.Since(startOff) + stopOff() + + 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() + + if durationOn > 3*durationOff+5*time.Millisecond { + t.Fatalf("logging verlangsamt durchsatz relevant: ohne=%v, mit=%v", durationOff, durationOn) + } +} diff --git a/mail/internal/imap/server.go b/mail/internal/imap/server.go index aaad656..1b6987b 100644 --- a/mail/internal/imap/server.go +++ b/mail/internal/imap/server.go @@ -5,6 +5,7 @@ import ( "crypto/tls" "errors" "fmt" + "log/slog" "net" "gitea.perlbach24.de/scripte/nexarch/mail/internal/protoguard" @@ -21,6 +22,7 @@ type Server struct { store MailboxStore guardCfg protoguard.Config tlsConfig *tls.Config + logger *slog.Logger } func NewServer(auth Authenticator, store MailboxStore) *Server { @@ -41,6 +43,13 @@ func NewServerWithGuardAndTLSConfig(auth Authenticator, store MailboxStore, guar return &Server{auth: auth, store: store, guardCfg: guardCfg, tlsConfig: tlsConfig} } +// NewServerWithGuardTLSAndLogger erlaubt zusätzlich strukturiertes +// Protokoll-Logging (ING-08). logger darf nil sein (Logging dann +// deaktiviert, Rückwärtskompatibilität zu ING-01..ING-07). +func NewServerWithGuardTLSAndLogger(auth Authenticator, store MailboxStore, guardCfg protoguard.Config, tlsConfig *tls.Config, logger *slog.Logger) *Server { + return &Server{auth: auth, store: store, guardCfg: guardCfg, tlsConfig: tlsConfig, logger: logger} +} + // Serve nimmt Verbindungen auf listener an, bis ctx beendet wird oder // Accept endgültig fehlschlägt. Blockiert den Aufrufer. func (srv *Server) Serve(ctx context.Context, listener net.Listener) error { @@ -61,7 +70,7 @@ func (srv *Server) Serve(ctx context.Context, listener net.Listener) error { } return fmt.Errorf("imap: verbindung annehmen: %w", err) } - session := newSession(conn, srv.auth, srv.store, srv.guardCfg, srv.tlsConfig) + session := newSession(conn, srv.auth, srv.store, srv.guardCfg, srv.tlsConfig, srv.logger) go session.Serve(ctx) } } diff --git a/mail/internal/imap/session.go b/mail/internal/imap/session.go index 608603a..25fc0fc 100644 --- a/mail/internal/imap/session.go +++ b/mail/internal/imap/session.go @@ -6,10 +6,12 @@ import ( "crypto/tls" "errors" "io" + "log/slog" "net" "strings" "gitea.perlbach24.de/scripte/nexarch/mail/internal/protoguard" + "gitea.perlbach24.de/scripte/nexarch/mail/internal/protolog" ) // phaseNotAuthenticated/phaseSelected sind die protoguard-Phasen dieser @@ -39,12 +41,13 @@ type Session struct { guard *protoguard.Guard tlsConfig *tls.Config // nil = kein TLS/STARTTLS angeboten (ING-06) tlsActive bool + log *protolog.SessionLogger // ING-08, nie nil (log.Event() ist nil-sicher) state State mailbox string // gewähltes Postfach im Zustand Selected mailboxSize uint32 // Nachrichtenzahl aus dem letzten erfolgreichen SELECT } -func newSession(conn net.Conn, auth Authenticator, store MailboxStore, guardCfg protoguard.Config, tlsConfig *tls.Config) *Session { +func newSession(conn net.Conn, auth Authenticator, store MailboxStore, guardCfg protoguard.Config, tlsConfig *tls.Config, logger *slog.Logger) *Session { _, alreadyTLS := conn.(*tls.Conn) return &Session{ conn: conn, @@ -55,6 +58,7 @@ func newSession(conn net.Conn, auth Authenticator, store MailboxStore, guardCfg guard: protoguard.New(guardCfg), tlsConfig: tlsConfig, tlsActive: alreadyTLS, + log: protolog.NewSessionLogger(logger, "imap"), state: NotAuthenticated, } } @@ -74,6 +78,11 @@ func (s *Session) State() State { return s.state } func (s *Session) Serve(ctx context.Context) { defer func() { _ = s.conn.Close() }() + // Akzeptanzkriterium 1 (ING-08): strukturierte Logs mit + // Korrelations-ID über die gesamte Verbindungsdauer. + s.log.Event(ctx, "session_start", slog.String("remote_addr", s.conn.RemoteAddr().String())) + defer s.log.Event(ctx, "session_end") + if err := writeUntagged(s.writer, "OK IMAP4rev1 Service Ready"); err != nil { return } @@ -107,6 +116,10 @@ func (s *Session) Serve(ctx context.Context) { continue } + // Akzeptanzkriterium 2 (ING-08): LOGIN-Argumente (Passwort) + // erscheinen über RedactCommandLine nie im Klartext im Log. + s.log.Event(ctx, "command", slog.String("command", protolog.RedactCommandLine(cmd.Name, cmd.Args))) + if !s.dispatch(ctx, cmd) { return // LOGOUT oder nicht behebbarer Schreibfehler } diff --git a/mail/internal/pop3/protolog_test.go b/mail/internal/pop3/protolog_test.go new file mode 100644 index 0000000..a917f14 --- /dev/null +++ b/mail/internal/pop3/protolog_test.go @@ -0,0 +1,167 @@ +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) + } +} diff --git a/mail/internal/pop3/server.go b/mail/internal/pop3/server.go index 3fb4715..9d7d868 100644 --- a/mail/internal/pop3/server.go +++ b/mail/internal/pop3/server.go @@ -5,6 +5,7 @@ import ( "crypto/tls" "errors" "fmt" + "log/slog" "net" "gitea.perlbach24.de/scripte/nexarch/mail/internal/protoguard" @@ -23,6 +24,7 @@ type Server struct { store MailboxStore guardCfg protoguard.Config tlsConfig *tls.Config + logger *slog.Logger } func NewServer(auth Authenticator, store MailboxStore) *Server { @@ -43,6 +45,13 @@ func NewServerWithGuardAndTLSConfig(auth Authenticator, store MailboxStore, guar return &Server{auth: auth, store: store, guardCfg: guardCfg, tlsConfig: tlsConfig} } +// NewServerWithGuardTLSAndLogger erlaubt zusätzlich strukturiertes +// Protokoll-Logging (ING-08). logger darf nil sein (Logging dann +// deaktiviert, Rückwärtskompatibilität zu ING-01..ING-07). +func NewServerWithGuardTLSAndLogger(auth Authenticator, store MailboxStore, guardCfg protoguard.Config, tlsConfig *tls.Config, logger *slog.Logger) *Server { + return &Server{auth: auth, store: store, guardCfg: guardCfg, tlsConfig: tlsConfig, logger: logger} +} + // Serve nimmt Verbindungen auf listener an, bis ctx beendet wird. func (srv *Server) Serve(ctx context.Context, listener net.Listener) error { go func() { @@ -62,7 +71,7 @@ func (srv *Server) Serve(ctx context.Context, listener net.Listener) error { } return fmt.Errorf("pop3: verbindung annehmen: %w", err) } - session := newSession(conn, srv.auth, srv.store, srv.guardCfg, srv.tlsConfig) + session := newSession(conn, srv.auth, srv.store, srv.guardCfg, srv.tlsConfig, srv.logger) go session.Serve(ctx) } } diff --git a/mail/internal/pop3/session.go b/mail/internal/pop3/session.go index 66cd755..5749c21 100644 --- a/mail/internal/pop3/session.go +++ b/mail/internal/pop3/session.go @@ -6,10 +6,12 @@ import ( "crypto/tls" "errors" "io" + "log/slog" "net" "strings" "gitea.perlbach24.de/scripte/nexarch/mail/internal/protoguard" + "gitea.perlbach24.de/scripte/nexarch/mail/internal/protolog" ) // phaseAuthorization/phaseTransaction sind die protoguard-Phasen dieser @@ -42,13 +44,15 @@ type Session struct { tlsConfig *tls.Config tlsActive bool + log *protolog.SessionLogger // ING-08, nie nil (aber log.Event() ist nil-sicher) + state State pendingUsername string // nach USER, vor erfolgreichem PASS username string // nach erfolgreichem PASS deleted map[int]bool } -func newSession(conn net.Conn, auth Authenticator, store MailboxStore, guardCfg protoguard.Config, tlsConfig *tls.Config) *Session { +func newSession(conn net.Conn, auth Authenticator, store MailboxStore, guardCfg protoguard.Config, tlsConfig *tls.Config, logger *slog.Logger) *Session { _, alreadyTLS := conn.(*tls.Conn) return &Session{ conn: conn, @@ -59,6 +63,7 @@ func newSession(conn net.Conn, auth Authenticator, store MailboxStore, guardCfg guard: protoguard.New(guardCfg), tlsConfig: tlsConfig, tlsActive: alreadyTLS, + log: protolog.NewSessionLogger(logger, "pop3"), state: Authorization, deleted: map[int]bool{}, } @@ -79,6 +84,11 @@ func (s *Session) State() State { return s.state } func (s *Session) Serve(ctx context.Context) { defer func() { _ = s.conn.Close() }() + // Akzeptanzkriterium 1 (ING-08): strukturierte Logs mit + // Korrelations-ID über die gesamte Verbindungsdauer. + s.log.Event(ctx, "session_start", slog.String("remote_addr", s.conn.RemoteAddr().String())) + defer s.log.Event(ctx, "session_end") + if err := writeOK(s.writer, "POP3 server ready"); err != nil { return } @@ -115,6 +125,12 @@ func (s *Session) Serve(ctx context.Context) { continue } + // Akzeptanzkriterium 2 (ING-08): Zugangsdaten (PASS-Argument) + // erscheinen über RedactCommandLine nie im Klartext im Log. + // Nachrichteninhalte werden hier grundsätzlich nicht geloggt — + // RETR/LIST-Antworten sind kein Bestandteil dieses Ereignisses. + s.log.Event(ctx, "command", slog.String("command", protolog.RedactCommandLine(cmd.Name, cmd.Args))) + if !s.dispatch(ctx, cmd) { return } diff --git a/mail/internal/protolog/diagnose.go b/mail/internal/protolog/diagnose.go new file mode 100644 index 0000000..28df848 --- /dev/null +++ b/mail/internal/protolog/diagnose.go @@ -0,0 +1,68 @@ +package protolog + +import ( + "bufio" + "encoding/json" + "fmt" + "io" +) + +// Entry ist ein einzelner strukturierter Logeintrag, wie ihn +// slog.NewJSONHandler schreibt. +type Entry struct { + Time string + Level string + Msg string + CorrelationID string + Protocol string + // Fields enthält alle weiteren Felder des Eintrags (auch time/ + // level/msg/correlation_id/protocol nochmals, der Einfachheit + // halber), für Diagnosewerkzeuge, die zusätzliche Attribute + // auswerten wollen. + Fields map[string]any +} + +// Reconstruct liest zeilenweise JSON-Logs aus r und liefert, +// in Log-Reihenfolge, ausschließlich die Einträge mit passender +// correlation_id — das geforderte Diagnosewerkzeug +// (Akzeptanzkriterium 3): eine einzelne Session vollständig anhand +// ihrer Korrelations-ID nachvollziehbar. +func Reconstruct(r io.Reader, correlationID string) ([]Entry, error) { + var result []Entry + scanner := bufio.NewScanner(r) + scanner.Buffer(make([]byte, 0, 64*1024), 4*1024*1024) + lineNo := 0 + for scanner.Scan() { + lineNo++ + line := scanner.Bytes() + if len(line) == 0 { + continue + } + var raw map[string]any + if err := json.Unmarshal(line, &raw); err != nil { + return nil, fmt.Errorf("protolog: log-zeile %d parsen: %w", lineNo, err) + } + cid, _ := raw["correlation_id"].(string) + if cid != correlationID { + continue + } + entry := Entry{CorrelationID: cid, Fields: raw} + if v, ok := raw["time"].(string); ok { + entry.Time = v + } + if v, ok := raw["level"].(string); ok { + entry.Level = v + } + if v, ok := raw["msg"].(string); ok { + entry.Msg = v + } + if v, ok := raw["protocol"].(string); ok { + entry.Protocol = v + } + result = append(result, entry) + } + if err := scanner.Err(); err != nil { + return nil, fmt.Errorf("protolog: log lesen: %w", err) + } + return result, nil +} diff --git a/mail/internal/protolog/protolog.go b/mail/internal/protolog/protolog.go new file mode 100644 index 0000000..3a4c430 --- /dev/null +++ b/mail/internal/protolog/protolog.go @@ -0,0 +1,63 @@ +// Package protolog implementiert ING-08: strukturiertes Logging für +// IMAP-/POP3-/SMTP-Sessions mit Korrelations-ID (Akzeptanzkriterium 1), +// Redaktion sensibler Felder (Akzeptanzkriterium 2) und ein +// Diagnosewerkzeug, das eine einzelne Session anhand ihrer +// Korrelations-ID aus den Logs rekonstruiert (Akzeptanzkriterium 3, +// diagnose.go). +package protolog + +import ( + "context" + "crypto/rand" + "encoding/hex" + "log/slog" +) + +// NewCorrelationID erzeugt eine zufällige, session-eindeutige +// Korrelations-ID. +func NewCorrelationID() string { + buf := make([]byte, 8) + // crypto/rand.Read schlägt praktisch nie fehl; ein Nullwert würde + // höchstens zu einer unwahrscheinlichen ID-Kollision führen, kein + // Sicherheitsproblem für ein reines Diagnosemerkmal. + _, _ = rand.Read(buf) + return hex.EncodeToString(buf) +} + +// SessionLogger loggt strukturierte Ereignisse EINER Verbindung mit +// fester Korrelations-ID über deren gesamte Dauer (Akzeptanzkriterium +// 1). Ein SessionLogger mit logger == nil ist sicher benutzbar und +// loggt nichts (Standard für Server ohne konfigurierten Logger). +type SessionLogger struct { + logger *slog.Logger + correlationID string + protocol string +} + +// NewSessionLogger erstellt einen SessionLogger mit frischer +// Korrelations-ID. logger darf nil sein (Logging dann deaktiviert). +func NewSessionLogger(logger *slog.Logger, protocol string) *SessionLogger { + return &SessionLogger{logger: logger, correlationID: NewCorrelationID(), protocol: protocol} +} + +// CorrelationID liefert die Korrelations-ID dieser Session. +func (l *SessionLogger) CorrelationID() string { + if l == nil { + return "" + } + return l.correlationID +} + +// Event loggt EIN strukturiertes Ereignis mit correlation_id und +// protocol als festen Feldern. attrs dürfen NIE Zugangsdaten oder +// Nachrichteninhalte enthalten — siehe RedactCommandLine für +// Kommandozeilen (Akzeptanzkriterium 2). +func (l *SessionLogger) Event(ctx context.Context, event string, attrs ...slog.Attr) { + if l == nil || l.logger == nil { + return + } + all := make([]slog.Attr, 0, len(attrs)+2) + all = append(all, slog.String("correlation_id", l.correlationID), slog.String("protocol", l.protocol)) + all = append(all, attrs...) + l.logger.LogAttrs(ctx, slog.LevelInfo, event, all...) +} diff --git a/mail/internal/protolog/protolog_test.go b/mail/internal/protolog/protolog_test.go new file mode 100644 index 0000000..2ec49f9 --- /dev/null +++ b/mail/internal/protolog/protolog_test.go @@ -0,0 +1,91 @@ +package protolog + +import ( + "bytes" + "context" + "log/slog" + "strings" + "testing" +) + +// TestRedactCommandLine_HidesCredentials ist Teil der geforderten +// Pflichtprüfung 1 (ING-08): Redaktion sensibler Felder. +func TestRedactCommandLine_HidesCredentials(t *testing.T) { + cases := []struct { + verb string + args []string + wantSafe bool // true: darf das geheimnis NICHT enthalten + secret string + }{ + {"PASS", []string{"geheim123"}, true, "geheim123"}, + {"LOGIN", []string{"alice", "geheim123"}, true, "geheim123"}, + {"AUTH", []string{"PLAIN", "AGFsaWNlAGdlaGVpbTEyMw=="}, true, "AGFsaWNlAGdlaGVpbTEyMw=="}, + {"STAT", nil, false, ""}, + {"USER", []string{"alice"}, false, "alice"}, + } + for _, tc := range cases { + out := RedactCommandLine(tc.verb, tc.args) + if tc.wantSafe && strings.Contains(out, tc.secret) { + t.Fatalf("%s: geheimnis im klartext gefunden: %q", tc.verb, out) + } + if !strings.HasPrefix(out, strings.ToUpper(tc.verb)) { + t.Fatalf("%s: kommandoname fehlt in redigierter zeile: %q", tc.verb, out) + } + } +} + +// TestSessionLogger_EventNeverContainsRawMessage stellt sicher, dass +// über die reguläre Event-API keine Nachrichteninhalte geloggt werden +// können, ohne dass der Aufrufer sie explizit (und damit sichtbar im +// Code) als Attribut übergibt — Event selbst fügt nie Rohinhalte hinzu. +func TestSessionLogger_EventNeverContainsRawMessage(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, nil)) + sl := NewSessionLogger(logger, "pop3") + + sl.Event(context.Background(), "command", slog.String("command", RedactCommandLine("PASS", []string{"geheim123"}))) + + if strings.Contains(buf.String(), "geheim123") { + t.Fatalf("passwort im log gefunden: %s", buf.String()) + } + if !strings.Contains(buf.String(), sl.CorrelationID()) { + t.Fatalf("correlation_id fehlt im log: %s", buf.String()) + } +} + +// TestReconstruct_ReturnsOnlyMatchingSessionInOrder ist die geforderte +// Pflichtprüfung 2 (ING-08): eine komplette Session ist über die +// Korrelations-ID lückenlos rekonstruierbar, aus einem Log mit +// mehreren gemischten Sessions. +func TestReconstruct_ReturnsOnlyMatchingSessionInOrder(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, nil)) + + target := NewSessionLogger(logger, "imap") + other := NewSessionLogger(logger, "imap") + + target.Event(context.Background(), "session_start", slog.String("remote_addr", "127.0.0.1:1")) + other.Event(context.Background(), "session_start", slog.String("remote_addr", "127.0.0.1:2")) + target.Event(context.Background(), "command", slog.String("command", "LOGIN [REDACTED]")) + other.Event(context.Background(), "command", slog.String("command", "SELECT INBOX")) + target.Event(context.Background(), "command", slog.String("command", "SELECT INBOX")) + target.Event(context.Background(), "session_end") + other.Event(context.Background(), "session_end") + + entries, err := Reconstruct(&buf, target.CorrelationID()) + if err != nil { + t.Fatalf("Reconstruct: %v", err) + } + if len(entries) != 4 { + t.Fatalf("erwartete 4 einträge für die zielsession, habe %d", len(entries)) + } + wantMsgs := []string{"session_start", "command", "command", "session_end"} + for i, e := range entries { + if e.Msg != wantMsgs[i] { + t.Fatalf("eintrag %d: erwartete msg %q, habe %q", i, wantMsgs[i], e.Msg) + } + if e.CorrelationID != target.CorrelationID() { + t.Fatalf("eintrag %d gehört zur falschen session", i) + } + } +} diff --git a/mail/internal/protolog/redact.go b/mail/internal/protolog/redact.go new file mode 100644 index 0000000..2e73248 --- /dev/null +++ b/mail/internal/protolog/redact.go @@ -0,0 +1,35 @@ +package protolog + +import "strings" + +// sensitiveCommandVerbs sind Kommandos, deren Argumente Zugangsdaten +// enthalten können (Akzeptanzkriterium 2: Zugangsdaten erscheinen nie +// im Klartext im Log). PASS (POP3), LOGIN (IMAP) tragen das Passwort +// direkt als Argument; AUTH ist für zukünftige SMTP-Authentifizierung +// vorsorglich mit aufgenommen, auch wenn ING-03 kein AUTH implementiert. +var sensitiveCommandVerbs = map[string]bool{ + "PASS": true, + "LOGIN": true, + "AUTH": true, +} + +// RedactCommandLine liefert eine loggbare Darstellung einer +// Kommandozeile: das Kommando (Verb) bleibt sichtbar — wichtig für die +// Diagnose (Akzeptanzkriterium 3) —, Argumente sensibler Kommandos +// werden vollständig durch "[REDACTED]" ersetzt statt einzeln +// geparst, damit auch unerwartet platzierte Zugangsdaten (z. B. ein +// Benutzername, der zufällig wie ein Passwort aussieht) nicht +// versehentlich durchrutschen. +func RedactCommandLine(verb string, args []string) string { + verbUpper := strings.ToUpper(verb) + if sensitiveCommandVerbs[verbUpper] { + if len(args) == 0 { + return verbUpper + } + return verbUpper + " [REDACTED]" + } + if len(args) == 0 { + return verbUpper + } + return verbUpper + " " + strings.Join(args, " ") +} diff --git a/mail/internal/smtp/protolog_test.go b/mail/internal/smtp/protolog_test.go new file mode 100644 index 0000000..24e1c9c --- /dev/null +++ b/mail/internal/smtp/protolog_test.go @@ -0,0 +1,157 @@ +package smtp + +import ( + "bufio" + "bytes" + "context" + "encoding/json" + "log/slog" + "net" + "strings" + "testing" + "time" + + "gitea.perlbach24.de/scripte/nexarch/mail/internal/protolog" +) + +func startLoggedTestServer(t *testing.T, sink MessageSink, logger *slog.Logger) (addr string, stop func()) { + t.Helper() + srv := NewServerWithMaxMessageBytesTLSAndLogger(sink, defaultMaxMessageBytes, 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("EHLO client.example.com\r\n")) + for { + line, _ := reader.ReadString('\n') + if strings.HasPrefix(line, "250 ") { + break + } + } + _, _ = conn.Write([]byte("MAIL FROM:\r\n")) + _, _ = reader.ReadString('\n') + _, _ = conn.Write([]byte("RCPT TO:\r\n")) + _, _ = reader.ReadString('\n') + _, _ = conn.Write([]byte("DATA\r\n")) + _, _ = reader.ReadString('\n') + _, _ = conn.Write([]byte("Subject: geheime betreffzeile Passwort=geheim123\r\n\r\nGeheimer Nachrichtentext.\r\n.\r\n")) + _, _ = reader.ReadString('\n') + _, _ = conn.Write([]byte("QUIT\r\n")) + _, _ = reader.ReadString('\n') +} + +// TestProtolog_NeverLogsMessageBodyOrRedactsCredentials ist die +// geforderte Pflichtprüfung 1 (ING-08) gegen den echten, laufenden +// SMTP-Server: Nachrichteninhalte (DATA-Body, hier bewusst mit einem +// eingebetteten "Passwort=geheim123" versehen) erscheinen NIE im Log, +// weil DATA-Zeilen strukturell gar nicht durch den Kommando-Logpfad +// laufen. +func TestProtolog_NeverLogsMessageBodyOrRedactsCredentials(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, nil)) + sink := &fakeSink{} + addr, stop := startLoggedTestServer(t, sink, logger) + defer stop() + + runFullSession(t, addr) + + if sink.count() != 1 { + t.Fatalf("testaufbau fehlerhaft: erwartete 1 angenommene nachricht, habe %d", sink.count()) + } + logged := buf.String() + if strings.Contains(logged, "geheim123") { + t.Fatalf("nachrichteninhalt (mit eingebettetem geheimnis) im log gefunden:\n%s", logged) + } + if strings.Contains(logged, "Geheimer Nachrichtentext") { + t.Fatalf("nachrichtentext im log gefunden:\n%s", logged) + } +} + +// TestProtolog_SessionFullyReconstructableByCorrelationID ist die +// geforderte Pflichtprüfung 2 (ING-08). +func TestProtolog_SessionFullyReconstructableByCorrelationID(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, nil)) + sink := &fakeSink{} + addr, stop := startLoggedTestServer(t, sink, logger) + defer stop() + + runFullSession(t, addr) + runFullSession(t, addr) + + 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 (EHLO/MAIL/RCPT/DATA), session_end. + // QUIT wird VOR seiner eigenen Verarbeitung noch geloggt, danach + // endet die Sitzung -> zusätzlich 1 kommando-eintrag für QUIT. + if len(entries) != 7 { + t.Fatalf("erwartete 7 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: %+v", entries) + } +} + +// TestProtolog_LoggingDoesNotRelevantlyImpactThroughput ist die +// geforderte Pflichtprüfung 3 (ING-08). +func TestProtolog_LoggingDoesNotRelevantlyImpactThroughput(t *testing.T) { + const sessions = 100 + + sinkOff := &fakeSink{} + addrOff, stopOff := startLoggedTestServer(t, sinkOff, nil) + startOff := time.Now() + for i := 0; i < sessions; i++ { + runFullSession(t, addrOff) + } + durationOff := time.Since(startOff) + stopOff() + + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, nil)) + sinkOn := &fakeSink{} + addrOn, stopOn := startLoggedTestServer(t, sinkOn, logger) + startOn := time.Now() + for i := 0; i < sessions; i++ { + runFullSession(t, addrOn) + } + durationOn := time.Since(startOn) + stopOn() + + if durationOn > 3*durationOff+5*time.Millisecond { + t.Fatalf("logging verlangsamt durchsatz relevant: ohne=%v, mit=%v", durationOff, durationOn) + } +} diff --git a/mail/internal/smtp/server.go b/mail/internal/smtp/server.go index 05617d0..4be6996 100644 --- a/mail/internal/smtp/server.go +++ b/mail/internal/smtp/server.go @@ -5,6 +5,7 @@ import ( "crypto/tls" "errors" "fmt" + "log/slog" "net" ) @@ -21,6 +22,7 @@ type Server struct { sink MessageSink maxMessageBytes int64 tlsConfig *tls.Config + logger *slog.Logger } func NewServer(sink MessageSink) *Server { @@ -40,6 +42,13 @@ func NewServerWithMaxMessageBytesAndTLSConfig(sink MessageSink, maxMessageBytes return &Server{sink: sink, maxMessageBytes: maxMessageBytes, tlsConfig: tlsConfig} } +// NewServerWithMaxMessageBytesTLSAndLogger erlaubt zusätzlich +// strukturiertes Protokoll-Logging (ING-08). logger darf nil sein +// (Logging dann deaktiviert, Rückwärtskompatibilität zu ING-01..ING-06). +func NewServerWithMaxMessageBytesTLSAndLogger(sink MessageSink, maxMessageBytes int64, tlsConfig *tls.Config, logger *slog.Logger) *Server { + return &Server{sink: sink, maxMessageBytes: maxMessageBytes, tlsConfig: tlsConfig, logger: logger} +} + // Serve nimmt Verbindungen auf listener an, bis ctx beendet wird. func (srv *Server) Serve(ctx context.Context, listener net.Listener) error { go func() { @@ -59,7 +68,7 @@ func (srv *Server) Serve(ctx context.Context, listener net.Listener) error { } return fmt.Errorf("smtp: verbindung annehmen: %w", err) } - session := newSession(conn, srv.sink, srv.maxMessageBytes, srv.tlsConfig) + session := newSession(conn, srv.sink, srv.maxMessageBytes, srv.tlsConfig, srv.logger) go session.Serve(ctx) } } diff --git a/mail/internal/smtp/session.go b/mail/internal/smtp/session.go index 47d4d0f..086a54f 100644 --- a/mail/internal/smtp/session.go +++ b/mail/internal/smtp/session.go @@ -6,8 +6,11 @@ import ( "crypto/tls" "errors" "io" + "log/slog" "net" "strings" + + "gitea.perlbach24.de/scripte/nexarch/mail/internal/protolog" ) // maxCommandLineBytes begrenzt eine einzelne Kommando-/DATA-Zeile @@ -29,12 +32,14 @@ type Session struct { tlsConfig *tls.Config // nil = kein STARTTLS angeboten (ING-06) tlsActive bool + log *protolog.SessionLogger // ING-08, nie nil (log.Event() ist nil-sicher) + state State from string to []string } -func newSession(conn net.Conn, sink MessageSink, maxMessageBytes int64, tlsConfig *tls.Config) *Session { +func newSession(conn net.Conn, sink MessageSink, maxMessageBytes int64, tlsConfig *tls.Config, logger *slog.Logger) *Session { _, alreadyTLS := conn.(*tls.Conn) return &Session{ conn: conn, @@ -44,6 +49,7 @@ func newSession(conn net.Conn, sink MessageSink, maxMessageBytes int64, tlsConfi maxMessageBytes: maxMessageBytes, tlsConfig: tlsConfig, tlsActive: alreadyTLS, + log: protolog.NewSessionLogger(logger, "smtp"), state: Greeting, } } @@ -55,6 +61,11 @@ func (s *Session) State() State { return s.state } func (s *Session) Serve(ctx context.Context) { defer func() { _ = s.conn.Close() }() + // Akzeptanzkriterium 1 (ING-08): strukturierte Logs mit + // Korrelations-ID über die gesamte Verbindungsdauer. + s.log.Event(ctx, "session_start", slog.String("remote_addr", s.conn.RemoteAddr().String())) + defer s.log.Event(ctx, "session_end") + if err := s.reply(220, "nexarch-mail SMTP server ready"); err != nil { return } @@ -69,6 +80,17 @@ func (s *Session) Serve(ctx context.Context) { } verb, arg := parseCommand(line) + // Akzeptanzkriterium 2 (ING-08): sensible Argumente (z. B. ein + // künftiges AUTH) erscheinen über RedactCommandLine nie im + // Klartext im Log. DATA-Nachrichteninhalte werden hier NICHT + // erfasst — nur das Kommando "DATA" selbst, der Body wird an + // keiner Stelle geloggt. + var args []string + if arg != "" { + args = strings.Fields(arg) + } + s.log.Event(ctx, "command", slog.String("command", protolog.RedactCommandLine(verb, args))) + if !s.dispatch(ctx, verb, arg) { return }