From 316c2c4275a2c9d84f40f2cf62055710f7a26577 Mon Sep 17 00:00:00 2001 From: Klaus Date: Sat, 23 May 2026 19:04:28 +0000 Subject: [PATCH] debug: structured tool/HTTP logging, request IDs, config dump MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- cmd/cmd.go | 28 ++++++- operation/operation.go | 50 ++++++++++- pkg/context/context.go | 5 +- pkg/debug/debug.go | 148 +++++++++++++++++++++++++++++++++ pkg/debug/debug_test.go | 136 ++++++++++++++++++++++++++++++ pkg/flag/flag.go | 26 ++++++ pkg/flag/flag_test.go | 41 +++++++++ pkg/gitea/gitea.go | 27 +++++- pkg/gitea/rest.go | 2 +- pkg/gitea/transport.go | 67 +++++++++++++++ pkg/middleware/logging.go | 87 +++++++++++++++++++ pkg/middleware/logging_test.go | 91 ++++++++++++++++++++ pkg/to/to.go | 39 ++++++++- 13 files changed, 736 insertions(+), 11 deletions(-) create mode 100644 pkg/debug/debug.go create mode 100644 pkg/debug/debug_test.go create mode 100644 pkg/flag/flag_test.go create mode 100644 pkg/gitea/transport.go create mode 100644 pkg/middleware/logging.go create mode 100644 pkg/middleware/logging_test.go diff --git a/cmd/cmd.go b/cmd/cmd.go index 286b59d..e0c0fa2 100644 --- a/cmd/cmd.go +++ b/cmd/cmd.go @@ -61,6 +61,7 @@ func init() { fmt.Fprintf(w, " GITEA_ACCESS_TOKEN\tProvide access token\n") fmt.Fprintf(w, " GITEA_ACCESS_TOKEN_FILE\tPath to a file containing the access token (e.g. a Docker secret)\n") fmt.Fprintf(w, " GITEA_DEBUG\tSet to 'true' for debug mode\n") + fmt.Fprintf(w, " GITEA_DEBUG_SCOPES\tComma-separated debug scopes: tools, http, config (default: all)\n") fmt.Fprintf(w, " GITEA_HOST\tOverride Gitea host URL\n") fmt.Fprintf(w, " GITEA_INSECURE\tSet to 'true' to ignore TLS errors\n") fmt.Fprintf(w, " GITEA_READONLY\tSet to 'true' for read-only mode\n") @@ -79,8 +80,14 @@ func init() { flagPkg.Port = port flagPkg.Token = token + if flagPkg.Token != "" { + flagPkg.TokenSource = "flag" + } if flagPkg.Token == "" { - flagPkg.Token = os.Getenv("GITEA_ACCESS_TOKEN") + if v := os.Getenv("GITEA_ACCESS_TOKEN"); v != "" { + flagPkg.Token = v + flagPkg.TokenSource = "env" + } } if flagPkg.Token == "" { if tokenFile := os.Getenv("GITEA_ACCESS_TOKEN_FILE"); tokenFile != "" { @@ -90,6 +97,9 @@ func init() { os.Exit(1) } flagPkg.Token = strings.TrimRight(string(data), "\r\n") + if flagPkg.Token != "" { + flagPkg.TokenSource = "env-file" + } } } @@ -115,6 +125,22 @@ func init() { flagPkg.Debug = true } + // GITEA_DEBUG_SCOPES restricts what categories of debug output are + // emitted. Empty (the default) means "everything". Known scopes: + // "tools" (per-tool-call entry/exit), "http" (upstream Gitea API + // requests), "config" (effective config dump at startup). + if scopes := os.Getenv("GITEA_DEBUG_SCOPES"); scopes != "" { + set := map[string]struct{}{} + for s := range strings.SplitSeq(scopes, ",") { + if s = strings.TrimSpace(s); s != "" { + set[s] = struct{}{} + } + } + if len(set) > 0 { + flagPkg.DebugScopes = set + } + } + // Set insecure mode based on environment variable if os.Getenv("GITEA_INSECURE") == "true" { flagPkg.Insecure = true diff --git a/operation/operation.go b/operation/operation.go index c92a201..e087ec1 100644 --- a/operation/operation.go +++ b/operation/operation.go @@ -27,9 +27,11 @@ import ( mcpContext "gitea.com/gitea/gitea-mcp/pkg/context" "gitea.com/gitea/gitea-mcp/pkg/flag" "gitea.com/gitea/gitea-mcp/pkg/log" + "gitea.com/gitea/gitea-mcp/pkg/middleware" "gitea.com/gitea/gitea-mcp/pkg/tool" "github.com/mark3labs/mcp-go/server" + "go.uber.org/zap" ) var ( @@ -80,12 +82,18 @@ func getContextWithToken(ctx context.Context, r *http.Request) context.Context { return ctx } - return context.WithValue(ctx, mcpContext.TokenContextKey, token) + ctx = context.WithValue(ctx, mcpContext.TokenContextKey, token) + // Mark per-request header tokens so debug logs can show whether a tool + // call was authenticated via the header (per-request) or fell through + // to the process-wide flag/env token. + ctx = context.WithValue(ctx, mcpContext.TokenSourceContextKey, "header") + return ctx } func Run() error { mcpServer = newMCPServer(flag.Version) RegisterTool(mcpServer) + logEffectiveConfig() switch flag.Mode { case "stdio": if err := server.ServeStdio( @@ -135,5 +143,45 @@ func newMCPServer(version string) *server.MCPServer { server.WithToolCapabilities(true), server.WithLogging(), server.WithRecovery(), + // ToolLogging emits structured entry/exit logs and attaches a + // request_id + tool name to the context so downstream layers + // (the gitea RoundTripper, pkg/to result logging) can correlate. + server.WithToolHandlerMiddleware(middleware.ToolLogging), + ) +} + +// logEffectiveConfig records the runtime configuration once at startup +// when debug mode is on. This makes "did my env var actually take effect?" +// answerable from the log file without having to instrument the process. +// +// Token *values* are never logged — only the source (flag / env / env-file) +// so the operator can tell which auth path was taken. +func logEffectiveConfig() { + if !flag.DebugScopeEnabled("config") { + return + } + tokenSource := flag.TokenSource + if tokenSource == "" { + tokenSource = "none" + } + scopes := "all" + if len(flag.DebugScopes) > 0 { + keys := make([]string, 0, len(flag.DebugScopes)) + for k := range flag.DebugScopes { + keys = append(keys, k) + } + scopes = strings.Join(keys, ",") + } + log.Info("gitea-mcp effective config", + zap.String("version", flag.Version), + zap.String("host", flag.Host), + zap.String("mode", flag.Mode), + zap.Int("port", flag.Port), + zap.Bool("read_only", flag.ReadOnly), + zap.Bool("insecure", flag.Insecure), + zap.Bool("debug", flag.Debug), + zap.String("debug_scopes", scopes), + zap.String("token_source", tokenSource), + zap.Int("allowed_tools", len(flag.AllowedTools)), ) } diff --git a/pkg/context/context.go b/pkg/context/context.go index 1671037..2ea6265 100644 --- a/pkg/context/context.go +++ b/pkg/context/context.go @@ -3,5 +3,8 @@ package context type contextKey string const ( - TokenContextKey = contextKey("token") + TokenContextKey = contextKey("token") + TokenSourceContextKey = contextKey("token_source") + RequestIDContextKey = contextKey("request_id") + ToolNameContextKey = contextKey("tool_name") ) diff --git a/pkg/debug/debug.go b/pkg/debug/debug.go new file mode 100644 index 0000000..f84ecfd --- /dev/null +++ b/pkg/debug/debug.go @@ -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() +} diff --git a/pkg/debug/debug_test.go b/pkg/debug/debug_test.go new file mode 100644 index 0000000..8ec4ece --- /dev/null +++ b/pkg/debug/debug_test.go @@ -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 + } +} diff --git a/pkg/flag/flag.go b/pkg/flag/flag.go index 9e537c4..8c359db 100644 --- a/pkg/flag/flag.go +++ b/pkg/flag/flag.go @@ -11,4 +11,30 @@ var ( ReadOnly bool Debug bool AllowedTools map[string]struct{} + + // TokenSource records where flag.Token was loaded from when the process + // started: "flag", "env", "env-file", or "" if no startup token was set. + // Per-request tokens from the Authorization header bypass this and are + // labelled "header" in the context value instead. + TokenSource string + + // DebugScopes restricts what categories of debug output are emitted when + // Debug is true. An empty set means "everything" (the default). Known + // scopes: "tools", "http", "config". Parsed from GITEA_DEBUG_SCOPES. + DebugScopes map[string]struct{} ) + +// DebugScopeEnabled reports whether a given debug scope should be logged. +// Returns true if Debug is off (so callers don't accidentally activate logs +// they shouldn't), false. When Debug is on and DebugScopes is empty, all +// scopes are enabled. +func DebugScopeEnabled(scope string) bool { + if !Debug { + return false + } + if len(DebugScopes) == 0 { + return true + } + _, ok := DebugScopes[scope] + return ok +} diff --git a/pkg/flag/flag_test.go b/pkg/flag/flag_test.go new file mode 100644 index 0000000..ce27d8c --- /dev/null +++ b/pkg/flag/flag_test.go @@ -0,0 +1,41 @@ +package flag + +import "testing" + +func TestDebugScopeEnabled(t *testing.T) { + origDebug := Debug + origScopes := DebugScopes + defer func() { + Debug = origDebug + DebugScopes = origScopes + }() + + t.Run("off when debug disabled", func(t *testing.T) { + Debug = false + DebugScopes = nil + if DebugScopeEnabled("tools") { + t.Fatal("scope should be disabled when Debug is false") + } + }) + + t.Run("all scopes when set is empty", func(t *testing.T) { + Debug = true + DebugScopes = nil + for _, s := range []string{"tools", "http", "config", "anything"} { + if !DebugScopeEnabled(s) { + t.Fatalf("scope %q should be enabled when DebugScopes is empty", s) + } + } + }) + + t.Run("only listed scopes when set is non-empty", func(t *testing.T) { + Debug = true + DebugScopes = map[string]struct{}{"tools": {}} + if !DebugScopeEnabled("tools") { + t.Fatal("tools should be enabled") + } + if DebugScopeEnabled("http") { + t.Fatal("http should not be enabled") + } + }) +} diff --git a/pkg/gitea/gitea.go b/pkg/gitea/gitea.go index 06c3a5c..1b0f04a 100644 --- a/pkg/gitea/gitea.go +++ b/pkg/gitea/gitea.go @@ -18,6 +18,8 @@ var ( clientCache sync.Map // token -> *gitea.Client sharedTransOnce sync.Once sharedTrans *http.Transport + sharedRTOnce sync.Once + sharedRT http.RoundTripper ) func sharedTransport() *http.Transport { @@ -30,6 +32,22 @@ func sharedTransport() *http.Transport { return sharedTrans } +// sharedRoundTripper returns the RoundTripper used by every HTTP client in +// this package. In debug mode it wraps the underlying transport with a +// logger that records one entry per upstream Gitea call. Wrapping at the +// RoundTripper layer means both the SDK-driven path (NewClient) and the +// hand-rolled REST helpers (DoJSON/DoBytes) get the same instrumentation. +func sharedRoundTripper() http.RoundTripper { + sharedRTOnce.Do(func() { + var rt http.RoundTripper = sharedTransport() + if flag.Debug { + rt = &loggingRoundTripper{base: rt} + } + sharedRT = rt + }) + return sharedRT +} + // NewClient returns a cached *gitea.Client keyed by host+token. The SDK's per-client // version cache and the shared transport let us reuse keep-alive connections // and avoid the SDK's /api/v1/version preflight on every tool call. @@ -40,16 +58,17 @@ func NewClient(token string) (*gitea.Client, error) { } httpClient := &http.Client{ - Transport: sharedTransport(), + Transport: sharedRoundTripper(), CheckRedirect: checkRedirect, } + // We intentionally don't enable gitea.SetDebugMode() even when + // flag.Debug is on: that mode writes to a separate, unstructured stream + // that doesn't merge with our zap log file. The loggingRoundTripper + // installed above provides equivalent (and structured) visibility. opts := []gitea.ClientOption{ gitea.SetToken(token), gitea.SetHTTPClient(httpClient), } - if flag.Debug { - opts = append(opts, gitea.SetDebugMode()) - } client, err := gitea.NewClient(flag.Host, opts...) if err != nil { return nil, fmt.Errorf("create gitea client err: %w", err) diff --git a/pkg/gitea/rest.go b/pkg/gitea/rest.go index ba745da..fb2ca04 100644 --- a/pkg/gitea/rest.go +++ b/pkg/gitea/rest.go @@ -51,7 +51,7 @@ var ( func restHTTPClient() *http.Client { restClientOnce.Do(func() { restClient = &http.Client{ - Transport: sharedTransport(), + Transport: sharedRoundTripper(), Timeout: httpClientTimeout, CheckRedirect: checkRedirect, } diff --git a/pkg/gitea/transport.go b/pkg/gitea/transport.go new file mode 100644 index 0000000..63a436a --- /dev/null +++ b/pkg/gitea/transport.go @@ -0,0 +1,67 @@ +package gitea + +import ( + "net/http" + "time" + + "gitea.com/gitea/gitea-mcp/pkg/debug" + "gitea.com/gitea/gitea-mcp/pkg/flag" + "gitea.com/gitea/gitea-mcp/pkg/log" + + "go.uber.org/zap" +) + +// loggingRoundTripper wraps an http.RoundTripper to emit one structured log +// entry per upstream Gitea API call when debug is enabled. The information +// here is much more useful for diagnosing slow / failing tool calls than the +// gitea SDK's built-in debug mode (which only writes a separate, free-form +// stream that doesn't merge with the zap log file). +// +// We log: +// - method, URL (with sensitive query params stripped) +// - request_id from the request context (when the caller propagated one) +// - HTTP status code (or transport-level error) +// - duration in milliseconds +// - response Content-Length when the server provided one +// +// We deliberately do NOT log request or response bodies — those routinely +// contain user secrets (tokens being created, webhook payloads, file +// contents) and the log file is meant to be safe to share. +type loggingRoundTripper struct { + base http.RoundTripper +} + +func (rt *loggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) { + if !flag.DebugScopeEnabled("http") { + return rt.base.RoundTrip(req) + } + + start := time.Now() + resp, err := rt.base.RoundTrip(req) + duration := time.Since(start) + + fields := []zap.Field{ + zap.String("method", req.Method), + zap.String("url", debug.StripQueryTokens(req.URL.String())), + zap.Int64("duration_ms", duration.Milliseconds()), + } + if reqID := debug.RequestIDFromContext(req.Context()); reqID != "" { + fields = append(fields, zap.String("request_id", reqID)) + } + if toolName := debug.ToolNameFromContext(req.Context()); toolName != "" { + fields = append(fields, zap.String("tool", toolName)) + } + + if err != nil { + fields = append(fields, zap.String("error", err.Error())) + log.Debug("gitea http: transport error", fields...) + return resp, err + } + + fields = append(fields, + zap.Int("status", resp.StatusCode), + zap.Int64("bytes_in", resp.ContentLength), + ) + log.Debug("gitea http: response", fields...) + return resp, nil +} diff --git a/pkg/middleware/logging.go b/pkg/middleware/logging.go new file mode 100644 index 0000000..7d2cd24 --- /dev/null +++ b/pkg/middleware/logging.go @@ -0,0 +1,87 @@ +// Package middleware contains MCP tool-handler middlewares. +package middleware + +import ( + "context" + "time" + + mcpContext "gitea.com/gitea/gitea-mcp/pkg/context" + "gitea.com/gitea/gitea-mcp/pkg/debug" + "gitea.com/gitea/gitea-mcp/pkg/flag" + "gitea.com/gitea/gitea-mcp/pkg/log" + + "github.com/mark3labs/mcp-go/mcp" + "github.com/mark3labs/mcp-go/server" + "go.uber.org/zap" +) + +// ToolLogging wraps a ToolHandlerFunc to emit structured entry/exit logs +// for every tool invocation. When debug is off it is effectively a no-op +// aside from attaching a request ID and tool name to the context (which the +// `to` package and the HTTP RoundTripper read for correlation). +// +// At debug level we log: +// - on entry: tool name, redacted args, request_id, token source +// - on exit: status (ok/error), duration_ms, error message if any +// +// At error level we always log a contextual error entry (even when debug is +// off) so an operator looking at the log can tell *which* tool failed. +func ToolLogging(next server.ToolHandlerFunc) server.ToolHandlerFunc { + return func(ctx context.Context, req mcp.CallToolRequest) (*mcp.CallToolResult, error) { + reqID := debug.NewRequestID() + ctx = context.WithValue(ctx, mcpContext.RequestIDContextKey, reqID) + ctx = context.WithValue(ctx, mcpContext.ToolNameContextKey, req.Params.Name) + + tokenSource := tokenSourceFromContext(ctx) + + if flag.DebugScopeEnabled("tools") { + log.Debug("tool call: start", + zap.String("tool", req.Params.Name), + zap.String("request_id", reqID), + zap.String("token_source", tokenSource), + zap.Any("args", debug.RedactArgs(req.Params.Arguments)), + ) + } + + start := time.Now() + result, err := next(ctx, req) + duration := time.Since(start) + + fields := []zap.Field{ + zap.String("tool", req.Params.Name), + zap.String("request_id", reqID), + zap.Int64("duration_ms", duration.Milliseconds()), + } + + switch { + case err != nil: + // Always-on contextual error log. This replaces the bare + // `log.Errorf("%s", err)` previously in pkg/to.ErrorResult, + // which had no tool name attached. + log.Error("tool call: error", + append(fields, zap.String("error", err.Error()))...) + case result != nil && result.IsError: + if flag.DebugScopeEnabled("tools") { + log.Debug("tool call: returned isError=true", fields...) + } + default: + if flag.DebugScopeEnabled("tools") { + log.Debug("tool call: ok", fields...) + } + } + + return result, err + } +} + +func tokenSourceFromContext(ctx context.Context) string { + if ctx != nil { + if v, ok := ctx.Value(mcpContext.TokenSourceContextKey).(string); ok && v != "" { + return v + } + } + if flag.TokenSource != "" { + return flag.TokenSource + } + return "none" +} diff --git a/pkg/middleware/logging_test.go b/pkg/middleware/logging_test.go new file mode 100644 index 0000000..d84f016 --- /dev/null +++ b/pkg/middleware/logging_test.go @@ -0,0 +1,91 @@ +package middleware + +import ( + "context" + "errors" + "testing" + + mcpContext "gitea.com/gitea/gitea-mcp/pkg/context" + "gitea.com/gitea/gitea-mcp/pkg/debug" + "gitea.com/gitea/gitea-mcp/pkg/flag" + + "github.com/mark3labs/mcp-go/mcp" +) + +func TestToolLogging_PropagatesContextValues(t *testing.T) { + origDebug := flag.Debug + defer func() { flag.Debug = origDebug }() + flag.Debug = false // exercise the no-log code path; context wiring runs regardless + + var ( + gotToolName string + gotReqID string + ) + handler := func(ctx context.Context, _ mcp.CallToolRequest) (*mcp.CallToolResult, error) { + gotToolName = debug.ToolNameFromContext(ctx) + gotReqID = debug.RequestIDFromContext(ctx) + return mcp.NewToolResultText("ok"), nil + } + + wrapped := ToolLogging(handler) + + req := mcp.CallToolRequest{} + req.Params.Name = "get_me" + req.Params.Arguments = map[string]any{"x": 1} + + res, err := wrapped(context.Background(), req) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if res == nil { + t.Fatal("expected non-nil result") + } + if gotToolName != "get_me" { + t.Fatalf("tool name not propagated, got %q", gotToolName) + } + if gotReqID == "" { + t.Fatal("request id not propagated") + } +} + +func TestToolLogging_ReturnsHandlerError(t *testing.T) { + want := errors.New("boom") + wrapped := ToolLogging(func(_ context.Context, _ mcp.CallToolRequest) (*mcp.CallToolResult, error) { + return nil, want + }) + + req := mcp.CallToolRequest{} + req.Params.Name = "broken_tool" + + _, err := wrapped(context.Background(), req) + if !errors.Is(err, want) { + t.Fatalf("error not surfaced, got %v", err) + } +} + +func TestTokenSourceFromContext(t *testing.T) { + origFlag := flag.TokenSource + defer func() { flag.TokenSource = origFlag }() + + t.Run("falls back to flag.TokenSource", func(t *testing.T) { + flag.TokenSource = "env" + if got := tokenSourceFromContext(context.Background()); got != "env" { + t.Fatalf("got %q want env", got) + } + }) + + t.Run("returns none when no source is known", func(t *testing.T) { + flag.TokenSource = "" + if got := tokenSourceFromContext(context.Background()); got != "none" { + t.Fatalf("got %q want none", got) + } + }) + + t.Run("context value beats flag", func(t *testing.T) { + flag.TokenSource = "env" + ctx := context.WithValue(context.Background(), mcpContext.TokenSourceContextKey, "header") + if got := tokenSourceFromContext(ctx); got != "header" { + t.Fatalf("got %q want header", got) + } + }) +} diff --git a/pkg/to/to.go b/pkg/to/to.go index b56dd23..3de0940 100644 --- a/pkg/to/to.go +++ b/pkg/to/to.go @@ -1,13 +1,16 @@ package to import ( + "context" "encoding/json" "fmt" + "gitea.com/gitea/gitea-mcp/pkg/debug" "gitea.com/gitea/gitea-mcp/pkg/flag" "gitea.com/gitea/gitea-mcp/pkg/log" "github.com/mark3labs/mcp-go/mcp" + "go.uber.org/zap" ) func TextResult(v any) (*mcp.CallToolResult, error) { @@ -15,13 +18,43 @@ func TextResult(v any) (*mcp.CallToolResult, error) { if err != nil { return nil, fmt.Errorf("marshal result err: %v", err) } - if flag.Debug { - log.Debugf("Text Result: %s", string(resultBytes)) + if flag.DebugScopeEnabled("tools") { + // We can't take a context here without breaking every caller, so we + // log without the request_id correlation. The middleware's exit log + // records the request_id + duration; this entry adds a (truncated) + // payload preview for callers that want to see what came back. + log.Debug("tool call: result", + zap.Int("bytes", len(resultBytes)), + zap.String("preview", debug.TruncatePreview(string(resultBytes))), + ) } return mcp.NewToolResultText(string(resultBytes)), nil } +// TextResultCtx is the context-aware variant of TextResult. New call sites +// should prefer it so log lines carry the request_id and tool name. The +// non-context TextResult above is kept for backwards compatibility with +// the many existing tool handlers. +func TextResultCtx(ctx context.Context, v any) (*mcp.CallToolResult, error) { + resultBytes, err := json.Marshal(v) + if err != nil { + return nil, fmt.Errorf("marshal result err: %v", err) + } + if flag.DebugScopeEnabled("tools") { + log.Debug("tool call: result", + zap.String("tool", debug.ToolNameFromContext(ctx)), + zap.String("request_id", debug.RequestIDFromContext(ctx)), + zap.Int("bytes", len(resultBytes)), + zap.String("preview", debug.TruncatePreview(string(resultBytes))), + ) + } + return mcp.NewToolResultText(string(resultBytes)), nil +} + +// ErrorResult returns the error to the MCP layer. We no longer log here — +// the ToolLogging middleware emits a structured error entry that includes +// the tool name and request_id, which is far more useful than the bare +// `log.Errorf("%s", err)` this used to do. func ErrorResult(err error) (*mcp.CallToolResult, error) { - log.Errorf("%s", err.Error()) return nil, err } -- 2.54.0