diff --git a/src/logging_filters.py b/src/logging_filters.py new file mode 100644 index 0000000..f4979fe --- /dev/null +++ b/src/logging_filters.py @@ -0,0 +1,53 @@ +"""Logging filters used by ``server._run`` to mute known-benign upstream noise. + +These filters are pure log hygiene — they neither change behaviour nor mask +real errors, only drop specific records the operator can do nothing useful +with. Each filter is scoped to a single logger and a single record shape. +""" + +from __future__ import annotations + +import logging + +import anyio + + +class StandaloneSseWriterRaceFilter(logging.Filter): + """Drop the ``mcp.server.streamable_http`` ERROR record that fires on + session teardown when ``GET /mcp`` SSE writers race against ``DELETE + /mcp`` cleanup. + + The upstream MCP SDK logs a full ``ClosedResourceError`` traceback from + ``standalone_sse_writer`` (around line 711 of + ``mcp/server/streamable_http.py``) every time a stateful client opens an + SSE stream and immediately terminates the session — which, for our + LiteLLM-fronted setup, is every brokered call. The DELETE itself returns + 200, the session ends cleanly, the client gets its response; the trace + is purely log noise. + + Upstream PR #1384 (merged 2025-12-04) added explicit + ``ClosedResourceError`` handling to the sibling ``message_router``. The + same pattern hasn't been ported to ``standalone_sse_writer`` yet, so we + filter the record locally rather than crank the whole logger to + ``CRITICAL``. + + Filter is intentionally narrow: only drops records whose exact message + matches and whose ``exc_info`` is an ``anyio.ClosedResourceError`` (or + subclass). Every other ERROR from the same logger — including legitimate + streamable-HTTP failures — passes through unchanged. + """ + + _MESSAGE = "Error in standalone SSE writer" + + def filter(self, record: logging.LogRecord) -> bool: + if record.getMessage() != self._MESSAGE: + return True + if not record.exc_info: + return True + exc_type = record.exc_info[0] + if exc_type is None: + return True + try: + return not issubclass(exc_type, anyio.ClosedResourceError) + except TypeError: + return True diff --git a/src/server.py b/src/server.py index 871f2fe..83edcc8 100644 --- a/src/server.py +++ b/src/server.py @@ -488,6 +488,14 @@ def _run(transport: str) -> None: import uvicorn from src.auth import BearerAuthMiddleware + from src.logging_filters import StandaloneSseWriterRaceFilter + + # Mute the upstream SDK's ClosedResourceError noise on session teardown. + # See StandaloneSseWriterRaceFilter for why this is benign and narrow. + # Idempotent: re-entry into _run (eg. tests) doesn't stack duplicate filters. + sdk_logger = logging.getLogger("mcp.server.streamable_http") + if not any(isinstance(f, StandaloneSseWriterRaceFilter) for f in sdk_logger.filters): + sdk_logger.addFilter(StandaloneSseWriterRaceFilter()) app = mcp.streamable_http_app() if transport == "streamable-http" else mcp.sse_app() diff --git a/tests/test_logging_filters.py b/tests/test_logging_filters.py new file mode 100644 index 0000000..062c8b6 --- /dev/null +++ b/tests/test_logging_filters.py @@ -0,0 +1,92 @@ +"""Tests for ``src.logging_filters.StandaloneSseWriterRaceFilter``.""" + +from __future__ import annotations + +import logging +import sys + +import anyio +import pytest + +from src.logging_filters import StandaloneSseWriterRaceFilter + + +def _make_record( + message: str, + *, + exc_info: tuple | None = None, +) -> logging.LogRecord: + return logging.LogRecord( + name="mcp.server.streamable_http", + level=logging.ERROR, + pathname=__file__, + lineno=0, + msg=message, + args=(), + exc_info=exc_info, + ) + + +def _exc_info_for(exc: BaseException) -> tuple: + try: + raise exc + except BaseException: + return sys.exc_info() + + +class TestStandaloneSseWriterRaceFilter: + def setup_method(self) -> None: + self.filt = StandaloneSseWriterRaceFilter() + + def test_passes_unrelated_message(self) -> None: + rec = _make_record("Some other error", exc_info=_exc_info_for(anyio.ClosedResourceError())) + assert self.filt.filter(rec) is True + + def test_passes_target_message_without_exc_info(self) -> None: + rec = _make_record("Error in standalone SSE writer") + assert self.filt.filter(rec) is True + + def test_passes_target_message_with_unrelated_exc(self) -> None: + rec = _make_record( + "Error in standalone SSE writer", + exc_info=_exc_info_for(RuntimeError("totally different")), + ) + assert self.filt.filter(rec) is True + + def test_drops_target_message_with_closed_resource_error(self) -> None: + rec = _make_record( + "Error in standalone SSE writer", + exc_info=_exc_info_for(anyio.ClosedResourceError()), + ) + assert self.filt.filter(rec) is False + + def test_drops_subclass_of_closed_resource_error(self) -> None: + class _SubError(anyio.ClosedResourceError): + pass + + rec = _make_record( + "Error in standalone SSE writer", + exc_info=_exc_info_for(_SubError()), + ) + assert self.filt.filter(rec) is False + + def test_handles_malformed_exc_info_gracefully(self) -> None: + """exc_info[0] = None can happen on some logging shapes — must not raise.""" + rec = _make_record("Error in standalone SSE writer", exc_info=(None, None, None)) + assert self.filt.filter(rec) is True + + +@pytest.mark.parametrize( + "msg", + [ + "error in standalone sse writer", + "Error in standalone SSE writer (extra)", + "Standalone SSE writer error", + ], +) +def test_message_match_is_exact(msg: str) -> None: + """Filter intentionally matches only the exact upstream message string — + a future upstream wording change should bring the noise back, not mask it.""" + filt = StandaloneSseWriterRaceFilter() + rec = _make_record(msg, exc_info=_exc_info_for(anyio.ClosedResourceError())) + assert filt.filter(rec) is True diff --git a/tests/test_run_wiring.py b/tests/test_run_wiring.py index 4e0d12f..cb8fffe 100644 --- a/tests/test_run_wiring.py +++ b/tests/test_run_wiring.py @@ -8,6 +8,7 @@ from __future__ import annotations +import logging from contextlib import contextmanager from unittest.mock import MagicMock, patch @@ -15,6 +16,7 @@ import src.server as server_mod from src.auth import BearerAuthMiddleware +from src.logging_filters import StandaloneSseWriterRaceFilter def _fake_settings(*, has_token: bool, token: str = "s3cret") -> MagicMock: @@ -100,3 +102,60 @@ def test_warns_when_token_missing(self, caplog: pytest.LogCaptureFixture) -> Non "MCP_BEARER_TOKEN not set" in rec.message and rec.levelname == "WARNING" for rec in caplog.records ) + + +@pytest.fixture +def _clean_sdk_logger_filters(): + """Strip our race filter from the upstream logger before + after each test + so order-of-execution doesn't leak attachment state across cases.""" + sdk_logger = logging.getLogger("mcp.server.streamable_http") + + def _purge() -> None: + for f in list(sdk_logger.filters): + if isinstance(f, StandaloneSseWriterRaceFilter): + sdk_logger.removeFilter(f) + + _purge() + try: + yield sdk_logger + finally: + _purge() + + +class TestRaceFilterInstallation: + def test_attaches_race_filter_on_http_transport( + self, _clean_sdk_logger_filters: logging.Logger + ) -> None: + bare_app = object() + with ( + patch.object(server_mod.mcp, "streamable_http_app", return_value=bare_app), + patch.object(server_mod, "settings", _fake_settings(has_token=False)), + _patched_uvicorn(), + ): + server_mod._run("streamable-http") + assert any( + isinstance(f, StandaloneSseWriterRaceFilter) for f in _clean_sdk_logger_filters.filters + ) + + def test_does_not_attach_on_stdio(self, _clean_sdk_logger_filters: logging.Logger) -> None: + with _patched_uvicorn(), patch.object(server_mod.mcp, "run"): + server_mod._run("stdio") + assert not any( + isinstance(f, StandaloneSseWriterRaceFilter) for f in _clean_sdk_logger_filters.filters + ) + + def test_attachment_is_idempotent(self, _clean_sdk_logger_filters: logging.Logger) -> None: + bare_app = object() + with ( + patch.object(server_mod.mcp, "streamable_http_app", return_value=bare_app), + patch.object(server_mod, "settings", _fake_settings(has_token=False)), + _patched_uvicorn(), + ): + server_mod._run("streamable-http") + server_mod._run("streamable-http") + race_filters = [ + f + for f in _clean_sdk_logger_filters.filters + if isinstance(f, StandaloneSseWriterRaceFilter) + ] + assert len(race_filters) == 1 diff --git a/uv.lock b/uv.lock index 09e35eb..e1e06fc 100644 --- a/uv.lock +++ b/uv.lock @@ -434,7 +434,7 @@ wheels = [ [[package]] name = "homarr-mcp" -version = "1.0.1" +version = "1.1.0" source = { editable = "." } dependencies = [ { name = "httpx" },