From 88c7a7454db02d8e2e02ae999b8c9a59d42bab32 Mon Sep 17 00:00:00 2001 From: Michel Thomazo Date: Wed, 8 Jul 2026 16:36:36 +0200 Subject: [PATCH 1/3] fix(connection): log unhandled request handler exceptions MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Connection._run_request catches any unexpected handler exception, converts it to a JSON-RPC -32603 response, and re-raises a fresh RequestError `from None` — discarding the original exception and its traceback. Unlike every other error path in this module (main_loop, the receive loop, stream observers, _on_receive_error, _on_task_error), it is never logged, so server-side handler crashes are invisible: integrators only ever see a contextless "Internal error" on the wire with no stack to diagnose the root cause. Log the original exception before converting it, mirroring the existing logging.exception(..., exc_info=exc) calls in this file. Only the method name and the exception (type + traceback) are logged, not the request params, and str(exc) is already returned to the peer today — so this adds no new data exposure. The protocol response is unchanged. Adds a regression test: a handler that raises returns -32603 and the exception is logged. Generated by Mistral Vibe. Co-Authored-By: Mistral Vibe --- src/acp/connection.py | 5 ++++ tests/test_request_error_logging.py | 46 +++++++++++++++++++++++++++++ 2 files changed, 51 insertions(+) create mode 100644 tests/test_request_error_logging.py diff --git a/src/acp/connection.py b/src/acp/connection.py index 09e5a0e..8978849 100644 --- a/src/acp/connection.py +++ b/src/acp/connection.py @@ -255,6 +255,11 @@ async def _run_request(self, message: dict[str, Any]) -> Any: self._notify_observers(StreamDirection.OUTGOING, payload) raise err from None except Exception as exc: + logging.exception( + "Unhandled error while handling request method=%s", + method, + exc_info=exc, + ) try: data = json.loads(str(exc)) except Exception: diff --git a/tests/test_request_error_logging.py b/tests/test_request_error_logging.py new file mode 100644 index 0000000..951407b --- /dev/null +++ b/tests/test_request_error_logging.py @@ -0,0 +1,46 @@ +import asyncio +import json +import logging +from typing import cast + +import pytest + +from acp import Agent +from acp.core import AgentSideConnection +from tests.conftest import TestAgent + + +@pytest.mark.asyncio +async def test_unexpected_handler_error_is_logged_and_returns_internal_error(server, caplog): + class _RaisingAgent(TestAgent): + __test__ = False + + async def initialize( + self, + protocol_version, + client_capabilities=None, + client_info=None, + **kwargs, + ): + raise RuntimeError("boom") + + AgentSideConnection( + cast(Agent, _RaisingAgent()), + server.server_writer, + server.server_reader, + listening=True, + ) + + req = {"jsonrpc": "2.0", "id": 1, "method": "initialize", "params": {"protocolVersion": 1}} + with caplog.at_level(logging.ERROR): + server.client_writer.write((json.dumps(req) + "\n").encode()) + await server.client_writer.drain() + line = await asyncio.wait_for(server.client_reader.readline(), timeout=1) + + resp = json.loads(line) + assert resp["id"] == 1 + assert resp["error"]["code"] == -32603 # internal error + + # The original exception (with its traceback) must be logged, not silently + # swallowed into the JSON-RPC response. + assert any(record.exc_info for record in caplog.records) From c1735ffe4264eee909b08b3511c7c902684ce584 Mon Sep 17 00:00:00 2001 From: Michel Thomazo Date: Thu, 9 Jul 2026 16:19:01 +0200 Subject: [PATCH 2/3] fix(connection): log unhandled notification handler exceptions MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Connection._run_notification wrapped the handler call in contextlib.suppress(Exception), swallowing every notification-handler error silently: no log, and (correctly) no wire response since notifications have none by protocol. It was the only handler-error path in the module that stayed silent — main_loop, the receive loop, stream observers, _on_receive_error, _on_task_error, and (since the previous commit) _run_request all log. Integrators wiring Sentry via the logging integration therefore had to wrap every notification handler (cancel, ext_notification, and on the client side session_update, complete_elicitation) by hand to see failures. Replace the suppress with a try/except that logs the original exception and its traceback, mirroring the logging.exception(..., exc_info=exc) call in _run_request. Behaviour is otherwise unchanged: the exception is still not propagated, and the telemetry span still sees no exception (contextlib.suppress already exited before span_context, so this is not a span-status change). Unlike _run_request we deliberately do not re-raise: notifications have no response and no store bookkeeping, so re-raising would only add a duplicate, contextless "Background task failed" line. Drop the now-unused contextlib import. Adds a regression test: a session/cancel handler that raises is logged (with traceback) instead of silently swallowed. Generated by Mistral Vibe. Co-Authored-By: Mistral Vibe --- src/acp/connection.py | 12 ++++++++--- tests/test_request_error_logging.py | 32 +++++++++++++++++++++++++++++ 2 files changed, 41 insertions(+), 3 deletions(-) diff --git a/src/acp/connection.py b/src/acp/connection.py index 8978849..41cdebc 100644 --- a/src/acp/connection.py +++ b/src/acp/connection.py @@ -1,7 +1,6 @@ from __future__ import annotations import asyncio -import contextlib import copy import inspect import json @@ -272,8 +271,15 @@ async def _run_request(self, message: dict[str, Any]) -> Any: async def _run_notification(self, message: dict[str, Any]) -> None: method = message["method"] - with span_context("acp.notification", attributes={"method": method}), contextlib.suppress(Exception): - await self._handler(method, message.get("params"), True) + with span_context("acp.notification", attributes={"method": method}): + try: + await self._handler(method, message.get("params"), True) + except Exception as exc: + logging.exception( + "Unhandled error while handling notification method=%s", + method, + exc_info=exc, + ) async def _handle_response(self, message: dict[str, Any]) -> None: request_id = message["id"] diff --git a/tests/test_request_error_logging.py b/tests/test_request_error_logging.py index 951407b..d4769ce 100644 --- a/tests/test_request_error_logging.py +++ b/tests/test_request_error_logging.py @@ -44,3 +44,35 @@ async def initialize( # The original exception (with its traceback) must be logged, not silently # swallowed into the JSON-RPC response. assert any(record.exc_info for record in caplog.records) + + +@pytest.mark.asyncio +async def test_unexpected_notification_error_is_logged_and_not_swallowed(server, caplog): + class _RaisingCancelAgent(TestAgent): + __test__ = False + + def __init__(self) -> None: + super().__init__() + self.cancel_called = asyncio.Event() + + async def cancel(self, session_id, **kwargs): + self.cancel_called.set() + raise RuntimeError("boom") + + agent = _RaisingCancelAgent() + AgentSideConnection( + cast(Agent, agent), + server.server_writer, + server.server_reader, + listening=True, + ) + + note = {"jsonrpc": "2.0", "method": "session/cancel", "params": {"sessionId": "s1"}} + with caplog.at_level(logging.ERROR): + server.client_writer.write((json.dumps(note) + "\n").encode()) + await server.client_writer.drain() + await asyncio.wait_for(agent.cancel_called.wait(), timeout=1) + + # A notification handler that raises must be logged, not silently swallowed, + # so integrators can surface it (e.g. to Sentry). + assert any(record.exc_info for record in caplog.records) From 1f0b15d74cdb143e41023b97fa0379318f5872dc Mon Sep 17 00:00:00 2001 From: Michel Thomazo Date: Thu, 9 Jul 2026 16:38:26 +0200 Subject: [PATCH 3/3] test(connection): harden unhandled-handler-exception regression tests Rewrites the request/notification error-logging tests to be deterministic and precise instead of only asserting that "some record has exc_info": - Drive Connection._run_request / _run_notification directly with a recording sender (mirroring test_core's TrackingSender) so assertions cover the exact wire frame: a request emits one -32603 error carrying {"details": ...} and re-raises RequestError; a notification emits nothing (deterministic, no timeout read). - Assert the logged record is the original RuntimeError (type + message) under the expected method=..., not merely that a record exists. Confirmed both tests fail on the pre-fix behaviour (silent suppress / no request log) and pass with it. Generated by Mistral Vibe. Co-Authored-By: Mistral Vibe --- tests/test_request_error_logging.py | 164 ++++++++++++++++------------ 1 file changed, 97 insertions(+), 67 deletions(-) diff --git a/tests/test_request_error_logging.py b/tests/test_request_error_logging.py index d4769ce..3581804 100644 --- a/tests/test_request_error_logging.py +++ b/tests/test_request_error_logging.py @@ -1,78 +1,108 @@ +"""Unhandled RPC handler exceptions must be logged instead of silently swallowed. + +Requests already returned a JSON-RPC -32603 error but discarded the original +traceback; notifications suppressed the exception entirely. Both now log the +underlying exception so integrators (e.g. Sentry via its logging integration) +can see server-side handler crashes. +""" + +from __future__ import annotations + import asyncio -import json import logging -from typing import cast +from typing import Any +from unittest.mock import MagicMock import pytest -from acp import Agent -from acp.core import AgentSideConnection -from tests.conftest import TestAgent +from acp.connection import Connection, MethodHandler +from acp.exceptions import RequestError + + +class _RecordingSender: + """Duck-typed MessageSender that records outgoing frames instead of writing them.""" + + def __init__(self, writer: asyncio.StreamWriter, supervisor: Any) -> None: + self.sent: list[dict[str, Any]] = [] + + async def send(self, payload: dict[str, Any]) -> None: + self.sent.append(payload) + + async def close(self) -> None: + pass + + +def _make_connection(handler: MethodHandler) -> tuple[Connection, _RecordingSender]: + captured: dict[str, _RecordingSender] = {} + + def sender_factory(writer: asyncio.StreamWriter, supervisor: Any) -> _RecordingSender: + captured["sender"] = _RecordingSender(writer, supervisor) + return captured["sender"] + + conn = Connection(handler, MagicMock(), MagicMock(), sender_factory=sender_factory, listening=False) + return conn, captured["sender"] + + +async def _raising_handler(method: str, params: Any, is_notification: bool) -> Any: + raise RuntimeError("kaboom") + + +def _assert_logged_runtime_error(caplog: pytest.LogCaptureFixture, method: str) -> None: + records = [ + record + for record in caplog.records + if record.levelno == logging.ERROR and record.exc_info and f"method={method}" in record.getMessage() + ] + assert len(records) == 1, f"expected exactly one logged error for method={method}" + exc_info = records[0].exc_info + assert exc_info is not None + logged = exc_info[1] + assert isinstance(logged, RuntimeError) + assert str(logged) == "kaboom" @pytest.mark.asyncio -async def test_unexpected_handler_error_is_logged_and_returns_internal_error(server, caplog): - class _RaisingAgent(TestAgent): - __test__ = False - - async def initialize( - self, - protocol_version, - client_capabilities=None, - client_info=None, - **kwargs, - ): - raise RuntimeError("boom") - - AgentSideConnection( - cast(Agent, _RaisingAgent()), - server.server_writer, - server.server_reader, - listening=True, - ) - - req = {"jsonrpc": "2.0", "id": 1, "method": "initialize", "params": {"protocolVersion": 1}} - with caplog.at_level(logging.ERROR): - server.client_writer.write((json.dumps(req) + "\n").encode()) - await server.client_writer.drain() - line = await asyncio.wait_for(server.client_reader.readline(), timeout=1) - - resp = json.loads(line) - assert resp["id"] == 1 - assert resp["error"]["code"] == -32603 # internal error - - # The original exception (with its traceback) must be logged, not silently - # swallowed into the JSON-RPC response. - assert any(record.exc_info for record in caplog.records) +async def test_run_request_unhandled_exception_is_logged_and_returned_as_internal_error(caplog): + conn, sender = _make_connection(_raising_handler) + request = {"jsonrpc": "2.0", "id": 7, "method": "explode", "params": None} + + try: + with caplog.at_level(logging.ERROR), pytest.raises(RequestError) as exc_info: + await conn._run_request(request) + finally: + await conn.close() + + # The handler exception is re-raised as a JSON-RPC internal error... + raised = exc_info.value + assert isinstance(raised, RequestError) + assert raised.code == -32603 + assert raised.data == {"details": "kaboom"} + + # ...and exactly one error frame carrying the handler's message is written to the peer. + assert len(sender.sent) == 1 + response = sender.sent[0] + assert response["id"] == 7 + assert "result" not in response + assert response["error"] == {"code": -32603, "message": "Internal error", "data": {"details": "kaboom"}} + + # The original exception is logged, not discarded by `raise err from None`. + _assert_logged_runtime_error(caplog, "explode") @pytest.mark.asyncio -async def test_unexpected_notification_error_is_logged_and_not_swallowed(server, caplog): - class _RaisingCancelAgent(TestAgent): - __test__ = False - - def __init__(self) -> None: - super().__init__() - self.cancel_called = asyncio.Event() - - async def cancel(self, session_id, **kwargs): - self.cancel_called.set() - raise RuntimeError("boom") - - agent = _RaisingCancelAgent() - AgentSideConnection( - cast(Agent, agent), - server.server_writer, - server.server_reader, - listening=True, - ) - - note = {"jsonrpc": "2.0", "method": "session/cancel", "params": {"sessionId": "s1"}} - with caplog.at_level(logging.ERROR): - server.client_writer.write((json.dumps(note) + "\n").encode()) - await server.client_writer.drain() - await asyncio.wait_for(agent.cancel_called.wait(), timeout=1) - - # A notification handler that raises must be logged, not silently swallowed, - # so integrators can surface it (e.g. to Sentry). - assert any(record.exc_info for record in caplog.records) +async def test_run_notification_unhandled_exception_is_logged_and_not_answered(caplog): + conn, sender = _make_connection(_raising_handler) + notification = {"jsonrpc": "2.0", "method": "session/cancel", "params": {"sessionId": "s1"}} + + try: + with caplog.at_level(logging.ERROR): + result = await conn._run_notification(notification) + finally: + await conn.close() + + # A notification has no response: the error is neither raised nor written to the wire. + assert result is None + assert sender.sent == [] + + # It must still be logged — previously contextlib.suppress dropped it silently. + _assert_logged_runtime_error(caplog, "session/cancel")