Add logging

3 files changed, 34 insertions, 2 deletions

diff --git a/src/petthecord/bot.py b/src/petthecord/bot.py
index 666c336..a7e08e3 100644
--- a/src/petthecord/bot.py
+++ b/src/petthecord/bot.py
@@ -1,3 +1,5 @@
+from logging import getLogger
+
 from aiohttp.web import AppRunner, TCPSite
 from discord import app_commands, Interaction, Intents, User
 from discord.ext import commands
@@ -10,6 +12,10 @@ class PatTheCordCog(commands.Cog):
         self.client = client
         self.origin = origin
 
+        super().__init__()
+
+        self._logger = getLogger("petthecord.bot")
+
     @app_commands.allowed_installs(users=True)
     @app_commands.allowed_contexts(guilds=True, dms=True, private_channels=True)
     @app_commands.command(
@@ -27,6 +33,7 @@ class PatTheCordCog(commands.Cog):
         user: User,
         r: str = ""
     ) -> None:
+        self._logger.info(f"Petting {user.id} for {interaction.user.id}")
         await interaction.response.send_message(f"{self.origin}/{user.id}.{r}.gif")
 
 
@@ -54,6 +61,8 @@ class Bot(commands.Bot):
         self._cache_lifetime = cache_lifetime
         self._cache_gc_delay = cache_gc_delay
 
+        self._logger = getLogger("petthecord")
+
     async def on_ready(self) -> None:
         await self.add_cog(PatTheCordCog(self, self._origin))
         await self.tree.sync()
@@ -70,5 +79,7 @@ class Bot(commands.Bot):
         site = TCPSite(runner, self._host, self._port)
         await site.start()
 
+        getLogger("petthecord.server").info(f"Started serving on {self._host}:{self._port}")
+
         if self._caching:
             await server.clean_cache()
diff --git a/src/petthecord/main.py b/src/petthecord/main.py
index a1bc1a6..f85d473 100644
--- a/src/petthecord/main.py
+++ b/src/petthecord/main.py
@@ -1,4 +1,5 @@
 from argparse import ArgumentParser
+from logging import Formatter, StreamHandler, Logger, getLogger
 from os import getenv
 from sys import argv, stderr
 
@@ -57,6 +58,14 @@ def main() -> None:
     )
     args = parser.parse_args()
 
+    # logger = getLogger()
+    # handler = StreamHandler()
+    # handler.setFormatter(
+    #     Formatter("[{asctime}] [{levelname:<8}] {name}: {message}", '%Y-%m-%d %H:%M:%S', style="{")
+    # )
+    # logger.addHandler(handler)
+    # logger.log(1, "Hello!")
+
     bot = Bot(
         args.host,
         args.port,
@@ -67,10 +76,10 @@ def main() -> None:
         args.cache_gc_delay
     )
     if (token := getenv("PETTHECORD_TOKEN")) is not None:
-        bot.run(token)
+        bot.run(token, root_logger=True)
     elif (token_path := getenv("PETTHECORD_TOKEN_FILE")) is not None:
         with open(token_path) as f:
             token = f.read()
-        bot.run(token)
+        bot.run(token, root_logger=True)
     else:
         print(f"{argv[0]}: Neither PETTHECORD_TOKEN nor PETTHECORD_TOKEN_FILE are set", file=stderr)
diff --git a/src/petthecord/server.py b/src/petthecord/server.py
index d5e31b1..47f449f 100644
--- a/src/petthecord/server.py
+++ b/src/petthecord/server.py
@@ -1,6 +1,7 @@
 from asyncio import sleep
 from json import load, dumps
 from io import BytesIO
+from logging import getLogger
 from os import listdir, remove
 from os.path import getmtime
 from pathlib import Path
@@ -30,9 +31,13 @@ class Server(Application):
         self.cache_gc_delay = cache_gc_delay
         super().__init__()
 
+        self._logger = getLogger("petthecord.server")
+        self._cache_logger = getLogger("petthecord.cache")
+
         if self.caching:
             index_path = self.cache_path / "index.json"
             if not index_path.exists():
+                self._cache_logger.warning("Cache's index.json doesn't exist, creating...")
                 with open(index_path, "w") as f:
                     f.write("{}")
 
@@ -50,6 +55,7 @@ class Server(Application):
         raise HTTPFound("https://github.com/nakidai/petthecord")
 
     async def petpet(self, request: Request) -> StreamResponse:
+        self._logger.info(f"Incoming '{request.rel_url}' request from {request.remote}")
         try:
             uid = int(request.match_info["uid"][:request.match_info["uid"].find('.')])
         except ValueError:
@@ -68,6 +74,7 @@ class Server(Application):
         avatar_path = str(self.cache_path / f"{user.id}_{user.avatar.key}.gif")
         if self.caching:
             if (path := self.cache.get(user.id)) != avatar_path:
+                self._cache_logger.debug("Regenerating cached avatar {user.id}")
                 if path:
                     remove(path)
                 self.cache[user.id] = avatar_path
@@ -93,13 +100,18 @@ class Server(Application):
                 return Response(body=f.read(), content_type="image/gif")
 
     async def clean_cache(self) -> None:
+        self._cache_logger.info("Starting new cache's gc iteration")
+
         for filename in listdir(self.cache_path):
             path = (self.cache_path / filename)
             if path.is_file() and filename != "index.json":
                 if (time() - getmtime(path) > self.cache_lifetime):
+                    self._cache_logger.debug(f"Removing {filename}")
                     del self.cache[filename.split('_')[0]]
                     remove(path)
         with open(self.cache_path / "index.json", "w") as f:
             f.write(dumps(self.cache))
 
+        self._cache_logger.debug("Finished collecting old cache")
+
         await sleep(self.cache_gc_delay)