improve logging in notifications, add logging to utils

nomen/main.py

@@ -23,7 +23,7 @@ logger_disnake.setLevel(logging.WARNING)
 log = logging.getLogger("nomen")
 log.setLevel(logging.DEBUG)
 
-formatter = logging.Formatter("%(asctime)s:%(levelname)s:%(name)s: %(message)s")
+formatter = logging.Formatter("{asctime} {levelname:8} {name}: {message}", "%Y-%m-%d %H:%M:%S", "{")
 handler = logging.StreamHandler(sys.stdout)
 handler.setFormatter(formatter)
 logging.getLogger(None).addHandler(handler)

nomen/notifications.py

@@ -8,7 +8,16 @@ from disnake.ext.commands import Cog, group, guild_only
 from .utils import can_view, confirm, fetch_unpacked, test_keyword
 
 log = logging.getLogger("nomen.notifications")
-log.setLevel(logging.INFO)
+log.setLevel(logging.DEBUG)
+log_ = log
+
+
+class NotifierLogAdapter(logging.LoggerAdapter):
+    def process(self, msg, kwargs):
+        return (
+            f"[guild: {self.extra["guild"]}, user: {self.extra["user"]}, keyword: {self.extra["keyword"]}] {msg}",
+            kwargs,
+        )
 
 
 async def handle_notification(db_updates, ctx, message, keyword, user_id, use_embed):
@@ -16,21 +25,24 @@ async def handle_notification(db_updates, ctx, message, keyword, user_id, use_em
     Async task to dispatch a notification
     """
 
-    log.debug(f"- Handling `{keyword}` for {user_id}")
-
     member = await ctx.guild.getch_member(user_id)
 
+    log = NotifierLogAdapter(log_.getChild("notifier"), {"guild": ctx.guild, "user": member, "keyword": keyword})
+
+    log.debug("Handling notification")
+
     if not await can_view(ctx, member):
-        log.debug(f"- - Missing permission {user_id}")
+        log.debug("Missing permission")
         return
 
-    log.debug(f"- - Notifying {user_id}")
+    log.debug("Notifying")
     db_updates.append((ctx.guild.id, keyword, user_id))
 
     header = f"🔔 `{message.author.display_name}` mentioned `{keyword}` on `{ctx.guild}`:"
     footer = f"\n<t:{int(message.created_at.timestamp())}:R> | [Show]({message.jump_url}) | <#{ctx.channel.id}>"
 
     if use_embed:
+        log.debug("Sending embed")
         embed = Embed(description=message.content + "\n" + footer)
         embed.set_author(
             name=f"{message.author.display_name} ({message.author})",
@@ -39,14 +51,19 @@ async def handle_notification(db_updates, ctx, message, keyword, user_id, use_em
 
         await member.send(header, embed=embed)
     else:
+        log.debug("Sending plain message")
         await member.send("\n".join((header, indent(message.content, "> ", lambda line: True).strip(), footer)))
 
+    log.debug("Sent")
+
 
 async def handle_triggers(ctx, message):
     """
     Main function that handles message triggers
     """
 
+    log.debug(f"Handling triggers for '{message.content}' from {ctx.author}")
+
     params = {
         "author": ctx.author.id,
         "channel": ctx.channel.id,
@@ -93,6 +110,7 @@ async def handle_triggers(ctx, message):
 
                 tg.create_task(handle_notification(db_updates, ctx, message, keyword, user_id, use_embed))
 
+    log.debug("Incrementing notification counts")
     await ctx.bot.db.executemany(
         "UPDATE keywords SET count = count + 1 WHERE guild_id=? AND keyword=? AND user_id=?",
         db_updates,

nomen/utils.py

@@ -1,9 +1,12 @@
+import logging
 from asyncio import TimeoutError
 from itertools import chain
 
 import re2 as re
 from disnake import ChannelType
 
+log = logging.getLogger("nomen.utils")
+
 ALPHABET = list("abcdefghijklmnopqrstuvwxyz ")
 
 COMMON_WORDS = [