feat(mcp): instrument the MCP feature with structured tracing #102

Merged

David merged 3 commits from feat/YT-43-mcp-structured-tracing into main

2026-07-05 21:47:05 +02:00

Claude-Run commented

2026-07-05 19:51:04 +02:00

Member

Give the MCP feature complete, appropriately-levelled observability. Every MCP boundary event now emits a structured tracing event, with tokens, secrets, authorization codes, session cookies, and issue/comment/article body content redacted.

Tool dispatch: every #[tool] method funnels through a new run_tool wrapper that opens a per-invocation tool span carrying the tool name and authenticated user, logs entry with a non-secret argument summary, and logs the outcome and elapsed time. Argument redaction lives in one auditable place (tools/log_args.rs) via a LogArgs impl per arg type (scalars and presence flags only, never body content), locked in by a redaction test. resolve_client logs per-user client resolution and failures.

HTTP layer: a trace_requests middleware logs each inbound request at INFO with method, path, status, latency, and a per-request request_id that the tool spans inherit for correlation; /healthz stays at DEBUG.

OAuth / Hub / session / DB: authorize/token/register/hub-callback milestones, Hub code exchange / identity / refresh, session create/validate, admin-gate denials, and SQLite operations emit happy-path INFO (hot-path reads at DEBUG) and failures at warn/error, always redacting token/secret/code values.

Defaults and format: yt mcp serve / yt mcp stdio default (verbose = 0) to info for the youtrack_mcp and tower_http targets so the service is observable out of the box; other subcommands keep warn; RUST_LOG and -v still override. LOG_FORMAT=json switches the subscriber to JSON output (documented in .env.example and docs/deployment.md). The generated systemd unit sets SyslogIdentifier=youtrack-mcp so journalctl -t youtrack-mcp groups the service's logs.

Invariant sweep of the zero-log files in the ticket's Background table (invariant: every MCP boundary event emits a structured, redacted tracing event):

