From 2eb69bdcfed9340909033e242d4d1bce23d2cc1f Mon Sep 17 00:00:00 2001 From: Carsten Abele Date: Fri, 14 Aug 2026 09:08:19 +0200 Subject: [PATCH] =?UTF-8?q?feat(audit):=20JSONL-Logger=20mit=20Gr=C3=B6?= =?UTF-8?q?=C3=9Fenrotation,=20gzip=20und=20SIGHUP-Reopen?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01NBHF4R9EAejDJUMdwr6C68 --- internal/audit/event.go | 60 +++++++++++++ internal/audit/logger.go | 77 ++++++++++++++++ internal/audit/logger_test.go | 124 ++++++++++++++++++++++++++ internal/audit/rotate.go | 159 ++++++++++++++++++++++++++++++++++ internal/audit/rotate_test.go | 106 +++++++++++++++++++++++ 5 files changed, 526 insertions(+) create mode 100644 internal/audit/event.go create mode 100644 internal/audit/logger.go create mode 100644 internal/audit/logger_test.go create mode 100644 internal/audit/rotate.go create mode 100644 internal/audit/rotate_test.go diff --git a/internal/audit/event.go b/internal/audit/event.go new file mode 100644 index 0000000..ec7b443 --- /dev/null +++ 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 = "" + +// 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] +} diff --git a/internal/audit/logger.go b/internal/audit/logger.go new file mode 100644 index 0000000..36905ae --- /dev/null +++ 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() +} diff --git a/internal/audit/logger_test.go b/internal/audit/logger_test.go new file mode 100644 index 0000000..396d4ab --- /dev/null +++ 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") + } +} diff --git a/internal/audit/rotate.go b/internal/audit/rotate.go new file mode 100644 index 0000000..8318644 --- /dev/null +++ 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:] + } +} diff --git a/internal/audit/rotate_test.go b/internal/audit/rotate_test.go new file mode 100644 index 0000000..af6efaf --- /dev/null +++ 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) + } +}