Code block: add trace logging

3 files changed, 48 insertions, 6 deletions

diff --git a/bot/cogs/codeblock/cog.py b/bot/cogs/codeblock/cog.py
index 19ddb8c73..e4b87938d 100644
--- a/bot/cogs/codeblock/cog.py
+++ b/bot/cogs/codeblock/cog.py
@@ -35,6 +35,7 @@ class CodeBlockCog(Cog, name="Code Block"):
     @staticmethod
     def is_help_channel(channel: discord.TextChannel) -> bool:
         """Return True if `channel` is in one of the help categories."""
+        log.trace(f"Checking if #{channel} is a help channel.")
         return (
             getattr(channel, "category", None)
             and channel.category.id in (Categories.help_available, Categories.help_in_use)
@@ -46,10 +47,12 @@ class CodeBlockCog(Cog, name="Code Block"):
 
         Note: only channels in the `channel_cooldowns` have cooldowns enabled.
         """
+        log.trace(f"Checking if #{channel} is on cooldown.")
         return (time.time() - self.channel_cooldowns.get(channel.id, 0)) < 300
 
     def is_valid_channel(self, channel: discord.TextChannel) -> bool:
         """Return True if `channel` is a help channel, may be on cooldown, or is whitelisted."""
+        log.trace(f"Checking if #{channel} qualifies for code block detection.")
         return (
             self.is_help_channel(channel)
             or channel.id in self.channel_cooldowns
@@ -62,6 +65,8 @@ class CodeBlockCog(Cog, name="Code Block"):
 
         The embed will be deleted automatically after 5 minutes.
         """
+        log.trace("Sending an embed with code block formatting instructions.")
+
         embed = Embed(description=description)
         bot_message = await message.channel.send(f"Hey {message.author.mention}!", embed=embed)
         self.codeblock_message_ids[message.id] = bot_message.id
@@ -92,25 +97,27 @@ class CodeBlockCog(Cog, name="Code Block"):
     async def on_message(self, msg: Message) -> None:
         """Detect incorrect Markdown code blocks in `msg` and send instructions to fix them."""
         if not self.should_parse(msg):
+            log.trace(f"Skipping code block detection of {msg.id}: message doesn't qualify.")
             return
 
         # When debugging, ignore cooldowns.
         if self.is_on_cooldown(msg.channel) and not DEBUG_MODE:
+            log.trace(f"Skipping code block detection of {msg.id}: #{msg.channel} is on cooldown.")
             return
 
         blocks = parsing.find_code_blocks(msg.content)
         if not blocks:
-            # No code blocks found in the message.
+            log.trace(f"No code blocks were found in message {msg.id}.")
             description = instructions.get_no_ticks_message(msg.content)
         else:
-            # Get the first code block with invalid ticks.
+            log.trace("Searching results for a code block with invalid ticks.")
             block = next((block for block in blocks if block.tick != parsing.BACKTICK), None)
 
             if block:
-                # A code block exists but has invalid ticks.
+                log.trace(f"A code block exists in {msg.id} but has invalid ticks.")
                 description = instructions.get_bad_ticks_message(block)
             else:
-                # Only other possibility is a block with valid ticks but a missing language.
+                log.trace(f"A code block exists in {msg.id} but is missing a language.")
                 block = blocks[0]
 
                 # Check for a bad language first to avoid parsing content into an AST.
@@ -121,6 +128,7 @@ class CodeBlockCog(Cog, name="Code Block"):
         if description:
             await self.send_guide_embed(msg, description)
             if msg.channel.id not in self.channel_whitelist:
+                log.trace(f"Adding #{msg.channel} to the channel cooldowns.")
                 self.channel_cooldowns[msg.channel.id] = time.time()
 
     @Cog.listener()
@@ -134,6 +142,7 @@ class CodeBlockCog(Cog, name="Code Block"):
             # Makes sure there's a channel id in the message payload
             or payload.data.get("channel_id") is None
         ):
+            log.trace("Message edit does not qualify for code block detection.")
             return
 
         # Parse the message to see if the code blocks have been fixed.
diff --git a/bot/cogs/codeblock/instructions.py b/bot/cogs/codeblock/instructions.py
index 9de418765..28242ce75 100644
--- a/bot/cogs/codeblock/instructions.py
+++ b/bot/cogs/codeblock/instructions.py
@@ -5,7 +5,7 @@ from . import parsing
 
 log = logging.getLogger(__name__)
 
