|
| 1 | +"""MCP SDK / fastmcp log-noise filters shared across every HTTP launcher. |
| 2 | +
|
| 3 | +Extracted from :mod:`ha_mcp.__main__` for the same reason as |
| 4 | +:mod:`ha_mcp.browser_landing`: the in-process server (the ``ha_mcp_tools`` |
| 5 | +custom-component worker thread) must never import ``ha_mcp.__main__``, since |
| 6 | +that module runs process-global side effects at import time |
| 7 | +(``truststore.inject_into_ssl()``, signal handlers, ``asyncio.run``). These |
| 8 | +filters only call ``logging.Logger.addFilter`` on specific named loggers -- |
| 9 | +no ``basicConfig``, no handler or root-logger changes -- so |
| 10 | +``install_sdk_log_filters()`` is safe to call from any launcher, including |
| 11 | +one that must leave Home Assistant's own logging configuration untouched |
| 12 | +(see the ``log_config=None`` comment in ``embedded_server.py``). |
| 13 | +""" |
| 14 | + |
| 15 | +from __future__ import annotations |
| 16 | + |
| 17 | +import logging |
| 18 | + |
| 19 | +import anyio |
| 20 | +from fastmcp.exceptions import ToolError |
| 21 | +from pydantic import ValidationError as PydanticValidationError |
| 22 | + |
| 23 | + |
| 24 | +class StatelessSessionLogFilter(logging.Filter): |
| 25 | + """Suppress the routine 'Terminating session: None' log from the MCP SDK. |
| 26 | +
|
| 27 | + In stateless HTTP mode every request creates and tears down a temporary |
| 28 | + session whose id is ``None``, so the SDK emits an INFO |
| 29 | + ``Terminating session: None`` (mcp/server/streamable_http.py) on *every* |
| 30 | + request. The line is routine but looks alarming and has repeatedly |
| 31 | + confused users into thinking the connection is broken. |
| 32 | +
|
| 33 | + Returning ``False`` drops the record at this logger before it reaches any |
| 34 | + handler. (Merely downgrading the level to DEBUG did not work: the level |
| 35 | + gate is applied before the filter runs, so the record was already admitted |
| 36 | + and still emitted -- just relabelled.) Real session terminations carry an |
| 37 | + actual id and are not matched, so they still log. |
| 38 | +
|
| 39 | + # TODO: remove when modelcontextprotocol/python-sdk#2329 is resolved |
| 40 | + """ |
| 41 | + |
| 42 | + def filter(self, record: logging.LogRecord) -> bool: |
| 43 | + """Drop the routine stateless-teardown record; pass everything else.""" |
| 44 | + if record.name != "mcp.server.streamable_http": |
| 45 | + return True |
| 46 | + try: |
| 47 | + message = record.getMessage() |
| 48 | + except (ValueError, TypeError): |
| 49 | + # A malformed %-format record on this logger is not our target, and |
| 50 | + # a filter must not raise: filters run in Logger.handle() with no |
| 51 | + # exception handling, so a raise would crash the logging call. |
| 52 | + return True |
| 53 | + # Drop the stateless teardown noise; keep everything else. |
| 54 | + return "Terminating session: None" not in message |
| 55 | + |
| 56 | + |
| 57 | +class ToolValidationLogFilter(logging.Filter): |
| 58 | + """Demote fastmcp tool-failure tracebacks to single-line warnings. |
| 59 | +
|
| 60 | + Pydantic ValidationError and tool-raised ToolError aren't server bugs, |
| 61 | + so the traceback through fastmcp/pydantic internals is just noise. The |
| 62 | + structured error detail is preserved in the WARNING message; stack is |
| 63 | + intentionally dropped because these are user-input errors, not bugs. |
| 64 | + """ |
| 65 | + |
| 66 | + def filter(self, record: logging.LogRecord) -> bool: |
| 67 | + """Demote a known-benign validation/tool-error record to WARNING.""" |
| 68 | + if record.name != "fastmcp.server.server" or not record.exc_info: |
| 69 | + return True |
| 70 | + |
| 71 | + msg = record.getMessage() |
| 72 | + err = record.exc_info[1] |
| 73 | + if "Error validating tool" in msg and isinstance(err, PydanticValidationError): |
| 74 | + record.msg = f"{msg}: {err.errors(include_url=False)}" |
| 75 | + elif "Error calling tool" in msg and isinstance(err, ToolError): |
| 76 | + record.msg = f"{msg}: {err}" |
| 77 | + else: |
| 78 | + return True |
| 79 | + |
| 80 | + record.args = () |
| 81 | + record.levelno = logging.WARNING |
| 82 | + record.levelname = "WARNING" |
| 83 | + record.exc_info = None |
| 84 | + record.exc_text = None |
| 85 | + return True |
| 86 | + |
| 87 | + |
| 88 | +_DISCONNECT_TEARDOWN_ERRORS = (anyio.ClosedResourceError, anyio.BrokenResourceError) |
| 89 | + |
| 90 | + |
| 91 | +def _is_only_disconnect_teardown_errors(err: BaseException) -> bool: |
| 92 | + """True if ``err`` is (or an ExceptionGroup wrapping only) a benign |
| 93 | + streamable-HTTP memory-stream teardown error. |
| 94 | +
|
| 95 | + ``mcp.server.lowlevel.server.Server.run()`` dispatches each incoming |
| 96 | + message via ``anyio.create_task_group().start_soon(...)``, so an error |
| 97 | + raised while delivering one message's response is raised from a |
| 98 | + task-group child -- anyio always wraps that in an ``ExceptionGroup``, |
| 99 | + even for a single failure. The exception a "session crashed" log record |
| 100 | + carries is therefore ``ExceptionGroup(...[<teardown error>])``, not a |
| 101 | + bare one. |
| 102 | +
|
| 103 | + Both ``ClosedResourceError`` and ``BrokenResourceError`` -- sibling |
| 104 | + ``Exception`` subclasses, neither a subclass of the other -- can surface |
| 105 | + here for the same disconnect race: which one depends on which end |
| 106 | + closed first (our end closing raises ``Closed``; the peer's |
| 107 | + ``streamable_http`` ``terminate()`` closing first can wake a parked |
| 108 | + sender into raising ``Broken`` instead, even though the situation is |
| 109 | + identical from the caller's perspective). This repo already treats the |
| 110 | + two as an equivalent pair for streamable-HTTP memory-stream teardown |
| 111 | + elsewhere -- see ``tests/src/haos_runtime.py``'s transient-error tuple. |
| 112 | +
|
| 113 | + Recurse through (possibly nested) groups; any other leaf type means |
| 114 | + this is not the known-benign disconnect race, so the caller should |
| 115 | + leave the record alone. |
| 116 | + """ |
| 117 | + if isinstance(err, _DISCONNECT_TEARDOWN_ERRORS): |
| 118 | + return True |
| 119 | + if isinstance(err, BaseExceptionGroup): |
| 120 | + return bool(err.exceptions) and all( |
| 121 | + _is_only_disconnect_teardown_errors(sub) for sub in err.exceptions |
| 122 | + ) |
| 123 | + return False |
| 124 | + |
| 125 | + |
| 126 | +class SessionDisconnectLogFilter(logging.Filter): |
| 127 | + """Demote 'session crashed' tracebacks caused by an already-gone client. |
| 128 | +
|
| 129 | + Every HTTP entry point runs Streamable HTTP in stateless mode (see |
| 130 | + ``ha_mcp.__main__._http_run_kwargs``). A tool call slow enough to outlast |
| 131 | + the client's patience -- a busy Home Assistant instance, a |
| 132 | + resource-contended local LLM host on the client side, or an ordinary HTTP |
| 133 | + timeout -- lets the SDK finish serving the response and tear the |
| 134 | + transport down while ``app.run()`` is still working; the eventual attempt |
| 135 | + to deliver the response then writes into an already-closed memory stream |
| 136 | + and raises ``anyio.ClosedResourceError`` or ``anyio.BrokenResourceError`` |
| 137 | + (wrapped in an ``ExceptionGroup`` -- see |
| 138 | + ``_is_only_disconnect_teardown_errors``). The SDK already catches this |
| 139 | + (``except Exception: logger.exception(...)`` in both the stateless and |
| 140 | + stateful session runners of mcp/server/streamable_http_manager.py) -- it |
| 141 | + just logs it as an alarming ERROR-level traceback. That's an expected |
| 142 | + race in a stateless HTTP protocol (the client already gave up), not a |
| 143 | + server bug, so demote it the same way ToolValidationLogFilter demotes |
| 144 | + other known-benign failures. Any other exception on this logger -- an |
| 145 | + actual crash -- is left untouched. |
| 146 | + """ |
| 147 | + |
| 148 | + def filter(self, record: logging.LogRecord) -> bool: |
| 149 | + """Demote a disconnect-caused 'session crashed' record to WARNING.""" |
| 150 | + if record.name != "mcp.server.streamable_http_manager" or not record.exc_info: |
| 151 | + return True |
| 152 | + |
| 153 | + err = record.exc_info[1] |
| 154 | + if err is None or not _is_only_disconnect_teardown_errors(err): |
| 155 | + return True |
| 156 | + |
| 157 | + record.msg = ( |
| 158 | + f"{record.getMessage()}: client disconnected before response delivery" |
| 159 | + ) |
| 160 | + record.args = () |
| 161 | + record.levelno = logging.WARNING |
| 162 | + record.levelname = "WARNING" |
| 163 | + record.exc_info = None |
| 164 | + record.exc_text = None |
| 165 | + return True |
| 166 | + |
| 167 | + |
| 168 | +def _add_filter_once(logger_name: str, filter_cls: type[logging.Filter]) -> None: |
| 169 | + """Attach one ``filter_cls`` instance to ``logger_name``, replacing any stale one. |
| 170 | +
|
| 171 | + ``install_sdk_log_filters()`` can run more than once per process: the |
| 172 | + in-process embedded server calls it on every ``_serve()`` reload without |
| 173 | + a process restart, and process-wide ``logging`` state (including each |
| 174 | + named logger's filter list) persists across those reloads. Each reload |
| 175 | + also re-imports this module from scratch (the embedded server purges |
| 176 | + ``ha_mcp.*`` from ``sys.modules`` before reinstalling -- see |
| 177 | + ``_purge_ha_mcp_modules``), so ``filter_cls`` is a BRAND NEW class object |
| 178 | + each time, even though its name is unchanged. A same-``isinstance``-check |
| 179 | + against a filter instance from a PREVIOUS generation would therefore |
| 180 | + never match, letting filters accumulate one more stale instance per |
| 181 | + reload forever. Match by ``(module, qualname)`` instead -- stable across |
| 182 | + reloads of the same module path -- and drop every stale-generation match |
| 183 | + before attaching the current one, so a logger never carries more than |
| 184 | + one filter of a given conceptual type, and it's always this generation's. |
| 185 | + """ |
| 186 | + logger = logging.getLogger(logger_name) |
| 187 | + identity = (filter_cls.__module__, filter_cls.__qualname__) |
| 188 | + logger.filters[:] = [ |
| 189 | + f |
| 190 | + for f in logger.filters |
| 191 | + if (type(f).__module__, type(f).__qualname__) != identity |
| 192 | + ] |
| 193 | + logger.addFilter(filter_cls()) |
| 194 | + |
| 195 | + |
| 196 | +def install_sdk_log_filters() -> None: |
| 197 | + """Attach the demotion filters above to their target SDK/fastmcp loggers. |
| 198 | +
|
| 199 | + Every HTTP launcher must call this: the CLI (``ha_mcp.__main__``), the |
| 200 | + Home Assistant app's ``start.py``, and the in-process embedded server |
| 201 | + (``ha_mcp_tools/embedded_server.py``) each build and run their own |
| 202 | + Streamable HTTP app, so none of them share another launcher's logging |
| 203 | + setup. Safe to call repeatedly -- see ``_add_filter_once``. |
| 204 | + """ |
| 205 | + _add_filter_once("mcp.server.streamable_http", StatelessSessionLogFilter) |
| 206 | + _add_filter_once("mcp.server.streamable_http_manager", SessionDisconnectLogFilter) |
| 207 | + _add_filter_once("fastmcp.server.server", ToolValidationLogFilter) |
0 commit comments