feat(mcp): add observability to MCP service#41921
Conversation
… error hook The MCP service emitted zero StatsD metrics and its middleware swallowed every exception before any error tracker could see them. This adds per-tool success/error counters and timing in LoggingMiddleware and GlobalErrorHandlerMiddleware (mirroring the @statsd_metrics pattern in base_api.py), fixes has_app_context() silently dropping DB audit rows by wrapping event_logger calls in the existing app-context manager, adds a vendor-neutral MCP_ERROR_HOOK config for wiring an external error tracker, surfaces the previously-discarded error_type from structured error responses, and adds server-side logging at several ops-invisible error return sites.
Codecov Report❌ Patch coverage is Additional details and impacted files@@ Coverage Diff @@
## master #41921 +/- ##
==========================================
- Coverage 65.19% 65.14% -0.05%
==========================================
Files 2790 2790
Lines 156809 156890 +81
Branches 35808 35811 +3
==========================================
- Hits 102229 102207 -22
- Misses 52621 52725 +104
+ Partials 1959 1958 -1
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
dosubot
Bot
added
change:backend
Code Review Agent Run #fce5d0Actionable Suggestions - 0Review Details
Bito Usage GuideCommands Type the following command in the pull request comment and save the comment.
Refer to the documentation for additional commands. Configuration This repository uses Documentation & Help AI Code Review powered by |
rebenitez1802
left a comment
rebenitez1802
left a comment
There was a problem hiding this comment.
Request changes: solid, well-tested observability work — the audit-row fix, MCP_ERROR_HOOK design (no double-hook, failures swallowed), and the error_id/error_type changes are all correct. But the metrics it adds are double-counted and misclassified, which undermines the feature's own purpose, and one metric key is built from unbounded client input. Details below.
🟡 Medium — Error counters double-counted and misclassified across the two middlewares
GlobalErrorHandlerMiddleware._handle_error (middleware.py:688) increments mcp.tool.{tool}.{warning|error} then re-raises ToolError; that exception propagates to the outer LoggingMiddleware.on_call_tool, whose finally (middleware.py:417) increments mcp.tool.{tool}.error again. So a raised system error counts .error twice, and a raised user error hits both .warning (GEH) and .error (Logging) — polluting the very success/warning/error split the PR says it mirrors from base_api.py. A tool that returns a structured error (no raise) is counted once by Logging only — a third inconsistent path. In the tool-search-proxy case the two also key differently (call_tool in GEH vs the resolved name in Logging). Fix: emit the per-tool outcome from exactly one place — e.g. drop the incr from _handle_error and move the _is_user_error classification into LoggingMiddleware so it can emit .success/.warning/.error itself. (Dormant under the default no-op DummyStatsLogger, but active in exactly the StatsD deployments this targets.)
🟡 Medium — Unbounded / injectable StatsD metric key via the call_tool proxy name
In on_call_tool, metric_tool = mcp_tool or tool_name (middleware.py:416), where mcp_tool = _resolve_tool_name(...) returns params["name"] from the call_tool search proxy verbatim, with no check against the registered tool set (middleware.py:324-331). It flows unsanitized into incr(f"mcp.tool.{metric_tool}.error") / timing(...), and the finally emits it even when the proxied tool name is bogus. With a real StatsdStatsLogger (keys passed straight to pystatsd, stats_logger.py:96-103) any authenticated client can (a) create unbounded metric series and (b) inject forged StatsD lines if name contains \n/:/|. base_api.py avoids this by keying on code-derived class/method names. Not an RBAC-matrix violation per SECURITY.md (operator-owned metrics infra) — a robustness bug, not a CVE. Fix: validate metric_tool against the registered tools and fall back to a constant ("call_tool"/"unknown") otherwise; keep the raw name only in the (non-StatsD) curated payload.
🟡 Medium — Test gap lets the double-count ship undetected
Every new stats test exercises one middleware in isolation and asserts incr.assert_called_once_with(...) (test_middleware.py:1363, test_middleware_logging.py:702), so each passes even though both middlewares fire in the wired chain. The one real-chain test (TestMiddlewareChainOrder) never patches stats_logger_manager. Fix: add a chain-level test that drives a raising tool through build_middleware_list(), patches stats_logger_manager, and asserts the exact set of incr calls for one failed call — that pins whether the double-emission is intended.
🟢 Low — event_logger.log in the finally isn't wrapped in try/except
on_call_tool (middleware.py:384-393) and on_message (433-450) call event_logger.log unguarded — unlike sibling _handle_error (670-684) and ResponseSizeGuardMiddleware. The default DBEventLogger swallows SQLAlchemyError, but a custom EVENT_LOGGER that raises (or a failure entering the app context) would mask the tool's real exception on the error path and skip the incr/timing that follow it. Fix: wrap the log call in try/except like _handle_error does (or emit the metrics before the log).
🟢 Low — Hook-context contract is documented inaccurately
PRODUCTION.md and the mcp_config.py comment say context includes tool_name, mcp_call_id, user_id, error_type, sanitized_message, duration_ms "already sanitized." But the last-resort site in StructuredContentStripperMiddleware.on_call_tool (middleware.py:540-547) passes only tool_name, mcp_call_id, error_type, and the hook's first arg is the raw exception (only sanitized_message is scrubbed). A hook indexing context['user_id'] would fail on that path (swallowed, so the report is silently lost). Fix: either populate the missing keys (even as None) at the last-resort site, or document that only tool_name/mcp_call_id/error_type are guaranteed and that the raw exception may contain sensitive data.
🟢 Low — New OAuth logger.info in get_chart_data sits on a rarely-reached branch
The added logger.info("...OAuth authentication required...") (get_chart_data.py:916) is in the outer except OAuth2RedirectError, but query-time OAuth errors from command.run() are caught first by the inner except (..., SupersetException, ...) (~:896, since OAuth2RedirectError subclasses SupersetException) and returned as a generic DataError. The routing is pre-existing — just be aware this new log (and the OAuth redirect response) rarely fires. query_dataset.py orders its handlers correctly.
🟢 Low — Doc nits in the Sentry example
PRODUCTION.md uses the deprecated sentry_sdk.push_scope() (removed-path in sentry-sdk 2.x) → new_scope() (inline suggestion below). Also add a note — as the sibling MCP_CHART_PLUGIN_ENABLED_FUNC comment does — that MCP_ERROR_HOOK runs synchronously on the asyncio event loop, so a blocking hook stalls tool handling; offload network I/O to a background transport (the Sentry SDK already does).
Confirmed correct and not issues: the has_app_context() → _get_app_context_manager() change is the intended audit-row fix (returns nullcontext() under a request context, no g.user races); the MCP_ERROR_HOOK typing/imports are valid; and the hook is not double-invoked (the isinstance(e, ToolError) guard prevents it).
Reviewed with a multi-agent pass (adversarial verification of the two metric findings + sweeps over the diff, tests, and docs).
| sanitized_message, and duration_ms — already sanitized by the MCP | ||
| service before this hook runs. | ||
| """ | ||
| with sentry_sdk.push_scope() as scope: |
There was a problem hiding this comment.
Deprecated in sentry-sdk 2.x — push_scope() is on the removal path. Use new_scope() (same body):
| with sentry_sdk.push_scope() as scope: | |
| with sentry_sdk.new_scope() as scope: |
There was a problem hiding this comment.
Applied in 46c2332 — switched to sentry_sdk.new_scope().
…tric keys Per-tool outcome counters are emitted from exactly one place (LoggingMiddleware), classified user/system via the ToolError __cause__ unwrap, so raised errors are no longer double-counted between the two middlewares. Metric keys are validated against the FastMCP tool registry so client-controlled tool names cannot mint unbounded StatsD series or inject metadata characters. Also: event-logger calls in the logging middleware are guarded so a failing logger cannot mask the tool's real exception; the last-resort error-hook site populates the full context-key contract; docs switch to sentry_sdk.new_scope() and document the hook's synchronous execution and raw-exception caveat; OAuth errors in get_chart_data re-raise past the generic inner handler so the dedicated OAuth branches are reachable. Chain-level tests pin the exact set of stats calls through build_middleware_list().
|
Thanks for the thorough review — all findings addressed in 46c2332. Double-counted / misclassified error counters — took the suggested fix: the per-tool outcome counter is now emitted from exactly one place, Unbounded / injectable metric key — added Chain-level test gap — added Unguarded Hook-context contract — the last-resort site in OAuth branch reachability in Doc nits — Full MCP unit suite passes locally (3103 tests; the one failure, |
✅ Deploy Preview for superset-docs-preview ready!
To edit notification comments on pull requests, go to your Netlify project configuration. |
![codeant-ai-for-open-source[bot]](https://avatars.githubusercontent.com/u/151810221?s=60&v=4){kind=small}
| await self._emit_call_metrics( | ||
| context, | ||
| tool_name, | ||
| mcp_tool, | ||
| success=success, | ||
| raised_is_user_error=raised_is_user_error, | ||
| duration_ms=duration_ms, | ||
| ) |
There was a problem hiding this comment.
Suggestion: The metrics emission is awaited directly inside the finally block without protection, so any runtime failure in stats logging (for example, backend outage or client error) will raise a new exception and can mask the original tool result/exception. Wrap this call in its own try/except and swallow/log metric failures so observability side effects never alter MCP tool behavior. [possible bug]
Severity Level: Major ⚠️
- ❌ MCP tool calls can fail when stats logger misbehaves.
- ⚠️ Original ToolError replaced by metrics RuntimeError in finally.
- ⚠️ Downstream MCP clients see spurious failures unrelated to tools.Steps of Reproduction ✅
1. In `superset/mcp_service/middleware.py:409-517`, inspect
`LoggingMiddleware.on_call_tool`; its `finally` block ends with an awaited call to
`_emit_call_metrics` at lines 509-516.
2. In a test, import `LoggingMiddleware` from `superset/mcp_service/middleware.py` and
construct a middleware instance plus a minimal `MiddlewareContext` and `call_next` that
returns a successful `ToolResult`.
3. Monkeypatch `stats_logger_manager.instance.incr` or `timing` (called inside
`_emit_call_metrics` at lines 398-405) to raise `RuntimeError("metrics backend down")`,
simulating a failing metrics backend or misconfigured client.
4. Await `LoggingMiddleware.on_call_tool(context, call_next)`; `call_next` returns
successfully, but when the `finally` block executes, the awaited `_emit_call_metrics` call
raises `RuntimeError`, causing `on_call_tool` to propagate this new exception instead of
returning the `ToolResult` (or instead of preserving any original exception),
demonstrating that metrics failures can alter or mask the real tool outcome.
(Use Cmd/Ctrl + Click for best experience)
Prompt for AI Agent 🤖
This is a comment left during a code review.
**Path:** superset/mcp_service/middleware.py
**Line:** 509:516
**Comment:**
*Possible Bug: The metrics emission is awaited directly inside the `finally` block without protection, so any runtime failure in stats logging (for example, backend outage or client error) will raise a new exception and can mask the original tool result/exception. Wrap this call in its own `try/except` and swallow/log metric failures so observability side effects never alter MCP tool behavior.
Validate the correctness of the flagged issue. If correct, How can I resolve this? If you propose a fix, implement it and please make it concise.
Once fix is implemented, also check other comments on the same PR, and ask user if the user wants to fix the rest of the comments as well. if said yes, then fetch all the comments validate the correctness and implement a minimal fixThere was a problem hiding this comment.
Valid catch — fixed in 664b5c7. The await self._emit_call_metrics(...) in the finally is now wrapped in its own try/except that logs a warning and swallows the failure, matching the guard already applied to the event_logger.log call above it. Added two regression tests: a stats client raising RuntimeError neither turns a successful call into an error (result still returned) nor replaces the tool's original exception (the original ValueError still propagates, not the metrics RuntimeError).
Code Review Agent Run #a1e59bActionable Suggestions - 0Additional Suggestions - 1
Review Details
Bito Usage GuideCommands Type the following command in the pull request comment and save the comment.
Refer to the documentation for additional commands. Configuration This repository uses Documentation & Help AI Code Review powered by |
The metrics emission in LoggingMiddleware's finally block is wrapped in try/except so a failing stats backend can never mask the tool's real result or exception — matching the guard already applied to the event-logger call. Adds tests that a raising stats client neither turns a successful call into an error nor replaces the original exception, and OAuth routing tests for get_chart_data verifying query-time OAuth2RedirectError/OAuth2Error reach the dedicated handlers instead of being swallowed into a generic DataError.
|
Addressed the two remaining automated-review items in 664b5c7: Unprotected metrics emission in the Missing OAuth test coverage for the Also merged the latest master into the branch (includes #41923's dead-middleware removal — no conflicts with this PR's changes). Full MCP unit suite: 3125 passed locally. |
rebenitez1802
left a comment
rebenitez1802
left a comment
There was a problem hiding this comment.
Follow-up (round 2) — re-reviewed at 00a4944 after 664b5c7 (fix: guard metrics emission in finally; add OAuth routing tests).
All blocking items from my earlier review are verified fixed — thanks for the fast turnaround. I re-ran an adversarial pass over each fix and they hold up:
- Metric double-count → single emission point
LoggingMiddleware._emit_call_metricswith a real success/warning/error split (raised user→warning, raised system→error);_handle_errorno longer emits. The chain-level test proves exactly-one counter per call. ✅ - Injectable/unbounded metric key →
_resolve_metric_tool_namevalidates against the FastMCP registry and falls back tocall_tool/unknown; the regex path isn't reachable on a real tool call (fastmcp_contextis always set) and its charset blocks StatsD metadata chars anyway. ✅ - Unguarded
event_logger.log/ metrics → both wrapped in try/except; the in-flight tool exception still propagates. ✅ - Hook-context contract,
push_scope→new_scope, sync-hook warning → all applied. ✅ - Also confirmed: the
__cause__unwrap is correct, and_mcp_call_id_varis safe (MCP dispatches each message in its own task, so no stale-id leak).
One Medium remains, plus a few Lows.
🟡 Medium — OAuth redirect still swallowed on the unsaved-chart (form_data_key) path
The OAuth-routing fix was applied to the saved-chart path (the except (OAuth2RedirectError, OAuth2Error): raise at get_chart_data.py:896, ahead of the generic handler — correct, and covered by the new TestOAuthErrorRouting). But the sibling _query_from_form_data (reached via the form_data_key/no-identifier branch at :381) runs its own command.run() and its only handler is except (CommandException, SupersetException, ValueError) at :1100, with no OAuth re-raise. Since OAuth2RedirectError/OAuth2Error subclass SupersetException, an OAuth error on this path is returned as a generic error_type="DataError" and never reaches the outer OAuth handlers (:917/:930) — so an LLM client querying an unsaved chart against a DB that needs re-auth gets a generic error instead of the OAUTH2_REDIRECT it needs. The new tests only exercise the saved path, so they give false confidence that "query-time OAuth errors reach the dedicated handlers." Line 381 is inside the outer try (:330), so mirroring the saved-path re-raise before :1100 is sufficient (both names are already imported at :36):
except (OAuth2RedirectError, OAuth2Error):
# OAuth errors subclass SupersetException; re-raise so the caller's
# outer OAuth handlers return the redirect instead of a generic DataError.
raise
except (CommandException, SupersetException, ValueError) as e:
...Worth folding in before merge, with a regression test through the form_data_key path.
🟢 Low — Last-resort handler can itself raise via str(exc)
StructuredContentStripperMiddleware.on_call_tool's final except — the documented "true last-resort capture point" that must never propagate — builds its message with _sanitize_error_for_logging(e) and f"Error: {e}" (both call str(e)) unguarded. A pathological __str__/__repr__ would make this handler raise past the middleware chain, the exact "encoding without a string argument" failure it exists to prevent. Rare (needs a hostile __str__), hence Low. Fix: wrap the format/sanitize in a try/except falling back to type(e).__name__.
🟢 Low — Structured error responses all bucket into .error (design note)
Tools that return a ChartError-style schema (not_found, NoData, EmptyQuery, bad params…) hit raised_is_user_error is None → .error. Since that's the primary error channel for these tools, expected/user-caused outcomes inflate mcp.tool.*.error, which makes it hard to use for system-error alerting; .warning only ever gets raised user-class exceptions. The code comment calls this an intentional tradeoff — flagging so it's a conscious one. The parsed error_type is already available, so mapping a curated set of user-class types to .warning (or a separate .structured_error counter) would make .error mean "system failure."
🟢 Low — Test gaps
The metrics/event-logger guard tests assert the exception isn't masked but never assert the swallowed error is logged (logger.warning("Failed to emit MCP tool metrics…")), so a silent-swallow regression would pass. There's also no chain-level assertion for the structured-error .error bucket, and the hostile-name rejection is only exercised via the non-awaitable-MagicMock regex branch rather than a reachable registry returning None. All minor.
🟢 Low — Doc nits
The PRODUCTION.md Sentry example forwards the raw exception (capture_exception(error)) with no before_send scrubber — i.e. it doesn't practice the "raw exception may contain connection strings/tokens" caveat the docstring just added. And the hook-context docs single out user_id/duration_ms as possibly None, but mcp_call_id (and tool_name→"unknown") can also be None for a system error on a non-tool message.
Re-reviewed with a multi-agent adversarial pass over the fixes + a fresh sweep of the reworked code, tests, and docs.
rebenitez1802
left a comment
rebenitez1802
left a comment
There was a problem hiding this comment.
Approving — the blocking items from my first review (metric double-count, injectable metric key, unguarded finally) are all verified fixed.
Non-blocking follow-ups: the OAuth redirect on the unsaved-chart (form_data_key) path is still swallowed (see my round-2 comment — a 3-line mirror of the saved-path fix + a test), plus the low nits. Happy for those to land here or as a quick follow-up. Nice work.
Code Review Agent Run #49cc52Actionable Suggestions - 0Review Details
Bito Usage GuideCommands Type the following command in the pull request comment and save the comment.
Refer to the documentation for additional commands. Configuration This repository uses Documentation & Help AI Code Review powered by |
3 participants
SUMMARY
The MCP service emitted zero StatsD/Prometheus metrics, and its middleware swallowed every exception before any error tracker could see them. This adds:
LoggingMiddleware.on_call_tool, plus a user-vs-system error counter split inGlobalErrorHandlerMiddleware._handle_error— mirrors the@statsd_metricspattern already used inviews/base_api.py.LoggingMiddlewareskipped itsevent_logger.log(...)call entirely whenhas_app_context()wasFalseat the time the middlewarefinallyblock ran (the per-tool app context had already exited). Both call sites now wrap the log call in the existing_get_app_context_manager()helper instead of skipping it.MCP_ERROR_HOOKconfig: a vendor-neutralCallable[[Exception, dict], None] | Nonehook invoked for system-class errors inGlobalErrorHandlerMiddleware._handle_error(primary capture point) and inStructuredContentStripperMiddleware.on_call_tool's last-resort except block (for exceptions that bypass the primary handler entirely). This lets operators wire an external error tracker (e.g. Sentry) without the OSS repo taking a hard dependency on any vendor SDK.PRODUCTION.mdis updated to note thatFlaskIntegrationdoes not cover the FastMCP tool-execution path and shows wiring Sentry via the hook instead.error_typeextraction:LoggingMiddlewarepreviously substring-sniffed"error_type"in serialized tool responses only to decide success/failure, discarding the actual value. It's now parsed and included in the log line, curated payload, and metric tag.f"err_{int(time.time())}"ID that collides under concurrent failures — replaced with the existing per-callmcp_call_id. Addedevent_logger.log_contextinstrumentation toget_chart_type_schema(previously the only uninstrumented tool). Added server-sidelogger.warning/logger.exceptioncalls next to severalreturn XError(...)sites inget_chart_data,get_tag_info, andquery_datasetthat only logged to the MCP client (ctx.error/ctx.warning, which never reaches server logs) or didn't log at all.BEFORE/AFTER
Before:
grep -r "stats_logger\|statsd\|incr(\|timing(" superset/mcp_service/→ no hits. No error tracker could ever see an MCP tool failure, and DB audit rows formcp_tool_call/mcp_messagewere silently dropped whenever the ambient Flask app context had already exited.After: Per-tool
mcp.tool.{name}.{success|error}counters andmcp.tool.{name}.timetiming are emitted on every tool call. Audit rows are always written. Operators can wireMCP_ERROR_HOOKto forward system-class errors to an external tracker.TESTING INSTRUCTIONS
tests/unit_tests/mcp_service/test_middleware.pyandtest_middleware_logging.pywith unit tests covering: metrics emission (success/error counters + timing, including thecall_toolproxy tool-name resolution case),error_typeextraction from structured responses, theMCP_ERROR_HOOKinvocation/no-op/exception-swallowing paths in both middlewares, themcp_call_id-as-error_idfix, and regression tests confirming bothLoggingMiddleware.on_call_toolandon_messageroute their audit-row log call through_get_app_context_manager()rather than conditionally skipping it.pytest tests/unit_tests/mcp_service/— 2691 passed.ruff check/ruff format --check/mypy/pylintall pass on the changed files.ADDITIONAL INFORMATION