From e103accdfbe18e096e5574a25e6cb99e7678f3fe Mon Sep 17 00:00:00 2001 From: Eric Callahan Date: Thu, 20 Jan 2022 11:44:28 -0500 Subject: [PATCH] websockets: refactor open/close logging Log the User Agent when a websocket is opened. When a websocket is closed log the close code, close Reason, and time elapsed since the last pong was recieved from the client. When Moonraker shuts down send a 1001 Code with Server Shutdown as the reason. Signed-off-by: Eric Callahan --- moonraker/websockets.py | 19 ++++++++++++++++--- 1 file changed, 16 insertions(+), 3 deletions(-) diff --git a/moonraker/websockets.py b/moonraker/websockets.py index 6ef6650..5a92576 100644 --- a/moonraker/websockets.py +++ b/moonraker/websockets.py @@ -343,13 +343,13 @@ class WebsocketManager(APITransport): def add_websocket(self, ws: WebSocket) -> None: self.websockets[ws.uid] = ws - logging.info(f"New Websocket Added: {ws.uid}") + logging.debug(f"New Websocket Added: {ws.uid}") def remove_websocket(self, ws: WebSocket) -> None: old_ws = self.websockets.pop(ws.uid, None) if old_ws is not None: self.server.remove_subscription(old_ws) - logging.info(f"Websocket Removed: {ws.uid}") + logging.debug(f"Websocket Removed: {ws.uid}") if self.closed_event is not None and not self.websockets: self.closed_event.set() @@ -371,7 +371,7 @@ class WebsocketManager(APITransport): return self.closed_event = asyncio.Event() for ws in list(self.websockets.values()): - ws.close() + ws.close(1001, "Server Shutdown") try: await asyncio.wait_for(self.closed_event.wait(), 2.) except asyncio.TimeoutError: @@ -389,14 +389,21 @@ class WebSocket(WebSocketHandler, Subscribable): self.ip_addr: str = self.request.remote_ip self.queue_busy: bool = False self.message_buf: List[Union[str, Dict[str, Any]]] = [] + self.last_pong_time: float = self.event_loop.get_loop_time() def open(self, *args, **kwargs) -> None: self.set_nodelay(True) + agent = self.request.headers.get("User-Agent", "") + logging.info(f"Websocket Opened: ID: {self.uid}, " + f"User Agent: {agent}") self.wsm.add_websocket(self) def on_message(self, message: Union[bytes, str]) -> None: self.event_loop.register_callback(self._process_message, message) + def on_pong(self, data: bytes) -> None: + self.last_pong_time = self.event_loop.get_loop_time() + async def _process_message(self, message: str) -> None: try: response = await self.rpc.dispatch(message, self) @@ -445,6 +452,12 @@ class WebSocket(WebSocketHandler, Subscribable): def on_close(self) -> None: self.is_closed = True self.message_buf = [] + now = self.event_loop.get_loop_time() + pong_elapsed = now - self.last_pong_time + logging.info(f"Websocket Closed: ID: {self.uid} " + f"Close Code: {self.close_code}, " + f"Close Reason: {self.close_reason}, " + f"Pong Time Elapsed: {pong_elapsed:.2f}") self.wsm.remove_websocket(self) def check_origin(self, origin: str) -> bool: