v0.111.0: remote app-log diagnostics — error context capture (±5 lines, capped+redacted) + on-demand log tails via ACK pull pattern

- 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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01PSK5g6qYLknKj8u3QAFEr6
2026-07-10 15:43:29 +02:00
parent 332725a024
commit 544c42a618
12 changed files with 670 additions and 8 deletions
@@ -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.
@@ -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)
+	}
+}
@@ -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 <token>" 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
+}
@@ -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)
+		}
+	}
+}