From f6840a777c5a90e0ff1f16e90410aec8b840f6be Mon Sep 17 00:00:00 2001 From: cottongin Date: Thu, 12 Mar 2026 07:55:04 -0400 Subject: [PATCH] chore: add verbose WS logging to both bot plugins Log each phase: thread start, TCP connect, subscribe sent, message received (type), status updates with client list, connection closed reasons, connection refused/timeout as distinct warnings. Made-with: Cursor --- plugins/limnoria/NtrPlaylist/plugin.py | 24 +++++++++++++++++++++--- plugins/sopel/ntr_playlist.py | 24 +++++++++++++++++++++--- 2 files changed, 42 insertions(+), 6 deletions(-) diff --git a/plugins/limnoria/NtrPlaylist/plugin.py b/plugins/limnoria/NtrPlaylist/plugin.py index f32a93c..f29dd3b 100644 --- a/plugins/limnoria/NtrPlaylist/plugin.py +++ b/plugins/limnoria/NtrPlaylist/plugin.py @@ -139,6 +139,7 @@ class NtrPlaylist(callbacks.Plugin): backoff = 5 max_backoff = 60 + LOGGER.info("WS listener thread started") while not self._ws_stop.is_set(): ws_url = self.registryValue("wsUrl") @@ -151,17 +152,20 @@ class NtrPlaylist(callbacks.Plugin): self._ws_stop.wait(30) continue + LOGGER.info("Connecting to %s as client_id=%s", ws_url, client_id) ws = None try: ws = websocket.WebSocket() ws.connect(ws_url, timeout=10) - ws.send(json.dumps({ + LOGGER.info("WebSocket TCP connection established") + subscribe_msg = { "type": "subscribe", "token": token, "role": "bot", "client_id": client_id, - })) - LOGGER.info("Connected to announce WebSocket at %s", ws_url) + } + ws.send(json.dumps(subscribe_msg)) + LOGGER.info("Sent subscribe message (role=bot, client_id=%s)", client_id) backoff = 5 while not self._ws_stop.is_set(): @@ -169,22 +173,36 @@ class NtrPlaylist(callbacks.Plugin): try: raw = ws.recv() if not raw: + LOGGER.warning("Received empty message, connection closing") break data = json.loads(raw) + LOGGER.debug("Received WS message: type=%s", data.get("type")) if data.get("type") == "announce" and "message" in data: msg = ircmsgs.privmsg(channel, data["message"]) self._irc.queueMsg(msg) LOGGER.info("Announced to %s: %s", channel, data["message"]) + elif data.get("type") == "status": + LOGGER.info( + "Status update: %d bot(s) connected, clients=%s", + data.get("subscribers", 0), + [c.get("client_id") for c in data.get("clients", [])], + ) except websocket.WebSocketTimeoutException: continue except websocket.WebSocketConnectionClosedException: + LOGGER.warning("WebSocket connection closed by server") break + except ConnectionRefusedError: + LOGGER.warning("Connection refused at %s", ws_url) + except TimeoutError: + LOGGER.warning("Connection timed out to %s", ws_url) except Exception: LOGGER.exception("WS listener error") finally: if ws: try: ws.close() + LOGGER.debug("WebSocket closed cleanly") except Exception: pass diff --git a/plugins/sopel/ntr_playlist.py b/plugins/sopel/ntr_playlist.py index 368d66b..c6b94fe 100644 --- a/plugins/sopel/ntr_playlist.py +++ b/plugins/sopel/ntr_playlist.py @@ -50,6 +50,7 @@ def _ws_listener(bot): backoff = 5 max_backoff = 60 + LOGGER.info("WS listener thread started") while not _ws_stop.is_set(): ws_url = bot.settings.ntr_playlist.ws_url @@ -62,17 +63,20 @@ def _ws_listener(bot): _ws_stop.wait(30) continue + LOGGER.info("Connecting to %s as client_id=%s", ws_url, client_id) ws = None try: ws = websocket.WebSocket() ws.connect(ws_url, timeout=10) - ws.send(json.dumps({ + LOGGER.info("WebSocket TCP connection established") + subscribe_msg = { "type": "subscribe", "token": token, "role": "bot", "client_id": client_id, - })) - LOGGER.info("Connected to announce WebSocket at %s", ws_url) + } + ws.send(json.dumps(subscribe_msg)) + LOGGER.info("Sent subscribe message (role=bot, client_id=%s)", client_id) backoff = 5 while not _ws_stop.is_set(): @@ -80,21 +84,35 @@ def _ws_listener(bot): try: raw = ws.recv() if not raw: + LOGGER.warning("Received empty message, connection closing") break data = json.loads(raw) + LOGGER.debug("Received WS message: type=%s", data.get("type")) if data.get("type") == "announce" and "message" in data: bot.say(data["message"], channel) LOGGER.info("Announced to %s: %s", channel, data["message"]) + elif data.get("type") == "status": + LOGGER.info( + "Status update: %d bot(s) connected, clients=%s", + data.get("subscribers", 0), + [c.get("client_id") for c in data.get("clients", [])], + ) except websocket.WebSocketTimeoutException: continue except websocket.WebSocketConnectionClosedException: + LOGGER.warning("WebSocket connection closed by server") break + except ConnectionRefusedError: + LOGGER.warning("Connection refused at %s", ws_url) + except TimeoutError: + LOGGER.warning("Connection timed out to %s", ws_url) except Exception: LOGGER.exception("WS listener error") finally: if ws: try: ws.close() + LOGGER.debug("WebSocket closed cleanly") except Exception: pass