From 544c42a6185c466ef6fda729070e0a4084e26b45 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Fri, 10 Jul 2026 15:43:29 +0200 Subject: [PATCH] =?UTF-8?q?v0.111.0:=20remote=20app-log=20diagnostics=20?= =?UTF-8?q?=E2=80=94=20error=20context=20capture=20(=C2=B15=20lines,=20cap?= =?UTF-8?q?ped+redacted)=20+=20on-demand=20log=20tails=20via=20ACK=20pull?= =?UTF-8?q?=20pattern?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - metrics: LogIssue.Context on first-occurrence errors (≤11 lines, ≤400 chars/line, warns carry none); RedactLine sanitizer (password/token/api-key/bearer/64-hex) applied to everything shipped; FetchContainerLogTail - report: 16KB per-report context budget (lowest-count issues dropped first); log_tail_requests ACK flag → next report ships log_tails (200 lines, ≤64KB/app head-truncated, ordered, redacted); consume-once drain - tests: synthetic-window context capture, caps, redaction, budget order, consume-once, fetch-error skip Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01PSK5g6qYLknKj8u3QAFEr6 --- controller/cmd/controller/main.go | 4 + controller/internal/metrics/logscanner.go | 91 +++++++++- .../internal/metrics/logscanner_test.go | 159 ++++++++++++++++++ controller/internal/metrics/redact.go | 22 +++ controller/internal/metrics/redact_test.go | 66 ++++++++ controller/internal/report/builder.go | 13 ++ controller/internal/report/logtail.go | 109 ++++++++++++ controller/internal/report/logtail_test.go | 115 +++++++++++++ controller/internal/report/pusher.go | 4 + controller/internal/report/telemetry.go | 43 +++++ controller/internal/report/telemetry_test.go | 48 ++++++ controller/internal/report/types.go | 4 + 12 files changed, 670 insertions(+), 8 deletions(-) create mode 100644 controller/internal/metrics/logscanner_test.go create mode 100644 controller/internal/metrics/redact.go create mode 100644 controller/internal/metrics/redact_test.go create mode 100644 controller/internal/report/logtail.go create mode 100644 controller/internal/report/logtail_test.go create mode 100644 controller/internal/report/telemetry_test.go diff --git a/controller/cmd/controller/main.go b/controller/cmd/controller/main.go index 172ae08..3fac70a 100644 --- a/controller/cmd/controller/main.go +++ b/controller/cmd/controller/main.go @@ -443,6 +443,10 @@ func main() { // SLICE 3: run the escrow auto-confirm on the same ACK (after the config refresh decision — // a refresh-restart re-enters here anyway on the next cycle). escrowConfirmer.Reconcile(resp.Escrow) + // v0.111.0: operator log-tail requests ride the same ACK (pull pattern — the hub + // never reaches in). The NEXT report cycle collects + ships the tails; the hub + // clears its pending request on receipt. An empty list clears any stale local set. + report.SetPendingLogTails(resp.LogTailRequests) } // Wire hub push status into alert manager for dashboard alerts alertMgr.SetHubPushStatus(func() web.HubPushStatusData { diff --git a/controller/internal/metrics/logscanner.go b/controller/internal/metrics/logscanner.go index 0201850..be713e7 100644 --- a/controller/internal/metrics/logscanner.go +++ b/controller/internal/metrics/logscanner.go @@ -26,8 +26,18 @@ type LogIssue struct { Message string `json:"message"` Count int `json:"count"` LastSeen time.Time `json:"last_seen"` + // Context is up to ±5 raw log lines around the FIRST occurrence of an error-severity + // issue in this scrape window (≤11 lines, each ≤400 chars, redacted). Warn-severity + // issues never carry context — bounds the payload. Additive since v0.111.0. + Context []string `json:"context,omitempty"` } +const ( + // contextRadius lines before + the error line + contextRadius after = ≤11 lines. + contextRadius = 5 + contextMaxLineChars = 400 +) + var ( // Strip ANSI escape codes (color, bold, etc.) reANSI = regexp.MustCompile(`\x1b\[[0-9;]*m`) @@ -97,17 +107,28 @@ func scanOneContainer(name string, since time.Duration, logger *log.Logger) Cont return summary } + lines := strings.Split(string(output), "\n") + summary.ErrorCount, summary.WarnCount, summary.RecentIssues = analyzeLogLines(lines) + + return summary +} + +// analyzeLogLines classifies and deduplicates a scan window's raw log lines. +// Pure (no docker, no I/O) so it is unit-testable with synthetic windows. +// Error-severity issues get a ±5-line context captured on their FIRST occurrence +// only (never on repeats); warns carry no context. +func analyzeLogLines(lines []string) (errorCount, warnCount int, issues []LogIssue) { // fingerprint → issue tracking type issueEntry struct { severity string message string count int lastSeen time.Time + context []string } fingerprints := make(map[string]*issueEntry) - lines := strings.Split(string(output), "\n") - for _, line := range lines { + for i, line := range lines { if !utf8.Valid([]byte(line)) { continue } @@ -124,9 +145,9 @@ func scanOneContainer(name string, since time.Duration, logger *log.Logger) Cont } if severity == "error" { - summary.ErrorCount++ + errorCount++ } else { - summary.WarnCount++ + warnCount++ } fp := fingerprint(line) @@ -138,23 +159,28 @@ func scanOneContainer(name string, since time.Duration, logger *log.Logger) Cont if len(msg) > 200 { msg = msg[:200] } - fingerprints[fp] = &issueEntry{ + entry := &issueEntry{ severity: severity, message: msg, count: 1, lastSeen: time.Now(), } + if severity == "error" { + entry.context = captureContext(lines, i) + } + fingerprints[fp] = entry } } // Convert map to slice, sort by count DESC then lastSeen DESC, cap at 10 - issues := make([]LogIssue, 0, len(fingerprints)) + issues = make([]LogIssue, 0, len(fingerprints)) for _, e := range fingerprints { issues = append(issues, LogIssue{ Severity: e.severity, Message: e.message, Count: e.count, LastSeen: e.lastSeen, + Context: e.context, }) } sort.Slice(issues, func(i, j int) bool { @@ -166,9 +192,58 @@ func scanOneContainer(name string, since time.Duration, logger *log.Logger) Cont if len(issues) > 10 { issues = issues[:10] } - summary.RecentIssues = issues + return errorCount, warnCount, issues +} - return summary +// captureContext returns the ±contextRadius window around lines[i], ordered as emitted. +// Empty and invalid-UTF8 slots are dropped; each kept line is ANSI-stripped, truncated +// to contextMaxLineChars with "…", and redacted (RedactLine) — nothing raw ships. +func captureContext(lines []string, i int) []string { + lo := i - contextRadius + if lo < 0 { + lo = 0 + } + hi := i + contextRadius + if hi > len(lines)-1 { + hi = len(lines) - 1 + } + out := make([]string, 0, hi-lo+1) + for j := lo; j <= hi; j++ { + l := lines[j] + if l == "" || !utf8.Valid([]byte(l)) { + continue + } + l = reANSI.ReplaceAllString(l, "") + l = truncateRunes(l, contextMaxLineChars) + out = append(out, RedactLine(l)) + } + return out +} + +// truncateRunes rune-safely truncates s to max runes, appending "…" when cut. +func truncateRunes(s string, max int) string { + runes := []rune(s) + if len(runes) <= max { + return s + } + return string(runes[:max]) + "…" +} + +// FetchContainerLogTail returns the last tailLines lines of one container's docker log, +// ordered as emitted (stdout+stderr merged). Same CLI plumbing as the scanner; used by +// the report's on-demand log-tail (operator request riding the ACK). Caller caps/redacts. +func FetchContainerLogTail(name string, tailLines int) (string, error) { + if tailLines <= 0 || tailLines > 1000 { + tailLines = 200 + } + ctx, cancel := context.WithTimeout(context.Background(), 15*time.Second) + defer cancel() + cmd := exec.CommandContext(ctx, "docker", "logs", fmt.Sprintf("--tail=%d", tailLines), name) + output, err := cmd.CombinedOutput() + if err != nil { + return "", fmt.Errorf("docker logs %s: %w", name, err) + } + return string(output), nil } // cleanLine strips ANSI escape codes and timestamps from a log line. diff --git a/controller/internal/metrics/logscanner_test.go b/controller/internal/metrics/logscanner_test.go new file mode 100644 index 0000000..7385630 --- /dev/null +++ b/controller/internal/metrics/logscanner_test.go @@ -0,0 +1,159 @@ +package metrics + +import ( + "fmt" + "strings" + "testing" + "unicode/utf8" +) + +func findIssue(t *testing.T, issues []LogIssue, substr string) LogIssue { + t.Helper() + for _, is := range issues { + if strings.Contains(is.Message, substr) { + return is + } + } + t.Fatalf("no issue containing %q in %+v", substr, issues) + return LogIssue{} +} + +// Part B — a synthetic scrape with an error mid-stream: Context must be EXACTLY the +// ±5 window, ordered as emitted. Red-proof: dropping the captureContext call leaves +// Context empty → this fails. +func TestAnalyzeLogLines_ErrorContextWindow(t *testing.T) { + lines := []string{ + "boot line zero", + "ctx minus five", + "ctx minus four", + "ctx minus three", + "ctx minus two", + "ctx minus one", + "ERROR: nfs mount lost", // index 6 + "ctx plus one", + "ctx plus two", + "ctx plus three", + "ctx plus four", + "ctx plus five", + "outside the window", + } + errC, warnC, issues := analyzeLogLines(lines) + if errC != 1 || warnC != 0 { + t.Fatalf("counts: errors=%d warns=%d, want 1/0", errC, warnC) + } + is := findIssue(t, issues, "nfs mount lost") + want := []string{ + "ctx minus five", "ctx minus four", "ctx minus three", "ctx minus two", "ctx minus one", + "ERROR: nfs mount lost", + "ctx plus one", "ctx plus two", "ctx plus three", "ctx plus four", "ctx plus five", + } + if len(is.Context) != len(want) { + t.Fatalf("context has %d lines, want %d: %#v", len(is.Context), len(want), is.Context) + } + for i := range want { + if is.Context[i] != want[i] { + t.Fatalf("context[%d] = %q, want %q (order must match emission)", i, is.Context[i], want[i]) + } + } +} + +// Repeat occurrence of the same fingerprint in one window: count aggregates but the +// context stays the FIRST occurrence's window — never re-captured on repeats. +func TestAnalyzeLogLines_RepeatKeepsFirstContext(t *testing.T) { + lines := []string{ + "first neighborhood", + "ERROR: db connection refused", + "after the first", + "filler a", "filler b", "filler c", "filler d", "filler e", "filler f", + "second neighborhood", + "ERROR: db connection refused", + "after the second", + } + _, _, issues := analyzeLogLines(lines) + is := findIssue(t, issues, "db connection refused") + if is.Count != 2 { + t.Fatalf("count = %d, want 2 (same fingerprint must dedupe)", is.Count) + } + joined := strings.Join(is.Context, "\n") + if !strings.Contains(joined, "first neighborhood") { + t.Fatalf("context lost the FIRST occurrence window: %#v", is.Context) + } + if strings.Contains(joined, "second neighborhood") { + t.Fatalf("context re-captured on a repeat occurrence: %#v", is.Context) + } +} + +// Warn-severity issues carry NO context (message-only) — bounds the payload. +func TestAnalyzeLogLines_WarnHasNoContext(t *testing.T) { + lines := []string{"before", "WARN: disk latency high", "after"} + _, warnC, issues := analyzeLogLines(lines) + if warnC != 1 { + t.Fatalf("warns = %d, want 1", warnC) + } + is := findIssue(t, issues, "disk latency high") + if len(is.Context) != 0 { + t.Fatalf("warn issue must not carry context, got %#v", is.Context) + } +} + +// Caps: oversized context lines are truncated to 400 runes + "…" (rune-safe). +func TestAnalyzeLogLines_ContextLineTruncated(t *testing.T) { + long := strings.Repeat("x", 450) + lines := []string{long, "ERROR: it broke", "after"} + _, _, issues := analyzeLogLines(lines) + is := findIssue(t, issues, "it broke") + if len(is.Context) == 0 { + t.Fatalf("expected context") + } + got := is.Context[0] + if utf8.RuneCountInString(got) != 401 || !strings.HasSuffix(got, "…") { + t.Fatalf("oversized line not truncated to 400+ellipsis: len=%d suffix=%q", + utf8.RuneCountInString(got), got[len(got)-3:]) + } +} + +// Part E on the capture path: a secret in a NEIGHBOR line must ship redacted. +func TestAnalyzeLogLines_ContextRedacted(t *testing.T) { + lines := []string{ + "connecting with password=hunter2 now", + "ERROR: auth failed", + "retrying", + } + _, _, issues := analyzeLogLines(lines) + is := findIssue(t, issues, "auth failed") + joined := strings.Join(is.Context, "\n") + if strings.Contains(joined, "hunter2") { + t.Fatalf("secret shipped in context: %#v", is.Context) + } + if !strings.Contains(joined, "password=[REDACTED]") { + t.Fatalf("expected redaction marker in context: %#v", is.Context) + } +} + +// Error at the very start/end of the window: the ±5 clamps without panicking +// and still contains the error line itself. +func TestAnalyzeLogLines_WindowClamped(t *testing.T) { + lines := []string{"ERROR: first line broke", "after one"} + _, _, issues := analyzeLogLines(lines) + is := findIssue(t, issues, "first line broke") + if len(is.Context) != 2 { + t.Fatalf("clamped context = %#v, want the 2 available lines", is.Context) + } +} + +// The 10-issue cap and count-DESC ordering still hold with contexts attached. +func TestAnalyzeLogLines_CapAndOrder(t *testing.T) { + var lines []string + for i := 0; i < 12; i++ { + lines = append(lines, fmt.Sprintf("ERROR: distinct failure mode %s", strings.Repeat("z", i+1))) + } + // make one of them dominant + lines = append(lines, "ERROR: distinct failure mode z", "ERROR: distinct failure mode z") + _, _, issues := analyzeLogLines(lines) + if len(issues) != 10 { + t.Fatalf("issues = %d, want capped at 10", len(issues)) + } + if issues[0].Count != 3 { + t.Fatalf("top issue count = %d, want the dominant one (3) first", issues[0].Count) + } +} diff --git a/controller/internal/metrics/redact.go b/controller/internal/metrics/redact.go new file mode 100644 index 0000000..7311a35 --- /dev/null +++ b/controller/internal/metrics/redact.go @@ -0,0 +1,22 @@ +package metrics + +import "regexp" + +// Redaction is controller-side and authoritative: every context line and log-tail line +// must pass through RedactLine before it leaves the box (rides the hub report). +var ( + // key[=: ]value shapes — the value is masked. The optional "bearer " prefix inside the + // value group catches "Authorization: Bearer " in one pass. + reSecretKV = regexp.MustCompile(`(?i)\b(password|passwd|secret|token|api[_-]?key|authorization|bearer)([=: ]\s*)((?:bearer\s+)?\S+)`) + // 64-hex string = restic repo password / key-material shape. + reHex64 = regexp.MustCompile(`\b[0-9a-fA-F]{64}\b`) +) + +// RedactLine masks secret-shaped values in a log line. Applied to context lines and +// log-tail lines before shipping; deliberately narrow (support usefulness over +// aggression) but the named patterns are non-negotiable. +func RedactLine(s string) string { + s = reSecretKV.ReplaceAllString(s, "${1}${2}[REDACTED]") + s = reHex64.ReplaceAllString(s, "[REDACTED-HEX64]") + return s +} diff --git a/controller/internal/metrics/redact_test.go b/controller/internal/metrics/redact_test.go new file mode 100644 index 0000000..40cc8b7 --- /dev/null +++ b/controller/internal/metrics/redact_test.go @@ -0,0 +1,66 @@ +package metrics + +import ( + "strings" + "testing" +) + +// Part E — sanitization. Red-proof: gutting RedactLine (return s unchanged) must fail +// every case here with the secret visible in the failure message. +func TestRedactLine_SpecPatterns(t *testing.T) { + in := "password=hunter2 token: abc Bearer xyz" + got := RedactLine(in) + want := "password=[REDACTED] token: [REDACTED] Bearer [REDACTED]" + if got != want { + t.Fatalf("RedactLine(%q) = %q, want %q", in, got, want) + } + for _, secret := range []string{"hunter2", "abc", "xyz"} { + if strings.Contains(got, secret) { + t.Fatalf("secret %q shipped: %q", secret, got) + } + } +} + +func TestRedactLine_Hex64(t *testing.T) { + hex64 := strings.Repeat("ab12", 16) // 64 hex chars — restic repo password shape + in := "repo unlock with " + hex64 + " done" + got := RedactLine(in) + if strings.Contains(got, hex64) { + t.Fatalf("64-hex secret shipped: %q", got) + } + if !strings.Contains(got, "[REDACTED-HEX64]") { + t.Fatalf("expected [REDACTED-HEX64] marker, got %q", got) + } +} + +func TestRedactLine_Variants(t *testing.T) { + cases := []struct{ in, want string }{ + {"authorization: Bearer eyJhbGciOi.payload.sig", "authorization: [REDACTED]"}, + {"api_key=sk-live-123", "api_key=[REDACTED]"}, + {"API-KEY: verysecret", "API-KEY: [REDACTED]"}, + {"apikey=whatever", "apikey=[REDACTED]"}, + {"PASSWD: root123", "PASSWD: [REDACTED]"}, + {"client secret=s3cr3t", "client secret=[REDACTED]"}, + } + for _, c := range cases { + if got := RedactLine(c.in); got != c.want { + t.Errorf("RedactLine(%q) = %q, want %q", c.in, got, c.want) + } + } +} + +// Benign lines must pass through byte-identical — support usefulness over aggression. +func TestRedactLine_BenignUntouched(t *testing.T) { + cases := []string{ + "connection refused to 10.0.0.5:5432", + "GET /api/keys 200 12ms", // "api/keys" is not "api_key" + "tokenizer initialized in 40ms", // "token" not followed by separator+value + "ERROR: NFS mount /mnt/media gone", // the CWA shape — must stay readable + "deadbeef", // short hex, not 64 + } + for _, c := range cases { + if got := RedactLine(c); got != c { + t.Errorf("benign line mangled: %q -> %q", c, got) + } + } +} diff --git a/controller/internal/report/builder.go b/controller/internal/report/builder.go index f0cf5e3..fc36596 100644 --- a/controller/internal/report/builder.go +++ b/controller/internal/report/builder.go @@ -155,6 +155,19 @@ func BuildReport( // App telemetry (metrics + log scan) r.AppTelemetry = buildAppTelemetrySection(stackMgr, metricsStore, logger) + // On-demand log tails (v0.111.0): drain the ACK-requested apps and collect their tails. + // Stacks go through the existing compose-logs plumbing; the controller's own container + // through the scanner's docker-logs plumbing. Consume-once: drained here, re-armed by + // the next ACK if the push fails. + if tailApps := drainPendingLogTails(); len(tailApps) > 0 { + r.LogTails = buildLogTailsSection(tailApps, func(app string, lines int) (string, error) { + if app == controllerContainerName { + return metrics.FetchContainerLogTail(app, lines) + } + return stackMgr.GetLogs(app, lines) + }, logger) + } + // Geo-restriction status — ALWAYS present (even when never configured) so the hub // always renders the section. A nil pointer (omitempty) made the hub hide the whole // section for a never-configured controller; a present-but-disabled report renders diff --git a/controller/internal/report/logtail.go b/controller/internal/report/logtail.go new file mode 100644 index 0000000..d829f3c --- /dev/null +++ b/controller/internal/report/logtail.go @@ -0,0 +1,109 @@ +package report + +import ( + "log" + "strings" + "sync" + "time" + + "gitea.dooplex.hu/admin/felhom-controller/internal/metrics" +) + +// On-demand log tail (pull-based, same ACK-flag pattern as escrow/config-refresh): +// the hub stores a pending request per (customer, app); the report ACK advertises the +// requested app names in log_tail_requests; the NEXT report carries the collected tails +// in log_tails. The hub clears the pending request when a tail arrives (consume-once) — +// the controller listens to no one, it only pushes on its own cycle. + +const ( + logTailLines = 200 + logTailMaxLineChars = 400 + logTailMaxBytes = 64 * 1024 // per app; head-truncated (newest lines kept) +) + +// LogTail is one app's on-demand ordered log tail riding the report. +type LogTail struct { + App string `json:"app"` + CollectedAt time.Time `json:"collected_at"` + Lines []string `json:"lines"` +} + +var ( + pendingTailsMu sync.Mutex + pendingTails []string +) + +// SetPendingLogTails records the hub-requested apps from the latest ACK. The hub is +// the source of truth: an ACK without requests clears any stale local pending set. +func SetPendingLogTails(apps []string) { + pendingTailsMu.Lock() + defer pendingTailsMu.Unlock() + pendingTails = append([]string(nil), apps...) +} + +// drainPendingLogTails takes and CLEARS the pending set (consume-once controller-side). +// If the subsequent push fails, the hub's request is still pending and the next ACK +// re-arms it — fail-safe retry, no duplicate shipping. +func drainPendingLogTails() []string { + pendingTailsMu.Lock() + defer pendingTailsMu.Unlock() + apps := pendingTails + pendingTails = nil + return apps +} + +// buildLogTailsSection collects the requested tails via fetch (seam: stacks.GetLogs or +// metrics.FetchContainerLogTail). Lines stay ordered as emitted; each line is truncated +// to 400 chars and redacted; per-app total is capped at 64KB keeping the NEWEST lines. +// A failed fetch is skipped (logged) — the hub request stays pending and retries next cycle. +func buildLogTailsSection(apps []string, fetch func(app string, lines int) (string, error), logger *log.Logger) []LogTail { + var tails []LogTail + for _, app := range apps { + raw, err := fetch(app, logTailLines) + if err != nil { + if logger != nil { + logger.Printf("[WARN] [report] log-tail fetch for %s failed: %v", app, err) + } + continue + } + lines := capTailLines(strings.Split(raw, "\n")) + tails = append(tails, LogTail{App: app, CollectedAt: time.Now().UTC(), Lines: lines}) + if logger != nil { + logger.Printf("[INFO] [report] log-tail collected for %s: %d lines", app, len(lines)) + } + } + return tails +} + +// capTailLines truncates each line to logTailMaxLineChars, redacts it, and enforces the +// per-app byte budget by dropping from the HEAD (oldest) so the newest lines survive. +func capTailLines(lines []string) []string { + // Drop a trailing empty split artifact. + for len(lines) > 0 && lines[len(lines)-1] == "" { + lines = lines[:len(lines)-1] + } + out := make([]string, 0, len(lines)) + for _, l := range lines { + l = metrics.RedactLine(truncateTailLine(l, logTailMaxLineChars)) + out = append(out, l) + } + // Head-truncate to the byte budget: walk from the end accumulating. + total := 0 + start := len(out) + for i := len(out) - 1; i >= 0; i-- { + total += len(out[i]) + 1 // +1 for the newline it represents + if total > logTailMaxBytes { + break + } + start = i + } + return out[start:] +} + +func truncateTailLine(s string, max int) string { + runes := []rune(s) + if len(runes) <= max { + return s + } + return string(runes[:max]) + "…" +} diff --git a/controller/internal/report/logtail_test.go b/controller/internal/report/logtail_test.go new file mode 100644 index 0000000..aa37e58 --- /dev/null +++ b/controller/internal/report/logtail_test.go @@ -0,0 +1,115 @@ +package report + +import ( + "errors" + "fmt" + "strings" + "testing" + "unicode/utf8" +) + +// Part D — the consume-once seam: an ACK arms the pending set, the FIRST build drains +// it, the FOLLOWING build gets nothing. Red-proof: removing the clear in +// drainPendingLogTails makes the second drain return the apps again → this fails. +func TestPendingLogTails_ConsumeOnce(t *testing.T) { + SetPendingLogTails([]string{"gokapi", "cwa"}) + + first := drainPendingLogTails() + if len(first) != 2 || first[0] != "gokapi" || first[1] != "cwa" { + t.Fatalf("first drain = %v, want the two requested apps", first) + } + second := drainPendingLogTails() + if len(second) != 0 { + t.Fatalf("second drain = %v — tails would ship on EVERY report (consume-once broken)", second) + } +} + +// An ACK without requests clears any stale local set (hub is the source of truth). +func TestPendingLogTails_EmptyAckClears(t *testing.T) { + SetPendingLogTails([]string{"gokapi"}) + SetPendingLogTails(nil) + if got := drainPendingLogTails(); len(got) != 0 { + t.Fatalf("stale pending set survived an empty ACK: %v", got) + } +} + +func TestBuildLogTailsSection_OrderedAndRedacted(t *testing.T) { + fetch := func(app string, lines int) (string, error) { + if lines != 200 { + t.Fatalf("fetch asked for %d lines, want 200", lines) + } + return "line one\nline two with password=hunter2\nline three\n", nil + } + tails := buildLogTailsSection([]string{"gokapi"}, fetch, nil) + if len(tails) != 1 || tails[0].App != "gokapi" { + t.Fatalf("tails = %+v", tails) + } + got := tails[0].Lines + if len(got) != 3 { + t.Fatalf("lines = %d (trailing empty must be dropped): %#v", len(got), got) + } + if got[0] != "line one" || got[2] != "line three" { + t.Fatalf("order broken: %#v", got) + } + if strings.Contains(got[1], "hunter2") || !strings.Contains(got[1], "[REDACTED]") { + t.Fatalf("tail line not redacted: %q", got[1]) + } + if tails[0].CollectedAt.IsZero() { + t.Fatalf("collected_at not stamped") + } +} + +func TestBuildLogTailsSection_LineLengthCap(t *testing.T) { + fetch := func(string, int) (string, error) { + return strings.Repeat("y", 900) + "\nshort", nil + } + tails := buildLogTailsSection([]string{"a"}, fetch, nil) + first := tails[0].Lines[0] + if utf8.RuneCountInString(first) != 401 || !strings.HasSuffix(first, "…") { + t.Fatalf("line not capped at 400+ellipsis: runes=%d", utf8.RuneCountInString(first)) + } +} + +// 64KB per-app budget: HEAD-truncate — the newest lines must survive. +func TestBuildLogTailsSection_ByteBudgetKeepsNewest(t *testing.T) { + var sb strings.Builder + for i := 0; i < 300; i++ { + sb.WriteString(fmt.Sprintf("%04d ", i)) + sb.WriteString(strings.Repeat("p", 295)) + sb.WriteString("\n") + } + fetch := func(string, int) (string, error) { return sb.String(), nil } + tails := buildLogTailsSection([]string{"a"}, fetch, nil) + lines := tails[0].Lines + if len(lines) >= 300 { + t.Fatalf("budget not enforced: %d lines kept", len(lines)) + } + total := 0 + for _, l := range lines { + total += len(l) + 1 + } + if total > logTailMaxBytes { + t.Fatalf("kept %d bytes > %d budget", total, logTailMaxBytes) + } + if !strings.HasPrefix(lines[len(lines)-1], "0299") { + t.Fatalf("NEWEST line lost — head-truncation inverted; last kept = %q", lines[len(lines)-1][:5]) + } + if strings.HasPrefix(lines[0], "0000") { + t.Fatalf("oldest line survived a budget overflow — nothing was dropped") + } +} + +// A failed fetch skips that app but the others still ship (hub retries the failed one +// next cycle since its pending request was never fulfilled). +func TestBuildLogTailsSection_FetchErrorSkips(t *testing.T) { + fetch := func(app string, _ int) (string, error) { + if app == "broken" { + return "", errors.New("no such stack") + } + return "ok line\n", nil + } + tails := buildLogTailsSection([]string{"broken", "healthy"}, fetch, nil) + if len(tails) != 1 || tails[0].App != "healthy" { + t.Fatalf("tails = %+v, want only the healthy app", tails) + } +} diff --git a/controller/internal/report/pusher.go b/controller/internal/report/pusher.go index 4d17ff7..08050c6 100644 --- a/controller/internal/report/pusher.go +++ b/controller/internal/report/pusher.go @@ -40,6 +40,10 @@ type PushResponse struct { // Escrow (SLICE 3) is the hub's escrow status for this customer — the input to the hub-verified // auto-confirm (EscrowAutoConfirmer). nil = no escrow row on the hub (or an old hub) → stays pending. Escrow *EscrowStatus `json:"escrow"` + // LogTailRequests (v0.111.0) — app names the operator wants a log tail for. Same + // pull-based ACK-flag pattern as escrow: the NEXT report ships the tails; the hub + // clears the pending request on receipt (consume-once). Absent/empty = nothing pending. + LogTailRequests []string `json:"log_tail_requests"` } // Pusher sends reports to the central hub. diff --git a/controller/internal/report/telemetry.go b/controller/internal/report/telemetry.go index 4f54d48..5caf799 100644 --- a/controller/internal/report/telemetry.go +++ b/controller/internal/report/telemetry.go @@ -59,9 +59,52 @@ func buildAppTelemetrySection(stackMgr *stacks.Manager, metricsStore *metrics.Me if result == nil { result = []AppTelemetry{} } + + // 7. Enforce the per-report context budget (v0.111.0): drop context from the + // lowest-count issues first until under 16KB. Warns never carry context (scanner). + enforceContextBudget(result, contextBudgetBytes) + return result } +// contextBudgetBytes is the HARD per-report total for all LogIssue.Context lines. +const contextBudgetBytes = 16 * 1024 + +// enforceContextBudget drops Context from the lowest-count issues (across all apps) +// until the summed context bytes fit the budget. Mutates apps in place. +func enforceContextBudget(apps []AppTelemetry, budget int) { + type ref struct { + app, issue, size, count int + } + var refs []ref + total := 0 + for ai := range apps { + for ii := range apps[ai].Issues { + ctx := apps[ai].Issues[ii].Context + if len(ctx) == 0 { + continue + } + sz := 0 + for _, l := range ctx { + sz += len(l) + } + refs = append(refs, ref{app: ai, issue: ii, size: sz, count: apps[ai].Issues[ii].Count}) + total += sz + } + } + if total <= budget { + return + } + sort.Slice(refs, func(i, j int) bool { return refs[i].count < refs[j].count }) + for _, r := range refs { + if total <= budget { + break + } + apps[r.app].Issues[r.issue].Context = nil + total -= r.size + } +} + // buildAppTelemetry aggregates container-level telemetry and log data into per-stack AppTelemetry entries. func buildAppTelemetry(allStacks []stacks.Stack, telemetry []metrics.ContainerTelemetry, logs []metrics.ContainerLogSummary) []AppTelemetry { // Build lookup maps diff --git a/controller/internal/report/telemetry_test.go b/controller/internal/report/telemetry_test.go new file mode 100644 index 0000000..797ac37 --- /dev/null +++ b/controller/internal/report/telemetry_test.go @@ -0,0 +1,48 @@ +package report + +import ( + "strings" + "testing" + + "gitea.dooplex.hu/admin/felhom-controller/internal/metrics" +) + +func appWithIssue(name string, count, ctxBytes int) AppTelemetry { + var ctx []string + if ctxBytes > 0 { + ctx = []string{strings.Repeat("c", ctxBytes)} + } + return AppTelemetry{ + AppName: name, + Issues: []metrics.LogIssue{{Severity: "error", Message: name + " boom", Count: count, Context: ctx}}, + } +} + +// Part B caps — budget overflow drops context from the LOWEST-count issues first, +// across apps. Red-proof: inverting the sort (highest first) keeps the wrong survivor. +func TestEnforceContextBudget_DropsLowestCountFirst(t *testing.T) { + apps := []AppTelemetry{ + appWithIssue("rare", 2, 600), // lowest count — first to lose context + appWithIssue("frequent", 50, 600), // must keep context + appWithIssue("medium", 10, 600), // dropped second + } + enforceContextBudget(apps, 1000) // total 1800 → must shed 800 → drop rare, then medium + + if apps[0].Issues[0].Context != nil { + t.Fatalf("lowest-count issue kept its context") + } + if apps[2].Issues[0].Context != nil { + t.Fatalf("second-lowest issue kept its context (still over budget after one drop)") + } + if len(apps[1].Issues[0].Context) == 0 { + t.Fatalf("highest-count issue LOST its context — wrong drop order") + } +} + +func TestEnforceContextBudget_UnderBudgetUntouched(t *testing.T) { + apps := []AppTelemetry{appWithIssue("a", 1, 100), appWithIssue("b", 2, 100)} + enforceContextBudget(apps, 16*1024) + if len(apps[0].Issues[0].Context) == 0 || len(apps[1].Issues[0].Context) == 0 { + t.Fatalf("under-budget contexts must be untouched") + } +} diff --git a/controller/internal/report/types.go b/controller/internal/report/types.go index 56a8e88..198aefb 100644 --- a/controller/internal/report/types.go +++ b/controller/internal/report/types.go @@ -34,6 +34,10 @@ type Report struct { // alerts). Absent when no offbox target is enabled (and on pre-v0.109 controllers — the checker is // nil-safe on both). Offsite *backup.OffboxReportStatus `json:"offsite,omitempty"` + + // LogTails (v0.111.0) — on-demand ordered log tails, present only on the report cycle + // right after the ACK requested them (log_tail_requests). Redacted + capped (logtail.go). + LogTails []LogTail `json:"log_tails,omitempty"` } // SystemReport holds host-level system info.