-PY_LANG_CODES = ("python", "py")
+PY_LANG_CODES = ("python", "py")  # Order is important; "py" is second cause it's a subset.
 EXAMPLE_PY = "{lang}\nprint('Hello, world!')"  # Make sure to escape any Markdown symbols here.
 EXAMPLE_CODE_BLOCKS = (
     "\\`\\`\\`{content}\n\\`\\`\\`\n\n"
@@ -16,6 +16,7 @@ EXAMPLE_CODE_BLOCKS = (
 
 def get_bad_ticks_message(code_block: parsing.CodeBlock) -> Optional[str]:
     """Return instructions on using the correct ticks for `code_block`."""
+    log.trace("Creating instructions for incorrect code block ticks.")
     valid_ticks = f"\\{parsing.BACKTICK}" * 3
 
     # The space at the end is important here because something may be appended!
@@ -25,7 +26,7 @@ def get_bad_ticks_message(code_block: parsing.CodeBlock) -> Optional[str]:
         f"The correct symbols would be {valid_ticks}, not `{code_block.tick * 3}`. "
     )
 
-    # Check if the code has an issue with the language specifier.
+    log.trace("Check if the bad ticks code block also has issues with the language specifier.")
     addition_msg = get_bad_lang_message(code_block.content)
     if not addition_msg:
         addition_msg = get_no_lang_message(code_block.content)
@@ -33,19 +34,26 @@ def get_bad_ticks_message(code_block: parsing.CodeBlock) -> Optional[str]:
     # Combine the back ticks message with the language specifier message. The latter will
     # already have an example code block.
     if addition_msg:
+        log.trace("Language specifier issue found; appending additional instructions.")
+
         # The first line has a double line break which is not desirable when appending the msg.
         addition_msg = addition_msg.replace("\n\n", " ", 1)
 
         # Make the first character of the addition lower case.
         instructions += "\n\nFurthermore, " + addition_msg[0].lower() + addition_msg[1:]
     else:
+        log.trace("No issues with the language specifier found.")
+
         # Determine the example code to put in the code block based on the language specifier.
         if code_block.language.lower() in PY_LANG_CODES:
+            log.trace(f"Code block has a Python language specifier `{code_block.language}`.")
             content = EXAMPLE_PY.format(lang=code_block.language)
         elif code_block.language:
+            log.trace(f"Code block has a foreign language specifier `{code_block.language}`.")
             # It's not feasible to determine what would be a valid example for other languages.
             content = f"{code_block.language}\n..."
         else:
+            log.trace("Code block has no language specifier (and the code isn't valid Python).")
             content = "Hello, world!"
 
         example_blocks = EXAMPLE_CODE_BLOCKS.format(content=content)
@@ -56,6 +64,8 @@ def get_bad_ticks_message(code_block: parsing.CodeBlock) -> Optional[str]:
 
 def get_no_ticks_message(content: str) -> Optional[str]:
     """If `content` is Python/REPL code, return instructions on using code blocks."""
+    log.trace("Creating instructions for a missing code block.")
+
     if parsing.is_repl_code(content) or parsing.is_python_code(content):
         example_blocks = EXAMPLE_CODE_BLOCKS.format(content=EXAMPLE_PY.format(lang="python"))
         return (
@@ -65,6 +75,8 @@ def get_no_ticks_message(content: str) -> Optional[str]:
             "helps improve the legibility and makes it easier for us to help you.\n\n"
             f"**To do this, use the following method:**\n{example_blocks}"
         )
+    else:
+        log.trace("Aborting missing code block instructions: content is not Python code.")
 
 
 def get_bad_lang_message(content: str) -> Optional[str]:
@@ -73,6 +85,8 @@ def get_bad_lang_message(content: str) -> Optional[str]:
 
     If `content` doesn't start with "python" or "py" as the language specifier, return None.
     """
+    log.trace("Creating instructions for a poorly specified language.")
+
     stripped = content.lstrip().lower()
     lang = next((lang for lang in PY_LANG_CODES if stripped.startswith(lang)), None)
 
@@ -81,9 +95,11 @@ def get_bad_lang_message(content: str) -> Optional[str]:
         lines = ["It looks like you incorrectly specified a language for your code block.\n"]
 
         if content.startswith(" "):
+            log.trace("Language specifier was preceded by a space.")
             lines.append(f"Make sure there are no spaces between the back ticks and `{lang}`.")
 
         if stripped[len(lang)] != "\n":
+            log.trace("Language specifier was not followed by a newline.")
             lines.append(
                 f"Make sure you put your code on a new line following `{lang}`. "
                 f"There must not be any spaces after `{lang}`."
@@ -93,6 +109,8 @@ def get_bad_lang_message(content: str) -> Optional[str]:
         lines.append(f"\n**Here is an example of how it should look:**\n{example_blocks}")
 
         return "\n".join(lines)
+    else:
+        log.trace("Aborting bad language instructions: language specified isn't Python.")
 
 
 def get_no_lang_message(content: str) -> Optional[str]:
@@ -101,6 +119,8 @@ def get_no_lang_message(content: str) -> Optional[str]:
 
     If `content` is not valid Python or Python REPL code, return None.
     """
+    log.trace("Creating instructions for a missing language.")
+
     if parsing.is_repl_code(content) or parsing.is_python_code(content):
         example_blocks = EXAMPLE_CODE_BLOCKS.format(content=EXAMPLE_PY.format(lang="python"))
 
@@ -111,3 +131,5 @@ def get_no_lang_message(content: str) -> Optional[str]:
             "it easier for us to help you.\n\n"
             f"**To do this, use the following method:**\n{example_blocks}"
         )