server.rs: INSTRUMENTED (run_tool span per tool: name, user, arg summary, outcome, latency; resolve_client resolution + failures).
tools/* (issues, articles, agile, comments, projects, users, work_items): INSTRUMENTED at the boundary (every tool fn flows through run_tool; entry summary is redacted per LogArgs; REST failures log at warn with HTTP {status} from {url} and no token).
db/mod.rs: INSTRUMENTED (writes at INFO, hot-path reads at DEBUG; hashes and ciphertext are never logged; failures surface at the call sites via internal_error/resolve_client at warn/error).
web/oauth_as.rs: INSTRUMENTED (authorize/token/register/hub-callback happy-path INFO; every rejection via bad_request/oauth_json_error/redirect_error at warn).
web/oauth_hub.rs: INSTRUMENTED (exchange_code/fetch_identity/refresh_hub_token INFO; identity HTTP failure at warn; token values never logged).
web/session.rs: N/A (pure HMAC seal/verify with no I/O boundary; session lifecycle is logged at the call sites in oauth_as/admin that create and validate cookies).
web/it_oauth.rs: N/A (#[cfg(test)] integration test, no runtime boundary).
crypto.rs: N/A (pure in-memory AEAD/hash/PKCE/token primitives, no I/O; logging plaintext or keys here would itself be a leak).
config.rs: N/A (pure env/URL parsing; load failures surface via anyhow context to the serve_http caller).

#YT-43

Give the MCP feature complete, appropriately-levelled observability. Every MCP boundary event now emits a structured `tracing` event, with tokens, secrets, authorization codes, session cookies, and issue/comment/article body content redacted. Tool dispatch: every `#[tool]` method funnels through a new `run_tool` wrapper that opens a per-invocation `tool` span carrying the tool name and authenticated user, logs entry with a non-secret argument summary, and logs the outcome and elapsed time. Argument redaction lives in one auditable place (`tools/log_args.rs`) via a `LogArgs` impl per arg type (scalars and presence flags only, never body content), locked in by a redaction test. `resolve_client` logs per-user client resolution and failures. HTTP layer: a `trace_requests` middleware logs each inbound request at INFO with method, path, status, latency, and a per-request `request_id` that the tool spans inherit for correlation; `/healthz` stays at DEBUG. OAuth / Hub / session / DB: authorize/token/register/hub-callback milestones, Hub code exchange / identity / refresh, session create/validate, admin-gate denials, and SQLite operations emit happy-path INFO (hot-path reads at DEBUG) and failures at warn/error, always redacting token/secret/code values. Defaults and format: `yt mcp serve` / `yt mcp stdio` default (verbose = 0) to `info` for the `youtrack_mcp` and `tower_http` targets so the service is observable out of the box; other subcommands keep `warn`; `RUST_LOG` and `-v` still override. `LOG_FORMAT=json` switches the subscriber to JSON output (documented in `.env.example` and `docs/deployment.md`). The generated systemd unit sets `SyslogIdentifier=youtrack-mcp` so `journalctl -t youtrack-mcp` groups the service's logs. Invariant sweep of the zero-log files in the ticket's Background table (invariant: every MCP boundary event emits a structured, redacted tracing event): - server.rs: INSTRUMENTED (run_tool span per tool: name, user, arg summary, outcome, latency; resolve_client resolution + failures). - tools/* (issues, articles, agile, comments, projects, users, work_items): INSTRUMENTED at the boundary (every tool fn flows through run_tool; entry summary is redacted per LogArgs; REST failures log at warn with `HTTP {status} from {url}` and no token). - db/mod.rs: INSTRUMENTED (writes at INFO, hot-path reads at DEBUG; hashes and ciphertext are never logged; failures surface at the call sites via `internal_error`/resolve_client at warn/error). - web/oauth_as.rs: INSTRUMENTED (authorize/token/register/hub-callback happy-path INFO; every rejection via bad_request/oauth_json_error/redirect_error at warn). - web/oauth_hub.rs: INSTRUMENTED (exchange_code/fetch_identity/refresh_hub_token INFO; identity HTTP failure at warn; token values never logged). - web/session.rs: N/A (pure HMAC seal/verify with no I/O boundary; session lifecycle is logged at the call sites in oauth_as/admin that create and validate cookies). - web/it_oauth.rs: N/A (`#[cfg(test)]` integration test, no runtime boundary). - crypto.rs: N/A (pure in-memory AEAD/hash/PKCE/token primitives, no I/O; logging plaintext or keys here would itself be a leak). - config.rs: N/A (pure env/URL parsing; load failures surface via anyhow context to the `serve_http` caller). #YT-43

Claude-Run added 1 commit

2026-07-05 19:51:04 +02:00

feat(mcp): instrument the MCP feature with structured tracing

Check / fmt + clippy + build + tests (pull_request) Failing after 46s

Details

f8f73b4c76

Give the MCP feature complete, appropriately-levelled observability. Every MCP boundary event now emits a structured `tracing` event, with tokens, secrets, authorization codes, session cookies, and issue/comment/article body content redacted.

Tool dispatch: every `#[tool]` method funnels through a new `run_tool` wrapper that opens a per-invocation `tool` span carrying the tool name and authenticated user, logs entry with a non-secret argument summary, and logs the outcome and elapsed time. Argument redaction lives in one auditable place (`tools/log_args.rs`) via a `LogArgs` impl per arg type (scalars and presence flags only, never body content), locked in by a redaction test. `resolve_client` logs per-user client resolution and failures.

HTTP layer: a `trace_requests` middleware logs each inbound request at INFO with method, path, status, latency, and a per-request `request_id` that the tool spans inherit for correlation; `/healthz` stays at DEBUG.

OAuth / Hub / session / DB: authorize/token/register/hub-callback milestones, Hub code exchange / identity / refresh, session create/validate, admin-gate denials, and SQLite operations emit happy-path INFO (hot-path reads at DEBUG) and failures at warn/error, always redacting token/secret/code values.

Defaults and format: `yt mcp serve` / `yt mcp stdio` default (verbose = 0) to `info` for the `youtrack_mcp` and `tower_http` targets so the service is observable out of the box; other subcommands keep `warn`; `RUST_LOG` and `-v` still override. `LOG_FORMAT=json` switches the subscriber to JSON output (documented in `.env.example` and `docs/deployment.md`). The generated systemd unit sets `SyslogIdentifier=youtrack-mcp` so `journalctl -t youtrack-mcp` groups the service's logs.

Invariant sweep of the zero-log files in the ticket's Background table (invariant: every MCP boundary event emits a structured, redacted tracing event):

- server.rs: INSTRUMENTED (run_tool span per tool: name, user, arg summary, outcome, latency; resolve_client resolution + failures).
- tools/* (issues, articles, agile, comments, projects, users, work_items): INSTRUMENTED at the boundary (every tool fn flows through run_tool; entry summary is redacted per LogArgs; REST failures log at warn with `HTTP {status} from {url}` and no token).
- db/mod.rs: INSTRUMENTED (writes at INFO, hot-path reads at DEBUG; hashes and ciphertext are never logged; failures surface at the call sites via `internal_error`/resolve_client at warn/error).
- web/oauth_as.rs: INSTRUMENTED (authorize/token/register/hub-callback happy-path INFO; every rejection via bad_request/oauth_json_error/redirect_error at warn).
- web/oauth_hub.rs: INSTRUMENTED (exchange_code/fetch_identity/refresh_hub_token INFO; identity HTTP failure at warn; token values never logged).
- web/session.rs: N/A (pure HMAC seal/verify with no I/O boundary; session lifecycle is logged at the call sites in oauth_as/admin that create and validate cookies).
- web/it_oauth.rs: N/A (`#[cfg(test)]` integration test, no runtime boundary).
- crypto.rs: N/A (pure in-memory AEAD/hash/PKCE/token primitives, no I/O; logging plaintext or keys here would itself be a leak).
- config.rs: N/A (pure env/URL parsing; load failures surface via anyhow context to the `serve_http` caller).

#YT-43

David added 1 commit

2026-07-05 19:55:31 +02:00

Merge branch 'main' into feat/YT-43-mcp-structured-tracing

Check / fmt + clippy + build + tests (pull_request) Failing after 39s

Details

13bb2973cf

David scheduled this pull request to auto merge when all checks succeed

2026-07-05 19:55:38 +02:00

David added 1 commit

2026-07-05 21:46:23 +02:00

test(mcp): deflake the request-logging test with a global default subscriber

Check / fmt + clippy + build + tests (pull_request) Successful in 39s

Details

Create release / Create release from merged PR (pull_request) Has been skipped

Details

35a8af1c9f

The `requests_log_at_info_with_request_id_and_healthz_at_debug` test installed only a thread-local capturing subscriber. Because no global default subscriber existed, the shared `http_request` span and "handled request" event callsites (also hit by the it_oauth / admin / oauth_as tests that drive `build_router` under the no-op default) could register process-wide as `Interest::never`, short-circuiting this test's thread-local subscriber and making the assertion flaky in CI (reproduced ~1 in 7 runs locally).

Install a benign global default subscriber (info level, output discarded to sink) so those callsites always register with `Interest::sometimes` and interest is re-evaluated per event against the current thread's dispatcher. The per-request capture still flows through the thread-local subscriber. Validated 0 failures across 40 full-suite runs (was 5/30 before).

#YT-43

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>