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>

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

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)),
 	)
 }

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")
 )

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()
+}

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
+	}
+}

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
+}

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")
+		}
+	})
+}

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)

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,
 		}

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
+}

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"
+}

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)
+		}
+	})
+}

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 {
+	if flag.DebugScopeEnabled("tools") {
-		log.Debugf("Text Result: %s", string(resultBytes))
+		// 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
 }