debug: make debug mode actually useful for troubleshooting #14

2026-05-23T19:06:27Z

Klaus commented

2026-05-23 19:06:27 +00:00

Closes #13.

Why

GITEA_DEBUG=true is the only observability knob the server has, and today it does surprisingly little:

Lowers the zap level to Debug (pkg/log/log.go).
Emits a contextless Text Result: <json> blob from pkg/to/to.go.
Enables gitea.SetDebugMode(), which writes to its own stream that does not merge with our log file (pkg/gitea/gitea.go).

When a tool call goes wrong, none of that tells you:

Which tool was called, with what args, by which caller?
How long did it take? Was the slow part the MCP server or the upstream Gitea API?
Was the call authenticated via the per-request Authorization header, or did it fall through to --token / GITEA_ACCESS_TOKEN?
Which upstream API request actually failed?
In HTTP mode with concurrent clients, which debug lines belong together?

This PR closes those gaps without changing default behaviour for users who don't enable debug.

What changed

1. Structured tool-invocation logging (`pkg/middleware/logging.go`)

A new ToolLogging middleware is registered via server.WithToolHandlerMiddleware(...) in newMCPServer. For every tool call it:

Generates a short hex request_id and stores it in the context together with the tool name.
On entry (debug only) logs tool, request_id, token_source, and args (redacted — see §4).
On exit logs duration_ms and status. Errors are logged at error level (always on) so even non-debug operators can see which tool failed; previously to.ErrorResult did log.Errorf("%s", err.Error()) with no tool context attached.

This replaces the Text Result: blob in pkg/to.TextResult with a proper structured entry that includes the tool name, request_id, byte count, and a truncated preview. A new TextResultCtx(ctx, v) variant is provided for new call sites; the legacy TextResult is preserved unchanged for backwards compatibility with the many existing handlers.

2. Upstream HTTP logging via a RoundTripper (`pkg/gitea/transport.go`)

A loggingRoundTripper wraps the shared *http.Transport. When flag.Debug is on, it emits one structured entry per upstream Gitea API call:

method, url (with sensitive query params stripped), status, duration_ms, bytes_in
request_id and tool pulled from req.Context() when available, so HTTP lines can be joined with the middleware's entry/exit lines

Because the RoundTripper sits on the shared transport, both code paths use it: NewClient(...) (the gitea SDK path) and the hand-rolled DoJSON / DoBytes helpers in rest.go. The latter propagate the tool ctx end-to-end via http.NewRequestWithContext, so HTTP log lines from those carry a correlation id; SDK calls don't propagate the ctx (the SDK uses its own background context on the cached client), so they log without a request_id — still useful because method+url+status+duration is the actionable information.

gitea.SetDebugMode() is no longer enabled — the RoundTripper supersedes it and integrates with the existing zap log file.

3. Effective-config dump at startup (`operation.logEffectiveConfig`)

When debug + config scope are on, the server logs version, host, mode, port, read-only, insecure, debug, debug_scopes, token_source, and allowed_tools count exactly once. No token values are ever logged — only the source.

This answers "did my env var actually get picked up?" without having to instrument the process.

4. Token source tracking

pkg/flag now records where the process-wide token came from at startup: flag (CLI), env (GITEA_ACCESS_TOKEN), env-file (GITEA_ACCESS_TOKEN_FILE), or empty. In HTTP mode, when an Authorization header supplies a token, getContextWithToken stashes "header" as the context-scoped token source. The middleware and the startup dump both report this.

5. Baseline redaction (`pkg/debug.RedactArgs` / `StripQueryTokens`)

Issue #13 notes that redaction overlaps with #5. This PR adds a minimal redactor — case-insensitive substring match on token, password, secret, api_key, authorization, auth, credential — so turning on debug isn't an immediate footgun. The package doc explicitly flags this as a placeholder that #5's shared redactor should replace.

Result-preview truncation (debug.TruncatePreview, 1024 runes) is multibyte-safe (operates on runes, not bytes) to avoid splitting a UTF-8 sequence in the log file.

6. Stretch goal: `GITEA_DEBUG_SCOPES`

Implemented as listed in the issue:

GITEA_DEBUG_SCOPES=tools,http,config
Empty (default) = all scopes when debug is on
flag.DebugScopeEnabled(scope) is the single check used by every call site

Why this shape

A few design choices worth flagging:

