Skip to content

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

Merged
adriannoes merged 14 commits into
devfrom
feat/373-request-log-middleware
Jul 14, 2026
Merged

feat(mcp): add HTTP request log middleware and hosted wiring (#373 stack 2/3)#376
adriannoes merged 14 commits into
devfrom
feat/373-request-log-middleware

Conversation

@adriannoes

@adriannoes adriannoes commented Jul 8, 2026

Copy link
Copy Markdown
Collaborator

Part of #373 (stack 2/3). Depends on #375.

Summary

  • Pure-ASGI RequestLogMiddleware: one JSON line per HTTP request, no body buffering (ordering + disconnect tests).
  • wire_hosted_observability: calls streamable_http_app() once, mounts middleware, stores request_id in scope["state"].
  • HTTP transport serves via manual uvicorn with access_log=False (structured lines replace text access logs).
  • Configures the stdout emitter only on the HTTP path (stdio stdout stays the JSON-RPC wire).

What lands

Structured HTTP request lines on the hosted profile. Tool-call lines arrive in stack 3/3 (#377).

Stack status

Test plan

  • uv run pytest packages/mcp/tests/observability/test_request_log_middleware.py packages/mcp/tests/observability/test_wiring.py -q
  • uv run pytest packages/mcp/tests/test_server.py -q
  • rg BaseHTTPMiddleware packages/mcp/src (only documented prohibition in AGENTS.md)

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.
@adriannoes
adriannoes force-pushed the feat/373-request-log-middleware branch from 4b0f34b to 323206e Compare July 9, 2026 18:43
@adriannoes

Copy link
Copy Markdown
Collaborator Author

Review follow-ups from #375 (Daniel)

This PR now also addresses the approve notes on #375:

  1. Level pin (e707d9e7): structured emitter always INFO; PIPEFY_MCP_LOG_LEVEL = FastMCP text only.
  2. feat(mcp): add tool-call middleware seam #378 unification (323206eb): tool_log_middlewareemit_structured_event / builders (no parallel logger).
  3. Framing: debugging + privacy allowlist (docs/AGENTS).

Also already on this branch from earlier review: stderr, HTTP-only configure, honor x-request-id / x-correlation-id.

Rebased onto latest #375 (includes #378 merge). Stack 3/3 (#377) will be adjusted so it does not add a second CallToolRequest tool logger on top of #378's middleware.

@adriannoes

Copy link
Copy Markdown
Collaborator Author

Cross-ref: #377 has been reshaped so it does not reintroduce a CallToolRequest tool logger on top of #378 — only CHANGELOG + correlation e2e remain there. Tool emission stays on this PR's emitter + tool_log_middleware unification.

Base automatically changed from feat/373-json-log-emitter to dev July 9, 2026 19:17
Keep stack-2 observability choices (stderr emitter, INFO pin, HTTP-only
configure) over the #375 stdout/run_server wiring; take #381's tool-error
envelope relocation into core.
@adriannoes
adriannoes marked this pull request as ready for review July 9, 2026 19:19
@adriannoes
adriannoes requested a review from Danielmoraisg July 9, 2026 19:19
@adriannoes

Copy link
Copy Markdown
Collaborator Author

Conflicts with dev resolved after #375 (and #381) landed:

Ready for review.

Keep stack-2 HTTP serve via _serve_streamable_http (uvicorn + request
log middleware); drop _assert_safe_http_bind in favor of
McpSettings._enforce_bind_safety from #396.
Comment thread packages/mcp/src/pipefy_mcp/observability/request_log_middleware.py
Comment thread packages/mcp/tests/observability/test_wiring.py
Comment thread packages/mcp/src/pipefy_mcp/observability/wiring.py
@adriannoes
adriannoes merged commit 08168be into dev Jul 14, 2026
3 checks passed
@adriannoes
adriannoes deleted the feat/373-request-log-middleware branch July 14, 2026 14:32
adriannoes added a commit that referenced this pull request Jul 14, 2026
Take #396 bind-safety settings/docs and keep stack-2 HTTP serve via
_serve_streamable_http; drop the duplicated serve helper from the merge.
@adriannoes

Copy link
Copy Markdown
Collaborator Author

Follow-ups from this review → landed in #377

Merged before these threads were addressed; they are handled on stack 3/3 (#377):

Thread Commit
Privacy allowlist: state that sub/client_id are included on http_request; asymmetry with tool_call 801800af
Drop unused _settings on wire_hosted_observability 7f4635b2
Integration test: identity via wired auth stack (not injected scope["user"]) c5f9d745

Also synced #377 onto dev after this merge + #396 (4680bae5).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants