feat(mcp): add tool-call structured logger (#373 stack 3/3) by adriannoes · Pull Request #377 · pipefy/ai-toolkit

adriannoes · 2026-07-08T13:25:21Z

Part of #373 (stack 3/3).

Summary

Lands the user-facing CHANGELOG entry for hosted structured logging (Structured request and tool logging #373).
Adds an in-process e2e that locks HTTP↔tool request_id correlation under stateful Streamable HTTP (D4), using #378's tool_log_middleware + the shared structured emitter from stacks 1–2.

Follow-ups from #376 review (Daniel)

Addressed here so the stack closes cleanly after #376 merged:

Privacy allowlist (801800af): document that http_request lines include caller sub/client_id by design; tool_call lines omit sub until a consumer needs it. Also dedupe the Hosted structured logging section.
Drop unused _settings (7f4635b2): wire_hosted_observability(app) only — the settings arg was never read.
Wired-app identity test (c5f9d745): drive wire_hosted_observability through FastMCP's real AuthenticationMiddleware and assert sub/client_id (including the UnauthenticatedUser 401 path), replacing the call-only wiring mocks.

What this PR deliberately does not do

Does not add a second CallToolRequest tool logger. After feat(mcp): add tool-call middleware seam #378 merged to dev, tool lines are emitted by tool_log_middleware (unified onto emit_structured_event in feat(mcp): add HTTP request log middleware and hosted wiring (#373 stack 2/3) #376). A parallel wrap would double-log.

Stack status

Rebased/synced onto dev after feat(mcp): add HTTP request log middleware and hosted wiring (#373 stack 2/3) #376 (+ feat(mcp): replace bind-host guard with auth-posture interlock #396 bind interlock).
Ready for review.

Test plan

uv run pytest packages/mcp/tests/observability/test_observability_end_to_end.py packages/mcp/tests/observability/test_wiring.py packages/mcp/tests/test_server.py -q
uv run ruff check packages/mcp && uv run ruff format --check packages/mcp

Introduce allowlisted JSON event builders and a dedicated stdout logger with propagate=False so hosted observability coexists with FastMCP's RichHandler. Add PIPEFY_MCP_LOG_LEVEL to McpSettings and wire it through run_server and FastMCP construction.

Extend the resource-server token mapping with an optional sub field so hosted HTTP request logs can emit caller subject alongside client_id without re-decoding the bearer.

normalize_log_level resolved names via getattr(logging, ...), which returns non-level module attributes (BASIC_FORMAT) and accepts aliases the settings Literal rejects (WARN, FATAL); an explicit map fails loudly on both. The observability package now re-exports its stdlib-only emitter surface per the package convention, and a suite-wide autouse fixture drops leftover stdout handlers so a test that configures the process-global logger cannot leak a closed-stream handler into later tests.

…he token PipefyAccessToken.sub is str | None, so a validly-signed token carrying a numeric sub raised ValidationError inside _to_access_token and verify_token turned it into a 401, a token dev accepted before the field existed. sub feeds request logging only; a malformed value must not gate authentication. RFC 7519 requires StringOrURI, so only non-compliant IdPs ever hit this.

Keep the stdlib-only JSON emitter package surface from this stack and the tool-call middleware composition root from #378; wire both into server.py.

Emit one structured JSON line per HTTP request from middleware that only inspects response.start, stores request_id in scope state, and reads caller identity from the auth context at emit time.

Wire RequestLogMiddleware through streamable_http_app once and replace FastMCP.run(streamable-http) with explicit uvicorn serve and access_log disabled so structured request lines replace text access logs.

configure_observability_logging ran before the transport branch, arming a stdout handler in the stdio process too, where stdout is the JSON-RPC wire. Nothing emits under stdio today, but the D10 guarantee was conventional rather than structural: one future emit call in shared code would corrupt the protocol. The call now lives in _serve_streamable_http, and the stdio test asserts configuration never happens there. Also imports AuthenticatedUser from its defining module (bearer_auth) and extends the middleware tests: bearer absent from output with an Authorization header planted, UnauthenticatedUser yields null identity, the ordering test fails fast instead of hanging, and a send that raises mid-stream still emits exactly one line.

Route the hosted observability handler to stderr so structured lines never share the stdio JSON-RPC stdout channel. Collectors already capture both streams; HTTP-only configure remains the gate that keeps local installs clean.

Prefer an upstream request or correlation id when present so hosted request logs stay correlated across service boundaries; mint a UUID only when both headers are absent or blank.

PIPEFY_MCP_LOG_LEVEL now governs only the FastMCP root logger. The hosted structured emitter stays at INFO so quieting noisy text logs cannot silently drop request/tool debugging lines. Docs frame these events as debugging with a privacy allowlist, not an audit trail.

Reuse build_tool_call_event/emit_structured_event so #378 tool lines share the pinned stderr JSON channel and allowlisted shape (including cancelled and elicitation outcomes) instead of a parallel logger.info path.

Stack 3/3 no longer adds a second CallToolRequest tool logger: #378's tool_log_middleware already emits through the shared structured emitter. Keep the correlation e2e (adapted to stderr + middleware) and the user-facing changelog entry for #373.

adriannoes · 2026-07-09T18:44:55Z

Stack 3/3 reshaped after #378 landed in `dev`

#378 already provides the tool-call middleware seam + tool_log_middleware. Duplicating that with a second CallToolRequest wrap (tool_call_logger.py) would emit two tool_call lines per invocation.

This PR is now slimmed on top of #376:

No tool_call_logger / install_call_tool_logger — tool lines come from #378 middleware → shared structured emitter (wired on feat(mcp): add HTTP request log middleware and hosted wiring (#373 stack 2/3) #376).
Keeps the correlation e2e (test_observability_end_to_end.py), adapted to stderr + tool_log_middleware.
Keeps the user-facing CHANGELOG entry for Structured request and tool logging #373 (stderr, level pin, debugging framing).

Cross-refs: #375 (emitter) → #376 (HTTP middleware + pin + unify) → this PR (docs + e2e lock).

Take #396 bind-safety settings/docs and keep stack-2 HTTP serve via _serve_streamable_http; drop the duplicated serve helper from the merge.

http_request lines include sub and client_id by design; tool_call lines omit sub until a consumer needs it. Deduplicate the Hosted structured logging section left by the stack merge.

The parameter was threaded through call sites and tests but never read. Settings-driven toggles can return when there is a real consumer.

Drive wire_hosted_observability with FastMCP's AuthenticationMiddleware so sub/client_id are asserted from a real scope["user"] (including the UnauthenticatedUser 401 path), not from an injected unit-test scope.

adriannoes · 2026-07-14T14:44:54Z

Follow-ups from #376 review

These commits address Daniel's open review threads on #376 (merged before they were handled):

Feedback (#376)	Commit
Privacy allowlist: state that `http_request` includes caller `sub`/`client_id`; document asymmetry with `tool_call`	`801800af`
Drop unused `_settings` on `wire_hosted_observability`	`7f4635b2`
Integration test: identity via the wired auth stack (not injected `scope["user"]`)	`c5f9d745`

Threads on #376 are replied to and resolved, with links back here. Original stack scope (CHANGELOG + correlation e2e) is unchanged above these.

c/c: @Danielmoraisg

Swap em dashes for commas/parens in shipped docstrings and the hosted-logging changelog entry per #377 review.

This was referenced Jul 8, 2026

feat(mcp): add HTTP request log middleware and hosted wiring (#373 stack 2/3) #376

Merged

Structured request and tool logging #373

Open

adriannoes self-assigned this Jul 8, 2026

adriannoes added 4 commits July 8, 2026 11:33

feat(mcp): preserve JWT sub claim in PipefyAccessToken

9d0f061

Extend the resource-server token mapping with an optional sub field so hosted HTTP request logs can emit caller subject alongside client_id without re-decoding the bearer.

adriannoes force-pushed the feat/373-tool-call-logger branch from f5c9236 to 43c1c93 Compare July 8, 2026 14:34

adriannoes force-pushed the feat/373-request-log-middleware branch from a843c1c to f9bca74 Compare July 8, 2026 14:34

This was referenced Jul 8, 2026

feat(mcp): add JSON structured logging emitter and JWT sub claim (#373 stack 1/3) #375

Merged

Tool-call middleware seam #374

Closed

adriannoes added 8 commits July 9, 2026 15:21

merge(dev): resolve conflicts with tool-call middleware (#378)

cb9e505

Keep the stdlib-only JSON emitter package surface from this stack and the tool-call middleware composition root from #378; wire both into server.py.

feat(mcp): add pure-ASGI HTTP request log middleware

a03af02

Emit one structured JSON line per HTTP request from middleware that only inspects response.start, stores request_id in scope state, and reads caller identity from the auth context at emit time.

feat(mcp): serve HTTP with request logging via manual uvicorn

8f5e57f

Wire RequestLogMiddleware through streamable_http_app once and replace FastMCP.run(streamable-http) with explicit uvicorn serve and access_log disabled so structured request lines replace text access logs.

fix(mcp): emit structured JSON logs on stderr

ed0eec8

Route the hosted observability handler to stderr so structured lines never share the stdio JSON-RPC stdout channel. Collectors already capture both streams; HTTP-only configure remains the gate that keeps local installs clean.

feat(mcp): honor inbound x-request-id and x-correlation-id

52bb9a8

Prefer an upstream request or correlation id when present so hosted request logs stay correlated across service boundaries; mint a UUID only when both headers are absent or blank.

refactor(mcp): route tool_log_middleware through the structured emitter

323206e

Reuse build_tool_call_event/emit_structured_event so #378 tool lines share the pinned stderr JSON channel and allowlisted shape (including cancelled and elicitation outcomes) instead of a parallel logger.info path.

adriannoes force-pushed the feat/373-request-log-middleware branch from 4b0f34b to 323206e Compare July 9, 2026 18:43

adriannoes force-pushed the feat/373-tool-call-logger branch from 43c1c93 to 5b0a506 Compare July 9, 2026 18:44

adriannoes marked this pull request as ready for review July 13, 2026 11:34

Base automatically changed from feat/373-request-log-middleware to dev July 14, 2026 14:32

adriannoes added 5 commits July 14, 2026 11:41

merge(dev): sync stack 3/3 after #376 and #396

4680bae

Take #396 bind-safety settings/docs and keep stack-2 HTTP serve via _serve_streamable_http; drop the duplicated serve helper from the merge.

docs(mcp): state caller identity in the privacy allowlist

801800a

http_request lines include sub and client_id by design; tool_call lines omit sub until a consumer needs it. Deduplicate the Hosted structured logging section left by the stack merge.

refactor(mcp): drop unused settings from wire_hosted_observability

7f4635b

The parameter was threaded through call sites and tests but never read. Settings-driven toggles can return when there is a real consumer.

test(mcp): lock request-log identity through the wired auth stack

c5f9d74

Drive wire_hosted_observability with FastMCP's AuthenticationMiddleware so sub/client_id are asserted from a real scope["user"] (including the UnauthenticatedUser 401 path), not from an injected unit-test scope.

style(mcp): sort imports in observability e2e test

d21e6e3

Danielmoraisg previously approved these changes Jul 14, 2026

View reviewed changes

Comment thread packages/mcp/tests/observability/test_wiring.py Outdated

Comment thread packages/mcp/tests/observability/test_observability_end_to_end.py Outdated

Comment thread CHANGELOG.md Outdated

style(mcp): replace em dashes in review nits

84bfe0d

Swap em dashes for commas/parens in shipped docstrings and the hosted-logging changelog entry per #377 review.

adriannoes dismissed Danielmoraisg’s stale review via 84bfe0d July 14, 2026 18:48

adriannoes requested a review from Danielmoraisg July 14, 2026 19:08

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

feat(mcp): add tool-call structured logger (#373 stack 3/3)#377

feat(mcp): add tool-call structured logger (#373 stack 3/3)#377
adriannoes wants to merge 19 commits into
devfrom
feat/373-tool-call-logger

adriannoes commented Jul 8, 2026 •

edited

Loading

Uh oh!

adriannoes commented Jul 9, 2026

Uh oh!

adriannoes commented Jul 14, 2026 •

edited

Loading

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Uh oh!

Conversation

adriannoes commented Jul 8, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary

Follow-ups from #376 review (Daniel)

What this PR deliberately does not do

Stack status

Test plan

Uh oh!

adriannoes commented Jul 9, 2026

Stack 3/3 reshaped after #378 landed in dev

Uh oh!

adriannoes commented Jul 14, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Follow-ups from #376 review

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

adriannoes commented Jul 8, 2026 •

edited

Loading

Stack 3/3 reshaped after #378 landed in `dev`

adriannoes commented Jul 14, 2026 •

edited

Loading