Tool middleware over per-handler wrappers. mcp-go exposes WithToolHandlerMiddleware, which lets us instrument all 45 tools centrally. Wrapping each handler would have meant touching every operation/*/*.go file and would have made backports messier.
Request ID via context, not headers. The middleware sets request_id in ctx.Value(...). For pkg/gitea/rest.go this propagates through http.NewRequestWithContext, so the RoundTripper sees it on req.Context(). SDK calls lose the linkage because the cached SDK client owns its own context, but that's an acceptable trade for keeping the SDK client cache (which avoids a /api/v1/version preflight per call).
TextResult left intact. Every operation module calls to.TextResult(...). Changing its signature would have caused a churn-y diff and conflict with in-flight work. TextResultCtx is provided so new code can opt in to context-aware logging.
Errors logged unconditionally. Even when debug is off, tool call: error is now a structured error-level entry with tool name and request_id. The pre-existing bare log.Errorf in to.ErrorResult lost this context — the middleware restores it.

Test coverage

pkg/debug/debug_test.go — argument redaction (nested maps, slices, non-sensitive keys preserved, input not mutated), query-string stripping, multi-byte-safe preview truncation, request-id uniqueness / format, context lookup.
pkg/flag/flag_test.go — DebugScopeEnabled semantics (off when debug off, "everything" when empty, allow-list when populated).
pkg/middleware/logging_test.go — context wiring (tool name + request_id reach the handler), error propagation from wrapped handler, token-source resolution order (ctx > flag > "none").

go test ./... is green; go vet ./... is clean.

Out of scope

Full redaction (depends on #5 — placeholder marker left in pkg/debug and in code comments).
Server-side propagation of an X-Request-Id header into the client-facing response (depends on #9).
Switching every existing to.TextResult call site to TextResultCtx. Doable as a follow-up; the new variant is in place for it.

Closes #13. ## Why `GITEA_DEBUG=true` is the only observability knob the server has, and today it does surprisingly little: 1. Lowers the zap level to `Debug` (`pkg/log/log.go`). 2. Emits a contextless `Text Result: <json>` blob from `pkg/to/to.go`. 3. Enables `gitea.SetDebugMode()`, which writes to its own stream that **does not merge with our log file** (`pkg/gitea/gitea.go`). When a tool call goes wrong, none of that tells you: - Which tool was called, with what args, by which caller? - How long did it take? Was the slow part the MCP server or the upstream Gitea API? - Was the call authenticated via the per-request Authorization header, or did it fall through to `--token` / `GITEA_ACCESS_TOKEN`? - Which upstream API request actually failed? - In HTTP mode with concurrent clients, which debug lines belong together? This PR closes those gaps without changing default behaviour for users who don't enable debug. ## What changed ### 1. Structured tool-invocation logging (`pkg/middleware/logging.go`) A new `ToolLogging` middleware is registered via `server.WithToolHandlerMiddleware(...)` in `newMCPServer`. For every tool call it: - Generates a short hex `request_id` and stores it in the context together with the tool name. - On entry (debug only) logs `tool`, `request_id`, `token_source`, and `args` (redacted — see §4). - On exit logs `duration_ms` and `status`. Errors are logged at `error` level (always on) so even non-debug operators can see *which* tool failed; previously `to.ErrorResult` did `log.Errorf("%s", err.Error())` with no tool context attached. This replaces the `Text Result:` blob in `pkg/to.TextResult` with a proper structured entry that includes the tool name, request_id, byte count, and a truncated preview. A new `TextResultCtx(ctx, v)` variant is provided for new call sites; the legacy `TextResult` is preserved unchanged for backwards compatibility with the many existing handlers. ### 2. Upstream HTTP logging via a RoundTripper (`pkg/gitea/transport.go`) A `loggingRoundTripper` wraps the shared `*http.Transport`. When `flag.Debug` is on, it emits one structured entry per upstream Gitea API call: - `method`, `url` (with sensitive query params stripped), `status`, `duration_ms`, `bytes_in` - `request_id` and `tool` pulled from `req.Context()` when available, so HTTP lines can be joined with the middleware's entry/exit lines Because the RoundTripper sits on the shared transport, **both** code paths use it: `NewClient(...)` (the gitea SDK path) and the hand-rolled `DoJSON` / `DoBytes` helpers in `rest.go`. The latter propagate the tool ctx end-to-end via `http.NewRequestWithContext`, so HTTP log lines from those carry a correlation id; SDK calls don't propagate the ctx (the SDK uses its own background context on the cached client), so they log without a request_id — still useful because method+url+status+duration is the actionable information. `gitea.SetDebugMode()` is no longer enabled — the RoundTripper supersedes it and integrates with the existing zap log file. ### 3. Effective-config dump at startup (`operation.logEffectiveConfig`) When `debug` + `config` scope are on, the server logs version, host, mode, port, read-only, insecure, debug, debug_scopes, token_source, and allowed_tools count exactly once. No token *values* are ever logged — only the source. This answers "did my env var actually get picked up?" without having to instrument the process. ### 4. Token source tracking `pkg/flag` now records where the process-wide token came from at startup: `flag` (CLI), `env` (`GITEA_ACCESS_TOKEN`), `env-file` (`GITEA_ACCESS_TOKEN_FILE`), or empty. In HTTP mode, when an `Authorization` header supplies a token, `getContextWithToken` stashes `"header"` as the context-scoped token source. The middleware and the startup dump both report this. ### 5. Baseline redaction (`pkg/debug.RedactArgs` / `StripQueryTokens`) Issue #13 notes that redaction overlaps with #5. This PR adds a *minimal* redactor — case-insensitive substring match on `token`, `password`, `secret`, `api_key`, `authorization`, `auth`, `credential` — so turning on debug isn't an immediate footgun. The package doc explicitly flags this as a placeholder that #5's shared redactor should replace. Result-preview truncation (`debug.TruncatePreview`, 1024 runes) is multibyte-safe (operates on runes, not bytes) to avoid splitting a UTF-8 sequence in the log file. ### 6. Stretch goal: `GITEA_DEBUG_SCOPES` Implemented as listed in the issue: - `GITEA_DEBUG_SCOPES=tools,http,config` - Empty (default) = all scopes when debug is on - `flag.DebugScopeEnabled(scope)` is the single check used by every call site ## Why this shape A few design choices worth flagging: - **Tool middleware over per-handler wrappers.** mcp-go exposes `WithToolHandlerMiddleware`, which lets us instrument all 45 tools centrally. Wrapping each handler would have meant touching every `operation/*/*.go` file and would have made backports messier. - **Request ID via context, not headers.** The middleware sets `request_id` in `ctx.Value(...)`. For `pkg/gitea/rest.go` this propagates through `http.NewRequestWithContext`, so the RoundTripper sees it on `req.Context()`. SDK calls lose the linkage because the cached SDK client owns its own context, but that's an acceptable trade for keeping the SDK client cache (which avoids a `/api/v1/version` preflight per call). - **`TextResult` left intact.** Every operation module calls `to.TextResult(...)`. Changing its signature would have caused a churn-y diff and conflict with in-flight work. `TextResultCtx` is provided so new code can opt in to context-aware logging. - **Errors logged unconditionally.** Even when debug is off, `tool call: error` is now a structured `error`-level entry with tool name and request_id. The pre-existing bare `log.Errorf` in `to.ErrorResult` lost this context — the middleware restores it. ## Test coverage - `pkg/debug/debug_test.go` — argument redaction (nested maps, slices, non-sensitive keys preserved, input not mutated), query-string stripping, multi-byte-safe preview truncation, request-id uniqueness / format, context lookup. - `pkg/flag/flag_test.go` — `DebugScopeEnabled` semantics (off when debug off, "everything" when empty, allow-list when populated). - `pkg/middleware/logging_test.go` — context wiring (tool name + request_id reach the handler), error propagation from wrapped handler, token-source resolution order (ctx > flag > "none"). `go test ./...` is green; `go vet ./...` is clean. ## Out of scope - Full redaction (depends on #5 — placeholder marker left in `pkg/debug` and in code comments). - Server-side propagation of an X-Request-Id header into the client-facing response (depends on #9). - Switching every existing `to.TextResult` call site to `TextResultCtx`. Doable as a follow-up; the new variant is in place for it.

Klaus added 1 commit 2026-05-23 19:06:28 +00:00

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

check-and-test / check-and-test (pull_request) Has been cancelled

Details

316c2c4275

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>

check-and-test / check-and-test (pull_request) Has been cancelled

Details

This pull request can be merged automatically.

You are not authorized to merge this pull request.

View command line instructions

Checkout

From your project repository, check out a new branch and test the changes.

git fetch -u origin issue-13-structured-debug-logging:issue-13-structured-debug-logging

git checkout issue-13-structured-debug-logging

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: Klaus/gitea-mcp#14