+    else:
+        log.trace("Aborting missing language instructions: content is not Python code.")
diff --git a/bot/cogs/codeblock/parsing.py b/bot/cogs/codeblock/parsing.py
index 9adb4e0ab..7409653d7 100644
--- a/bot/cogs/codeblock/parsing.py
+++ b/bot/cogs/codeblock/parsing.py
@@ -51,6 +51,8 @@ def find_code_blocks(message: str) -> Sequence[CodeBlock]:
     return an empty sequence. This is based on the assumption that if the user managed to get
     one code block right, they already know how to fix the rest themselves.
     """
+    log.trace("Finding all code blocks in a message.")
+
     code_blocks = []
     for match in RE_CODE_BLOCK.finditer(message):
         # Used to ensure non-matched groups have an empty string as the default value.
@@ -58,16 +60,20 @@ def find_code_blocks(message: str) -> Sequence[CodeBlock]:
         language = groups["lang"].strip()  # Strip the newline cause it's included in the group.
 
         if groups["tick"] == BACKTICK and language:
+            log.trace("Message has a valid code block with a language; returning empty tuple.")
             return ()
         elif len(groups["code"].split("\n", 3)) > 3:
             code_block = CodeBlock(groups["code"], language, groups["tick"])
             code_blocks.append(code_block)
+        else:
+            log.trace("Skipped a code block shorter than 4 lines.")
 
     return code_blocks
 
 
 def is_python_code(content: str) -> bool:
     """Return True if `content` is valid Python consisting of more than just expressions."""
+    log.trace("Checking if content is Python code.")
     try:
         # Attempt to parse the message into an AST node.
         # Invalid Python code will raise a SyntaxError.
@@ -80,6 +86,7 @@ def is_python_code(content: str) -> bool:
     # This check is to avoid all nodes being parsed as expressions.
     # (e.g. words over multiple lines)
     if not all(isinstance(node, ast.Expr) for node in tree.body):
+        log.trace("Code is valid python.")
         return True
     else:
         log.trace("Code consists only of expressions.")
@@ -88,12 +95,16 @@ def is_python_code(content: str) -> bool:
 
 def is_repl_code(content: str, threshold: int = 3) -> bool:
     """Return True if `content` has at least `threshold` number of Python REPL-like lines."""
+    log.trace(f"Checking if content is Python REPL code using a threshold of {threshold}.")
+
     repl_lines = 0
     for line in content.splitlines():
         if line.startswith(">>> ") or line.startswith("... "):
             repl_lines += 1
 
         if repl_lines == threshold:
+            log.trace("Content is Python REPL code.")
             return True
 
+    log.trace("Content is not Python REPL code.")
     return False