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

[adriannoes]

Part of #373 (stack 1/3).

Summary

• Introduces allowlisted JSON event builders and a dedicated stdout logger (propagate=False) for hosted observability.
• Adds PIPEFY_MCP_LOG_LEVEL to McpSettings and wires it through FastMCP(log_level=...).
• Extends PipefyAccessToken with optional sub from JWT claims for caller subject in request logs (D16).
• Hardens log level normalization (explicit map) and degrades non-string sub to null instead of rejecting the token.

What does not land yet

No structured lines are emitted until stack 2/3 (#376) and 3/3 (#377) merge. This PR only lays the emitter and identity groundwork.

Stack status

• Rebased onto dev after refactor: reshape the Pipefy client into an engine/session split #348 merged (8adea173).
• Ready for review — stacks 2/3 and 3/3 remain draft until this lands.
• User-visible changelog entry lands in feat(mcp): add tool-call structured logger (#373 stack 3/3) #377.

Test plan

• uv run pytest packages/mcp/tests/observability/test_json_logging.py -q
• uv run pytest packages/mcp/tests/auth/test_resource_server.py -q
• uv run ruff check packages/mcp && uv run ruff format --check packages/mcp

[Danielmoraisg]

On the structured logging design (stack-level, non-blocking)

A few suggestions on the observability shape before 2/3 and 3/3 wire emission on top. These are about the logging design, not this diff specifically, and none of them block merging 1/3.

1. Route structured logs to stderr, not stdout. Under the stdio transport stdout is the JSON-RPC channel, so a structured line written there corrupts the protocol. configure_observability_logging currently runs unconditionally in run_server, before the transport branch, so on stdout it needs gating to HTTP only. Log collectors capture stdout and stderr equally, so moving structured output to stderr removes the hazard without losing anything.

2. Prefer one uniform structured stream over two bespoke events. Today two event types are emitted as JSON while every other log stays human-formatted text (for example the "Inbound bearer rejected" warning in resource_server.py). In a log backend those text lines are unparseable and fall out of structured queries. Attaching a JSON formatter to the app loggers makes every log structured, so the two events become well-known shapes inside one consistent stream rather than the only structured output.

3. Carry request context ambiently rather than per event. A context variable populated once per request (request id plus whatever identity and resource ids apply), merged into every line by the formatter, lets any log within a request correlate back to it, including errors raised deep in a handler. Threading fields through the two builder functions only covers those two call sites.

4. Source the request id from the inbound header. When the caller or an upstream proxy already sends x-request-id or x-correlation-id, honor it and generate an id only when it is absent. That keeps a request correlated across service boundaries instead of minting an id that stops here.

5. Add trace context if these logs feed a tracing backend. Injecting trace_id and span_id into each line lets logs join distributed traces. Without it the request id correlates logs to each other but not to spans.

6. Split the level knob from the format knob. One setting that governs both text verbosity and structured output means raising it to WARNING silently drops all structured events, including tool-call errors, since every event is emitted at INFO. A separate level (how much) and format (json or text) lets you quiet text logs without losing structured error events.

Points 1, 2, and 5 get harder to change once emission is wired, so they are worth settling here.

[adriannoes]

Thanks for the stack-level feedback, @Danielmoraisg , agreeing this is about the observability shape before 2/3 and 3/3 wire emission, not a blocker for the emitter/identity groundwork in this PR.

1. stderr + HTTP-only gate — accepted

Addressed on stack 2/3 (#376):

• Structured emitter already configures only on the HTTP serve path (f9bca745), so stdio never arms the process-global handler.
• Follow-up on feat(mcp): add HTTP request log middleware and hosted wiring (#373 stack 2/3) #376 routes the handler to stderr (8037c0e1) so structured lines never share the stdio JSON-RPC stdout channel. Collectors capture both streams equally.

2. Uniform structured stream vs allowlisted events — keeping current design

The two allowlisted event shapes (http_request / tool_call) are intentional for the hosted audit trail: fixed fields, no arg values, no exception messages, no query strings. Attaching a JSON formatter to every app logger would pull free-form text (e.g. auth warnings) into the structured pipeline and weaken that privacy boundary.

We are keeping bespoke allowlisted events for #373. If we later need every app log line to be queryable as JSON, that should be a separate follow-up (formatter on app loggers), not mixed into this audit-trail contract.

3. Ambient request context via contextvars — declining for correlation

Under stateful Streamable HTTP, the session task freezes contextvars at initialize. A ContextVar set in middleware on a later HTTP request would mis-correlate tool work running on that session task (silently). Stacks 2/3 correlate via scope["state"]["request_id"] + request_ctx (the current message's ASGI scope) instead. Happy to revisit if the FastMCP session model changes.

4. Honor inbound x-request-id / x-correlation-id — accepted

This PR still has no request-id generation (emitter only). Implemented on #376 (4b0f34bb): prefer x-request-id, then x-correlation-id, mint a UUID only when both are absent or blank.

5. trace_id / span_id — deferring, with a question

Out of scope for #373 today (no tracing backend in this path). Before we add fields: which backend do you have in mind (OpenTelemetry already on the hosted path, or schema prep only)? If there is a concrete consumer, we can add trace_id/span_id in a follow-up once that wiring exists — otherwise empty fields would just pollute the allowlist.

6. Split level vs format knobs — documenting constraint; follow-up later

Agreed that one knob means WARNING+ drops INFO structured events. For this stack we keep a single PIPEFY_MCP_LOG_LEVEL and will document that hosted deployments must run at INFO (planned with the docs pass on stack 3/3, #377). Splitting level vs format (or pinning the observability logger independently of the FastMCP root) stays a follow-up; not expanding this PR.

[adriannoes]

Ask: @Danielmoraisg , since you noted none of these block merging 1/3, and points 1 + 4 are already on #376, could you re-review / approve this PR so we can land the emitter groundwork and keep 2/3 and 3/3 moving?

[adriannoes]

Rebased/merged latest dev (includes #378 tool-call middleware) and resolved the conflicts:

• observability/__init__.py: keep the stdlib-only emitter re-exports (middleware stays a submodule import).
• server.py: keep both configure_observability_logging / log_level from this PR and the tool-call middleware composition root from feat(mcp): add tool-call middleware seam #378.

@Danielmoraisg could you re-review when you have a moment? Thanks again for the earlier approval.

[Danielmoraisg]

Approving, though I disagree with the reframing of logs as audit trail as we generally use it for debugging It is good to be mindfull of privacy.

Regarding the point 6: Documenting "run at INFO" isn't enough, and it sits uneasily with the point 2 framing. If these events are a hosted audit trail, a single knob that silently drops the whole trail at WARNING+ is a real gap, not a doc footnote. Raising log verbosity to quiet noisy text logs is a normal operator action, and here it disables the audit trail with no signal that it happened.

[adriannoes]

@Danielmoraisg following up on your approve notes (framing + point 6) — and holding the merge of this PR until you've had a chance to react.

Point 6 + framing — addressed on #376 (not only docs)

Agreed that documenting "run at INFO" was not enough. On stack 2/3 (#376):

• e707d9e7 — PIPEFY_MCP_LOG_LEVEL now governs only the FastMCP root logger (text). The dedicated structured logger is pinned at INFO, so raising the knob to quiet noisy text cannot silently drop request/tool lines.
• 323206eb — #378's tool_log_middleware now emits through the same build_tool_call_event / emit_structured_event path (same pinned channel + allowlist), instead of a parallel logger.info that would still have been muted by root level.
• Docs/AGENTS framing updated: these are hosted debugging logs with a privacy allowlist — not an audit trail. Privacy still matters; the primary use is debugging.

PR: #376

Point 5 (trace_id / span_id) — question before we touch the allowlist

We are not adding trace_id/span_id yet. With no tracing backend (and no inbound trace headers consumed today), nullable fields would just pollute the allowlist; minting local IDs that don't join real spans would be worse.

Before we do anything here: does the hosted ingress already send W3C traceparent (or Datadog trace headers), and is there a concrete backend that should join these log lines to spans? If yes, we can do passive header propagation into scope["state"] + the builders on #376. If not, we'll keep request_id only and revisit when APM/OTel lands.

Holding merge of #375 until you've weighed in on the above (especially point 5). Thanks again for the push on point 6.