feat(audit): JSONL-Logger mit Größenrotation, gzip und SIGHUP-Reopen

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01NBHF4R9EAejDJUMdwr6C68
2026-08-14 09:08:19 +02:00 · 2026-08-14 09:08:19 +02:00 · 2eb69bdcfe
commit 2eb69bdcfe
parent b47ee11ba4
5 changed files with 526 additions and 0 deletions
--- a/internal/audit/event.go
+++ b/internal/audit/event.go
@ -0,0 +1,60 @@
+// Package audit schreibt strukturierte Audit-Ereignisse als JSON Lines.
+package audit
+
+import (
+	"crypto/sha256"
+	"encoding/hex"
+)
+
+// Audit-Ereignisse.
+const (
+	EventLoginSuccess   = "login_success"
+	EventLoginFailed    = "login_failed"
+	EventLogout         = "logout"
+	EventSessionExpired = "session_expired"
+	EventConfigDownload = "config_download"
+	EventDownloadDenied = "download_denied"
+)
+
+// Betriebsereignisse.
+const (
+	EventNoCertFound         = "no_cert_found"
+	EventOPNsenseUnreachable = "opnsense_unreachable"
+	EventLDAPFailover        = "ldap_failover"
+	EventRateLimited         = "rate_limited"
+	EventStartup             = "startup"
+)
+
+// UnknownUser ersetzt den eingegebenen Namen, wenn der Benutzer im AD nicht
+// gefunden wurde. Damit landet ein versehentlich ins Username-Feld getipptes
+// Passwort nie im Klartext im Log.
+const UnknownUser = "<unknown>"
+
+// Event ist eine Zeile im Audit-Log. Leere Felder werden nicht serialisiert.
+type Event struct {
+	TS          string `json:"ts"`
+	Event       string `json:"event"`
+	User        string `json:"user,omitempty"`
+	SrcIP       string `json:"src_ip,omitempty"`
+	Session     string `json:"session,omitempty"`
+	Reason      string `json:"reason,omitempty"`
+	VPNInstance string `json:"vpn_instance,omitempty"`
+	CertCN      string `json:"cert_cn,omitempty"`
+	CertExpiry  string `json:"cert_expiry,omitempty"`
+	Format      string `json:"format,omitempty"`
+	Pattern     string `json:"pattern,omitempty"`
+	Server      string `json:"server,omitempty"`
+	Version     string `json:"version,omitempty"`
+	ConfigSum   string `json:"config_sum,omitempty"`
+	Detail      string `json:"detail,omitempty"`
+}
+
+// ShortSession liefert eine kurze, nicht umkehrbare Korrelations-ID.
+// Der Session-Token selbst darf niemals ins Log gelangen.
+func ShortSession(token string) string {
+	if token == "" {
+		return ""
+	}
+	sum := sha256.Sum256([]byte(token))
+	return hex.EncodeToString(sum[:])[:4]
+}
--- a/internal/audit/logger.go
+++ b/internal/audit/logger.go
@ -0,0 +1,77 @@
+package audit
+
+import (
+	"encoding/json"
+	"fmt"
+	"io"
+	"sync"
+	"time"
+)
+
+// Options steuert Rotation und Nebenausgabe.
+type Options struct {
+	MaxSizeMB  int
+	MaxBackups int
+	Compress   bool
+	// Stdout erhält eine Kopie jeder Zeile (systemd-Journal). Nil = keine Kopie.
+	Stdout io.Writer
+	// Clock ist injizierbar für Tests. Nil = time.Now.
+	Clock func() time.Time
+}
+
+// Logger schreibt Events zeilenweise als JSON.
+type Logger struct {
+	mu     sync.Mutex
+	file   *rotatingFile
+	stdout io.Writer
+	clock  func() time.Time
+}
+
+// New öffnet das Audit-Log und liefert einen Logger.
+// Ein fehlendes Verzeichnis wird angelegt.
+func New(path string, opts Options) (*Logger, error) {
+	if opts.Clock == nil {
+		opts.Clock = time.Now
+	}
+	rf, err := openRotating(path, opts)
+	if err != nil {
+		return nil, err
+	}
+	return &Logger{file: rf, stdout: opts.Stdout, clock: opts.Clock}, nil
+}
+
+// Log schreibt ein Ereignis. Fehler beim Schreiben werden nach stdout gemeldet,
+// dürfen den laufenden Request aber nie scheitern lassen.
+func (l *Logger) Log(e Event) {
+	if e.TS == "" {
+		e.TS = l.clock().Format(time.RFC3339)
+	}
+	line, err := json.Marshal(e)
+	if err != nil {
+		return // Event enthält nur Strings; kann praktisch nicht passieren
+	}
+	line = append(line, '\n')
+
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	if _, err := l.file.Write(line); err != nil && l.stdout != nil {
+		fmt.Fprintf(l.stdout, "{\"ts\":%q,\"event\":\"audit_write_failed\",\"detail\":%q}\n",
+			e.TS, err.Error())
+	}
+	if l.stdout != nil {
+		l.stdout.Write(line)
+	}
+}
+
+// Reopen schließt die aktuelle Datei und öffnet sie neu (SIGHUP/logrotate).
+func (l *Logger) Reopen() error {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	return l.file.reopen()
+}
+
+func (l *Logger) Close() error {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	return l.file.Close()
+}
--- a/internal/audit/logger_test.go
+++ b/internal/audit/logger_test.go
@ -0,0 +1,124 @@
+package audit
+
+import (
+	"bytes"
+	"encoding/json"
+	"os"
+	"path/filepath"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+)
+
+func newTestLogger(t *testing.T, opts Options) (*Logger, string, *bytes.Buffer) {
+	t.Helper()
+	dir := t.TempDir()
+	path := filepath.Join(dir, "audit.log")
+	var stdout bytes.Buffer
+	opts.Stdout = &stdout
+	if opts.MaxSizeMB == 0 {
+		opts.MaxSizeMB = 50
+	}
+	lg, err := New(path, opts)
+	if err != nil {
+		t.Fatalf("New: %v", err)
+	}
+	t.Cleanup(func() { lg.Close() })
+	return lg, path, &stdout
+}
+
+func readLines(t *testing.T, path string) []map[string]any {
+	t.Helper()
+	raw, err := os.ReadFile(path)
+	if err != nil {
+		t.Fatal(err)
+	}
+	var out []map[string]any
+	for _, line := range strings.Split(strings.TrimSpace(string(raw)), "\n") {
+		if line == "" {
+			continue
+		}
+		var m map[string]any
+		if err := json.Unmarshal([]byte(line), &m); err != nil {
+			t.Fatalf("Zeile ist kein gültiges JSON: %q: %v", line, err)
+		}
+		out = append(out, m)
+	}
+	return out
+}
+
+func TestLogWritesJSONLWithTimezone(t *testing.T) {
+	fixed := time.Date(2026, 8, 14, 9, 32, 11, 0, time.FixedZone("CEST", 2*3600))
+	lg, path, stdout := newTestLogger(t, Options{Clock: func() time.Time { return fixed }})
+
+	lg.Log(Event{Event: EventLoginSuccess, User: "mmueller", SrcIP: "10.1.20.34", Session: "a3f9"})
+	if err := lg.Close(); err != nil {
+		t.Fatal(err)
+	}
+
+	lines := readLines(t, path)
+	if len(lines) != 1 {
+		t.Fatalf("got %d Zeilen, want 1", len(lines))
+	}
+	got := lines[0]
+	if got["ts"] != "2026-08-14T09:32:11+02:00" {
+		t.Errorf("ts = %v, want RFC3339 mit Zeitzone", got["ts"])
+	}
+	if got["event"] != EventLoginSuccess || got["user"] != "mmueller" {
+		t.Errorf("Feldwerte falsch: %v", got)
+	}
+	if _, present := got["reason"]; present {
+		t.Errorf("leere Felder dürfen nicht serialisiert werden: %v", got)
+	}
+	if !strings.Contains(stdout.String(), EventLoginSuccess) {
+		t.Error("Event muss zusätzlich nach stdout gehen")
+	}
+}
+
+func TestLogIsConcurrencySafe(t *testing.T) {
+	lg, path, _ := newTestLogger(t, Options{})
+	var wg sync.WaitGroup
+	for i := 0; i < 50; i++ {
+		wg.Add(1)
+		go func() {
+			defer wg.Done()
+			lg.Log(Event{Event: EventLoginFailed, User: UnknownUser, SrcIP: "10.0.0.1"})
+		}()
+	}
+	wg.Wait()
+	if err := lg.Close(); err != nil {
+		t.Fatal(err)
+	}
+	if n := len(readLines(t, path)); n != 50 {
+		t.Fatalf("got %d Zeilen, want 50 (kein Interleaving erlaubt)", n)
+	}
+}
+
+func TestNewCreatesFileWithTightPermissions(t *testing.T) {
+	_, path, _ := newTestLogger(t, Options{})
+	info, err := os.Stat(path)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if perm := info.Mode().Perm(); perm&0o077 != 0 {
+		t.Errorf("Audit-Log hat Rechte %#o — Gruppe/Welt dürfen nicht zugreifen", perm)
+	}
+}
+
+func TestShortSessionNeverLeaksToken(t *testing.T) {
+	token := "0123456789abcdef0123456789abcdef"
+	short := ShortSession(token)
+	if len(short) != 4 {
+		t.Errorf("ShortSession = %q, want 4 Zeichen", short)
+	}
+	if strings.Contains(token, short) {
+		t.Errorf("gekürzte ID %q ist ein Präfix des Tokens — muss gehasht sein", short)
+	}
+	if ShortSession(token) != short {
+		t.Error("ShortSession muss deterministisch sein")
+	}
+	if ShortSession("") != "" {
+		t.Error("leerer Token muss leere ID liefern")
+	}
+}
--- a/internal/audit/rotate.go
+++ b/internal/audit/rotate.go
@ -0,0 +1,159 @@
+package audit
+
+import (
+	"compress/gzip"
+	"fmt"
+	"io"
+	"os"
+	"path/filepath"
+	"sort"
+	"strings"
+	"time"
+)
+
+// logFileMode: nur der Eigentümer darf lesen und schreiben — das Log enthält
+// personenbezogene Daten.
+const logFileMode os.FileMode = 0o600
+
+// rotatingFile ist ein größenrotierender Writer ohne externe Dependency.
+// Nicht selbst gesperrt — der Aufrufer (Logger) hält das Mutex.
+type rotatingFile struct {
+	path       string
+	maxBytes   int64
+	maxBackups int
+	compress   bool
+
+	f    *os.File
+	size int64
+}
+
+func openRotating(path string, opts Options) (*rotatingFile, error) {
+	if opts.MaxSizeMB <= 0 {
+		opts.MaxSizeMB = 50
+	}
+	rf := &rotatingFile{
+		path:       path,
+		maxBytes:   int64(opts.MaxSizeMB) * 1024 * 1024,
+		maxBackups: opts.MaxBackups,
+		compress:   opts.Compress,
+	}
+	if err := rf.open(); err != nil {
+		return nil, err
+	}
+	return rf, nil
+}
+
+func (r *rotatingFile) open() error {
+	if err := os.MkdirAll(filepath.Dir(r.path), 0o750); err != nil {
+		return fmt.Errorf("Log-Verzeichnis %s: %w", filepath.Dir(r.path), err)
+	}
+	f, err := os.OpenFile(r.path, os.O_CREATE|os.O_WRONLY|os.O_APPEND, logFileMode)
+	if err != nil {
+		return fmt.Errorf("Audit-Log %s: %w", r.path, err)
+	}
+	info, err := f.Stat()
+	if err != nil {
+		f.Close()
+		return fmt.Errorf("Audit-Log %s: %w", r.path, err)
+	}
+	r.f, r.size = f, info.Size()
+	return nil
+}
+
+func (r *rotatingFile) Write(p []byte) (int, error) {
+	if r.size+int64(len(p)) > r.maxBytes && r.size > 0 {
+		if err := r.rotate(); err != nil {
+			return 0, err
+		}
+	}
+	n, err := r.f.Write(p)
+	r.size += int64(n)
+	return n, err
+}
+
+// reopen schließt und öffnet die Datei neu (SIGHUP nach externem logrotate).
+func (r *rotatingFile) reopen() error {
+	if r.f != nil {
+		r.f.Close()
+	}
+	return r.open()
+}
+
+func (r *rotatingFile) Close() error {
+	if r.f == nil {
+		return nil
+	}
+	err := r.f.Close()
+	r.f = nil
+	return err
+}
+
+func (r *rotatingFile) rotate() error {
+	if err := r.f.Close(); err != nil {
+		return err
+	}
+	backup := fmt.Sprintf("%s.%s", r.path, time.Now().UTC().Format("20060102T150405.000"))
+	if err := os.Rename(r.path, backup); err != nil {
+		return fmt.Errorf("Rotation von %s: %w", r.path, err)
+	}
+	if r.compress {
+		if gzPath, err := gzipFile(backup); err == nil {
+			os.Remove(backup)
+			backup = gzPath
+		}
+	}
+	if err := r.open(); err != nil {
+		return err
+	}
+	r.pruneBackups()
+	return nil
+}
+
+func gzipFile(path string) (string, error) {
+	in, err := os.Open(path)
+	if err != nil {
+		return "", err
+	}
+	defer in.Close()
+	out, err := os.OpenFile(path+".gz", os.O_CREATE|os.O_WRONLY|os.O_TRUNC, logFileMode)
+	if err != nil {
+		return "", err
+	}
+	defer out.Close()
+	zw := gzip.NewWriter(out)
+	if _, err := io.Copy(zw, in); err != nil {
+		return "", err
+	}
+	if err := zw.Close(); err != nil {
+		return "", err
+	}
+	return path + ".gz", nil
+}
+
+// pruneBackups löscht die ältesten rotierten Dateien über maxBackups hinaus.
+func (r *rotatingFile) pruneBackups() {
+	if r.maxBackups <= 0 {
+		return
+	}
+	dir, base := filepath.Split(r.path)
+	if dir == "" {
+		dir = "."
+	}
+	entries, err := os.ReadDir(dir)
+	if err != nil {
+		return
+	}
+	var backups []string
+	for _, e := range entries {
+		name := e.Name()
+		if name != base && strings.HasPrefix(name, base+".") {
+			backups = append(backups, name)
+		}
+	}
+	// Die Zeitstempel im Namen sind lexikografisch sortierbar.
+	sort.Strings(backups)
+	for len(backups) > r.maxBackups {
+		os.Remove(filepath.Join(dir, backups[0]))
+		backups = backups[1:]
+	}
+}
--- a/internal/audit/rotate_test.go
+++ b/internal/audit/rotate_test.go
@ -0,0 +1,106 @@
+package audit
+
+import (
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+)
+
+func TestRotationCreatesBackupAndTruncates(t *testing.T) {
+	dir := t.TempDir()
+	path := filepath.Join(dir, "audit.log")
+	rf, err := openRotating(path, Options{MaxSizeMB: 1, MaxBackups: 2})
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer rf.Close()
+	rf.maxBytes = 200 // Rotationsschwelle für den Test verkleinern
+
+	line := []byte(strings.Repeat("x", 60) + "\n")
+	for i := 0; i < 10; i++ {
+		if _, err := rf.Write(line); err != nil {
+			t.Fatal(err)
+		}
+	}
+	entries, err := os.ReadDir(dir)
+	if err != nil {
+		t.Fatal(err)
+	}
+	var backups int
+	for _, e := range entries {
+		if e.Name() != "audit.log" && strings.HasPrefix(e.Name(), "audit.log.") {
+			backups++
+		}
+	}
+	if backups == 0 {
+		t.Fatal("es muss mindestens eine rotierte Datei geben")
+	}
+	if backups > 2 {
+		t.Fatalf("MaxBackups=2 überschritten: %d Backups", backups)
+	}
+	info, err := os.Stat(path)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if info.Size() > rf.maxBytes {
+		t.Fatalf("aktive Datei ist %d Bytes groß, Schwelle ist %d", info.Size(), rf.maxBytes)
+	}
+}
+
+func TestRotationCompresses(t *testing.T) {
+	dir := t.TempDir()
+	path := filepath.Join(dir, "audit.log")
+	rf, err := openRotating(path, Options{MaxSizeMB: 1, MaxBackups: 3, Compress: true})
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer rf.Close()
+	rf.maxBytes = 100
+
+	for i := 0; i < 6; i++ {
+		if _, err := rf.Write([]byte(strings.Repeat("y", 60) + "\n")); err != nil {
+			t.Fatal(err)
+		}
+	}
+	entries, _ := os.ReadDir(dir)
+	var gz int
+	for _, e := range entries {
+		if strings.HasSuffix(e.Name(), ".gz") {
+			gz++
+		}
+	}
+	if gz == 0 {
+		t.Fatal("bei Compress=true müssen rotierte Dateien .gz sein")
+	}
+}
+
+func TestReopenRecreatesDeletedFile(t *testing.T) {
+	dir := t.TempDir()
+	path := filepath.Join(dir, "audit.log")
+	rf, err := openRotating(path, Options{MaxSizeMB: 1})
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer rf.Close()
+
+	if _, err := rf.Write([]byte("erste\n")); err != nil {
+		t.Fatal(err)
+	}
+	if err := os.Rename(path, path+".moved"); err != nil {
+		t.Fatal(err)
+	}
+	if err := rf.reopen(); err != nil {
+		t.Fatal(err)
+	}
+	if _, err := rf.Write([]byte("zweite\n")); err != nil {
+		t.Fatal(err)
+	}
+	raw, err := os.ReadFile(path)
+	if err != nil {
+		t.Fatalf("nach reopen muss die Datei wieder existieren: %v", err)
+	}
+	if string(raw) != "zweite\n" {
+		t.Errorf("neue Datei enthält %q, want \"zweite\\n\"", raw)
+	}
+}