From 46cd20ac746d0e2bf085429f37c7f409a10312f6 Mon Sep 17 00:00:00 2001 From: Joscha Date: Sun, 29 Jul 2018 12:20:40 +0000 Subject: [PATCH] Log more stuff --- examplebot.py | 12 ++++++++---- yaboli/connection.py | 7 ++++--- yaboli/cookiejar.py | 7 ++++--- yaboli/room.py | 17 +++++++++++++++-- 4 files changed, 31 insertions(+), 12 deletions(-) diff --git a/examplebot.py b/examplebot.py index 7d355f5..83f3b7a 100644 --- a/examplebot.py +++ b/examplebot.py @@ -1,14 +1,15 @@ import asyncio import logging -# Turn all debugging on -asyncio.get_event_loop().set_debug(True) -logging.basicConfig(level=logging.DEBUG) - import yaboli from yaboli.utils import * from join_rooms import join_rooms # List of rooms kept in separate file, which is .gitignore'd +# Turn all debugging on +asyncio.get_event_loop().set_debug(True) +logging.getLogger("asyncio").setLevel(logging.INFO) +logging.getLogger("yaboli").setLevel(logging.DEBUG) + class ExampleBot(yaboli.Bot): async def send(self, room, message): @@ -26,6 +27,9 @@ class ExampleBot(yaboli.Bot): await self.botrulez_uptime(room, message) await self.botrulez_kill(room, message, text="/me dies spectacularly") await self.botrulez_restart(room, message, text="/me restarts spectacularly") + + if message.content == "!!!": + await room._connection._ws.close() forward = send # should work without modifications for most bots diff --git a/yaboli/connection.py b/yaboli/connection.py index 97a6bae..c0bb174 100644 --- a/yaboli/connection.py +++ b/yaboli/connection.py @@ -154,6 +154,7 @@ class Connection: while not self._stopped: await self._connect(self.reconnect_attempts) + logger.debug(f"{self.url}:Connected") try: while True: @@ -170,13 +171,13 @@ class Connection: try: while True: - logger.debug("Pinging...") + logger.debug(f"{self.url}:Pinging...") wait_for_reply = await self._ws.ping() await asyncio.wait_for(wait_for_reply, self.ping_timeout) - logger.debug("Pinged!") + logger.debug(f"{self.url}:Pinged!") await asyncio.sleep(self.ping_delay) except asyncio.TimeoutError: - logger.warning("Ping timed out.") + logger.warning(f"{self.url}:Ping timed out") await self.reconnect() except (websockets.ConnectionClosed, ConnectionResetError, asyncio.CancelledError): pass diff --git a/yaboli/cookiejar.py b/yaboli/cookiejar.py index ac4f3bf..8b3a073 100644 --- a/yaboli/cookiejar.py +++ b/yaboli/cookiejar.py @@ -17,10 +17,11 @@ class CookieJar: self._cookies = cookies.SimpleCookie() if not self._filename: - logger.info("Could not load cookies, no filename given.") + logger.warning("Could not load cookies, no filename given.") return with contextlib.suppress(FileNotFoundError): + logger.info(f"Loading cookies from {self._filename!r}") with open(self._filename, "r") as f: for line in f: self._cookies.load(line) @@ -50,10 +51,10 @@ class CookieJar: """ if not self._filename: - logger.info("Could not save cookies, no filename given.") + logger.warning("Could not save cookies, no filename given.") return - logger.debug(f"Saving cookies to {self._filename!r}") + logger.info(f"Saving cookies to {self._filename!r}") with open(self._filename, "w") as f: for morsel in self._cookies.values(): diff --git a/yaboli/room.py b/yaboli/room.py index d193e8f..7dde973 100644 --- a/yaboli/room.py +++ b/yaboli/room.py @@ -161,6 +161,7 @@ class Room: async def _disconnected(self): # While disconnected, keep the last known session info, listing etc. # All of this is instead reset when the hello/snapshot events are received. + logger.warn(f"&{self.roomname}:Lost connection.") self.status = Room.DISCONNECTED self._connected_future = asyncio.Future() @@ -193,6 +194,7 @@ class Room: await function(data) async def _event_bounce(self, data): + logger.info(f"&{self.roomname}:Received bounce-event") if self.password is not None: try: data = {"type": passcode, "passcode": self.password} @@ -201,10 +203,14 @@ class Room: success = rdata.get("success") if not success: reason = rdata.get("reason") - raise AuthenticationRequired(f"Could not join &{self.roomname}: {reason}") + logger.warn(f"&{self.roomname}:Authentication failed: {reason}") + raise AuthenticationRequired(f"Could not join &{self.roomname}:{reason}") + else: + logger.info(f"&{self.roomname}:Authentication successful") except ConnectionClosed: pass else: + logger.warn(f"&{self.roomname}:Could not authenticate: Password unknown") raise AuthenticationRequired(f"&{self.roomname} is password locked but no password was given") async def _event_hello(self, data): @@ -225,6 +231,7 @@ class Room: async def _event_network(self, data): server_id = data.get("server_id") server_era = data.get("server_era") + logger.debug(f"&{self.roomname}:Received network-event: server_id: {server_id!r}, server_era: {server_era!r}") sessions = self.listing.remove_combo(server_id, server_era) for session in sessions: @@ -266,6 +273,7 @@ class Room: message = Message.from_dict(data) if self._status == Room.FORWARDING: + logger.info(f"&{self.roomname}:Received new message while forwarding, adding to queue") self._forward_new.append(message) else: self._last_known_mid = message.mid @@ -274,6 +282,7 @@ class Room: # TODO: Figure out a way to bring fast-forwarding into this async def _event_snapshot(self, data): + logger.debug(f"&{self.roomname}:Received snapshot-event, gained access to the room") log = [Message.from_dict(m) for m in data.get("log")] sessions = [Session.from_dict(d) for d in data.get("listing")] @@ -290,6 +299,7 @@ class Room: # Make sure a room is not CONNECTED without a nick if self.target_nick and self.target_nick != self.session.nick: + logger.info(f"&{self.roomname}:Current nick doesn't match target nick {self.target_nick!r}, changing nick") try: _, nick_data, _, _ = await self._connection.send("nick", data={"name": self.target_nick}) self.session.nick = nick_data.get("to") @@ -298,10 +308,12 @@ class Room: # Now, we're finally connected again! if self._last_known_mid is None: + logger.info(f"&{self.roomname}:Fully connected") self._status = Room.CONNECTED if log: # log goes from old to new self._last_known_mid = log[-1].mid else: + logger.info(f"&{self.roomname}:Not fully connected yet, starting message rewinding") self._status = Room.FORWARDING self._forward_new = [] @@ -313,7 +325,6 @@ class Room: self._connected_future.set_result(None) # Let's let the inhabitant know. - logger.debug("Letting inhabitant know") await self._inhabitant.connected(self, log) # TODO: Figure out a way to bring fast-forwarding into this @@ -354,6 +365,7 @@ class Room: log = await self.log(100, before=log[0].mid) + logger.info(f"&{self.roomname}:Reached last known message, forwarding through messages") for message in reversed(old_messages): self._last_known_mid = message.mid asyncio.ensure_future(self._inhabitant.forward(self, message)) @@ -361,6 +373,7 @@ class Room: self._last_known_mid = message.mid asyncio.ensure_future(self._inhabitant.forward(self, message)) + logger.info(f"&{self.roomname}:Forwarding complete, fully connected") self._forward_new = [] self._status = Room.CONNECTED