Log connection failures at WARNING, with their cause (opal#711)

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")

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}")

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 == []