|
| 1 | +"""Unhandled RPC handler exceptions must be logged instead of silently swallowed. |
| 2 | +
|
| 3 | +Requests already returned a JSON-RPC -32603 error but discarded the original |
| 4 | +traceback; notifications suppressed the exception entirely. Both now log the |
| 5 | +underlying exception so integrators (e.g. Sentry via its logging integration) |
| 6 | +can see server-side handler crashes. |
| 7 | +""" |
| 8 | + |
| 9 | +from __future__ import annotations |
| 10 | + |
1 | 11 | import asyncio |
2 | | -import json |
3 | 12 | import logging |
4 | | -from typing import cast |
| 13 | +from typing import Any |
| 14 | +from unittest.mock import MagicMock |
5 | 15 |
|
6 | 16 | import pytest |
7 | 17 |
|
8 | | -from acp import Agent |
9 | | -from acp.core import AgentSideConnection |
| 18 | +from acp.connection import Connection, MethodHandler |
| 19 | +from acp.exceptions import RequestError |
10 | 20 | from tests.conftest import TestAgent |
11 | 21 |
|
12 | 22 |
|
| 23 | +class _RecordingSender: |
| 24 | + """Duck-typed MessageSender that records outgoing frames instead of writing them.""" |
| 25 | + |
| 26 | + def __init__(self, writer: asyncio.StreamWriter, supervisor: Any) -> None: |
| 27 | + self.sent: list[dict[str, Any]] = [] |
| 28 | + |
| 29 | + async def send(self, payload: dict[str, Any]) -> None: |
| 30 | + self.sent.append(payload) |
| 31 | + |
| 32 | + async def close(self) -> None: |
| 33 | + pass |
| 34 | + |
| 35 | + |
| 36 | +def _make_connection(handler: MethodHandler) -> tuple[Connection, _RecordingSender]: |
| 37 | + captured: dict[str, _RecordingSender] = {} |
| 38 | + |
| 39 | + def sender_factory(writer: asyncio.StreamWriter, supervisor: Any) -> _RecordingSender: |
| 40 | + captured["sender"] = _RecordingSender(writer, supervisor) |
| 41 | + return captured["sender"] |
| 42 | + |
| 43 | + conn = Connection(handler, MagicMock(), MagicMock(), sender_factory=sender_factory, listening=False) |
| 44 | + return conn, captured["sender"] |
| 45 | + |
| 46 | + |
| 47 | +async def _raising_handler(method: str, params: Any, is_notification: bool) -> Any: |
| 48 | + raise RuntimeError("kaboom") |
| 49 | + |
| 50 | + |
| 51 | +def _assert_logged_runtime_error(caplog: pytest.LogCaptureFixture, method: str) -> None: |
| 52 | + records = [ |
| 53 | + record |
| 54 | + for record in caplog.records |
| 55 | + if record.levelno == logging.ERROR and record.exc_info and f"method={method}" in record.getMessage() |
| 56 | + ] |
| 57 | + assert len(records) == 1, f"expected exactly one logged error for method={method}" |
| 58 | + exc_info = records[0].exc_info |
| 59 | + assert exc_info is not None |
| 60 | + logged = exc_info[1] |
| 61 | + assert isinstance(logged, RuntimeError) |
| 62 | + assert str(logged) == "kaboom" |
| 63 | + |
| 64 | + |
13 | 65 | @pytest.mark.asyncio |
14 | | -async def test_unexpected_handler_error_is_logged_and_returns_internal_error(server, caplog): |
15 | | - class _RaisingAgent(TestAgent): |
16 | | - __test__ = False |
17 | | - |
18 | | - async def initialize( |
19 | | - self, |
20 | | - protocol_version, |
21 | | - client_capabilities=None, |
22 | | - client_info=None, |
23 | | - **kwargs, |
24 | | - ): |
25 | | - raise RuntimeError("boom") |
26 | | - |
27 | | - AgentSideConnection( |
28 | | - cast(Agent, _RaisingAgent()), |
29 | | - server.server_writer, |
30 | | - server.server_reader, |
31 | | - listening=True, |
32 | | - ) |
33 | | - |
34 | | - req = {"jsonrpc": "2.0", "id": 1, "method": "initialize", "params": {"protocolVersion": 1}} |
35 | | - with caplog.at_level(logging.ERROR): |
36 | | - server.client_writer.write((json.dumps(req) + "\n").encode()) |
37 | | - await server.client_writer.drain() |
38 | | - line = await asyncio.wait_for(server.client_reader.readline(), timeout=1) |
| 66 | +async def test_run_request_unhandled_exception_is_logged_and_returned_as_internal_error(caplog): |
| 67 | + conn, sender = _make_connection(_raising_handler) |
| 68 | + request = {"jsonrpc": "2.0", "id": 7, "method": "explode", "params": None} |
| 69 | + |
| 70 | + try: |
| 71 | + with caplog.at_level(logging.ERROR), pytest.raises(RequestError) as exc_info: |
| 72 | + await conn._run_request(request) |
| 73 | + finally: |
| 74 | + await conn.close() |
| 75 | + |
| 76 | + # The handler exception is re-raised as a JSON-RPC internal error... |
| 77 | + raised = exc_info.value |
| 78 | + assert isinstance(raised, RequestError) |
| 79 | + assert raised.code == -32603 |
| 80 | + assert raised.data == {"details": "kaboom"} |
39 | 81 |
|
40 | | - resp = json.loads(line) |
41 | | - assert resp["id"] == 1 |
42 | | - assert resp["error"]["code"] == -32603 # internal error |
| 82 | + # ...and exactly one error frame carrying the handler's message is written to the peer. |
| 83 | + assert len(sender.sent) == 1 |
| 84 | + response = sender.sent[0] |
| 85 | + assert response["id"] == 7 |
| 86 | + assert "result" not in response |
| 87 | + assert response["error"] == {"code": -32603, "message": "Internal error", "data": {"details": "kaboom"}} |
43 | 88 |
|
44 | | - # The original exception (with its traceback) must be logged, not silently |
45 | | - # swallowed into the JSON-RPC response. |
46 | | - assert any(record.exc_info for record in caplog.records) |
| 89 | + # The original exception is logged, not discarded by `raise err from None`. |
| 90 | + _assert_logged_runtime_error(caplog, "explode") |
47 | 91 |
|
48 | 92 |
|
49 | 93 | @pytest.mark.asyncio |
50 | | -async def test_unexpected_notification_error_is_logged_and_not_swallowed(server, caplog): |
51 | | - class _RaisingCancelAgent(TestAgent): |
52 | | - __test__ = False |
53 | | - |
54 | | - def __init__(self) -> None: |
55 | | - super().__init__() |
56 | | - self.cancel_called = asyncio.Event() |
57 | | - |
58 | | - async def cancel(self, session_id, **kwargs): |
59 | | - self.cancel_called.set() |
60 | | - raise RuntimeError("boom") |
61 | | - |
62 | | - agent = _RaisingCancelAgent() |
63 | | - AgentSideConnection( |
64 | | - cast(Agent, agent), |
65 | | - server.server_writer, |
66 | | - server.server_reader, |
67 | | - listening=True, |
68 | | - ) |
69 | | - |
70 | | - note = {"jsonrpc": "2.0", "method": "session/cancel", "params": {"sessionId": "s1"}} |
| 94 | +async def test_run_notification_unhandled_exception_is_logged_and_not_answered(caplog): |
| 95 | + conn, sender = _make_connection(_raising_handler) |
| 96 | + notification = {"jsonrpc": "2.0", "method": "session/cancel", "params": {"sessionId": "s1"}} |
| 97 | + |
| 98 | + try: |
| 99 | + with caplog.at_level(logging.ERROR): |
| 100 | + result = await conn._run_notification(notification) |
| 101 | + finally: |
| 102 | + await conn.close() |
| 103 | + |
| 104 | + # A notification has no response: the error is neither raised nor written to the wire. |
| 105 | + assert result is None |
| 106 | + assert sender.sent == [] |
| 107 | + |
| 108 | + # It must still be logged — previously contextlib.suppress dropped it silently. |
| 109 | + _assert_logged_runtime_error(caplog, "session/cancel") |
| 110 | + |
| 111 | + |
| 112 | +class _RaisingCancelAgent(TestAgent): |
| 113 | + __test__ = False |
| 114 | + |
| 115 | + def __init__(self) -> None: |
| 116 | + super().__init__() |
| 117 | + self.cancel_called = asyncio.Event() |
| 118 | + |
| 119 | + async def cancel(self, session_id: str, **kwargs: Any) -> None: |
| 120 | + self.cancel_called.set() |
| 121 | + raise RuntimeError("kaboom") |
| 122 | + |
| 123 | + |
| 124 | +@pytest.mark.asyncio |
| 125 | +@pytest.mark.parametrize("agent", [_RaisingCancelAgent()]) |
| 126 | +async def test_agent_notification_handler_error_is_logged_and_connection_survives(connect, agent, caplog): |
| 127 | + _, client_conn = connect() |
| 128 | + |
71 | 129 | with caplog.at_level(logging.ERROR): |
72 | | - server.client_writer.write((json.dumps(note) + "\n").encode()) |
73 | | - await server.client_writer.drain() |
| 130 | + await client_conn.cancel(session_id="sess-1") |
74 | 131 | await asyncio.wait_for(agent.cancel_called.wait(), timeout=1) |
| 132 | + # The crashing handler must not tear down the connection: a follow-up request still round-trips. |
| 133 | + response = await asyncio.wait_for(client_conn.initialize(protocol_version=1), timeout=1) |
75 | 134 |
|
76 | | - # A notification handler that raises must be logged, not silently swallowed, |
77 | | - # so integrators can surface it (e.g. to Sentry). |
78 | | - assert any(record.exc_info for record in caplog.records) |
| 135 | + assert response.protocol_version == 1 |
| 136 | + _assert_logged_runtime_error(caplog, "session/cancel") |
0 commit comments