Add logging for moderation functions

4 files changed, 81 insertions, 9 deletions

diff --git a/bot/cogs/moderation/scheduler.py b/bot/cogs/moderation/scheduler.py
index 7990df226..7a08fc236 100644
--- a/bot/cogs/moderation/scheduler.py
+++ b/bot/cogs/moderation/scheduler.py
@@ -39,6 +39,8 @@ class InfractionScheduler(Scheduler):
         """Schedule expiration for previous infractions."""
         await self.bot.wait_until_ready()
 
+        log.trace(f"Rescheduling infractions for {self.__class__.__name__}.")
+
         infractions = await self.bot.api_client.get(
             'bot/infractions',
             params={'active': 'true'}
@@ -59,6 +61,10 @@ class InfractionScheduler(Scheduler):
 
         # Mark as inactive if less than a minute remains.
         if delta < 60:
+            log.info(
+                "Infraction will be deactivated instead of re-applied "
+                "because less than 1 minute remains."
+            )
             await self.deactivate_infraction(infraction)
             return
 
@@ -78,6 +84,9 @@ class InfractionScheduler(Scheduler):
         icon = utils.INFRACTION_ICONS[infr_type][0]
         reason = infraction["reason"]
         expiry = infraction["expires_at"]
+        _id = infraction['id']
+
+        log.trace(f"Applying {infr_type} infraction #{_id} to {user}.")
 
         if expiry:
             expiry = time.format_infraction(expiry)
@@ -111,10 +120,20 @@ class InfractionScheduler(Scheduler):
                 log_content = ctx.author.mention
 
         if infraction["actor"] == self.bot.user.id:
+            log.trace(
+                f"Infraction #{_id} actor is bot; including the reason in the confirmation message."
+            )
+
             end_msg = f" (reason: {infraction['reason']})"
         elif ctx.channel.id not in STAFF_CHANNELS:
+            log.trace(
+                f"Infraction #{_id} context is not in a staff channel; omitting infraction count."
+            )
+
             end_msg = ""
         else:
+            log.trace(f"Fetching total infraction count for {user}.")
+
             infractions = await self.bot.api_client.get(
                 "bot/infractions",
                 params={"user__id": str(user.id)}
@@ -124,6 +143,7 @@ class InfractionScheduler(Scheduler):
 
         # Execute the necessary actions to apply the infraction on Discord.
         if action_coro:
+            log.trace(f"Awaiting the infraction #{_id} application action coroutine.")
             try:
                 await action_coro
                 if expiry:
@@ -136,12 +156,16 @@ class InfractionScheduler(Scheduler):
                 log_content = ctx.author.mention
                 log_title = "failed to apply"
 
+                log.warning(f"Failed to apply {infr_type} infraction #{_id} to {user}.")
+
         # Send a confirmation message to the invoking context.
+        log.trace(f"Sending infraction #{_id} confirmation message.")
         await ctx.send(
             f"{dm_result}{confirm_msg} **{infr_type}** to {user.mention}{expiry_msg}{end_msg}."
         )
 
         # Send a log message to the mod log.
+        log.trace(f"Sending apply mod log for infraction #{_id}.")
         await self.mod_log.send_log_message(
             icon_url=icon,
             colour=Colours.soft_red,
@@ -157,9 +181,14 @@ class InfractionScheduler(Scheduler):
             footer=f"ID {infraction['id']}"
         )
 
+        log.info(f"Applied {infr_type} infraction #{_id} to {user}.")
+
     async def pardon_infraction(self, ctx: Context, infr_type: str, user: MemberObject) -> None:
         """Prematurely end an infraction for a user and log the action in the mod log."""
+        log.trace(f"Pardoning {infr_type} infraction for {user}.")
+
         # Check the current active infraction
+        log.trace(f"Fetching active {infr_type} infractions for {user}.")
         response = await self.bot.api_client.get(
             'bot/infractions',
             params={
@@ -170,6 +199,7 @@ class InfractionScheduler(Scheduler):
         )
 
         if not response:
+            log.debug(f"No active {infr_type} infraction found for {user}.")
             await ctx.send(f":x: There's no active {infr_type} infraction for user {user.mention}.")
             return
 
@@ -179,12 +209,16 @@ class InfractionScheduler(Scheduler):
         log_text["Member"] = f"{user.mention}(`{user.id}`)"
         log_text["Actor"] = str(ctx.message.author)
         log_content = None
-        footer = f"ID: {response[0]['id']}"
+        _id = response[0]['id']
+        footer = f"ID: {_id}"
 
         # If multiple active infractions were found, mark them as inactive in the database
         # and cancel their expiration tasks.
         if len(response) > 1:
-            log.warning(f"Found more than one active {infr_type} infraction for user {user.id}")
+            log.warning(
+                f"Found more than one active {infr_type} infraction for user {user.id}; "
+                "deactivating the extra active infractions too."
+            )
 
             footer = f"Infraction IDs: {', '.join(str(infr['id']) for infr in response)}"
 
@@ -227,11 +261,16 @@ class InfractionScheduler(Scheduler):
             confirm_msg = ":x: failed to pardon"
             log_title = "pardon failed"
             log_content = ctx.author.mention
+
+            log.warning(f"Failed to pardon {infr_type} infraction #{_id} for {user}.")
         else:
             confirm_msg = f":ok_hand: pardoned"
             log_title = "pardoned"
 
+            log.info(f"Pardoned {infr_type} infraction #{_id} for {user}.")
+
         # Send a confirmation message to the invoking context.
+        log.trace(f"Sending infraction #{_id} pardon confirmation message.")
         await ctx.send(
             f"{dm_emoji}{confirm_msg} infraction **{infr_type}** for {user.mention}. "
             f"{log_text.get('Failure', '')}"
@@ -268,7 +307,7 @@ class InfractionScheduler(Scheduler):
         _type = infraction["type"]
         _id = infraction["id"]
 
-        log.debug(f"Marking infraction #{_id} as inactive (expired).")
+        log.info(f"Marking infraction #{_id} as inactive (expired).")
 
         log_content = None
         log_text = {
@@ -278,7 +317,9 @@ class InfractionScheduler(Scheduler):
         }
 
         try:
+            log.trace("Awaiting the pardon action coroutine.")
             returned_log = await self._pardon_action(infraction)
+
             if returned_log is not None:
                 log_text = {**log_text, **returned_log}  # Merge the logs together
             else:
@@ -296,6 +337,8 @@ class InfractionScheduler(Scheduler):
 
         # Check if the user is currently being watched by Big Brother.
         try:
+            log.trace(f"Determining if user {user_id} is currently being watched by Big Brother.")
+
             active_watch = await self.bot.api_client.get(
                 "bot/infractions",
                 params={
@@ -312,6 +355,7 @@ class InfractionScheduler(Scheduler):
 
         try:
             # Mark infraction as inactive in the database.
+            log.trace(f"Marking infraction #{_id} as inactive in the database.")
             await self.bot.api_client.patch(
                 f"bot/infractions/{_id}",
                 json={"active": False}
@@ -335,6 +379,7 @@ class InfractionScheduler(Scheduler):
         if send_log:
             log_title = f"expiration failed" if "Failure" in log_text else "expired"
 
+            log.trace(f"Sending deactivation mod log for infraction #{_id}.")
             await self.mod_log.send_log_message(
                 icon_url=utils.INFRACTION_ICONS[_type][1],
                 colour=Colours.soft_green,
diff --git a/bot/cogs/moderation/superstarify.py b/bot/cogs/moderation/superstarify.py
index c66222e5a..9ab870823 100644
--- a/bot/cogs/moderation/superstarify.py
+++ b/bot/cogs/moderation/superstarify.py
@@ -34,8 +34,8 @@ class Superstarify(InfractionScheduler, Cog):
             return  # User didn't change their nickname. Abort!
 
         log.trace(
-            f"{before.display_name} is trying to change their nickname to {after.display_name}. "
-            "Checking if the user is in superstar-prison..."
+            f"{before} ({before.display_name}) is trying to change their nickname to "
+            f"{after.display_name}. Checking if the user is in superstar-prison..."
         )
 
         active_superstarifies = await self.bot.api_client.get(
@@ -48,6 +48,7 @@ class Superstarify(InfractionScheduler, Cog):
         )
 
         if not active_superstarifies:
+            log.trace(f"{before} has no active superstar infractions.")
             return
 
         infraction = active_superstarifies[0]
@@ -132,15 +133,17 @@ class Superstarify(InfractionScheduler, Cog):
         # Post the infraction to the API
         reason = reason or f"old nick: {member.display_name}"
         infraction = await utils.post_infraction(ctx, member, "superstar", reason, duration)
+        _id = infraction["id"]
 
         old_nick = member.display_name
-        forced_nick = self.get_nick(infraction["id"], member.id)
+        forced_nick = self.get_nick(_id, member.id)
         expiry_str = format_infraction(infraction["expires_at"])
 
         # Apply the infraction and schedule the expiration task.
+        log.debug(f"Changing nickname of {member} to {forced_nick}.")
         self.mod_log.ignore(constants.Event.member_update, member.id)
         await member.edit(nick=forced_nick, reason=reason)
-        self.schedule_task(ctx.bot.loop, infraction["id"], infraction)
+        self.schedule_task(ctx.bot.loop, _id, infraction)
 
         # Send a DM to the user to notify them of their new infraction.
         await utils.notify_infraction(
@@ -152,6 +155,7 @@ class Superstarify(InfractionScheduler, Cog):
         )
 
         # Send an embed with the infraction information to the invoking context.
+        log.trace(f"Sending superstar #{_id} embed.")
         embed = Embed(
             title="Congratulations!",
             colour=constants.Colours.soft_orange,
@@ -167,6 +171,7 @@ class Superstarify(InfractionScheduler, Cog):
         await ctx.send(embed=embed)
 
         # Log to the mod log channel.
+        log.trace(f"Sending apply mod log for superstar #{_id}.")
         await self.mod_log.send_log_message(
             icon_url=utils.INFRACTION_ICONS["superstar"][0],
             colour=Colour.gold(),
@@ -180,7 +185,7 @@ class Superstarify(InfractionScheduler, Cog):
                 Old nickname: `{old_nick}`
                 New nickname: `{forced_nick}`
             """),
-            footer=f"ID {infraction['id']}"
+            footer=f"ID {_id}"
         )
 
     @command(name="unsuperstarify", aliases=("release_nick", "unstar"))
@@ -198,6 +203,10 @@ class Superstarify(InfractionScheduler, Cog):
 
         # Don't bother sending a notification if the user left the guild.
         if not user:
+            log.debug(
+                "User left the guild and therefore won't be notified about superstar "
+                f"{infraction['id']} pardon."
+            )
             return {}
 
         # DM the user about the expiration.
@@ -216,6 +225,8 @@ class Superstarify(InfractionScheduler, Cog):
     @staticmethod
     def get_nick(infraction_id: int, member_id: int) -> str:
         """Randomly select a nickname from the Superstarify nickname list."""
+        log.trace(f"Choosing a random nickname for superstar #{infraction_id}.")
+
         rng = random.Random(str(infraction_id) + str(member_id))
         return rng.choice(STAR_NAMES)
 
diff --git a/bot/cogs/moderation/utils.py b/bot/cogs/moderation/utils.py
index 9179c0afb..325b9567a 100644
--- a/bot/cogs/moderation/utils.py
+++ b/bot/cogs/moderation/utils.py
@@ -37,6 +37,8 @@ def proxy_user(user_id: str) -> discord.Object:
 
     Used when a Member or User object cannot be resolved.
     """
+    log.trace(f"Attempting to create a proxy user for the user id {user_id}.")
+
     try:
         user_id = int(user_id)
     except ValueError:
@@ -59,6 +61,8 @@ async def post_infraction(
     active: bool = True,
 ) -> t.Optional[dict]:
     """Posts an infraction to the API."""
+    log.trace(f"Posting {infr_type} infraction for {user} to the API.")
+
     payload = {
         "actor": ctx.message.author.id,
         "hidden": hidden,
@@ -92,6 +96,8 @@ async def post_infraction(
 
 async def has_active_infraction(ctx: Context, user: MemberObject, infr_type: str) -> bool:
     """Checks if a user already has an active infraction of the given type."""
+    log.trace(f"Checking if {user} has active infractions of type {infr_type}.")
+
     active_infractions = await ctx.bot.api_client.get(
         'bot/infractions',
         params={
@@ -101,12 +107,14 @@ async def has_active_infraction(ctx: Context, user: MemberObject, infr_type: str
         }
     )
     if active_infractions:
+        log.trace(f"{user} has active infractions of type {infr_type}.")
         await ctx.send(
             f":x: According to my records, this user already has a {infr_type} infraction. "
             f"See infraction **#{active_infractions[0]['id']}**."
         )
         return True
     else:
+        log.trace(f"{user} does not have active infractions of type {infr_type}.")
         return False
 
 
@@ -118,6 +126,8 @@ async def notify_infraction(
     icon_url: str = Icons.token_removed
 ) -> bool:
     """DM a user about their new infraction and return True if the DM is successful."""
+    log.trace(f"Sending {user} a DM about their {infr_type} infraction.")
+
     embed = discord.Embed(
         description=textwrap.dedent(f"""
             **Type:** {infr_type.capitalize()}
@@ -146,6 +156,8 @@ async def notify_pardon(
     icon_url: str = Icons.user_verified
 ) -> bool:
     """DM a user about their pardoned infraction and return True if the DM is successful."""
+    log.trace(f"Sending {user} a DM about their pardoned infraction.")
+
     embed = discord.Embed(
         description=content,
         colour=Colours.soft_green
diff --git a/bot/utils/scheduling.py b/bot/utils/scheduling.py
index 08abd91d7..ee6c0a8e6 100644
--- a/bot/utils/scheduling.py
+++ b/bot/utils/scheduling.py
@@ -36,11 +36,15 @@ class Scheduler(metaclass=CogABCMeta):
         `task_data` is passed to `Scheduler._scheduled_expiration`
         """
         if task_id in self.scheduled_tasks:
+            log.debug(
+                f"{self.cog_name}: did not schedule task #{task_id}; task was already scheduled."
+            )
             return
 
         task: asyncio.Task = create_task(loop, self._scheduled_task(task_data))
 
         self.scheduled_tasks[task_id] = task
+        log.debug(f"{self.cog_name}: scheduled task #{task_id}.")
 
     def cancel_task(self, task_id: str) -> None:
         """Un-schedules a task."""
@@ -51,7 +55,7 @@ class Scheduler(metaclass=CogABCMeta):
             return
 
         task.cancel()
-        log.debug(f"{self.cog_name}: Unscheduled {task_id}.")
+        log.debug(f"{self.cog_name}: unscheduled task #{task_id}.")
         del self.scheduled_tasks[task_id]