diff --git a/fastapi_websocket_rpc/websocket_rpc_client.py b/fastapi_websocket_rpc/websocket_rpc_client.py index f30103e..9db51f2 100644 --- a/fastapi_websocket_rpc/websocket_rpc_client.py +++ b/fastapi_websocket_rpc/websocket_rpc_client.py @@ -49,27 +49,28 @@ async def connect(self, uri: str, **connect_kwargs): try: self._websocket = await asyncio.get_event_loop().run_in_executor(None, websocket.create_connection, uri, **connect_kwargs) # See https://websocket-client.readthedocs.io/en/latest/exceptions.html - except websocket._exceptions.WebSocketAddressException: - logger.info("websocket address info cannot be found") + # A failed connect is re-raised for the retry wrapper, and this is the + # only place it is logged, so it must be visible above INFO. + except websocket._exceptions.WebSocketAddressException as err: + logger.warning("websocket address info cannot be found - %s", err) raise - except websocket._exceptions.WebSocketBadStatusException: - logger.info("bad handshake status code") + except websocket._exceptions.WebSocketBadStatusException as err: + logger.warning("bad handshake status code - %s", err) raise - except websocket._exceptions.WebSocketConnectionClosedException: - logger.info("remote host closed the connection or some network error happened") + except websocket._exceptions.WebSocketConnectionClosedException as err: + logger.warning("remote host closed the connection or some network error happened - %s", err) raise - except websocket._exceptions.WebSocketPayloadException: - logger.info( - f"WebSocket payload is invalid") + except websocket._exceptions.WebSocketPayloadException as err: + logger.warning("WebSocket payload is invalid - %s", err) raise - except websocket._exceptions.WebSocketProtocolException: - logger.info(f"WebSocket protocol is invalid") + except websocket._exceptions.WebSocketProtocolException as err: + logger.warning("WebSocket protocol is invalid - %s", err) raise - except websocket._exceptions.WebSocketProxyException: - logger.info(f"proxy error occurred") + except websocket._exceptions.WebSocketProxyException as err: + logger.warning("proxy error occurred - %s", err) raise except OSError as err: - logger.info("RPC Connection failed - %s", err) + logger.warning("RPC Connection failed - %s", err) raise except Exception as err: logger.exception("RPC Error") @@ -117,24 +118,26 @@ def __init__(self): async def connect(self, uri: str, **connect_kwargs): try: self._websocket = await websockets.connect(uri, **connect_kwargs) - except ConnectionRefusedError: - logger.info("RPC connection was refused by server") + # A failed connect is re-raised for the retry wrapper, and this is the + # only place it is logged, so it must be visible above INFO. + except ConnectionRefusedError as err: + logger.warning("RPC connection was refused by server - %s", err) raise - except websockets.ConnectionClosedError: - logger.info("RPC connection lost") + except websockets.ConnectionClosedError as err: + logger.warning("RPC connection lost - %s", err) raise - except websockets.ConnectionClosedOK: - logger.info("RPC connection closed") + except websockets.ConnectionClosedOK as err: + logger.warning("RPC connection closed - %s", err) raise except websockets.InvalidStatusCode as err: - logger.info( + logger.warning( f"RPC Websocket failed - with invalid status code {err.status_code}") raise except websockets.WebSocketException as err: - logger.info(f"RPC Websocket failed - with {err}") + logger.warning(f"RPC Websocket failed - with {err}") raise except OSError as err: - logger.info("RPC Connection failed - %s", err) + logger.warning("RPC Connection failed - %s", err) raise except Exception as err: logger.exception("RPC Error") diff --git a/fastapi_websocket_rpc/websocket_rpc_endpoint.py b/fastapi_websocket_rpc/websocket_rpc_endpoint.py index 28ef5b1..0f8c1fb 100644 --- a/fastapi_websocket_rpc/websocket_rpc_endpoint.py +++ b/fastapi_websocket_rpc/websocket_rpc_endpoint.py @@ -94,10 +94,12 @@ async def main_loop(self, websocket: WebSocket, client_id: str = None, **kwargs) logger.info( f"Client disconnected - {websocket.client.port} :: {channel.id}") await self.handle_disconnect(websocket, channel) - except: + except BaseException as err: # cover cases like - RuntimeError('Cannot call "send" once a close message has been sent.') - logger.info( - f"Client connection failed - {websocket.client.port} :: {channel.id}") + # Same catch set as a bare `except:`; the cause is named so an + # operator can tell a bad password from a dropped socket. + logger.warning( + f"Client connection failed - {websocket.client.port} :: {channel.id} - {err!r}") await self.handle_disconnect(websocket, channel) except: logger.exception(f"Failed to serve - {websocket.client.port}") diff --git a/tests/log_level_test.py b/tests/log_level_test.py new file mode 100644 index 0000000..de73d93 --- /dev/null +++ b/tests/log_level_test.py @@ -0,0 +1,84 @@ +""" +Connection failures must log above INFO (permitio/opal#711). + +A failed connect is re-raised for the retry wrapper and logged only in the +handler, and the endpoint's catch-all around the receive loop was the only +record of a client that died mid-session. Both were INFO, so an operator +running at WARNING saw nothing. +""" +import logging +import sys + +import pytest + +from fastapi_websocket_rpc.logger import get_logger +from fastapi_websocket_rpc.websocket_rpc_client import WebSocketsClientHandler +from fastapi_websocket_rpc.websocket_rpc_endpoint import WebsocketRPCEndpoint + + +class _Capture(logging.Handler): + """The library's loggers do not always propagate to root (UVICORN mode sets + propagate=False), so attach directly instead of relying on caplog.""" + + def __init__(self): + super().__init__(level=logging.DEBUG) + self.records = [] + + def emit(self, record): + self.records.append(record) + + +@pytest.fixture +def captured(): + handler = _Capture() + root = logging.getLogger("fastapi_ws_rpc") + root.addHandler(handler) + previous = root.level + root.setLevel(logging.DEBUG) + yield handler.records + root.removeHandler(handler) + root.setLevel(previous) + + +@pytest.mark.asyncio +async def test_refused_connection_is_logged_as_a_warning(captured): + # Port 1 has no listener; websockets raises before any handshake. + handler = WebSocketsClientHandler() + with pytest.raises(OSError): + await handler.connect("ws://127.0.0.1:1/ws", open_timeout=5) + failures = [r for r in captured if "refused" in r.getMessage() or "Connection failed" in r.getMessage()] + assert failures, [r.getMessage() for r in captured] + assert all(r.levelno >= logging.WARNING for r in failures), [ + (r.levelname, r.getMessage()) for r in failures] + + +class _Client: + port = 54321 + + +class _CrashingWebSocket: + """A FastAPI WebSocket stand-in whose receive loop dies with a RuntimeError, + the shape the endpoint's catch-all comment names.""" + client = _Client() + + async def accept(self): + pass + + async def receive_text(self): + raise RuntimeError('Cannot call "send" once a close message has been sent.') + + async def close(self, code=1000): + pass + + +@pytest.mark.asyncio +async def test_a_client_that_dies_mid_session_is_logged_as_a_warning_with_its_cause(captured): + endpoint = WebsocketRPCEndpoint() + await endpoint.main_loop(_CrashingWebSocket()) + failures = [r for r in captured if "Client connection failed" in r.getMessage()] + assert len(failures) == 1, [r.getMessage() for r in captured] + record = failures[0] + assert record.levelno == logging.WARNING + assert "RuntimeError" in record.getMessage() and "close message" in record.getMessage() + # the crashed socket is no longer tracked as active + assert endpoint.manager.active_connections == []