Log more stuff

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):
@@ -27,6 +28,9 @@ class ExampleBot(yaboli.Bot):
 		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
 
 def main():

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

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():

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