debug: structured tool/HTTP logging, request IDs, config dump

Closes #13. Today GITEA_DEBUG=true only flips the zap level to debug, dumps a contextless `Text Result:` blob per tool call, and enables the gitea SDK's own debug stream (which doesn't merge with our log file). That is not enough to diagnose a misbehaving tool call in production. This change introduces: - A `pkg/middleware.ToolLogging` ToolHandlerMiddleware that logs each tool invocation on entry and exit with structured fields: tool name, redacted args, request_id, token source, duration_ms, and status. The request_id is stashed in the context so downstream layers can correlate. - A `loggingRoundTripper` in `pkg/gitea` that wraps the shared HTTP transport and emits one structured line per upstream Gitea API call (method, token-stripped URL, status, duration_ms, bytes). This replaces — and is far more useful than — `gitea.SetDebugMode()`. - An effective-config dump at startup (`logEffectiveConfig`) when debug+config scope is on, so "did my env var get picked up?" becomes answerable from the log file. - Token source tracking. CLI flag / GITEA_ACCESS_TOKEN / GITEA_ACCESS_TOKEN_FILE / per-request Authorization header are now distinguished in logs as flag/env/env-file/header. - A baseline redactor in `pkg/debug` that masks args / query params whose keys look like secrets (token, password, secret, api_key, authorization, …). This is the placeholder for issue #5's shared redactor; once that lands, callers here should defer to it. - `GITEA_DEBUG_SCOPES` env var to scope debug output to any subset of `tools,http,config`. Default (unset) is "everything". Test coverage was added for the redactor, scope flag, request-id helpers, preview truncation (multibyte-safe), and the middleware's context wiring + error propagation. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
2026-05-23 19:04:28 +00:00
parent 4d7a33e57e
commit 316c2c4275
13 changed files with 736 additions and 11 deletions
@@ -0,0 +1,148 @@
+// Package debug provides helpers for the structured debug-mode plumbing:
+// request IDs, baseline argument/result redaction, and result-preview
+// truncation. See issue #13.
+//
+// Redaction here is intentionally a thin baseline. Issue #5 will introduce a
+// shared redactor; once that lands the helpers in this file should defer to
+// it instead of doing their own key-name matching.
+package debug
+
+import (
+	"context"
+	"crypto/rand"
+	"encoding/hex"
+	"net/url"
+	"strings"
+	"unicode/utf8"
+
+	mcpContext "gitea.com/gitea/gitea-mcp/pkg/context"
+)
+
+// MaxResultPreview caps the size of result snippets in debug logs so a huge
+// response body doesn't dominate the log file.
+const MaxResultPreview = 1024
+
+// NewRequestID returns a short hex-encoded identifier used to correlate
+// log lines for a single tool invocation across the middleware, the result
+// formatter, and the HTTP RoundTripper.
+func NewRequestID() string {
+	var b [6]byte
+	if _, err := rand.Read(b[:]); err != nil {
+		// crypto/rand failing is exceptional; fall back to a fixed marker
+		// rather than panicking inside an observability-only code path.
+		return "req-unknown"
+	}
+	return hex.EncodeToString(b[:])
+}
+
+// RequestIDFromContext returns the request ID from ctx, or "" if absent.
+func RequestIDFromContext(ctx context.Context) string {
+	if ctx == nil {
+		return ""
+	}
+	if v, ok := ctx.Value(mcpContext.RequestIDContextKey).(string); ok {
+		return v
+	}
+	return ""
+}
+
+// ToolNameFromContext returns the tool name recorded by the logging
+// middleware, or "" if the call wasn't routed through it (e.g. direct REST
+// helper calls in tests).
+func ToolNameFromContext(ctx context.Context) string {
+	if ctx == nil {
+		return ""
+	}
+	if v, ok := ctx.Value(mcpContext.ToolNameContextKey).(string); ok {
+		return v
+	}
+	return ""
+}
+
+// sensitiveKeys are argument names that should never appear verbatim in logs.
+// Match is case-insensitive and substring-based to catch variants like
+// "access_token", "api_key", "client_secret".
+var sensitiveKeys = []string{
+	"token", "password", "passwd", "secret", "api_key", "apikey",
+	"authorization", "auth", "credential",
+}
+
+// RedactArgs walks a tool-argument value and returns a copy with sensitive
+// fields masked. Non-map / non-slice values are returned as-is. The input is
+// not mutated.
+func RedactArgs(v any) any {
+	switch t := v.(type) {
+	case map[string]any:
+		out := make(map[string]any, len(t))
+		for k, val := range t {
+			if isSensitiveKey(k) {
+				out[k] = "[REDACTED]"
+				continue
+			}
+			out[k] = RedactArgs(val)
+		}
+		return out
+	case []any:
+		out := make([]any, len(t))
+		for i, val := range t {
+			out[i] = RedactArgs(val)
+		}
+		return out
+	default:
+		return v
+	}
+}
+
+func isSensitiveKey(k string) bool {
+	lower := strings.ToLower(k)
+	for _, s := range sensitiveKeys {
+		if strings.Contains(lower, s) {
+			return true
+		}
+	}
+	return false
+}
+
+// StripQueryTokens removes query parameters whose names look sensitive so
+// they don't end up in HTTP-level URL logs. Returns the input unchanged if
+// it can't be parsed.
+func StripQueryTokens(rawURL string) string {
+	u, err := url.Parse(rawURL)
+	if err != nil {
+		return rawURL
+	}
+	q := u.Query()
+	changed := false
+	for k := range q {
+		if isSensitiveKey(k) {
+			q.Set(k, "REDACTED")
+			changed = true
+		}
+	}
+	if !changed {
+		return rawURL
+	}
+	u.RawQuery = q.Encode()
+	return u.String()
+}
+
+// TruncatePreview returns s clipped to MaxResultPreview runes, with an
+// ellipsis suffix if anything was dropped. Operates on runes (not bytes) so
+// we don't slice through the middle of a UTF-8 sequence.
+func TruncatePreview(s string) string {
+	if utf8.RuneCountInString(s) <= MaxResultPreview {
+		return s
+	}
+	var b strings.Builder
+	b.Grow(MaxResultPreview + 4)
+	count := 0
+	for _, r := range s {
+		if count >= MaxResultPreview {
+			break
+		}
+		b.WriteRune(r)
+		count++
+	}
+	b.WriteString("...")
+	return b.String()
+}
@@ -0,0 +1,136 @@
+package debug
+
+import (
+	"context"
+	"strings"
+	"testing"
+
+	mcpContext "gitea.com/gitea/gitea-mcp/pkg/context"
+)
+
+func TestRedactArgs(t *testing.T) {
+	in := map[string]any{
+		"owner":    "octocat",
+		"repo":     "hello",
+		"token":    "ghp_secret",
+		"password": "hunter2",
+		"nested": map[string]any{
+			"api_key":     "abc",
+			"safe":        "value",
+			"authHeader":  "Bearer xyz",
+			"client_id":   "ok-to-log",
+			"credentials": "shh",
+		},
+		"items": []any{
+			map[string]any{"secret": "zzz", "ok": "yes"},
+		},
+	}
+	out := RedactArgs(in).(map[string]any)
+	if out["owner"] != "octocat" {
+		t.Fatalf("owner should be unchanged, got %v", out["owner"])
+	}
+	if out["token"] != "[REDACTED]" {
+		t.Fatalf("token should be redacted, got %v", out["token"])
+	}
+	if out["password"] != "[REDACTED]" {
+		t.Fatalf("password should be redacted, got %v", out["password"])
+	}
+	nested := out["nested"].(map[string]any)
+	if nested["api_key"] != "[REDACTED]" || nested["authHeader"] != "[REDACTED]" || nested["credentials"] != "[REDACTED]" {
+		t.Fatalf("nested sensitive keys not redacted: %+v", nested)
+	}
+	if nested["safe"] != "value" {
+		t.Fatalf("safe key should be unchanged: %+v", nested)
+	}
+	// client_id does not match any sensitive substring; "id" alone shouldn't trip.
+	if nested["client_id"] != "ok-to-log" {
+		t.Fatalf("client_id should be unchanged: %+v", nested)
+	}
+	item := out["items"].([]any)[0].(map[string]any)
+	if item["secret"] != "[REDACTED]" {
+		t.Fatalf("list item secret not redacted: %+v", item)
+	}
+	if item["ok"] != "yes" {
+		t.Fatalf("safe list item key changed: %+v", item)
+	}
+	// Original input must not be mutated.
+	if in["token"] != "ghp_secret" {
+		t.Fatalf("RedactArgs mutated input: %+v", in)
+	}
+}
+
+func TestRedactArgs_NonMap(t *testing.T) {
+	for _, v := range []any{"plain", 42, nil, true} {
+		if got := RedactArgs(v); got != v {
+			t.Fatalf("non-map value should pass through unchanged: got %v want %v", got, v)
+		}
+	}
+}
+
+func TestStripQueryTokens(t *testing.T) {
+	in := "https://gitea.example.com/api/v1/repos/x/y?token=abc&page=1&access_token=def"
+	got := StripQueryTokens(in)
+	if strings.Contains(got, "abc") || strings.Contains(got, "def") {
+		t.Fatalf("token value leaked through: %s", got)
+	}
+	if !strings.Contains(got, "page=1") {
+		t.Fatalf("non-sensitive params should be preserved: %s", got)
+	}
+}
+
+func TestStripQueryTokens_NoChange(t *testing.T) {
+	in := "https://gitea.example.com/api/v1/repos/x/y?page=1"
+	if got := StripQueryTokens(in); got != in {
+		t.Fatalf("non-sensitive URL was modified: %s -> %s", in, got)
+	}
+}
+
+func TestTruncatePreview(t *testing.T) {
+	long := strings.Repeat("a", MaxResultPreview+50)
+	got := TruncatePreview(long)
+	if !strings.HasSuffix(got, "...") {
+		t.Fatalf("truncated preview should end with ellipsis: %q", got[len(got)-10:])
+	}
+	if len(got) > MaxResultPreview+5 {
+		t.Fatalf("preview not bounded: len=%d", len(got))
+	}
+
+	short := "hi"
+	if got := TruncatePreview(short); got != short {
+		t.Fatalf("short string should be returned as-is, got %q", got)
+	}
+}
+
+func TestTruncatePreview_MultibyteSafe(t *testing.T) {
+	// Make a string with multi-byte runes long enough to trip naive byte-slicing.
+	r := strings.Repeat("日", MaxResultPreview+10)
+	got := TruncatePreview(r)
+	// Must remain valid UTF-8: a naive byte slice on this would split a rune.
+	for _, b := range got {
+		_ = b // ranging validates that decoding doesn't panic
+	}
+}
+
+func TestRequestIDFromContext(t *testing.T) {
+	if got := RequestIDFromContext(context.Background()); got != "" {
+		t.Fatalf("absent request id should return \"\", got %q", got)
+	}
+	ctx := context.WithValue(context.Background(), mcpContext.RequestIDContextKey, "abc123")
+	if got := RequestIDFromContext(ctx); got != "abc123" {
+		t.Fatalf("got %q, want abc123", got)
+	}
+}
+
+func TestNewRequestID_UniqueAndHex(t *testing.T) {
+	seen := map[string]bool{}
+	for i := 0; i < 100; i++ {
+		id := NewRequestID()
+		if id == "" {
+			t.Fatal("empty request id")
+		}
+		if seen[id] {
+			t.Fatalf("duplicate request id: %s", id)
+		}
+		seen[id] = true
+	}
+}