Skip to content

fix: prevent infinite warning-logging loop in _handle_message#3124

Open
rahul188 wants to merge 2 commits into
modelcontextprotocol:v1.xfrom
rahul188:fix-3122-handle-message-warning-loop
Open

fix: prevent infinite warning-logging loop in _handle_message#3124
rahul188 wants to merge 2 commits into
modelcontextprotocol:v1.xfrom
rahul188:fix-3122-handle-message-warning-loop

Conversation

@rahul188

Copy link
Copy Markdown

Summary

Fixes #3122

Server._handle_message (mcp/server/lowlevel/server.py) logs the warnings recorded during message handling while still inside the warnings.catch_warnings(record=True) block. Because record=True installs an "always" filter, any warning emitted by a logging handler while those logger.info calls run is appended to the very list being iterated, so the for warning in w loop never terminates. The loop is synchronous with no await points, so task cancellation cannot interrupt it; the handling task wedges until an external timeout kills the process. This shows up in practice when a formatter on the logger chain warns per record (for example a datetime.utcnow()-based JSON timestamp formatter on Python 3.12+), and it is easy to trigger under pytest, which runs with an "always" warning filter.

Fix

Snapshot the recorded warnings and emit the log lines after leaving the catch_warnings block. Once the block exits, the recording showwarning is restored, so a warning raised by a logging handler goes to the normal warnings machinery instead of being appended to the snapshot, and the loop iterates a fixed list. Behaviour for the normal case (recorded warnings are still logged once each) is unchanged.

Tests

Added tests/issues/test_3122_warning_loop.py. It drives _handle_message with a request that records one warning and attaches a logging handler that itself warns on every record, then asserts the handler is invoked exactly once. The handler stops re-warning after a cap so that a regressed (looping) build terminates and fails the assertion rather than hanging the session. The test fails on v1.x before this change (handler invoked many times) and passes after.

This targets v1.x; main already dropped this block in the v2 receive-path rewrite, so it is not affected.

Server._handle_message logged recorded warnings while still inside the
warnings.catch_warnings(record=True) block. Since record=True installs an
always filter, a warning emitted by a logging handler during that logging step
was appended to the list being iterated, so the loop never terminated. The loop
is synchronous, so cancellation could not interrupt it and the task wedged.

Snapshot the recorded warnings and log them after leaving the catch_warnings
block so handler-emitted warnings can no longer extend the iteration.

Github-Issue: modelcontextprotocol#3122
Reported-by: fas89

@cubic-dev-ai cubic-dev-ai Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No issues found across 2 files

Re-trigger cubic

Record two warnings during handling and warn on only the first log record, so
the handler's cap branch is taken in the passing run too (the repo enforces
fail-under=100). Still asserts the handler is invoked once per recorded warning
(twice), which a regressed build breaks by re-appending its own warning.
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.

1 participant